Moodle

process_question_answer queries the DB for each answer rather than per questions

Details

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

Bug - A problem which impairs or prevents Moodle from functioning correctly. MDL-30018 Quiz Duplication With Carriage Return Results in a Fatal Error

  • Critical - Crashes server, loss of data, severe memory leak
  • Closed - The issue is considered finished, the resolution is correct. Issues which are closed should not be reopened.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Russell Smith added a comment -

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.

Show
Russell Smith added a comment - 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.
Hide
Permalink
Russell Smith added a comment -

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.

Show
Russell Smith added a comment - 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.
Hide
Permalink
Russell Smith added a comment -

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%
Show
Russell Smith added a comment - 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%
Hide
Permalink
Russell Smith added a comment -

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.

Show
Russell Smith added a comment - 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.
Hide
Permalink
Tim Hunt added a comment -

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

Show
Tim Hunt added a comment - 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.)
Hide
Permalink
Tim Hunt added a comment -

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.

Show
Tim Hunt added a comment - 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.
Hide
Permalink
Russell Smith added a comment -

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.

Show
Russell Smith added a comment - 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.
Hide
Permalink
Tim Hunt added a comment -

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

Show
Tim Hunt added a comment - 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
Hide
Permalink
Russell Smith added a comment - - edited

I decided to re-implement this using a local class cache. The reasons were;

  1. The restriction and overhead of sha1 does cost time for little benefit.
  2. This allows me to backport to 2.3 where MUC is not available
  3. 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.

Show
Russell Smith added a comment - - edited 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.
Hide
Permalink
Tim Hunt added a comment -

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

Show
Tim Hunt added a comment - [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.
Hide
Permalink
Russell Smith added a comment -

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.

Show
Russell Smith added a comment - 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.
Hide
Permalink
Tim Hunt added a comment -

Submitting for integration.

Show
Tim Hunt added a comment - Submitting for integration.
Hide
Permalink
Dan Poltawski added a comment -

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

Show
Dan Poltawski added a comment - 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
Hide
Permalink
Dan Poltawski added a comment -

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

Show
Dan Poltawski added a comment - 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
Hide
Permalink
Dan Poltawski added a comment -

Integrated to master, 25 and 24 - thanks Russell

Show
Dan Poltawski added a comment - Integrated to master, 25 and 24 - thanks Russell
Hide
Permalink
Frédéric Massart added a comment -

Passing, thanks!

Show
Frédéric Massart added a comment - Passing, thanks!
Hide
Permalink
Damyon Wiese added a comment -

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!

Show
Damyon Wiese added a comment - 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!

People

Vote (0)
Watch (5)

Dates

  • Created:
    Updated:
    Resolved: