MySQL（7）——慢查询日志

一、 概述

慢查询是MySQL中提供的一个记录耗时特别长的SQL语句的功能。该功能默认是关闭的。打开之后，慢查询日志默认记录在日志文件中，可以配置为记录在表中。
慢查询会对服务器性能产生一定的影响，一般不在生产环境中开启。

二、开启慢查询

1. 查看开启状态

show variables like 'slow_query%';

+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| slow_query_log      | OFF                                  |
| slow_query_log_file | /var/lib/mysql/mysql-master-slow.log |
+---------------------+--------------------------------------+

OFF是关闭状态，ON是开启状态。
mysql-master-slow.log 是hostname-slow.log的格式。

2. 开启慢查询

mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'slow_query%';
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| slow_query_log      | ON                                   |
| slow_query_log_file | /var/lib/mysql/mysql-master-slow.log |
+---------------------+--------------------------------------+
2 rows in set (0.01 sec)

3. 修改long_query_time

mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.01 sec)

mysql> set global long_query_time=3;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

默认10秒以上的查询为慢查询，修改long_query_time=3以后，当前会话查询的参数还未改变。需要重新打开会话（或开启新的会话）。

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 3.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

• 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的值所指向的目录。

4. 测试慢查询

执行查询语句：

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 3.000000 |
+-----------------+----------+
1 row in set (0.00 sec)

查看日志：

[root@mysql-master ~]# cat /var/lib/mysql/mysql-master-slow.log 
/usr/sbin/mysqld, Version: 5.7.33 (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 2021-04-19T01:30:59.631745Z
# User@Host: root[root] @ localhost []  Id:     7
# Query_time: 4.000185  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1618795859;
select sleep(4);

这里有一个小的问题，日志的记录时间对不上。这是因为我们的记录日志的参数log_timestamps没有配置正确导致的。

mysql> show global variables like 'log_timestamps';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| log_timestamps | UTC   |
+----------------+-------+
1 row in set (0.00 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.00 sec)

将log_timestamps设置为system，再次执行慢查询sql语句:

mysql> select sleep(4);
+----------+
| sleep(4) |
+----------+
|        0 |
+----------+
1 row in set (4.00 sec)

mysql> select sleep(5);
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.00 sec)

查看慢查询日志:

[root@mysql-master ~]# cat /var/lib/mysql/mysql-master-slow.log 
/usr/sbin/mysqld, Version: 5.7.33 (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 2021-04-19T01:30:59.631745Z
# User@Host: root[root] @ localhost []  Id:     7
# Query_time: 4.000185  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1618795859;
select sleep(4);
# Time: 2021-04-19T09:41:31.981046+08:00
# User@Host: root[root] @ localhost []  Id:     7
# Query_time: 4.000187  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1618796491;
select sleep(4);
# Time: 2021-04-19T09:41:41.075500+08:00
# User@Host: root[root] @ localhost []  Id:     7
# Query_time: 5.000392  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1618796501;
select sleep(5);

三、使用mysqldumpslow分析慢查询日志

mysqldumpslow是mysql自带的一个慢日志分析工具：

[root@mysql-master ~]# 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
                 l: lock time
                 r: rows sent
                 t: query time  
  -r           reverse the sort order (largest last instead of first)
  -t NUM       just show the top n queries
  -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

• -s t 按总query time排序
• -s l 按总lock time排序
• -s r 按总row send排序
• -s c 按count排序
• -s at 按平均query time排序
• -s al 按平均lock time排序
• -s as 按平均row send排序
• -r 倒序排列
• -a 不要将数字和字符串抽象成N和S。如果where id = 19 and name=‘张三’，mysqldumpslow工具会把这样的SQL抽象为where id = N and name=S，而这个参数的功能就是不让其进行这样的转换。
• -t NUM 只显示结果的前NUM行结果
• -g 后边可以写一个正则匹配模式,大小写不敏感

## 按照平均query time排序查看日志
[root@mysql-master mysql]# mysqldumpslow -s at mysql-master-slow.log   

Reading mysql slow query log from mysql-master-slow.log
Count: 3  Time=4.33s (13s)  Lock=0.00s (0s)  Rows=1.0 (3), root[root]@localhost
  select sleep(N)

## 按照平均query time排序查看日志，并且不要将数字和字符抽象
[root@mysql-master mysql]# mysqldumpslow -a -s at mysql-master-slow.log 

Reading mysql slow query log from mysql-master-slow.log
Count: 1  Time=5.00s (5s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(5)

Count: 2  Time=4.00s (8s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  select sleep(4)
## 按count排序，不要将数字和字符抽象
[root@mysql-master mysql]# mysqldumpslow -a -s c mysql-master-slow.log 

Reading mysql slow query log from mysql-master-slow.log
Count: 2  Time=4.00s (8s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  select sleep(4)

Count: 1  Time=5.00s (5s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select sleep(5)

[root@mysql-master mysql]#