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 的输出格式。实际输出可能因工具版本和选项不同而略有差异。