Strategies for Debugging Load Spikes

Posted by kcoop on August 4, 2009 at 9:17pm

I'm running a site that has lately been experiencing significant load spikes that appear unrelated to the number of concurrent users.

I'm running apache on a dedicated CentOS server. I've now got Boost and eAccelerator installed. My loads are typically very minimal (< .5), but then spike to over 35 (they were hitting over 100 before I added eAccelerator), at which point I have to restart apache to calm things down.

The site is the commenting board for an externally hosted blog. Its primary function is posting/viewing comments that are associated with a stub node. I've written a few modules to integrate with the external site, and to provide auto update functionality based on ajax polling, but I'm using the stock comment module. The site attracts a significant number of anonymous users (typically 500 guests/50 users at peak times), and they aren't authorized to post.

My question is how to go about debugging this. I don't have a tremendous amount of experience with lamp, so have been stabbing in the dark, without success (boost and eaccelerator have dropped the general load considerably, but not prevented the spikes). Are there tools/strategies any kind soul would recommend to determine what the issue might be? My latest hunch is that table locking is causing the server to bog down (it is a relatively high traffic site), but I don't know how to verify this before I dive into converting things to innodb.

Comments

MySQL queries?

Posted by kbahey on August 5, 2009 at 2:25am

You can make use of memcache as a first tier in conjunction with Boost. It will cache the variables, menu, and other stuff and benefit the site in general.

For starters, did you check any MySQL queries?

You can do that by seeing the output from the command:

mysqladmin -i3 processlist

This will display all the queries that are currently running every 3 seconds. If you are using MyISAM, and you have a locking issue, you will see a lot of "Locked" status. Converting the tables to InnoDB will help if that is the case, and you are running Drupal 6.

ALTER TABLE tablename Engine=InnoDB;

Drupal performance tuning, development, customization and consulting: 2bits.com, Inc..
Personal blog: Baheyeldin.com.

I've been meaning to install

Posted by kcoop on August 5, 2009 at 3:41am

I've been meaning to install memcache too, just wanted to determine what the real core problem is.

Thanks for the mysqladmin pointer. I'm looking at mysqladmin -i3 processlist, and seeing nothing but the following:

+---------+------+-----------+----------+---------+------+-------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+---------+------+-----------+----------+---------+------+-------+------------------+
| 1429862 | dev1 | localhost | dev1_hcn | Sleep | 24 | | |
| 1429883 | dev1 | localhost | | Query | 0 | | show processlist |
+---------+------+-----------+----------+---------+------+-------+------------------+

and I've currently got 54 active connections, so something seems awry.

I am running drupal 6. Are there side effects of switching to InnoDB? Any core patches that need to be applied, or is drupal 6 innodb ready?

InnoDB

Posted by omega8cc on August 5, 2009 at 10:04am

InnoDB helps when you have a lot of writes, but can degrade performance when you have a lot of select/sort queries on big tables. It works, but needs attention, monitoring and tuning.

Useful to start with: http://tag1consulting.com/MySQL_Engines_MyISAM_vs_InnoDB

And one more thing: if you are on 6.x, consider switching to Pressflow - http://pressflow.org - it includes important enhancements in core, especially for high traffic Drupal websites.

HTH
~Grace

-- Turnkey Drupal Hosting on Steroids -- http://twitter.com/omega8cc

Many many more reads than writes

Posted by kcoop on August 5, 2009 at 4:47pm

I see probably one or two posts per minute.

I'll look into pressflow, thanks.

No queries

Posted by kbahey on August 5, 2009 at 10:27pm

What this says is that there are no queries running when you are monitoring.

Did you do that when the site is under load and observe no queries still?

As for the number of MySQL connections 54 is not unreasonably high, specially when you are running PHP as an Apache module.

If you switch to running PHP as FastCGI, you can use much less PHP processes, and the connections go down automatically in MySQL. See Apache with fcgid: acceptable performance and better resource utilization.

[Just saw it was referenced below. It should also make serving static files less resource intensive as Grace said later.]

Don't jump into trying Pressflow and Nginx and memcache and whatnot until you have diagnosed the problem first.

Drupal performance tuning, development, customization and consulting: 2bits.com, Inc..
Personal blog: Baheyeldin.com.

It's not under heavy load, but load nonetheless

Posted by kcoop on August 5, 2009 at 10:52pm

which struck me as very odd. Is this output somehow missing part of the queries? Possibly filtered by user, database, or something else?

And sorry to be unclear, the connections I'm referring to are via netstat, piped through sort, uniq and then wc.

No

Posted by kbahey on August 6, 2009 at 12:28am

No, it is not missing anything.

It shows the first chunk of the query, but you will see a query and a state.

Here is an example of query from two sites:

| 128852 | live | localhost | live | Query   | 1    | Copying to tmp table | SELECT DISTINCT(n.nid), n.sticky, n.title, n.created FROM node n  INNER JOIN term_node tn0 ON n.vid  |
| 1811986 | live | localhost | live | Query   | 0    | end   |  UPDATE sessions SET uid = 0, cache = 0, hostname = '10.10.10.10', session = '', timestamp = 1249517840 WHERE sid = 'zzzzzzzzzzzzz' |
| 1812141 | live | localhost | live | Query   | 0    |       |  SELECT p.perm FROM role r INNER JOIN permission p ON p.rid = r.rid WHERE r.rid IN (1) |
| 1813014 | live | localhost | live | Query   | 0    | statistics |  SELECT t.vid FROM term_node r INNER JOIN term_data t ON r.tid = t.tid INNER JOIN vocabulary v ON t.vid = v.vid WHERE r.vid = 10099 ORDER BY v.weight, t.weight, t.name LIMIT 0, 1 |

As for the number of connections, I assumed they are MySQL. Now you say they are network connections (most probably). You need to focus on the ESTABLISHED ones. So grep EST and then do the sort and wc.

You also need to let Apache set the KeepAliveTimeout to 3 or so, not the huge default that it comes with. You may want to reduce the KeepAliveRequests to 20 or so as well.

Again, we are chasing to many things. You need to describe the state of the system AT THE TIME OF THE SPIKE, not when it is normal. This means memory, swapping (if any), CPU, network, ...etc.

Munin was mentioned in this thread. I second that.

Drupal performance tuning, development, customization and consulting: 2bits.com, Inc..
Personal blog: Baheyeldin.com.

I was actually grepping :80 for connections

Posted by kcoop on August 6, 2009 at 1:09am

To be clear, here's the line:

netstat -an | grep :80 | awk '{ print $5 }' |  grep -o -P '\d+.\d+.\d+.\d+' | sort | uniq -c | sort -n | wc -l

At this moment, this results in a value of 119. When I run mysqladmin -i3 processlist just now for as long as a minute, all I saw are the processlist itself, and occasionally a sleep. I even set it to -i1 for grins, and the sleeps simply went away.

I want to do this at the time of the spike, but haven't seen one today, and want to sanity check the test before the heat is on. So far this doesn't seem sane.

EDIT: I just finally saw a query. I'm now a believer. Waiting for the next spike...

BTW, I'm in the process of installing Munin, which looks great, but it's turning out to be a big pain to install on CentOS.

You want established

Posted by kbahey on August 6, 2009 at 1:45am

If you have KeepAliveTimeout set to a reasonably low value, you should not care about any connection state besides the ESTABLISHED one.

Here is the command modified a bit.

See the number difference there?

# netstat -an | grep ":80 .*ESTABLISHED" | awk '{ print $5 }' |  grep -o '[0-9]*\.[0-9]*\.[0-9]*\.[0-9]*' | sort -u | wc -l
85

# netstat -an | grep :80 | awk '{ print $5 }' |  grep -o '[0-9]*\.[0-9]*\.[0-9]*\.[0-9]*' | sort -u | wc -l
550

EDIT: This is on a 4GB, 4 core server that gets over a million page views a day. 120 requests per second.

I agree Munin (and other stuff, like APC) are a pain on CentOS. This is why at 2bits.com we love Ubuntu Server LTS.

Drupal performance tuning, development, customization and consulting: 2bits.com, Inc..
Personal blog: Baheyeldin.com.

Yes, I'm learning about CentOS

Posted by kcoop on August 6, 2009 at 3:34am

Stuck with what my provider offered. Will be changing soon to a cloud server, once I can get past these issues.

Thanks for that, I'll update my script.

Site monitoring?

Posted by raintonr on August 5, 2009 at 7:10am

Are you using Cacti or similar to keep an eye on your server? Or from another box that is never overloaded would be even better.

With the usual 5 minute interval it might not be so useful for spotting shorter spikes, but it might help. Eg, maybe you are running out of memory (memory leak?) that then causes thrashing and the slowdown you see? With Cacti you'd see long term trends like that.

You can install templates for monitoring underlying server, MySQL and memcache even (if you go that way).

FWIW I was using eAccelerator but found it too unstable (is it even being actively maintained?). APC seems rock solid in comparison.

As suggested memcached can take load from your MySQL server and is easy to install (I used the memcache module).

Have you checked your mysql-slow.log or Apache error logs for clues?

Your site doesn't look to have any heavy blocks, but are there things that registered (or anonymous for that matter) users can do that a quick glance at the home page wouldn't reveal?

I'll take a look at cacti, thanks.

Posted by kcoop on August 5, 2009 at 4:39pm

I first installed APC, but it was incompatible with zend optimizer, and caused my server to crash. My host suggested eAccelerator at that point, and I haven't experienced problems. The spikes came earlier, so this is not the culprit.

There aren't any heavy blocks, and I don't have search enabled. The big load are the node pages themselves. I have 300 comments per page specified, which is a requirement (my users hate paging, and I'd completely eliminate the limit if I could).

I've looked at mysql-slow.log, and found an occasional slow query against the comments table. I'm unclear on what the value for time represents - is it milliseconds? Seems short for a value that is showing up as 49. Seconds? If so, yikes.

I've just taken a look at my apache log, thanks, and found two references to php taking longer than 30 seconds in the smiley module! I doubt this is the problem - it's been happening more frequently than these errors, but it's interesting nonetheless.

@kcoop

Posted by omega8cc on August 5, 2009 at 9:39am

Before hunting for solutions (Boost, eAccelerator, memcache etc.) you have to find a source of this problem.

Your problem can be related to something even outside of Drupal. For example it is possible your disk(s) experiences random problems and spikes are related to randomly degraded IO performance. BTW: do you have a full, fresh backup?

If you have million rows in a few tables and not enough memory for sort_buffer_size and/or myisam_sort_buffer_size, it will give you spikes in response to some heavy sort queries.

The list can be long.

@raintonr is right, you need a good system monitoring tool. I would recommend Munin - http://munin.projects.linpro.no/

It is the first step to diagnose the problem before trying any solutions.

HTH
~Grace

-- Turnkey Drupal Hosting on Steroids -- http://twitter.com/omega8cc

I've been wondering about monitoring tools, thanks.

Posted by kcoop on August 5, 2009 at 4:42pm

I'll take a look at munin and cacti.

And I do have at least a million rows in my comments table. My users are prolific.

Yes, with million rows..

Posted by omega8cc on August 5, 2009 at 5:34pm

...and not optimized Drupal - I mean vanilla Drupal with standard performance killers like LOWER() and locking tables, and maybe standard search enabled (I hope you disabled it), it is very easy to run into problems. Add here your "ajax polling" and bad things has to happen.

With over million comments you have to switch to Pressflow to survive :)

HTH
~Grace

-- Turnkey Drupal Hosting on Steroids -- http://twitter.com/omega8cc

Search was killing me

Posted by kcoop on August 5, 2009 at 8:51pm

so I did disable it. And the ajax polling has actually reduced traffic (the site has a lot of F5-ers) - it only polls if the last comment is visible (so idle users don't poll), and then only at a governable interval. And of course, no css, js, or images are requested.

Pressflow sounds promising, thanks.

Pressflow & Boost

Posted by mikeytown2 on August 5, 2009 at 9:54pm

FYI unless you grab the latest dev, or use this patch, boost and Pressflow don't work together.
http://drupal.org/node/530772

Oh, and yes, I do have a

Posted by kcoop on August 5, 2009 at 5:24pm

Oh, and yes, I do have a full fresh backup. :-)

Munin is great!

Posted by kcoop on August 6, 2009 at 3:58am

Thanks a lot for that tip. I had written a hacky little load monitor, wondering if there were better tools out there.

@kcoop

Posted by omega8cc on August 5, 2009 at 11:10am

Just checked you are using Apache to deliver static files (CSS etc) and you didn't enabled CSS aggregation. This simply means the heavy Apache with enabled mod_php, mod_ssl etc. has to work too hard.

You can enable CSS/JS aggregation here: http://www.hoocoodanode.org/admin/settings/performance

HTH
~Grace

-- Turnkey Drupal Hosting on Steroids -- http://twitter.com/omega8cc

I had css (and js) aggregation enabled initially

Posted by kcoop on August 5, 2009 at 4:43pm

Some of my users complained of browser errors, so I switched it off and the complaints went away. I'd MUCH prefer to have fewer css and js files served up. Any thoughts on this?

Use Nginx..

Posted by omega8cc on August 5, 2009 at 5:51pm

...for static files, or at least mod_fcgid in Apache to lower resources usage when serving static files. See:

http://groups.drupal.org/node/24130#comment-83548
http://2bits.com/articles/apache-fcgid-acceptable-performance-and-better...

With Nginx you can use expires 30d; for images and without aggregation (it's better to enable it and find why some users complained about problems) also for CSS/JS files.

But it seems the source of your problem is elsewhere. I think you need Pressflow and some MySQL tuning.

HTH
~Grace

-- Turnkey Drupal Hosting on Steroids -- http://twitter.com/omega8cc

Oops, just realized how much noise I'm adding to this group

Posted by kcoop on August 5, 2009 at 5:44pm

Thanks all. I appreciate the help.

A Followup

Posted by kcoop on August 27, 2009 at 10:35pm

This has been a great learning experience. Thank you all for your input.

Just to satisfy the curious, it turns out the primary culprit was a slow query in the CommentRSS module. It was taking 45 seconds, and other requests were getting backed up behind it.

Thanks everyone!

A Second Followup

Posted by kcoop on September 7, 2009 at 2:41am

While clearly the CommentRSS module was a problem, the spikes continued. I then added memcached, and disabled the glossary module (which it turns out is quite expensive if people are allowed to edit it). But they went on...

Today, I finally found the likely culprit. Someone has been executing a DoS attack on the site. I hadn't suspected it, because the apache volume didn't go up that much. But with the help of mod_status, I saw a correlation today between the spike and a suspicious swath of non-browser page accesses. This was confirmed when I looked at the apache logs and found a number of calls to cron.php...

I'm writing this mostly to help any neophytes like me... be sure to check mod_status!

@Ken

Posted by omega8cc on August 28, 2009 at 11:07pm

Thanks for the update! CommentRSS? Interesting. Will check that on some sites we used it in the past. Good to know.

~Grace -- Turnkey Drupal Hosting on Steroids -- http://omega8.cc

Another hot tip...

Posted by kcoop on September 10, 2009 at 7:21am

Check the ip address when you think you've got a bad guy. It might be yours. :-) Turns out this was a bug in a module I had written, that was calling back into the site. Maybe should have gotten a hint from all those cron.php calls...

Strategies for Debugging Load Spikes

Comments

MySQL queries?

I've been meaning to install

InnoDB

Many many more reads than writes

No queries

It's not under heavy load, but load nonetheless

No

I was actually grepping :80 for connections

You want established

Yes, I'm learning about CentOS

Site monitoring?

I'll take a look at cacti, thanks.

@kcoop

I've been wondering about monitoring tools, thanks.

Yes, with million rows..

Search was killing me

Pressflow & Boost

Oh, and yes, I do have a

Munin is great!

@kcoop

I had css (and js) aggregation enabled initially

Use Nginx..

Oops, just realized how much noise I'm adding to this group

A Followup

A Second Followup

@Ken

Another hot tip...

High performance

Group organizers

New groups

Group notifications