Tracing a Slow MySQL Query

We have a few slow queries in forums. I am trying to track them down and see if I can fix them somehow. Here is an example from our mysql-slow.log:

# Time: 090929  9:04:54
# User@Host: unixdb[unixdb] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 10  Rows_examined: 75157
SELECT thread.threadid, thread.title, thread.lastpost, thread.forumid, thread.replycount, thread.lastposter, thread.dateline, thread.views, thread.visible, thread.open, user.username, user.userid, user.usergroupid, user.displaygroupid
                                        FROM thread AS thread
                                        LEFT JOIN user AS user ON (user.username = thread.lastposter)
                                        WHERE NOT ISNULL(thread.threadid) AND thread.visible = '1' AND thread.open!='10' AND thread.forumid NOT IN(39,128,99,59,87,126,92,95,65,73,114,78,41,133,68,123,74,115,75,66,58,76,94,64,72,80,111,63,103,79,105,62,31,58,59,62,64,65,66,67,68,69,72,73,74,75,76,78,80,90,91,92,94,95,97,98,99,102,103,105,106, 107, 108,110,111,112,113,115) 
                                        ORDER BY lastpost DESC
                                        LIMIT 0, 10;
# User@Host: unixdb[unixdb] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 10  Rows_examined: 75157
SELECT thread.threadid, thread.title, thread.lastpost, thread.forumid, thread.replycount, thread.lastposter, thread.dateline, thread.views, thread.visible, thread.open, user.username, user.userid, user.usergroupid, user.displaygroupid
                                        FROM thread AS thread
                                        LEFT JOIN user AS user ON (user.username = thread.lastposter)
                                        WHERE NOT ISNULL(thread.threadid) AND thread.visible = '1' AND thread.open!='10' AND thread.forumid NOT IN(39,128,99,59,87,126,92,95,65,73,114,78,41,133,68,123,74,115,75,66,58,76,94,64,72,80,111,63,103,79,105,62,31,58,59,62,64,65,66,67,68,69,72,73,74,75,76,78,80,90,91,92,94,95,97,98,99,102,103,105,106, 107, 108,110,111,112,113,115) 
                                        ORDER BY lastpost DESC
                                        LIMIT 0, 10;

I have searched the templates in the database and the php code but I have yet to find what part of the PHP code base is executing this query.

Any ideas how to track this MySQL query down?

---------- Post updated at 10:13 ---------- Previous update was at 10:10 ----------

Here is another one:

# Time: 090929  8:44:25
# User@Host: unixdb[unixdb] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 1  Rows_examined: 26765
SELECT t.forumid, t.threadid, t.title, t.replycount, t.lastposter, t.lastpost
FROM thread AS t
LEFT JOIN deletionlog AS deletionlog ON(deletionlog.primaryid = t.threadid AND type = 'thread')
WHERE forumid = 30 AND lastpost < 1217920495 AND visible = 1 AND open <> 10
AND deletionlog.primaryid IS NULL
ORDER BY lastpost DESC
LIMIT 1;
# User@Host: unixdb[unixdb] @ localhost []
# Query_time: 7  Lock_time: 0  Rows_sent: 1  Rows_examined: 26765
SELECT t.forumid, t.threadid, t.title, t.replycount, t.lastposter, t.lastpost
FROM thread AS t
LEFT JOIN deletionlog AS deletionlog ON(deletionlog.primaryid = t.threadid AND type = 'thread')
WHERE forumid = 30 AND lastpost < 1253204446 AND visible = 1 AND open <> 10
AND deletionlog.primaryid IS NULL
ORDER BY lastpost DESC
LIMIT 1;
# Time: 090929  8:44:27
# User@Host: unixdb[unixdb] @ localhost []
# Query_time: 6  Lock_time: 0  Rows_sent: 1  Rows_examined: 26765
SELECT t.forumid, t.threadid, t.title, t.replycount, t.lastposter, t.lastpost
FROM thread AS t
LEFT JOIN deletionlog AS deletionlog ON(deletionlog.primaryid = t.threadid AND type = 'thread')
WHERE forumid = 30 AND lastpost > 1134582244 AND visible = 1 AND open <> 10
AND deletionlog.primaryid IS NULL
ORDER BY lastpost 
LIMIT 1;

Suggestions to trace where these queries originate in the PHP code?

---------- Post updated at 11:15 ---------- Previous update was at 10:13 ----------

Follow up:

I found the MySQL query (one of them) searching the database using phpMyAdmin. An exact phrase search query did not match, but searching for all the words in the phrase matched a vBulletin plugin.

---------- Post updated at 11:32 ---------- Previous update was at 11:15 ----------

Note: I upgraded the Advanced Forum Statistics below the navbar on the home page of the forums to see if the latest version of this plugin solves the issue with the slow query.

Anyway, the latest version looks nicer :smiley:

---------- Post updated at 11:45 ---------- Previous update was at 11:32 ----------

Ah Ha! The second slow query is coming from the vB plugin Prevent DoublePost. I'll search for a later version which might be better written (optimized).

Arbitrary question - I've only worked Oracle & access for the last 25 years -
Can you not add indexes, update statistics, or use other tools rather than wait and hope for somebody to write an optimized query?

Yes, I can.

But it is better to search for an update first before modifying code. The chances are that it has already been fixed; so first we search for updates, talk to the developer, then if that does not give the results we need, we modify the code.

Cheers.

PS: For the first query, we have not seen any slow queries since I installed the latest version. I will continue to monitor the log. Looks better so far.

---------- Post updated 2009-09-30 at 09:09 ---------- Previous update was 2009-09-29 at 16:03 ----------

Great! No slow queries at all since I upgraded that "troublesome" vB plugin :smiley:

If this continues I will tweek my.cnf from

long_query_time = 5

to

long_query_time = 4