MySQL中慢查询日志_vlambda技术博客

vlambda
2020-12-31

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语句的效率低拖慢整个应用系统。希望上面的这些总结可以对你使用慢查询日志的功能有所帮助。

第一时间了解更多干货分享，还有各类视频教程资源。扫描它，带走我

vlambda博客
学习文章列表