Stats problems again - new bug in Moodle 1.9.2?

Stats problems again - new bug in Moodle 1.9.2?

by Tony Butler -
Number of replies: 22
After having a nightmare with the stats in Moodle 1.8.2 it was great to see it was all sorted in 1.9. However I've just upgraded to 1.9.2 (Build: 20080716) to take advantage of the security fixes and we're now having serious problems with high MySQL utilisation during stats processing again.

What seems to be happening is: for each day's statistics the number of mysql processes gradually increases to 100 (the max allowed), stays there for about 30 minutes and then slowly drops back down again for the start of the next day's stats, and the cycle begins again (we're still catching up after having to turn off the stats in 1.8.2). While the number of processes is above about 30-40 the site becomes unuseable - each day's cycle takes about 1.5 hours and I reckon Moodle's pretty much unavailable for at least an hour of that. And this is with 2 x 2.5 GHz CPUs and 4 GB of RAM!

The weird thing is the queries that are running when the number of processes ramps up (see attached). There's always a query acting on the stats tables as expected, and this doesn't seem to cause any problems, but then multiple instances of the same query start running, and this seems to be what causes the problem. In the screen dump the query is truncated but it's actually "SELECT * FROM mdl_context WHERE contextlevel = '10' LIMIT 1;" - a simple query that returns just 1 record! There comes a point where I can't view the processlist anymore via phpMyAdmin, but I'm guessing this same query is just being duplicated until max_connections is reached.

Is this another stats bug that's crept in? The stats seemed to be running really quickly in older 1.9.x releases I've tested. Has anyone else been experiencing this in 1.9.2?

Many thanks,
Tony
Attachment stats.gif
Average of ratings: -
In reply to Tony Butler

Re: Stats problems again - new bug in Moodle 1.9.2?

by Neil S -
Hi Tony,

You are not alone with this issue. I am seeing the same behavior. What is really happening here from what I can tell is that the insert query is running and has locked the mdl_context table. This keeps the other simple queries from processing; as you have observed. Eventually everyone using the site ends up 'waiting' for this very slow query because it doesn't take many clicks to require a call to mdl_context...This can be alleviated a little bit if you configure mysql correctly, but unfortunatly not good enough for our site. The problem query for us (and it looks like for you too) is as follows:

INSERT INTO mdl_stats_daily (stattype, timeend, courseid, roleid, stat1, stat2)

SELECT 'enrolments', timeend, courseid, roleid, COUNT(DISTINCT userid), 0
FROM (
SELECT 1218686400 AS timeend, pl.courseid, pl.roleid, pl.userid
FROM (
SELECT DISTINCT ra.roleid, ra.userid, c.id as courseid
FROM mdl_role_assignments ra JOIN mdl_context ctx
ON ctx.id = ra.contextid
CROSS JOIN mdl_course c
JOIN mdl_role_capabilities rc
ON rc.roleid = ra.roleid LEFT OUTER JOIN mdl_course_categories cc1
ON cc1.id = c.category
WHERE ((rc.capability = 'moodle/course:view' )
AND rc.permission = 1 AND rc.contextid = 1
AND (ctx.contextlevel = 10
OR (c.id = ctx.instanceid AND ctx.contextlevel = 50) OR (cc1.id = ctx.instanceid AND ctx.contextlevel = 40)))
) pl
) inline_view
GROUP BY timeend, courseid, roleid

This query would kick off via the cron job and would not finish before the next cron job. I have not spent any time debugging yet -- for now I have simply disabled stats. We upgraded from 1.6+ where stats worked perfectly. I miss them and would like to get them going again. We do have a fairly busy site with lots of cool logs and stats. This query, though, is not cool... wink

I believe this issue is in the tracker here.... vote, or comment!!
http://tracker.moodle.org/browse/MDL-13548

Cheers,
Neil Streeter
eLearning Systems Administrator
Northwestern Michigan College

Average of ratings: -
In reply to Neil S

Re: Stats problems again - new bug in Moodle 1.9.2?

by Tony Butler -
Thanks Neil - good to know it's not just us!

I too have turned off stats for now. My plan is to catch up the stats on another box while tuning mysql on the live one. That way when I import the up-to-date stats tables back into the live database it might be in good enough shape to at least process one day's stats per night and keep on top of them. Hopefully! mixed

Cheers,
Tony
Average of ratings: -
In reply to Neil S

Re: Stats problems again - new bug in Moodle 1.9.2?

by Lewis Carr -
Yes indeed stats take a considerable amount of time and processing power, especially on large Moodle sites. We have over 2000 courses and 5000 users to press and we often get a backlog of stats.
Switching to Innodb can improve this but then I've found Moodle in general performs slightly slower than with MyISAM. So maybe there is some trade off here.

  • Running cron via command line or as a service is less processor intensive than through a browser and stats will generate faster.
  • Good tuning of MySQL is really important. Make sure you have tuned your my.ini to suit your server environment and resources.
Often many users leave default MySQL settings and this will really put a strain on your database server.
At times of need I have run large stats offline (locally) and imported them back in to our production server). The trick is not to let your stats get too far behind. Address it early locally if you have to.
Average of ratings: -
In reply to Tony Butler

Re: Stats problems again - new bug in Moodle 1.9.2?

by joe vieira -
Has anyone found a good solution to this issue? I am experiencing it as well.
Average of ratings: -
In reply to Tony Butler

Re: Stats problems again - new bug in Moodle 1.9.2?

by Quentin Hartman -
Thanks for posting on this. I'm new to production-grade Moodle, and after a week of head scratching I finally uncovered this same query as the root of the performance problems our site was having.

The usage profile of this site is very bursty. It will be mostly idle except for a couple hours a day, wherein it just gets hammered.

I haven't yet dug into what all the half-hourly cron-job does, but I was wondering if there were any opinions on whether or not it would be a good solution to just change up the schedule of it so it did not run during our busy time. We'd still like stats, but there's no reason we can't live with having them updated only daily.

I'm just about to dive into this problem and see if this looks to be a tenable solution. I'll post my findings back here once I do, but if anyone has thoughts on it, I'd like to hear them.
Average of ratings: -
In reply to Quentin Hartman

Re: Stats problems again - new bug in Moodle 1.9.2?

by Quentin Hartman -
It looks like there may be a bug in the scheduling of the stats run. On my system, the Admin UI indicates that this should only be running at 2 AM, but that's not when it is firing off, it seems to be starting at about 6 PM, or maybe even happening with every run of the cron job. I'm going to see if there are any open bug reports on this, file one if not, and dig into it a bit and see if I can find the offending code.
Average of ratings: -
In reply to Tony Butler

Re: Stats problems again - new bug in Moodle 1.9.2?

by Quentin Hartman -
Bug report opened here: http://tracker.moodle.org/browse/MDL-16709
Average of ratings: -
In reply to Quentin Hartman

Re: Stats problems again - new bug in Moodle 1.9.2?

by Lewis Carr -
I too have stats problems with Moodle 1.9.2.
Stats used to work fine with a daily cron job.
Now the cron never compiles stats even though it's enabled.
It can't seem to catch up once the Moodle site becomes large and heavily used.
I exported the MySQL database and imported it to a local server. I was able to run it offline and it processed it eventually (after 2 hours). I may too have to import this back into Moodle until we can figure out this bug.
Average of ratings: -
In reply to Lewis Carr

Re: Stats problems again - new bug in Moodle 1.9.2?

by Alastair Graham -

Hi Lewis,

Would it be possible for you to either post the process you're using to export the data to process locally or email me with suggested instructions?

We updated to Moodle 1.9.2 over the Summer Holidays and stats haven't run since which is a problem as the college is using the stats as an indication as to the success of Moodle as our VLE. With OFSTED looming we coud really do with this information.

Also, could someone tell me how I'd run the cron job through command line?

Average of ratings: -
In reply to Alastair Graham

Re: Stats problems again - new bug in Moodle 1.9.2?

by Lewis Carr -
Hi Alastair,
Sorry for the delay.
To run the stats locally I simply dumped the entire MYSQL table and installed Moodle locally to my desktop. (Use PHPmyAdmin or SQLYOG http://www.webyog.com/en/downloads.php). SQLYOG is a great mysql gui that exports and imports really quickly, and the community edition is free.

Use something like XAMPP or WAMP to setup your local webserver. Make sure your local install uses the database you exported from your production server.

Now, with Moodle working locally, run the cron from command line or web interface. Leave it running for as long as you need until it's caught up on your stats.

Then , use PHPMyAdmin or WEBYOG to export the stats tables and import this data back into your Moodle Production Server Database.

To run from command line (DOS) you need this command (substitute the path values to match your setup)

d:\xampp\php\php.exe d:\xampp\htdocs\admin\cron.php

Hope this helps. It's not the prettiest scenario but it does work. Hopefully someone may have a faster solution.

Regards,

Lewis


Average of ratings: -
In reply to Tony Butler

Re: Stats problems again - new bug in Moodle 1.9.2?

by Phil Houghton -

We are getting the same issue as well, except when the sql process's max out the stats section of the cron job stops and errors out with:-

.........error occured, completed 0 days of statistics.

any help on this would be appreciated

Average of ratings: -
In reply to Phil Houghton

Re: Stats problems again - new bug in Moodle 1.9.2?

by joe vieira -
Hey,

I posted before, and I think that I've found a possible solution. are you all using mysql with MyIsam engine types? myisam does not support row level locking so when the inital update query is running that whole table is locked. that stops other queries to that table, which is why they show in the locked state, mysql processes queries in sequence so, with locked queries cloging up your queue, you'll run out of processes and see a totally unresponsive database. i am going to test switching to the innodb engine ( which supports row level locking ) and see if that helps.

Joe V
Average of ratings: -
In reply to joe vieira

Re: Stats problems again - new bug in Moodle 1.9.2?

by Quentin Hartman -
Joe-

You are right, that should alleviate the "clogging" problem and I'm anxious to hear about your results. However, it doesn't do anything to address the apparent scheduling problem that I saw (see my posts and bug report above), and it also seems that there was some other change in the query in this version of Moodle to cause the performance problem.

I think this may be a good work-around, but unless I'm wrong, it will really only spackle over underlying issues.

Hopefully my client will allocate some funding for me to dig into this so I can help get to the root of the issue soon!

-QH-

Average of ratings: -
In reply to Quentin Hartman

Re: Stats problems again - new bug in Moodle 1.9.2?

by joe vieira -
I have not seen any issues with scheduling.
when does cron.php run? cron.php needs to be IN crontab, if it's set to 6am then it will run all the stuff it was supposed to run up untill it itself runs.

also, i don't think that using innodb is just spackling over an issue, a long update on a table that gets a lot of other reads / writes should be done with row-level locking...

Joe
Average of ratings: -
In reply to joe vieira

Re: Stats problems again - new bug in Moodle 1.9.2?

by Quentin Hartman -
In the server in question, cron.php runs every thirty minutes. From what I was able to infer from that and the admin UI in Moodle is that the statistics portion of the cron.php job only gets fired if it is / near to the time specified in the UI. I tested this theory by running cron.php manually; the statistics collection query did not run, and the job returned in less than a second. Note that this is all based on what I was able to infer from limited information in a very limited window of time, so it may very well be wrong. If it is wrong, I welcome correction.

As far as whether or not using innodb is a real fix or not, I would say it is not for the simple reason that this query (or one functionally like it) was apparently running in older versions _without_ causing performance problems. This suggests that something in that routine changed and had a negative effect. Changing something else to compensate does nothing to fix the root issue.

I would argue that the whole database should be using innodb instead of MyISAM, the benefits far outweigh any possible shortcoming. So please don't take my comment to mean that I think it's a bad idea, I think it's a great idea. It does not, however, resolve the root problem that is suggested by the evidence at hand. If it turns out that the query was changed for a good reason, then moving to innodb would be a good call. I think it's more likely though that someone just slipped in a cartesian join.... :D

Average of ratings: -
In reply to joe vieira

Re: Stats problems again - new bug in Moodle 1.9.2?

by Eric Bollens -
Joe V, InnoDB doesn't get at the root of this issue, I don't think. Look at the queries against the database: "WHERE contextlevel = 10". That is the site context that gets locked, and it will get locked almost certainly by the statistics process regardless of whether we use MyISAM or InnoDB. Don't get me wrong. I think with a beefy enough 64-bit system that InnoDB is the right way to go for Moodle, but I agree with some others here that InnoDB shouldn't solve this problem. If the site context gets locked by statistics, it doesn't matter if it is at the table or row level; either way, we're looking at a very inconvinient lock, which I assume is what is causing the backlog posted by Tony.
Average of ratings: -
In reply to Eric Bollens

Re: Stats problems again - new bug in Moodle 1.9.2?

by Elvedin Trnjanin -
I was under the impression that the only time InnoDB locks a row/table during a SELECT is if you explicitly state to lock it - eg, during SELECT ... FOR UPDATE

Is that not correct?
Average of ratings: -
In reply to Elvedin Trnjanin

Re: Stats problems again - new bug in Moodle 1.9.2?

by Taylor Judd -
I'm not an mySQL expert so please someone correct me if I am wrong. As I understand it if you have a complex sort based on a WHERE or a JOIN clause then you can get row level locking in a 'shared' state. Now depending on some of the other quarries trying to be executed on the table during the sort that may need 'exclusive' locks this may be a problem. But like others said this may not be the case here. We don't run stats on our moodle build; I am basing this answer on what I know about mySQL and InnoDB
http://dev.mysql.com/doc/refman/5.0/en/innodb-lock-modes.html
Average of ratings: -
In reply to Taylor Judd

Re: Stats problems again - new bug in Moodle 1.9.2?

by Tony Butler -
I don't know whether anyone's still following this thread, but I have a happy ending. smile

I upgraded to Moodle 1.9.4+ last week and the stats are now running in less than half the time, and the number of concurrent MySQL connections building up during the process has dropped to less than 20% of what it was before. Presumably this is due to the resolution of the bugs mentioned above, so many thanks for that.

So for anyone still suffering, if at all possible and if you haven't done already, upgrade to the latest weekly build!

Cheers,
Tony
Average of ratings: Useful (1)
In reply to Eric Bollens

Re: Stats problems again - new bug in Moodle 1.9.2?

by HJWUCGA INC. -
Eric is correct... we have a beefy 64 bit OS and innoDB and it now locks up ... version 1.9.6 (November 24, 2009 build)

gives us the 0 stats and errors
Average of ratings: -