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

          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