Moodle
  1. Moodle
  2. MDL-14302

Course Restore Fails with Heavy User Data

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Duplicate
    • Affects Version/s: 1.9
    • Fix Version/s: 1.9.5
    • Component/s: Backup, Quiz
    • Labels:
      None
    • Environment:
      Linux OS, Apache 2.0.59, MySQL 4.1.22, PHP 5.2.4, Dell Dual Xeon 3.0ghz server
    • Rank:
      26439

      Description

      Normally backup and restore work OK. With heavy user data (446 users taking 50 m/c quiz items), the backup worked OK, but the restore failed. We got this error message after the restore message, "Creating course modules"....
      Fatal error: Allowed memory size of 524288000 bytes exhausted (tried to allocate 32 bytes) in /usr/moodle/ptest17/lib/xmlize.php on line 116

        Issue Links

          Activity

          Don Hinkelman created issue -
          Don Hinkelman made changes -
          Field Original Value New Value
          Environment Linux OS, MySQL 5, PHP 5, Dell Dual Xeon 3.0ghz server Linux OS, Apache 2.0.59, MySQL 4.1.22, PHP 5.2.4, Dell Dual Xeon 3.0ghz server
          Description Normally backup and restore work OK. With heavy user data (446 quizzes with 50 items), the backup worked OK, but the restore failed. We got this error message after the restore message, "Creating course modules"....
          Fatal error: Allowed memory size of 524288000 bytes exhausted (tried to allocate 32 bytes) in /usr/moodle/ptest17/lib/xmlize.php on line 116
          Normally backup and restore work OK. With heavy user data (446 users taking 50 m/c quiz items), the backup worked OK, but the restore failed. We got this error message after the restore message, "Creating course modules"....
          Fatal error: Allowed memory size of 524288000 bytes exhausted (tried to allocate 32 bytes) in /usr/moodle/ptest17/lib/xmlize.php on line 116
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Wow. That's really a lot of memory for just 500 users... assigning to Tim...

          Show
          Eloy Lafuente (stronk7) added a comment - Wow. That's really a lot of memory for just 500 users... assigning to Tim...
          Eloy Lafuente (stronk7) made changes -
          Component/s Quiz [ 10059 ]
          Fix Version/s 1.9.1 [ 10240 ]
          Eloy Lafuente (stronk7) made changes -
          Link This issue has been marked as being related by MDL-9838 [ MDL-9838 ]
          Hide
          Eloy Lafuente (stronk7) added a comment -

          re-assigning to Tim, I don't know what failed in my previous assignment (sure I did a simple comment instead, grrr). Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - re-assigning to Tim, I don't know what failed in my previous assignment (sure I did a simple comment instead, grrr). Ciao
          Eloy Lafuente (stronk7) made changes -
          Assignee Eloy Lafuente (stronk7) [ stronk7 ] Tim Hunt [ timhunt ]
          Hide
          Don Hinkelman added a comment -

          Thanks, Eloy and Tim. If you need direct access to our server and database, I can arrange that. We keep this special twice-a-year placement test site separate from our main production server. Also we discovered some other issues with version 1.9 under load. I cannot pinpoint the problems yet, but we found the same size quiz spiked up 6-10x the server load under 1.9 than under 1.8. A bit worrisome. We survived this year, because we had 900% overcapacity built in to our system. But surprisingly 1.8 was far superior in handling the throughput. Don

          Show
          Don Hinkelman added a comment - Thanks, Eloy and Tim. If you need direct access to our server and database, I can arrange that. We keep this special twice-a-year placement test site separate from our main production server. Also we discovered some other issues with version 1.9 under load. I cannot pinpoint the problems yet, but we found the same size quiz spiked up 6-10x the server load under 1.9 than under 1.8. A bit worrisome. We survived this year, because we had 900% overcapacity built in to our system. But surprisingly 1.8 was far superior in handling the throughput. Don
          Hide
          Tim Hunt added a comment -

          I'm not completely sure why you are assigning this to me Eloy. I think the problem is with the overall architecture of the restore process. When it restores a quiz, it does

          restore_read_xml_modules

          Which, as I understand it, ends up in MoodleParser::endElementModules. By this point, the whole of the <MODULES> section (or possibly just one <MOD> tag) from moodle.xml has been read into the string $this->temp.

          Then we call $data = xmlize($xml_data,0) to parse that. My guess is that this is where memory runs out. And we have not touched any quiz-specific code yet. This problem would affect any module with huge amounts of user data. For example, what happens if you try to backup and restore the general problems forum from Moodle.org - to pick another example of huge amounts of user data.

          Show
          Tim Hunt added a comment - I'm not completely sure why you are assigning this to me Eloy. I think the problem is with the overall architecture of the restore process. When it restores a quiz, it does restore_read_xml_modules Which, as I understand it, ends up in MoodleParser::endElementModules. By this point, the whole of the <MODULES> section (or possibly just one <MOD> tag) from moodle.xml has been read into the string $this->temp. Then we call $data = xmlize($xml_data,0) to parse that. My guess is that this is where memory runs out. And we have not touched any quiz-specific code yet. This problem would affect any module with huge amounts of user data. For example, what happens if you try to backup and restore the general problems forum from Moodle.org - to pick another example of huge amounts of user data.
          Hide
          Dan Marsden added a comment -

          Pio Ko has an interesting patch in MDL-12780 that looks like it could potentially improve performance, although I haven't verified whether $index is needed....

          in terms of overall architecture, there's a good article here on xml processing:
          http://blog.liip.ch/archive/2004/05/10/processing_large_xml_documents_with_php.html

          Dan

          Show
          Dan Marsden added a comment - Pio Ko has an interesting patch in MDL-12780 that looks like it could potentially improve performance, although I haven't verified whether $index is needed.... in terms of overall architecture, there's a good article here on xml processing: http://blog.liip.ch/archive/2004/05/10/processing_large_xml_documents_with_php.html Dan
          Hide
          Dan Marsden added a comment -

          Don - any chance you could let me have a copy of one of your large backup files for testing?

          thanks!

          Dan

          Show
          Dan Marsden added a comment - Don - any chance you could let me have a copy of one of your large backup files for testing? thanks! Dan
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Hi Tim,

          I really don't understand either why I assigned this to you. For sure I read it really quickly and assumed that 524 MB for one activity is far too much.

          Talking about memory usage when restoring... I remember I started with a "pure SAX" conception of the task, saving info sequentially to temp tables while reading it. And AFAIK that continues being the approach now.

          So, for example, MODULES section, when processed... each time ONE particular MODULE is parsed (SAX) from backup file, it's sent straight to temp table, consuming only the memory needed by that MODULE.

          The, once all the individual MODULES have been stored in temp tables, the restore process starts processing them. And here is where the conversion of 1-MODULE XML file to one array is performed by xmlize.

          I.E. one activity is the "atom" in the restore process. I took this decision because never thought that 1-activity could need more than a few MB so, xmlizing it shouldn't really require hundreds of MBs.

          Certainly we can improve restore in a lot of ways... just addressing here some of them:

          • Change a lot of get_records() loops by they get_recordset() counterparts.
          • Provide some alternative to XMLIZE trying to save memory as possible.
          • Reduce the size of the array generated by XMLIZE (or replacement). It seems to have too much levels to support, for example attributes, where moodle backup format hasn't attributes at all.
          • Try to detect if some module is backing up "too much".
          • Profile how memory grows along the process...
          • Separate computations, debug and output along all the process, to make it more readable and easy to trace.
          • ...

          Apart from this...also... we could change the "atom" here... from "activity" to something within them (different for each activity), but I really think this will add complexity to the process. I would leave atoms as they currently are.

          But yes, definitively we are SAX-parsing backup files (the best way, for sure, DOM is evil here). The problem is that we are reading some "atoms" that due to current implementation (xmlize, sql...) eats too much memory (apart from other bugs, of course).

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Hi Tim, I really don't understand either why I assigned this to you. For sure I read it really quickly and assumed that 524 MB for one activity is far too much. Talking about memory usage when restoring... I remember I started with a "pure SAX" conception of the task, saving info sequentially to temp tables while reading it. And AFAIK that continues being the approach now. So, for example, MODULES section, when processed... each time ONE particular MODULE is parsed (SAX) from backup file, it's sent straight to temp table, consuming only the memory needed by that MODULE. The, once all the individual MODULES have been stored in temp tables, the restore process starts processing them. And here is where the conversion of 1-MODULE XML file to one array is performed by xmlize. I.E. one activity is the "atom" in the restore process. I took this decision because never thought that 1-activity could need more than a few MB so, xmlizing it shouldn't really require hundreds of MBs. Certainly we can improve restore in a lot of ways... just addressing here some of them: Change a lot of get_records() loops by they get_recordset() counterparts. Provide some alternative to XMLIZE trying to save memory as possible. Reduce the size of the array generated by XMLIZE (or replacement). It seems to have too much levels to support, for example attributes, where moodle backup format hasn't attributes at all. Try to detect if some module is backing up "too much". Profile how memory grows along the process... Separate computations, debug and output along all the process, to make it more readable and easy to trace. ... Apart from this...also... we could change the "atom" here... from "activity" to something within them (different for each activity), but I really think this will add complexity to the process. I would leave atoms as they currently are. But yes, definitively we are SAX-parsing backup files (the best way, for sure, DOM is evil here). The problem is that we are reading some "atoms" that due to current implementation (xmlize, sql...) eats too much memory (apart from other bugs, of course). Ciao
          Hide
          Don Hinkelman added a comment -

          Problem backup files available temporarily here: http://englishforum.sgu.ac.jp/downloads/DanMarsden/
          The second one is with logs included.

          Show
          Don Hinkelman added a comment - Problem backup files available temporarily here: http://englishforum.sgu.ac.jp/downloads/DanMarsden/ The second one is with logs included.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Hi Don...

          thanks a lot for you backup files! Anyway, just to comment you to delete them ASAP because having them in that public URL isn't really good for privacy data! IMO it's better to send such files/links via email, potentially protected to avoid problems.

          Just a comment, re-thanks!

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Hi Don... thanks a lot for you backup files! Anyway, just to comment you to delete them ASAP because having them in that public URL isn't really good for privacy data! IMO it's better to send such files/links via email, potentially protected to avoid problems. Just a comment, re-thanks! Ciao
          Hide
          Dan Marsden added a comment -

          it seems to be a problem with xml_parse() when the XML contains what I presume are Japanese characters?

          memory usage sits at around: 31079956 but then explodes and crashes at 201326592 (for me) when the following data from that restore gets parsed:

          <MOD>
          <ID>34</ID>
          <MODTYPE>quiz</MODTYPE>
          <NAME>"C" ?????????? - ?????????</NAME>
          <INTRO>This is the 2008 English placement test &quot;C version&quot;, for law, commerce, economics and social information majors. <br /><font size="1"><br />*NB Updated: March 2008.3.25 Tim Grose, April 2008.4.6 Don Hinkelman</font><br /></INTRO>
          <TIMEOPEN>0</TIMEOPEN>

          maybe a bug with PHP xml_parse() ?

          Dan

          Show
          Dan Marsden added a comment - it seems to be a problem with xml_parse() when the XML contains what I presume are Japanese characters? memory usage sits at around: 31079956 but then explodes and crashes at 201326592 (for me) when the following data from that restore gets parsed: <MOD> <ID>34</ID> <MODTYPE>quiz</MODTYPE> <NAME>"C" ?????????? - ?????????</NAME> <INTRO>This is the 2008 English placement test &quot;C version&quot;, for law, commerce, economics and social information majors. <br /><font size="1"><br />*NB Updated: March 2008.3.25 Tim Grose, April 2008.4.6 Don Hinkelman</font><br /></INTRO> <TIMEOPEN>0</TIMEOPEN> maybe a bug with PHP xml_parse() ? Dan
          Hide
          Tim Hunt added a comment -
          Show
          Tim Hunt added a comment - Reassigning to Eloy, as per his comment http://tracker.moodle.org/browse/MDL-14302?focusedCommentId=47761#action_47761
          Tim Hunt made changes -
          Assignee Tim Hunt [ timhunt ] Eloy Lafuente (stronk7) [ stronk7 ]
          Martin Dougiamas made changes -
          Fix Version/s 1.9.2 [ 10280 ]
          Fix Version/s 1.9.1 [ 10240 ]
          Petr Škoda made changes -
          Fix Version/s 1.9.3 [ 10290 ]
          Fix Version/s 1.9.2 [ 10280 ]
          Hide
          Tim Hunt added a comment -

          I see people have already spotted that this issue is a duplicate of MDL-9838. So, why don't we close one of the two?

          Show
          Tim Hunt added a comment - I see people have already spotted that this issue is a duplicate of MDL-9838 . So, why don't we close one of the two?
          Hide
          Don Hinkelman added a comment -

          Hi Eloy, Tim, Dan,
          What is the status of this bug? After sending Dan our backup file, it appeared he may have located the problem. We have a plan to use the Quiz Module with 400-500 users in a few months and need backup/restore working.
          Thanks! Don

          Show
          Don Hinkelman added a comment - Hi Eloy, Tim, Dan, What is the status of this bug? After sending Dan our backup file, it appeared he may have located the problem. We have a plan to use the Quiz Module with 400-500 users in a few months and need backup/restore working. Thanks! Don
          Hide
          Dan Marsden added a comment -

          Hi Don,

          bit of a long-shot, but any chance you could upgrade to PHP 5.2.6 and see if it's an issue there? - I haven't had time to look at this further sorry!

          Dan

          Show
          Dan Marsden added a comment - Hi Don, bit of a long-shot, but any chance you could upgrade to PHP 5.2.6 and see if it's an issue there? - I haven't had time to look at this further sorry! Dan
          Martin Dougiamas made changes -
          Fix Version/s 1.9.4 [ 10300 ]
          Fix Version/s 1.9.3 [ 10290 ]
          Petr Škoda made changes -
          Fix Version/s 1.9.5 [ 10320 ]
          Fix Version/s 1.9.4 [ 10300 ]
          Hide
          Don Hinkelman added a comment -

          Last month we repeated our language placement test with 414 users using 50 quiz questions and 30 audio files. Again Backup worked OK, but Restore failed. This is the error message:
          Fatal error: Allowed memory size of 201326592 bytes exhausted (tried to allocate 35 bytes) in /usr/moodle/ptest193/lib/xmlize.php on line 53
          We are using Moodle 1.9.4+ and PHP 5.2.8.

          1. Is there any setting we can change in PHP or Moodle to allow more memory?
          2. Would removing Japanese characters, concievably change the load?
          3. Why does Backup succeed but Restore fail?

          Show
          Don Hinkelman added a comment - Last month we repeated our language placement test with 414 users using 50 quiz questions and 30 audio files. Again Backup worked OK, but Restore failed. This is the error message: Fatal error: Allowed memory size of 201326592 bytes exhausted (tried to allocate 35 bytes) in /usr/moodle/ptest193/lib/xmlize.php on line 53 We are using Moodle 1.9.4+ and PHP 5.2.8. 1. Is there any setting we can change in PHP or Moodle to allow more memory? 2. Would removing Japanese characters, concievably change the load? 3. Why does Backup succeed but Restore fail?
          Hide
          Don Hinkelman added a comment -

          FYI, we found a workaround to complete Restore. But it takes 29 minutes for the restore! We changed the php settings in php.ini to allow greater memory. First, we upped it from 128MB to 512MB, but got a similar error message. Then we upped it to 1024MB and restore continued for 29 minutes before success. Normally we could restore this course with Moodle 1.6 in less than minute, so there is still some kind of bug in there. We also increased the execution time to allow item analysis, which now works. So these are the settings we changed in php.ini:
          memory_limit = 1024MB
          max_execution_time = 120

          Show
          Don Hinkelman added a comment - FYI, we found a workaround to complete Restore. But it takes 29 minutes for the restore! We changed the php settings in php.ini to allow greater memory. First, we upped it from 128MB to 512MB, but got a similar error message. Then we upped it to 1024MB and restore continued for 29 minutes before success. Normally we could restore this course with Moodle 1.6 in less than minute, so there is still some kind of bug in there. We also increased the execution time to allow item analysis, which now works. So these are the settings we changed in php.ini: memory_limit = 1024MB max_execution_time = 120
          Eloy Lafuente (stronk7) made changes -
          Link This issue is duplicated by MDL-15489 [ MDL-15489 ]
          Hide
          Eloy Lafuente (stronk7) added a comment -

          I'm closing this as duplicate of MDL-15489. Update your watches.

          Show
          Eloy Lafuente (stronk7) added a comment - I'm closing this as duplicate of MDL-15489 . Update your watches.
          Eloy Lafuente (stronk7) made changes -
          Status Open [ 1 ] Closed [ 6 ]
          Resolution Duplicate [ 3 ]
          Martin Dougiamas made changes -
          Workflow jira [ 25862 ] MDL Workflow [ 59435 ]
          Martin Dougiamas made changes -
          Workflow MDL Workflow [ 59435 ] MDL Full Workflow [ 88587 ]

            People

            • Votes:
              4 Vote for this issue
              Watchers:
              12 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: