前言
我们通常使用 mysqldumpslow 工具来分析 MySQL 慢日志，这里推荐一个更加完善，输出有用信息更多的工具 pt-query-digest。
基本用法
1. 直接分析慢日志
pt-query-digest rds_slow_query.log > rds_slowlog_digest.log
2. 只分析针对某个用户的慢查询
pt-query-digest --filter '($event->{user} || "") =~ m/^rudonx/i' rds_slow_query.log> rds_slowlog_digest1.log
3. 只分析最近1天的慢查询
pt-query-digest --since=24h rds_slow_query.log > rds_slowlog_digest2.log
4. 查询所有全表扫描或者是 full join 慢查询
pt-query-digest --filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' rds_slow_query.log> rds_slowlog_digest3.log
5. 查询所有 select 类型的慢 SQL
pt-query-digest --filter '$event->{arg} =~ m/^select/i' rds_slow_query.log> rds_slowlog_digest4.log
6. 查询 query 大于 1M 的慢查询
pt-query-digest --filter '$event->{bytes} >= 1' rds_slow_query.log> rds_slowlog_digest5.log
7. 查询执行的 IP 地址发起的慢查询
pt-query-digest --filter '($event->{host} || $event->{ip} || "") =~ m/127.0.0.1/' rds_slow_query.log> rds_slowlog_digest6.log
8. 查询指定时间范围内的查询
pt-query-digest rds_slow_query.log --since '2022-03-22 17:30:00' --until '2022-03-22 18:00:00'> > slow_report7.log
输出内容解析
输出文件中的内容可以分为三个部分，解析如下：
第一部分
第一部分指名了输出结果的总体信息。
表明pt-query-digest 在运行过程中在用户态，内核态，以及分配的内存和虚拟内存的大小：
# 160ms user time, 10ms system time, 29.75M rss, 224.98M vsz
指明当前日期，运行 pt-query-digest 的主机名，以及文件名：
# Current date: Tue Mar 22 08:07:11 2022
# Hostname: ip-10-0-0-22.cn-northwest-1.compute.internal
# Files: rds_slow_query.log
表明语句的总数量，对查询条件进行参数化以后，总共有多少个不同的查询，每秒查询以及查询的并发
# Overall: 20 total, 7 unique, 0.00 QPS, 0.01x concurrency _______________
日志记录的时间范围：
# Time range: 2022-03-03T18:02:35 to 2022-03-15T18:08:17
这部分指明了语句在执行过程中的统计信息，分别为：
- total：总计
- min：最小
- max：最大
- avg：平均
- 95%：将所有值从小到大排列，位置位于95%的那个数
- stddev：标准差
- median：中位数，把所有值从小到大排列，位置位于中间那个数
同时还有执行时间(exec time) 以及 锁时间(lock time)，发送到客户端的行数(Rows sent)，扫描的行数(rows examine)，以及查询的字符数(query size)
**# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 6268s 1s 2887s 313s 1909s 733s 2s
# Lock time 3ms 0 660us 142us 541us 160us 80us
# Rows sent 12 0 1 0.60 0.99 0.49 0.99
# Rows examine 109.07M 0 9.54M 5.45M 9.30M 4.23M 8.86M
# Query size 1.26k 25 730 64.55 54.21 150.76 26.08**
第二部分
第二部分输出了分组统计信息。
- Rank：所有语句的排名，默认按查询时间降序排列。
- Query ID：语句的ID信息，是通过hash得到的。
- Response：总的响应时间
- time：该查询在本次分析中总的时间占比
- calls：执行次数，也就是说，本次分析总共有多少条这种类型的查询语句。
- R/Call：平均每次执行的响应时间。
- V/M：响应时间Variance-to-mean的比率
- Item：查询对象
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ============================= =============== ===== ========= =====
# 1 0x6A4427C529BE8F5939FB73A8... 6242.4422 99.6% 5 1248.4884 82... CALL add_t_user
# 2 0x62335394101D6CACEC5B16DB... 15.6641 0.2% 10 1.5664 0.01 SELECT t_user
# MISC 0xMISC 10.3380 0.2% 5 2.0676 0.0 <5 ITEMS>
第三部分
第三部分指明了每一种查询的详细统计信息，是对第二部分输出内容的扩展，其中包括：
- ID：查询的ID号，和第二部分的 Query ID对应
- Databases：涉及到的数据库名
- Hosts：运行语句客户端分布情况
- Users：各个用户执行的次数占比
- Query_time distribution ：查询时间分布
- Tables：查询中涉及到的表
- Explain：涉及到的 SQL 语句
# Query 1: 0.00 QPS, 0.01x concurrency, ID 0x6A4427C529BE8F5939FB73A8E21D6C8C at byte 7960
# This item is included in the report because it matches --limit.
# Scores: V/M = 825.53
# Time range: 2022-03-03T18:10:41 to 2022-03-11T16:32:31
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 25 5
# Exec time 99 6242s 196s 2887s 1248s 2821s 1015s 964s
# Lock time 60 2ms 148us 660us 344us 657us 216us 194us
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Query size 64 832 25 730 166.40 719.66 277.93 24.84
# String:
# Databases insert_test
# Hosts 180.184.74.156 (3/60%), 192.168.1.57 (2/40%)
# Users rudonx
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
call add_t_user(10000000)\G
总结
从上面可以看出，pt-query-digest 具有多种使用姿势，输出内容也比 mysqldumpslow 更加丰富，是一款分析慢日志的利器。
参考文档
[1]https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html
如果您有其他问题，欢迎您联系火山引擎技术支持服务
