Moodle
  1. Moodle
  2. MDL-40893

process_question_answer queries the DB for each answer rather than per questions

    Details

    • 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

          Activity

          Hide
          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
          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
          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
          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
          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
          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
          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
          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
          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
          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
          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
          Tim Hunt added a comment -

          Submitting for integration.

          Show
          Tim Hunt added a comment - Submitting for integration.
          Hide
          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
          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
          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
          Frédéric Massart added a comment -

          Passing, thanks!

          Show
          Frédéric Massart added a comment - Passing, thanks!
          Hide
          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

            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: