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

Question

我们偶尔会看到 show global status like "Queries" 每秒报告数千个查询，但在启用所有功能的慢速查询日志中看不到它们，所以我们看不到这些查询是什么。

如果我想在慢查询日志中查看一切，这里是(我认为是)相关的全局变量:

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

在 5 分钟内，mysql 全局状态变量 Questions 报告了 90433 个查询，但慢日志中只有 56479 个查询。丢失的 33954 (38%) 个查询在哪里？

我使用 enableLog.pl 脚本启用日志，该脚本将上述变量设置 5 分钟，然后将它们恢复为原始值:

# 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

虽然 enableLog.pl 在这里运行是(相关的)全局变量:

# 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

此外，它们不是查询缓存命中:

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

Answer 1

请注意，对全局变量的更改不会被现有 session 继承。

session 在 session 开始时制作全局变量的副本，并且 session 在 session 的生命周期内不会重新复制全局变量。因此，如果 session 持续时间相对较长，有些人就不会“听说”他们应该记录他们的慢速查询。确保所有 session 都遵循新全局设置的唯一方法是让它们重新连接并启动新 session 。

其他一些答案建议启用一般查询日志，但如果 session 长期存在并且不知道全局配置选项的更改，这将无济于事。也不会为这些 session 启用常规查询日志。

Percona Server 实现了一个配置选项 slow_query_log_use_global_control使 session 对某些查询日志选项使用全局选项。但是 MySQL 中没有此功能。

我实现了一个类似于您的 enableLog.pl 的脚本。它在这里:

• 代码:https://github.com/billkarwin/bk-tools/blob/master/full-slow-log
• 手册:https://github.com/billkarwin/bk-tools/blob/master/doc/full-slow-log.rst