Moodle
  1. Moodle
  2. MDL-29520

Badly performing MySQL queries connected to questions

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 2.1.1, 2.2
    • Fix Version/s: 2.1.2
    • Component/s: Questions, Quiz
    • Labels:
    • Environment:
      MySQL server version: 5.0.77
    • Database:
      MySQL
    • Testing Instructions:
      Hide

      You need a database that already contains many quiz attempts. See some of the table sizes quoted in comments below.

      You also need to test this with MySQL (to verify the new code) and with another DB (to verify there are no regressions).

      1. Create a quiz
      2. Attempt it several times as different students.
      3. Go to the quiz reports, select all attempts, and delete them.
      4. Verify that it does not take too long, and that only the right quiz attempts are deleted. (You can probably do that by doing a row count of all the question_attempt* tables, and verifying that that after creating a lot of quiz attempts, and then deleting them, you get back to exactly the same number of rows. Of course, this requires no one else to be using quizzes on the server at the same time.)

      Show
      You need a database that already contains many quiz attempts. See some of the table sizes quoted in comments below. You also need to test this with MySQL (to verify the new code) and with another DB (to verify there are no regressions). 1. Create a quiz 2. Attempt it several times as different students. 3. Go to the quiz reports, select all attempts, and delete them. 4. Verify that it does not take too long, and that only the right quiz attempts are deleted. (You can probably do that by doing a row count of all the question_attempt* tables, and verifying that that after creating a lot of quiz attempts, and then deleting them, you get back to exactly the same number of rows. Of course, this requires no one else to be using quizzes on the server at the same time.)
    • Workaround:
      Hide

      1. Use a real database like Postgres.

      2. Or this code change will fix the problem for MySQL users, although there are issues with the code that we can't use it in the standard Moodle release.

      The problem is in code /question/engine/datalib.php

      For example starting at line 662:

      $this->db->delete_records_select('question_attempt_step_data', "attemptstepid IN (
      SELECT qas.id
      FROM

      {question_attempts} qa
      JOIN {question_attempt_steps} qas ON qas.questionattemptid = qa.id
      WHERE $where)", $params);

      Why this MySQL query is slow: http://forums.mysql.com/read.php?24,5240,5240
      Updated code, that works much faster:

      $stepids = $this->db->get_fieldset_sql("
      SELECT qas.id
      FROM {question_attempts}

      qa
      JOIN

      {question_attempt_steps}

      qas ON qas.questionattemptid = qa.id
      WHERE $where", $params);
      if (!empty($stepids))

      { list($sqlin, $delparams) = $this->db->get_in_or_equal($stepids); $this->db->delete_records_select('question_attempt_step_data', "attemptstepid $sqlin", $delparams); }

      Similar problems also at lines:
      668-671,
      696-699.

      datalib.php file, with this fix: https://github.com/mangus/moodle/blob/7259b04e27ec4e5d03539f3355791ab451e3fe0c/question/engine/datalib.php

      Show
      1. Use a real database like Postgres. 2. Or this code change will fix the problem for MySQL users, although there are issues with the code that we can't use it in the standard Moodle release. The problem is in code /question/engine/datalib.php For example starting at line 662: $this->db->delete_records_select('question_attempt_step_data', "attemptstepid IN ( SELECT qas.id FROM {question_attempts} qa JOIN {question_attempt_steps} qas ON qas.questionattemptid = qa.id WHERE $where)", $params); Why this MySQL query is slow: http://forums.mysql.com/read.php?24,5240,5240 Updated code, that works much faster: $stepids = $this->db->get_fieldset_sql(" SELECT qas.id FROM {question_attempts} qa JOIN {question_attempt_steps} qas ON qas.questionattemptid = qa.id WHERE $where", $params); if (!empty($stepids)) { list($sqlin, $delparams) = $this->db->get_in_or_equal($stepids); $this->db->delete_records_select('question_attempt_step_data', "attemptstepid $sqlin", $delparams); } Similar problems also at lines: 668-671, 696-699. datalib.php file, with this fix: https://github.com/mangus/moodle/blob/7259b04e27ec4e5d03539f3355791ab451e3fe0c/question/engine/datalib.php
    • Affected Branches:
      MOODLE_21_STABLE, MOODLE_22_STABLE
    • Fixed Branches:
      MOODLE_21_STABLE
    • Pull from Repository:
    • Pull Master Branch:
    • Rank:
      19233

      Description

      Example: deleting question attempts on large MySQL database can take up to 10 minutes and is wasting database server resources.

      Large database in this case means:
      question_attempts table – ~ 1.5M rows
      question_attempt_steps table – ~ 4M rows
      question_attempt_step_data table – ~ 9M rows

      The fix described in Workaround makes this action to take less then some seconds.

      1. testsql_performing_badly.php
        8 kB
        Eloy Lafuente (stronk7)
      2. testsql_performing_badly.txt
        3 kB
        Eloy Lafuente (stronk7)
      3. variables
        6 kB
        Mart Mangus

        Issue Links

          Activity

          Hide
          Tim Hunt added a comment -

          That is totally ridiculous, but then this is MySQL we are talking about.

          Your suggested 'solution' is no good. Not only is it fundamentally bad for performance to drag all the IDs over the network to PHP, only to send them back to the DB server, this will break on some database systems that have a maximum length limit on IN () lists (for example Oracle).

          So, the problem seems to be that MySQL thinks that the subquery is a correlated subquery, even though it clearly isn't. I see, according to http://forums.mysql.com/read.php?24,5240,5266#msg-5266 that is build in brain-dead-ness. Can we find a way to rewrite the query that is comprehensible to MySQL's little brain, and which is also works on all our supported databases. I seem to remember that there is some issue with trying to use the DELETE ... JOIN syntax for cross-DB compatibility.

          Here's a thought. Does it do any good to change the SQL to IN (SELECT DISTINCT ...). Probably not, but worth a try.

          Oh, and by the way, your code is wrong. You should be using placeholders (that is, $DB->get_in_or_equal()) to build the second query.)

          Adding Eloy, our DB expert.

          Show
          Tim Hunt added a comment - That is totally ridiculous, but then this is MySQL we are talking about. Your suggested 'solution' is no good. Not only is it fundamentally bad for performance to drag all the IDs over the network to PHP, only to send them back to the DB server, this will break on some database systems that have a maximum length limit on IN () lists (for example Oracle). So, the problem seems to be that MySQL thinks that the subquery is a correlated subquery, even though it clearly isn't. I see, according to http://forums.mysql.com/read.php?24,5240,5266#msg-5266 that is build in brain-dead-ness. Can we find a way to rewrite the query that is comprehensible to MySQL's little brain, and which is also works on all our supported databases. I seem to remember that there is some issue with trying to use the DELETE ... JOIN syntax for cross-DB compatibility. Here's a thought. Does it do any good to change the SQL to IN (SELECT DISTINCT ...). Probably not, but worth a try. Oh, and by the way, your code is wrong. You should be using placeholders (that is, $DB->get_in_or_equal()) to build the second query.) Adding Eloy, our DB expert.
          Hide
          Mart Mangus added a comment - - edited

          Thanks for suggestions and tips.

          Here's a thought. Does it do any good to change the SQL to IN (SELECT DISTINCT ...). Probably not, but worth a try.

          That did not help (made queries even more slow).

          Can we find a way to rewrite the query that is comprehensible to MySQL's little brain, and which is also works on all our supported databases.

          Yes, the SQL query looks like that:

          DELETE FROM qasd
              USING question_attempts qa
                  JOIN question_attempt_steps qas ON qas.questionattemptid = qa.id
                  JOIN question_attempt_step_data qasd ON qasd.attemptstepid = qas.id
              WHERE qa.questionusageid = ?
          ;
          

          But moodle_database class seems not to support such queries?
          How to write such SQL code in Moodle?

          Because this is kind of critical in our production site, then we'll temporary use this fix: https://github.com/mangus/moodle/commit/f24c461ace9905f9875fca3b6862336b6b1e968a + https://github.com/mangus/moodle/commit/7259b04e27ec4e5d03539f3355791ab451e3fe0c

          Show
          Mart Mangus added a comment - - edited Thanks for suggestions and tips. Here's a thought. Does it do any good to change the SQL to IN (SELECT DISTINCT ...). Probably not, but worth a try. That did not help (made queries even more slow). Can we find a way to rewrite the query that is comprehensible to MySQL's little brain, and which is also works on all our supported databases. Yes, the SQL query looks like that: DELETE FROM qasd USING question_attempts qa JOIN question_attempt_steps qas ON qas.questionattemptid = qa.id JOIN question_attempt_step_data qasd ON qasd.attemptstepid = qas.id WHERE qa.questionusageid = ? ; But moodle_database class seems not to support such queries? How to write such SQL code in Moodle? Because this is kind of critical in our production site, then we'll temporary use this fix: https://github.com/mangus/moodle/commit/f24c461ace9905f9875fca3b6862336b6b1e968a + https://github.com/mangus/moodle/commit/7259b04e27ec4e5d03539f3355791ab451e3fe0c
          Hide
          Tim Hunt added a comment -

          You can do any sort of SQL in Moodle using $DB->execute.

          Looks like Postgres supports DELETE FROM ... USING ... syntax, but neither Oracle nor MS SQL server can deal with it. http://www.postgresql.org/docs/8.1/static/sql-delete.html implies that it is a non-standard extension.

          Show
          Tim Hunt added a comment - You can do any sort of SQL in Moodle using $DB->execute. Looks like Postgres supports DELETE FROM ... USING ... syntax, but neither Oracle nor MS SQL server can deal with it. http://www.postgresql.org/docs/8.1/static/sql-delete.html implies that it is a non-standard extension.
          Hide
          Anthony Borrow added a comment -

          Tim - Just to add that I have a production site that is also suffering from this issue. They are working to create a test server that we could use for testing any patches. Thanks for your work on this and let me know how I might be of help. Peace - Anthony

          Show
          Anthony Borrow added a comment - Tim - Just to add that I have a production site that is also suffering from this issue. They are working to create a test server that we could use for testing any patches. Thanks for your work on this and let me know how I might be of help. Peace - Anthony
          Hide
          Tim Hunt added a comment -

          Note that we do DELETE FROM x WHERE id IN (SELECT ...) in lots of places in Moodle. Look, for example, at the course reset code. forum_reset_userdata in mod/forum/lib.php would be a specific example.

          Also, it looks like they may have fixed this in mariadb 5.3 (that is the truly open-source fork of MySQL, not the evil Oracle-owned one).

          Show
          Tim Hunt added a comment - Note that we do DELETE FROM x WHERE id IN (SELECT ...) in lots of places in Moodle. Look, for example, at the course reset code. forum_reset_userdata in mod/forum/lib.php would be a specific example. Also, it looks like they may have fixed this in mariadb 5.3 (that is the truly open-source fork of MySQL, not the evil Oracle-owned one).
          Hide
          Tim Hunt added a comment -

          Anthony, if you could test this using mariadb 5.3, that might be helpful. Don't know how easy it is to switch from MySQL to mariadb

          Show
          Tim Hunt added a comment - Anthony, if you could test this using mariadb 5.3, that might be helpful. Don't know how easy it is to switch from MySQL to mariadb
          Hide
          Tim Hunt added a comment - - edited

          Also, Eloy suggests that SQL like

          DELETE FROM question_attempt_step_data qasd
          WHERE EXISTS (
              SELECT 1
              FROM question_attempts qa
              JOIN question_attempt_steps qas ON qas.questionattemptid = qa.id
              WHERE qa.questionusageid = ? AND qasd.attemptstepid = qas.id
          )
          

          might be a way to make this work with good performance on all DBs.

          I find that difficult to believe, but it would be good to test this on MySQL.

          Show
          Tim Hunt added a comment - - edited Also, Eloy suggests that SQL like DELETE FROM question_attempt_step_data qasd WHERE EXISTS ( SELECT 1 FROM question_attempts qa JOIN question_attempt_steps qas ON qas.questionattemptid = qa.id WHERE qa.questionusageid = ? AND qasd.attemptstepid = qas.id ) might be a way to make this work with good performance on all DBs. I find that difficult to believe, but it would be good to test this on MySQL.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Clarification: I just think that the "EXISTS" alternative is always "faster" than the "IN" one. And how much "faster" it is, depends of the cardinality of each table and, of course, of the type of correlation between both (it can go from marginal faster to way more faster, but never be slower, based in my experience).

          Side-silly-note: Is is any index missing in those tables? Perhaps the problem there is that we are using both qa.id and qa.questionusageid in the same query and MySQL only is able to use one index per table on each query (if I'm not wrong), so we are accessing one of them by index but not the other, aka, full scan forced. One trivial way to check if that is the cause would be to create one index on both columns and see if it performs better that way.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Clarification: I just think that the "EXISTS" alternative is always "faster" than the "IN" one. And how much "faster" it is, depends of the cardinality of each table and, of course, of the type of correlation between both (it can go from marginal faster to way more faster, but never be slower, based in my experience). Side-silly-note: Is is any index missing in those tables? Perhaps the problem there is that we are using both qa.id and qa.questionusageid in the same query and MySQL only is able to use one index per table on each query (if I'm not wrong), so we are accessing one of them by index but not the other, aka, full scan forced. One trivial way to check if that is the cause would be to create one index on both columns and see if it performs better that way. Ciao
          Hide
          Rick Cook added a comment -

          This query issue extends past deleting questions. When trying to regrade a test, the subquery that is used runs through all 4.7 million records in the mdl_question_attempt_step_data table. Since this subquery is executed multiple times it is causing the process to take 15 minutes or more and it consumes 100% of the processor.

          Show
          Rick Cook added a comment - This query issue extends past deleting questions. When trying to regrade a test, the subquery that is used runs through all 4.7 million records in the mdl_question_attempt_step_data table. Since this subquery is executed multiple times it is causing the process to take 15 minutes or more and it consumes 100% of the processor.
          Hide
          Mart Mangus added a comment -
          DELETE FROM question_attempt_step_data qasd
          WHERE EXISTS (
              SELECT 1
              FROM question_attempts qa
              JOIN question_attempt_steps qas ON qas.questionattemptid = qa.id
              WHERE qa.questionusageid = ? AND qasd.attemptstepid = qas.id
          )
          

          There is a problem for MySQL with this one also: http://bugs.mysql.com/bug.php?id=5123

          I tested performance of this with similar SELECT query – that did perform about 2 times faster (original query 1 min 14.27 sec, this one 39.24 sec), but this is still very bad.

          Indexes

          No missing indexes.

          Adding index for testing to see if it helps:

          CREATE INDEX performance_test ON question_attempts (id, questionusageid);
          
          • Original "DELETE ... WHERE IN" – 55.57 sec
          • "SELECT ... WHERE EXISTS" – 32.86 sec

          Little improvement, but still not very helpful.

          Show
          Mart Mangus added a comment - DELETE FROM question_attempt_step_data qasd WHERE EXISTS ( SELECT 1 FROM question_attempts qa JOIN question_attempt_steps qas ON qas.questionattemptid = qa.id WHERE qa.questionusageid = ? AND qasd.attemptstepid = qas.id ) There is a problem for MySQL with this one also: http://bugs.mysql.com/bug.php?id=5123 I tested performance of this with similar SELECT query – that did perform about 2 times faster (original query 1 min 14.27 sec, this one 39.24 sec), but this is still very bad. Indexes No missing indexes. Adding index for testing to see if it helps: CREATE INDEX performance_test ON question_attempts (id, questionusageid); Original "DELETE ... WHERE IN" – 55.57 sec "SELECT ... WHERE EXISTS" – 32.86 sec Little improvement, but still not very helpful.
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          Mart, thanks for the complete info. 5 more questions:

          1) Which cardinality have those 3 tables. How many records are deleted in your tests on each execution (10, 100, 1000 ... 10^n accuracy is enough).

          2) Which engine are you using MyISAM / InnoDB. Version? OS?

          3) Can you attach / send me privately the complete "Server variables and settings" page from phpmyadmin to see how you've it configured? Pool / caches and friends.

          Those were aimed to simulate your situation here. Now:

          4) Do you run check / optimize and specially analyze your DB (those tables) from time to time? Any difference after that? It can cause dramatic differences if statistics haven't been run for a log time and numbers (cardinality, grow differences...) have changed a lot.

          5) If 1) does not helps, surely we'll end needing to try "DELETE USING" / "DELETE JOIN" (not cross-db, will require conditional coding for each DB), or, alternatively, if continues being so slooow we can try to put target ids into temp table and then delete from it (surely cross-db).

          Finally, one side note that we should not forget: DELETE operations are the most heavy operations performed by DBs. Specially if running under ACID transaction modes, where the whole recordset to be deleted must be calculated and kept available for the rest of sessions. It requires time and huge pool sizes. Not to talk about the time needed to rebuild indexes, write logs... just one reminder, not an excuse

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - - edited Mart, thanks for the complete info. 5 more questions: 1) Which cardinality have those 3 tables. How many records are deleted in your tests on each execution (10, 100, 1000 ... 10^n accuracy is enough). 2) Which engine are you using MyISAM / InnoDB. Version? OS? 3) Can you attach / send me privately the complete "Server variables and settings" page from phpmyadmin to see how you've it configured? Pool / caches and friends. Those were aimed to simulate your situation here. Now: 4) Do you run check / optimize and specially analyze your DB (those tables) from time to time? Any difference after that? It can cause dramatic differences if statistics haven't been run for a log time and numbers (cardinality, grow differences...) have changed a lot. 5) If 1) does not helps, surely we'll end needing to try "DELETE USING" / "DELETE JOIN" (not cross-db, will require conditional coding for each DB), or, alternatively, if continues being so slooow we can try to put target ids into temp table and then delete from it (surely cross-db). Finally, one side note that we should not forget: DELETE operations are the most heavy operations performed by DBs. Specially if running under ACID transaction modes, where the whole recordset to be deleted must be calculated and kept available for the rest of sessions. It requires time and huge pool sizes. Not to talk about the time needed to rebuild indexes, write logs... just one reminder, not an excuse Ciao
          Hide
          Eloy Lafuente (stronk7) added a comment -

          PS: About the bug above ( http://bugs.mysql.com/bug.php?id=5123 ) it sounds to me that the solution was not to use table aliases for the table being deleted but use always its complete name as prefix in the subqueries. Not sure if the problem persists or no yet, but I'm 85% confident that was the workaround).

          Show
          Eloy Lafuente (stronk7) added a comment - PS: About the bug above ( http://bugs.mysql.com/bug.php?id=5123 ) it sounds to me that the solution was not to use table aliases for the table being deleted but use always its complete name as prefix in the subqueries. Not sure if the problem persists or no yet, but I'm 85% confident that was the workaround).
          Hide
          Tim Hunt added a comment -

          That MySQL bug definitely does not apply. The problem it refers to is using the same table that is being deleted in the sub-query. We don't need to do that.

          Eloy, surely UPDATE is worse than DELETE in transactions. That needs to keep both the old and new states of the rows, not just the old rows. Anyway, it is clearly a solvable problem for database makers, since Postgres handles it just fine.

          Typical cardinalities are

          #qa = big
          #qas ~= #qa * 3 // (3 == average number of steps per question attempt)
          #qasd ~= #qas * 3 // (3 == average number of bits of data per step)

          and typically we will be deleting a few qa. That is, all the qa in one quiz attempt, and there is one qa for each question in the quiz. Right at the top of this bug are some acutual numbers.

          Show
          Tim Hunt added a comment - That MySQL bug definitely does not apply. The problem it refers to is using the same table that is being deleted in the sub-query. We don't need to do that. Eloy, surely UPDATE is worse than DELETE in transactions. That needs to keep both the old and new states of the rows, not just the old rows. Anyway, it is clearly a solvable problem for database makers, since Postgres handles it just fine. Typical cardinalities are #qa = big #qas ~= #qa * 3 // (3 == average number of steps per question attempt) #qasd ~= #qas * 3 // (3 == average number of bits of data per step) and typically we will be deleting a few qa. That is, all the qa in one quiz attempt, and there is one qa for each question in the quiz. Right at the top of this bug are some acutual numbers.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Offtopic: Tim, when you want, we can, under standard conditions, weight and compare deleting and updating. But I'm not going to discuss about that here.

          I asked for exact configuration to Mart because I created here one quick test, with 3 tables (not the real ones) and having one factor of 10x number of records between them. (10^4, 10^5 and 10^6 records) indexed similarly. And I got constant deletion times of 0.2 secs here (not specially quick notebook running MySQL 5.5). Note that 5.5 introduced some improvements about subquery handling.

          So I'm aiming to see if the problem is something in the server (missing analyze / configuration / MySQL version...) before jumping to dbfamily specific alternatives.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Offtopic: Tim, when you want, we can, under standard conditions, weight and compare deleting and updating. But I'm not going to discuss about that here. I asked for exact configuration to Mart because I created here one quick test, with 3 tables (not the real ones) and having one factor of 10x number of records between them. (10^4, 10^5 and 10^6 records) indexed similarly. And I got constant deletion times of 0.2 secs here (not specially quick notebook running MySQL 5.5). Note that 5.5 introduced some improvements about subquery handling. So I'm aiming to see if the problem is something in the server (missing analyze / configuration / MySQL version...) before jumping to dbfamily specific alternatives. Ciao
          Hide
          Mart Mangus added a comment -

          1) Which cardinality have those 3 tables.

          question_attempts table – ~ 1.5M rows – cardinality (id): 1571521
          question_attempt_steps table – ~ 4M rows – cardinality (questionattemptid): 3793537
          question_attempt_step_data table – ~ 9M rows – cardinality (id): 8157577

          How many records are deleted in your tests on each execution (10, 100, 1000 ... 10^n accuracy is enough).

          I can run the same query multiple times (~ 10 deleted rows in first run), but dispite there is no deleted rows in next runs, it still takes more then 1 minute (Query OK, 0 rows affected (1 min 10.40 sec)).

          2) Which engine are you using MyISAM / InnoDB. Version? OS?

          InnoDB, server version: 5.0.77-log Source distribution, CentOS 5.3

          3) Can you attach / send me privately the complete "Server variables and settings" page from phpmyadmin to see how you've it configured? Pool / caches and friends.

          We dont have PHPMyAdmin, but i'll attach "SHOW VARIABLES;" command output – is this sufficient?

          4) Do you run check / optimize and specially analyze your DB (those tables) from time to time? Any difference after that? It can cause dramatic differences if statistics haven't been run for a log time and numbers (cardinality, grow differences...) have changed a lot.

          We don't run these periodically; tried "CHECK TABLE" and "OPTIMIZE TABLE" and "ANALYZE TABLE" for these 3 tables, but no improvement.

          Note that 5.5 introduced some improvements about subquery handling.

          I'll try to upgrade to 5.5 in some days to see if it makes difference.

          Show
          Mart Mangus added a comment - 1) Which cardinality have those 3 tables. question_attempts table – ~ 1.5M rows – cardinality (id): 1571521 question_attempt_steps table – ~ 4M rows – cardinality (questionattemptid): 3793537 question_attempt_step_data table – ~ 9M rows – cardinality (id): 8157577 How many records are deleted in your tests on each execution (10, 100, 1000 ... 10^n accuracy is enough). I can run the same query multiple times (~ 10 deleted rows in first run), but dispite there is no deleted rows in next runs, it still takes more then 1 minute (Query OK, 0 rows affected (1 min 10.40 sec)). 2) Which engine are you using MyISAM / InnoDB. Version? OS? InnoDB, server version: 5.0.77-log Source distribution, CentOS 5.3 3) Can you attach / send me privately the complete "Server variables and settings" page from phpmyadmin to see how you've it configured? Pool / caches and friends. We dont have PHPMyAdmin, but i'll attach "SHOW VARIABLES;" command output – is this sufficient? 4) Do you run check / optimize and specially analyze your DB (those tables) from time to time? Any difference after that? It can cause dramatic differences if statistics haven't been run for a log time and numbers (cardinality, grow differences...) have changed a lot. We don't run these periodically; tried "CHECK TABLE" and "OPTIMIZE TABLE" and "ANALYZE TABLE" for these 3 tables, but no improvement. Note that 5.5 introduced some improvements about subquery handling. I'll try to upgrade to 5.5 in some days to see if it makes difference.
          Hide
          Mart Mangus added a comment -

          Problematic MySQL server variables (maybe it's a configuration issue).

          Show
          Mart Mangus added a comment - Problematic MySQL server variables (maybe it's a configuration issue).
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          Thanks Mart!

          I've attached above two files:

          • testsql_performing_badly.php, one simpletest script used to build the case (the 3 tables) fill them and run all the possible queries under each DB-flavour in order to get the records deleted. You can execute it at any time in your (testing!) servers just putting it into under lib/simpletest and invoking it from admin->dev->unittests. It's not destructive at all, but better keep it away from any production machine.
          • testsql_performing_badly.txt, the results of the execution under the 4 DBs (mysl, postgresql, mssql and oracle). For mysql I executed the test with 20000, 100000 and 500000 attempts. For the rest only the 100000 one.

          Results are really clear:

          1) Subqueries in MySQL are really horrible. Times grow linearly, so any of the IN / EQUAL / EXISTS alternatives are nono there. Only the JOIN or de USING alternatives are viable ones for big tables.

          2) The rest of RDBMS perform subqueries really, really better, surely transforming them to sort of JOINs and other mechanishm. In general the worst alternative was the EQUAL one, with the IN being always better and the EXIST one beating them (specially under MSSQL and Oracle).

          3) The propietary solutions: USING under PostgreSQL and JOIN under MSSQL also work great but are slightly different from the MySQL ones (also propietary), see .php file.

          4) Disclaimer: The MySQL and PostgreSQL test were executed in my laptop natively. The MSSQL and Oracle ones in my laptop using virtual machine.

          Summary: my +1 goes to:

          1) Implement the JOIN solution for MySQL
          2) Implement the EXISTS solution for the other 3 (it's cross-db 100%)

          That is! Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - - edited Thanks Mart! I've attached above two files: testsql_performing_badly.php, one simpletest script used to build the case (the 3 tables) fill them and run all the possible queries under each DB-flavour in order to get the records deleted. You can execute it at any time in your (testing!) servers just putting it into under lib/simpletest and invoking it from admin->dev->unittests. It's not destructive at all, but better keep it away from any production machine. testsql_performing_badly.txt, the results of the execution under the 4 DBs (mysl, postgresql, mssql and oracle). For mysql I executed the test with 20000, 100000 and 500000 attempts. For the rest only the 100000 one. Results are really clear: 1) Subqueries in MySQL are really horrible. Times grow linearly, so any of the IN / EQUAL / EXISTS alternatives are nono there. Only the JOIN or de USING alternatives are viable ones for big tables. 2) The rest of RDBMS perform subqueries really, really better, surely transforming them to sort of JOINs and other mechanishm. In general the worst alternative was the EQUAL one, with the IN being always better and the EXIST one beating them (specially under MSSQL and Oracle). 3) The propietary solutions: USING under PostgreSQL and JOIN under MSSQL also work great but are slightly different from the MySQL ones (also propietary), see .php file. 4) Disclaimer: The MySQL and PostgreSQL test were executed in my laptop natively. The MSSQL and Oracle ones in my laptop using virtual machine. Summary: my +1 goes to: 1) Implement the JOIN solution for MySQL 2) Implement the EXISTS solution for the other 3 (it's cross-db 100%) That is! Ciao
          Hide
          Tim Hunt added a comment -

          OK then Eloy, what is the least-bad way for me to use different SQL for different DB types in my code?

          Show
          Tim Hunt added a comment - OK then Eloy, what is the least-bad way for me to use different SQL for different DB types in my code?
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          I think that, for stable current codebase if should be something like:

              $dbfamily = $DB->get_dbfamily();
              if ($dbfamily == 'xxxx') {
                  ....
              } else if ($dbfamily == 'yyyy') {
                  ....
              } else {
                  ....
              }
          

          Or alternatively switch / case syntax (if the code to put on each case in not a monster). Both possible syntaxes always with the final (else/default) for the most-used case.

          In the mean time, I'm trying to implement sort of delete_records_join() helper / dml method to see if it can be done automatically, so you pass the table to delete from, the complete join + where and it works out the better way for each DB. But that won't land into stables right now.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - - edited I think that, for stable current codebase if should be something like: $dbfamily = $DB->get_dbfamily(); if ($dbfamily == 'xxxx') { .... } else if ($dbfamily == 'yyyy') { .... } else { .... } Or alternatively switch / case syntax (if the code to put on each case in not a monster). Both possible syntaxes always with the final (else/default) for the most-used case. In the mean time, I'm trying to implement sort of delete_records_join() helper / dml method to see if it can be done automatically, so you pass the table to delete from, the complete join + where and it works out the better way for each DB. But that won't land into stables right now. Ciao
          Hide
          Tim Hunt added a comment -

          Proposed (not tested) fix in https://github.com/timhunt/moodle/compare/master...MDL-29520_eloy_wont_like_it.

          However, Eloy is working on a more general solution (a new $DB->delete_records_join_select method MDL-29589) which should let us fix this in a better way. I hope I can wait for that.

          Show
          Tim Hunt added a comment - Proposed (not tested) fix in https://github.com/timhunt/moodle/compare/master...MDL-29520_eloy_wont_like_it . However, Eloy is working on a more general solution (a new $DB->delete_records_join_select method MDL-29589 ) which should let us fix this in a better way. I hope I can wait for that.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          I would +1 to send this to integration if:

          1) You change the branch name, LOL.
          2) We agree this will be replaced by generic solution once implemented and tested.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - I would +1 to send this to integration if: 1) You change the branch name, LOL. 2) We agree this will be replaced by generic solution once implemented and tested. Ciao
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Replacing test php file by slightly modified one showing the SQL differences a bit better.

          Show
          Eloy Lafuente (stronk7) added a comment - Replacing test php file by slightly modified one showing the SQL differences a bit better.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Replaced php test to be able to run the $DB->delete_records_join_select() once it's available

          Show
          Eloy Lafuente (stronk7) added a comment - Replaced php test to be able to run the $DB->delete_records_join_select() once it's available
          Hide
          Tim Hunt added a comment -

          Right, pushed for integration, which is really naughty, because I don't have a copy of MySQL to test this on.

          Please could someone test my new patches on MySQL, ideally before integration starts on Monday (New Zealand time).

          If no-one has tested it before then, then please test it yourselves, integrators, or make the issue wait for another week. (Perhaps I should change this issue to be in peer-review state?)

          Show
          Tim Hunt added a comment - Right, pushed for integration, which is really naughty, because I don't have a copy of MySQL to test this on. Please could someone test my new patches on MySQL, ideally before integration starts on Monday (New Zealand time). If no-one has tested it before then, then please test it yourselves, integrators, or make the issue wait for another week. (Perhaps I should change this issue to be in peer-review state?)
          Hide
          Rob added a comment -

          I just tested on my production site. Deleting a quiz took only a few seconds. Without the fix, it takes several minutes. With the file linked at the top of this page, it takes about 45 seconds. However, with Tim's fix, I get an error when previewing a quiz as a teacher. The preview is fine the first attempt, but on subsequent attempts I get an error. I have pasted it below (debugging on).

          Coding error detected, it must be fixed by a programmer: PHP catchable fatal error

          More information about this error
          Debug info: Argument 1 passed to question_engine_data_mapper::delete_usage_records_for_mysql() must be an instance of qubaid_condition, none given, called in /srv/www/htdocs/question/engine/datalib.php on line 663 and defined
          Stack trace:

          line 359 of /lib/setuplib.php: coding_exception thrown
          line 692 of /question/engine/datalib.php: call to default_error_handler()
          line 663 of /question/engine/datalib.php: call to question_engine_data_mapper->delete_usage_records_for_mysql()
          line 111 of /question/engine/lib.php: call to question_engine_data_mapper->delete_questions_usage_by_activities()
          line 102 of /question/engine/lib.php: call to question_engine::delete_questions_usage_by_activities()
          line 150 of /mod/quiz/locallib.php: call to question_engine::delete_questions_usage_by_activity()
          line 180 of /mod/quiz/locallib.php: call to quiz_delete_attempt()
          line 110 of /mod/quiz/startattempt.php: call to quiz_delete_previews()

          Show
          Rob added a comment - I just tested on my production site. Deleting a quiz took only a few seconds. Without the fix, it takes several minutes. With the file linked at the top of this page, it takes about 45 seconds. However, with Tim's fix, I get an error when previewing a quiz as a teacher. The preview is fine the first attempt, but on subsequent attempts I get an error. I have pasted it below (debugging on). Coding error detected, it must be fixed by a programmer: PHP catchable fatal error More information about this error Debug info: Argument 1 passed to question_engine_data_mapper::delete_usage_records_for_mysql() must be an instance of qubaid_condition, none given, called in /srv/www/htdocs/question/engine/datalib.php on line 663 and defined Stack trace: line 359 of /lib/setuplib.php: coding_exception thrown line 692 of /question/engine/datalib.php: call to default_error_handler() line 663 of /question/engine/datalib.php: call to question_engine_data_mapper->delete_usage_records_for_mysql() line 111 of /question/engine/lib.php: call to question_engine_data_mapper->delete_questions_usage_by_activities() line 102 of /question/engine/lib.php: call to question_engine::delete_questions_usage_by_activities() line 150 of /mod/quiz/locallib.php: call to question_engine::delete_questions_usage_by_activity() line 180 of /mod/quiz/locallib.php: call to quiz_delete_attempt() line 110 of /mod/quiz/startattempt.php: call to quiz_delete_previews()
          Hide
          Antti Andreimann added a comment -

          Tested on my laptop.
          Got a following error when trying to delete an attempt:

          Coding error detected, it must be fixed by a programmer: PHP catchable fatal error

          More information about this error
          Debug info: Argument 1 passed to question_engine_data_mapper::delete_usage_records_for_mysql() must be an instance of qubaid_condition, none given, called in /home/anttix/products/moodle/2.1+/question/engine/datalib.php on line 663 and defined
          Stack trace:

          line 359 of /lib/setuplib.php: coding_exception thrown
          line 692 of /question/engine/datalib.php: call to default_error_handler()
          line 663 of /question/engine/datalib.php: call to question_engine_data_mapper->delete_usage_records_for_mysql()
          line 111 of /question/engine/lib.php: call to question_engine_data_mapper->delete_questions_usage_by_activities()
          line 102 of /question/engine/lib.php: call to question_engine::delete_questions_usage_by_activities()
          line 150 of /mod/quiz/locallib.php: call to question_engine::delete_questions_usage_by_activity()
          line 362 of /mod/quiz/report/attemptsreport.php: call to quiz_delete_attempt()
          line 144 of /mod/quiz/report/overview/report.php: call to quiz_attempt_report->delete_selected_attempts()
          line 100 of /mod/quiz/report.php: call to quiz_overview_report->display()

          Show
          Antti Andreimann added a comment - Tested on my laptop. Got a following error when trying to delete an attempt: Coding error detected, it must be fixed by a programmer: PHP catchable fatal error More information about this error Debug info: Argument 1 passed to question_engine_data_mapper::delete_usage_records_for_mysql() must be an instance of qubaid_condition, none given, called in /home/anttix/products/moodle/2.1+/question/engine/datalib.php on line 663 and defined Stack trace: line 359 of /lib/setuplib.php: coding_exception thrown line 692 of /question/engine/datalib.php: call to default_error_handler() line 663 of /question/engine/datalib.php: call to question_engine_data_mapper->delete_usage_records_for_mysql() line 111 of /question/engine/lib.php: call to question_engine_data_mapper->delete_questions_usage_by_activities() line 102 of /question/engine/lib.php: call to question_engine::delete_questions_usage_by_activities() line 150 of /mod/quiz/locallib.php: call to question_engine::delete_questions_usage_by_activity() line 362 of /mod/quiz/report/attemptsreport.php: call to quiz_delete_attempt() line 144 of /mod/quiz/report/overview/report.php: call to quiz_attempt_report->delete_selected_attempts() line 100 of /mod/quiz/report.php: call to quiz_overview_report->display()
          Hide
          Antti Andreimann added a comment -

          Adding argument to delete_usage_records_for_mysql function on line 663 at question/engine/datalib.php will help (works for me now). However the DB in my laptop is small so I cannot comment on performance.

          --- question/engine/datalib.php.orig	2011-10-01 20:37:30.000000000 +0300
          +++ question/engine/datalib.php	2011-10-01 20:34:49.000000000 +0300
          @@ -660,7 +660,7 @@
                   }
           
                   if ($this->db->get_dbfamily() == 'mysql') {
          -            $this->delete_usage_records_for_mysql();
          +            $this->delete_usage_records_for_mysql($qubaids);
                       return;
                   }
          
          Show
          Antti Andreimann added a comment - Adding argument to delete_usage_records_for_mysql function on line 663 at question/engine/datalib.php will help (works for me now). However the DB in my laptop is small so I cannot comment on performance. --- question/engine/datalib.php.orig 2011-10-01 20:37:30.000000000 +0300 +++ question/engine/datalib.php 2011-10-01 20:34:49.000000000 +0300 @@ -660,7 +660,7 @@ } if ($this->db->get_dbfamily() == 'mysql') { - $this->delete_usage_records_for_mysql(); + $this->delete_usage_records_for_mysql($qubaids); return; }
          Hide
          Eloy Lafuente (stronk7) added a comment -

          yup, it seems this needs some love... thanks for pre-testing! I'll halt awaiting for Tim's fix.

          Show
          Eloy Lafuente (stronk7) added a comment - yup, it seems this needs some love... thanks for pre-testing! I'll halt awaiting for Tim's fix.
          Hide
          Tim Hunt added a comment -

          OK, commits re=based.

          Show
          Tim Hunt added a comment - OK, commits re=based.
          Hide
          Antti Andreimann added a comment -

          2.1 branch works for me now. Still can't comment on performance though.

          Show
          Antti Andreimann added a comment - 2.1 branch works for me now. Still can't comment on performance though.
          Hide
          Mart Mangus added a comment -

          Tested the fix in our conditions (database as in Description of this issue) and the actions that took multiple minutes before took some seconds now!

          Show
          Mart Mangus added a comment - Tested the fix in our conditions (database as in Description of this issue) and the actions that took multiple minutes before took some seconds now!
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          Tim, I've seen you've added one more use for the custom mysql deletions: delete_attempt_steps_for_mysql()

          It annoyed me a bit to see the 1st param there named "test". Could it be renamed to something more "final"? (sql, attemptslist, qaidssql or whatever)

          Ciao

          Edited: Also, tiny detail: "This funciton is a work-around..."

          Show
          Eloy Lafuente (stronk7) added a comment - - edited Tim, I've seen you've added one more use for the custom mysql deletions: delete_attempt_steps_for_mysql() It annoyed me a bit to see the 1st param there named "test". Could it be renamed to something more "final"? (sql, attemptslist, qaidssql or whatever) Ciao Edited: Also, tiny detail: "This funciton is a work-around..."
          Hide
          Tim Hunt added a comment -

          Well, the variable is called $test in the function I re-factored this out of. It is a snipped of SQL code that is a $test, use as WHERE column $test. I think the variable name is OK, and the patch has been tested as-is. If I edit the patch there is a risk of breaking something.

          I could fix the comment typo (tomorrow), or you could, or you could integrate it as is. Let me know which you prefer.

          Show
          Tim Hunt added a comment - Well, the variable is called $test in the function I re-factored this out of. It is a snipped of SQL code that is a $test, use as WHERE column $test. I think the variable name is OK, and the patch has been tested as-is. If I edit the patch there is a risk of breaking something. I could fix the comment typo (tomorrow), or you could, or you could integrate it as is. Let me know which you prefer.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          yeah, i just ask you for amending those trivial changes to avoid un-useful history (if I add extra commit) or to break your history (if I amend your commit). But I've not problem at all about amending if you give me a global "ok" about that.

          With it, I'll be amending these automatically in the future (comments / typos) and adding extra commit if something obvious was wrong in code.

          Sounds ok? Do I have your global "ok"? Should I start with this?

          About $test, well "risk of breaking anything" by changing two "test" occurrences to something more meaningful... hehe, sounds a bit excessive. In any case it's not a reason to reject the patch, just a suggestion for improve (readability) it. So feel free to ignore it.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - yeah, i just ask you for amending those trivial changes to avoid un-useful history (if I add extra commit) or to break your history (if I amend your commit). But I've not problem at all about amending if you give me a global "ok" about that. With it, I'll be amending these automatically in the future (comments / typos) and adding extra commit if something obvious was wrong in code. Sounds ok? Do I have your global "ok"? Should I start with this? About $test, well "risk of breaking anything" by changing two "test" occurrences to something more meaningful... hehe, sounds a bit excessive. In any case it's not a reason to reject the patch, just a suggestion for improve (readability) it. So feel free to ignore it. Ciao
          Hide
          Eloy Lafuente (stronk7) added a comment -

          After chat... amending + integrating...

          Show
          Eloy Lafuente (stronk7) added a comment - After chat... amending + integrating...
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Amended and integrated, thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Amended and integrated, thanks!
          Hide
          Rajesh Taneja added a comment -

          Deletion is much faster then before
          Thanks for fixing this Tim.

          Show
          Rajesh Taneja added a comment - Deletion is much faster then before Thanks for fixing this Tim.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          git repositories have been updated with your awesome changes, thanks! Closing.

          Show
          Eloy Lafuente (stronk7) added a comment - git repositories have been updated with your awesome changes, thanks! Closing.
          Hide
          Ryan Smith added a comment -

          We upgraded to the latest version of Moodle late last week that contained this fixes. Now, when trying to regrade a quiz, we get an error writing to the database. This is a critical problem! Everything was working fine (well, the operations were REALLY SLOW) before this fix was released.

          The error said to turn debugging on, so I did, and these errors appeared in the Apache error log:

          [Sun Oct 09 12:08:39 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: Database transaction aborted automatically in C:\\Apache2\\htdocs
          moodle/mod/quiz/report.php, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: Database transaction aborted automatically in C:\\Apache2\\htdocs
          moodle/mod/quiz/report.php, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: Default exception handler: Error writing to database Debug: Duplicate entry '541231-0' for key 'mdl_quesattestep_queseq_uix', referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: INSERT INTO mdl_question_attempt_steps (questionattemptid,sequencenumber,state,fraction,timecreated,userid) VALUES(?,?,?,?,?,?), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: [array (, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 0 => '541231',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 1 => 0,, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 2 => 'todo',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 3 => NULL,, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 4 => '1317962017',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 5 => '5868',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: )], referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 397 of \\lib\\dml
          moodle_database.php: dml_write_exception thrown, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 893 of \\lib\\dml
          mysqli_native_moodle_database.php: call to moodle_database->query_end(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 935 of \\lib\\dml
          mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 119 of \\question\\engine
          datalib.php: call to mysqli_native_moodle_database->insert_record(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 1015 of \\question\\engine
          datalib.php: call to question_engine_data_mapper->insert_question_attempt_step(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 91 of \\question\\engine
          lib.php: call to question_engine_unit_of_work->save(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 403 of \\mod\\quiz\\report\\overview
          report.php: call to question_engine::save_questions_usage_by_activity(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 447 of \\mod\\quiz\\report\\overview
          report.php: call to quiz_overview_report->regrade_attempt(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 159 of \\mod\\quiz\\report\\overview
          report.php: call to quiz_overview_report->regrade_attempts(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 100 of \\mod\\quiz
          report.php: call to quiz_overview_report->display(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview

          Show
          Ryan Smith added a comment - We upgraded to the latest version of Moodle late last week that contained this fixes. Now, when trying to regrade a quiz, we get an error writing to the database. This is a critical problem! Everything was working fine (well, the operations were REALLY SLOW) before this fix was released. The error said to turn debugging on, so I did, and these errors appeared in the Apache error log: [Sun Oct 09 12:08:39 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: Database transaction aborted automatically in C:\\Apache2\\htdocs moodle/mod/quiz/report.php, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: Database transaction aborted automatically in C:\\Apache2\\htdocs moodle/mod/quiz/report.php, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: Default exception handler: Error writing to database Debug: Duplicate entry '541231-0' for key 'mdl_quesattestep_queseq_uix', referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: INSERT INTO mdl_question_attempt_steps (questionattemptid,sequencenumber,state,fraction,timecreated,userid) VALUES(?,?,?,?,?,?), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: [array (, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 0 => '541231',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 1 => 0,, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 2 => 'todo',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 3 => NULL,, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 4 => '1317962017',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: 5 => '5868',, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: )], referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 397 of \\lib\\dml moodle_database.php: dml_write_exception thrown, referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 893 of \\lib\\dml mysqli_native_moodle_database.php: call to moodle_database->query_end(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 935 of \\lib\\dml mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 119 of \\question\\engine datalib.php: call to mysqli_native_moodle_database->insert_record(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 1015 of \\question\\engine datalib.php: call to question_engine_data_mapper->insert_question_attempt_step(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 91 of \\question\\engine lib.php: call to question_engine_unit_of_work->save(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 403 of \\mod\\quiz\\report\\overview report.php: call to question_engine::save_questions_usage_by_activity(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 447 of \\mod\\quiz\\report\\overview report.php: call to quiz_overview_report->regrade_attempt(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 159 of \\mod\\quiz\\report\\overview report.php: call to quiz_overview_report->regrade_attempts(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview [Sun Oct 09 12:09:58 2011] [warn] [client x.x.x.x] mod_fcgid: stderr: * line 100 of \\mod\\quiz report.php: call to quiz_overview_report->display(), referer: http://www.mymoodleserver.org/moodle/mod/quiz/report.php?id=103592&mode=overview
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          Uh, oh. Just to confirm this, under 21_STABLE, I'm getting also, each time I try to regrade one attempt or all them:

          Debug info: Duplicate entry '1-0' for key 'mdl_quesattestep_queseq_uix'
          INSERT INTO mdl_question_attempt_steps (questionattemptid,sequencenumber,state,fraction,timecreated,userid) VALUES(?,?,?,?,?,?)
          [array (
          0 => '1',
          1 => 0,
          2 => 'todo',
          3 => NULL,
          4 => '1287061174',
          5 => '5',
          )]
          Stack trace:
          line 397 of /lib/dml/moodle_database.php: dml_write_exception thrown
          line 893 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()
          line 935 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw()
          line 119 of /question/engine/datalib.php: call to mysqli_native_moodle_database->insert_record()
          line 1015 of /question/engine/datalib.php: call to question_engine_data_mapper->insert_question_attempt_step()
          line 91 of /question/engine/lib.php: call to question_engine_unit_of_work->save()
          line 403 of /mod/quiz/report/overview/report.php: call to question_engine::save_questions_usage_by_activity()
          line 447 of /mod/quiz/report/overview/report.php: call to quiz_overview_report->regrade_attempt()
          line 159 of /mod/quiz/report/overview/report.php: call to quiz_overview_report->regrade_attempts()
          line 100 of /mod/quiz/report.php: call to quiz_overview_report->display()
          

          Note that deletion seems to be working ok here, it's regrading the one failing badly. Same happening under master.

          Show
          Eloy Lafuente (stronk7) added a comment - - edited Uh, oh. Just to confirm this, under 21_STABLE, I'm getting also, each time I try to regrade one attempt or all them: Debug info: Duplicate entry '1-0' for key 'mdl_quesattestep_queseq_uix' INSERT INTO mdl_question_attempt_steps (questionattemptid,sequencenumber,state,fraction,timecreated,userid) VALUES(?,?,?,?,?,?) [array ( 0 => '1', 1 => 0, 2 => 'todo', 3 => NULL, 4 => '1287061174', 5 => '5', )] Stack trace: line 397 of /lib/dml/moodle_database.php: dml_write_exception thrown line 893 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end() line 935 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->insert_record_raw() line 119 of /question/engine/datalib.php: call to mysqli_native_moodle_database->insert_record() line 1015 of /question/engine/datalib.php: call to question_engine_data_mapper->insert_question_attempt_step() line 91 of /question/engine/lib.php: call to question_engine_unit_of_work->save() line 403 of /mod/quiz/report/overview/report.php: call to question_engine::save_questions_usage_by_activity() line 447 of /mod/quiz/report/overview/report.php: call to quiz_overview_report->regrade_attempt() line 159 of /mod/quiz/report/overview/report.php: call to quiz_overview_report->regrade_attempts() line 100 of /mod/quiz/report.php: call to quiz_overview_report->display() Note that deletion seems to be working ok here, it's regrading the one failing badly. Same happening under master.
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          September 28th weekly (master): 228d24fd976f52e24813d13a63ca75b2cbc87a76 worked ok

          Parent of this issue commit (f0bfd964bad45974b154efa1874e8ba6dd0b40b6) also working ok.

          Confirmed: f0bfd964bad45974b154efa1874e8ba6dd0b40b6 introduces the error (git-reverting the commit causes things to work again).

          So I guess the unified deletion is not equivalent to the old/slow/split one always... looking.

          Show
          Eloy Lafuente (stronk7) added a comment - - edited September 28th weekly (master): 228d24fd976f52e24813d13a63ca75b2cbc87a76 worked ok Parent of this issue commit (f0bfd964bad45974b154efa1874e8ba6dd0b40b6) also working ok. Confirmed: f0bfd964bad45974b154efa1874e8ba6dd0b40b6 introduces the error (git-reverting the commit causes things to work again). So I guess the unified deletion is not equivalent to the old/slow/split one always... looking.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Reduced to delete_attempt_steps_for_mysql() being the one causing the error. In my server:

          DELETE qas, qasd
            FROM mdl_question_attempt_steps qas
            JOIN mdl_question_attempt_step_data qasd ON qasd.attemptstepid = qas.id
           WHERE qas.questionattemptid = ? [array ( 0 => 7, )]
          

          an later, insertion:

          INSERT INTO mdl_question_attempt_steps
              (questionattemptid,sequencenumber,state,fraction,timecreated,userid)
          VALUES
              (?,?,?,?,?,?) [array ( 0 => '7', 1 => 0, 2 => 'todo', 3 => NULL, 4 => '1318186521', 5 => '5', )]
          

          reproduces the error above.

          Show
          Eloy Lafuente (stronk7) added a comment - Reduced to delete_attempt_steps_for_mysql() being the one causing the error. In my server: DELETE qas, qasd FROM mdl_question_attempt_steps qas JOIN mdl_question_attempt_step_data qasd ON qasd.attemptstepid = qas.id WHERE qas.questionattemptid = ? [array ( 0 => 7, )] an later, insertion: INSERT INTO mdl_question_attempt_steps (questionattemptid,sequencenumber,state,fraction,timecreated,userid) VALUES (?,?,?,?,?,?) [array ( 0 => '7', 1 => 0, 2 => 'todo', 3 => NULL, 4 => '1318186521', 5 => '5', )] reproduces the error above.
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          Just guessing what happens if one question_attempt_steps has not any child question_attempt_step_data. That seems to be the case here.

          Perhaps outer joining should be provided instead?

          Confirmed, outer joining question_attempt_step_data did the trick here. Just guessing if the 2 _mysql() functions are candidates for outer joining... in your hands, ciao

          Show
          Eloy Lafuente (stronk7) added a comment - - edited Just guessing what happens if one question_attempt_steps has not any child question_attempt_step_data. That seems to be the case here. Perhaps outer joining should be provided instead? Confirmed, outer joining question_attempt_step_data did the trick here. Just guessing if the 2 _mysql() functions are candidates for outer joining... in your hands, ciao
          Hide
          Tim Hunt added a comment -

          Thanks Eloy for making patch https://github.com/stronk7/moodle/compare/master...MDL-29520. That looks right to me.

          Show
          Tim Hunt added a comment - Thanks Eloy for making patch https://github.com/stronk7/moodle/compare/master...MDL-29520 . That looks right to me.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Thanks Tim, applying to master and 21_STABLE and sending upstream...

          If in the mean time somebody can test both deletion and regrading is working of with that patch, it will be really welcome!

          Trick: try it with one quiz containing some truefalse question, that's enough to reproduce the problem.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Thanks Tim, applying to master and 21_STABLE and sending upstream... If in the mean time somebody can test both deletion and regrading is working of with that patch, it will be really welcome! Trick: try it with one quiz containing some truefalse question, that's enough to reproduce the problem. Ciao
          Hide
          Eloy Lafuente (stronk7) added a comment -

          git and cvs repositories have been updated with this fix, you can grab it from them.

          Show
          Eloy Lafuente (stronk7) added a comment - git and cvs repositories have been updated with this fix, you can grab it from them.
          Hide
          Ryan Smith added a comment -

          Thanks for the fast fix! It appears to be working now.

          Show
          Ryan Smith added a comment - Thanks for the fast fix! It appears to be working now.
          Hide
          Anthony Borrow added a comment -

          I installed on a production site and the users seem to be happy with quiz regrading again. Many thanks for the quick response. Peace - Anthony

          Show
          Anthony Borrow added a comment - I installed on a production site and the users seem to be happy with quiz regrading again. Many thanks for the quick response. Peace - Anthony

            People

            • Votes:
              3 Vote for this issue
              Watchers:
              9 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: