mysql慢查询：pt-query-digest 分析

"某些SQL语句执行效率慢"，这个问题总体上分为两类：

1. 出现了慢查询语句
2. 某些查询语句没有使用索引

由于数据的写入量非常大，所以要想直接打开慢查询日志来查看到底哪些语句有问题几乎是不可能的，因为日志的刷新速度太快了，于是想起了pt工具，pt工具中的pt-query-digest比较擅长解决这个问题。

子曰：“工欲善其事，必先利其器”

善于利用好的性能分析工具可以使运维效率事半功倍。
pt-query-digest 属于 Percona Toolkit 工具集中较为常用的工具，用于分析 slow log，可以分析 MySQL 数据库的 binary log 、 general log 日志，同时也可以使用 show processlist 或从 tcpdump 抓取的 MySQL 协议数据来进行分析。

# wget https://www.percona.com/downloads/percona-toolkit/3.2.1/binary/redhat/7/x86_64/percona-toolkit-3.2.1-1.el7.x86_64.rpm
# yum -y localinstall percona-toolkit-3.2.1-1.el7.x86_64.rpm

根据时间点，这里我们用alert_time来表示，那么导致报警的SQL很有可能在这个时间点附近。
这里用到Linux中的sed命令来把日志先截取出来，sed命令的使用方法如下：

sed -n '/2019-02-27T01:55:04/,/2019-02-27T02:02:04/p'     /path/to/mysql-slow.log  > mysql-slow.log.tmp

这个命令将格林尼治时间01:55:04到02:05:04的慢日志打印出来，重定向到一个mysql-slow.log.tmp的文件中，需要注意的是格林尼治时间加上8小时就是北京时间。

发现这个mysql-slow.log.tmp也比较大，所以我又重新把时间定格在60s之内，这样得到了一个比较小的tmp文件，这个时候，就该pt工具上场了。

如果不想用sed命令，其实pt工具本身也自带一些参数，可以通过--since参数和 --until参数来把日志中固定时间段的日志打印出来：

pt-query-digest  --since='2019-02-27 09:30:00'   --until=2019-02-27 09:31:00'   /path/to/mysql-slow.log  >  mysql-slow.log.tmp

用pt工具分析慢日志的结果如下，总体分为三个部分。

第一部分是总体统计结果，如下：

该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小
# 480ms user time, 10ms system time, 26.18M rss, 206.09M vsz
工具执行时间
# Current date: Wed Feb 27 10:51:36 2019
主机名
# Hostname: 
被分析的文件名
# Files: yyz.tmp
语句总数量，唯一的语句数量，QPS，并发数
# Overall: 1.00k total, 32 unique, 8.45 QPS, 0.02x concurrency ___________
日志记录的时间范围
# Time range: 2019-02-27T02:34:04 to 2019-02-27T02:36:03
属性                  总计      最小     最大     平均    95%  标准     中等
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
语句执行时间
# Exec time             2s    97us   515ms     2ms     5ms    21ms   799us
锁占用时间
# Lock time           85ms    32us   448us    84us   131us    32us    80us
发送到客户端的行数
# Rows sent        237.45k       0   2.36k  241.93   1.96k  551.62       0
select语句扫描的行数
# Rows examine       3.53M       0 536.64k   3.60k   4.07k  33.64k  685.39
发送改变的行数(update,delete,insert)语句
# Rows affecte           0       0       0       0       0       0       0
发送多少bytes的查询结果集
# Bytes sent        65.63M       0   1.31M  66.87k 753.18k 221.17k  346.17
查询语句的字符数
# Query size       107.70k      56     303  109.74  223.14   48.96   92.72

第二部分是查询分组的统计结果，包含了一些花费时间比较长的SQL语句，如下：

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0xCB9AD73BDFEDCAD9  0.9584 42.9%     2 0.4792  0.01 UPDATE SELECT dic_push_dao_assistant tem_selectAssDAO
#    2 0x2AEA2001E6ED5A86  0.3696 16.5%   288 0.0013  0.00 SELECT dic_alert_alarm_msg
#    3 0xE2874B8D2170C494  0.2174  9.7%    18 0.0121  0.00 SELECT dic_fsm_cccd_info
#    4 0xEB9DC21456584EF6  0.0919  4.1%    18 0.0051  0.00 SELECT dic_fsm_info
#    5 0xF3A68A619C5E8B35  0.0906  4.1%    18 0.0050  0.00 SELECT dic_fsm_info
#    6 0x5C1B79C191BDA497  0.0725  3.2%   118 0.0006  0.00 SELECT original_dic_fsm_info
#    7 0x5DB1B21F7EEC9EF4  0.0597  2.7%    18 0.0033  0.00 SELECT dic_fsm_config_info
#    8 0xA88FE251DC1A981A  0.0584  2.6%    18 0.0032  0.00 SELECT dic_fsm_config_info
#    9 0x69E716E15CCC4A0F  0.0539  2.4%   118 0.0005  0.00 SELECT original_dic_fsm_config_info
#   10 0x0A6FC9E2C8542E17  0.0476  2.1%    18 0.0026  0.00 SELECT dic_cal_expression
#   11 0x7C0C6F0CFBADF271  0.0427  1.9%    19 0.0022  0.00 SELECT dic_cal_expression
#   12 0x872EBAFA1A73057B  0.0311  1.4%    19 0.0016  0.00 SELECT dic_guide_list_info
#   13 0xE73D713D87E945FC  0.0232  1.0%   102 0.0002  0.00 SELECT dic_alert_refresh
#   14 0x194B14BA91941B81  0.0204  0.9%    18 0.0011  0.00 SELECT dic_fsm_map_relation
# MISC 0xMISC              0.0960  4.3%   213 0.0005   0.0 <18 ITEMS>

Rank：所有语句的排名，默认按查询时间降序排列Query ID：语句的IDResponse：总的响应时间time：该查询在本次分析中总的时间占比calls：执行次数，即本次分析总共有多少条这种类型的查询语句R/Call：平均每次执行的响应时间V/M：响应时间Variance-to-mean的比率

可以看到，有一些语句一秒钟之内call了大概288次，并发量算是比较高了。
还有第一行的update语句大概占用了将近一半的运行时间，但是我们可以看到，这个响应时间是很短的，几乎都在1s之内，按道理不会出现在慢查询日志上面。
之所以这些执行时间在1s之内的SQL语句会出现在慢查询日志上面，是因为MySQL中开启了一个参数，如下：

 1 mysql> show variables like '%index%';2+----------------------------------------+--------------------------------------------+3| Variable_name                          | Value                                      |4+----------------------------------------+--------------------------------------------+5| eq_range_index_dive_limit              | 200                                        |6| expand_fast_index_creation             | OFF                                        |7| innodb_adaptive_hash_index             | ON                                         |8| innodb_adaptive_hash_index_parts       | 8                                          |9| innodb_cmp_per_index_enabled           | OFF                                        |
10| log_bin_index                          | /path/to/mysqlbin.index  |
11| log_queries_not_using_indexes          | ON                                         |
12| log_throttle_queries_not_using_indexes | 0                                          |
13| performance_schema_max_index_stat      | -1                                         |
14| relay_log_index                        | /path/to/slave-relay-bin.index |
15+----------------------------------------+--------------------------------------------+
1610 rows in set (0.00 sec)

也就是第11行的log_queries_not_using_indexes参数，这个参数开启的话，MySQL会默认将没有使用index的SQL语句也记录在慢日志中，如果数据量比较小的话，这些SQL语句看着没什么大的问题，一旦表中的数据变的很大的时候，这些SQL极有可能出现性能问题。

第三部分是第二部分查出来的每一个SQL语句的详细统计结果。如下：

 1# Query 1: 0.03 QPS, 0.02x concurrency, ID 0xCB9AD73BDFEDCAD9 at byte 604302# This item is included in the report because it matches --limit.3# Scores: V/M = 0.014# Time range: 2019-02-27T02:34:32 to 2019-02-27T02:35:325# Attribute    pct   total     min     max     avg     95%  stddev  median6# ============ === ======= ======= ======= ======= ======= ======= =======7# Count          0       28# Exec time     42   958ms   443ms   515ms   479ms   515ms    51ms   479ms9# Lock time      0   254us   116us   138us   127us   138us    15us   127us
10# Rows sent      0       0       0       0       0       0       0       0
11# Rows examine  29   1.05M 536.64k 536.64k 536.64k 536.64k       0 536.64k
12# Rows affecte   0       0       0       0       0       0       0       0
13# Bytes sent     0       0       0       0       0       0       0       0
14# Query size     0     252     126     126     126     126       0     126
15# String:
16# Databases    tgp_db
17# Hosts        127.0.0.1
18# Last errno   0
19# Stored routi tgp_db.PCall_TGP_GetAssDAO
20# Users        dba_admin
21# Query_time distribution
22#   1us
23#  10us
24# 100us
25#   1ms
26#  10ms
27# 100ms  ################################################################
28#    1s
29#  10s+
30# Tables
31#    SHOW TABLE STATUS FROM `tgp_db` LIKE 'dic_push_dao_assistant'\G
32#    SHOW CREATE TABLE `tgp_db`.`dic_push_dao_assistant`\G
33#    SHOW TABLE STATUS FROM `tgp_db` LIKE 'tem_selectAssDAO'\G
34#    SHOW CREATE TABLE `tgp_db`.`tem_selectAssDAO`\G
35update `dic_push_dao_assistant`
36    set `state` = 1
37    where `id` in 
38    (
39select `id`
40        from `tem_selectAssDAO`
41    )\G
42# Converted for EXPLAIN
43# EXPLAIN /*!50100 PARTITIONS*/
44select  `state` = 1 from `dic_push_dao_assistant` where  `id` in 
45    (
46select `id`
47        from `tem_selectAssDAO`
48    )\G

这里给出的每一个语句执行的时候的一些信息，最上面的表格列出了执行次数、最大、最小、平均、95%等各项目的统计。

ID：查询的ID号，和上图的Query ID对应Databases：数据库名Users：各个用户执行的次数（占比）Query_time distribution ：查询时间分布, 长短体现区间占比，本例中1s-10s之间查询数量是10s以上的两倍。Tables：查询中涉及到的表

通过上面的SQL语句分析，可以看出查询的时候是把update操作转化成了select操作，然后这个select操作里面扫描了tem_selectAssDAO全表，所以导致SQL的执行时间比较长，如果表中的数据量很大的话，这无疑是一个慢SQL。

pt-query-digest常用方法：

1.直接分析慢查询文件:
pt-query-digest slow.log > slow_report.log2.分析最近12小时内的查询：
pt-query-digest  --since=12h   slow.log > slow_report2.log3.分析指定时间范围内的查询：
pt-query-digest slow.log  --since '2017-01-07 09:30:00'   --until '2017-01-07 10:00:00' > slow_report3.log4.分析指含有select语句的慢查询
pt-query-digest  --filter   '$event->{fingerprint} =~ m/^select/i'   slow.log  > slow_report4.log5针对某个用户的慢查询
pt-query-digest --filter '($event->{user} || "") =~ m/^root/i'  slow.log > slow_report5.log6.查询所有全表扫描或full join的慢查询
pt-query-digest  --filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' slow.log  > slow_report6.log7.把查询保存到query_review表pt-query-digest  --user=root  -password=abc123  --review h=localhost,D=test,t=query_review  --create-review-table  slow.log8.分析binlog
mysqlbinlog mysql-bin.000093    > mysql-bin000093.sql
pt-query-digest   --type=binlog  mysql-bin000093.sql  >  slow_report10.log9.分析general log
pt-query-digest  --type=genlog  localhost.log  > slow_report11.log

参考

MySQL 5.7 Reference Manual / The Slow Query Log
https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

pt-query-digest - Analyze MySQL queries from logs, processlist, and tcpdump
https://docs.percona.com/percona-toolkit/pt-query-digest.html

MySQL日常运维之percona-toolkit工具pt-query-digest
https://www.modb.pro/db/42424

pt-query-digest查询日志分析工具
http://t.zoukankan.com/hfclytze-p-pt-query-digest.html