Remove Explicit CAST from textbox to artefact upgrade queries

[Yaju Mahida]

Mahara version : Mahara upgrade from 1.4.2 to 1.5.2
Operating System : Redhat Linux
Database : MySQL

https://mahara.org/interaction/forum/topic.php?id=4544#post21091

We got an issue with timings when we were upgrading from 1.4.2 to 1.5.2. We got around 55304 textbox records in block_instance and during the upgrade to convert textboxes to artefacts process it takes so much time that this upgrade never finishes. It doesn't halt at any point, it just kept running even after 12-20 hours !

We did so many trial & error efforts for this upgrade with various tweakings like changing the limit of rows as 1, 100, 1000, 5000 to 8192 without any success (https://bugs.launchpad.net/mahara/+bug/1018590).

All the time we had to interrupt the process in middle as it never finishes. We also tweaked various MySQL configuration in case it is not optimized for performance or something else at MySQL side is causing it but this was not the case. For each attempt we used the fresh copy of existing production database which is at Mahara 1.4.2.

Take this example where we started the upgrade on 17th August 2012 with 100 rows at a time to update/insert to convert textboxes to artefacts.

The slow query log is full with the two queries, UPDATE "block_instance", "artefact" and INSERT INTO "view_artefact" (view, block, artefact) for numerous times and each taking around 16 to 20 seconds. These two queries are logged with each iteration of the while loop (/artefact/internal/blocktype/textbox/db/upgrade.php line 52 while ($records = get_records_sql_array($sql, array($lastid, 'textbox'), 0, $limit)) ). It took 8 hours and still the upgrade wasn't finished - we did check and the update/insert query were still running ! At last we had to interrupt this process and at the end of log the above two queries were found where each took around 3000 seconds and upto this point it upgraded textbox blocks: 38100/55304 ! Still there were 11004 textblocks left and if you count according to last four query timings it will finish in few days !

In another attempt when binary logging was enabled it took more than 12 hours to upgrade 44100 blocks and still it was upgrading rest of the blocks with each update & insert query taking up time upto 3800 seconds !

Please, see the following slow query log,

# Time: 120817 13:11:41
# User@Host: mahara[mahara] @ localhost []
# Query_time: 16 Lock_time: 0 Rows_sent: 0 Rows_examined: 5530500
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;

# Time: 120817 13:12:07
# User@Host: mahara[mahara] @ localhost []
# Query_time: 17 Lock_time: 0 Rows_sent: 0 Rows_examined: 5530600
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;

# Time: 120817 13:12:32
# User@Host: mahara[mahara] @ localhost []
# Query_time: 16 Lock_time: 0 Rows_sent: 0 Rows_examined: 5530700
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;
.

.

.

.

(This continued for each 100 rows)

.

.

.

(This is the end of slow query log and see the number of rows examined junmped from 5568200 to 2101607304)

# Time: 120817 17:50:47
# User@Host: mahara[mahara] @ localhost []
# Query_time: 13 Lock_time: 0 Rows_sent: 0 Rows_examined: 5568200
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;

# Time: 120817 17:51:09
# User@Host: mahara[mahara] @ localhost []
# Query_time: 14 Lock_time: 0 Rows_sent: 0 Rows_examined: 5568300
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;

# Time: 120817 18:48:02
# User@Host: mahara[mahara] @ localhost []
# Query_time: 3405 Lock_time: 0 Rows_sent: 0 Rows_examined: 2101607304
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;
# Time: 120817 19:44:00
# User@Host: mahara[mahara] @ localhost []
# Query_time: 3358 Lock_time: 0 Rows_sent: 0 Rows_examined: 2101607304
INSERT INTO "view_artefact" (view, block, artefact)
                SELECT b.view, b.id, a.id
                FROM "block_instance" b, "artefact" a
                WHERE b.blocktype = 'textbox' AND a.artefacttype = 'html' AND a.note IS NOT NULL AND CAST(b.id AS CHAR) = a.note;
# Time: 120817 20:38:08
# User@Host: mahara[mahara] @ localhost []
# Query_time: 3246 Lock_time: 0 Rows_sent: 0 Rows_examined: 2107137704
UPDATE "block_instance", "artefact"
                    SET "block_instance".configdata = CONCAT('a:1:{s:10:"artefactid";i:', CAST("artefact".id AS CHAR), ';}')
                    WHERE
                        "artefact".artefacttype = 'html'
                        AND "artefact".note IS NOT NULL
                        AND "block_instance".blocktype = 'textbox'
                        AND CAST("block_instance".id AS CHAR) = "artefact".note;
# Time: 120817 21:31:21
# User@Host: mahara[mahara] @ localhost []
# Query_time: 3193 Lock_time: 0 Rows_sent: 0 Rows_examined: 2107137704
INSERT INTO "view_artefact" (view, block, artefact)
                SELECT b.view, b.id, a.id
                FROM "block_instance" b, "artefact" a
                WHERE b.blocktype = 'textbox' AND a.artefacttype = 'html' AND a.note IS NOT NULL AND CAST(b.id AS CHAR) = a.note;

After spending 6 days behind this issue we found that the CAST("block_instance".id AS CHAR) is a root cause for this issue.

According to MySQL 5.0 manual we don't need to use the explicit CAST as some conversions should occure implicitly via MySQL. We removed the CAST function and allowed MySQL to do the comparision using implicit rules and it finished within 10-15 minutes !

Also we found a bug report (not a bug) Bug #11346 slow query due to datatype cast? which was closed by MySQL with the following comments, (ofcourse it is old but still applies)

[16 Jul 2005 20:31] Sergei Golubchik

Thank you for taking the time to write to us, but this is not
a bug. Please double-check the documentation available at
http://www.mysql.com/documentation/ and the instructions on
how to report a bug at http://bugs.mysql.com/how-to-report.php

Additional info:

Yes, there is a reason why integer values are not casted to string values before query execution and index selection.
Because according to implicit casting that MySQL performs for comparison, when you compare a string with a number, they are compared as numbers. E.g. when all the following will evaluate to TRUE:

  1 = "1"
  1 = " 1"
  1 = " +1"
  1 = "000000001"

etc. You see, if you cast an integer (1 in my examples) to a string, and perform a string comparison, you won't be able to keep all the above TRUE anymore.

To investigate this further we commented out the update block_instance and insert into view_artefact lines and allowed it to create 55403 records into artefact from block_instance which are textboxes(INSERT INTO {artefact}....from block_instance).

When we executed a simple select statment to these dataset using MySQL admin tool it took 12.339 seconds for 100 records !

16:20:25 select * from block_instance, artefact WHERE artefact.artefacttype = 'html' AND artefact.note IS NOT NULL AND block_instance.blocktype = 'textbox' AND CAST(block_instance.id AS char) = artefact.note limit 100 100 row(s) returned 2.028 sec / 12.339 sec.

explain select * from block_instance, artefact WHERE artefact.artefacttype = 'html' AND artefact.note IS NOT NULL AND block_instance.blocktype = 'textbox' AND CAST(block_instance.id AS char) = artefact.note;
    id,select_type,table,type,possible_keys,key,key_len,ref,rows,Extra
    1,SIMPLE,artefact,ref,arte_art_ix,arte_art_ix,767,const,72512,"Using where"
    1,SIMPLE,block_instance,ref,blocinst_blo_ix,blocinst_blo_ix,767,const,74814,"Using where"

When we executed the same query without cast it took 0.016 seconds !

16:22:31 select * from block_instance, artefact WHERE artefact.artefacttype = 'html' AND artefact.note IS NOT NULL AND block_instance.blocktype = 'textbox' AND block_instance.id = artefact.note limit 100 100 row(s) returned 0.016 sec / 0.000 sec.

explain select * from block_instance, artefact WHERE artefact.artefacttype = 'html' AND artefact.note IS NOT NULL AND block_instance.blocktype = 'textbox' AND block_instance.id = artefact.note;
    id,select_type,table,type,possible_keys,key,key_len,ref,rows,Extra
    1,SIMPLE,artefact,ref,arte_art_ix,arte_art_ix,767,const,72512,"Using where"
    1,SIMPLE,block_instance,eq_ref,"PRIMARY,blocinst_blo_ix",PRIMARY,8,mahara15-trunk.artefact.note,1,"Using where"

Following to this investigation I would recommend to remove the explicit CAST from the textbox upgrade queries.

[Hugh Davenport (hugh-davenport)]

Hi Yaju,

Thanks for that fix, if you like you can submit a patch of that to our review system, or one of our team can pick it up and do it on your behalf.

See https://wiki.mahara.org/index.php/Developer_Area/Contributing_Code for details on how to submit.

Cheers,

Hugh

[Hugh Davenport (hugh-davenport)]

https://reviews.mahara.org/1585

[Donna Hrynkiw (donna-hrynkiw)]

We ran into this bug while upgrading from 1.4.0 to 1.6.2. It was a point of significant frustration for us until Yaju responded to our forum posting with a pointer to this page. Many thanks to Yaju for providing such a complete description of both the bug and its fix.

The explicit CAST is now present in *three* locations in the v1.6.2 version of mahara/htdocs/artefact/internal/blocktype/textbox/db/upgrade.php

This were our changes:
# diff upgrade.php-orig upgrade.php
91c91
< SET {block_instance}.configdata = CONCAT('a:1:{s:10:\"artefactid\";i:', CAST({artefact}.id AS CHAR), ';}')
---
> SET {block_instance}.configdata = CONCAT('a:1:{s:10:\"artefactid\";i:', {artefact}.id, ';}')
96c96
< AND CAST({block_instance}.id AS CHAR) = {artefact}.note"
---
> AND {block_instance}.id = {artefact}.note"
106c106
< WHERE b.blocktype = 'textbox' AND a.artefacttype = 'html' AND a.note IS NOT NULL AND CAST(b.id AS $casttype) = a.note",
---
> WHERE b.blocktype = 'textbox' AND a.artefacttype = 'html' AND a.note IS NOT NULL AND b.id = a.note",
#

After this fix, our upgrade was successful.

[Yaju Mahida (yvm)]

We had the same issue after upgrade. We created an index artefact_access_role, create index arteaccerole_roleart_ix on artefact_access_role (role,artefact);

Even after the above index it is slow but better than before as now it takes few seconds 20-30.

https://mahara.org/interaction/forum/topic.php?id=5370&offset=0&limit=10#post23195

[Yaju Mahida (yvm)]

https://mahara.org/interaction/forum/topic.php?id=5143&offset=0&limit=10#post23196

[Aaron Wells (u-aaronw)]

Hi guys,

Thanks for the patch. I've updated it on https://reviews.mahara.org/#/c/1585/ to make sure it works on Postgres & MySQL, and I've removed all three of the CAST's identified by Donna in this comment: https://bugs.launchpad.net/mahara/+bug/1039865/comments/4

I'll try to get this out as part of the next minor release for 1.5, 1.6, and 1.7.

Cheers,
Aaron

[Mahara Bot (dev-mahara)]

Reviewed: https://reviews.mahara.org/1585
Committed: http://gitorious.org/mahara/mahara/commit/fbd17670e2088a79a1364bb13c91a38d4c1b197f
Submitter: Son Nguyen (<email address hidden>)
Branch: master

commit fbd17670e2088a79a1364bb13c91a38d4c1b197f
Author: Hugh Davenport <email address hidden>
Date: Wed Aug 29 10:16:01 2012 +1200

Bug #1039865: Fix slow upgrade query

Remove the CAST from the query, as was causing slow
downs on MySQL.

https://mahara.org/interaction/forum/topic.php?id=4544#post21091

Could be related to the following MySQL bug

http://bugs.mysql.com/bug.php?id=11346

Solution was provided by Yaju Mahida

Signed-off-by: Aaron Wells <email address hidden>
Change-Id: I7e076d9dc8da46890364373ee10b46eb95ba638b

[Aaron Wells (u-aaronw)]

Backporting:

1.7: https://reviews.mahara.org/2134
1.6: https://reviews.mahara.org/2135
1.5: https://reviews.mahara.org/2136

[Mahara Bot (dev-mahara)]

Reviewed: https://reviews.mahara.org/2136
Committed: http://gitorious.org/mahara/mahara/commit/7b4ab219b3f6bf5007fbad458479e5b4ec8e73a0
Submitter: Aaron Wells (<email address hidden>)
Branch: 1.5_STABLE

commit 7b4ab219b3f6bf5007fbad458479e5b4ec8e73a0
Author: Hugh Davenport <email address hidden>
Date: Wed Aug 29 10:16:01 2012 +1200

Bug #1039865: Fix slow upgrade query

Remove the CAST from the query, as was causing slow
downs on MySQL.

https://mahara.org/interaction/forum/topic.php?id=4544#post21091

Could be related to the following MySQL bug

http://bugs.mysql.com/bug.php?id=11346

Solution was provided by Yaju Mahida

Signed-off-by: Aaron Wells <email address hidden>
Change-Id: I7e076d9dc8da46890364373ee10b46eb95ba638b

[Mahara Bot (dev-mahara)]

Reviewed: https://reviews.mahara.org/2135
Committed: http://gitorious.org/mahara/mahara/commit/3fc6d1e840e180e31f6fde945dd90aac30bdd55a
Submitter: Aaron Wells (<email address hidden>)
Branch: 1.6_STABLE

commit 3fc6d1e840e180e31f6fde945dd90aac30bdd55a
Author: Hugh Davenport <email address hidden>
Date: Wed Aug 29 10:16:01 2012 +1200

Bug #1039865: Fix slow upgrade query

Remove the CAST from the query, as was causing slow
downs on MySQL.

https://mahara.org/interaction/forum/topic.php?id=4544#post21091

Could be related to the following MySQL bug

http://bugs.mysql.com/bug.php?id=11346

Solution was provided by Yaju Mahida

Change-Id: I5b8f81b5afb993b8df6a5e67a7cc4140c65249f4
Signed-off-by: Aaron Wells <email address hidden>

[Mahara Bot (dev-mahara)]

Reviewed: https://reviews.mahara.org/2134
Committed: http://gitorious.org/mahara/mahara/commit/1855945fbb667e46c50c6387c87d2df71fecaa89
Submitter: Aaron Wells (<email address hidden>)
Branch: 1.7_STABLE

commit 1855945fbb667e46c50c6387c87d2df71fecaa89
Author: Hugh Davenport <email address hidden>
Date: Wed Aug 29 10:16:01 2012 +1200

Bug #1039865: Fix slow upgrade query

Remove the CAST from the query, as was causing slow
downs on MySQL.

https://mahara.org/interaction/forum/topic.php?id=4544#post21091

Could be related to the following MySQL bug

http://bugs.mysql.com/bug.php?id=11346

Solution was provided by Yaju Mahida

Signed-off-by: Aaron Wells <email address hidden>
Change-Id: I7e076d9dc8da46890364373ee10b46eb95ba638b