MySQL中慢查询日志
Posted 程序猿集锦
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了MySQL中慢查询日志相关的知识，希望对你有一定的参考价值。
第一时间了解更多干货分享，还有各类视频教程资源。扫描它，带走我
背景
什么是慢查询日志
如何开启慢查询日志
慢查询日志的参数
如何读懂慢查询日志
慢查询日志文件中的日志
慢查询日志表中的日志
如何分析慢查询日志
总结
背景
你是否有这样的疑问：我还如何定位当前mysql数据中的一些执行特别耗时的SQL语句，那些特别慢的SQL都有哪些？我怎么样把他们都给筛选出来呢？MySQL中是否可以记录这些执行特别慢的SQL？
MySQL中的慢查询日志就是来满足上面的这些需求而设计的。
什么是慢查询日志
MySQL中提供了一个记录耗时特别长的SQL语句的功能，这个功能就是我们平时听说的慢查询日志。
你可能会问这些日志记录在哪里呢？我平时怎么没有看到过。这个慢查询日志的功能，在默认情况下是不会自动开启的。也是需要我们自行的选项性的打开这个功能才可以记录慢查询的SQL语句。打开之后，可以选择把这个日志记录在服务器上面的某个目录下面(默认是记录在日志文件中)，当然也可以记录在MySQL的表中，还可以选择及记录日志文件中还记录在表中。具体如何配置，下面会详细介绍。
打开之后，肯定都会对数据库的性能是有一定的影响的，但是这个影响也是我们可以接受的范围内的。同时，它还会占用一定的磁盘存储空间。我们一般情况下，不会在生产环境上开启这个记录慢查询日志的功能的。我们只会在DEV、SIT、UAT等环境下面才会开启这个功能，把所有的慢查询的SQL在这些环境中给筛选出来，解决掉，这样在生产环境中就没有必要开启慢查询的功能了。
如何开启慢查询日志
在开启之前，首先需要检查一下当前的MySQL是否已经开启了慢查询日志记录的功能，如果开启了，就不需要再次执行了，如果没有开启，在参考下面的配置开启慢查询的功能。可以通过如下命令查看是否开启了慢查询日志：
mysql> show variables like "slow_%";
+---------------------+------------------------------+
| Variable_name | Value |
+---------------------+------------------------------+
| slow_launch_time | 2 |
| slow_query_log | OFF |/* OFF，这里表示没有开启 */
| slow_query_log_file | /var/lib/mysql/test-slow.log |
+---------------------+------------------------------+
3 rows in set (0.01 sec)
如果要开启慢查询日志，可以在MySQL的配置文件中配置如下参数：
[mysqld]
# 开启慢查询日志，1表示开启，0表示关闭。
slow_query_log = 1
配置这个参数之后，重启MySQL实例之后，就可以了。如果不想重启MySQL数据库实例，可以直接在MySQL的terminal窗口中，执行如下的SQL命令来开启慢查询日志，但是同时也需要在配置文件中配置上上面的参数，否则MySQL示例重启后，慢查询日志又关闭了。为了避免重启MySQL数据实例之后失效，所以上面的修改配置文件的步骤也不可以省略。
mysql> set global slow_query_log = 1; /*开启慢查询日志的命令*/
Query OK, 0 rows affected (0.03 sec)
mysql> show variables like "slow_%";
+---------------------+------------------------------+
| Variable_name | Value |
+---------------------+------------------------------+
| slow_launch_time | 2 |
| slow_query_log | ON |/*ON, 此时表示已经开启了慢查询日志记录的功能*/
| slow_query_log_file | /var/lib/mysql/test-slow.log |
+---------------------+------------------------------+
3 rows in set (0.02 sec)
mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name | Value |
+-----------------+----------+
| long_query_time | 3.000000 |
+-----------------+----------+
1 row in set (0.01 sec)
这里需要先了解3个参数：
long_query_time：决定一个SQL语句是否是慢查询的阈值。如果一个SQL的执行时间超过这个阈值，则认定这个SQL为慢查询的SQL语句，将其记录在慢查询日志中，否则不记录。默认值为
10s，如果设置为0s，则表示记录所有的SQL语句。slow_query_log：慢查询日志是否开启的标识，ON或者1表示开启，OFF或者0表示没有开启。
slow_query_log_file：慢查询日志存放目录，对应到MySQL数据库服务器上面的一个日志文件。默认的日志文件名称为
服务器主机名称-slow.log。默认的日志存储的路径为变量：datadir的值所指向的目录。
上面我们已经开启了慢查询日志的功能，下面我们来验证开启后的效果。
我们在MySQL的命令行中执行一个慢查询SQL，然后看下这个SQL语句是否被记录在了MySQL的慢查询日志中。因为我们上面使用的默认慢查询的阈值为10s，所以我们执行下面的一个执行11s的SQL语句。
mysql> select sleep(11);
+----------+
| sleep(11) |
+----------+
| 0 |
+----------+
1 row in set (11.00 sec)
现在去查看日志文件，查看的结果如下：
root@test:/# tail -6 /var/lib/mysql/test-slow.log
# Time: 2020-12-30T08:42:25.599835Z
# User@Host: root[root] @ [172.19.0.1] Id: 2
# Query_time: 3.001212 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
use feng;
SET timestamp=1609317745;
select sleep(11);
root@test:/#
通过上面的查询结果，我们可以确认我们的开启已经生效了，但是有一个小的问题，日志的记录时间对不上，我执行的时间是2020-12-30 16:42:25，但是上面记录的时间是：2020-12-30T08:42:25.599835Z。这是因为我们的记录日志的参数log_timestamps没有配置正确导致的。我们修改一下这个参数的配置，然后再次验证一下。
mysql> show global variables like 'log_timestamps';
+----------------+-------+
| Variable_name | Value |
+----------------+-------+
| log_timestamps | UTC |
+----------------+-------+
1 row in set (0.01 sec)
mysql> set global log_timestamps = system;
Query OK, 0 rows affected (0.00 sec)
mysql> show global variables like 'log_timestamps';
+----------------+--------+
| Variable_name | Value |
+----------------+--------+
| log_timestamps | SYSTEM |
+----------------+--------+
1 row in set (0.01 sec)
mysql> select sleep(12);
+----------+
| sleep(12) |
+----------+
| 0 |
+----------+
1 row in set (12.00 sec)
mysql> select now();
+---------------------+
| now() |
+---------------------+
| 2020-12-30 16:51:26 |
+---------------------+
1 row in set (0.02 sec)
此时我们再次去看下慢查询日志中记录的时间是否正确：
root@test:/# tail -6 /var/lib/mysql/test-slow.log
select sleep(11);
# Time: 2020-12-30T16:48:49.137716+08:00
# User@Host: root[root] @ [172.19.0.1] Id: 2
# Query_time: 4.000988 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1609318129;
select sleep(12);
root@test:/#
慢查询日志的参数
前面我们认识了几个关于慢查询日志的参数，其实慢查询日志的参数还有很多。下面逐一介绍一下。可以根据自己的业务需求，选择性的配置。
log_output：决定慢查询日志记录在哪里，是日志文件中，还是表中，还是两个地方都记录。它的值我可以为：
FILE、TABLE、FILE,TABLE中的一个。如果为
TABLE表示记录在表中，表的名称为：mysql.slow_log。如果为
FILE表示只记录在日志文件中，日志路径默认在datadir变量中所配置的路径下，日志文件名称为主键名-slow.log，这个路径和名称都是可以在my.cnf配置文件中根据需求执行配置修改。如果是
FILE,TABLE则表示在表和日志中同时记录慢查询日志。slow_query_log_file：如果是使用日志文件来存储慢查询日志，可以通过这个参数配置具体的慢查询日志的存储目录，而不使用默认的存储目录和名称。
log_queries_not_using_indexes：如果一个SQL语句没有时候用到任何索引查询，那么将这个SQL语句也记录在慢查询日志中。避免漏掉由于原先数据量小、SQL查询语句执行比较快没有超过慢查询的阈值、且没有使用任何索引的SQL，因为这些SQL语句有可能因为日后的表中的数据量增加，而导致他们的查询效率急剧下降。
log_throttle_queries_not_using_indexes：控制每一分钟内，那些因为没有使用索引的SQL在慢查询日志中记录的次数。避免一分钟内频繁记录没有使用索引的SQL的情况，从而减少了慢查询日志的大小，避免慢查询日志暴增的情况。
min_examined_row_limit：控制扫描记录行数少于该值的SQL语句，不被记录在慢查询日志中。前面介绍的参数，对没有使用任何索引的SQL语句也记录在慢查询日志中。但是有可能存在这样的一些表，表中数据一种都是有几十行，查询的SQL没有使用任何索引，查询速度也很快。这些SQL即使没有使用到索引，也可以不记录在慢查询日志中。通过这个参数就可以避免把这些SQL也记录在内。
log_slow_admin_statements：是否记录一些管理命令使用的SQL到慢查询日志中。比如：
alter table、analyze table的语句。
下面看一个比较全面的慢查询日志的配置参数，一般情况下不把没有使用索引的SQL记录进来。
[mysqld]
# 设置日志中记录日志记录的时候使用的时间，避免和系统时间差8个小时的问题。
log_timestamps=system
############### 慢查询日志配置相关 #######################################
slow_query_log=1
# 慢查询日志记录在mysql.slow_log表中
log_output=table,file
slow_query_log_file=/var/lib/mysql/test-slow.log
# 慢查询日志的SQL耗时的阈值
long_query_time=10
# 对没有使用索引的SQL，即便是查询耗时低于10s，也记录日志
#log_queries_not_using_indexes=1
# 对没有使用索引的SQL，即便是查询耗时低于10s，也记录日志，但是一分钟内置记录1次。
#log_throttle_queries_not_using_indexes=1
# 没有使用索引的SQL，如果扫描的行数低于1000，则不记录到慢查询日志中
#min_examined_row_limit=1000
# alter，analyze语句，如果超过慢查询的阈值，也记录在慢查询日志中
#log_slow_admin_statements=1
############### 慢查询日志配置相关 #######################################
如何读懂慢查询日志
慢查询日志文件中的日志
一条完整慢查询日志如下所示，我们来分析一些各个字段的含义。
# Time: 2020-12-30T18:00:51.995777+08:00
# User@Host: root[root] @ [172.19.0.1] Id: 2
# Query_time: 12.006039 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1609322451;
select sleep(12);
Time：表示这个慢查询的SQL发生的时间。
Query_time：表示这个SQL语句执行所花费的时间，单位是秒。
Lock_time：表示这个SQL语句在执行的过程中，锁定表或行的时间。
Rows_sent：表示最后查询的结果发送给客户端的行数。
Rows_examined：表示这个SQL语句在执行过程中，实际扫描的行数。
SET timestamp=1609322451：记录日志的时间
最后就是SQL语句的具体内容。
慢查询日志表中的日志
如果你选择把慢查询日志记录在表中，那么会记录在mysql.slow_log中。我们截取其中一条记录如下所示：
mysql> select *, CONVERT(sql_text using utf8mb4) from mysql.slow_log\G
*************************** 7. row ***************************
start_time: 2020-12-30 18:00:51.995777
user_host: root[root] @ [172.19.0.1]
query_time: 00:00:12.006039
lock_time: 00:00:00.000000
rows_sent: 1
rows_examined: 0
db:
last_insert_id: 0
insert_id: 0
server_id: 100
sql_text: 0x73656C65637420736C65657028313229
thread_id: 2
CONVERT(sql_text using utf8mb4): select sleep(12)
7 rows in set (0.02 sec)
mysql>
start_time：SQL语句执行的时间
query_time：该SQL语句执行所消耗的时间，单位是秒。
lock_time：锁表或行的时间。
rows_sent：返回的结果集行数。
rows_examined：实际扫描的记录行数。
db：该SQL语句的是在哪个schema下面执行的。
server_id：在MySQL集群中，数据库实例的编号。
sql_text：SQL语句的具体内容，此处是BLOB字段，不能直接查看，需要时候用
CONVERT(sql_text using utf8mb4)函数转换一下，再查看具体的SQL内容。thread_id：线程编号。
如何分析慢查询日志
最简单也是最常用的一个工具就是MySQL自带的mysqldumpslow。它的使用帮助如下：
root@test:/# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
Parse and summarize the MySQL slow query log. Options are
--verbose verbose
--debug debug
--help write this text to standard output
-v verbose
-d debug
-s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default
al: average lock time
ar: average rows sent
at: average query time
c: count # SQL语句出现的次数
l: lock time # SQL语句锁定表或行的时间
r: rows sent # SQL语句返回的结果集行数
t: query time # SQL语句执行锁消耗的时间
-r reverse the sort order (largest last instead of first) # 倒序排列输出结果
-t NUM just show the top n queries # 取top n个记录
-a don't abstract all numbers to N and strings to 'S'
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep: only consider stmts that include this string
-h HOSTNAME hostname of db server for *-slow.log filename (can be wildcard),
default is '*', i.e. match all
-i NAME name of server instance (if using mysql.server startup script)
-l don't subtract lock time from total time
root@test:/#
参数解释：
| 序号 | 参数名称 | 参数解释 |
|---|---|---|
| 1 | -s t | 按总query time排序 |
| 2 | -s l | 按总locktime排序 |
| 3 | -s s | 按总row send排序 |
| 4 | -s c | 按count排序 |
| 5 | -s at | 按平均query time排序 |
| 6 | -s al | 按平均lock time排序 |
| 7 | -s as | 按平均row send排序 |
| 8 | -r | 倒序排列 |
| 9 | -a | 不要将数字和字符串抽象成N和S。如果where id = 19 and name='张三'，mysqldumpslow工具会把这样的SQL抽象为 where id = N and name=S，而这个参数的功能就是不让其进行这样的转换。 |
| 10 | -t NUM | 只显示结果的前NUM行结果。 |
| 11 | -g | 后边可以写一个正则匹配模式,大小写不敏感。 |
常用的mysqldumpslow命令使用组合有如下几个：
root@test:# cd /var/lib/mysql
root@test:/var/lib/mysql# #按照query time排序查看日志
root@test:/var/lib/mysql# mysqldumpslow -s t test-slow.log> slow.1.dat
root@test:/var/lib/mysql# #按照平均query time排序查看日志
root@test:/var/lib/mysql# mysqldumpslow -s at test-slow.log > slow.2.dat
root@test:/var/lib/mysql# #按照平均query time排序并且不抽象数字的方式排序
root@test:/var/lib/mysql# mysqldumpslow -a -s at test-slow.log > slow.3.dat
root@test:/var/lib/mysql# #安装执行次数排序
root@test:/var/lib/mysql# mysqldumpslow -a -s c test-slow.log > slow.4.dat
总结
在我们平时的开发和应用中，有必要排查出那些效率特别低的SQL语句，然后进行相应的优化，避免项目上线后，因为SQL语句的效率低拖慢整个应用系统。希望上面的这些总结可以对你使用慢查询日志的功能有所帮助。
第一时间了解更多干货分享，还有各类视频教程资源。扫描它，带走我
以上是关于MySQL中慢查询日志的主要内容，如果未能解决你的问题，请参考以下文章
理解性能的奥秘——应用程序中慢，SSMS中快——案例：如何应对参数嗅探