MySQL优化之慢查询日志

慢查询日志概述

所谓慢查询日志，就是用于记录mysql中响应时间超过设定阈值的sql语句，通过打开慢查询开关，mysql会将大于阈值的sql记录在日志中，以便于分析性能。

慢查询日志选项默认是关闭的，如果要开启，则需要手动设置。
慢查询日志选项不建议一直开启，因为记录日志意味着io操作，本身对性能有一定的影响，因此，建议在生产环境关闭该选项；而在开发环境调优阶段可以适当打开该选项。
检查是否开启了慢查询日志：

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| variable_name       | value                                   |
+---------------------+-----------------------------------------+
| slow_query_log      | off                                     |
| slow_query_log_file | /var/lib/mysql/desktop-q5j25hr-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.03 sec)

slow_query_log选项即开启慢查询的开关，off为关闭，on为开启。
slow_query_log_file即慢查询日志的名称。

如果要开启慢查询日志，则执行如下语句：

set global slow_query_log = on;
/* 或者 */
set global slow_query_log = 1;

以上两句话是一个意思，执行任意一条都可以。执行完毕，再次查询，已经打开。

mysql> set global slow_query_log = on;
query ok, 0 rows affected (0.05 sec)

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| variable_name       | value                                   |
+---------------------+-----------------------------------------+
| slow_query_log      | on                                      |
| slow_query_log_file | /var/lib/mysql/desktop-q5j25hr-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.00 sec)

同样的，慢查询日志的文件名也可以重新指定，只需要设置set global slow_query_log_file = 文件名即可。

前面说过，慢查询日志只有当sql语句响应时间超过一定阈值才会记录在日志中，那么这个阈值是多少，该如何设置呢？
可通过以下命令查看慢查询日志的阈值：

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

可以看到，默认的阈值是10秒，该值同样可以通过设置来修改，如设置为0.1秒：

set global long_query_time = 0.1;

long_query_time设置完成后，需要退出mysql客户端，重新登录后才生效，于是可以看到该值已经变成了0.1：

mysql> show variables like '%long_query_time%';
+-----------------+----------+
| variable_name   | value    |
+-----------------+----------+
| long_query_time | 0.100000 |
+-----------------+----------+
1 row in set (0.01 sec)

慢查询日志具体案例

接下来通过案例的方式来演示慢查询日志：
我在当前数据库里有一张test01表，表结构如下所示：

mysql> desc test01;
+--------+-------------+------+-----+---------+-------+
| field  | type        | null | key | default | extra |
+--------+-------------+------+-----+---------+-------+
| id     | int(4)      | yes  | mul | null    |       |
| name   | varchar(20) | yes  |     | null    |       |
| passwd | char(20)    | yes  |     | null    |       |
| inf    | char(50)    | yes  |     | null    |       |
+--------+-------------+------+-----+---------+-------+
4 rows in set (0.04 sec)

分别做如下查询：

select * from test01;
select sleep(1);
select id, sleep(2) from test01;

执行结果如下所示：

mysql> select * from test01;
+------+------+--------+--------+
| id   | name | passwd | inf    |
+------+------+--------+--------+
|    1 | zz   | 123456 | asdfgh |
+------+------+--------+--------+
1 row in set (0.00 sec)

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

mysql> select id, sleep(2) from test01;
+------+----------+
| id   | sleep(2) |
+------+----------+
|    1 |        0 |
+------+----------+
1 row in set (2.00 sec)

此时并需要去不关心sql本身，而是看这三条sql执行的时间，从上面可以看到，第一条sql执行几乎不耗时间，显示0.00 sec，第二条sql显示时间为 1.00 sec，第三条sql为 2.00 sec。
因为我们设置了阈值为0.1秒，因此后两条sql应该都要记录在慢查询日志中，接下来验证是否如此：
通过如下命令，可查看慢查询sql的条数：

mysql> show global status like '%slow_queries%';
+---------------+-------+
| variable_name | value |
+---------------+-------+
| slow_queries  | 2     |
+---------------+-------+
1 row in set (0.02 sec)

显示记录为2条，与实际情况一致。
通过show variables like '%slow_query_log%'命令，可以查看到日志的具体路径。

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------+
| variable_name       | value                                   |
+---------------------+-----------------------------------------+
| slow_query_log      | on                                      |
| slow_query_log_file | /var/lib/mysql/desktop-q5j25hr-slow.log |
+---------------------+-----------------------------------------+
2 rows in set (0.00 sec)

打开/var/lib/mysql/desktop-q5j25hr-slow.log，可以看到日志当中记录了时间超过阈值的那两条sql语句：

/usr/sbin/mysqld, version: 5.7.29-0ubuntu0.18.04.1 ((ubuntu)). started with:
tcp port: 3306  unix socket: /var/run/mysqld/mysqld.sock
time                 id command    argument
/usr/sbin/mysqld, version: 5.7.29-0ubuntu0.18.04.1 ((ubuntu)). started with:
tcp port: 3306  unix socket: /var/run/mysqld/mysqld.sock
time                 id command    argument
# time: 2020-03-31t13:41:25.726554z
# user@host: root[root] @ localhost []  id:     6
# query_time: 1.000644  lock_time: 0.000000 rows_sent: 1  rows_examined: 0
use testdb;
set timestamp=1585662085;
select sleep(1);
# time: 2020-03-31t13:41:34.246770z
# user@host: root[root] @ localhost []  id:     6
# query_time: 2.000536  lock_time: 0.000057 rows_sent: 1  rows_examined: 1
set timestamp=1585662094;
select id, sleep(2) from test01;

mysqldumpslow工具

以上介绍的方法虽然可以查看出所有慢sql语句，但显然都记录在一个日志文件里，会显得很乱，而且一旦sql比较多，定位起来还是比较麻烦的。
好在mysql本身提供了一个专门用来查看慢查询日志的工具，即mysqldumpslow。
可通过mysqldumpslow -help查看具体使用方法：

chenyc@desktop-q5j25hr:~$ 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

从以上文件中，可以知道，该工具用法如下：

mysqldumpslow [选项] [日志名]

常用选项说明：

• -s 即order排序,后面可以有以下选项：
  • al 平均锁定时间
  • ar 平均返回记录时间
  • at 平均查询时间
  • c 计数
  • l 锁定时间
  • r 逆序排序
  • t 查询时间
• -t，相当于top n，即返回前面n条语句
• -g， 匹配正则表达式，大小写不敏感
  如：

sudo mysqldumpslow -s r -t 3 -g 'select' /var/lib/mysql/desktop-q5j25hr-slow.log

以上命令表示：返回按逆序排序的其中三条语句，且语句中包含select的sql语句。
结果如下所示：

chenyc@desktop-q5j25hr:~$ sudo mysqldumpslow -s r -t 3 -g 'select' /var/lib/mysql/desktop-q5j25hr-slow.log

reading mysql slow query log from /var/lib/mysql/desktop-q5j25hr-slow.log
count: 1  time=2.00s (2s)  lock=0.00s (0s)  rows=1.0 (1), root[root]@localhost
  select id, sleep(n) from test01

count: 1  time=1.00s (1s)  lock=0.00s (0s)  rows=1.0 (1), root[root]@localhost
  select sleep(n)

died at /usr/bin/mysqldumpslow line 167, <> chunk 2.

profiles工具

profiles最大的作用是用来分析海量数据，该命令会记录所有执行过的sql语句。
这个选项默认也是关闭的，需要手动打开。
查询profiles选项命令：

mysql> show variables like '%profiling%';
+------------------------+-------+
| variable_name          | value |
+------------------------+-------+
| have_profiling         | yes   |
| profiling              | off   |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.01 sec)

打开命令：

mysql> set profiling = on;
query ok, 0 rows affected, 1 warning (0.00 sec)

再次查看，可以换一种方式查看：

mysql> select @@profiling;
+-------------+
| @@profiling |
+-------------+
|           1 |
+-------------+
1 row in set, 1 warning (0.00 sec)

以上选项，1代表打开，0代表关闭。
为了更为直观的查看profile，我们再执行两条sql：

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

mysql> select * from test01;
+------+------+--------+--------+
| id   | name | passwd | inf    |
+------+------+--------+--------+
|    1 | zz   | 123456 | asdfgh |
+------+------+--------+--------+
1 row in set (0.00 sec)

好了，准备工作就到这里，现在来查看profile：

mysql> show profiles;
+----------+------------+-----------------------------------+
| query_id | duration   | query                             |
+----------+------------+-----------------------------------+
|        1 | 0.00214400 | show variables like '%profiling%' |
|        2 | 0.00017400 | select @@profiling                |
|        3 | 3.00062925 | select sleep(3)                   |
|        4 | 0.00023450 | select * from test01              |
+----------+------------+-----------------------------------+
4 rows in set, 1 warning (0.00 sec)

如上所示，它会记录所有的语句，其中第二列duration代表的是执行时间。
以上虽然可以看到每条sql的执行时间，但我们无法精确知道有多少时间花费在io上，多少时间花费在cpu上，因此，还可使用以下语句查看更为精确的内容：

show profile all for query $(query_id);

上面的query_id即show profiles结果中第一列的id编号。如：

mysql> show profile all for query 4;
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| status               | duration | cpu_user | cpu_system | context_voluntary | context_involuntary | block_ops_in | block_ops_out | messages_sent | messages_received | page_faults_major | page_faults_minor | swaps | source_function       | source_file
    | source_line |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+
| starting             | 0.000045 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | null                  | null
    |        null |
| checking permissions | 0.000008 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | check_access          | sql_authorization.cc |         809 |
| opening tables       | 0.000020 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables           | sql_base.cc
    |        5781 |
| init                 | 0.000017 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | handle_query          | sql_select.cc
    |         128 |
| system lock          | 0.000016 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 2 |     0 | mysql_lock_tables     | lock.cc
    |         330 |
| optimizing           | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc
    |         158 |
| statistics           | 0.000014 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc
    |         374 |
| preparing            | 0.000010 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | optimize              | sql_optimizer.cc
    |         482 |
| executing            | 0.000004 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | exec                  | sql_executor.cc
    |         126 |
| sending data         | 0.000051 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 8 |     0 | exec                  | sql_executor.cc
    |         202 |
| end                  | 0.000005 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | handle_query          | sql_select.cc
    |         206 |
| query end            | 0.000007 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc
    |        4956 |
| closing tables       | 0.000007 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command | sql_parse.cc
    |        5009 |
| freeing items        | 0.000013 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse           | sql_parse.cc
    |        5622 |
| cleaning up          | 0.000013 | 0.000000 |   0.000000 |                 0 |                   0 |            0 |
0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command      | sql_parse.cc
    |        1931 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+-------------
--+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------
----+-------------+
15 rows in set, 1 warning (0.00 sec)

上面的结果由于选项太多，看起来还是有些乱，其实很多东西我们并不关注，而主要只关注cpu和io情况，因此，可以进一步简化如下：

mysql> show profile cpu, block io for query 4;
+----------------------+----------+----------+------------+--------------+---------------+
| status               | duration | cpu_user | cpu_system | block_ops_in | block_ops_out |
+----------------------+----------+----------+------------+--------------+---------------+
| starting             | 0.000045 | 0.000000 |   0.000000 |            0 |             0 |
| checking permissions | 0.000008 | 0.000000 |   0.000000 |            0 |             0 |
| opening tables       | 0.000020 | 0.000000 |   0.000000 |            0 |             0 |
| init                 | 0.000017 | 0.000000 |   0.000000 |            0 |             0 |
| system lock          | 0.000016 | 0.000000 |   0.000000 |            0 |             0 |
| optimizing           | 0.000005 | 0.000000 |   0.000000 |            0 |             0 |
| statistics           | 0.000014 | 0.000000 |   0.000000 |            0 |             0 |
| preparing            | 0.000010 | 0.000000 |   0.000000 |            0 |             0 |
| executing            | 0.000004 | 0.000000 |   0.000000 |            0 |             0 |
| sending data         | 0.000051 | 0.000000 |   0.000000 |            0 |             0 |
| end                  | 0.000005 | 0.000000 |   0.000000 |            0 |             0 |
| query end            | 0.000007 | 0.000000 |   0.000000 |            0 |             0 |
| closing tables       | 0.000007 | 0.000000 |   0.000000 |            0 |             0 |
| freeing items        | 0.000013 | 0.000000 |   0.000000 |            0 |             0 |
| cleaning up          | 0.000013 | 0.000000 |   0.000000 |            0 |             0 |
+----------------------+----------+----------+------------+--------------+---------------+
15 rows in set, 1 warning (0.00 sec)

全局查询日志

同profiles一样，打开全局查询日志选项以后，它会记录下所有sql语句，但是由于该操作比较耗费性能，因此，只建议在开发环境临时打开该选项。
查看全局查询日志命令：

mysql> show variables like '%general_log%';
+------------------+------------------------------------+
| variable_name    | value                              |
+------------------+------------------------------------+
| general_log      | off                                |
| general_log_file | /var/lib/mysql/desktop-q5j25hr.log |
+------------------+------------------------------------+
2 rows in set (0.01 sec)

打开全局查询日志选项：

set global general_log = on;

再次查询：

mysql> show variables like '%general_log%';
+------------------+------------------------------------+
| variable_name    | value                              |
+------------------+------------------------------------+
| general_log      | on                                 |
| general_log_file | /var/lib/mysql/desktop-q5j25hr.log |
+------------------+------------------------------------+
2 rows in set (0.00 sec)

设置完以上之后，还需要做如下设置：

set global log_output = 'table';

同样的，准备以下sql：

select * from test01;
select id, name from test01 where id = 1;

全局查询日志记录在mysql.general_log表中。

mysql> select * from mysql.general_log;
+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+
| event_time                 | user_host                 | thread_id | server_id | command_type | argument
          |
+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+
| 2020-03-31 22:31:24.750895 | root[root] @ localhost [] |         6 |         0 | query        | select * from test01
          |
| 2020-03-31 22:31:26.128924 | root[root] @ localhost [] |         6 |         0 | query        | select id, name from test01 whe
re id = 1 |
| 2020-03-31 22:32:15.736558 | root[root] @ localhost [] |         6 |         0 | query        | select * from mysql.general_log
          |
+----------------------------+---------------------------+-----------+-----------+--------------+--------------------------------
----------+
3 rows in set (0.01 sec)

既然有记录到表中，自然也有记录到文件中，只需要做如下设置：

set global general_log_file = '/tmp/mysql_general.log';		--设置文件路径
set global log_output = 'file';	--设置记录到文件

可通过如下命令查看文件路径：

mysql> show variables like '%general_log%';
+------------------+------------------------+
| variable_name    | value                  |
+------------------+------------------------+
| general_log      | on                     |
| general_log_file | /tmp/mysql_general.log |
+------------------+------------------------+
2 rows in set (0.00 sec)

同样执行以上两条sql：

select * from test01;
select id, name from test01 where id = 1;

查看文件内容，得到如下结果：

chenyc@desktop-q5j25hr:~$ sudo cat /tmp/mysql_general.log
/usr/sbin/mysqld, version: 5.7.29-0ubuntu0.18.04.1 ((ubuntu)). started with:
tcp port: 3306  unix socket: /var/run/mysqld/mysqld.sock
time                 id command    argument
2020-03-31t14:35:49.793176z         6 query     show variables like '%general_log%'
2020-03-31t14:37:20.241374z         6 query     select * from test01
2020-03-31t14:37:21.408617z         6 query     select id, name from test01 where id = 1