Why does mysql slow log reports these non-slow queries

Question

My mysql server has long_query_time = 2 configured but I still see these queries reported in slow query log that seem fast:

# Time: 120730  5:06:41
# User@Host: <user> @ <Host> [<IP>] 
# Query_time: 0.000412  Lock_time: 0.000060 Rows_sent: 5  Rows_examined: 5
SET timestamp=1343639201;
SELECT album_id FROM `TB_albums` where album_id!='res_4fe4333271bda7.42833845' and deleted is NULL order by `created_time` desc limit 5;

As you can see Query_time: 0.000412 Lock_time: 0.000060 seems way below 2 seconds

Do you have any Idea why these "fast" queries are reported?

have you checked for variable log_queries_not_using_indexes? — Omesh, Jul 30 '12 at 09:32
@Omesh - checked and this is exactly the problem, I wonder what I can index here??? — ekeren, Jul 30 '12 at 10:10

Chris McCauley · Accepted Answer · 2012-07-30T09:48:59.047

MySQL also logs queries which do not use an index

The option log-queries-not-using-indexes in my.cnf is used to control this. Mine is turned off (by commenting out) as you can see from this snippet of my.cnf

# Here you can see queries with especially long duration
log_slow_queries        = /var/log/mysql/mysql-slow.log
long_query_time = 2
#log-queries-not-using-indexes

If you don't have access to the my.cnf, you can check using SQL

mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+
1 row in set (0.00 sec)

Hope that helps!

Chris

Omesh · Answer 2 · 2012-07-30T09:31:28.630

check for variable log-queries-not-using-indexes

show variables like '%log_queries_not_using_indexes%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   | 
+-------------------------------+-------+

for your case it must be set to OFF, if ON then you can set log_queries_not_using_indexes = OFF in my.cnf file and then restart the MySQL server.

score 0 · Answer 3 · answered Jul 30 '12 at 09:22

AFAIK MySQL measures the query time for a data-fetching query from query submission up to the end of the fetch phase.this means, that something like

Start timer
Start fast SELECT query
Wait for result 
Check timer and note time
sleep 2 seconds
fetch query results
Stop timer

will end up with noted time<2s and end time>2s, and the slow query log triggering on the longer time.

score 0 · Answer 4 · answered Jul 30 '12 at 09:24

From the manual, you need to check the other config that related to write a query to the show query log.

The server uses the controlling parameters in the following order to determine whether to write a query to the slow query log:

1.The query must either not be an administrative statement, or --log-slow-admin-statements must have been specified.

2.The query must have taken at least long_query_time seconds, or log_queries_not_using_indexes must be enabled and the query used no indexes for row lookups.

3.The query must have examined at least min_examined_row_limit rows.

4.The query must not be suppressed according to the log_throttle_queries_not_using_indexes setting.

Why does mysql slow log reports these non-slow queries

4 Answers4

MySQL also logs queries which do not use an index