Public bug reported: 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. ** Affects: mahara Importance: Undecided Status: New -- You received this bug notification because you are a member of Mahara Contributors, which is subscribed to Mahara. https://bugs.launchpad.net/bugs/1039865 Title: Remove Explicit CAST from textbox to artefact upgrade queries Status in Mahara ePortfolio: New Bug description: 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. To manage notifications about this bug go to: https://bugs.launchpad.net/mahara/+bug/1039865/+subscriptions _______________________________________________ Mailing list: https://launchpad.net/~mahara-contributors Post to : mahara-contributors@lists.launchpad.net Unsubscribe : https://launchpad.net/~mahara-contributors More help : https://help.launchpad.net/ListHelp
