mysql之慢查询详解，mysqldumpslow的使用

mahan

1. mysql中的慢查询是我们分析问题，定位问题的利器，巧妙使用可以快速解决问题

2. 原理：运行时间超过 long_query_time 的sql语句会被写入到慢查询日志文件中或者mysql.slow_log表中，long_query_time的默认值是10s

3. 还可以使用慢日志分析工具 mysqldumpslow 来进行分析慢查询

相关参数

slow_query_log    ：是否开启慢查询日志，1表示开启，0表示关闭。

log-slow-queries  ：旧版（5.6以下版本）MySQL数据库慢查询日志存储路径。可以不设置该参数，系统则会默认给一个缺省的文件host_name-slow.log

slow-query-log-file：新版（5.6及以上版本）MySQL数据库慢查询日志存储路径。可以不设置该参数，系统则会默认给一个缺省的文件host_name-slow.log

long_query_time ：慢查询阈值，当查询时间多于设定的该值时，则写入日志。注意该值修改后再次查询显示的还是旧值，要使用 show global variables like 'long_query_time'; 这样的语句查询才更新

log_queries_not_using_indexes：未使用索引的查询也被记录到慢查询日志中（可选项）。

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

演示步骤

1. 查询慢查询是否开启，慢查询的阈值，慢查询日志文件的路径

mysql> show global variables like '%query%';
+------------------------------+----------------------------------+
| Variable_name                | Value                            |
+------------------------------+----------------------------------+
| binlog_rows_query_log_events | OFF                              |
| ft_query_expansion_limit     | 20                               |
| have_query_cache             | NO                               |
| long_query_time              | 10.000000                        |
| query_alloc_block_size       | 8192                             |
| query_prealloc_size          | 8192                             |
| slow_query_log               | OFF                              |
| slow_query_log_file          | /var/lib/mysql/kickseed-slow.log |
+------------------------------+----------------------------------+
8 rows in set (0.00 sec)


long_query_time： 10.000000 表慢查询的阈值是10s,可以精确到0.000001秒，也就是1微秒。关于运行时间正好等于long_query_time的情况，并不会被记录下来。也就是说，在mysql源码里是判断大于long_query_time，而非大于等于

slow_query_log：OFF 表慢查询未开启

slow_query_log_file：slow_query_log_file 表慢查询日志文件的位置

2. 打开慢查询开关，修改慢查询的阈值

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

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

mysql> show global variables like '%query%';
+------------------------------+----------------------------------+
| Variable_name                | Value                            |
+------------------------------+----------------------------------+
| binlog_rows_query_log_events | OFF                              |
| ft_query_expansion_limit     | 20                               |
| have_query_cache             | NO                               |
| long_query_time              | 1.000000                         |
| query_alloc_block_size       | 8192                             |
| query_prealloc_size          | 8192                             |
| slow_query_log               | ON                               |
| slow_query_log_file          | /var/lib/mysql/kickseed-slow.log |
+------------------------------+----------------------------------+
8 rows in set (0.00 sec)

long_query_time： 1.000000 表慢查询的阈值是1.0秒,运行时间超过1秒的sql语句会被写入到慢日志文件

slow_query_log：ON 表慢查询已开启

谨记：

1) : 修改long_query_time后再查询不能使用 “show variables like '%query%';”来进行查询，这样查询还是旧的，必须要在前面添加global才能查到最新的 long_query_time 值。当然也可以断开这个连接，重新连接进来再查询不使用global也行

2) : 而且修改long_query_time后，执行sql语句的连接必须断开后再次连接mysql，设置的阈值才能起效

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

3. 测试慢sql语句，查看慢日志

mysql> select sleep(2);
+----------+
| sleep(2) |
+----------+
|        0 |
+----------+
1 row in set (2.01 sec)
select sleep(2);表执行暂停2秒的sql语句

然后我们打开慢日志文件，也就是slow_query_log_file的值，即/var/lib/mysql/kickseed-slow.log文件，跳转到最后可以看到如下内容

# Time: 2021-02-23T11:38:25.222093Z
# User@Host: root[root] @ localhost [127.0.0.1]  Id:    19
# Query_time: 2.000681  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1614080303;
select sleep(2);
Time:Time: 2021-02-23T11:38:25.222093Z 表该条慢sql执行的时间点

User@Host: root[root] @ localhost [127.0.0.1]  Id: 19 表该条慢sql的连接账号为root，IP地址为127.0.0.1，Id表连接ID，每次连接该ID加1

Query_time: 2.000681  表执行该sql的总时间为2.000681秒

Lock_time: 0.000000  表锁表时间

Rows_sent: 1 表发送sql结果的行数，只有1行

Rows_examined: 1 表执行该sql语句检查数据库的行数

4. 系统变量 log_output， log-queries-not-using-indexes， log_slow_admin_statements的作用

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

mysql> show variables like '%log_output%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.01 sec)
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.01 sec)
log_slow_admin_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.01 sec)
5. 日志分析工具mysqldumpslow，mysql官方自带的，只要安装了mysql就可以使用它，可以用来帮助我们分析慢日志文件

在生产环境中，如果要手工分析日志文件，查找、分析SQL，显然是个体力活，MySQL提供了日志分析工具mysqldumpslow，如下

root@kickseed:/home# 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语句（行数最多排序需要 -s r ；限制10条需要 -t 10）

mysqldumpslow -s r -t 10 /database/mysql/mysql06_slow.log

得到访问次数最多的10个SQL（访问次数最多排序需要 -s c ；限制10条需要 -t 10）

mysqldumpslow -s c -t 10 /database/mysql/mysql06_slow.log

得到按照执行时间排序的前10条，且sql语句里面含有左连接的查询语句（执行时间排序需要 -s t；限制10条需要 -t 10）

mysqldumpslow -s t -t 10 -g “left join” /database/mysql/mysql06_slow.log

另外建议在使用这些命令时结合 | 和more 使用 ，否则有可能出现刷屏的情况。

mysqldumpslow -s r -t 20 /mysqldata/mysql/mysql06-slow.log | more

笔者以自己的慢日志为例，做一次查询

mysqldumpslow -s t -t 5 kickseed-slow.log 表我要分析kickseed-slow.log文件，该文件是mysql的慢日志文件，得到按照执行时间，从大到小排序，最多5条sql语句

root@kickseed:/var/lib/mysql# mysqldumpslow -s t -t 5 kickseed-slow.log

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

Count: 3  Time=0.21s (0s)  Lock=0.00s (0s)  Rows=25.0 (75), root[root]@[192.168.54.28]
  SHOW TABLE STATUS FROM `hyj_player`

Count: 1  Time=0.21s (0s)  Lock=0.00s (0s)  Rows=23211.0 (23211), root[root]@[192.168.54.28]
  SELECT * FROM `hyj_player`.`t_player_basic_data` LIMIT N, N

Count: 1  Time=0.20s (0s)  Lock=0.00s (0s)  Rows=24211.0 (24211), root[root]@[192.168.54.28]
  SELECT * FROM t_player_basic_data

Count: 4  Time=0.02s (0s)  Lock=0.00s (0s)  Rows=1.0 (4), root[root]@[192.168.54.28]
  SELECT COUNT(*) FROM t_player_basic_data WHERE playerID < N

从返回的结果中可以看到，从最大耗时的2秒，到最小耗时的0.02秒，一共5条记录