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

Badly performing MySQL queries connected to questions

    Details

    • Type: Bug
    • Status: Closed
    • Priority: 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:

      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.

        Gliffy Diagrams

          Attachments

            Issue Links

              Activity

              Hide
              timhunt 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
              timhunt 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
              mangus 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
              mangus 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
              timhunt 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
              timhunt 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
              aborrow 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
              aborrow 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
              timhunt 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
              timhunt 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
              timhunt 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
              timhunt 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
              timhunt 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
              timhunt 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
              stronk7 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
              stronk7 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@asbury.edu 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@asbury.edu 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
              mangus 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
              mangus 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
              stronk7 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
              stronk7 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
              stronk7 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
              stronk7 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
              timhunt 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
              timhunt 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
              stronk7 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
              stronk7 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
              mangus 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
              mangus 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
              mangus Mart Mangus added a comment -

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

              Show
              mangus Mart Mangus added a comment - Problematic MySQL server variables (maybe it's a configuration issue).
              Hide
              stronk7 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
              stronk7 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
              timhunt 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
              timhunt 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
              stronk7 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
              stronk7 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
              timhunt 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
              timhunt 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
              stronk7 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
              stronk7 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
              stronk7 Eloy Lafuente (stronk7) added a comment -

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

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - Replacing test php file by slightly modified one showing the SQL differences a bit better.
              Hide
              stronk7 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
              stronk7 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
              timhunt 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
              timhunt 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
              rob13 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
              rob13 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
              anttix 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
              anttix 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
              anttix 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
              anttix 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
              stronk7 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
              stronk7 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
              timhunt Tim Hunt added a comment -

              OK, commits re=based.

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

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

              Show
              anttix Antti Andreimann added a comment - 2.1 branch works for me now. Still can't comment on performance though.
              Hide
              mangus 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
              mangus 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
              stronk7 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
              stronk7 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
              timhunt 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
              timhunt 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
              stronk7 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
              stronk7 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
              stronk7 Eloy Lafuente (stronk7) added a comment -

              After chat... amending + integrating...

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

              Amended and integrated, thanks!

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

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

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

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

              Show
              stronk7 Eloy Lafuente (stronk7) added a comment - git repositories have been updated with your awesome changes, thanks! Closing.
              Hide
              smithrn 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
              smithrn 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
              stronk7 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
              stronk7 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
              stronk7 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
              stronk7 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
              stronk7 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
              stronk7 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
              stronk7 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
              stronk7 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
              timhunt 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
              timhunt 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
              stronk7 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
              stronk7 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
              stronk7 Eloy Lafuente (stronk7) added a comment -

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

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

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

              Show
              smithrn Ryan Smith added a comment - Thanks for the fast fix! It appears to be working now.
              Hide
              aborrow 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
              aborrow 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:
                    Fix Release Date:
                    10/Oct/11