Ideas….

For those of you that aren’t Systems Administrators, here is the reason you don’t want to be.  At 12:30am when things go down, you have to wake up and figure out why.  And here I am writing a blog post about it.  Luckily its not 4am.  That was totally worse (I say this now…let’s see how long it takes me to figure this stuff out).

So I got my text message at 12:30am.  It confused me but then I woke up a bit.  It was a good thing I wrote the notes I did in my previous post, because trust me, I could have never come up with that stuff on my own right now.

First thing I did was run top.  CPU was at 100.1% (way to work hard server) for the mysqld process.  Second thing I did was check the slow query log.  There were actually a few slow queries, the first ones are still puzzling me.  Basically these were checking a table that had a whole lot of rows of data, the data didn’t need to be stored in those tables, i removed the data, and I stopped logging that data in the tables.  I probably won’t see those queries ever again. But this doesn’t really matter, those queries weren’t the ones hanging up the system, they were only take 11 t0 17 seconds to run.

I did see the last query that ran though, and this seems to be part of the problem, but not the query that was actually causing mysqld to hang. This query was:

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

SELECT ‘enrolments’, timeend, courseid, roleid, COUNT(DISTINCT userid), 0
FROM (
SELECT 1251691200 AS timeend, pl.courseid, pl.roleid, pl.userid
FROM (
SELECT DISTINCT ra.roleid, ra.userid, c.id as courseid
FROM role_assignments ra JOIN context ctx
ON ctx.id = ra.contextid
CROSS JOIN course c
JOIN role_capabilities rc
ON rc.roleid = ra.roleid LEFT OUTER JOIN 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 took a total of 41 seconds to execute.  I’m assuming that the next query after this was the one that brought the house down.  I saw the beginning of this when I went into mysql and did a show processlist:

+——-+————+———–+——–+———+——+————–+——————————————————————————————————+
| Id    | User       | Host      | db     | Command | Time | State        | Info                                                                                                 |
+——-+————+———–+——–+———+——+————–+——————————————————————————————————+
| 45654 | moodleuser | localhost | moodle | Query   | 1776 | Sending data | UPDATE stats_daily
SET stat2 = (SELECT COUNT(DISTINCT ra.userid)
|

The full query finally showed up in my query log once I killed the process.  Here it is in case you’re curious:

090902  0:01:29      45654 Query       UPDATE stats_daily
SET stat2 = (SELECT COUNT(DISTINCT ra.userid)
FROM role_assignments ra JOIN context ctx
ON ctx.id = ra.contextid
CROSS JOIN course c
JOIN role_capabilities rc
ON rc.roleid = ra.roleid LEFT OUTER JOIN course_categories cc1
ON cc1.id = c.category
WHERE ra.roleid = stats_daily.roleid AND
c.id = 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 log l
WHERE l.course = stats_daily.courseid AND
l.userid = ra.userid AND l.time >= 1251604800  AND l.time  < 1251691200))
WHERE stats_daily.stattype = ‘enrolments’ AND
stats_daily.timeend = 1251691200 AND
stats_daily.courseid IN
(SELECT DISTINCT l.course
FROM log l
WHERE l.time >= 1251604800  AND l.time  < 1251691200)

I also saw a whole bunch of other queries locked, waiting for this query to run.  I thought that perhaps switching the tables over to InnoDB rather than MyISAM might help alleviate the problem, but the truth is this appears to be a “the query is just ridiculous” problem rather than a “InnoDB is better at performance” problem.

So at anyrate I looked around and it seems this is a problem with the stats that Moodle keeps about itself.  Apparently in version 1.6 people had this problem a lot (because stats was new).  Basically I enabled stats because someone thought it was a good idea and I didn’t bother to consider how resource intensive this process could be (note to self: be a better sys admin and read documentation when someone thinks something might be useful).  I changed some settings in the stats configuration page and hope that this reduces the load and processing time of the stats query.  We’ll see if this fixes my problem.

Also, the amount of time I spent on this right now totally makes up for leaving work an hour and a half early to go meet my brother in law the electrician so he could replace outlets and light fixtures (my $12 sconces from lowes look quite lovely).

If you’re not interested in Moodle or troubleshooting MySQL problems, than you probably don’t want to read this post.  I however wanted to write some notes for myself and need it to be portable.  Since that’s technically the purpose of this blog, I figured I should put it here.

Recently Nagios started informing me that HTTPS was going down infrequently (but started to become more frequent).

***** Nagios  *****
Notification Type: PROBLEM
Service: HTTPS
Host: Moodle Server
Address: 123.456.78.912
State: CRITICAL
Date/Time: Fri Aug 28 01:06:50 EDT 2009
Additional Info:
CRITICAL – Socket timeout after 10 seconds

What was strange was that HTTP wasn’t going down.  I felt like Nagios was lying to me so I figured I would have to wake up late at night (early in the morning?) and catch it lying to me.  To do this I decided I’d try to figure out if my cellphone had an email to associate to text messaging.  Mine wasn’t working so I had to talk to Sprint about it.

In the mean time though, it was still going down.  Luckily last night at 4am I randomly woke up. I ran downstairs (imagine kid at Christmas…but like a reverse Christmas) and fired up the laptop.  Sure enough when I went to the Moodle homepage I saw this:

Error: Database connection failed.

It is possible that the database is overloaded or otherwise not running properly.

The site administrator should also check that the database details have been correctly specified in config.php

Now in hindsight, there were so many things I could have done at this point.  But it was 4am and my house was freezing so I made some mistakes.  The first thing I did was restart Apache.  It appeared to be running and the restart didn’t throw any errors, but it didn’t fix the problem either.  Next I “turned off SSL”.  I was able to get to the error page without the HTTPS so I determined at this point that Nagios clearly was lying to me, something else was wrong (p.s. i am thankful to Nagios for telling me that something was wrong).  So then I decided that maybe it was a database problem.  I went into MySQL and was able to access the Moodle database and do a “show tables;”.  So I thought at that point I should restart MySQL, in hindsight there are so many other things I should have done first, but I will document those below.  A restart of MySQL fixed the issue.

So what will I do next time (and yes…there will be a next time):

1) run top on the server: See if MySQL is hogging the CPU.  This could lead you to a number of options.

2) check the mysql-slow-queries.log: I set up the mysql option log-slow-queries.  this in conjunction with the long-query-time option will log any query that takes over a certain amount of time (default is 10s).

3) show mysql processlist: If you haven’t set up the log slow queries option this might also be helpful in determining what mysql is doing.  Here is a brief explaination of show processlist and its companion of kill <processid>.  I also found this handy script that you could set up as part of a cron to kill any runaway processes.

4) query is poorly written: I’ve found a number of reports that MySQL queries are poorly written in Moodle and that these can cause the CPU usage to top out at %100 which causes Moodle to be unusable.  Below are a few Moodle Tracker reports of this:

• http://tracker.moodle.org/browse/MDL-14911
• http://tracker.moodle.org/browse/MDL-19584
• http://tracker.moodle.org/browse/MDL-17051
• http://tracker.moodle.org/browse/MDL-10848

To see if this is the case with your Moodle use the slow query logging (or just the plain old query logging) with a backup of your database to see if you can replicate the problem somewhere else.  If you can the problem is probably the query and maybe you can figure out a way to rewrite the query (or get it rewritten) to see if that fixes the problem.

5) check your persistent db connection: Check to see if you have persistent database connections set up in the Moodle config.php file and in the php.ini file.  If you do, turn it off and see if this solves the problem.  it may be that your connections aren’t closing and they are killing your database regularly.

6) check your max connections: Are the maximum number of Apache connections greater than your maximum number of MySQL connections?  If so that might be a problem.  Basically users could get to the website but then when they go to request something in the database they can’t because the # of connections are taken up.  I have a feeling though that this may be a completely different error than what I was experiencing (people…including myself…really need to take screenshots or document errors better).

7) check your MySQL performance: Perhaps you haven’t configured Moodle right.  Take a look at these performance tuning tips to see if you can get it working better.

8) check your database tables: Stop mysqld and run a check on your Moodle tables.  See if some of the tables are corrupted, if they are fix them.

So if you’re wondering what I’m doing at 4am tomorrow, there’s the list.  Wish me luck.

Currently we are using the LMB Plugin for Moodle to enroll students into our courses.  This works swimmingly, until you have to enroll a large group into a class that really isn’t a class.  Let me explain…no let me sum up.

We have a bunch of placement tests and advising courses and that sort of thing we want our first year students to be enrolled in.  Moodle happens to have a flat file enrollment feature.  Below are the instructions from that enrollment feature:

This method will repeatedly check for and process a specially-formatted text file in the location that you specify. The file is a comma separated file assumed to have four or six fields per line:

*  operation, role, idnumber(user), idnumber(course) [, starttime, endtime]
where:
*  operation        = add | del
*  role             = student | teacher | teacheredit
*  idnumber(user)   = idnumber in the user table NB not id
*  idnumber(course) = idnumber in the course table NB not id
*  starttime        = start time (in seconds since epoch) - optional
*  endtime          = end time (in seconds since epoch) - optional

It could look something like this:

   add, student, 5, CF101
   add, teacher, 6, CF101
   add, teacheredit, 7, CF101
   del, student, 8, CF101
   del, student, 17, CF101
   add, student, 21, CF101, 1091115000, 1091215000

So great, I need to pull a randomly generated number rather than a username in order to enroll students.  So now I need to figure out a way to take a list of usernames in banner and get their corresponding idnumbers in Moodle.

Now if this were a one time thing I would take the lazy man’s way out and I would create a table in the database and do a simple

select table.username, user.idnumber
from table, user
where table.username = user.username;

But I’m going to have to do this every year until we either get rid of Moodle or I leave Wheaton.  Since plans are not in the work for either, I’ll actually do something more substantive.

First I made the decision to use the MySQL select in clause.  For those of you who don’t know, you can do:

select username, idnumber
from user
where username in ('value1', 'value2', 'valueN');

Its pretty useful really.  I can’t really find a MySQL page that talks about the in() clause but I did find a good post in the MySQL lists.  The next thing I had to figure out was how to push a file into a php array.  Again I found a great post on using the file() command to do this.  The only drawback is that when i go to print it’ll just show:

value1 value2 valueN

When that’s not what I want.  I need quotes and commas and crap around it.  So I found another great post that talks about using the implode function to put a php array into an in() clause.  The implode function will allow me to put quotes and what not around each one of the values in the array so it will look like this:

'value1', 'value2', 'valueN'

So now that I have the component parts, all I need to do is create a php page that will let me upload a file, run the query, and retrieve the outfile.  Of course the idea of writing this code makes me tired and since its 5pm I shall just publish this post and write the code tomorrow (hopefully).

UPDATE

I was wrong.  The value is not a randomly generated number, well it is, but its randomly generated by Banner.  In the Banner XML the value is the <sourcedid> for a <person>.

Luckily this randomly generated value is something that we can pull out of Banner using our reporting system.  The value (in our Banner) is gobsrid_sourced_id.  Not sure if it will be the same in your Banner, but hopefully this will put someone on the right track.

My next step is to document how to do all of this in our Moodle Documentation Wiki.  I might do a Jing Video.