使用 percona-toolkit 工具分析 MySQL 慢日志

默认总耗时时长超过 3s 的语句会被记录到慢日志中。时长可通过参数 Long_query_time 进行调整，参数详细介绍及修改参数的步骤请参见参数介绍和修改配置参数。

本小节主要介绍如何通过 percona-toolkit 工具进行 MySQL 慢日志分析。

获取 percona-toolkit 工具路径

percona-toolkit 工具在主实例/只读实例节点所在主机上。

工具集路径：/home/ubuntu/percona-toolkit/bin/
慢日志统计工具路径：/home/ubuntu/percona-toolkit/bin/pt-query-digest

获取慢日志路径

日志保存在主实例/只读实例节点所在主机上。

慢日志保存路径：/data/mysql-log/mysql-slow/mysql-slow.log

分析慢日志

登录主实例/只读实例节点所在主机。
执行以下命令，分析 mysql-slow.log 中的相关慢日志，并输出分析结果（本文以输出到文本文件 A.txt 为例）。
```
/home/ubuntu/percona-toolkit/bin/pt-query-digest /data/mysql-log/mysql-slow/mysql-slow.log > /data/A.txt
```
参数说明：
- /home/ubuntu/percona-toolkit/bin/pt-query-digest：慢日志统计工具路径。
- /data/mysql-log/mysql-slow/mysql-slow.log：慢日志保存路径。
- A.txt：分析结果的文本文件名称，可以自定义。

分析结果示例

打开 A.txt 文件，即可看到慢日志分析结果。

# 200ms user time, 10ms system time, 29.74M rss, 36.67M vsz
# Current date: Thu Dec 29 15:49:04 2022
# Hostname: i-6emrs19i
# Files: /data/mysql-log/mysql-slow/mysql-slow.log
# Overall: 8 total, 2 unique, 0.00 QPS, 0.03x concurrency ________________
# Time range: 2022-12-29T14:16:26 to 2022-12-29T15:38:52
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           158s      3s     51s     20s     49s     15s     20s
# Lock time            2ms   148us     1ms   306us     1ms   276us   224us
# Rows sent              0       0       0       0       0       0       0
# Rows examine      33.50M   1.00M   8.00M   4.19M   7.65M   2.54M   4.93M
# Rows affecte      20.75M 512.00k   8.00M   2.59M   7.65M   2.22M   2.42M
# Bytes sent           446      14      62   55.75   59.77   15.19   59.77
# Query size           407      22      55   50.88   54.21   10.83   54.21

# Profile
# Rank Query ID                           Response time  Calls R/Call  V/M
# ==== ================================== ============== ===== ======= ===
#    1 0x1F32B88358F38D34F85C6FAE9E2CE01A 106.5287 67.5%     7 15.2184  7.13 INSERT SELECT apple_test
#    2 0xCED5D8C62622BEA1DE7AD589E9A48AA9  51.2485 32.5%     1 51.2485  0.00 DELETE apple_test

# Query 1: 0.00 QPS, 0.02x concurrency, ID 0x1F32B88358F38D34F85C6FAE9E2CE01A at byte 3850
# This item is included in the report because it matches --limit.
# Scores: V/M = 7.13
# Time range: 2022-12-29T14:16:26 to 2022-12-29T15:38:52
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         87       7
# Exec time     67    107s      3s     36s     15s     35s     10s     11s
# Lock time     57     1ms   148us   315us   202us   301us    52us   159us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  76  25.50M   1.00M   8.00M   3.64M   7.65M   2.29M   2.88M
# Rows affecte  61  12.75M 512.00k   4.00M   1.82M   3.86M   1.14M   1.46M
# Bytes sent    96     432      61      62   61.71   59.77       0   59.77
# Query size    94     385      55      55      55      55       0      55
# String:
# Databases    testdb
# Hosts        localhost
# Last errno   0
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `testdb` LIKE 'apple_test'\G
#    SHOW CREATE TABLE `testdb`.`apple_test`\G
insert into apple_test(a, b) select a,b from apple_test\G

# Query 2: 0 QPS, 0x concurrency, ID 0xCED5D8C62622BEA1DE7AD589E9A48AA9 at byte 4190
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2022-12-29T15:28:18
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         12       1
# Exec time     32     51s     51s     51s     51s     51s       0     51s
# Lock time     42     1ms     1ms     1ms     1ms     1ms       0     1ms
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine  23   8.00M   8.00M   8.00M   8.00M   8.00M       0   8.00M
# Rows affecte  38   8.00M   8.00M   8.00M   8.00M   8.00M       0   8.00M
# Bytes sent     3      14      14      14      14      14       0      14
# Query size     5      22      22      22      22      22       0      22
# String:
# Databases    testdb
# Hosts        localhost
# Last errno   0
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `testdb` LIKE 'apple_test'\G
#    SHOW CREATE TABLE `testdb`.`apple_test`\G
delete from apple_test\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  apple_test\G

分析结果说明

结果示例中有两类耗时较长的语句，如下：

insert into apple_test(a, b) select a,b from apple_test;
delete from apple_test;

可将结果分为三部分：

第一部分：总体概要信息

   # 200ms user time, 10ms system time, 29.74M rss, 36.67M vsz
   # Current date: Thu Dec 29 15:49:04 2022
   # Hostname: i-6emrs19i
   # Files: /data/mysql-log/mysql-slow/mysql-slow.log
   # Overall: 8 total, 2 unique, 0.00 QPS, 0.03x concurrency ________________
   # Time range: 2022-12-29T14:16:26 to 2022-12-29T15:38:52
   # Attribute          total     min     max     avg     95%  stddev  median
   # ============     ======= ======= ======= ======= ======= ======= =======
   # Exec time           158s      3s     51s     20s     49s     15s     20s
   # Lock time            2ms   148us     1ms   306us     1ms   276us   224us
   # Rows sent              0       0       0       0       0       0       0
   # Rows examine      33.50M   1.00M   8.00M   4.19M   7.65M   2.54M   4.93M
   # Rows affecte      20.75M 512.00k   8.00M   2.59M   7.65M   2.22M   2.42M
   # Bytes sent           446      14      62   55.75   59.77   15.19   59.77
   # Query size           407      22      55   50.88   54.21   10.83   54.21

参数说明如下：

参数名称	参数说明
Current date	分析结果生成的时间。
Hostname	主机名。
Files	分析的文件所在路径。
Overall	分析的 SQL 数量统计。本示例中总共存在的慢 SQL 有 8 条，实际上分为两类，insert 和 delete。 total 为总语句数量。 unique 为唯一查询数量，即对查询条件进行参数化以后，统计的总共有多少个不同的查询。
Time range	本次分析中所以慢 SQL 所在的时间段。
Exec time	SQL 执行时间。 total 总时间。 min 最短时间。 max 最长时间。 avg 平均时间。 95% 把所有耗时从小到大排列，位置最接近 95% 的那个数。 stddev 标准偏差。 median 中位数。
Lock time	锁占用的时间。
Row sent	发送到客户端的行数。
Row examine	SQL 语句扫描行数。
Bytes sent	发送到客户端的字节数。
Query size	查询的字符数。

参数名称

参数说明

Current date

分析结果生成的时间。

Hostname

主机名。

Files

分析的文件所在路径。

Overall

分析的 SQL 数量统计。
本示例中总共存在的慢 SQL 有 8 条，实际上分为两类，insert 和 delete。

total 为总语句数量。
unique 为唯一查询数量，即对查询条件进行参数化以后，统计的总共有多少个不同的查询。

Time range

本次分析中所以慢 SQL 所在的时间段。

Exec time

SQL 执行时间。

total 总时间。
min 最短时间。
max 最长时间。
avg 平均时间。
95% 把所有耗时从小到大排列，位置最接近 95% 的那个数。
stddev 标准偏差。
median 中位数。

Lock time

锁占用的时间。

Row sent

发送到客户端的行数。

Row examine

SQL 语句扫描行数。

Bytes sent

发送到客户端的字节数。

Query size

查询的字符数。

第二部分：SQL 概要信息

   # Profile
   # Rank Query ID                           Response time  Calls R/Call  V/M
   # ==== ================================== ============== ===== ======= ===
   #    1 0x1F32B88358F38D34F85C6FAE9E2CE01A 106.5287 67.5%     7 15.2184  7.13 INSERT SELECT apple_test
   #    2 0xCED5D8C62622BEA1DE7AD589E9A48AA9  51.2485 32.5%     1 51.2485  0.00 DELETE apple_test

参数说明如下：

参数名称	参数说明
Rank	SQL 在此次统计中的耗时排名。
Query ID	pt-query-digest 为此类 SQL 生成的唯一 ID，可以通过此 ID 找到本 SQL 对应的详细信息。
Response time	此类 SQL 总耗时时间。全部 Query 加起来就是所有慢 SQL 的总耗时时间。百分比数值是该类 SQL 耗时占此次统计慢 SQL 总耗时时间的百分比。全部 Query 加起来就是 100%。
calls	执行次数，即本次分析总共有多少条这种类型的 SQL 语句。
R/Call	平均每次执行的响应时间。
V/M	响应时间的方差与平均比。
-	大致的 SQL 语句，体现 SQL 的类型。

参数名称

参数说明

Rank

SQL 在此次统计中的耗时排名。

Query ID

pt-query-digest 为此类 SQL 生成的唯一 ID，可以通过此 ID 找到本 SQL 对应的详细信息。

Response time

此类 SQL 总耗时时间。全部 Query 加起来就是所有慢 SQL 的总耗时时间。
百分比数值是该类 SQL 耗时占此次统计慢 SQL 总耗时时间的百分比。全部 Query 加起来就是 100%。

calls

执行次数，即本次分析总共有多少条这种类型的 SQL 语句。

R/Call

平均每次执行的响应时间。

V/M

响应时间的方差与平均比。

大致的 SQL 语句，体现 SQL 的类型。

第三部分：SQL 详细信息

   # Query 1: 0.00 QPS, 0.02x concurrency, ID 0x1F32B88358F38D34F85C6FAE9E2CE01A at byte 3850
   # This item is included in the report because it matches --limit.
   # Scores: V/M = 7.13
   # Time range: 2022-12-29T14:16:26 to 2022-12-29T15:38:52
   # Attribute    pct   total     min     max     avg     95%  stddev  median
   # ============ === ======= ======= ======= ======= ======= ======= =======
   # Count         87       7
   # Exec time     67    107s      3s     36s     15s     35s     10s     11s
   # Lock time     57     1ms   148us   315us   202us   301us    52us   159us
   # Rows sent      0       0       0       0       0       0       0       0
   # Rows examine  76  25.50M   1.00M   8.00M   3.64M   7.65M   2.29M   2.88M
   # Rows affecte  61  12.75M 512.00k   4.00M   1.82M   3.86M   1.14M   1.46M
   # Bytes sent    96     432      61      62   61.71   59.77       0   59.77
   # Query size    94     385      55      55      55      55       0      55
   # String:
   # Databases    testdb
   # Hosts        localhost
   # Last errno   0
   # Users        root
   # Query_time distribution
   #   1us
   #  10us
   # 100us
   #   1ms
   #  10ms
   # 100ms
   #    1s  ################################################
   #  10s+  ################################################################
   # Tables
   #    SHOW TABLE STATUS FROM `testdb` LIKE 'apple_test'\G
   #    SHOW CREATE TABLE `testdb`.`apple_test`\G
   insert into apple_test(a, b) select a,b from apple_test\G

   # Query 2: 0 QPS, 0x concurrency, ID 0xCED5D8C62622BEA1DE7AD589E9A48AA9 at byte 4190
   # This item is included in the report because it matches --limit.
   # Scores: V/M = 0.00
   # Time range: all events occurred at 2022-12-29T15:28:18
   # Attribute    pct   total     min     max     avg     95%  stddev  median
   # ============ === ======= ======= ======= ======= ======= ======= =======
   # Count         12       1
   # Exec time     32     51s     51s     51s     51s     51s       0     51s
   # Lock time     42     1ms     1ms     1ms     1ms     1ms       0     1ms
   # Rows sent      0       0       0       0       0       0       0       0
   # Rows examine  23   8.00M   8.00M   8.00M   8.00M   8.00M       0   8.00M
   # Rows affecte  38   8.00M   8.00M   8.00M   8.00M   8.00M       0   8.00M
   # Bytes sent     3      14      14      14      14      14       0      14
   # Query size     5      22      22      22      22      22       0      22
   # String:
   # Databases    testdb
   # Hosts        localhost
   # Last errno   0
   # Users        root
   # Query_time distribution
   #   1us
   #  10us
   # 100us
   #   1ms
   #  10ms
   # 100ms
   #    1s
   #  10s+  ################################################################
   # Tables
   #    SHOW TABLE STATUS FROM `testdb` LIKE 'apple_test'\G
   #    SHOW CREATE TABLE `testdb`.`apple_test`\G
   delete from apple_test\G
   # Converted for EXPLAIN
   # EXPLAIN /*!50100 PARTITIONS*/
   select * from  apple_test\G

Query 1、Query 2 是此次分析结果中出现的两类慢 SQL。

参数说明：

列表参数可以参考第一部分，其他参数说明如下：

参数名称	参数说明
Databases	SQL 执行的数据库。
Users	SQL 执行的用户。
Query_time distribution	查询时长的分布，此次统计中的两个 SQL 语句执行时间都在秒级和十秒级。

参数名称

参数说明

Databases

SQL 执行的数据库。

Users

SQL 执行的用户。

Query_time distribution

查询时长的分布，此次统计中的两个 SQL 语句执行时间都在秒级和十秒级。

如下表示如果用户想优化在慢日志中看到的 SQL 语句，可能需要检查表的状态以及表结构，这些就是相关的 SQL 语句。
```
SHOW TABLE STATUS FROM `testdb` LIKE 'apple_test'\G
SHOW CREATE TABLE `testdb`.`apple_test`\G
```
delete from apple_test\G 是此类慢 SQL 语句的示例。
如下是 SQL 语句的相关执行计划，但是对于非 select 语句通常不能再次执行来查看执行计划，因此 pt-query-digest 会尝试将 SQL 转化为等效的 select 语句然后展示出来。
```
Converted for EXPLAIN
EXPLAIN /*!50100 PARTITIONS*/
select * from  apple_test\G
```