博客 / Linux/ pt-query-digest分析慢查询日志后输出的结果怎么看?

pt-query-digest分析慢查询日志后输出的结果怎么看?

pt-query-digest分析慢查询日志后输出的结果怎么看?

pt-query-digest 输出结果解读

使用 pt-query-digest mysql-slow.log 命令分析慢查询日志后,会生成一份详细的报告。以下是对报告各部分的解读。

报告头部信息

报告开头部分包含工具执行环境和日志文件的元数据:

# A software update is available:
#   * The current version for Percona::Toolkit is 2.2.9.

# 170ms user time, 10ms system time, 26.00M rss, 213.39M vsz
# Current date: Mon Jul 28 09:55:34 2014
# Hostname: lump.group.com
# Files: mysql-slow.log
# Overall: 5 total, 4 unique, 0.02 QPS, 0.04x concurrency ________________
# Time range: 2014-07-28 09:50:30 to 09:54:50
  • user time / system time / rss / vsz:工具分析日志时消耗的 CPU 时间、物理内存和虚拟内存。
  • Current date / Hostname:执行分析的系统时间和主机名(注意:这是运行分析工具的主机,不一定是数据库服务器)。
  • Files:被分析的日志文件名称。
  • Overall:日志中查询语句总数、去重后的唯一语句数、平均每秒查询数(QPS)以及估算的并发度。
  • Time range:日志记录的时间范围。

总体统计摘要

这部分提供了所有查询的聚合统计信息:

# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            10s      1s      3s      2s      3s   753ms      1s
# Lock time          196us       0    79us    39us    76us    33us    42us
# Rows sent          1.40k       0     716     287  685.39  335.14    3.89
# Rows examine      15.32k       0  11.13k   3.06k  10.80k   4.02k   2.06k
# Rows affecte           0       0       0       0       0       0       0
# Bytes sent        72.42k      11  38.85k  14.48k  38.40k  17.57k  234.30
# Query size           807       6     342  161.40  329.68  146.53  112.70
  • Exec time:查询执行时间。
  • Lock time:锁等待时间。
  • Rows sent:返回给客户端的行数。
  • Rows examine:扫描的行数(主要针对 SELECT 语句)。
  • Rows affecte:受影响的行数(针对 INSERT、UPDATE、DELETE 语句)。
  • Bytes sent:返回结果集的大小(字节)。
  • Query size:查询语句的长度(字符数)。

每列含义:total(总计)、min(最小值)、max(最大值)、avg(平均值)、95%(95分位数)、stddev(标准差)、median(中位数)。

查询性能概览(Profile)

这部分按响应时间对查询进行排名:

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ===============
#    1 0x4A9CF4735A0490F2  3.1898 31.9%     1 3.1898  0.00 SELECT history_uint
#    2 0x2B0044BDE0960A2F  2.6991 27.0%     1 2.6991  0.00 SELECT history
#    3 0x813031B8BBC3B329  2.5755 25.7%     2 1.2877  0.00 COMMIT
#    4 0x469563A79E581DDB  1.5380 15.4%     1 1.5380  0.00 SELECT sessions
  • Rank:查询排名,默认按响应时间降序排列。
  • Query ID:查询的指纹(Fingerprint),通过去除空格、文本变量并标准化后生成的唯一标识。
  • Response time:总响应时间及其在全部查询时间中的占比。
  • Calls:该查询被执行的次数。
  • R/Call:每次执行的平均响应时间。
  • V/M:响应时间的方差与均值之比(离散指数),用于衡量响应时间的波动性。
  • Item:查询的简化表示。

详细查询分析

报告随后会对每个独立的查询(Query ID)进行详细分析。以第一个查询为例:

# Query 1: 0 QPS, 0x concurrency, ID 0x4A9CF4735A0490F2 at byte 591 ______
  • QPS:该查询的每秒查询数。
  • concurrency:估算的并发度。
  • ID:查询指纹的十六进制表示。可用于过滤(使用 --filter 选项时需移除 0x 前缀)。
  • at byte 591:该查询在日志文件中的字节偏移量,可用于快速定位。

接着是该查询的详细统计表:

# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         20       1
# Exec time     31      3s      3s      3s      3s      3s       0      3s
# Lock time     40    79us    79us    79us    79us    79us       0    79us
# Rows sent     49     715     715     715     715     715       0     715
# Rows examine  13   2.09k   2.09k   2.09k   2.09k   2.09k       0   2.09k
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    45  33.31k  33.31k  33.31k  33.31k  33.31k       0  33.31k
# Query size    42     342     342     342     342     342       0     342

第一列 pct 表示该查询的该项指标占所有查询总和的百分比。例如 Count 20 表示该查询的执行次数占总执行次数的 20%。

后续部分提供了更多上下文信息:

  • String:数据库、用户、主机等上下文信息。
  • Query_time distribution:查询执行时间的分布直方图(示例中显示所有执行都落在 1-10 秒区间)。
  • Tables:提供了用于获取表状态和结构的 SQL 语句:
    • SHOW TABLE STATUS FROM `zabbix` LIKE 'history_uint'G:查看表的大小等统计信息。
    • SHOW CREATE TABLE `zabbix`.`history_uint`G:查看表的完整创建语句(结构)。
  • EXPLAIN:工具会自动生成(或转换出)一个可用于查看执行计划的 SELECT 语句,帮助进行查询优化分析。

本文基于公开资料整理,旨在帮助理解 pt-query-digest 的输出格式。实际输出可能因工具版本和选项不同而略有差异。

发表评论

您的邮箱不会公开。必填项已用 * 标注。