使用pt-query-digest分析慢查询日志，并用SHOW

近期在看《高性能MySQL》一书，看到第三章，服务器性能剖析，并按书中的方法实践了一把，并做个笔记记录一下。
首先开启MySQL服务器的慢查询 过程略
下载安装percona toolkit 过程略
使用pt-query-digest命令分析日志，并重定向到文件，方便随时查看
pt-query-digest localhost.slow.log > slow_query.txt
查看slow_query.txt

# Profile
# Rank Query ID           Response time   Calls  R/Call V/M   Item
# ==== ================== =============== ====== ====== ===== ============
#    1 0x9030B064B9B05621 1608.8106 36.5%    747 2.1537  0.07 INSERT ******
#    2 0xD1067DE6404C9A1E  237.7894  5.4%   1267 0.1877  0.03 SELECT ******
#    3 0xEDB8A2003D49B29E  190.9826  4.3%     22 8.6810  0.00 SELECT ******
#    4 0x11AFADF7FEDF026D  171.9935  3.9%    437 0.3936  0.06 SELECT ******
#    5 0x531B51924BC5DC2F  171.8103  3.9% 529836 0.0003  0.46 INSERT ******
#    6 0x6E8E1C4EDE1534F1  159.9553  3.6% 622102 0.0003  0.30 UPDATE ******
#    7 0x74DCC0441536A1FC  116.7364  2.6%   2156 0.0541  1.62 INSERT ******
#    8 0x92EB9323811ECEB1   97.8649  2.2%   2219 0.0441  0.47 ******
#    9 0xA7C1CE93DED8C1E1   93.5586  2.1%  57165 0.0016  0.21 SELECT ******
#   10 0xBA22ED3718F81667   81.9668  1.9% 210312 0.0004  0.85 INSERT ******
#   11 0x45170D814B5B0DD6   76.8364  1.7%   2154 0.0357  1.22 UPDATE ******
#   12 0x6DACBDEFBBD8A568   70.9832  1.6%   3331 0.0213  1.07 INSERT ******
#   13 0x312C4E87BA9FBCAE   70.1009  1.6%   1391 0.0504  0.08 SELECT ******
......

可以看到按占用时间排序的列表，V/M是每条语句执行时间的方差除以平均值，称为离散指数，值越大说明这条语句执行越不稳定，需要关注。Item这里原本是由语句摘要的，我用******做了替换
我先关注排名第一的这条INSERT语句
继续往下看slow_query.txt

# Query 1: 0.25 QPS, 0.54x concurrency, ID 0x9030B064B9B05621 at byte 197427536
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.07
# Time range: 2018-04-27 13:44:35 to 14:34:03
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0     747
# Exec time     36   1609s      2s      6s      2s      2s   400ms      2s
# Lock time      0    66ms    56us   556us    88us   131us    30us    76us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  63 806.39M   1.08M   1.08M   1.08M   1.03M       0   1.03M
# Query size     0 185.35k     253     263  254.08  246.02    1.41  246.02
# String:
# Databases    ******
# Hosts        ******
# Users        ******
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM ******` LIKE '******'\G
#    SHOW CREATE TABLE `******`.`******`\G
这里应该是执行时间最长的一条实际的查询，我已'insert into students (name,sex,age,class) values ('Marvin','male',18,1);'来举例

这里我们可以看到几个数值
统计时间区间是13:44:35 to 14:34:03，大概50分钟，
count=747，总共执行了747条该查询
Exec time种95%为2s
而且离散指数为0.07，并不大，说明这条查询的执行时间基本上都需要2S
看下面的直方图也全部落在1s档上
接下来按照下面给的实际运行查询来剖析这条语句
使用SHOW PROFILE方法剖析单条查询
SET profiling = 1; #开启PROFILE
insert into students (name,sex,age,class) values ('Marvin','male',18,1); #执行报告里提示的查询

mysql> SHOW PROFILES;
+----------+------------+------------------------------------------------------------------------------------------------+
| Query_ID | Duration   | Query                                                                                          |
+----------+------------+------------------------------------------------------------------------------------------------+
|        1 | 1.02122750 | Update ****** SET ******
+----------+------------+------------------------------------------------------------------------------------------------+

到这里我一开始有点蒙，明明是INSERT语句，怎么变成UPDATE了，后来查看了表结构，发现这张表是关联触发器的，查看触发器种配置的存储结构，发现这个表插入的同时，也会对另外一张表做更新。
继续剖析

+---------------------------+----------+
| Status                    | Duration |
+---------------------------+----------+
| continuing inside routine | 0.000031 |
| checking permissions      | 0.000026 |
| Opening tables            | 0.000024 |
| init                      | 0.000086 |
| updating                  | 1.020918 |
| end                       | 0.000090 |
| query end                 | 0.000021 |
| closing tables            | 0.000032 |
+---------------------------+----------+

从结果可以看出来，主要是updating过程花了大部分时间。
查看这条update语句是
Update abc SET a=1 WHERE b='x' AND c='y';
查看abc表的表结构，发现x和y没有创建索引 ，赶紧创建索引，创建好后再将profile的步骤重新执行一遍

mysql> SHOW PROFILE for query 1;
+---------------------------+----------+
| Status                    | Duration |
+---------------------------+----------+
| continuing inside routine | 0.000025 |
| checking permissions      | 0.000021 |
| Opening tables            | 0.000021 |
| init                      | 0.000076 |
| updating                  | 0.000078 |
| end                       | 0.000023 |
| query end                 | 0.000020 |
| closing tables            | 0.000023 |
+---------------------------+----------+

发现updating时间小了很多。
接下去如果继续研究这个问题，我想应该是重新关开慢查询，让其重新生成慢查询日志，重新分析，看看上面的INSERT语句有没有正常，我这里等下再做这个步骤，现在继续查看下面的QUERY
我的QUERY 3

# Query 3: 0.01 QPS, 0.07x concurrency, ID 0xEDB8A2003D49B29E at byte 544689032
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2018-04-27 13:46:17 to 14:33:41
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      22
# Exec time      4    191s      9s      9s      9s      8s       0      8s
# Lock time      0     2ms   102us   157us   112us   119us    12us   108us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0 455.70k  20.71k  20.71k  20.71k  20.37k    0.00  20.37k
# Query size     0   6.04k     281     281     281     281       0     281
# String:
# Databases    ******
# Hosts        ******
# Users       ******
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
......
# EXPLAIN /*!50100 PARTITIONS*/
Select A.a1,A.a2,A.a3,A.a4, From A,B, C Where A.a5 = x And B.b5 = y And B.b2 = z And A.a1=B.b1 And C.c5=1 And A.a2 = C.c2  Order by A.a1,A.a2\G

我们可以看到，这条查询在将近50分钟时间内只运行了22次，不算频繁，但是每次查询都要花掉8秒多，所以要看看究竟时间花在哪里，同样用SHOW PROFILE方法
我们看到

mysql> show PROFILE FOR QUERY 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000200 |
| checking permissions | 0.000022 |
| checking permissions | 0.000021 |
| checking permissions | 0.000022 |
| Opening tables       | 0.000055 |
| init                 | 0.000067 |
| System lock          | 0.000032 |
| optimizing           | 0.000040 |
| statistics           | 0.000070 |
| preparing            | 0.000070 |
| Creating tmp table   | 0.000056 |
| Sorting result       | 0.000022 |
| executing            | 0.000020 |
| Sending data         | 8.835811 |
| Creating sort index  | 0.000104 |
| end                  | 0.000067 |
| removing tmp table   | 0.000025 |
| end                  | 0.000023 |
| query end            | 0.000023 |
| closing tables       | 0.000033 |
| freeing items        | 0.000040 |
| logging slow query   | 0.000025 |
| cleaning up          | 0.000057 |
+----------------------+----------+

可以看到，时间都花在了Sending data上，那什么是Sending data呢？我先去问下度娘继续写