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

时间：2021-12-31 23:36:43

high performance MySQL笔记：


孔子说“工欲善其事，必先利其器”， 今天就介绍一下percona toolkit中的pt-query-digest。

下载地址：

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参数设置得很合理。

 
# 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的内容。
第一部分是摘要：

 
 
# 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之类的。

继续看第二部分：

 
# 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为例。

# 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


标签：

相关文章