记一次使用pt-query-digest工具分析MySQL慢查询日志

最近遇到了MySQL性能问题，使用percona 的 pt-query-digest工具分析性能的瓶颈点。并且pt-query-digest工具要优于MySQL本身自带的mysqldumpslow工具。

查看pt-query-digest工具在ubuntu下的安装流程请看：ubuntu下安装pt-query-digest_一缕阳光a的博客-CSDN博客https://blog.csdn.net/zgaoq/article/details/124710484?spm=1001.2014.3001.5502

先将结果贴上，然后在分析：

[root@xxx log]# pt-query-digest   mysql-slow.log

# 110ms user time, 20ms system time, 37.57M rss, 49.25M vsz
# Current date: Wed May 11 15:49:08 2022
# Hostname: aaaa
# Files: /home/ddd/slow_query/slow3306_small.log
# Overall: 10 total, 7 unique, 0.00 QPS, 0.02x concurrency _______________
# Time range: 2022-04-27T15:39:28 to 2022-04-28T14:55:06
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          1648s   500ms    827s    165s    271s    235s     29s
# Lock time            6ms       0     1ms   629us   925us   343us   626us
# Rows sent              1       0       1    0.10       0    0.30       0
# Rows examine      25.35M   1.48k   4.81M   2.53M   4.70M   2.21M   4.70M
# Rows affecte       1.43M       0 488.28k 146.48k 485.50k 222.49k       0
# Bytes sent         4.64G       0   1.08G 475.62M   1.08G 506.28M 106.64M
# Query size           864      13     543   78.55  118.34  147.95   21.45

# Profile
# Rank Query ID                            Response time   Calls R/Call   
# ==== =================================== =============== ===== ======== 
#    1 0x7738DBC3D65602BBA1A040E0905E1052  1024.3274 62.2%     2 512.1637 38... UPDATE sbtest?
#    2 0x43ED0F75107CE7B9724C1FA36FFD880F   590.3572 35.8%     4 147.5893 97.58 UPDATE sbtest?
# MISC 0xMISC                                33.2763  2.0%     4   8.3191   0.0 <4 ITEMS>

# Query 1: 0.00 QPS, 0.74x concurrency, ID 0x7738DBC3D65602BBA1A040E0905E1052 at byte 4018
# This item is included in the report because it matches --limit.
# Scores: V/M = 387.17
# Time range: 2022-04-28T14:32:08 to 2022-04-28T14:55:06
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         20       2
# Exec time     62   1024s    197s    827s    512s    827s    445s    512s
# Lock time     29     2ms   926us   932us   929us   932us     4us   929us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  37   9.61M   4.81M   4.81M   4.81M   4.81M       0   4.81M
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    46   2.16G   1.08G   1.08G   1.08G   1.08G    4.24   1.08G
# Query size     5      48      24      24      24      24       0      24
# String:
# Databases    test
# Hosts        127.0.0.1
# Last errno   1180
# Users        xxxxx
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
update sbtest1 set k=k+2\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  k=k+2 from sbtest1 \G

# Query 2: 0.00 QPS, 0.01x concurrency, ID 0x43ED0F75107CE7B9724C1FA36FFD880F at byte 1793
# This item is included in the report because it matches --limit.
# Scores: V/M = 97.58
# Time range: 2022-04-27T16:00:34 to 2022-04-28T14:07:24
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         40       4
# Exec time     35    590s     23s    273s    148s    271s    120s    265s
# Lock time     37     2ms   536us   638us   596us   626us    41us   596us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  41  10.49M 488.28k   4.77M   2.62M   4.70M   2.11M   4.70M
# Rows affecte  66 976.56k       0 488.28k 244.14k 485.50k 242.75k 485.50k
# Bytes sent    51   2.38G 109.52M   1.08G 609.52M   1.08G 500.00M   1.08G
# Query size    10      88      22      22      22      22       0      22
# String:
# Databases    test
# Hosts        127.0.0.1
# Last errno   0 (2/50%), 1180 (2/50%)
# Users        xxxx
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
update sbtest1 set d=1\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  d=1 from sbtest1 \G

下面根据各个部分进行详解：

第一部分：输出结果的总体信息

说明：执行过程中在用户中所花费的所有时间；
执行过程中内核空间中所花费的所有时间
pt-query-digest进程所分配的内存大小
pt-query-digest进程所分配的虚拟内存大小
# 120ms user time, 10ms system time, 37.39M rss, 49.25M vsz

说明：当前日期
# Current date: Wed May 11 15:30:59 2022

说明：执行pt-query-digest的主机名
# Hostname: aaaaa

说明：被分析的文件名
# Files: /home/ddd/slow_query/slow3306_small.log

说明：语句总数量，唯一语句数量，每秒查询量，查询的并发
# Overall: 10 total, 7 unique, 0.00 QPS, 0.02x concurrency _______________

说明：执行过程中日志记录的时间范围
# Time range: 2022-04-27T15:39:28 to 2022-04-28T14:55:06

# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
说明：执行时间
# Exec time          1648s   500ms    827s    165s    271s    235s     29s
说明：锁占用时间
# Lock time            6ms       0     1ms   629us   925us   343us   626us
说明：发送到客户端的行数
# Rows sent              1       0       1    0.10       0    0.30       0
说明：扫描的语句行数
# Rows examine      25.35M   1.48k   4.81M   2.53M   4.70M   2.21M   4.70M
说明：操作的行数
# Rows affecte       1.43M       0 488.28k 146.48k 485.50k 222.49k       0
说明：发送到客户端的字符数
# Bytes sent         4.64G       0   1.08G 475.62M   1.08G 506.28M 106.64M
说明：查询的字符数
# Query size           864      13     543   78.55  118.34  147.95   21.45

第二部分：输出总体统计信息

SQL语句的等级
Query ID：去掉了中间的符号
Response time：响应时间
Calls: 响应次数 
R/Call：每次响应的时间

# Profile
# Rank Query ID                            Response time   Calls R/Call   
# ==== =================================== =============== ===== ========
#    1 0x7738DBC3D65602BBA1A040E0905E1052  1024.3274 62.2%     2 512.1637 38... UPDATE sbtest?
#    2 0x43ED0F75107CE7B9724C1FA36FFD880F   590.3572 35.8%     4 147.5893 97.58 UPDATE sbtest?
# MISC 0xMISC                                33.2763  2.0%     4   8.3191   0.0 <4 ITEMS>

第三部分：输出每列查询的详细信息

以下面这个为例：

说明：查询队列1：每秒查询量，查询的并发，队列1的ID值，4018：表示文中偏移量（查看方法在下面‘偏1’中）
# Query 1: 0.00 QPS, 0.74x concurrency, ID 0x7738DBC3D65602BBA1A040E0905E1052 at byte 4018
# This item is included in the report because it matches --limit.
# Scores: V/M = 387.17
# Time range: 2022-04-28T14:32:08 to 2022-04-28T14:55:06
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         20       2
# Exec time     62   1024s    197s    827s    512s    827s    445s    512s
# Lock time     29     2ms   926us   932us   929us   932us     4us   929us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  37   9.61M   4.81M   4.81M   4.81M   4.81M       0   4.81M
# Rows affecte   0       0       0       0       0       0       0       0
# Bytes sent    46   2.16G   1.08G   1.08G   1.08G   1.08G    4.24   1.08G
# Query size     5      48      24      24      24      24       0      24
# String:
说明：使用的数据库名称
# Databases    test
说明：使用的主机IP
# Hosts        127.0.0.1
说明：上次的错误码
# Last errno   1180
说明：使用的用户名
# Users        xxx
说明：查询时间分布
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
说明：执行的慢语句信息
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
update sbtest1 set k=k+2\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  k=k+2 from sbtest1 \G

总之，percona pt-query-digest工具比较全面的分析了MySQL的慢查询日志，要比MySQL自身的慢日志工具mysqldumpslow要优秀，因此最好使用percona的 pt-query-digest 工具进行慢日志查询。