使用pt-query-digest分析mysql慢日志

工具介绍

  • pt系列(percona-toolkit)是一组高级命令行工具的集合,用来执行各种通过手工执行非常复杂和麻烦的mysql和系统任务。这些任务包括:
    • 检查master和slave数据的一致性
    • 有效地对记录进行归档
    • 查找重复的索引
    • 对服务器信息进行汇总
    • 分析来自日志和tcpdump的查询
    • 当系统出问题的时候收集重要的系统信息
  • pt-query-digest是用于分析mysql慢查询的一个工具,它可以分析binlog、General log、slowlog,也可以通过SHOWPROCESSLIST或者通过tcpdump抓取的MySQL协议数据来进行分析。可以把分析结果输出到文件中,分析过程是先对查询语句的条件进行参数化,然后对参数化以后的查询进行分组统计,统计出各查询的执行时间、次数、占比等,可以借助分析结果找出问题进行优化。

安装

  • 安装percona-toolkit非常简单,到官网下载.tar.gz包:

    1
    2
    wget percona.com/get/percona-toolkit.tar.gz
    tar -zxvf percona-toolkit-2.2.20.tar.gz

    然后依次执行下面的命令:

    1
    2
    3
    4
    perl Makefile.PL
    make
    make test
    make install

    默认的会被安装在/usr/local/bin目录下。执行man percona-toolkit可以查看安装了哪些工具。
    如果安装过程中遇到错误有可能是因为缺少相应包,.pm包实际上perl的包,运行下面的命令安装即可:

    1
    yum install -y perl-Time-HiRes

    如果安装过程中出现” Error Downloading Packages”错误,尝试yum clean all后再安装。使用其Percona Toolkit中其他工具也可能会遇到类似的问题,按照提示安装相应的perl包就可以了。s

    如果单独安装pt-query-digest
  • pt-query-digest是一个perl脚本,只需下载并赋权即可执行。
    1
    2
    [root@test1 ]# wget percona.com/get/pt-query-digest
    [root@test1 ]# chmod u+x pt-query-digest

语法及重要选项`

  • 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)、json、json-anon,一般使用report,以便于阅读。
    –since 从什么时间开始分析,值为字符串,可以是指定的某个”yyyy-mm-dd [hh:mm:ss]”格式的时间点,也可以是简单的一个时间值:s(秒)、h(小时)、m(分钟)、d(天),如12h就表示从12小时前开始统计。
    –until 截止时间,配合—since可以分析一段时间内的慢查询。

标准分析报告解释

  • 第一部分:总体统计结果,如下:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    # 30.3s user time, 100ms system time, 54.43M rss, 234.72M vsz
    # Current date: Thu Apr 20 14:29:53 2017
    # Hostname: sz-4PG5S62-143.233
    # Files: slowquery_2017041702.log
    # Overall: 148.29k total, 879 unique, 0.49 QPS, 0.01x concurrency ________
    # Time range: 2017-04-17 02:00:17 to 2017-04-20 14:29:49
    # Attribute total min max avg 95% stddev median
    # ============ ======= ======= ======= ======= ======= ======= =======
    # Exec time 1580s 45us 113s 11ms 24ms 444ms 490us
    # Lock time 16s 0 132ms 104us 204us 735us 76us
    # Rows sent 56.71M 0 122.51k 401.02 964.41 568.90 15.25
    # Rows examine 1.85G 0 763.31k 13.07k 46.68k 18.55k 537.02
    # Rows affecte 126.89k 0 109.06k 0.88 0 285.80 0
    # Bytes sent 16.31G 0 3.11M 115.35k 328.61k 146.47k 2.27k
    # Query size 45.01M 17 67.14k 318.25 621.67 425.75 166.51

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

  • 查询分组统计结果,如下:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    # Profile
    # Rank Query ID Response time Calls R/Call V/M Item
    # ==== ================== ============== ===== ======= ===== =============
    # 1 0x28BCEDE65DD7D889 675.7240 42.8% 54848 0.0123 0.00 SELECT x_sgoods_info
    # 2 0xD39A2C708040855B 265.9995 16.8% 4 66.4999 18.15 SELECT x_sgoods_apply
    # 3 0x8C491C4FD5198E48 106.7519 6.8% 4032 0.0265 0.00 UPDATE SELECT x_activity_ext
    # 4 0xD33CA91CD8B4E2D8 79.5063 5.0% 1 79.5063 0.00 DELETE x_sell_schedule
    # 5 0x5C6FF2B6FCCA3017 68.0030 4.3% 2520 0.0270 0.00 UPDATE x_activity_ext
    # 6 0xF5BDA316B1B737EA 41.2985 2.6% 6 6.8831 10.86 SELECT x_ims_inventory_? wms_sz
    # 7 0x30C0057AC8384E14 25.6073 1.6% 11 2.3279 0.10 SHOW TABLES
    # 8 0xF382DCE6D809E44D 25.4006 1.6% 504 0.0504 0.00 SELECT information_schema.triggers
    # 9 0x719C7301B7CF64D7 21.8942 1.4% 991 0.0221 0.00 SELECT x_activity
    # 10 0xF175BFA8DBAF36CA 17.9455 1.1% 16 1.1216 0.53 SELECT x_aftersale.x_back_order_history
    # 11 0xB6ED284B889F94EC 16.5861 1.1% 1 16.5861 0.00 SELECT x_ims_inventory wms_wh
    # 12 0x9118568215E7D69D 13.8534 0.9% 2 6.9267 1.59 SELECT x_ims_inventory_? wms_gz
    # 13 0x26D6EC4CB906C42B 13.5226 0.9% 504 0.0268 0.00 UPDATE x_activity_ext
    # 14 0xFA3C32281E8D3961 13.4112 0.8% 326 0.0411 0.00 SELECT x_business.x_business_brand
    # 15 0x8FAD804AD81A4A74 12.3985 0.8% 2289 0.0054 0.00 SELECT x_business.x_enter_brand
    # 16 0x445D20E44CF56324 10.6359 0.7% 7 1.5194 0.17 SHOW TABLE STATUS
    # 17 0x516BDC428E566067 8.5546 0.5% 37 0.2312 1.10 SELECT x_gsort_position
    # 18 0xA7F5E897554A30D5 8.4394 0.5% 3 2.8131 4.47 SELECT x_ims_inventory wms_wh
    # 19 0xEF6FFF1D5B1B645E 8.2623 0.5% 2 4.1312 0.38 SELECT INFORMATION_SCHEMA.KEY_COLUMN_USAGE
    # 20 0xB8A4114AE57A78EE 7.1822 0.5% 2 3.5911 6.49 SELECT x_sgoods_bag x_sgoods_apply
    # MISC 0xMISC 138.5347 8.8% 82182 0.0017 0.0 <859 ITEMS>

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

  • 第三部分:每一种查询的详细统计结果,如下:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    # Query 1: 0.18 QPS, 0.00x concurrency, ID 0x28BCEDE65DD7D889 at byte 6647850
    # This item is included in the report because it matches --limit.
    # Scores: V/M = 0.00
    # Time range: 2017-04-17 02:06:42 to 2017-04-20 14:22:48
    # Attribute pct total min max avg 95% stddev median
    # ============ === ======= ======= ======= ======= ======= ======= =======
    # Count 36 54848
    # Exec time 42 676s 4ms 89ms 12ms 19ms 4ms 12ms
    # Lock time 46 7s 74us 355us 131us 214us 43us 113us
    # Rows sent 90 51.27M 0 1000 980.16 964.41 124.14 964.41
    # Rows examine 81 1.52G 2.93k 56.25k 28.98k 51.46k 14.94k 28.66k
    # Rows affecte 0 0 0 0 0 0 0 0
    # Bytes sent 98 16.10G 2.36k 337.44k 307.89k 328.61k 40.65k 298.06k
    # Query size 73 33.25M 632 636 635.76 621.67 0 621.67
    # String:
    # Databases x_sgoods
    # Hosts 192.168.143.95
    # Last errno 0
    # Users test
    # Query_time distribution
    # 1us
    # 10us
    # 100us
    # 1ms ###############################
    # 10ms ################################################################
    # 100ms
    # 1s
    # 10s+
    # Tables
    # SHOW TABLE STATUS FROM `x_sgoods` LIKE 'x_sgoods_info'\G
    # SHOW CREATE TABLE `x_sgoods`.`x_sgoods_info`\G
    # EXPLAIN /*!50100 PARTITIONS*/
    SELECT
    ````
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    由上图可见,12号查询的详细统计结果,最上面的表格列出了执行次数、最大、最小、平均、95%等各项目的统计。
    Databases: 库名
    Users: 各个用户执行的次数(占比)
    Query_time distribution : 查询时间分布, 长短体现区间占比,本例中1s-10s之间查询数量是10s以上的两倍。
    Tables: 查询中涉及到的表
    Explain: 示例
    #### 用法示例
    * 直接分析慢查询文件:
    pt-query-digest slow.log > slow_report.log
    (slow.log为mysql路径的慢日志文件,后面为分析后的文件)
    获取慢日志地址:
    在mysql命令行执行
    ```mysql
    show variables like '%slow%';
  • 分析最近12小时内的查询:
    pt-query-digest –since=12h slow.log > slow_report2.log

  • 分析指定时间范围内的查询:
    pt-query-digest slow.log –since ‘2014-04-17 09:30:00’ –until ‘2014-04-17 10:00:00’> > slow_report3.log

  • 分析指含有select语句的慢查询:
    pt-query-digest–filter ‘$event->{fingerprint} =~ m/^select/i’ slow.log> slow_report4.log

  • 针对某个用户的慢查询:
    pt-query-digest–filter ‘($event->{user} || “”) =~ m/^root/i’ slow.log> slow_report5.log

  • 查询所有的全表扫描或full join的慢查询:
    pt-query-digest–filter ‘(($event->{Full_scan} || “”) eq “yes”) ||(($event->{Full_join} || “”) eq “yes”)’ slow.log> slow_report6.log

  • 把查询保存到query_review表:
    pt-query-digest –user=root –password=abc123 –review h=localhost,D=test,t=query_review–create-review-table slow.log

  • 把查询保存到queryhistory表:
    pt-query-digest –user=root –password=abc123 –review h=localhost,D=test,t=query
    history–create-review-table slow.log_20140401

  • 通过tcpdump抓取mysql的tcp协议数据,然后再分析:
    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

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

  • 分析general log:
    pt-query-digest –type=genlog localhost.log > slow_report11.log