Moodle

Just to be clear, is it showing the confirm page that is slow, or actually doing the delete after confirming?

And I would encourage you to trace through the code, and work out what it is doing, but my guess would be that most of the work is in quiz_question_list_instances in /mod/quiz/lib.php.

However, that should be really fast, since it is a single query, and all the necessary indices should exist. However, it would be nice to confirm that.

Of course, it is silly that this function returns a list of quizzes, and we later just check whether it is empty or not.

Anyway, it would be great to investigate this.

> Just to be clear, is it showing the confirm page that is slow, or actually doing the delete after confirming?

Yes, it is slow to get to the confirmation page. The actual delete is fast. The delete in 1.8 is/was slow.

> And I would encourage you to trace through the code, and work out what it is doing, but my guess would be that most of the work is in quiz_question_list_instances in /mod/quiz/lib.php.

We will do this. Any tips for tracing php code besides adding print and var_dump() statements. Do you use xdebug?

I tend to use the moodle-specific debugging and print_object instead of print and var_dump, simply because they are styled nicely in the moodle standard theme. Also, the former outputs a stack dump too.

The confirm and delete code is in /question/editlib.php between lines 470 and 550.

Hmm. That code isn't using question list instances. That is bad. Also it accesses $_REQUEST directly. It should use optional_param. So it probably needs a rewrite anyway.

What is very odd is that the confirm and delete code are very similar. Perhaps that suggests that your DB is doing a good job of caching repeat queries?

Thank you for the reminder on debugging and print_object.

> What is very odd is that the confirm and delete code are very similar. Perhaps that suggests that your DB is doing a good job of caching repeat queries?

I think that you are correct. I set up a question delete and had to leave my computer. When I got back I was logged out of Moodle and had to start the delete again. Both halves were fast. It made me almost believe in magic.

Tim,
We can confirm that you are correct on where the bottleneck is. We have nailed it down to inside
function question_showbank(... inside if (preg_match...
...
Lines 537-548
foreach ($rawquestions as $key => $value) { // Parse input for question ids
if (preg_match('!^q([0-9]+)$!', $key, $matches)) {
$key = $matches[1]; $questionlist .= $key.',';
question_require_capability_on($key, 'edit');
if (record_exists('quiz_question_instances', 'question', $key) or
record_exists('question_states', 'originalquestion', $key)) { $questionnames .= '* '; $inuse = true; }
$questionnames .= get_field('question', 'name', 'id', $key).'<br />';
}
}

Due to server caching or page rendering, I can't see where exactly, but I can look some more tomorrow. Or do you have enough to go on. I wonder if the repeated calls to question_require_capability_on($key, 'edit'); are part of the problem. The capability to edit questions is based on the category. If you are not showing sub categories, that would only need to be done once. If you were showing subcategories, it could be done more efficiently. The other guess is the logic to tell if a question is in use.

It is funny that you mentioned $_REQUEST. When I first was profiling this on our test machines $_REQUEST was loading slowly on its first use through the delete process; on the order of 3-8 seconds. But then magically, it loaded without problem. We had turned off APC cahce earlier on the box for testing.

What you have found out so far is very helpful, but it would be very helpful if you could pin down in even more detail which call is causing the slowness.

question_has_capability_on has some caching built in, but it does not cache the final answer, so maybe it could be improved, but we would need to confirm that it is really the problem first.

I have found where the problem is.

if (record_exists('quiz_question_instances', 'question', $questionid) or
481 : record_exists('question_states', 'originalquestion', $questionid)) {

if (record_exists('quiz_question_instances', 'question', $key) or
542 : record_exists('question_states', 'originalquestion', $key)) {

The record_exists calls on lines 481&542 take up ~99% of the execution time, except when the earlier record_exists evaluates true and boolean short-circuit logic causes the statements not to be evaluated. The confirmation page will take a while to run in cases where record_exists('quiz_question_instances', 'question', $questionid) is false and there isn't short-circuit logic. In my testing I was never able to get record_exists('question_states', 'originalquestion', $key) to evaluate true even when I rewrote the code so both lines always evaluated. Line 481 never evaluated true when line 480 was false. Is this checking for a condition that no longer can occur in 1.9.

I tested deleting under these conditions:
unused question
questions in an exam (which hides them instead of deletes them)
removing attempts then removing question from exam then deleting both hidden questions and questions that weren't hidden
(currently you can't remove a question from an exam if it still has attempts associated with it)
deleting exam then deleting questions, both hidden and not

I will attach a patch.

Patch removes two record_exists calls that seem to never evaluate true and are DB intensive.

Brilliant. I bet that question_states.originalquestion does not have an index on it, and question_states is a huge table. Actually, it is obsolete. It was part of a failed attempt to introduce question versioning.

Actually, I will probably not use your patch. Instead I will rewrite this code in terms of question_list_instances.

I can confirm that question_states.originalquestion does not have an index on it. Also for our production site with over 4,000,000 entries in question_states, originalquestion is always = 0, so I can confirm that it is not used and that both record_exists('question_states', 'originalquestion',... never evaluate true and therefore are currently not needed.

Because Tim's rewrite will probably be applied only to Moodle 1.9, and understandably so, I have attached another patch for Moodle 1.8 to remove those calls from showbank.php. Our testing on test sites has shown no problems with this. An alternative solution would be to add an index manually to question_states.originalquestion.

Caveats: I have only tested and looked at 1.8 and 1.9 code. I have searched in contrib for 1.8 and 1.9 and didn't find originalquestion, but there could be third party modules that do use this field. So before applying this patch, check your modifications, and check to make sure question_states.originalquestion is always 0. Also before applying the 1.9 patch, keep in mind that Tim will rewriting code and not using the 1.9 patch.

Now fixed in all branches from 1.7.x onwards.

In 1.9 and HEAD, I also took the opportunity to eliminate the direct access to $_REQUEST and $_POST that this code was doing in contravention of the Moodle coding guidelines.

Thanks for working out this fix Michael.

code reviewed, closing