Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-40893

process_question_answer queries the DB for each answer rather than per questions

    Details

    • Testing Instructions:
      Hide

      1. Create a quiz with a Multiple choice question.
      2. Duplicate the Quiz in the course.

      Ensure no errors.
      Ensure the answers to the questions are restored correctly by attempting the quiz.

      Show
      1. Create a quiz with a Multiple choice question. 2. Duplicate the Quiz in the course. Ensure no errors. Ensure the answers to the questions are restored correctly by attempting the quiz.
    • Affected Branches:
      MOODLE_25_STABLE
    • Fixed Branches:
      MOODLE_24_STABLE, MOODLE_25_STABLE
    • Pull Master Branch:
      MDL-40893-master

      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.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

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

              Submitting for integration.

              Show
              timhunt Tim Hunt added a comment - Submitting for integration.
              Hide
              poltawski 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
              poltawski 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
              poltawski 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
              poltawski 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
              poltawski Dan Poltawski added a comment -

              Integrated to master, 25 and 24 - thanks Russell

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

              Passing, thanks!

              Show
              fred Frédéric Massart added a comment - Passing, thanks!
              Hide
              damyon 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 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:
                    Fix Release Date:
                    9/Sep/13