「MySQL」- 慢查询日志

问题描述

该笔记将记录：介绍 MySQL 中的慢日志查询及分析方法。关于 MySQL 中的日志种类，查看站内《Server Logs》；

解决方案

MySQL Version 5.7

“慢查询日志”可用于查找需要很长时间执行的查询，因此可以用做优化的候选；

但是，分析一份很长的慢查询日志是很困难的。可以用 mysqldumpslow 来处理慢查询日志；

根据《高性能 MySQL》作者在章节 3.3.1 所说：

在 MySQL 当前的版本中，慢日志查询日志是开销最低、精度最高的测量查询时间工具。如果还在担心开启慢查询日志会带来额外的开销，大可放心。我们们在 I/O 密集型场景做过基准测试，慢日志查询带来的开销可以忽略不计（实际上在 CPU 密集型场景的影响还稍微大一些）；

当前的版本是 5.7，我们假设作者所有的在 5.7 中也适用；

The Slow Query Log

关于慢查询日志介绍，查看《Slow Query Log: MySQL 慢查询日志》；
https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

The DDL Log
https://dev.mysql.com/doc/refman/5.7/en/ddl-log.html

Server Log Maintenance
https://dev.mysql.com/doc/refman/5.7/en/log-file-maintenance.html

Selecting General Query and Slow Query Log Output Destinations
https://dev.mysql.com/doc/refman/5.7/en/log-destinations.html

慢查询日志相关选项

“慢查询日志”由 SQL 语句组成，每行日志都有时间戳。这些 SQL 语句执行时间超过 long_query_time（单位：秒）指定的时间，并且至少需要检查 min_expected_row_limit 指定的行数；

以下是关于慢日志查询的相关选项：

min_expected_row_limit

命令行: –min-examined-row-limit=#

如果检查的行数少于该参数指定的行数，不会记录到慢查询日志中；

取值范围:0～4294967295(32 位)，0～18446744073709551615(64 位)。默认 0；


https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_min_examined_row_limit

long_query_time

命令行选项：–long_query_time=#

如果 SQL 执行时间超过该值指定的时间（单位为秒），该 SQL 会被视为慢查询；

取值：整数，>=0。默认为 10。该值也可以以毫秒为单位，小数点后表示毫秒；

如果日志写入文件(log-output=FILE)，那么会保存时间的毫秒部分。如果日志写入表(log-output=TABLE)，只能保存秒，毫秒会被忽略；


https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_long_query_time

文档里的描述没有直接说明如何指定毫秒值，只有如下的几句话：

If a query takes longer than this many
seconds ……

The value can be specified to a resolution of microseconds.

其实这里可以推断毫秒部分是出现在小数后面的。所以我们做了如下测试来证明可以使用”0.N”来表示”N * 100″毫秒:

1.先将 long_query_time 设置为 0.5，启动 MySQL。并未得到相关的错误或者警告；

2.然后将 long_query_time 设置为 0.5.5，启动 MySQL。得到 long_query_time 配置错误的信息：“ [ERROR] Invalid
decimal value for option ‘long_query_time’”；

3.由此可见配置参数 0.5 确实被解析了，但不能证明是有效的；

4.其实 1.、2.、3.的用处并不大。接下来，构造两个查询，一个执行时间大于 500ms（select sleep(0.6);），一个小于 500ms(select sleep(0.4);)。分别执行，然后查看慢日志；

具体的细节就不再展开，请自行测试，结论:毫秒部分是出现在小数后面的。前面的一大堆废话，就是为了证明结论可信；

log_slow_admin_statements

命令行选项：不支持

该选项控制是否记录管理语句。默认情况下，不记录管理语句；

MySQL 中的管理语句有: ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, REPAIR TABLE；

log_queries_not_using_indexes

命令行选项：–log-queries-not-using-indexes

控制是否记录未使用索引的查询。默认，不会记录不使用索引进行查找的查询；

log_throttle_queries_not_using_indexes

命令行选项：不支持；

如果使用了 log_queries_not_using_indexes 选项，日志可能涨的很快啊。可以使用该选项限制每分钟写入慢查询日志的个数；

默认是 0，没有限制；

第一个查询会打开一个 60 秒的窗口，时间到了之后禁止其他查询写入。如果在窗口结束时存在抑制查询，则服务器将记录一个摘要，该摘要显示一共有多少以及在其中花费的总时间。当遇到下一个未使用索引的查询，将会开启一个新的窗口；

slow_query_log

命令行选项：–slow-query-log

是否启用慢查询日志。默认情况，慢查询日志是禁用的。0(或者 OFF)表示禁用；1(或者 ON)表示启用；

slow_query_log_file

命令行选项：–slow_query_log_file=file_name

用于指定日志文件名；

如果未指定 file_name，默认为：host_name-slow.log。MySQL 会在 data 目录下创建文件，除非给出了明确的绝对路径；

在运行时修改：如果日志文件已经打开了，会关闭它，然后打开一个新文件；

log-output=value,…

命令行选项：–log-output

指定日志记录类型，取值：TABLE，FILE，NONE:
TABLE: 将日志记录到 general_log 和 slow_log 表中；

FILE: 将日志写入文件中；

NONE: 不记录日志；
如果同时给出 TABLE 和 FILE，则文件和表中都会记录输出。如果出现了 NONE，NONE 的优先级最高，就是说不再记录日志；

注意：该选型并不能用于控制是否启用日志输出；

log_timestamps

系统变量控制写入慢查询日志文件的消息的时间戳时区（也控制了通用日志和错误日志）；

它不会影响写入日志表的“通用查询日志”和“慢查询日志”的时区；

不过取出的时候可以使用 CONVERT_TZ() 函数转化成需要的时区，也可以通过设置 time_zone 系统变量；

log_slow_slave_statements

命令行选项：不支持；

启用缓慢查询日志时，此变量可启用对从库执行超过 long_query_time 的查询的日志记录；

默认情况下，“从库复制”不会将复制查询写到慢查询日志中；

5.7.1 加入了该变量。设置了该变量不会马上生效。该变量的状态适用于所有后续 START SLAVE 语句；

–log-short-format

该选项只有命令行选项；

MySQL 将较少的信息写入慢查询日志；

MySQL 使用以下条件决定是否将一个查询写入慢查询日志。如下：

  • 不能是管理语句，管理语句不会写入，除非启用 log_slow_admin_statements 才可以；
  • 该查询至少花费了 long_query_time 指定的秒数，或者指定了 log_queries_not_using_indexes 并且该查询没有使用到索引；
  • 查询必须至少检查 min_expected_row_limit 行才可以；
  • 查询没有被 log_throttle_queries_not_using_indexes 抑制，意思就是没有超过窗口；

注意事项：

获得初始锁的时间没有计算在执行时间中；

在查询执行结束并且所有的锁已经释放之后，才将语句写入慢查询日志，所以日志顺序可能与执行顺序不同；

写入慢查询日志的语句中的密码不会以明文的形式出现，
https://dev.mysql.com/doc/refman/5.7/en/password-logging.html

服务器不会将查询缓存处理的查询写入慢查询日志；

由于表中具有零行或一行，不会将存在索引而无法获益的查询写入日志；

收集慢日志查询

在 .ini 中，将如下配置加入 [mysqld] 部分： 

[mysqld]

# 慢查询：启用日志
slow_query_log = 1

# 慢查询：执行时间阈值
long_query_time = 1

# 慢查询：日志文件路径
slow_query_log_file = /var/log/mysql/slow-query.log

# 慢查询：日志类型，默认就是 FILE，不指定也可以；
log-output = FILE

临时使用慢查询（How to enable the slow query log in MySQL）： 

# --------------------------------------------------------- # 开启慢查询

SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = X;
SET GLOBAL slow_query_log_file = '/path/filename';

# --------------------------------------------------------- # 关闭慢查询

SET GLOBAL slow_query_log = 'OFF';

处理慢查询日志

慢查询日志的格式

-- mysqld, Version: 5.7.15-log (MySQL Community Server (GPL)). started with:
-- Tcp port: 0  Unix socket: (null)
-- Time                 Id Command    Argument
-- # Time: 2017-04-01T01:11:13.039190Z
-- # User@Host: taobaoke[taobaoke] @ localhost []  Id:    87
-- # Query_time: 7.388035  Lock_time: 0.000113 Rows_sent: 30  Rows_examined: 18020
-- use taobaoke;
-- SET timestamp=1491009073;
-- SELECT * FROM tbk_article
-- WHERE 1
-- ORDER BY sort DESC,id DESC
-- LIMIT 0, 30;

这个 SQL 语句已经很慢了，但是这里并不是要将怎么优化这个 SQL 语句。以后会讨论这个问题的；

大量慢查询日志处理

检查一份很长的慢查询日志是很困难的；

关于慢查询日志的分析，可以使用 mysqldumpslow。MySQL 源码就带这个。关于 mysqldumpslow 的使用请查看：《mysqldumpslow 的使用》

参考文献

Doc: https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html
《高性能 MySQL》/ 章节 3.3.1

Filed under: K4NZDROID - @ 9:16 PM