「MySQL」- 慢查询日志

  CREATED BY JENKINSBOT

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

本文内容

内容: 介绍MySQL中的慢日志查询及分析方法。关于MySQL中的日志种类,查看站内《Server Logs》。

MySQL Version 5.7

“慢查询日志”可用于查找需要很长时间执行的查询,因此可以用做优化的候选。
但是,分析一份很长的慢查询日志是很困难的。可以用mysqldumpslow来处理慢查询日志。

慢查询日志相关选项

“慢查询日志”由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

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

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

当前的版本是5.7,我假设作者所有的在5.7中也适用。

慢查询日志格式

慢查询日志的格式:

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