Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Number of replies: 15
Picture of Core developers

Hi everyone, I've been trying to troubleshoot this issue with our environment for a while but have not had much luck. I have also inherited this Moodle installation so do not yet know all the ins and outs and I was hoping someone could point me in the right troubleshooting direction.

The basic problem is that one of our courses has very slow loading times for it's SCORM module based units. This course has been copied a number of times and the previous copies of it do not have any of the performance issues. The course is already running so re-creating it again to try to resolve the issue is a difficult proposition. All of the other components of the course run normally also, such as quizes, etc.

I've been doing troubleshooting and it does not seem to be related to any underlying server wide or db wide performance issues, as other courses are normal speed while this course is not. I do not think it's the SCORM package/module itself, as that same module with the exact same zip package file runs fine on other courses, with the exact same options.

With Fiddler I've managed to trace the slow down to pluginfile.php specifically, for example the HTTP GET request: /pluginfile.php/18294/mod_scorm/content/1/images/tableofcontents.png

takes over 11 seconds from the time the server got the request to the time it sends it's response. Since it has to run this for each file in the SCORM package (dozens of files), the whole things takes over a minute or several minutes to load.

Something specifically about pluginfile.php with a few specific DB identifiers seems to be slow. I have a few demo samples, don't worry about logging in, you can see the delay anyways.

This first link, from a scorm module in a previous instance of the course runs quickly, returning in under 1 second.

http://learning.desouzanurse.ca/pluginfile.php/15181/mod_scorm/content/1/images/tocauicon.gif

This second link, from a scorm module in the current slow instance of the course, takes over 4 seconds to return.

http://learning.desouzanurse.ca/pluginfile.php/18291/mod_scorm/content/1/images/tocauicon.gif

Both of these files don't actually exist on the server, so the underlying file system should return them at the same speed, and if there was a hardware performance issue, it should return them at the same speed also.

Any tips on narrowing this down further?

Specs:

Moodle 2.2.2

Dedicated Solaris web server running apache, seperate MySQL server. We don't handle huge numbers of users, on average about 10-20 concurrent users but our courses are rather large and interactive in terms of video and audio.

In addition, the problem seems to be interrmittent at times. Our users report that at most times it is slow, but ocassionaly when they switch browsers or try it at another time it speeds up.

Average of ratings: Useful (1)
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Visvanath Ratnaweera -
Picture of Particularly helpful Moodlers Picture of Translators
Any network mounted file systems? "load user's picture very slow" http://moodle.org/mod/forum/discuss.php?d=208375.

Just a thought.
Average of ratings: -
In reply to Visvanath Ratnaweera

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

Unfortunately no, I skimmed through that post and it is a similar setup to ours, but not quite. Our issue also is with a specific course instance being slow as opposed to everything.

The server is running in a Solaris zone, filesystem for where www root and data root is lofs and I believe underlying system is local zfs.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Dan Marsden -
Picture of Core developers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers Picture of Plugins guardians Picture of Testers Picture of Translators

send_file_not_found isn't very efficient and doesn't make a lot of sense for SCORM packages - if you upgrade to 2.2.3 it should perform a lot faster. or see MDL-32147 for the fix.

Average of ratings: -
In reply to Dan Marsden

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

Thank you Dan, I'll try to upgrade. I don't have much hope it will help though as the slow down is only for a specific course/db id of files, rather than all 404s.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

Upgraded my dev environment to this week's 2.2.4+ release, build 20120816. Still the same slowdown, only on that specific course and the one it is copied from. The .gif links also still perform strangely, with the one that uses pluginfile.php/18291/mod_scorm/ still taking 4 times as long as pluginfile.php/15181/mod_scorm/. Even chopping out all of the file contents and just having the url as siteroot/pluginfile.php/18291/mod_scorm/ seems to trigger it, which makes me think it's something specific to the mdl_files table for rows with that 18291 id.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Dan Marsden -
Picture of Core developers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers Picture of Plugins guardians Picture of Testers Picture of Translators

Can't think of anything specific to check - if you can trace the code to see where the delay is caused that would be useful? - if you're not able to do this yourself and have funding we can probably help to diagnose the issue.

(I work for the Moodle Partner Catalyst IT)

Average of ratings: -
In reply to Dan Marsden

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

 Following up on this, I've tested another server with the same data,web and db files. Running $siteroot$/pluginfile.php/18291/mod_scorm/ is just as fast as $siteroot$/pluginfile.php/15181/mod_scorm/, both clocking in at ~1.42 seconds. On the production site and staging site that use the same DB server and web server, the 18291 version clocks in at ~4 seconds, and the 1581 at the same ~1 seconds.

I've also setup a local xampp stack on my machine and tested it with same data, both 18291 and 15181 return in the same ~1 second time. So it must be something specific to my production apache/mysql configuration that is causing the issues.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Dan Marsden -
Picture of Core developers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers Picture of Plugins guardians Picture of Testers Picture of Translators

is that 1.42 seconds to return a 404? - that sounds a bit crazy... is that with the patch in place that I mentioned above?

Average of ratings: -
In reply to Dan Marsden

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

No, not explicitly a 404. If I type in a straight wrong URL, I get the 404 page within .004 of a second according to Fiddler. This is to return a 'Sorry, the requested file could not be found' error within Moodle which also displays all of the other site.

I've turned on all debugging on our staging site (which uses same db and apache server as production), and for both urls I test with the stack trace is:

Stack trace:

  • line 435 of /lib/setuplib.php: moodle_exception thrown
  • line 1568 of /lib/filelib.php: call to print_error()
  • line 3917 of /lib/filelib.php: call to send_file_not_found()
  • line 37 of /pluginfile.php: call to file_pluginfile()

and it reports the following stats when going to siteroot/pluginfile.php/15181/mod_scorm/

1.162587 secs
RAM: 36.1MB
RAM peak: 36.3MB
Included 660 files
Contexts for which filters were loaded: 0
Filters created: 0
Pieces of content filtered: 0
Strings filtered: 0
get_string calls: 1403
strings mem cache hits: 1219
strings disk cache hits: 186
Included YUI modules: 54
Other JavaScript modules: 2
DB reads/writes: 87/2
ticks: 116 user: 85 sys: 7 cuser: 0 csys: 0
Load average: 0.34
Session: 19.9KB

This page is: General type: incourse. Context SCORM package: Unit One - Normal Lab Values (context id 15181). Page type site-index.

and when going to siteroot/pluginfile.php/18291/mod_scorm/ (which is the contextid of one of the modules that is slow in the 'slow' course):

4.262509 secs
RAM: 35.6MB
RAM peak: 35.9MB
Included 657 files
Contexts for which filters were loaded: 0
Filters created: 0
Pieces of content filtered: 0
Strings filtered: 0
get_string calls: 1404
strings mem cache hits: 1219
strings disk cache hits: 187
Included YUI modules: 54
Other JavaScript modules: 2
DB reads/writes: 131/2
ticks: 426 user: 85 sys: 5 cuser: 0 csys: 0
Load average: 0.25
Session: 20KB

This page is: General type: incourse. Context SCORM package: Unit One - Normal Lab Values (context id 18291). Page type site-index.

 

When doing the same on my local machine with a locally hosted copy of all the data, for /pluginfile.php/15181/mod_scorm/ I get:

1.153662 secs
RAM: 35.6MB
RAM peak: 35.8MB
Included 656 files
Contexts for which filters were loaded: 0
Filters created: 0
Pieces of content filtered: 0
Strings filtered: 0
get_string calls: 1400
strings mem cache hits: 1216
strings disk cache hits: 186
Included YUI modules: 54
Other JavaScript modules: 2
DB reads/writes: 79/1
ticks: 115 user: 88 sys: 5 cuser: 0 csys: 0
Load average: 0.18
Session: 19.9KB
This page is: General type: incourse. Context SCORM package: Unit One - Normal Lab Values (context id 15181). Page type site-index.

and for /pluginfile.php/18291/mod_scorm/ I get:

1.331989 secs
RAM: 55.7MB
RAM peak: 55.9MB
Included 663 files
Contexts for which filters were loaded: 0
Filters created: 0
Pieces of content filtered: 0
Strings filtered: 0
get_string calls: 1504
strings mem cache hits: 1317
strings disk cache hits: 188
Included YUI modules: 54
Other JavaScript modules: 2
DB reads/writes: 124/2
Session: 19.9KB
This page is: General type: incourse. Context SCORM package: Unit One - Normal Lab Values (context id 18291). Page type site-index.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Matt Clarkson -
Picture of Core developers Picture of Peer reviewers Picture of Plugin developers

Are you using any sort of PHP accelerator, APC or eacclerator for example? 

Average of ratings: -
In reply to Matt Clarkson

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

No, I do not think we are, or atleast none indicated by PHP Info.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Dan Marsden -
Picture of Core developers Picture of Particularly helpful Moodlers Picture of Peer reviewers Picture of Plugin developers Picture of Plugins guardians Picture of Testers Picture of Translators

heh - stop everything else and go and install one... smile bit more info in perf docs here:

http://docs.moodle.org/23/en/Performance_recommendations#PHP_performance

Average of ratings: -
In reply to Dan Marsden

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

Thanks for the tip! Will try to load up xcache and see what impact it has.

Average of ratings: -
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

I've made progress!

I've managed to trace the delay down to the get_fast_modinfo function, which unsets the cache and then re-caches using a new course_modinfo($course, $userid) call. The constructor then has a loop near the end:

// We need at least 'dynamic' data from each course-module (this is basically the remaining
// data which was always present in previous version of get_fast_modinfo, so it's required
// for BC). Creating it in a second pass is necessary because obtain_dynamic_data sometimes
// needs to be able to refer to a 'complete' (with basic data) modinfo.
foreach ($this->cms as $cm) {
$cm->obtain_dynamic_data();
}

On the normal courses, this executes in less than a second. In the slow courses this loop take over 3-4 seconds. It loops 64 times on the fast courses, 65 times on the new ones, but each loop of it seems to roughly take the same amount of time.. 

It also seems to be unrelated to the backing database. On my development server/db all courses are fast. So I tried pointing my staging site db to the development db. Still had slow performance on those courses even though the db server was completely different.

Average of ratings: Useful (2)
In reply to Mathew Gancarz

Re: Extremely slow SCORM module performance, pluginfile retrieval, but only on a specific course and courses derived from it

by Mathew Gancarz -
Picture of Core developers

Just as a closing update on this, I first wanted to thank Dan Marsden for all the guidance he has given with helping to troubleshoot this. You've been a great help in finding the source.

End result seems to be that when we turn on completion tracking for a module in the course, it slows down the $cm -> obtain_dynamic_data() call by about 0.1 seconds. This then multiplies by the number of modules we had it on for (about 30) to slow all file loading on the course by 2-3 seconds. This would not be a problem but the SCORM Packages we use load about 30-40 files, so that 2-3 second slow down is multiplied again resulting in 2 minute plus load times.

This does not happen in other courses we have completion tracking enabled and not in our development environment, so it's something specific to our course and production setup. Either way we have a work around for now and the course is running fast again!

Thank you everyone for helping out.

 

Average of ratings: Useful (1)