mahara-contributors team mailing list archive

[Yaju Mahida <1039865@xxxxxxxxxxxxxxxxxx>]

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

-- 
You received this bug notification because you are a member of Mahara
Contributors, which is subscribed to Mahara.
Matching subscriptions: Subscription for all Mahara Contrib members
https://bugs.launchpad.net/bugs/1039865

Title:
  Remove Explicit CAST from textbox to artefact upgrade queries

Status in Mahara ePortfolio:
  In Progress

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