Slow performance at the top of the hour

Posted by mrwhizkid on February 5, 2011 at 5:16am

Hello everyone. I have been following this group for a while now and I hope that you can help me with a big problem. I posted this in Post Installation Issues on the forums but haven't received any response.

This has been driving me crazy but I think I finally have some solid information to work with.

My site (and actually all of the sites on my VPS) have been freezing up every day at the top of the hour from 8AM-11AM Eastern Standard Time. This does NOT correspond to any traffic spikes. This happens regardless of how much traffic I have.

I am using Boost to cache front-end and my sites run smoothly at the top of the hour as long as the cache is serving up the files. But if I try to hit the database (by logging in) or I am already logged in, the whole server seems to freeze up for 2-3 minutes.

I've been monitoring TOP and at those times, I do see some CPU spikes over 40% but it's all httpd and usually happens when I am trying to load a page. TOP really didn't help me much so I decided to enable slow query logging and I think I got a treasure trove of good information about what is causing the problem. However, I can't quite make any sense of what I'm seeing or what I should do about it. You can see the results from 8:00AM Eastern today below when my site started freezing up.

This has been going on for MONTHS now

I am using file caching with cacherouter, have APC installed and working properly on the server and I'm using block caching and views caching. I am running a Wordpress site and 4 Drupal sites on a VPS with 756mb ram.

I have played around quite a bit in the last few weeks with tweaking mysql and I have dbtuner installed to help me with that.

Please take a look at my slow_query log. I have changed the usernames for security purposes.

The first query you see here is the first query for 8:00 Eastern. The last query in my log was from around 7:45AM. 8:00 on the dot is when my site began freezing up. You will see some queries of over 20 a little farther down.

It seems to me that delete from cache seems to popup quite a bit. Could this be part of the problem?

DELETE FROM variable WHERE name = 'elysia_cron_last_run';
# Time: 110203  8:00:07
# User@Host: teachabr_publicp[teachabr_publicp] @ localhost []
# Query_time: 3  Lock_time: 0  Rows_sent: 9  Rows_examined: 39
use teachabr_teachabroadchina;
SET timestamp=1296738007;
SELECT *  , IF (DATE_ADD(link_updated, INTERVAL 120 MINUTE) >= NOW(), 1,0) as r$
# Time: 110203  8:00:13
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use chatabou_main3;

# Query_time: 6  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use chatabou_main3;
SELECT src FROM url_alias WHERE dst = 'content/our-christmas-party' AND languag$
# Time: 110203  8:00:16
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 3  Lock_time: 0  Rows_sent: 1  Rows_examined: 6
SELECT pid FROM gallerix_pictures WHERE nid = 5332 AND sort = 1;
# Time: 110203  8:00:27
# User@Host: prayerfe_mrwhizk[prayerfe_mrwhizk] @ localhost []
# Query_time: 11  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
use panze_pfintl;
DELETE FROM cache_content WHERE expire != 0 AND expire < 1296738016;
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 25  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
use chatabou_main3;
DELETE FROM variable WHERE name = 'elysia_cron_last_run';
# Time: 110203  8:00:35
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 17  Lock_time: 0  Rows_sent: 0  Rows_examined: 0

# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 17  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 28  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO watchdog
    (uid, type, message, variables, severity, link, location, referer, hostname$
    VALUES
    (0, 'access denied', 'appbar/refresh/count', 'N;', 4, '', 'http://www.chata$
# Time: 110203  8:00:40
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 13  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('elysia_cron_last_run', 'i:129673800$
# Time: 110203  8:00:48
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 8  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'cron_last';
# Time: 110203  8:00:51
# User@Host: eximstats[eximstats] @ localhost []

# Time: 110203  8:00:51
# User@Host: eximstats[eximstats] @ localhost []
# Query_time: 3  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
use eximstats;
INSERT INTO sends (mailtime,msgid,email,processed,user,size,ip,auth) VALUES(FRO$
# Time: 110203  8:00:58
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 85
use chatabou_main3;
SELECT n.title, n.type, n.status, ou.* FROM og_uid ou INNER JOIN node n ON ou.n$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 85
SELECT n.title, n.type, n.status, ou.* FROM og_uid ou INNER JOIN node n ON ou.n$
# Time: 110203  8:01:00
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 18  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 0, cache = 0, hostname = '113.76.31.222', session = '$
# User@Host: teachabr_mrwhizk[teachabr_mrwhizk] @ localhost []
# Query_time: 2  Lock_time: 0  Rows_sent: 1  Rows_examined: 1

# User@Host: teachabr_mrwhizk[teachabr_mrwhizk] @ localhost []
# Query_time: 2  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
use teachabr_teachjobs;
SELECT p.perm FROM role r INNER JOIN permission p ON p.rid = r.rid WHERE r.rid $
# Time: 110203  8:01:17
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 26  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
use chatabou_main3;
INSERT INTO variable (name, value) VALUES ('cron_last', 'i:1296738040;');
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 19  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE history SET timestamp = 1296738058 WHERE uid = 517 AND nid = 5443;
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 25  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO history (uid, nid, timestamp) VALUES (517, 5332, 1296738052);
# Time: 110203  8:01:26
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 26  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $

# Query_time: 26  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 23  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO watchdog
    (uid, type, message, variables, severity, link, location, referer, hostname$
    VALUES
    (0, 'access denied', 'appbar/refresh/count', 'N;', 4, '', 'http://www.chata$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 18  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 18  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 26  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE history SET timestamp = 1296738060 WHERE uid = 517 AND nid = 5443;
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 8  Lock_time: 0  Rows_sent: 0  Rows_examined: 0

# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 8  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 2  Rows_examined: 369
SELECT DISTINCT node.nid AS nid,
   node.title AS node_title,
   (SELECT COUNT(*) FROM node n INNER JOIN og_ancestry oga ON n.nid = oga.nid L$
 FROM node node
 LEFT JOIN og_uid og_uid ON node.nid = og_uid.nid
 LEFT JOIN og og ON node.nid = og.nid
  INNER JOIN node_access na ON na.nid = node.nid WHERE (na.grant_view >= 1 AND $
   )ORDER BY node_title ASC
 LIMIT 0, 50;
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 2  Rows_sent: 2  Rows_examined: 369
SELECT DISTINCT node.nid AS nid,
   node.title AS node_title,
   (SELECT COUNT(*) FROM node n INNER JOIN og_ancestry oga ON n.nid = oga.nid L

 node.title AS node_title,
   (SELECT COUNT(*) FROM node n INNER JOIN og_ancestry oga ON n.nid = oga.nid L$
 FROM node node
 LEFT JOIN og_uid og_uid ON node.nid = og_uid.nid
 LEFT JOIN og og ON node.nid = og.nid
  INNER JOIN node_access na ON na.nid = node.nid WHERE (na.grant_view >= 1 AND $
   )ORDER BY node_title ASC
 LIMIT 0, 50;
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
SELECT n.nid, n.type, n.language, n.uid, n.status, n.created, n.changed, n.comm$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
SELECT n.nid, n.type, n.language, n.uid, n.status, n.created, n.changed, n.comm$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 410
SELECT DISTINCT node.nid AS nid,
   node.title AS node_title
 FROM node node

 node.title AS node_title
 FROM node node
 LEFT JOIN og_ancestry og_ancestry ON node.nid = og_ancestry.nid
 INNER JOIN node node_og_ancestry ON og_ancestry.group_nid = node_og_ancestry.n$
 LEFT JOIN history history_user ON node.nid = history_user.nid AND history_user$
 INNER JOIN node_comment_statistics node_comment_statistics ON node.nid = node_$
 LEFT JOIN og_uid node_og_ancestry__og_uid ON node_og_ancestry.nid = node_og_an$
  INNER JOIN node_access na ON na.nid = node.nid WHERE (na.grant_view >= 1 AND $
   ) LIMIT 0, 1;
# Time: 110203  8:01:29
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 11  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO history (uid, nid, timestamp) VALUES (517, 5681, 1296738078);
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 11  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 12  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('elysia_cron_semaphore', 'i:12967380$

# Query_time: 12  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('elysia_cron_semaphore', 'i:12967380$
# Time: 110203  8:01:32
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 5  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 5  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 5  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 5  Lock_time: 1  Rows_sent: 0  Rows_examined: 0
UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# Time: 110203  8:01:36

UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# Time: 110203  8:01:36
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_last_run';
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 5  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE node_counter SET daycount = daycount + 1, totalcount = totalcount + 1, t$
# Time: 110203  8:01:38
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# Time: 110203  8:01:41

# Time: 110203  8:02:14
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 12  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'ecc_default_r';
# Time: 110203  8:02:19
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 5  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('ecc_default_r', 'i:1296738119;');
# Time: 110203  8:02:25
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# Time: 110203  8:02:29
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 10  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_semaphore';
# Time: 110203  8:02:34
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 9  Lock_time: 0  Rows_sent: 0  Rows_examined: 0

# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 9  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE users SET access = 1296738145 WHERE uid = 517;
# Time: 110203  8:02:43
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 14  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('elysia_cron_semaphore', 'i:12967381$
# Time: 110203  8:02:49
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'ecc_default_lr';
# Time: 110203  8:02:55
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('ecc_default_lr', 'i:1296738139;');
# Time: 110203  8:03:05
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 10  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_last_context';

# Query_time: 10  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_last_context';
# Time: 110203  8:03:08
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 10  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 517, cache = 0, hostname = '119.132.80.116', session $
# Time: 110203  8:03:09
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 4  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('elysia_cron_last_context', 's:7:\"d$
# Time: 110203  8:03:13
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 4  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_semaphore';
# Time: 110203  8:03:18
# User@Host: chata_mwhz[chata_mwhz] @ localhost []
# Query_time: 9  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO watchdog
    (uid, type, message, variables, severity, link, location, referer, hostname$

Comments

Have you tried contacting

Posted by Garrett Albright on February 5, 2011 at 5:22am

Have you tried contacting your hosting company and asking them if there are corresponding activity spikes on their servers at those times?

The Boise Drupal Guy!

Thanks for the reply. I have

Posted by mrwhizkid on February 5, 2011 at 5:54am

Thanks for the reply.

I have been in contact with my hosting company about this and we have both been monitoring apache. Using TOP, I have seen a few spikes (15-40%) for httpd process. Nothing for mysqld which is where I assumed the problem was originating from.

We did a trace on one of the spikes and it seemed to be pointing to sites/default/files in one of my biggest sites which also happens to be where my file caching folder is located. And, looking through my slow_query logs, it seems like some of the trouble seems to start with a delete_from_cache query at the top of the hour so I'm wondering if this has to do with clearing the cache?

Also, as I alluded to previously, I am running 4 other Drupal sites on this VPS along with 2 Wordpress sites. The VPS has 756 ram. Is this enough do you think for running these kinds of sites?

Chances are you have cron

Posted by catch on February 5, 2011 at 3:05pm

Chances are you have cron running on the hour, and cron does a cache_clear_all(). The file caching module you're using (which one?) may not be handling this correctly. If you're running a VPS, you should look at installing memcache and using the memcache backend, which has some safeguards compared to the core cache.inc (especially 1.8 release).

I'm running cacherouter with

Posted by mrwhizkid on February 5, 2011 at 3:41pm

I'm running cacherouter with file caching. Actually, I disabled the website/account that was giving me the delete from cache problem but I still seem to have this problem and now I am not seeing anything else about that in the logs.

If it did have to do with file caching, would my slow query log show me that since it has nothing to do with the database?

I have been watching my slow query logs for a few days now and I have begun to see an interesting pattern.

Please look at the following. This is from earlier today when my site froze up at about 9:00.

# Time: 110205  9:00:17
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 16  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_last_run';
# Time: 110205  9:00:32
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 30  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 24, cache = 0, hostname = '113.76.32.104', session = 'clickpath|a:6:{s:9:\"node/5012\";s:7:\"My Page\";s:9:\"node/5030\";s:16:\"Pr$
# Time: 110205  9:00:40
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 3  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
SELECT n.nid, n.type, n.language, n.uid, n.status, n.created, n.changed, n.comment, n.promote, n.moderate, n.sticky, n.tnid, n.translate, r.vid, r.uid AS re$
# Time: 110205  9:00:48
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 28  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
INSERT INTO variable (name, value) VALUES ('elysia_cron_last_run', 'i:1296914401;');
# Time: 110205  9:00:53
# User@Host: teachabr_prevent[teachabr_prevent] @ localhost []
# Query_time: 2  Lock_time: 0  Rows_sent: 1  Rows_examined: 25
use teachabr_taca;
SELECT DISTINCT t.* FROM term_node r INNER JOIN term_data t ON r.tid = t.tid INNER JOIN vocabulary v ON t.vid = v.vid  LEFT JOIN forum_access fa ON t.tid = $
# Time: 110205  9:00:56
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 24  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
use chatabou_main3;
UPDATE sessions SET uid = 24, cache = 0, hostname = '113.76.32.104', session = 'clickpath|a:6:{s:9:\"node/5012\";s:7:\"My Page\";s:9:\"node/5030\";s:16:\"Pr$
# Time: 110205  9:01:00
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 12  Lock_time: 0  Rows_sent: 0  Rows_examined: 0

I seem to always see the two same things:

# Time: 110205  9:00:17
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 16  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
DELETE FROM variable WHERE name = 'elysia_cron_last_run';

and

# Time: 110205  9:00:32
# User@Host: chatabou_mrwhizk[chatabou_mrwhizk] @ localhost []
# Query_time: 30  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
UPDATE sessions SET uid = 24, cache = 0, hostname = '113.76.32.104', session = 'clickpath|a:6:{s:9:\"node/5012\";s:7:\"My Page\";s:9:\"node/5030\";s:16:\"Pr$

I'm pretty sure that elysia_cron is not the culprit here. I only installed that module a few weeks ago and I've had this problem since last year. But for some reason, it's having a hard time inserting into the variable table.

I have 2,354 records in variable table and I've tried to clean that up by deleting records left over from old modules.

It also looks like the sessions table is struggling. What I don't understand though, is why this only happens during a few hours of the day.

InnoDB

Posted by mikeytown2 on February 5, 2011 at 11:10pm

Change the variable & sessions tables to InnoDB and try again. Also see if the clickpath module has any performance issues.

Hi-- Thanks for the advice.

Posted by mrwhizkid on February 6, 2011 at 1:41am

Hi-- Thanks for the advice. Actually, all of the tables are InnoDB with the exception of menurouter table. I switched from MyISAM some time ago. Clickpath is a relative recent addition to my site. This issue predates that.

I would like to ask you a question about cacherouter (a very useful module...so thanks). I am using it with file based caching which I have suspected could have something to do with this problem since my site slows down at the top of the hour.

If the problem has to do with file caching and cacherouter, would this be reflected in my slow query logs? I don't see cache_clear_all() at all in my slow query log. Is this what is triggering filecache to clear the files every hour?

Today, I have switched to db caching with cacherouter to see if this makes any difference.

If this turns out to the be the problem (I have heard filecaching can have trouble with serialization/unserialization), then I will probably install memcache and use that with cacherouter. I am only using a single server but I have heard that memcache is preferable to filecaching even on one server.

Thanks for your help and that great module.

edit *** @mikeytown -- oops...I got confused. I guess Boost is your module...not cacherouter. I also use Boost which is great for anonymous caching.

memcache

Posted by mikeytown2 on February 6, 2011 at 2:22am

I use memcache as well. The 1.8 version of it has a lot of advantages over older versions of it. Your server could be over loaded with IO; I've heard of people having issues with file IO on their VPS. See if it's boost.

Thanks. That very well could

Posted by mrwhizkid on February 6, 2011 at 2:59am

Thanks. That very well could be the problem. I think I will try memcache..

Can you tell me...are you using memcache with cacherouter?

And are you using it just on one server?

Our Setup

Posted by mikeytown2 on February 6, 2011 at 5:15am

Using just memcache for the drupal caches; varnish for page cache; boost as a backup in case of a cold start (happened about 4 times last year); use boost's DB table to control an external crawler. We have 12 servers for drupal; 3 DB, 9 Web (2 + 7). Each box has 24GB of ram. It's a powerful setup and it's allowed me to identify issues like this memory leak in views.

I've been improving logged in performance recently and my newly created module has done a lot for us. http://drupal.org/project/imageinfo_cache

Interesting module. We have

Posted by mrwhizkid on February 7, 2011 at 4:16am

Interesting module. We have quite a bit of imagecache usage so we'll have to check that out.

I've installed memcache on my VPS...so far so good but I notice that I'm only hitting it about 80% of the time which probably has to do with the fact that I'm using memcache as the default engine in cacherouter. I'm guessing it would be more efficient to just cache for the tables that I know will be hit?

Can you give me an idea of which tables you cache using memcache and which ones you might cache using APC or file?

Thanks

This isn't quite what I

Posted by Garrett Albright on February 6, 2011 at 9:26am

This isn't quite what I asked. What I meant was, is it possible that it's the entire system which is being bogged down and not just your individual VPS?

Though presumably, if you've been in contact with your hosting company, they've likely already checked this.

The Boise Drupal Guy!

+1 for this. This is the cons

Posted by sugiggs on February 9, 2011 at 6:25am

+1 for this.

This is the cons of using VPS. Your site/server can slow down because of other VPS-es on the same host are having high load.
Amazon/Rackspace are not spared also.

It sounds to me like you are

Posted by soyarma on February 6, 2011 at 1:08pm

It sounds to me like you are suffering from I/O wait. Everything you are seeing in your slow query log is just a symptom, not the cause. A MySQL table with less than 5000 rows should be able to be queried in less than a second even without indexes. It's slow because something is slowing down your MySQL server.

I'm guessing the MySQL server isn't on the same machine as your websites, or you'd see it spike high in your top while it is waiting. If it is on the same server, then things are getting more curious--but I'm betting it's not. I'd suggest using phpmyadmin and going to the processlist tab, or if you don't have that, run SHOW PROCESSLIST; from within a commandline connection, or make a page that does it. See if you have a hung process and other things waiting.

There are two possibilities:

You will see a query in some sort of WAIT statement that everything else is waiting on (though this is less likely with Innodb).
You will see nothing in a wait state that is blocking, but all sorts of queries that will run faster at other times run really slow at this time.

Either way the culprit is heavy disk usage on your MySQL server, on the subsystem below it. You can mitigate this by changing your crons to run at half past the hour, so at least you aren't doing so much at the same time the server seems to be having issues, or you can move to a new host.

I'd recommend trying out Rackspace's cloud hosting servers. I have 256MB RAM machines that run really strong--faster than 1GB machines with other hosts and they only cost $10-$20/month.

Thanks for the comments and

Posted by mrwhizkid on February 6, 2011 at 1:56pm

Thanks for the comments and advice. I have contacted my host and they have assured me that mysql is running on the same machine. However, they are looking into the I/O issue and will get back with me shortly about that.

I'm afraid we are going to get in trouble here for discussing a specific web host in the wrong place (don't want to be accused of advertising) so I just want to ask you a general question about using Drupal on a cloud server.

From what I can tell, it seems like installing mysql on a cloud isn't so straight forward. How did you do that? Are you using mysql?

I'm using MySQL and I had no

Posted by soyarma on February 6, 2011 at 4:01pm

I'm using MySQL and I had no problems whatsoever running mysql on the cloud servers. I just did the default CentOS install, and then used yum (yum install mysqld) to install MySQL and I was golden.

I've also used Amazon and MySQL runs fine there too.

I personally prefer Rackspace over Amazon because at RS all of your data is persistent, so the machines hosting you can go down and your data is still there. At Amazon if you relaunch a server your data is gone.

AWS EBS

Posted by stevenator on February 6, 2011 at 10:11pm

While I too prefer Rackspace like @soyarma, but AWS offers EBS now, which resolves the data loss problem on node instances. It still isn't ideal but it is their workaround.

Very true, I should have

Posted by soyarma on February 6, 2011 at 11:22pm

Very true, I should have mentioned that.

Did you try mtop to see if

Posted by elkin_taharon on February 12, 2011 at 2:47pm

Did you try mtop to see if there is some trouble with any queries running at that hour ?

New Relic

Posted by rjbrown99 on February 15, 2011 at 6:17am

Sign up for a demo of www.newrelic.com, hook it into your PHP, restart your webserver, and watch the magic. No disclaimer needed, I have nothing to do with them other than being excited about their monitoring tool. I've been working with it for the past week and have already found and fixed a ton of issues with my site.