Search code examples
mysqlmysql-slow-query-log

Mysql slow query log not honoring long_query_time variable, logs really quick queries

I'm running mysql 5.5 and am debugging a performance issue. I have enabled mysql slow logging. These are my relevant settings in my.cnf:

log_slow_queries    = /var/log/mysql/mysql-slow.log
long_query_time = 10
log-queries-not-using-indexes

Mysql is indeed creating and writing to a slow query log. However, it logging lots of queries that run much, much quicker than specified by the long_query_time parameter.

Here are a couple examples of that: 

# Query_time: 0.000142  Lock_time: 0.000039 Rows_sent: 1  Rows_examined: 1 
# Query_time: 0.000081  Lock_time: 0.000024 Rows_sent: 1  Rows_examined: 1
# Query_time: 0.000116  Lock_time: 0.000034 Rows_sent: 1  Rows_examined: 1

There are actually no instances of queries that have query or lock times that, together, add up to anything greater than 0.1. From my reading of what the long_query_time parameter is supposed to do, I would not expect to find those queries in the slow query log.

Solution

  • Editing the my.cnf does not apply the changes to the running instance. You must restart the MySQL Service for my.cnf to take effect.

    Alternatively, you can use SET GLOBAL long_query_time = 10 to apply the equivalent change in the currently running instance.

    My habit is to do both: edit my.cnf so that the next time I restart MySQL Service, it takes effect, and then I also use SET GLOBAL to apply the same changes to the running instance. Understand that not every MySQL server variable can be changed dynamically like that.

    Note also that only new client connections will get that global value. Existing client connections will continue to use the prior global value that was in effect when their connections began.

    Re your comment:

    Note you have log-queries-not-using-indexes set. This means to log all queries that don't use indexes, even if the query was quicker than long_query_time.

    https://dev.mysql.com/doc/refman/5.5/en/slow-query-log.html says:

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

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

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

    • The query must have examined at least min_examined_row_limit rows.

    Note that "not using indexes" is a little counter-intuitive. https://dev.mysql.com/doc/refman/5.5/en/server-options.html#option_mysqld_log-queries-not-using-indexes says:

    [The log-queries-not-using-indexes] option does not necessarily mean that no index is used. For example, a query that uses a full index scan uses an index but would be logged because the index would not limit the number of rows.