22 May 2012, 10:50

Hi all. I'm attempting to upgrade Mahara from 1.4.2 to 1.5. Each time the core upgrade icon spins indefinately. There appears to be no error being logged at all. I have logged all mysql queries and the last one to execute seems to be:

120522 16:29:38 143 Query 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
120522 16:33:51 143 Quit

Any info on how to log more or where to start woudl be appreciated. Running on windows7/apache/mysql
Cheers Thomas

22 May 2012, 17:49

Hi Thomas, I'd expect to see an error in webserver log if a query is failing for some reason, so it's more likely that there's a timeout or memory limit being exceeded.

24 May 2012, 6:16

Hi Richard and many thanks for your reply.

It would appear you were correct! Not that I doubted you for a second 

I had already upped all memory and execution times to something large in order to rule that out, but what I hadn't seen was the max_execution_time declared in lib/db/upgrade.php

I upped that too but I got the same result... however, after allowing the loading gif to spin for a time and keeping an eye on the harddrive activity until there was none, I reloaded the page (ctrl + r) and clicked to perform the upgrade and this time instead of giving me an error upgrading the core, it completely skipped the core and continued with the upgrade. I had to do the same thing once more for blocktype.externalfeed and voila! upgrade complete.

Many thanks again

A very pleased Thomas

24 May 2012, 7:33

Just a wee update...

I have changed line 32 of lib/db/upgrade.php from:

    ini_set('max_execution_time', 120); // Let's be safe

to:

    ini_set('max_execution_time', 1200); // Let's be safe

and I am pleased to report that my upgrade from Mahara1.4.0 went straight up to Mahara1.5.1 with no issues at all. No reloading of pages.

Admittedly, it took a few minutes, but a perfect upgrade.

Cheers Thomas

20 August 2012, 1:47

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. Do I need report this as a bug with patch that solves this ? 

21 August 2012, 3:57

Do I need report this as a bug with patch that solves this ?

I would say yes! By the way, great work and many thanks for putting so much effort into solving this!

Saludos.
Iñaki.

21 August 2012, 20:12

I will report this - thanks

21 August 2012, 17:30

Hi Yaju,

I've just had a read of the mysql manual to get bit more of an idea about what is happening.

As I read it, if you remove the CAST operator, then it will implicitly cast the note record (currently text) to a number (bigint, same as id), and do a numerical comparison. This comparison if I recall correctly, is not NULL-safe, so may cause problems on NULL values in the note field.

Another thing to note, is "For comparisons of a string column with a number, MySQL cannot use an index on the column to look up the value quickly."

Does this speed up the actual upgrade path if you take out the CAST operator? The file with it in is htdocs/artefact/internal/blocktype/textbox/db/upgrade.php, around line 106, and also line 91. Does it work as expected after the upgrade?

Cheers,

Hugh

21 August 2012, 20:38

Hi Hugh,

About NULL-safe, there is a where clause "artefact.note is not null" so don't think it will create any issue. We can use the CAST(artefact.note as unsigned) to compare

Yes removing the CAST operator speed up the whole upgrade process. After upgrade I am able to see the notes.

27 August 2012, 2:17

During the upgrade we got the following warning messages about the PHP function - unserialize(). This happenned with around 500 blocks of textboxes out of 55000.

[WAR] d2 (artefact/internal/blocktype/textbox/db/upgrade.php:56) unserialize(): Error at offset 492 of 513 bytes
Call stack (most recent first):
  * log_message("unserialize(): Error at offset 492 of 513 bytes", 8, true, true, "/var/www/html/mahara15-trunk/artefact/internal/blo...", 56) at /var/www/html/mahara15-trunk/lib/errors.php:446
  * error(8, "unserialize(): Error at offset 492 of 513 bytes", "/var/www/html/mahara15-trunk/artefact/internal/blo...", 56, array(size 11)) at Unknown:0
  * unserialize("a:1:{s:4:"text";s:469:"<strong>My Old Friend is a ...") at /var/www/html/mahara15-trunk/artefact/internal/blocktype/textbox/db/upgrade.php:56
  * xmldb_blocktype_textbox_upgrade("2010061800") at /var/www/html/mahara15-trunk/lib/upgrade.php:374
  * upgrade_plugin(object(stdClass)) at /var/www/html/mahara15-trunk/lib/db/upgrade.php:2576
  * xmldb_core_upgrade("2011061006") at /var/www/html/mahara15-trunk/lib/upgrade.php:301
  * upgrade_core(object(stdClass)) at /var/www/html/mahara15-trunk/lib/mahara.php:263
  * upgrade_mahara(array(size 7)) at /var/www/html/mahara15-trunk/admin/cli/upgrade.php:62