Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: 2.5
-
Component/s: Backup, Performance, Quiz
-
Labels:
-
Rank:51796
Description
During restore, questions have the answers attached to them in a serial manner. However the database is queried for each answer because of the progressive parsing loader.
Creating a small cache of the answers for a single question allows a reduction in database usage and also does a complete text match rather than the first 255 characters. Which does have the potential to expose the wrong answer to us.
The memory requirement for a single question should not be large as any quiz page will be required to pay the same cost when displaying the answers to the quiz.
Issue Links
- has a non-specific relationship to
-
MDL-30018
Quiz Duplication With Carriage Return Results in a Fatal Error
-
- Closed
-
Activity
I've not uploaded these yet. That will be done when peer review is requested. At this point, I am finalizing the testing to ensure the upload operates as expected.
My environment is not giving stables results for improvement across the entire restore. The diff below shows how the process_question_answer has changed. If you can discern the relevant parts. There is a good increase in processing time.
| Function Name | Calls Diff | Calls Diff% | Incl. Wall Diff (microsec) | IWall Diff% | Incl. CPU Diff (microsec) | ICpu Diff% | Incl. MemUse Diff (bytes) | IMemUse Diff% | Incl. PeakMemUse Diff (bytes) | IPeakMemUse Diff% Current Function |
|---|---|---|---|---|---|---|---|---|---|---|
| restore_qtype_plugin::process_question_answer | 0 | 0.0% | -205,682,433 | -1063.1% | -30,709,892 | -89.0% | -23,540,296 | -2248.2% | 0 | 0.0% |
| Exclusive Metrics Diff for Current Function | -14,050 | -0.0% | 956,042 | 3.1% | -42,607,224 | -181.0% | 0 | N/A% | ||
| Parent function | ||||||||||
| restore_structure_step::process | 0 | N/A% | -205,682,433 | -100.0% | -30,709,892 | -100.0% | -23,540,296 | -100.0% | 0 | N/A% |
| Child functions | ||||||||||
| restore_plugin::set_mapping | 0 | 0.0% | -123,621,282 | -60.1% | -8,208,528 | -26.7% | 294,704 | 1.3% | 0 | N/A% |
| moodle_database::get_field_sql | -25,233 | -35.6% | -73,093,410 | -35.5% | -47,199,011 | -153.7% | -4,288,184 | -18.2% | 0 | N/A% |
| restore_plugin::get_mappingid | 0 | 0.0% | -33,414,131 | -16.2% | -4,488,142 | -14.6% | -19,798,568 | -84.1% | 0 | N/A% |
| moodle_database::get_records | 6,818 | 9.6% | 18,710,614 | 9.1% | 17,969,103 | 58.5% | 32,454,096 | 137.9% | 0 | N/A% |
| cache::get | 50,440 | 71.2% | 3,671,201 | 1.8% | 6,324,389 | 20.6% | 601,072 | 2.6% | 0 | N/A% |
| cache::set | 32,028 | 45.2% | 1,923,898 | 0.9% | 3,332,229 | 10.9% | 19,267,376 | 81.8% | 0 | N/A% |
| cache::purge | 6,818 | 9.6% | 322,044 | 0.2% | 520,032 | 1.7% | -25,340,080 | -107.6% | 0 | N/A% |
| moodle_database::sql_compare_text | -50,466 | -71.2% | -288,832 | -0.1% | -460,021 | -1.5% | -2,688 | -0.0% | 0 | N/A% |
| preg_replace | 50,420 | 71.2% | 220,789 | 0.1% | 464,026 | 1.5% | 15,854,192 | 67.3% | 0 | N/A% |
| restore_plugin::get_old_parentid | 0 | 0.0% | -101,457 | -0.0% | 47,992 | 0.2% | -54,552 | -0.2% | 0 | N/A% |
| pgsql_native_moodle_database::insert_record | 13 | 0.0% | 76,611 | 0.0% | 36,003 | 0.1% | 33,400 | 0.1% | 0 | N/A% |
| restore_plugin::get_new_parentid | 0 | 0.0% | -58,501 | -0.0% | -32,010 | -0.1% | -59,528 | -0.3% | 0 | N/A% |
| array_key_exists | 0 | 0.0% | -20,151 | -0.0% | 24,004 | 0.1% | 216 | 0.0% | 0 | N/A% |
| cache::make_from_params | 5 | 0.0% | 4,224 | 0.0% | 4,000 | 0.0% | 105,472 | 0.4% | 0 | N/A% |
Please complete peer review on master only. I will cherry-pick/back-patch once the peer review passed. If it does not apply cleanly, I'll request a second peer review.
Why $this->questionanswercache->set($clean, $clean); ?
I see, the existing code is wrong (almost certainly). Specifically, the line $newitemid = $data->id; should say $newitemid = $answer->id;
Given that, you need to say $this->questionanswercache->set($clean, $answer->id); and then
if ($answerid = $this->questionanswercache->get($data->answertext)) { $newitemid = $answerid; }
(I think.)
Problem code was introduced in MDL-30018. https://github.com/timhunt/moodle/commit/a306ceb1ecda39cbd7f8da8346c0ae9dcb84dcb1. Compare the new code with the old code just above it to see the problem.
Thanks again Tim. I've adjusted the code in line with your comments. I've pushed it to github, but I've not yet had a chance to fully test. So I'm not going to push to peer review officially until I've done that.
That code now looks logically correct. I hope it works it testing.
Note that you have incorrect indent at https://github.com/mr-russ/moodle/compare/master...MDL-40893-master#L0R171
I decided to re-implement this using a local class cache. The reasons were;
- The restriction and overhead of sha1 does cost time for little benefit.
- This allows me to backport to 2.3 where MUC is not available
- We are only caching a single question in a single place in the code, MUC doesn't do a lot there.
I've reprofiled the function with the following results;
| Function Name | Calls Diff | Calls Diff% | Incl. Wall Diff (microsec) | IWall Diff% | Incl. CPU Diff (microsec) | ICpu Diff% | Incl. MemUse Diff (bytes) | IMemUse Diff% | Incl. PeakMemUse Diff (bytes) | IPeakMemUse Diff% |
|---|---|---|---|---|---|---|---|---|---|---|
| Current Function | ||||||||||
| restore_qtype_plugin::process_question_answer | 0 | 0.0% | -71,025,416 | -71.1% | -37,674,324 | -57.8% | -520,536 | -111.7% | 0 | 0.0% |
| Exclusive Metrics Diff for Current Function | 35,133 | 0.0% | 275,999 | 0.7% | -43,693,552 | -8394.0% | 0 | N/A% | ||
| Parent function | ||||||||||
| restore_structure_step::process | 0 | N/A% | -71,025,416 | -100.0% | -37,674,324 | -100.0% | -520,536 | -100.0% | 0 | N/A% |
| Child functions | ||||||||||
| moodle_database::get_field_sql | -25,233 | -136.9% | -73,093,410 | -102.9% | -47,199,011 | -125.3% | -4,288,184 | -823.8% | 0 | N/A% |
| moodle_database::get_records | 6,823 | 37.0% | 23,661,716 | 33.3% | 17,861,121 | 47.4% | 31,965,688 | 6140.9% | 0 | N/A% |
| restore_plugin::set_mapping | 0 | 0.0% | -13,815,813 | -19.5% | -5,024,246 | -13.3% | -268,448 | -51.6% | 0 | N/A% |
| restore_plugin::get_mappingid | 0 | 0.0% | -7,770,113 | -10.9% | -3,612,203 | -9.6% | -88,936 | -17.1% | 0 | N/A% |
| moodle_database::sql_compare_text | -50,466 | -273.8% | -288,832 | -0.4% | -460,021 | -1.2% | -2,688 | -0.5% | 0 | N/A% |
| preg_replace | 50,446 | 273.7% | 240,405 | 0.3% | 416,029 | 1.1% | 15,798,728 | 3035.1% | 0 | N/A% |
| restore_plugin::get_new_parentid | 0 | 0.0% | 28,108 | 0.0% | 116,006 | 0.3% | 28,624 | 5.5% | 0 | N/A% |
| restore_plugin::get_old_parentid | 0 | 0.0% | -20,962 | -0.0% | -60,000 | -0.2% | 28,232 | 5.4% | 0 | N/A% |
| array_key_exists | 0 | 0.0% | -1,648 | -0.0% | 12,002 | 0.0% | 0 | 0.0% | 0 | N/A% |
The information above can be interpreted as follows;
- set_mapping, get_mappindid changes are noise.
- get_field_sql is replaced by get_records for time cost.
- preg_replace now cleans all questions once, but the time is still smaller than the removed sql_compare_text.
Ignoring noise, it's about a 50 second improvement on a 1400 second restore. When implementing MDL-40581, we still see a 50 second improvement even though the restore time is below 800 seconds. Possibly more importantly it will now match full questions answers in all cases. There is no fallback, the cleaning is also done for all answers.
Final PHPUnit tests are running now. If a code review is successful, I'll backport and request as status update to integration review.
[Y] Syntax
[Y] Whitespace
[Y] Output
[Y] Language
[Y] Databases
[Y] Testing
[-] Security
[-] Documentation
[Y] Git
[Y] Sanity check
Looking good. Let me know when this is ready for Integration.
Okay, all branches made and rebased against the current week. I'm sure I'll get to rebase on Friday but we are ready for integration review now.
The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week.
TIA and ciao 
The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week.
TIA and ciao
Integrated to master, 25 and 24 - thanks Russell
Passing, thanks!
Thanks for your efforts. This issue is one of the outstanding issues that passed all our testing and was accepted into Moodle this week.
Hurray!
In
MDL-30018, Tim Hunt suggested in peer-review that we should be doing process question answers per question. It was discussed that it was not easy to do that.However now with MUC, we can cache the results of a single question in the function ready for the next call. This will reduce database queries to the number of questions rather than the number of answers.