I have several quizzes that are taking a long time to load. I enabled devel query log, display page timer, and display memory usage to try to see what's going on.
Executed 338 queries in 26621.22 ms. Queries exceeding 5 ms are highlighted. Page execution time was 27029.79 ms. Memory used at: devel_boot()=1.66 MB, devel_shutdown()=20 MB, PHP peak=21 MB.
When looking at the report, I see multiple lines with long execution times in relation to quiz_get_sub_questions with the query...
SELECT n.nid AS nid, n.type AS type, nr.vid AS vid, nr.title AS title, qnr.question_status AS question_status, qnr.weight AS weight, qnr.max_score AS max_score, qnr.auto_update_max_score AS auto_update_max_score, qnr.qnr_id AS qnr_id, qnr.qnr_pid AS qnr_pid, qnr.child_nid AS child_nid, qnr.child_vid AS child_vid, n.vid AS latest_vid FROM node n INNER JOIN node_revision nr ON n.nid = nr.nid INNER JOIN quiz_node_relationship qnr ON nr.vid = qnr.child_vid WHERE (qnr_pid = :db_condition_placeholder_0) ORDER BY weight ASC
These show up as many times as there are questions. So on a quiz with 170 questions, the total execution time is 26621.22 ms
Any ideas on why it is taking so long to execute?
Comment | File | Size | Author |
---|---|---|---|
#13 | 2895442-slow-subquestions.patch | 1.75 KB | djdevin |
| |||
#5 | mysql_advisor.txt | 1.99 KB | retiredpro |
Comments
Comment #2
djdevinHi,
Those queries will show up for each question as it's looking for subquestions (pages of questions).
But those typically take <1ms to execute as they are querying a parent ID specifically.
In your devel log did you see any queries that were taking more than 5ms to execute? (or a ton of queries that took longer than 5ms?)
In #2786013: Very slow on server we tested Quiz with 500+ questions but it was nowhere near 26s, so this must be something new affecting the loads.
Comment #3
retiredpro CreditAttribution: retiredpro commentedHi djdevin,
Thanks for the quick reply.
Looking at the devel log, quiz_get_questions takes 5.49 ms and each call to quiz_get_sub_questions takes anywhere between 135 ms to 180 ms. Everything else in the report is below 5 ms.
Comment #4
retiredpro CreditAttribution: retiredpro commentedAny ideas on how to troubleshoot this, djdevin?
Comment #5
retiredpro CreditAttribution: retiredpro commentedOur hosting company ran a MySQL report that was available from phpmyadmin. It appears to be an overall report and not something that is specific to the quiz module. See Attachment.
Based on the notes and comparing to the query I had originally posted, it appears that indexes need to be added to node_revision.vid and quiz_node_relationship.weight.
Of course node_revision is core so I'm not sure if it is correct to make that kind of adjustment on the table.
In any case I tried exporting this site to a different server and the page load is still pretty long. Not as long as on the original server but each call to quiz_get_sub_questions still takes roughly 130 ms - 140 ms to complete.
Comment #6
retiredpro CreditAttribution: retiredpro commentedThis site does not have subpages of questions, is it safe if I just comment out the call to quiz_get_sub_questions() in the quiz_get_questions() function?
Comment #7
djdevinHi,
Yes, for the time being if you do not use Quiz pages you could take that out.
Comment #8
retiredpro CreditAttribution: retiredpro commentedThanks, djdevin. I'll give that a shot.
Comment #9
djdevinAnd the patch...
This one was really hard to find, because the queries are only slow enough that you have to run 100 of them for it to make any difference. So they don't show up in slow query logs. A query that takes 0.05 seconds takes 5 seconds with 100 questions but isn't noticeable on a 10 question quiz.
Also fixed here is a very slow operation in _quiz_show_finish_button()
Comment #11
djdevinComment #13
djdevinComment #15
djdevin