使用pt-query-digest分析mysql慢日志

使用pt-query-digest分析mysql慢日志

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

sed -n '/2019-02-27T01:55:04/,/2019-02-27T02:02:04/p'  slowquery.log > yyz.tmp

这个命令将格林尼治时间01:55:04到02:05:04的慢日志打印出来，重定向到一个yyz.tmp的文件中，需要注意的是格林尼治时间加上8小时就是北京时间。发现这个yyz.tmp也比较大，所以我又重新把时间定格在60s之内，这样得到了一个比较小的tmp文件，这个时候，就该pt工具上场了。如果不想用sed命令，其实pt工具本身也自带一些参数，可以通过--since参数和--until参数来把日志中固定时间段的日志打印出来，如下

pt-query-digest --since='2019-02-27 09:30:00'--until=2019-02-27 ::' /data/mysql_4306/log/slowquery.log > 1.txt

使用pt工具分析慢日志的结果如下，总体分为三个部分，第一部分是总体统计结果，如下：

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

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

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

Rank：所有语句的排名，默认按查询时间降序排列

Query ID：语句的ID

Response：总的响应时间

time：该查询在本次分析中总的时间占比

calls：执行次数，即本次分析总共有多少条这种类型的查询语句

R/Call：平均每次执行的响应时间

V/M：响应时间Variance-to-mean的比率

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

mysql> show variables like '%index%';
+----------------------------------------+--------------------------------------------+
| Variable_name                          | Value                                      |
+----------------------------------------+--------------------------------------------+
| eq_range_index_dive_limit              |                                         |
| expand_fast_index_creation             | OFF                                        |
| innodb_adaptive_hash_index             | ON                                         |
| innodb_adaptive_hash_index_parts       |                                           |
| innodb_cmp_per_index_enabled           | OFF                                        |
| log_bin_index                          | /data/mysql_4306/innodblog/mysqlbin.index  |
| log_queries_not_using_indexes          | ON                                         |
| log_throttle_queries_not_using_indexes |                                           |
| performance_schema_max_index_stat      | -1                                         |
| relay_log_index                        | /data/mysql_4306/log/slave-relay-bin.index |
+----------------------------------------+--------------------------------------------+
 rows in set (0.00 sec)

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

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

# Query : 0.03 QPS, 0.02x concurrency, ID 0xCB9AD73BDFEDCAD9 at byte 
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2019-02-27T02:: to 2019-02-27T02::
# Attribute    pct   total     min     max     avg     %  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count                 
# Exec time        ms   ms   ms   ms   ms    ms   ms
# Lock time         us   us   us   us   us    us   us
# Rows sent                                                       
# Rows examine     1.05M 536.64k 536.64k 536.64k 536.64k        536.64k
# Rows affecte                                                    
# Bytes sent                                                      
# Query size                                          
# String:
# Data s    tgp_db
# Hosts        127.0.0.1
# Last errno   
# Stored routi tgp_db.PCall_TGP_GetAssDAO
# Users        dba_admin
# Query_time distribution
#   us
#  us
# us
#   ms
#  ms
# ms  ################################################################
#    s
#  s+
# Tables
#    SHOW TABLE STATUS FROM `tgp_db` LIKE 'dic_push_dao_assistant'G
#    SHOW CREATE TABLE `tgp_db`.`dic_push_dao_assistant`G
#    SHOW TABLE STATUS FROM `tgp_db` LIKE 'tem_selectAssDAO'G
#    SHOW CREATE TABLE `tgp_db`.`tem_selectAssDAO`G
update `dic_push_dao_assistant`
    set `state` = 
    where `id` in 
    (
select `id`
        from `tem_selectAssDAO`
    )G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  `state` =  from `dic_push_dao_assistant` where  `id` in 
    (
select `id`
        from `tem_selectAssDAO`
    )G

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

ID：查询的ID号，和上图的Query ID对应

Data s：数据库名

Users：各个用户执行的次数（占比）

Query_time distribution ：查询时间分布, 长短体现区间占比，本例中1s-10s之间查询数量是10s以上的两倍。

Tables：查询中涉及到的表

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

下面给出pt-query-digest常用方法。

pt-query-digest常用方法

1.直接分析慢查询文件:
pt-query-digest slow.log > slow_report.log

2.分析最近小时内的查询：
pt-query-digest --since=h slow.log > slow_report2.log

3.分析指定时间范围内的查询：
pt-query-digest slow.log --since '2017-01-07 09:30:00' --until '2017-01-07 10:00:00'> > slow_report3.log

4.分析指含有select语句的慢查询
pt-query-digest --filter '$event->{fingerprint} =~ m/^select/i' slow.log> slow_report4.log

5.针对某个用户的慢查询
pt-query-digest --filter '($event->{user} || "") =~ m/^root/i' slow.log> slow_report5.log

6.查询所有全表扫描或full join的慢查询
pt-query-digest --filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' slow.log> slow_report6.log

7.把查询保存到query_review表
pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_review--create-review-table slow.log

8.分析binlog
mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql
pt-query-digest --type=binlog mysql-bin000093.sql > slow_report10.log

9.分析general log
pt-query-digest --type=genlog localhost.log > slow_report11.log