使用pt-query-digest分析mysql slow query log

介绍一下percona toolkit中的pt-query-digest：

http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

下载地址：

http://www.percona.com/software/percona-toolkit/

官方文档：

http://www.percona.com/doc/percona-toolkit/pt-query-digest.html

请先确定在my.ini中打开了mysql的slow_query_log，并且保证long_query_time参数设置得很合理。

[sql] view plain copy print ?   # Log slow queries. Slow queries are queries which take more than the # amount OF TIME defined IN "long_query_time" OR which do NOT USE # indexes well, IF log_short_format IS NOT enabled. It IS normally good idea # TO have this turned ON IF you frequently ADD NEW queries TO the # system. slow_query_log   # ALL queries taking more than this amount OF TIME (IN seconds) will be # trated AS slow. Do NOT USE "1" AS a VALUE here, AS this will RESULT IN # even very fast queries being logged FROM TIME TO TIME (AS MySQL # currently measures TIME WITH SECOND accuracy ONLY). long_query_time = 2

pt-query-digest是一个perl脚本，只需下载即可。

[root@sso bianxuehui]# wget percona.com/get/pt-query-digest 
[root@sso bianxuehui]# file pt-query-digest 
pt-query-digest: a perl script text executable
[root@sso bianxuehui]# ll  pt-query-digest
-rw-r--r-- 1 root root 499727 09-02 00:01 pt-query-digest
[root@test_dx modify]# chmod u+x pt-query-digest 

使用如下，如果slow log够大的话，会消耗相当多的cpu和内存，所以最好把slow log和pt-query-digest放到其它的server上面运行。

[root@test_dx bianxuehui]# ./pt-query-digest  slow.log  >digest.log

看一下digest.log的内容。
第一部分是摘要：

[sql] view plain copy print ?     # 390ms USER TIME, 10ms system TIME, 15.67M rss, 105.84M vsz # CURRENT DATE: Thu DEC 29 13:22:42 2011 # Hostname: test_dx # Files: dxdb1-slow.log # Overall: 776 total, 11 UNIQUE, 0.00 QPS, 0.00x concurrency _____________ # TIME range: 2011-09-10 04:03:19 TO 2011-12-29 05:02:51 # Attribute total MIN MAX avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # EXEC TIME 5657s 2s 33s 7s 23s 6s 5s # LOCK TIME 33s 0 19s 43ms 98us 715ms 38us # ROWS sent 323.38k 0 107.36k 426.73 0.99 6.35k 0 # ROWS examine 323.39k 0 107.36k 426.74 0 6.35k 0 # Query SIZE 217.95k 38 562 287.61 420.77 81.78 284.79

从这份摘要中可以看出，dxdb1-slow.log中共有776条SQL语句， 去掉重复(至于怎样才算是重复，下文会有介绍)，有11条SQL。
然后又有很多的Attribute和很多的值，比如total(总和)，min最小值, max最大值, avg平均值,
95%(*)，stddev（不知道是啥，标准差？）和median中位数。
中位数的概念就是把这些值从小到大排序，位置位于最中间的那个数。

在这些值中，最有意义的恐怕就是95%了，与中位数类似，它也是把所有值从小到大排列，位置位于95%的那个数。
它过滤了一些非常大的值，因此更有统计学上的意义，其实统计学上更喜欢用四分位数(1/4, 1/2, 3/4), 中位数也是四分位数之一。

另外，根据SQL语句的不同，可能会有更多的Attribute显示出来。 比如Tmp tables, Tmp disk tbl，Tmp tbl size之类的。

继续看第二部分：

[sql] view plain copy print ?   # Profile # Rank Query ID Response TIME Calls R/CALL Apdx V/M Item # ==== ================== =============== ===== ====== ==== ===== ======== # 1 0x4BA72E7D091B848A 4002.9799 70.8% 547 7.3181 0.19 5.57 INSERT test_show # 2 0x4AE6E5D741E52A10 463.9715 8.2% 57 8.1399 0.12 3.98 INSERT test_?click # 3 0x120DE9D5CDE2DF8A 455.9982 8.1% 62 7.3548 0.17 5.72 INSERT cpm_pop # 4 0x88B2139A82CBB181 275.9844 4.9% 34 8.1172 0.24 7.41 INSERT UPDATE test_stat_1 # 5 0x0F6895DB36DE570A 191.5783 3.4% 20 9.5789 0.23 7.96 INSERT UPDATE test_stat_2 # 6 0x30FE5C2032672827 92.1919 1.6% 25 3.6877 0.36 0.59 SHOW TABLE STATUS # 7 0x40B69AB7631E4445 84.5306 1.5% 13 6.5024 0.15 3.48 SELECT test_show # MISC 0xMISC 89.7177 1.6% 18 4.9843 NS 0.0 <4 ITEMS>

这一部分显示了最慢的七种类型的SQL语句。
我这里最慢的是INSERT INTO test_show …… 共有547条语句，虽然每次插入的数据都是不同的，但也被归于同一类型的语句了。

第三部分最重要了。
以排名第七的SQL为例。

[sql] view plain copy print ?    # Query 7: 0.00 QPS, 0.00x concurrency, ID 0x40B69AB7631E4445 at byte 203205 # Scores: Apdex = 0.15 [1.0]*, V/M = 3.48 # Query_time sparkline: | ^_| # TIME range: 2011-11-24 05:02:15 TO 2011-12-10 05:02:43 # Attribute pct total MIN MAX avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # COUNT 1 13 # EXEC TIME 1 85s 2s 20s 7s 10s 5s 5s # LOCK TIME 0 1ms 0 118us 80us 108us 29us 86us # ROWS sent 0 12 0 1 0.92 0.99 0.26 0.99 # ROWS examine 0 16 0 3 1.23 2.90 1.09 0.99 # Query SIZE 0 1.16k 91 91 91 91 0 91 # String: # DATABASES test # Hosts dx_web_1 # Users test_user # Query_time distribution # 1us # 10us # 100us # 1ms # 10ms # 100ms # 1s ################################################################ # 10s+ ################### # TABLES # SHOW TABLE STATUS FROM `test` LIKE 'test_show'\G # SHOW CREATE TABLE `test`.`test_show`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT COUNT(*) AS modify___c FROM test_show WHERE ip=1303055780 AND web_id=5 AND ad_id = 4\G

从上面可以看出，共有13条语句，[95%]Exec time是10s，时间长得比较离谱了。数据库为test，主机为dx_web_1，用户名为test_user,然后是query time的分布图，这个图太恶心了，不过也可以看得出来大部分是处于1-10s之间的， 还有一些超过10秒了。

最后是几条SQL语句， 是pt-query-digest生成的，这些语句有助于分析问题。

事实上，pt-query-digest的功能远远不止于此，除了直接分析slow query log并生成报告，它还可以filter, replay, transform queries for mysql,postgresql, memcached!

参考文档：

http://dev.mysql.com/doc/refman/5.1/en/slow-query-log.html

http://dev.mysql.com/doc/refman/5.1/en/server-system-variables.html#sysvar_long_query_time

http://www.percona.com/doc/percona-server/5.1/diagnostics/slow_extended.html