mysql 5.7：为什么慢查询日志中丢失了38%的查询？

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

来自manual：

The server does not write queries handled by the query cache to the slow query log, nor queries that would not benefit from the presence of an index because the table has zero rows or one row.

使用

检查查询缓存提供了多少查询

SHOW STATUS LIKE 'Qcache%';

寻找 Qcache_hits。您还可以检查 GLOBAL 值。

阅读有关查询缓存的更多信息here

Answer 2

如果您想知道，请同时打开慢速查询日志（如所述）和同一脚本中的常规日志。将慢查询日志中的 'missing' 并排比较以查看常规日志正在做什么真的很容易。

记得在会话结束时关闭常规日志，以免填满您的存储设备。

Answer 3

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

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

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

Percona Server 实施了一个配置选项 slow_query_log_use_global_control 以使会话对某些查询日志选项使用全局选项。但是这个功能没有现货MySQL.

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

mysql 5.7：为什么慢查询日志中丢失了38%的查询？

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

mysql

mysql-slow-query-log