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);
  1. Time:表示这个慢查询的SQL发生的时间。

  2. Query_time:表示这个SQL语句执行所花费的时间,单位是秒。

  3. Lock_time:表示这个SQL语句在执行的过程中,锁定表或行的时间。

  4. Rows_sent:表示最后查询的结果发送给客户端的行数。

  5. Rows_examined:表示这个SQL语句在执行过程中,实际扫描的行数。

  6. SET timestamp=1609322451:记录日志的时间

  7. 最后就是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>
  1. start_time:SQL语句执行的时间

  2. query_time:该SQL语句执行所消耗的时间,单位是秒。

  3. lock_time:锁表或行的时间。

  4. rows_sent:返回的结果集行数。

  5. rows_examined:实际扫描的记录行数。

  6. db:该SQL语句的是在哪个schema下面执行的。

  7. server_id:在MySQL集群中,数据库实例的编号。

  8. sql_text:SQL语句的具体内容,此处是BLOB字段,不能直接查看,需要时候用CONVERT(sql_text using utf8mb4)函数转换一下,再查看具体的SQL内容。

  9. 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中慢查询日志的主要内容,如果未能解决你的问题,请参考以下文章

教你如何快速定位项目中慢查询[项目管理]

什么是慢查询?

使用 LINQ 优化内存中慢查询列表以检索数据

理解性能的奥秘——应用程序中慢,SSMS中快——案例:如何应对参数嗅探

在 Python 多处理进程中运行较慢的 OpenCV 代码片段

理解性能的奥秘——应用程序中慢,SSMS中快——案例:如何应对参数嗅探