Fully-indexed Fast Query appearing in the MySQL Slow Log

[NeedExpertHelp]

Hi guys,

I can't seem to wrap my head around this one.

I have a MySQL query that runs in about 0.03 seconds and has every column it refers to fully-indexed, yet it is popping up continuously in my MySQL Slow Log.

From what I understand, the MySQL Slow Log is only meant to log queries that are longer than 1 second or could benefit from indexing.

I don't see how my query could further benefit from indexing since all 7 columns it refers to have already been indexed, and the query is taking a lot less than 1 second to execute, so I have no idea why MySQL is considering it "slow".

I have copied the query below with the corresponding EXPLAIN output to see if anyone can shed some light on this.

Needless to say, if I can further improve this query's speed, that would be great, but right now it is overfilling my slow log.

The Query:

---------------------------

(SELECT tableOne . * , tableTwo . * FROM TABLEONE AS tableOne 
 LEFT JOIN TABLETWO AS tableTwo USING ( col1 ) 
 LEFT JOIN TABLETHREE AS tableThree USING ( col1 ) 
 WHERE tableOne.col1 != '25202' 
 AND tableOne.col2 = 'ZZ' 
 AND tableThree.col3 = 'Y' 
 AND tableThree.col4 > ( UNIX_TIMESTAMP( ) -7200 ) 
 AND tableOne.col5 LIKE 'F' 
 AND (tableOne.col6 LIKE 'M' OR tableOne.col6 LIKE 'M-B') 
 AND tableOne.col1 NOT IN (20758) 
GROUP BY tableOne.col1 
ORDER BY tableOne.col7 DESC LIMIT 50)
 
UNION 

( SELECT tableOne . * , tableTwo . * FROM TABLEONE AS tableOne 
   LEFT JOIN TABLETWO AS tableTwo USING ( col1 ) 
 LEFT JOIN TABLETHREE AS tableThree USING ( col1 ) 
 WHERE tableOne.col1 != '25202' 
 AND tableThree.col3 = 'Y' 
 AND tableThree.col4 > ( UNIX_TIMESTAMP( ) -7200 ) 
 AND tableOne.col5 LIKE 'F' 
 AND (tableOne.col6 LIKE 'M' OR tableOne.col6 LIKE 'M-B') 
 AND tableOne.col1 NOT IN (20758) 
GROUP BY tableOne.col1 
ORDER BY tableOne.col7 DESC LIMIT 50)

LIMIT 0, 5 ;


EXPLAIN:
Rows: 7
id select_type table type possible_keys key key_len ref rows Extra
1 PRIMARY tableThree range col4,col3,col1 col4 5 NULL 549 Using where; Using temporary; Using filesort
1 PRIMARY tableOne eq_ref PRIMARY,col2,col5,col6 PRIMARY 4 Database.tableThree.col1 1 Using where
1 PRIMARY tableTwo eq_ref PRIMARY PRIMARY 4 Database.tableOne.col1 1 
2 UNION tableThree range col4,col3,col1 col4 5 NULL 549 Using where; Using temporary; Using filesort
2 UNION tableOne eq_ref PRIMARY,col5,col6 PRIMARY 4 Database.tableThree.col1 1 Using where
2 UNION tableTwo eq_ref PRIMARY PRIMARY 4 Database.tableOne.col1 1 
NULL UNION RESULT <union1,2> ALL NULL NULL NULL NULL NULL

---------------------------

To re-iterate: col1, col2, col3, col4, col5, col6, and col7 above are all indexed.

Thanks a lot for your help, I really appreciate it!

[brotherhood of LAN]

Are they MyISAM tables? Does restarting the MySQL server have any increase/decrease in performance?

runs in about 0.03

Ensure that it's not in the query cache. A 10 second query will take a sub-second time after it is in the query cache.

If you add SQL_NO_CACHE to the query and find that it's in the slow query log all the time then perhaps that's why.

[NeedExpertHelp]

Thanks for the fast reply, brotherhood of LAN.

Yes, they are all MyISAM tables.

No, restarting the MySQL server did not impact performance by any noticeable degree.

No, adding "SQL_NO_CACHE" immediately after the two SELECT statements in the query did not impact performance by any noticeable degree.

Any other ideas? Thanks!

[brotherhood of LAN]

If there are inserts into the tables then any cache would be wiped.

If the tables take inserts, maybe try the query after an insert query?

[NeedExpertHelp]

It is tough for me to try the query after an insert because the site is quite active, with inserts and queries on those tables happening continuously. But what would that possibly reveal?

What I still don't get is that even within the MySQL Slow Log, the query time is well below 1 second and yet all the columns are indexed, so I don't understand why MySQL considers it "slow".

[brotherhood of LAN]

what would that possibly reveal?

MyISAM tables use the query cache whenever possible which is faster than retrieving the result set by actually performing the query.

MyISAM also uses a key buffer [dev.mysql.com] to store frequently accessed index blocks.

An insert on your tables would mean the query has to be performed... because results in query cache may be obsolete after the insert.

I'm not sure why it's being logged as slow since you say the query is being performed quickly...it's worth looking into (as you're doing) even if the queries are of adequate speed.

If it's your own server and you can allocate memory, it may be worth checking out the LOAD INDEX INTO CACHE [dev.mysql.com] route, to store your indexes fully into memory.

Your EXPLAIN pretty much says the indexes are being used so I can only guess that disk IO is the issue.

// Added

It's also worth considering that MyISAM tables are locked when INSERTs are happening. So sometimes your SELECTs may have to wait until the INSERTs are done, which can be a problem if the INSERTs are slow.

[NeedExpertHelp]

The Slow Log shows the lock times and they are negligible for this query (under 0.0004 seconds). That's what's so puzzling, it's actually a relatively fast query that is fully-indexed, yet for seem reason, MySQL considers it "slow". I have a feeling it has something to do with the UNION as that is one of the things that separates this query from others on my site that aren't appearing in the Slow Log.

If you or anyone else has any other ideas, please let me know. This is quite frustrating...