前言

数据库日志记录了用户对数据库的各种操作及数据库发生的各种事件。能帮助数据库管理员追踪、分析问题。MySQL提供了错误日志、二进制日志、查询日志、慢查询日志。

MySQL的慢查询日志是MySQL提供的一种日志记录，它用来记录在MySQL中响应时间超过阀值（long_query_time，单位：秒）的SQL语句。默认情况下，MySQL不启动慢查询日志。本文简单介绍如何开启慢查询日志，如何用mysqldumpslow分析慢查询。

开启慢查询日志

修改my.cnf

在配置文件my.cnf（一般为/etc/my.cnf）中的[mysqld] section增加如下参数。

[mysqld]
slow_query_log = 1
slow_query_log_file = /var/lib/mysql/slow-query.log   # 若没有指定，默认名字为hostname_slow.log
long_query_time = 1

log_queries_not_using_indexes = 1

其中，

• slow_query_log = 1
  • 表示开启慢查询，0表示关闭
• slow_query_log_file
  • 指定慢查询日志路径
  • 需要MySQL对该路径有写权限
• long_query_time = 1
  • 表示查询时间>=1秒才记录日志
  • 默认10s
• log_queries_not_using_indexes = 1
  • 表明记录没有使用索引的 SQL 语句

重启MySQL服务

# 重启
$ sudo service mysqld restart

# 重启后进程如下

root     22373  0.0  0.0  66064  1424 pts/3    S    16:59   0:00 /bin/sh /usr/local/mysql/bin/mysqld_safe --datadir=/var/lib/mysql --socket=/var/lib/mysql/mysql.sock --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --user=mysql
mysql    22721  0.3  0.5 890996 467040 pts/3   Sl   16:59   0:00 /usr/local/mysql/bin/mysqld --basedir=/usr/local/mysql --datadir=/var/lib/mysql --plugin-dir=/usr/local/mysql/lib/plugin --user=mysql --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/lib/mysql/mysql.sock

重启MySQL后会看到/var/lib/mysql/slow-query.log文件。

检查参数

通过如下命令可以检查上述参数配置情况。

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

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

测试

慢查询

制造慢查询并执行。如下。

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

慢查询日志

打开慢查询日志文件。可以看到上述慢查询的SQL语句被记录到日志中。

# Time: 180620 17:13:06
# User@Host: apsara[apsara] @ dc1487859883577.et2sqa [11.239.51.96]  Id:     3
# Query_time: 1.000246  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1529485986;
select sleep(1);

慢查询分析工具

mysqldumpslow

mysqldumpslow是MySQL自带的分析慢查询的工具。该工具是Perl脚本。

常用参数如下。

-s：排序方式，值如下
    c：查询次数
    t：查询时间
    l：锁定时间
    r：返回记录
    ac：平均查询次数
    al：平均锁定时间
    ar：平均返回记录书
    at：平均查询时间
-t：top N查询
-g：正则表达式

例子

• 我们执行了多次类似如下的查询。

select * from db_user where name like 'zb%';
select * from db_user where name like 'aaa%';
select * from db_user where name like 'bc%';
...

• 获取访问次数最多的5个SQL语句

$ mysqldumpslow -s c -t 5 /var/lib/mysql/slow-query.log

Reading mysql slow query log from /var/lib/mysql/slow-query.log
Count: 15  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), apsara[apsara]@dc1487859883577.et2sqa
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  SET timestamp=N;
  select * from db_user where name like 'S'

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), apsara[apsara]@dc1487859883577.et2sqa
  # Query_time: N.N  Lock_time: N.N Rows_sent: N  Rows_examined: N
  use test;
  SET timestamp=N;
  select * from db_user where name like 'S'

• 按照时间排的top 5个SQL语句

$ mysqldumpslow -s t -t 5 /var/lib/mysql/slow-query.log

• 按照时间排序且含有'like'的top 5个SQL语句

$ mysqldumpslow -s t -t 3 -g "like" /var/lib/mysql/slow-query.log

小结

默认情况下，MySQL不启动慢查询日志。若要检查慢查询，需要我们手动设置这个参数。一般情况下，若非调优需要，不建议启动该参数，因为开启慢查询日志或多或少会带来一定的性能影响。慢查询日志支持将日志记录写入文件，也支持将日志记录写入数据库表。

Reference

• https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html
• https://dev.mysql.com/doc/refman/5.7/en/mysqldumpslow.html