作者 | 阿文

责编 | 郭芮

今天和大家分享一下 MySQL 的慢日志。

在实际工作中，我面对很多用户会经常碰到一个问题，那就是在使用 MySQL 时，执行一条语句需要很长时间返回，这是为什么呢？当你在使用 MySQL 中，当发现一些性能问题的时，比如执行一个语句要很长时间才返回结果，我们称之为慢查询，一般来说，发生慢查询的原因有：

你的索引设计有问题，可能会导致每次执行语句都是全表扫描，这样很耗费时间；你的 SQL 语句没有写好，可能会导致查询时间变长；MySQL 选择了错误的索引，同样会导致全表扫描。

通常情况下，在业务上线之前，会在测试环境里面，把 MySQL 的慢查询打开，也就是把 longquerytime 设置为 0，这样确保每一条语句都被记录到慢日志中去，具体的配置可以参考下文。

MySQL 的慢查询日志是MySQL提供的一种日志记录，它是用来记录在MySQL中响应时间超过阀值的语句。系统默认情况下，MySQL 并不启动慢查询日志，需要我们手动来设置这个参数，当然，如果不是调优需要的话，一般不建议启动该参数，因为开启慢查询日志会或多或少带来一定的性能影响。

慢查询日志支持将日志记录写入文件，也支持将日志记录写入数据库表。

慢查询配置

默认情况下slowquerylog的值为OFF，表示慢查询日志是禁用的，可以通过设置slowquerylog的值来开启，如下所示：

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

开启慢查询日志：

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

然后看状态：

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

使用set global slowquerylog=1开启了慢查询日志只对当前数据库生效，如果MySQL重启后则会失效。如果要永久生效，就必须修改配置文件my.cnf（其它系统变量也是如此）。

例如如下所示：

[root@mysql ~]# vim /etc/my.cnfslow_query_log=1slow_query_log_file=/var/lib/mysql/mysql-slow.log

参数说明：

slowquerylog 慢查询开启状态；slowquerylog_file 慢查询日志存放的位置；longquerytime 查询超过多少秒才记录。

那么开启了慢查询日志后，什么样的SQL才会记录到慢查询日志里面呢？ 是否会被写入到慢日志是由参数longquerytime控制，默认情况下longquerytime的值为10秒，可以使用命令修改，也可以在my.cnf参数里面修改。关于运行时间正好等于longquerytime的情况，并不会被记录下来。也就是说，在MySQL源码里是判断大于longquerytime，而非大于等于。从MySQL 5.1开始，longquerytime开始以微秒记录SQL语句运行时间，之前仅用秒为单位记录。如果记录到表里面，只会记录整数部分，不会记录微秒部分。

查看long_time 值，默认是 10 秒。

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

设置值，例如这里设置为 5 秒：

 mysql> set global long_query_time=5; 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.01 sec)

如上所示，修改了变量longquerytime，但是查询变量longquerytime的值还是10。

使用命令 set global longquerytime=5修改后，需要重新连接或新开一个会话才能看到修改值。因为通过用show variables like 'longquerytime'查看是当前会话的变量值。

也可以不用重新连接会话，而是用 show global variables like 'longquerytime'; 如下所示：

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

我们设置longquerytime的值为2：

 mysql> set global long_query_time=2; Query OK, 0 rows affected (0.00 sec) mysql> show global variables like 'long_query_time'; +-----------------+----------+ | Variable_name | Value | +-----------------+----------+ | long_query_time | 2.000000 | +-----------------+----------+ 1 row in set (0.00 sec)

然后执行一条超时5秒的语句（需要重新连接MySQL）：

 [root@mysql ~]# mysql -u root -p Enter password: Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 4 Server version: 5.7.21-log MySQL Community Server (GPL) Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> show variables like 'long_query_time'; +-----------------+----------+ | Variable_name | Value | +-----------------+----------+ | long_query_time | 2.000000 | +-----------------+----------+ 1 row in set (0.02 sec) mysql> select sleep(5) -> ; +----------+ | sleep(5) | +----------+ | 0 | +----------+ 1 row in set (5.01 sec)

然后查看慢日志可以看到类似信息：

 [root@mysql ~]# cat /var/lib/mysql/mysql-slow.log /usr/sbin/mysqld, Version: 5.7.21 (MySQL Community Server (GPL)). started with: Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock Time Id Command Argument /usr/sbin/mysqld, Version: 5.7.21-log (MySQL Community Server (GPL)). started with: Tcp port: 0 Unix socket: /var/lib/mysql/mysql.sock Time Id Command Argument # Time: 2018-02-09T06:59:47.782111Z # User@Host: root[root] @ localhost [] Id: 4 # Query_time: 5.000252 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1518159587; select sleep(5);

logoutput 参数是指定日志的存储方式。logoutput='FILE'表示将日志存入文件，默认值是'FILE'。log_output='TABLE'表示将日志存入数据库，这样日志信息就会被写入到mysql.slowlog表中。MySQL数据库支持同时两种日志存储方式，配置的时候以逗号隔开即可，如：logoutput='FILE,TABLE'。日志记录到系统的专用日志表中，要比记录到文件耗费更多的系统资源，因此对于需要启用慢查询日志，又需要能够获得更高的系统性能，那么建议优先记录到文件。

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

设置为表：

 mysql> set global log_output='TABLE'; Query OK, 0 rows affected (0.00 sec) mysql> show variables like '%log_output%'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | log_output | TABLE | +---------------+-------+ 1 row in set (0.00 sec) mysql> select sleep(5); +----------+ | sleep(5) | +----------+ | 0 | +----------+ 1 row in set (5.00 sec)

执行 select * from mysql.slowlog; 观察慢查询日志里每类语句的输出，其中querytime表示query语句的执行时间，单位是为秒，lock time是锁定的时间，rowssent是query语句执行返回的记录数，而rowsexamined则是优化器估算的扫描行数，querytime、rowsexamined、rowssent 三个值可以大致衡量一条查询的成本，特别留意 rowsexamined 字段是否与预期一致。

系统变量log-queries-not-using-indexes：未使用索引的查询也被记录到慢查询日志中（可选项）。如果调优的话，建议开启这个选项。另外，开启了这个参数，其实使用full index scan的sql也会被记录到慢查询日志。

 mysql> show variables like 'log_queries_not_using_indexes'; +-------------------------------+-------+ | Variable_name | Value | +-------------------------------+-------+ | log_queries_not_using_indexes | OFF | +-------------------------------+-------+ 1 row in set (0.00 sec) mysql> set global log_queries_not_using_indexes=1; Query OK, 0 rows affected (0.00 sec) mysql> show variables like 'log_queries_not_using_indexes'; +-------------------------------+-------+ | Variable_name | Value | +-------------------------------+-------+ | log_queries_not_using_indexes | ON | +-------------------------------+-------+ 1 row in set (0.00 sec) mysql>

系统变量logslowadmin_statements表示是否将慢管理语句例如ANALYZE TABLE和ALTER TABLE等记入慢查询日志：

 mysql> show variables like 'log_slow_admin_statements'; +---------------------------+-------+ | Variable_name | Value | +---------------------------+-------+ | log_slow_admin_statements | OFF | +---------------------------+-------+ 1 row in set (0.00 sec) mysql> mysql> set global log_slow_admin_statements=1; Query OK, 0 rows affected (0.01 sec) mysql> show variables like 'log_slow_admin_statements'; +---------------------------+-------+ | Variable_name | Value | +---------------------------+-------+ | log_slow_admin_statements | ON | +---------------------------+-------+ 1 row in set (0.00 sec)

查询有多少条慢日志，可以使用系统变量：

 mysql> show global status like '%slow_queries%'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | Slow_queries | 2 | +---------------+-------+ 1 row in set (0.01 sec)

日志分析工具mysqldumpslow

MySQL 自带了一个查看慢日志的工具 mysqldumpslow，执行mysqldumpslow --help 可以查看其相关参数和说明：

 [root@mysql ~]# 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:是表示按照何种方式排序；c: 访问计数；l: 锁定时间；r: 返回记录；t: 查询时间；al:平均锁定时间；ar:平均返回记录数；at:平均查询时间；-t:是top n的意思，即为返回前面多少条的数据；-g:后边可以写一个正则匹配模式，大小写不敏感的。

例如，得到返回记录集最多的10个SQL：

 mysqldumpslow -s r -t 10 /mysql/mysql_slow.log

得到访问次数最多的10个SQL：

 mysqldumpslow -s c -t 10 /mysql/mysql_slow.log

通过以上方式我们可以配置和发现慢 SQL，那么在发现慢 SQL 语句之后，我们可以通过对数据库进行优化来提升 SQL 的执行速度，比如加索引或修改该应用的实现方式等。