pt-query-digest解析MySQL Binlog日志文件

来源：互联网发布：js 动态添加style 编辑：程序博客网时间：2024/06/09 13:49

解析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

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

㈠指定时间窗口

[root@ld88 mysqldata]# pt-query-digest --type binlog --since "2013-11-06 20:55:00" --until "2013-11-06 21:00:00" mysql-bin88.000189.sqlmysql-bin88.000189.sql:  17% 02:22 remainmysql-bin88.000189.sql:  33% 01:58 remainmysql-bin88.000189.sql:  47% 01:39 remainmysql-bin88.000189.sql:  62% 01:12 remainmysql-bin88.000189.sql:  83% 00:28 remain# 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`\Gupdate 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

[root@ld88 mysqldata]# pt-query-digest --type binlog --group-by fingerprint --limit "100%" --order-by "Query_time:cnt" --output report --report-format profile mysql-bin88.000189.sqlmysql-bin88.000189.sql:  13% 03:07 remainmysql-bin88.000189.sql:  25% 02:53 remainmysql-bin88.000189.sql:  38% 02:24 remainmysql-bin88.000189.sql:  49% 02:01 remainmysql-bin88.000189.sql:  60% 01:36 remainmysql-bin88.000189.sql:  72% 01:07 remainmysql-bin88.000189.sql:  84% 00:39 remainmysql-bin88.000189.sql:  96% 00:08 remain# 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

By 迦夜

2013-11-7

Good Luck