Search code examples
mysqlmysql-slow-query-log

mysql 5.7: Why are 38% of queries missing from the slow query log?

Sporadically we're seeing thousands of queries per second reported by show global status like "Queries" but don't see them in the slow query log with everything enabled, so we can't see what these queries are.

Here are (what I think are) the relevant global variables if I want to see everything in the slow query log:

log_queries_not_using_indexes   ON
log_slow_admin_statements   ON
log_slow_slave_statements   ON
log_throttle_queries_not_using_indexes  0
long_query_time 0.000000
min_examined_row_limit  0
slow_launch_time    2
slow_query_log  ON
slow_query_log_file /tmp/slow.log

Over a 5min period, mysql global status variable Questions reports 90433 queries, but there are only 56479 queries in the slow log. Where are the missing 33954 (38%) queries?

I enable the log with a enableLog.pl script that sets up the above variables for 5 minutes, then reverts them to their original values:

# mysql --login-path=cm -Ee 'show  global status like "Queries"' && rm -rf /tmp/slow.log && ./enableLog.pl --duration 5m /tmp/slow.log && mysql --login-path=cm -Ee 'show  global status like "Queries"'
*************************** 1. row ***************************
Variable_name: Queries
        Value: 73570440
11:41:51: logging for 00:05:00 until 11:46:51
... ending
*************************** 1. row ***************************
Variable_name: Queries
        Value: 73660873

# perl -E 'say 73660873-73570440'
90433

# grep '^# Time: ' /tmp/slow.log | wc -l
56479

# perl -E 'say 90433-56479'
33954

# perl -E 'say +(90433-56479)/90433'
0.375460285515243

While enableLog.pl is running here are the (relevant) global variables:

# mysql --login-path=cm -e 'show global variables;' | egrep '^(slow_|log_|min_)'
log_bin OFF
log_bin_basename    
log_bin_index   
log_bin_trust_function_creators OFF
log_bin_use_v1_row_events   OFF
log_builtin_as_identified_by_password   OFF
log_error   /var/log/mysql/error.log
log_error_verbosity 3
log_output  FILE
log_queries_not_using_indexes   ON
log_slave_updates   OFF
log_slow_admin_statements   ON
log_slow_slave_statements   ON
log_syslog  OFF
log_syslog_facility daemon
log_syslog_include_pid  ON
log_syslog_tag  
log_throttle_queries_not_using_indexes  0
log_timestamps  UTC
log_warnings    2
long_query_time 0.000000
min_examined_row_limit  0
slow_launch_time    2
slow_query_log  ON
slow_query_log_file /tmp/slow.log

# mysql --version
mysql  Ver 14.14 Distrib 5.7.9, for Linux (x86_64) using  EditLine wrapper

Also, they aren't query cache hits:

# mysql --login-path=cm -e 'SHOW GLOBAL STATUS LIKE "Qcache_hits";'
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Qcache_hits   | 0     |
+---------------+-------+
Solution

  • Note that changes to global variables are not inherited by existing sessions.

    Sessions make a copy of global variables when the session starts, and the session does not re-copy global variables during the session's lifetime. So if sessions are relatively long-lived, some won't have "heard" that they should log their slow queries. The only way to ensure that all sessions heed the new global settings is to make them re-connect and start new sessions.

    Some other answers have suggested enabling the general query log, but this won't help if sessions are long-lived and don't know about changes to the global config options. The general query log won't be enabled for those sessions either.

    Percona Server implemented a config option slow_query_log_use_global_control to make sessions use the global option for certain query-log options. But this feature is not in stock MySQL.

    I implemented a script similar to your enableLog.pl. It's here: