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;
CommentFileSizeAuthor
#3 mysql-slow.log149.75 KBakwala

Comments

akwala’s picture

The 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):

# User@Host: du[du] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 0  Rows_examined: 176
SELECT fa.* FROM file_attachments fa WHERE fa.nid = 279 AND fa.vid = 686 AND fa.cid = 0 ORDER BY fa.weight;
# User@Host: du[du] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 177
SELECT fa.* FROM file_attachments fa WHERE fa.nid = 280 AND fa.vid = 693 AND fa.cid = 0 ORDER BY fa.weight;
# User@Host: du[du] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 0  Rows_examined: 176
SELECT fa.* FROM file_attachments fa WHERE fa.nid = 281 AND fa.vid = 689 AND fa.cid = 0 ORDER BY fa.weight;
# User@Host: du[du] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 0  Rows_examined: 176
SELECT fa.* FROM file_attachments fa WHERE fa.nid = 282 AND fa.vid = 694 AND fa.cid = 0 ORDER BY fa.weight;
miglius’s picture

How 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.

akwala’s picture

StatusFileSize
new149.75 KB

Yes, they are from a single node (page) load. I'm attaching the log corresponding to this sequence of events, which I just repeated:

  1. Rotated the MySQL logs.
  2. Restarted MySQL server.
  3. Logged in to the site as user 'aslam' (role: authenticated user).
  4. Clicked on the link to the page (node) in question.
  5. Waited for the page to finish loading.
  6. Saved a copy of the mysql-slow.log snapshot.
miglius’s picture

How many (if any) attachments are attached to the node you were testing?

akwala’s picture

This particular node does not have any attachments. It does have one embedded image (Only local images are allowed. 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.

miglius’s picture

Status: Active » Postponed (maintainer needs more info)

This 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?

akwala’s picture

There 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:

  1. a node with 4 attachments, that also has an embedded children view (from the Node Hierarchy module); it currently shows 6 child links;
  2. a node with no attachments, but with 2 links to other nodes.

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.

akwala’s picture

Category: support » bug

FYI...

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.

johanneshahn’s picture

Status: Postponed (maintainer needs more info) » Closed (works as designed)

Response time and SQL Query / Performance improvement

@see roadmap