I'm guessing that this has to do with the File Framework module.
Users with the same Role experience vastly different response times for a given node. For some it's a couple of seconds, for others it's a up to a couple of minutes.
The client and connectivity can be eliminated as factors, since I tested with multiple 'authenticated user' accounts on the same client and Internet connection.
Circumstances/observations:
- I've copied the site to a different server and am accessing it using its IP, as opposed to its production URL.
- The users who get quick responses haven't used or posted much on the site.
- The nodes that exhibit this tend to have file attachments or embedded images -- I'm using the File Framework module and turning off Preview didn't help.
I noticed this after moving the site from a server with inadequate resources (where all nodes were dog slow) to a one that has plenty. During the slow response, I see the Apache2 process taking up 40%+ of the CPU. Memory doesn't seem to be an issue, there's lots free.
PHP settings:
- PHP memory 128M
- APC enabled
mysql-slow.log shows _lots_ of queries, with different bitcache URLs like the following, for a single request...
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 1 Rows_examined: 1034
SELECT g.uri g, s.uri s, p.uri p, o.uri o, t.uri type, d.lang, d.data FROM rdf_data_file d
LEFT JOIN rdf_resources g ON d.gid = g.rid
INNER JOIN rdf_resources s ON d.sid = s.rid
INNER JOIN rdf_resources p ON d.pid = p.rid
LEFT JOIN rdf_resources o ON d.oid = o.rid
LEFT JOIN rdf_resources t ON d.tid = t.rid
WHERE (s.uri = 'bitcache://fbc9586258dcc133ffc633f73625c5165785db2d') AND (p.uri = 'http://purl.org/dc/elements/1.1/extent')
ORDER BY d.did ASC;
...followed by...
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 4 Rows_examined: 15
SELECT r.* FROM role r INNER JOIN permission p ON r.rid = p.rid WHERE p.perm LIKE '%access fckeditor%' ORDER BY r.name;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 1 Rows_examined: 4
SELECT s.name FROM fckeditor_settings s INNER JOIN fckeditor_role r ON r.name = s.name WHERE r.rid='2';
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 3 Rows_examined: 3
SELECT * FROM fckeditor_settings;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 38 Rows_examined: 1144
SELECT DISTINCT(n.nid) FROM node n INNER JOIN node_access na ON na.nid = n.nid WHERE (na.grant_view >= 1 AND ((na.gid = 0 AND na.realm = 'all') OR (na.gid = 2 AND na.realm = 'node_privacy_byrole_role') OR (na.gid = 3 AND na.realm = 'node_privacy_byrole_user'))) AND ( n.status = 1 AND n.nid IN (199, 242, 243, 263, 244, 200, 10, 196, 195, 194, 17, 241, 258, 267, 262, 257, 278, 279, 282, 203, 204, 119, 110, 62, 205, 206, 54, 207, 183, 56, 161, 211, 208, 65, 158, 245, 260, 261));
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 7 Rows_examined: 11
SELECT v.*, n.type FROM vocabulary v LEFT JOIN vocabulary_node_types n ON v.vid = n.vid ORDER BY v.weight, v.name;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 229 Rows_examined: 932
SELECT t.tid, t.*, parent FROM term_data t INNER JOIN term_hierarchy h ON t.tid = h.tid WHERE t.vid = 2 ORDER BY weight, name;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 8 Rows_examined: 16
SELECT * FROM menu_custom ORDER BY title;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 10 Rows_examined: 1411
SELECT DISTINCT(nc.nid) FROM node_comment_statistics nc INNER JOIN node_access na ON na.nid = nc.nid WHERE (na.grant_view >= 1 AND ((na.gid = 0 AND na.realm = 'all') OR (na.gid = 2 AND na.realm = 'node_privacy_byrole_role') OR (na.gid = 3 AND na.realm = 'node_privacy_byrole_user'))) AND ( nc.comment_count > 0 )ORDER BY nc.last_comment_timestamp DESC LIMIT 0, 10;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 7 Rows_examined: 14
SELECT name, title, type, visibility, weight FROM profile_fields WHERE visibility IN (2, 3) ORDER BY weight;
# User@Host: du[du] @ localhost []
# Query_time: 0 Lock_time: 0 Rows_sent: 11 Rows_examined: 666
SELECT * FROM menu_router WHERE tab_root = 'node/%' ORDER BY weight, title;
| Comment | File | Size | Author |
|---|---|---|---|
| #3 | mysql-slow.log | 149.75 KB | akwala |
Comments
Comment #1
akwala commentedThe log entries in my previous post are preceded by _lots_ of entries like the following, for the same node request (if needed, I can email a snapshot of the log file for the node request in question):
Comment #2
miglius commentedHow many is _lots_?
Can you paste a slq log for a one particular node (page) load? Now it is unclear whether if those entries come from a one node load or from a several sequential page loads.
Comment #3
akwala commentedYes, they are from a single node (page) load. I'm attaching the log corresponding to this sequence of events, which I just repeated:
Comment #4
miglius commentedHow many (if any) attachments are attached to the node you were testing?
Comment #5
akwala commentedThis particular node does not have any attachments. It does have one embedded image (
tag), which is located in a user's directory -- URL: /system/files/u3/check.jpg
Incidentally, I've set the download to be Private, even though I'm using the default location -- see http://drupal.org/node/347589. I mention this in case it might be a factor.
Comment #6
miglius commentedThis sql is executed in the _file_attach_load() function, which is called from the hook_nodeapi() for the node operations 'load' and 'view'. I suspect that all nodes with the nids referenced in the sqls are loaded on your site with a node_load() function which triggers the hook_nodeapi() and sql checks if the node being loaded has attachments, but I don't know which code is doing that.
Do you have some block which lists a lot of nodes? Or uses views?
Comment #7
akwala commentedThere are blocks on the right nav bar that list multiple nodes -- Active forum topics, Recent comments, Recent blog posts. These appear with all nodes, so my guess is that they are not the cause.
The node in question has 2 links, each to another node:
Not sure if this answers your question; however, both of the these nodes exhibit the same behavior as the one in question.
Re views: Node Hierarchy provides the option to show an embedded children view, and I pick the one called "nodehierarchy_children_list". The node in question, however, has no children.
Comment #8
akwala commentedFYI...
I disabled all the File Framework modules, including Bitcache. This eliminated the problem. I'm now using the WebFM module. Fortunately, I didn't have too many attachments to recreate manually. Would be good to have a way to migrate attachments/files, back and forth, should I decide to use the File Framework in the future -- even if it's a series of steps to manually alter the db table/s.
Comment #9
johanneshahn commentedResponse time and SQL Query / Performance improvement
@see roadmap