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

AsiaYe

发布于 2019-11-06 16:45:17

1.9K0

发布于 2019-11-06 16:45:17

文章被收录于专栏：DBA随笔DBA随笔

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

今天早上来，某一台服务器疯狂报警，几乎每五分钟报警一次，报警的内容是"某些SQL语句执行效率慢"，这个问题总体上分为两类，第一类是出现了慢查询语句，第二类是某些查询语句没有使用索引，由于数据的写入量非常大，所以要想直接打开慢查询日志来查看到底哪些语句有问题几乎是不可能的，因为日志的刷新速度太快了，于是想起了pt工具，pt工具中的pt-query-digest比较擅长解决这个问题。

首先分析报警的时间点，这里我们用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_expression
#    0x7C0C6F0CFBADF271  0.0427  1.9%     0.0022  0.00 SELECT dic_cal_expression
#    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:
# Databases    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对应

Databases：数据库名

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

本文参与腾讯云自媒体分享计划，分享自微信公众号。

原始发表：2019-02-27，如有侵权请联系 cloudcommunity@tencent.com 删除

云数据库 SQL Server