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?

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

retiredpro created an issue. See original summary.

djdevin’s picture

Hi,

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.

retiredpro’s picture

Hi 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.

retiredpro’s picture

Any ideas on how to troubleshoot this, djdevin?

retiredpro’s picture

FileSize
1.99 KB

Our 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.

retiredpro’s picture

This 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?

function quiz_get_questions($quiz_nid, $quiz_vid = NULL) {
  $questions = array();
  $query = db_select('node', 'n');
  $query->fields('n', array('nid', 'type'));
  $query->fields('nr', array('vid', 'title'));
  $query->fields('qnr', array('question_status', 'weight', 'max_score', 'auto_update_max_score', 'qnr_id', 'qnr_pid', 'child_nid', 'child_vid'));
  $query->addField('n', 'vid', 'latest_vid');
  $query->join('node_revision', 'nr', 'n.nid = nr.nid');
  $query->leftJoin('quiz_node_relationship', 'qnr', 'nr.vid = qnr.child_vid');
  $query->condition('n.status', 1);
  $query->condition('qnr.parent_nid', $quiz_nid);
  if ($quiz_vid) {
    $query->condition('qnr.parent_vid', $quiz_vid);
  }
  $query->condition('qnr_pid', NULL, 'IS');
  $query->orderBy('qnr.weight');

  $result = $query->execute();
  
  foreach ($result as $question) {
    $questions[] = $question;
    //quiz_get_sub_questions($question->qnr_id, $questions);
  }

  return $questions;
}
djdevin’s picture

Version: 7.x-5.1 » 7.x-5.x-dev
Category: Support request » Bug report
Status: Active » Needs work

Hi,

Yes, for the time being if you do not use Quiz pages you could take that out.

retiredpro’s picture

Thanks, djdevin. I'll give that a shot.

djdevin’s picture

Status: Needs work » Needs review
FileSize
2.14 KB

And 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()

Status: Needs review » Needs work

The last submitted patch, 9: 2895442-slow-subquestions.patch, failed testing. View results

djdevin’s picture

Status: Needs work » Needs review
FileSize
1.75 KB

Status: Needs review » Needs work

The last submitted patch, 11: 2895442-slow-subquestions.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

djdevin’s picture

Status: Needs work » Needs review
FileSize
1.75 KB

  • djdevin committed 60398f2 on 7.x-5.x
    Issue #2895442 by djdevin, retiredpro: Long load times on quiz pages
    
djdevin’s picture

Status: Needs review » Fixed

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.