1. 工具简介

pt-query-digest是用于分析mysql慢查询的一个工具,它可以分析binlogGeneral logslowlog,也可以通过SHOWPROCESSLIST或者通过tcpdump抓取的MySQL协议数据来进行分析。可以把分析结果输出到文件中,分析过程是先对查询语句的条件进行参数化,然后对参数化以后的查询进行分组统计,统计出各查询的执行时间、次数、占比等,可以借助分析结果找出问题进行优化。
pt-query-digest
是一个perl脚本,只需下载并赋权即可执行。
[root@test1 ]# wget percona.com/get/pt-query-digest
[root@test1 ]# chmod u+x pt-query-digest

2.语法及重要选项

pt-query-digest [OPTIONS] [FILES] [DSN]

–create-review-table 当使用–review参数把分析结果输出到表中时,如果没有表就自动创建。
–create-history-table
当使用–history参数把分析结果输出到表中时,如果没有表就自动创建。
–filter
对输入的慢查询按指定的字符串进行匹配过滤后再进行分析
–limit限制输出结果百分比或数量,默认值是20,即将最慢的20条语句输出,如果是50%则按总响应时间占比从大到小排序,输出到总和达到50%位置截止。
–host mysql服务器地址
–user
mysql用户名
–password
mysql用户密码
–history将分析结果保存到表中,分析结果比较详细,下次再使用–history时,如果存在相同的语句,且查询所在的时间区间和历史表中的不同,则会记录到数据表中,可以通过查询同一CHECKSUM来比较某类型查询的历史变化。
–review将分析结果保存到表中,这个分析只是对查询条件进行参数化,一个类型的查询一条记录,比较简单。当下次使用–review时,如果存在相同的语句分析,就不会记录到数据表中。
–output分析结果输出类型,值可以是report(标准分析报告)slowlog(Mysql slow log)jsonjson-anon,一般使用report,以便于阅读。
–since从什么时间开始分析,值为字符串,可以是指定的某个”yyyy-mm-dd [hh:mm:ss]”格式的时间点,也可以是简单的一个时间值:s()h(小时)m(分钟)d(),如12h就表示从12小时前开始统计。
–until截止时间,配合—since可以分析一段时间内的慢查询。
3. 标准分析报告解释第一部分:总体统计结果,如下图

Overall: 总共有多少条查询,上例为总共266个查询。
Time range:
查询执行的时间范围。
unique:
唯一查询数量,即对查询条件进行参数化以后,总共有多少个不同的查询,该例为55
total:
总计 min:最小 max: 最大 avg:平均
95%:
把所有值从小到大排列,位置位于95%的那个数,这个数一般最具有参考价值。
median:
中位数,把所有值从小到大排列,位置位于中间那个数。第二部分:查询分组统计结果,如下图

由上图可见,这部分对查询进行参数化并分组,然后对各类查询的执行情况进行分析,结果按总执行时长,从大到小排序。
Response:
总的响应时间。
time:
该查询在本次分析中总的时间占比。
calls:
执行次数,即本次分析总共有多少条这种类型的查询语句。
R/Call:
平均每次执行的响应时间。
Item :
查询对象第三部分:每一种查询的详细统计结果,如下图:

上图可见,12号查询的详细统计结果,最上面的表格列出了执行次数、最大、最小、平均、95%等各项目的统计。
Databases:
库名
Users:
各个用户执行的次数(占比)
Query_time distribution :
查询时间分布, 长短体现区间占比,本例中1s-10s之间查询数量是10s以上的两倍。
Tables:
查询中涉及到的表
Explain:
示例

4.用法示例
(1)
直接分析慢查询文件:

pt-query-digest slow.log > slow_report.log

(2)分析最近12小时内的查询:
pt-query-digest –since=12h slow.log > slow_report2.log

 

(3)分析指定时间范围内的查询:

pt-query-digest slow.log –since ‘2014-04-17 09:30:00’ –until ‘2014-04-17 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)把查询保存到query_history
pt-query-digest –user=root –password=abc123 –review h=localhost,D=test,t=query_ history–create-review-table slow.log_20140401
pt-query-digest –user=root –password=abc123–review h=localhost,D=test,t=query_history–create-review-table slow.log_20140402

(9)
通过tcpdump抓取mysqltcp协议数据,然后再分析
tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt
pt-query-digest –type tcpdump mysql.tcp.txt> slow_report9.log

(10)
分析binlog
mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql
pt-query-digest –type=binlog mysql-bin000093.sql > slow_report10.log

(11)
分析general log
pt-query-digest –type=genlog localhost.log > slow_report11.log

 

官方文档:http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

 

 

 

================================

 

解析binlog工具百家争鸣,最常用的是mysqlbinlog,各有千秋,对于DBA,唯手熟尔罢了
然而,有工具的地方就有江湖,故本文无意争论工具属优属劣,免得引起不成熟的争端

仅介绍pt-query-digest其实也是能用来解析Binlog,友好、可读性强、便于快速诊断故障

 

如果直接:
[root@ld88 mysqldata]# pt-query-digest –type binlog mysql-bin88.000189
将无法解析,需先做如下转换
[root@ld88 mysqldata]# mysqlbinlog mysql-bin88.000189 > mysql-bin88.000189.sql

看两个例子,以下为了排版,对输出做了大量裁减-_-!

㈠ 指定时间窗口

# 160.9s user time, 8.8s system time, 23.62M rss, 150.04M vsz
# Current date: Thu Nov 7 15:37:19 2013
# Hostname: ld88
# Files: mysql-bin88.000189.sql
# Overall: 914 total, 31 unique, 3.06 QPS, 41.19kx concurrency ___________
# Time range: 2013-11-06 20:55:00 to 20:59:59
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 12316866s 13349s 13639s 13476s 13443s 145s 13443s
# Query size 442.35k 6 35.33k 434.29 1012.63 1.88k 143.84
# error code 0 0 0 0 0 0 0

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ================== ===== ========== ===== ======
# 1 0x972882477A1D4A3F 3739234.0000 30.4% 277 13499.0397 1.54 UPDATE tbBlogArticleStat?
# 2 0xF5B3ADEC45DB5266 1099848.0000 8.9% 82 13412.7805 1.39 UPDATE tbBlogArticleStat?
# 3 0xC05BF1F3A8344559 1099848.0000 8.9% 82 13412.7805 1.39 UPDATE tbBlogArticleChart
# 4 0xA85CE0CC3154666E 1024921.0000 8.3% 76 13485.8026 1.26 UPDATE tbBlogTag
# 5 0x7C12B8C66B369B73 822705.0000 6.7% 61 13486.9672 1.26 INSERT tbBlogTagArticle
# 6 0xE8059EB28F9F68AA 752337.0000 6.1% 56 13434.5893 1.39 INSERT tbBlogArticleVote
# 7 0x01FCF322381E8B7E 404606.0000 3.3% 30 13486.8667 1.28 INSERT tbBlogArticleDayClick
# 8 0xD5C00F71DB944F6C 404606.0000 3.3% 30 13486.8667 1.28 UPDATE tbBlogSubArticleStatist
# 9 0x6EFA3A2E4EC6B202 404606.0000 3.3% 30 13486.8667 1.28 UPDATE tbBlogMemberSort
# 10 0xE14AB2C787449950 404606.0000 3.3% 30 13486.8667 1.28 UPDATE tbBlogMemberStat
# 11 0x34764E44BE970CDD 404606.0000 3.3% 30 13486.8667 1.28 INSERT tbBlogArticleChart
# 12 0xCFEB2F244234CE05 404605.0000 3.3% 30 13486.8333 1.28 INSERT tbBlogArticleStat?
# 13 0xCDB381C90AF965D4 404604.0000 3.3% 30 13486.8000 1.28 INSERT tbBlogArticle?
# 14 0xF7D29C9021590977 162011.0000 1.3% 12 13500.9167 1.30 UPDATE tbBlogArticleChart
# 15 0xFBA7BD32B7694172 134777.0000 1.1% 10 13477.7000 1.23 INSERT tbBlogTag
# 16 0xB2317C2DE1E87251 108184.0000 0.9% 8 13523.0000 0.00 UPDATE tbBlogMemberStat
# MISC 0xMISC 540762.0000 4.4% 40 13519.0500 0.0 <14 ITEMS>

# Query 1: 0.93 QPS, 12.59kx concurrency, ID 0x972882477A1D4A3F at byte 218115626
# This item is included in the report because it matches –limit.
# Scores: V/M = 1.54
# Time range: 2013-11-06 20:55:00 to 20:59:57
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 30 277
# Exec time 30 3739234s 13351s 13639s 13499s 13443s 144s 13443s
# Query size 10 44.59k 144 201 164.84 192.76 17.53 166.51
# error code 0 0 0 0 0 0 0 0
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS LIKE \’tbBlogArticleStat0022\’\G
# SHOW CREATE TABLE tbBlogArticleStat0022\G
update tbBlogArticleStat0022 set PrevArticleID=\’0\’,PrevArticleAppearTime=\’\’,NextArticleID=\’35810718\’,NextArticleAppearTime=\’2011-03-14 19:59:01\’ where ArticleID=\’35605800\’\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select PrevArticleID=\’0\’,PrevArticleAppearTime=\’\’,NextArticleID=\’35810718\’,NextArticleAppearTime=\’2011-03-14 19:59:01\’ from tbBlogArticleStat0022 where ArticleID=\’35605800\’\G

㈡ 只输出Profile

# Profile
# Rank Query ID Response time Calls R/Call V/M Ite
# ==== ================== ==================== ====== ========== ===== ===
# 1 0x48CC1A2B52A30509 817766362.0000 18.1% 127173 6430.3458 39… UPDATE tbBlogArticleChart
# 2 0x76509399554D3FEF 741481163.0000 16.4% 113494 6533.2191 39… UPDATE tbBlogArticleDayClick
# 3 0xE0E6B927C2F5000A 726418316.0000 16.1% 111138 6536.1831 38… UPDATE tbBlogMemberDayClick
# 4 0xB0F33119C913EB04 726410137.0000 16.1% 111135 6536.2859 38… UPDATE tbBlogAccessStat
# 5 0xC05BF1F3A8344559 222658013.0000 4.9% 42971 5181.5879 38… UPDATE tbBlogArticleChart
# 6 0xF5B3ADEC45DB5266 222656784.0000 4.9% 42971 5181.5593 38… UPDATE tbBlogArticleStat?
# 7 0x972882477A1D4A3F 146520312.0000 3.2% 25960 5644.0798 52… UPDATE tbBlogArticleStat?
# 8 0xE8059EB28F9F68AA 131750313.0000 2.9% 25876 5091.6028 41… INSERT tbBlogArticleVote
# 9 0xDD9D4A59398D4FEC 76279669.0000 1.7% 13678 5576.8145 43… UPDATE tbBlogArticleDayClick
# 10 0x28D0E7634EB42A4F 85322783.0000 1.9% 13449 6344.1730 41… REPLACE tbBlogVisitor
# 11 0x017F3BABF98C01C3 84711387.0000 1.9% 12946 6543.4410 40… REPLACE tbBlogArticleVisitor
# 12 0xDBF77B093FF5DCAD 52730403.0000 1.2% 9920 5315.5648 44… INSERT tbBlogAccessStat
# 13 0xE66806F5A93FDF12 52731149.0000 1.2% 9919 5316.1759 44… UPDATE tbBlogMemberDayClick
# 14 0xE225E24322E8C40A 61140268.0000 1.4% 9648 6337.0925 42… REPLACE tbBlogVisitorTo
# 15 0x29CF2F2AB36D901F 49727504.0000 1.1% 7768 6401.5839 41… REPLACE tbUserVisitorArticle
# 16 0xA85CE0CC3154666E 38643377.0000 0.9% 7325 5275.5463 55… UPDATE tbBlogTag
# 17 0x7C12B8C66B369B73 31598603.0000 0.7% 6524 4843.4401 58… INSERT tbBlogTagArticle
# 18 0x1EFDEE6D63DED573 103492.0000 0.0% 6134 16.8719 0.51 DELETE tbBlogArticleChart
# 19 0x01FCF322381E8B7E 19873958.0000 0.4% 4856 4092.6602 63… INSERT tbBlogArticleDayClick
# 20 0xCDB381C90AF965D4 19871072.0000 0.4% 4856 4092.0659 63… INSERT tbBlogArticle?
# 21 0xCFEB2F244234CE05 19870602.0000 0.4% 4856 4091.9691 63… INSERT tbBlogArticleStat?

参考资料
http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

One thought on “pt-query-digest查询日志分析工具

Comments are closed.