General developer forum

We are having an issue with the Moodle 1.8.2 cron.php scripts taking a very long time (2+ hours) to run, while at the same time consuming a massive amount of resources in the form of MYSQL queries. Moreover, since the cron takes so long to run, it tends to spawn additional cron processes, which in turn cause even more resources to be consumed, which eventually slows the machine to a crawl.

Specifically, after configuring cron.php to display its actions, I was able to determine that it takes about 2.5 hours for our regular "dailystatistics" cron to run. This far exceeds the threshold I'd set of 1 hour, so when it finally concludes, it can't run the weekly stats, monthly stats, or cleanup.

When this cron runs, MySQL consumes an entire processor. The real problem comes into play when subsequent crons assume that the still-running job is stale (via the function set_cron_lock in cron.php), clobber the time stamp, and start the process all over again. Since each one of these processes consumes a processor, in a few days we reach the point where the server is running at nearly 400%, with almost all of the processors dedicated to running MySQL, which continues to get hammered by cron processes.

That's what it does in an ideal situation, on an exact clone of the production server (same hardware, same data, same config) without any other traffic hitting the database. In production though, we've seen the same job running for hours on end.

We can confirm that these processes are the problem by grepping ps for "cron" when demand is high, which yields a list of 2-6 cron processes, all of which have been running for a considerable (12+ hours) time. Manually killing these processes alleviates the MySQL demand immediately, as it drops back down to negligible levels, but doesn't solve the problem.

* * *

We are running Moodle 1.8.2, upgraded from Moodle 1.7.3. We have 811 courses in our database, of which about 250 are active. We have 3172 and most (3000) are active. We have defined 12 roles in our system, which are a mix of the traditional guest/student/teacher/admin roles as well as new rules such as "Librarian".

We are running MySQL 5.0.27 and PHP 5.2.0 on Apache 2.x. on a quad processor machine with something like 4 GB of ram. We're running Red Hat Enterprise Linux 4. (I'm working on getting the machine's specs; I'm going from memory right now).

* * *

There are a few things I've seen I've been working my way through the cron code:

1) By default, the dailystats script chugs through every course, active or inactive. If it only did inactive courses, we could reduce the time it takes to run this cron by 70% ... but the time would crawl back up as we added more active courses.

2) The cron is making certain assumptions about how long it will take to run that aren't accurate given our situation (and, I suspect, a lot of other schools as well).

3) The cron checks to see if the date in the "statsrunning" field in the table database is stale. If it is, then it triggers the stats job. The stats job itself only checks to see if a day has passed since the job last ran, not whether it is still, in fact, running. I believe this is how we end up with two or more stat-processing crons running simultaneously

I can think of a few hacks that could eek some performance out of cron for us including:

* limiting stat crunching to active courses, but I'm not sure what the implication of that is long term based on what Moodle assumes is being done with stat collection.
* increasing the stat time limit so that the job stays locked longer and does not spawn additional cronjobs.

Both of these are short term fixes; eventually the number of courses could grow to a point where the queries take as long or longer than they do right now.

I know of at least one other report of a similar issue reported in Tracker (MDL-9953):

* cron runs 12+hours accessing MySQL
http://tracker.moodle.org/browse/MDL-9953

* * *

The real problem lies with the queries, which are just taking far too long. Here are some examples of the time frames we're dealing with:

"Enrollment (roles)": 1.57 sec
"Enrollment (in time frame): 1.58 sec
"Activity": 1.86 seconds

These queries are run twice, once for teachers, once for students. Roughly speaking, that means 10.02 seconds per course. For 811 courses, that means 8126.22 seconds or 135 minutes.

When I do an EXPlAIN on the queries in question, I find a derived table that's created using the sql_primary_role_subselect() (from dmllib.php) function. This derived table incorporates 18,684 rows returned. My understanding is that because this table is derived, it's also unindexed, and I suspect it may be to blame for the speeds we're seeing.

The specific query fragment is:

[SELECT ... FROM]
mdl_role_assignments ra INNER JOIN mdl_role r ON ra.roleid = r.id INNER JOIN mdl_context c ON ra.contextid = c.id WHERE NOT EXISTS ( SELECT 1 FROM mdl_role_assignments i_ra INNER JOIN mdl_role i_r ON i_ra.roleid = i_r.id WHERE ra.userid = i_ra.userid AND ra.contextid = i_ra.contextid AND i_r.sortorder < r.sortorder) )
[REST OF QUERY]

My questions are:

1) Is anyone else seeing these sorts of slow behavior? Should we expect to see these kinds of query times?

2) Is there a way that these queries could be done using temp tables that would allow for indexing instead of a derived table (and thus, speed things up considerably).

3) Do you have any suggestions on other environmental variables that might be affecting our performance?