Details
-
Type:
Bug
-
Status:
Open
-
Priority:
Major
-
Resolution: Unresolved
-
Affects Version/s: 1.9.3, 1.9.4, 1.9.5
-
Fix Version/s: None
-
Component/s: Administration
-
Labels:
-
Environment:LAMP
-
Database:MySQL
-
Affected Branches:MOODLE_19_STABLE
Description
On 1.9.3+ (Build: 20090109) stats are completely unusable for us.
My server tried to runs stats for ONE SINGLE DAY of logs on our site (a pilot of only 30-odd courses but with 30000 mostly-unused rows in the user table). After 8 HOURS, I had to restart MySQL in the morning as it was still locked up at 100% and moodle could not connect to the DB.
MySQL struggled for 6 HOURS on a single query!!
Here is the monstrous query. We showed it to our Computer Science SQL lecturer for a laugh who said 'it is definitely a very bad query. Using cross join on large tables is a definite NO'. Creating 1.2 billion rows from our little DB is insane.
- Time: 090306 6:30:42
- User@Host: moodle[moodle] @ localhost []
- Query_time: 21631 Lock_time: 0 Rows_sent: 0 Rows_examined: 1199857693
UPDATE mdl_stats_daily
SET stat2 = (SELECT COUNT(DISTINCT ra.userid)
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 ra.roleid = mdl_stats_daily.roleid AND
c.id = mdl_stats_daily.courseid AND
((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))) AND
EXISTS (SELECT 'x'
FROM mdl_log l
WHERE l.course = mdl_stats_daily.courseid AND
l.userid = ra.userid AND l.time >= 1236164400 AND l.time < 1236250800))
WHERE mdl_stats_daily.stattype = 'enrolments' AND
mdl_stats_daily.timeend = 1236250800 AND
mdl_stats_daily.courseid IN
(SELECT DISTINCT l.course
FROM mdl_log l
WHERE l.time >= 1236164400 AND l.time < 1236250800);
Attachments
-
- commit-5b5a23f
- 19/Oct/09 8:44 AM
- 14 kB
- Matt Clarkson
-
- statslib.php-rev01.diff
- 09/Nov/10 5:20 PM
- 17 kB
- Matteo Scaramuccia
-
- statslib.php-rev02.diff
- 09/Nov/10 7:44 PM
- 18 kB
- Matteo Scaramuccia
-
- statslib.php-rev03.diff
- 05/Apr/11 1:56 AM
- 28 kB
- Juan Segarra Montesinos
-
- statslib.php-rev04.diff
- 06/Apr/11 12:02 AM
- 31 kB
- Juan Segarra Montesinos
-
- statslib.php-rev05.diff
- 07/Apr/11 8:07 PM
- 34 kB
- Juan Segarra Montesinos
-
- statslib.php-rev06.diff
- 12/Apr/11 7:15 PM
- 36 kB
- Juan Segarra Montesinos
-
- statslib.php-rev07.diff
- 12/Apr/11 8:09 PM
- 36 kB
- Juan Segarra Montesinos
-
- statslib.php-rev08.diff
- 12/Apr/11 11:40 PM
- 38 kB
- Juan Segarra Montesinos
-
- statslib.php-rev09.diff
- 09/Feb/12 5:16 AM
- 38 kB
- Tyler Bannister
Issue Links
Activity
- All
- Comments
- History
- Activity
- Source
- Test Sessions
For reference, I have attached a patch to statslib that incorporates many of the ideas from this tracker item. On a large DB it dropped stats process times down to around 10 minutes from several hours.
The patch is postgres specific, although it probably works in MySQL too.
We are having the same issue...
Did anyone try out Matt's patch with MySQL DB?
We are having the same issue, too.
We try out Matt's patch with MySQL 5.1.28.
This patch works, but error occured.
But, it will done in 1 minute.
Thanks for Matt.
— cron.php output —
Running daily statistics gathering, starting at 1242140400:
......error occured, completed 0 days of statistics.
Just applied the patch and it works perfectly for our installation. We are currently running Moodle 1.9.7 on PostgreSQL.
Before we had the problem of hanging database processes every once in a while. This was caused by the "UPDATE mdl_stats_daily" query hanging forever with postgres locked up at 100% CPU.
We got rid of this problem by applying the patch. In addition the stats processing is now significantly faster.
Thank you Matt for sharing this patch.
I can confirm that this is also occurring in Moodle 1.9.6+ (Build: 20091104).
We are on MySQL 5.0.44.
The query causing the blocking was:
UPDATE mdl_stats_daily
SET stat2 = (SELECT COUNT(DISTINCT ra.userid)
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 c.id = mdl_stats_daily.courseid AND
((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))) AND
EXISTS (SELECT 'x'
FROM mdl_log l
WHERE l.course = mdl_stats_daily.courseid AND
l.userid = ra.userid AND l.time >= 1258351200 AND l.time < 1258437600))
WHERE mdl_stats_daily.stattype = 'enrolments' AND
mdl_stats_daily.timeend = 1258437600 AND
mdl_stats_daily.roleid = 0 AND
mdl_stats_daily.courseid IN
(SELECT l.course
FROM mdl_log l
WHERE l.time >= 1258351200 AND l.time < 1258437600 AND l.course <> 1)
Output from Queries requested by others in this thread:
select * from mdl_config where name like '%stats%';
id, name, value
2, 'statsrolesupgraded', '1250715358'
146, 'enablestats', '1'
147, 'statsfirstrun', 'none'
148, 'statsmaxruntime', '0'
149, 'statsruntimestarthour', '0'
150, 'statsruntimestartminute', '0'
151, 'statsuserthreshold', '0'
152, 'statscatdepth', '1'
381, 'statsruntimedays', '31'
418, 'coursereport_stats_version', '2007101501'
430, 'statslastdaily', '1258351200'
431, 'statslastexecution', '1266386431'
432, 'statsrunning', '1266472831'
Thanks for the patch Matt. I've tested it with MySQL in a couple of different dev/test environments, and it gives the same error each time:
Running daily statistics gathering, starting at 1283904000:
1:103 2:0 3:24 <div class="notifytiny" style="text-align:center">Can't reopen table: 'l'<br /><br />UPDATE mdl_stats_daily
SET stat2 = (SELECT COUNT(DISTINCT e.userid)
FROM mdl_tmp_stats_enrolments e
INNER JOIN mdl_tmp_stats_logs l ON l.userid = e.userid AND l.course = e.courseid
WHERE e.courseid = mdl_stats_daily.courseid AND e.roleid = mdl_stats_daily.roleid
)
WHERE mdl_stats_daily.stattype = 'enrolments' AND
mdl_stats_daily.timeend = 1283990400 AND
mdl_stats_daily.courseid IN
(SELECT DISTINCT course
FROM mdl_tmp_stats_logs)<ul style="text-align: left"><li>line 103 of lib/dmllib.php: call to debugging()</li><li>line 274 of lib/statslib.php: call to execute_sql()</li><li>line 542 of admin/cron.php: call to stats_cron_daily()</li></ul></div>
...error occured, completed 0 days of statistics.
Any advice on how to make it work in MySQL?
Cheers,
Tony
Hi Tony,
have you tried to remove the string "TEMPORARY " from Matt's patch?
Since these 2 new temp tables, tmp_stats_*s, will be explicitly DROPped at the end of the process, TEMPORARY is not required and this could fix your Can't reopen table: 'l' error in MySQL. The same should apply to PostgreSQL too: in both systems, at the very end, a TEMPORARY table is used to strictly definy the life cycle of the table itself just within the user connection session i.e. assuming an automatic DROP statement, here explicitly coded.
Let me know since I'm interested too (+1) ![]()
Matteo
This is a first review of the original proposed patch, commit-5b5a23f.
Differences are:
- Removed TEMPORARY to avoid errors w/ MySQL
- [Minor] Added time elapsed for weekly and monthly, to keep tracking of the time spent on these tasks
- [Trivial] Added {dayly, weekly, monthly} stats type in "finished until" statement for the sake of easy reading
- [Trivial] Fixed indentation
- Removed TEMPORARY to avoid errors w/ MySQL
- [Minor] Added time elapsed for weekly and monthly, to keep tracking of the time spent on these tasks
- [Trivial] Added {dayly, weekly, monthly} stats type in "finished until" statement for the sake of easy reading
- [Trivial] Fixed indentation
Find below the time benefits of the first run of the reviewed patch proposal (commit-5b5a23f => statslib.php-rev01.diff) in MySQL on a medium sized Moodle site: besides locking is no more an issue.
Before:
cron_output-20101101T000301.log:................ finished until 1288566000: lunedì, 1 novembre 2010, 00:00 (in 4050 s) cron_output-20101102T000301.log:................ finished until 1288652400: martedì, 2 novembre 2010, 00:00 (in 3905 s) cron_output-20101103T000301.log:................ finished until 1288738800: mercoledì, 3 novembre 2010, 00:00 (in 4794 s) cron_output-20101104T000301.log:................ finished until 1288825200: giovedì, 4 novembre 2010, 00:00 (in 5040 s) cron_output-20101105T000301.log:................ finished until 1288911600: venerdì, 5 novembre 2010, 00:00 (in 8839 s) cron_output-20101106T000301.log:................ finished until 1288998000: sabato, 6 novembre 2010, 00:00 (in 8891 s) cron_output-20101107T000301.log:................ finished until 1289084400: domenica, 7 novembre 2010, 00:00 (in 9031 s) cron_output-20101108T000301.log:................ finished until 1289170800: lunedì, 8 novembre 2010, 00:00 (in 8582 s)
After:
cron_output-20101109T000301.log: finished until 1289257200: martedì, 9 novembre 2010, 00:00 (in 1591 s)
Note: dots missing here since I'm using $CFG->showcronsql = true; to track queries.
cron_output-20101101T000301.log:................ finished until 1288566000: lunedì, 1 novembre 2010, 00:00 (in 4050 s) cron_output-20101102T000301.log:................ finished until 1288652400: martedì, 2 novembre 2010, 00:00 (in 3905 s) cron_output-20101103T000301.log:................ finished until 1288738800: mercoledì, 3 novembre 2010, 00:00 (in 4794 s) cron_output-20101104T000301.log:................ finished until 1288825200: giovedì, 4 novembre 2010, 00:00 (in 5040 s) cron_output-20101105T000301.log:................ finished until 1288911600: venerdì, 5 novembre 2010, 00:00 (in 8839 s) cron_output-20101106T000301.log:................ finished until 1288998000: sabato, 6 novembre 2010, 00:00 (in 8891 s) cron_output-20101107T000301.log:................ finished until 1289084400: domenica, 7 novembre 2010, 00:00 (in 9031 s) cron_output-20101108T000301.log:................ finished until 1289170800: lunedì, 8 novembre 2010, 00:00 (in 8582 s)
cron_output-20101109T000301.log: finished until 1289257200: martedì, 9 novembre 2010, 00:00 (in 1591 s)
Added statslib.php-rev02.diff, small review of statslib.php-rev01.diff to cleanup not used vars & phpdoc and to better track DROP failures. I will start keep tracking of performances to see the time gain and possible other locking issues, the 1st result being already reported.
I expect some similar issues in the weekly process, being weekly simplier but acting on the same tables causing locking issues (monthly is equal to weekly except for table names and time range).
MySQL slow queries w/ statslib.php-rev02.diff is:
# Time: 101110 0:14:36 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 692 Lock_time: 0 Rows_sent: 0 Rows_examined: 2100148 use <moodle19db>; CREATE TABLE mdl_tmp_stats_enrolments AS ### stats_create_enrolled_table() ### ... # Time: 101110 0:15:04 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 25 Lock_time: 0 Rows_sent: 0 Rows_examined: 16753728 SET insert_id=1381637; INSERT INTO mdl_stats_user_daily (stattype, timeend, courseid, userid, statsreads, statswrites) ### 10th query ### ... # Time: 101110 0:28:57 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 832 Lock_time: 0 Rows_sent: 0 Rows_examined: 14121095 use <moodle19db>; SET insert_id=6695347; INSERT INTO mdl_stats_daily (stattype, timeend, courseid, roleid, stat1, stat2) ### 12th query ### ... # Time: 101110 0:29:16 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 19 Lock_time: 0 Rows_sent: 0 Rows_examined: 2063623 SET insert_id=6696487; INSERT INTO mdl_stats_daily (stattype, timeend, courseid, roleid, stat1, stat2) ### 13th query ### ...
Time spent here is 1568 while the overall time of the run is 1575:
cron_output-20101110T000301.log: finished daily until 1289343600: mercoledì, 10 novembre 2010, 00:00 (in 1575 s)
# Time: 101110 0:14:36 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 692 Lock_time: 0 Rows_sent: 0 Rows_examined: 2100148 use <moodle19db>; CREATE TABLE mdl_tmp_stats_enrolments AS ### stats_create_enrolled_table() ### ... # Time: 101110 0:15:04 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 25 Lock_time: 0 Rows_sent: 0 Rows_examined: 16753728 SET insert_id=1381637; INSERT INTO mdl_stats_user_daily (stattype, timeend, courseid, userid, statsreads, statswrites) ### 10th query ### ... # Time: 101110 0:28:57 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 832 Lock_time: 0 Rows_sent: 0 Rows_examined: 14121095 use <moodle19db>; SET insert_id=6695347; INSERT INTO mdl_stats_daily (stattype, timeend, courseid, roleid, stat1, stat2) ### 12th query ### ... # Time: 101110 0:29:16 # User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>] # Query_time: 19 Lock_time: 0 Rows_sent: 0 Rows_examined: 2063623 SET insert_id=6696487; INSERT INTO mdl_stats_daily (stattype, timeend, courseid, roleid, stat1, stat2) ### 13th query ### ...
cron_output-20101110T000301.log: finished daily until 1289343600: mercoledì, 10 novembre 2010, 00:00 (in 1575 s)
Find below the result of a 1 week screening: numbers are stable, locking has gone, optimization should be done as already described in http://tracker.moodle.org/browse/MDL-18484#comment_97426_header_matteo.
cron_output-20101109T000301.log: finished until 1289257200: martedì, 9 novembre 2010, 00:00 (in 1591 s) cron_output-20101110T000301.log: finished daily until 1289343600: mercoledì, 10 novembre 2010, 00:00 (in 1575 s) cron_output-20101111T000301.log: finished daily until 1289430000: giovedì, 11 novembre 2010, 00:00 (in 1574 s) cron_output-20101112T000301.log: finished daily until 1289516400: venerdì, 12 novembre 2010, 00:00 (in 1575 s) cron_output-20101113T000301.log: finished daily until 1289602800: sabato, 13 novembre 2010, 00:00 (in 1570 s) cron_output-20101114T000302.log: finished daily until 1289689200: domenica, 14 novembre 2010, 00:00 (in 1565 s) cron_output-20101114T000302.log: finished weekly until 1289689200: domenica, 14 novembre 2010, 00:00 (in 1 s)
cron_output-20101109T000301.log: finished until 1289257200: martedì, 9 novembre 2010, 00:00 (in 1591 s) cron_output-20101110T000301.log: finished daily until 1289343600: mercoledì, 10 novembre 2010, 00:00 (in 1575 s) cron_output-20101111T000301.log: finished daily until 1289430000: giovedì, 11 novembre 2010, 00:00 (in 1574 s) cron_output-20101112T000301.log: finished daily until 1289516400: venerdì, 12 novembre 2010, 00:00 (in 1575 s) cron_output-20101113T000301.log: finished daily until 1289602800: sabato, 13 novembre 2010, 00:00 (in 1570 s) cron_output-20101114T000302.log: finished daily until 1289689200: domenica, 14 novembre 2010, 00:00 (in 1565 s) cron_output-20101114T000302.log: finished weekly until 1289689200: domenica, 14 novembre 2010, 00:00 (in 1 s)
Hi Matteo,
This is looking very good. I've run a week's worth of stats on a test server, both before and after applying the patch, on the same set of data, just to satisfy myself that the actual statistics generated will be the same (and I can confirm that they are).
I've now applied the patched statslib.php to our live server and ran the first real set of stats last night. It took 32 minutes, as opposed to the usual hour+, so I'm very optimistic.
I'll report back with the results when I've got about a week's worth to show you.
Cheers,
Tony
Hi All,
the unresolved issues related w/ query #10 and #12 keep on giving some serious problems, see e.g. numbers ( 3631615089!!! ) at the end of a week:
# Time: 101121 0:41:55
# User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>]
# Query_time: 2332 Lock_time: 0 Rows_sent: 0 Rows_examined: 3631615089
use <moodle19db>;
CREATE TABLE mdl_tmp_stats_enrolments AS
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)));
Maybe an approach like the one suggested by Juan could be winning: has someone already reviewed statslib.php-rev02.diff, adding new stuff?
# Time: 101121 0:41:55
# User@Host: <moodleuser>[<moodleuser>] @ <moodlehost> [<moodleipaddress>]
# Query_time: 2332 Lock_time: 0 Rows_sent: 0 Rows_examined: 3631615089
use <moodle19db>;
CREATE TABLE mdl_tmp_stats_enrolments AS
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)));
It's now a week since I applied statslib.php-rev02.diff to our production server, so here are the results so far.
Before applying patch:
................ finished until 1289260800: Tuesday, 9 November 2010, 12:00 AM (in 6305 s) ................ finished until 1289347200: Wednesday, 10 November 2010, 12:00 AM (in 4912 s) ................ finished until 1289433600: Thursday, 11 November 2010, 12:00 AM (in 5757 s) ................ finished until 1289520000: Friday, 12 November 2010, 12:00 AM (in 4911 s) ................ finished until 1289606400: Saturday, 13 November 2010, 12:00 AM (in 4427 s) ................ finished until 1289692800: Sunday, 14 November 2010, 12:00 AM (in 3415 s) ................ finished until 1289779200: Monday, 15 November 2010, 12:00 AM (in 3653 s)
After applying patch:
................ finished daily until 1289865600: Tuesday, 16 November 2010, 12:00 AM (in 1924 s) ................ finished daily until 1289952000: Wednesday, 17 November 2010, 12:00 AM (in 1912 s) ................ finished daily until 1290038400: Thursday, 18 November 2010, 12:00 AM (in 2071 s) ................ finished daily until 1290124800: Friday, 19 November 2010, 12:00 AM (in 1699 s) ................ finished daily until 1290211200: Saturday, 20 November 2010, 12:00 AM (in 1520 s) ................ finished daily until 1290297600: Sunday, 21 November 2010, 12:00 AM (in 1497 s) ................ finished daily until 1290384000: Monday, 22 November 2010, 12:00 AM (in 1414 s)
That's an average execution time of ~1720 seconds per night, as opposed to ~4769 seconds before applying the patch, which I reckon is a pretty impressive improvement.
Locking is still an issue though. Nagios reports the site as being unresponsive for about 10 minutes now, whereas before applying the patch it was about 30 minutes per night.
Tony
................ finished until 1289260800: Tuesday, 9 November 2010, 12:00 AM (in 6305 s) ................ finished until 1289347200: Wednesday, 10 November 2010, 12:00 AM (in 4912 s) ................ finished until 1289433600: Thursday, 11 November 2010, 12:00 AM (in 5757 s) ................ finished until 1289520000: Friday, 12 November 2010, 12:00 AM (in 4911 s) ................ finished until 1289606400: Saturday, 13 November 2010, 12:00 AM (in 4427 s) ................ finished until 1289692800: Sunday, 14 November 2010, 12:00 AM (in 3415 s) ................ finished until 1289779200: Monday, 15 November 2010, 12:00 AM (in 3653 s)
................ finished daily until 1289865600: Tuesday, 16 November 2010, 12:00 AM (in 1924 s) ................ finished daily until 1289952000: Wednesday, 17 November 2010, 12:00 AM (in 1912 s) ................ finished daily until 1290038400: Thursday, 18 November 2010, 12:00 AM (in 2071 s) ................ finished daily until 1290124800: Friday, 19 November 2010, 12:00 AM (in 1699 s) ................ finished daily until 1290211200: Saturday, 20 November 2010, 12:00 AM (in 1520 s) ................ finished daily until 1290297600: Sunday, 21 November 2010, 12:00 AM (in 1497 s) ................ finished daily until 1290384000: Monday, 22 November 2010, 12:00 AM (in 1414 s)
Hi Matteo,
Sorry but I'm not really involved with this... if I just have time... I'll try to help.
Please, rewrite the query as in [1] and test (run it from mysql cilent, for instance. Do a RESET QUERY CACHE before). Please note that the query may contain repeated rows. I don't know if this can cause some problems in code... please review that
Maybe not or maybe we can circumvent it from PHP.
[1]
CREATE TABLE mdl_tmp_stats_enrolments AS
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)
UNION
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 c.id = ctx.instanceid AND ctx.contextlevel = 50)
UNION
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 cc1.id = ctx.instanceid AND ctx.contextlevel = 40);
Mmmm... forget about the repeated rows... it won't contain any ![]()
Hi Juan,
I've been following this as we have been having the same issue across a few sites. Is it possible to add your latest update into another attached diff file?
Thanks,
Andrea
I'm not working on this... and I don't have a patch... but I think that following this guidelines, code can run faster and reduce contention. I'll try to work on this and help...
That's great Juan because we still do not have this resolved. We have gone through all patches and guidelines here. The only part we were stuck on was the last comment by yourself. If that could be a patch, that would be amazing thanks
- Andrea
Hi all... I'm about to finish a new patch. Not heavily reviewed... so I'll need some feedback... stay tunned ![]()
This is a preliminary patch to test. It just adresses daily statistics gathering problem... once we get it validated I'll start with weekly and monthly.
Please, if you fell comfortable with SQL, please help to ensure equivalence with the new and old queries and the new enrollment pre-calculated tables.
The patch probably wont work for now in postgrees, but it can be easily adapted.
Thanks ![]()
Hi again. I'm trying to manage the whole thing with git:
https://github.com/anariel/moodle/tree/MDL-18484
bye! ![]()
Added statslib.php-rev04.diff
This patch adds the following:
. solves a critical problem in rev03 patch
. creates temporary tables using XMLDB
. runs faster than rev03
Please... anyone interested in testing?
bye ![]()
Added statslib.php-rev05.diff
Fixes some bugs in previous patch.
Need a little more testing
Added statslib.php-rev06.php
This fixes some bugs.
I have validated the results against the original statslib.php version on a server with more than 1 million actions per moth.
It runs really quickly. More or less 50 seconds per day.
Please give it a try.
Not tested on servers other than mysql. Runs on moodle 1.9.x
This just optimizes daily statistics. I'll do some code cleanup.
Regards ![]()
Uploaded statslib.php-rev07.diff
Fixed a typo in enrollments calculation.
Thanks Juan, I'll definitely give this a try. I've got a few things on the go right now but I'll hopefully have time to test it before the end of the week.
Tony
Thanks Tony
I need help with data validation... ie, if we get exactly the same results as with the original library.
Regards ![]()
(sorry for the spam) ![]()
Uploaded statslib.php-rev08.diff
Just code cleanup.
Regards ![]()
Hi Juan,
I've re-run last week's stats on a test server, with the following results (original results in brackets):
| Period ending | Guest | Student | Support Tutor | Lecturer | Administrator | All |
|---|---|---|---|---|---|---|
| 9 April 2011 | 139(139) | 3546(3546) | 87(87) | 1105(1105) | 653(653) | 5572(5572) |
| 8 April 2011 | 133(133) | 4370(4371) | 114(114) | 1244(1244) | 113(113) | 5935(5935) |
| 7 April 2011 | 147(147) | 5680(5684) | 326(326) | 1937(1937) | 124(124) | 8313(8313) |
| 6 April 2011 | 161(161) | 4984(4984) | 255(283) | 1946(1918) | 102(102) | 7506(7506) |
| 5 April 2011 | 130(114) | 6299(6315) | 163(163) | 2251(2251) | 228(228) | 9139(9139) |
As you can hopefully see (if the table formatting worked), most of the results are identical with just a few slight differences. But couldn't these small discrepancies have been caused by the fact that the stats were re-run at a later time, when some of the enrolments are bound to have changed?
By the way: wow, is it fast! It averaged about 35 seconds per day, even on a puny test VM. Nice work!
| Period ending | Guest | Student | Support Tutor | Lecturer | Administrator | All |
|---|---|---|---|---|---|---|
| 9 April 2011 | 139(139) | 3546(3546) | 87(87) | 1105(1105) | 653(653) | 5572(5572) |
| 8 April 2011 | 133(133) | 4370(4371) | 114(114) | 1244(1244) | 113(113) | 5935(5935) |
| 7 April 2011 | 147(147) | 5680(5684) | 326(326) | 1937(1937) | 124(124) | 8313(8313) |
| 6 April 2011 | 161(161) | 4984(4984) | 255(283) | 1946(1918) | 102(102) | 7506(7506) |
| 5 April 2011 | 130(114) | 6299(6315) | 163(163) | 2251(2251) | 228(228) | 9139(9139) |
Thanks Tony ![]()
Changes in roles may be the cause for the different numbers. The best way to test may be the following:
0. Use a copy of your database not in production. We are going to compare with the same resultset.
1. Calculate the stats with the original library
2. Copy the tables mdl_stats_daily and mdl_stats_user_daily. Just like this:
CREATE TABLE mdl_stats_daily_original LIKE
SELECT * FROM mdl_stats_daily;
CREATE TABLE mdl_stats_user_daily_original LIKE
SELECT * FROM mdl_stats_user_daily;
3. Now delete the rows just inserted in mdl_stats_daily and mdl_stats_user_daily.
4. Run the stats over the same period with the new statslib.php and with the same original data.
Now we can compare rows in both tables like this (sorry but :
SELECT COUNT![]()
FROM mdl_stats_daily s1
WHERE timeend > "put here a reasonable timestamp
" AND
EXISTS (
SELECT 1
FROM mdl_stats_daily_original s2
WHERE s1.timeend = s2.timeend AND
s1.userid = s2.userid AND
s1.courseid = s2.courseid AND
s1.roleid = s2.roleid AND
s1.stattype = s2.stattype AND
( s1.stat1 <> s2.stat1 OR
s1.stat2 <> s2.stat2 )
);
This COUNT should be 0
And this one too:
SELECT COUNT![]()
FROM mdl_stats_user_daily s1
WHERE timeend > "put here a reasonable timestamp
" AND
EXISTS (
SELECT 1
FROM mdl_stats_user_daily_original s2
WHERE s1.timeend = s2.timeend AND
s1.userid = s2.userid AND
s1.courseid = s2.courseid AND
s1.roleid = s2.roleid AND
s1.stattype = s2.stattype AND
( s1.statsreads <> s2.statsread OR
s1.statswrites <> s2.statswrites )
);
I've written this queries without testing them... so be careful. If I have time I'll do an easy script to automate this tests and others.
Thank you again for your time ![]()
No problem. I was hoping to get away with not re-running the stats with the original library on my test VM because of the amount of time it would take, but it looks like it's going to be the only way to get accurate results.
I left it going overnight and so far it's managed to process 1 day with the original library - in 56995 seconds! That's even worse than I expected. So I guess we can expect the final results by about the middle of next week. ![]()
Hi again. I've validated again in the way similar to that described before. I get exactly the same results with the original library and the new one. So the patch is ok.
Someone is able to test with postgress and others?
I'll port this to 2.x
Regards ![]()
Hi Juan,
Sorry about the delay with my results. By the time the re-run with the original library had completed (it took about a week!) I was out of the office on a week's leave. Since I got back I've been trying to compare the 2 sets of results using the method you described above (exact query used below):
SELECT COUNT![]()
FROM mdl_stats_daily s1
WHERE timeend > "1301616000" AND
EXISTS (
SELECT 1
FROM mdl_stats_daily_original s2
WHERE s1.timeend = s2.timeend AND
s1.courseid = s2.courseid AND
s1.roleid = s2.roleid AND
s1.stattype = s2.stattype AND
( s1.stat1 <> s2.stat1 OR
s1.stat2 <> s2.stat2 )
);
This one query has now been running for 517695 seconds (almost 6 days!) and still hasn't finished!
However, I have also done a visual comparison of the statistics report for the week in question, and the 2 sets of results are identical.
Tony
Hi Juan,
We have the "same" problems with stats in Moodle 2.x. Have you been able to port your fix yet?
Thx!
Jean-Philippe
Here's a fix for Moodle 2.x. : http://tracker.moodle.org/browse/MDL-30643
I only created temporary table for logs but the performances are good this way. (Less than 50 seconds -> 150 000 logs per day)
I tried out the patch on a test server and cron.php spat out these warnings 30 times each:
Warning: Invalid argument supplied for foreach() in /home/tyler/projects/moodle-plain/lib/statslib.php on line 258
Warning: Invalid argument supplied for foreach() in /home/tyler/projects/moodle-plain/lib/statslib.php on line 308
It looks like the patched code should check the return values from get_records_sql.
Hi Tyler,
This warning (in 1.9) is shown because get_records_sql returns false and we're giving foreach() a false value
You can test $res before giving it to forach().
bye! ![]()
I've added another patch file that fixes the error issue I mentioned.
My testing is returning identical results from this version as the original (unpatched) stats generation. With my additional changes the processing time for my sample data went from 90 minutes for 31 days of logs to approximately 88 seconds for the same logs which is a little less than the rev08 version.
The big changes are replacing the looped updates with individual queries and the removal of an unnecessary cross join during the "enrollments view" creation.
I've been working on this in our test servers and found serveral approaches that can be used in order to improve performance and table (or row) contention. We work with mysql 5.0.x and Innodb. Maybe this can help:
1. Enrollments are calculated in nearly every query in daily stats. They can be precalculated (just one time) in an indexed-temporary table and then use this temporary table in queries.
2. Logs table can be precalculated too. I'm using a temporary table of logs with this time restrictions. This reduces contention in mdl_log table and allows working with less data.
3. The ORs in enrollments calculation can be decompossed in UNIONs. This performs better in mysql because of one-index per table restriction. Don't know postgress or oracle...
Hope this tips help.
Regards