Why does mysql slow log reports these non-slow queries
-
23-06-2021 - |
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?
Solution
MySQL also logs queries which do not use an index
The optionlog-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
OTHER TIPS
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.
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.
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.