Too many queries... advice on tracking down

aharown07 - July 2, 2009 - 22:37

Well, my hosting co. informs me the site I built (first ever) is hitting the CPU too hard... around 60 mysql queries per second a good bit of the time I guess.

We moved to a dedicated server so now that's no problem, but we really can't afford to stay there.
Yes, we have a truckload of modules... and love every one of 'em.

So my questions...
1) Is there a way to identify what's generating so many queries without taking the site offline? Is it safe to run Devel and collect data when things are live?

2) Is there a list somewhere of what modules are the hardest on resources? It would be cool to be able to peruse a "top 10 cpu busting modules" to see how many I have on it. I suspect I'm using 7 or 8 of those!

3) I'm wondering how much the total number of modules itself impacts the query load... regardless of how intensive the modules themselves are.

...

Keyz - July 2, 2009 - 23:30

Yes you can run Devel on a live site (unless permissions are explicitly granted for other roles to view them, the stats it outputs are limited to the admin seeing them only). However personally I would only leave it on long enough to collect sample data and then disable it (I don't know about the current version, though I've had instances in the past where it had some issues with the jQuery connected with filefield uploads... could be fixed now but I don't know).

A good resource for performance info with Drupal is http://2bits.com/contents/articles
There's also a number of performance related videos at http://dc2009.drupalcon.org

Drupal does have a ton of queries (especially some aspects can add up such as pagers and aliases can produce a rather prodigious quantity of queries, and also updating the caches can add many queries... albeit very tiny ones). I believe this is improved quite a bit in Drupal 7 (once it's released) though with some care it can be worked with in D6.

I don't think the number of queries though is likely upping your CPU use "that" much (I believe the quantity of queries affects disk access more than CPU time, though I'm not an expert in that area). Perhaps "heavy" queries if you have some are hitting the CPU hard, but probably not just the quantity of queries over all. You can see very quickly in Devel how much time is spent on queries versus PHP processing. If you don't have any real bad queries than PHP is more likely where your high CPU usage may be coming from (make sure you're using an Op code cache such as APC, and also check for performance draining PHP mistakes). You can probably gain a lot of performance switching to Memcache for caching (see Memcache or Cache Router module). Also consider Boost module for your anonymous visitors to steal back a huge chunk of performance for use towards your logged in users. Most likely you can get everything you need on a good VPS (though I'd stay away from shared hosting).

I don't know of a list of worst performing modules... one I know off hand that can perform badly is Custom Pagers. The new Previous/Next API from 2bits is a better replacement for that if needed. Various other module performance issues are mentioned on the 2bits site.

Hope this helps.

Caching

yelvington - July 2, 2009 - 23:36

Be sure you have enabled caching.

If most of your traffic is anonymous, install Boost.

Remembered a few

Keyz - July 2, 2009 - 23:43

Forgot... one other module that's slow on a large site is Tracker. Drupal.org actually has switched to a contrib module to replace it, Tracker 2. Node access modules can have a slow-down effect on things, and also the forum module has a number of slow spots on sites with large quantities of nodes (it's possible to cache the forum issues with a tiny tweak, let me know if that's an issue you need help with). I haven't used it but I hear Tagadelic is hard on CPU (tag clouds I think), and also Faceted Search is hard on your system (for a large site it's better to switch to Solr). From 2bits I just learned that Admin Menu adds a lot of overhead (of course only to users who have access to it)... I believe version 3 though is much better. Also XML sitemap and core Statistics module are slow.

The XML sitemap 6.x-1.x

Dave Reid - July 3, 2009 - 18:47

The XML sitemap 6.x-1.x version has a lot of performance and scalability problems. The 6.x-2.x rewrite version of XML sitemap addresses these problems. You might want to give it a try.

Thanks

aharown07 - July 3, 2009 - 15:44

Lots of good info here. Appreciate it. Haven't actually seen any slowness to speak of.
I think the hosting co I'm with may be complaining about mysql queries just because they want to keep me on an expensive server.
Hard to be sure w/o more research though.

We just don't really have high traffic most of the time. About 2/3 of visitors are anon. so Boost looks attractive. And maybe we don't need Tracker... we just moved to Drupal so I think most users probably don't even know what it is yet.

I think I can get away with some Devel use briefly, but I've found that I have to turn off Ad module and Reftagger module when I do... they don't seem to get along.

Some Devel results...

aharown07 - July 3, 2009 - 20:02

Got some Devel results on my front page. But I don't really know what they mean.

Devel reports...
3727 queries in 1133.69 milliseconds. Page execution: 2808.96
Memory used at: devel_init()=1.71 MB, devel_shutdown()=33.71 MB.

I have some queries that apparently run 10 times.

Sample:
0.26  10   user_load SELECT * FROM users u WHERE uid = 36

0.29  10   user_load SELECT r.rid, r.name FROM role r INNER JOIN users_roles ur ON ur.rid = r.rid WHERE ur.uid = 36

0.43  10   profile_load_profile SELECT f.name, f.type, v.value FROM profile_fields f INNER JOIN profile_values v ON f.fid = v.fid WHERE uid = 36

0.21  10   signature_forum_user SELECT signature FROM users_signature WHERE uid = 36

Thought this might be the Who's Online block so I disabled on front page and loaded again. No change... so I really don't know why so many user_load's are occurring.

So any insight on what this data means?

(Edit: might help to mention what's on this front page... there's a main article section, nothing fancy. There's a sidebar block that is fed by a View, filtered by content type. There are two Ad module adblocks displaying one ad each.
One Quicktab block w/two tabs.... each showing diff. content types. A couple menu blocks. A taxonomy block (of the Advanced Taxonomy module type). An archive block fed by a View.)

Hmm

Keyz - July 3, 2009 - 21:04

For the user_loads that happen 10x, do you have anything on the page pulling user data with 10 results? Something from a View or other module? In any case that's not your big resource drain (total only about 12ms). I'd not worry about that. You definitely have far more queries running than normal. Browsing a pretty full featured client site I'm working on (80 contrib modules, not counting those module's sub-modules) I see query counts that rarely if ever exceed 800 at most on a page like the Front (and usually only a few hundred on most pages), much less 3-4000 (only time I see that is on loading the Modules page where it basically rebuilds everything so there's tons more queries there). The most prevalent query by far on my site is "module_rebuild_cache".... what queries do you see running a whole lot more than others? Do you see any queries in the log where the far left number is red, and if so how many ms and what module does it appear related to? Do you get much lower results if you refresh the page a second time, or are these numbers always this high? Do you have a lot of node_loads? Each one adds a chunk of related queries so could contribute to the query count being higher if you have quite a few of them on a given page.

Here's some examples from mine (this local server is also slower than the live one)...
Front page (standard node teasers, plus a few blocks):
Executed 794 queries in 317.21 milliseconds. Page execution time was 1308.68 ms.
Memory used at: devel_init()=0.49 MB, devel_shutdown()=10.97 MB.

Advanced Forum main page:
Executed 394 queries in 344.52 milliseconds. Page execution time was 1320.08 ms.
Memory used at: devel_init()=0.5 MB, devel_shutdown()=9.74 MB.

Some other observations on yours... you definitely have something a bit slow happening on the PHP side (more than 1.5 seconds spent in PHP, so probably losing around 1/2 second or more on PHP compared to normal). Your memory use at devel shutdown is also very high if your Op code cache is working correctly (it may not be). Does it always stay this high on every page load?

Make sure on the live site you disable all development related modules as well such as Views UI, ImageCache UI, etc which you don't need running all the time unless adjustments are needed. And of course remove any unused modules. On the site I'm working on I know there will likely be almost 1/4 less modules active on the live site.

Those four queries look like

Dave Reid - July 3, 2009 - 21:44

Those four queries look like 10 nodes being displayed on your front page. Nothing unusual.

Ah yeah

Keyz - July 3, 2009 - 22:00

Good observation Dave, thanks :)

I forgot to mention that you'll likely see a lot more queries logged in as UID 1 versus how many other roles will have. So ideally check on these numbers rather than those of the admin. To do this you might have to put the site off line for a few minutes, and give temporary permission to view Devel output to regular users. Also Devel itself has a bit of an effect on the page so at least a bit of the time is Devel.

For instance, here's the site's Front page logged in as a regular user:
Executed 543 queries in 234.14 milliseconds. Page execution time was 867.19 ms.
Memory used at: devel_init()=0.5 MB, devel_shutdown()=8.34 MB.

*Edit: And of course with standard caching on, the number would be even substantially lower for anonymous visitors... and almost non-existent if using Boost.

I bet no Op code cache

Keyz - July 3, 2009 - 22:34

Hmmm actually I would bet that you have no Op code cache at all. That's "server setup basics" so if your host forgot that (and blamed you no less) then you need to find a new host that knows what they are doing. Go to admin/reports/status and click the PHP version link to get a look at your PHP info... look for APC, eAccelerator, or XCache. *Edit: this may or may not have been the case on the shared account you were on, so it only "may" have been an issue before.

Here's an illustration... this is my Front page with APC disabled and Apache restarted (still as a regular user):
Executed 543 queries in 237.89 milliseconds. Page execution time was 1327.39 ms.
Memory used at: devel_init()=1.39 MB, devel_shutdown()=28.74 MB.

This doesn't explain your query issues, though it does explain why PHP is so slow for you, and why so much memory is being consumed needlessly. It also has a notable effect on CPU usage, which is "more likely" a big part of what your host is seeing spiking the CPU versus anything with your queries (unless you do have some real slow ones). As you can see, the Op code cache was so effective when enabled (in the earlier example) that it is edging towards nearly 2x faster PHP than without, and the difference in memory consumption is extreme.

Very helpful agian!

aharown07 - July 4, 2009 - 02:33

Thanks. You guessed right on the op code cache. ... and I'm planning on moving to a more Drupal-aware hoster fairly soon. There have been other problems that were their doing (though pretty minor... and I have to say they've always been very responsive, just not real aware of some things that are important. And when I say "Drupal" they start talking it down).

Anyway, still want to figure out why so many queries, but I think you're probably quite right about the php execution time.
I do have Admin Menu... and only I use it when I'm User 1. Could that do it?
I believe I can get some numbers closer to what most users generate by giving the Devel output to a role that is rarely used and signing on in that role.... avoid taking the site down that way.

I'm also using Simple Menu for folks that have various lend-a-hand roles... and User 1 sees that set of menus also. Don't know if that's a clue.

Slow queries
Did find a couple... and maybe this a big clue. Feed API stuff... these two are back to back.

8.91 1 execute
SELECT COUNT(*) FROM (SELECT DISTINCT(node.nid) AS nid FROM node node LEFT JOIN feedapi_node_item_feed feedapi_node_item_feed ON node.nid = feedapi_node_item_feed.feed_item_nid LEFT JOIN node node_feedapi_node_item_feed ON feedapi_node_item_feed.feed_nid = node_feedapi_node_item_feed.nid LEFT JOIN node_revisions node_revisions ON node.vid = node_revisions.vid WHERE (node.type in ('blogfeeditem')) AND ((node_feedapi_node_item_feed.title) LIKE ('%Liveblog%')) AND (node.status <> 0) ) count_alias

19.54 1 execute
SELECT DISTINCT(node.nid) AS nid, node.created AS node_created, node_revisions.body AS node_revisions_body, node_revisions.format AS node_revisions_format FROM node node LEFT JOIN feedapi_node_item_feed feedapi_node_item_feed ON node.nid = feedapi_node_item_feed.feed_item_nid LEFT JOIN node node_feedapi_node_item_feed ON feedapi_node_item_feed.feed_nid = node_feedapi_node_item_feed.nid LEFT JOIN node_revisions node_revisions ON node.vid = node_revisions.vid WHERE (node.type in ('blogfeeditem')) AND ((node_feedapi_node_item_feed.title) LIKE ('%Liveblog%')) AND (node.status <> 0) ORDER BY node_created DESC LIMIT 0, 10

Huge number of taxonomy related queries Didn't count the pages, but there must have been several dozen of nothing but taxonomy hierarchy stuff. So I think the Taxonomy Blocks module is either broken or isn't getting along with something. I can't believe it's supposed to require that many queries.
Going to turn it off and test w/Devel again.

Hmmm

aharown07 - July 4, 2009 - 02:48

Disabled Advanced Taxonomy Blocks (and something it depended on).
Loaded front page w/Devel on... now I don't see any queries at all. Not sure what's up with that.
Sure is faster though.

Page execution time was 1432.62 ms.
Memory usage:
Memory used at: devel_init()=1.71 MB, devel_shutdown()=28.89 MB.

Edit: oops. Didn't have collect query data turned on.
What a difference: Executed 805 queries in 339.42 milliseconds.

 
 

Drupal is a registered trademark of Dries Buytaert.