Comment 2 for bug 1081947

Revision history for this message
Yaju Mahida (yvm) wrote : Re: Adding Journal or Text box to a page takes approx 2 minutes to load

In December 2012 we upgraded to Mahara 1.5.4 and since the upgrade the apache error log was full with "MySQL server has gone away". After investigation we found two very slow queries related to TextBox.

To solve this we put the index create index arteaccerole_roleart_ix on artefact_access_role (role,artefact) which temporarily solved this issue but still it is very slow taking around 16 seconds for text box to create/open and save.

With so many concurrent users this slow downs the whole system consuming all MySQL resources and complains with the error "Failed to get a recordset: mysql error: [2013: Lost connection to MySQL server during query] in EXECUTE("SELECT COUNT(*) FROM "artefact" a , referer: https://mahara.localhost/view/blocks.php?id=50000".

Recently our functional support person reported following statistics after this fix.

The text box functionality has slowed a little – but still very usable:
Approx. 16 seconds for Text box: Configure to pop up
Approx. 16-21 seconds for the Text box to save (with just plain text in it)
There were 13 users online at time of test

The profile information block is slow :
Approx. 62 seconds for Profile information: Configure to pop up
Approx. 58 seconds for the Profile information to save
There were 10 users online at time of test

In peak days we have seen around 500 users logging on and I am scared to think that what will happen when there will be same heavy load!

---------------------------------------------------------------------
Investigation about the following two queries
---------------------------------------------------------------------

SELECT a.*, CAST(a.owner IS NOT NULL AND a.owner = '3542' AS UNSIGNED) AS editable
FROM artefact a
 LEFT OUTER JOIN artefact_parent_cache apc ON (a.id = apc.artefact AND a.institution = 'mahara' AND apc.parent = 4)
WHERE (
  a.owner = '3542'
  OR a.id IN (
   SELECT aar.artefact
   FROM group_member m
    JOIN artefact aa ON m.group = aa.group
    JOIN artefact_access_role aar ON aar.role = m.role AND aar.artefact = aa.id
   WHERE m.member = '3542' AND aar.can_republish = 1
  )
  OR a.id IN (SELECT artefact FROM artefact_access_usr WHERE usr = '3542' AND can_republish = 1)
  OR a.institution IN ('XXX','mahara')
 ) AND artefacttype IN('html') ORDER BY title ASC limit 5;

SELECT COUNT(*) FROM `artefact` a
            LEFT OUTER JOIN `artefact_parent_cache` apc ON (a.id = apc.artefact AND a.institution = 'mahara' AND apc.parent = 4) WHERE (
                a.owner = '3542'
                OR a.id IN (
                    SELECT aar.artefact
                    FROM `group_member` m
                        JOIN `artefact` aa ON m.group = aa.group
                        JOIN `artefact_access_role` aar ON aar.role = m.role AND aar.artefact = aa.id
                    WHERE m.member = '3542' AND aar.can_republish = 1
                )
                OR a.id IN (SELECT artefact FROM `artefact_access_usr` WHERE usr = '3542' AND can_republish = 1)
                OR (apc.parent IS NOT NULL)
                OR a.institution IN ('XXX')
            ) AND artefacttype IN('html');

-------------------------------
Without any indexes
-------------------------------

5 row(s) returned 119.793 sec / 0.000 sec

Explain:

'1', 'PRIMARY', 'a', 'ref', 'arte_art_ix,arte_own_ix,arte_ins_fk', 'arte_art_ix', '767', 'const', '94434', 'Using where; Using filesort'
'1', 'PRIMARY', 'apc', 'eq_ref', 'PRIMARY,arteparecach_art_ix,arteparecach_par_ix', 'PRIMARY', '16', 'mahara104.a.id,const', '1', 'Using index'
'3', 'DEPENDENT SUBQUERY', 'artefact_access_usr', 'ALL', NULL, NULL, NULL, NULL, '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'aar', 'ALL', NULL, NULL, NULL, NULL, '1515', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'aa', 'eq_ref', 'PRIMARY,arte_gro_fk', 'PRIMARY', '8', 'mahara104.aar.artefact', '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'm', 'eq_ref', 'PRIMARY,groumemb_gro_ix,groumemb_mem_ix', 'PRIMARY', '16', 'mahara104.aa.group,const', '1', 'Using where'

-------------------------------
With indexes

create index arteaccerole_artefact_ix on artefact_access_role (artefact);
create index arteacceusr_artefact_ix on artefact_access_usr (artefact);
-------------------------------

5 row(s) returned 2.667 sec / 0.000 sec

Explain:

'1', 'PRIMARY', 'a', 'ref', 'arte_art_ix,arte_own_ix,arte_ins_fk', 'arte_art_ix', '767', 'const', '94434', 'Using where; Using filesort'
'1', 'PRIMARY', 'apc', 'eq_ref', 'PRIMARY,arteparecach_art_ix,arteparecach_par_ix', 'PRIMARY', '16', 'mahara104.a.id,const', '1', 'Using index'
'3', 'DEPENDENT SUBQUERY', 'artefact_access_usr', 'index_subquery', 'arteacceusr_artefact_ix', 'arteacceusr_artefact_ix', '4', 'func', '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'aar', 'ref', 'arteaccerole_artefact_ix', 'arteaccerole_artefact_ix', '4', 'func', '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'aa', 'eq_ref', 'PRIMARY,arte_gro_fk', 'PRIMARY', '8', 'mahara104.aar.artefact', '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'm', 'eq_ref', 'PRIMARY,groumemb_gro_ix,groumemb_mem_ix', 'PRIMARY', '16', 'mahara104.aa.group,const', '1', 'Using where'

-------------------------------
With index

create index arteaccerole_roleart_ix on artefact_access_role (role,artefact);
-------------------------------

5 row(s) returned 8.206 sec / 0.000 sec

Explain:

'1', 'PRIMARY', 'a', 'ref', 'arte_art_ix,arte_own_ix,arte_ins_fk', 'arte_art_ix', '767', 'const', '94434', 'Using where; Using filesort'
'1', 'PRIMARY', 'apc', 'eq_ref', 'PRIMARY,arteparecach_art_ix,arteparecach_par_ix', 'PRIMARY', '16', 'mahara104.a.id,const', '1', 'Using index'
'3', 'DEPENDENT SUBQUERY', 'artefact_access_usr', 'ALL', NULL, NULL, NULL, NULL, '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'm', 'ref', 'PRIMARY,groumemb_gro_ix,groumemb_mem_ix', 'groumemb_mem_ix', '8', 'const', '10', ''
'2', 'DEPENDENT SUBQUERY', 'aar', 'ref', 'arteaccerole_roleart_ix', 'arteaccerole_roleart_ix', '771', 'mahara104.m.role,func', '1', 'Using where'
'2', 'DEPENDENT SUBQUERY', 'aa', 'eq_ref', 'PRIMARY,arte_gro_fk', 'PRIMARY', '8', 'mahara104.aar.artefact', '1', 'Using where'

Apart from indexes the query needs to be break down in two seperate fragements which takes less than 2 seconds without any of the above indexes.

1. $Results = SELECT aar.artefact
   FROM group_member m
    JOIN artefact aa ON m.group = aa.group
    JOIN artefact_access_role aar ON aar.role = m.role AND aar.artefact = aa.id
   WHERE m.member = '3542' AND aar.can_republish = 1

2. SELECT a.*, CAST(a.owner IS NOT NULL AND a.owner = '3542' AS UNSIGNED) AS editable
   FROM artefact a
   LEFT OUTER JOIN artefact_parent_cache apc ON (a.id = apc.artefact AND a.institution = 'mahara' AND apc.parent = 4)
   WHERE (
    a.owner = '3542'
    OR a.id IN ($Results)
    OR a.id IN (SELECT artefact FROM artefact_access_usr WHERE usr = '3542' AND can_republish = 1)
    OR a.institution IN ('XXX','mahara')
   ) AND artefacttype IN('html') ORDER BY title ASC limit 5;

 The query needs to be re-written for better performance and stability of the system. I think this bug should be given high priority and the severity of this can be experienced when the database is huge...