工具 - 【percona-toolkit】 pt-query-digest满日志分析 - 《Mysql》

1. 安装
2 命令
3 分析结果

1. 安装

安装包：

percona-toolkit-3.3.1-1.el7.x86_64.rpm

需要的依赖：

perl-Digest-1.17-245.el7.noarch.rpm
perl-Digest-MD5-2.52-3.el7.x86_64.rpm
perl-IO-Socket-IP-0.21-5.el7.noarch.rpm
perl-IO-Socket-SSL-1.94-7.el7.noarch.rpm
perl-Mozilla-CA-20130114-5.el7.noarch.rpm
perl-Net-LibIDN-0.12-15.el7.x86_64.rpm
perl-Net-SSLeay-1.55-6.el7.x86_64.rpm
perl-TermReadKey-2.30-20.el7.x86_64.rpm

# 使用yum本地安装
yum localinstall -y perl-*
yum localinstall -y percona-toolkit-3.3.1-1.el7.x86_64.rpm

2 命令

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

3 分析结果

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

3.1 第一部分

该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小
# 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

3.2 第二部分

第二部分是查询分组的统计结果，包含了一些花费时间比较长的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的比率

注意：log_queries_not_using_indexes参数，这个参数开启的话，mysql会默认将没有使用index的SQL语句也记录在慢日志中

3.3 第三部分

第三部分是第二部分查出来的每一个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