Percona Toolkit · 慢日志分析工具 pt-query-digest

发表于 | 更新于 | 分类于 | 阅读次数：

功能

提供慢日志分析功能，与 mysqldumpshow 工具相比，pt-query-digest 工具的分析结果更具体，更完善。

分析

第一部分：总体统计结果

  • Overall：总共有多少条查询
  • Time range：查询执行的时间范围
  • unique：唯一查询数量，即对查询条件进行参数化以后，总共有多少个不同的查询
  • total：总计
  • min：最小
  • max：最大
  • avg：平均
  • 95%：把所有值从小到大排列，位置位于 95% 的那个数，这个数一般最具有参考价值
  • median：中位数，把所有值从小到大排列，位置位于中间那个数
1
2
3
4
5
6
7
8
9
10
11
12
13
# 8.7s user time, 170ms system time, 47.34M rss, 241.90M vsz
# Current date: Wed Oct 16 16:25:30 2019
# Hostname: console
# Files: slow.log
# Overall: 7.99k total, 894 unique, 0.00 QPS, 0.02x concurrency __________
# Time range: 2018-12-21T14:35:34 to 2019-10-16T07:09:56
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        529092s      5s   6210s     66s    234s    211s     14s
# Lock time           808s       0    163s   101ms     5ms      3s   761us
# Rows sent        152.93M       0  15.14M  19.60k   1.39k 284.79k    0.99
# Rows examine     188.85G       0 867.98M  24.20M  72.18M  44.34M   3.68M
# Query size        31.32M       6  66.00k   4.01k  18.47k   5.60k  793.42

第二部分：查询分组统计结果

  • Rank：所有语句的排名，默认按【time】降序排列，通过 --order-by 指定
  • Query ID：语句 ID
  • Response：总的响应时间，单位为 S
  • Time：该查询在本次分析中总的时间占比
  • Calls：执行次数，即本次分析总共有多少条这种类型的查询语句
  • R/Call：平均每次执行的响应时间
  • Item：查询对象
1
2
3
4
5
6
7
8
9
10
11
12
13
# Profile
# Rank Query ID                    Response time     Calls R/Call    V/M
# ==== =========================== ================= ===== ========= =====
#    1 0xFFF66E9B3D962FA319C806... 211420.4504 40.0%   260  813.1556 25.32 ROLLBACK
#    2 0x73AFBACFEBF3942B3B02FB...  33680.6071  6.4%   173  194.6856  0.26 INSERT SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT UNION SELECT d_etl_odsgvs_faglflext_all tdmetl.odsgvs_faglflext_all
#    3 0xE1EA5439ED76CBFAA1C5A3...  24517.0767  4.6%     4 6129.2692  1.79 SELECT v_gvs_zgvs_bseg_edw
#    4 0xE562308914915E2720E128...  21322.3718  4.0%  1282   16.6321  8.55 SELECT tdmetl.gvs_zgvs_bseg_edw
#    5 0x0159EC63419857F0EC9D5B...  17472.3139  3.3%    71  246.0889  1.03 SELECT v_edw_data
#    6 0x2DD4B63FCE7C5DEEE14F92...  14743.4445  2.8%   159   92.7261  0.73 UPDATE SELECT d_tax_moth_data
#    7 0x9C084CB3E04D24D29E8BE9...   9081.9772  1.7%    85  106.8468 90.61 DELETE tdmetl.gvs_zgvs_bseg_edw
#    8 0xF879E6613E39CC61E92478...   7834.1462  1.5%   307   25.5184 62... SELECT v_gvs_zgvs_bseg_edw
#    9 0x2B3FA3F89D3D4498CC6FFD...   7490.2099  1.4%    35  214.0060  2.56 INSERT SELECT gvs_zgvs_bseg_edw_hz tdmetl.gvs_zgvs_bseg_edw
#   10 0x6DBDA9B50953D60A486825...   6925.0820  1.3%    71   97.5364 25... INSERT SELECT d_tax_moth_data v_d_tax_profit_data

第三部分：每一种查询的详细统计结果

  • ID：查询的 ID 号，和上图的 Query ID 对应
  • Databases：数据库名
  • Hosts：各个 Host 执行的次数占比
  • Users：查询用户
  • Query_time distribution ：查询时间分布，长短体现区间占比
  • Tables：查询中涉及到的表
  • Explain：SQL 语句
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
# Query 1: 0.00 QPS, 0.05x concurrency, ID 0xFFF66E9B3D962FA319C8068B5C1997CD at byte 3105049
# This item is included in the report because it matches --limit.
# Scores: V/M = 25.32
# Time range: 2019-02-15T18:37:47 to 2019-04-03T21:18:48
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          3     260
# Exec time     39 211420s    322s   1078s    813s   1013s    143s    793s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0   2.03k       8       8       8       8       0       8
# String:
# Databases    tdmetl
# Hosts        10.138.225.51 (140/53%), 10.138.225.43 (69/26%)... 3 more
# Users        tdmsetldev
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
rollback\G

使用

1
2
3
4
5
6
7
8
# 分析全量慢查询日志
$ pt-query-digest slow.log > slow_report.log

# 分析最近12个小时内的查询
$ pt-query-digest --since=12h  slow.log > slow_report.log

# 分析最近1个月内的查询
$ pt-query-digest slow.log --since '2019-06-08 10:00:00' --until '2019-07-08 10:00:00' > slow_report.log