一、前言

MySQL 总耗时时长超过参数的语句会被记录到慢日志中。时长可通过参数 Long_query_time 进行调整，本文主要介绍如何通过 pt-query-digest 工具进行 MySQL 慢日志分析。

pt-query-digest 仓库地址：https://github.com/percona/percona-toolkit

二、安装 pt-query-digest

需要准备一台 Linux 服务器，用于安装工具。

步骤1. 准备一台 Linux 服务器。

建议Linux 服务器与 MySQL 群部署在同一局域网下。

步骤2. 登录 Linux 服务器。

步骤3. 执行以下命令，下载工具集。

wget https://downloads.percona.com/downloads/percona-toolkit/3.5.0/binary/tarball/percona-toolkit-3.5.0_x86_64.tar.gz

步骤4. 执行以下命令，解压安装包。

tar -zxvf ./percona-toolkit-3.5.0_x86_64.tar.gz

步骤5. 进入安装目录，安装perl模块，制定依赖路径。

perl Makefile.PL PREFIX=/usr/local/percona-toolkit

报错如下：

Can't locate ExtUtils/MakeMaker.pm in @INC (@INC contains: /usr/local/lib/perl5 /usr/local/share/perl5 /usr/lib/perl5/vendor_perl /usr/share/perl5/vendor_perl /usr/lib/perl5 /usr/share/perl5 .) at Makefile.PL line 2.
BEGIN failed--compilation aborted at Makefile.PL line 2.

步骤6. 使用以下命令解决。

yum install perl-ExtUtils-MakeMaker

步骤7. 安装依赖包并再次执行编译。

yum install perl-DBD-MySQL
yum -y install perl-Digest-MD5

再次安装perl模块：

perl Makefile.PL PREFIX=/usr/local/percona-toolkit

步骤8. 编译安装。

make && make install

控制台输出如下，则编译安装成功。

Installing /usr/local/percona-toolkit/bin/pt-config-diff
Installing /usr/local/percona-toolkit/bin/pt-stalk
Appending installation info to /usr/local/percona-toolkit/lib64/perl5/perllocal.pod`

步骤9. 安装包解压后即可使用工具。

工具集路径：./percona-toolkit-3.5.0/bin/。
慢日志统计工具路径：./percona-toolkit-3.5.0/bin/pt-query-digest。

三、确认MySQL配置

我们可以用以下命令查看慢查询次数

使用该命令只能查看慢查询次数，但是我们没有办法知道是哪些查询产生了慢查询，如果想要知道是哪些查询导致的慢查询，那么我们必须修改 mysql 的配置文件。查看 mysql 的配置文件（windows系统是my.ini，linux系统是my.cnf），在 [mysqld] 下面加上以下代码

# General and Slow logging.
log-output=FILE
general-log=0
general_log_file="DESKTOP-MLD0KTS.log"
slow-query-log=1
slow_query_log_file="DESKTOP-MLD0KTS-slow.log"
long_query_time=1

此时我们在 mysql 中运行以下命令，可以看到 slow_query_log 是 ON 状态，log_file 也是我们指定的文件

只要查询时间大于 1s，查询语句都将存入日志文件

查看 mysql 安装目录下的 data 目录，该目录会产生一个慢查询日志文件：mysql_slow.log，该文件内容如下

在该日志文件中，我们可以知道慢查询产生的时间，最终产生了几行结果，测试了几行结果，以及运行语句是什么。

四、分析慢日志

步骤1. 将获取到的慢日志传到工具集所在的Linux 服务器上。

假如慢日志在 Linux 服务器上的保存路径为：/data/mysql-log/mysql-slow/mysql-slow.log。

步骤2. 登录 Linux 服务器。

步骤3. 执行以下命令，分析 mysql-slow.log 中的相关慢日志，并输出分析结果（本文以输出到文本文件 A.txt 为例）。

/home/percona-toolkit-3.5.0/bin/pt-query-digest /data/mysql-log/mysql-slow/mysql-slow.log > /data/A.txt

参数说明：

/home/percona-toolkit-3.5.0/bin/pt-query-digest：慢日志统计工具路径。
/data/mysql-log/mysql-slow/mysql-slow.log：慢日志保存路径。
A.txt：分析结果的文本文件名称，可以自定义。

五、分析结果示例

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


# 2251.6s user time, 5.5s system time, 133.95M rss, 298.91M vsz
# Current date: Wed Jul 17 16:34:40 2024
# Hostname: toolkit
# Files: /data/mysql-log/mysql-slow/mysql-slow.log
# Overall: 17.12M total, 998 unique, 7.32 QPS, 0.02x concurrency _________
# Time range: 2024-06-19T07:57:46 to 2024-07-16T09:28:30
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time         51426s    47us     52s     3ms    16ms    76ms   185us
# Lock time            81s       0     26s     4us     2us     9ms     1us
# Rows sent        382.85M       0   1.06M   23.45   80.10   1.66k       0
# Rows examine      40.91G       0  22.48M   2.51k  11.91k  51.86k   36.69
# Query size         4.17G       6 511.86k  261.69  313.99   3.16k  174.84

# Profile
# Rank Query ID                            Response time   Calls    R/Call
# ==== =================================== =============== ======== ======
#   22 0x6C545CFB55365122F1256A27240AEFC7    85.0967  0.2%       16  5.3185  0.02 INSERT sbtest?
#   25 0x410C2605CF6B250BE96B374065B13356    70.5435  0.1%       14  5.0388  0.00 UPDATE sbtest?
#   32 0xDDBF88031795EC65EAB8A8A8BEEFF705    51.7845  0.1%       10  5.1784  0.02 DELETE sbtest?
# MISC 0xMISC                              2053.0152  4.0%  1049587  0.0020   0.0 <977 ITEMS>

# Query 22: 0.00 QPS, 0.01x concurrency, ID 0x6C545CFB55365122F1256A27240AEFC7 at byte 93966
# This item is included in the report because it matches --outliers.
# Scores: V/M = 0.02
# Time range: 2024-06-20T03:00:18 to 2024-06-20T07:41:55
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      16
# Exec time      0     85s      5s      6s      5s      6s   343ms      5s
# Lock time      0    29us     1us    11us     1us     1us     2us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0   3.87k     247     248  247.75  246.02       0  246.02
# String:
# Databases    loadtest
# Hosts        192.168.0.9 (12/75%), 192.168.0.43 (4/25%)
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `loadtest` LIKE 'sbtest33'\G
#    SHOW CREATE TABLE `loadtest`.`sbtest33`\G
INSERT INTO sbtest33 (id, k, c, pad) VALUES (4104021, 5021939, '53760848582-61772455757-13756174941-26340673050-49215508093-02614923825-17307273142-19544845219-97933526313-59521997160', '64542834346-20908256378-17685105766-32329763748-20082021238')\G

# Query 25: 0.01 QPS, 0.04x concurrency, ID 0x410C2605CF6B250BE96B374065B13356 at byte 163533
# This item is included in the report because it matches --outliers.
# Scores: V/M = 0.00
# Time range: 2024-06-20T07:10:19 to 2024-06-20T07:41:55
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      14
# Exec time      0     71s      5s      5s      5s      5s       0      5s
# Lock time      0    26us       0    11us     1us     2us     2us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0      14       1       1       1       1       0       1
# Query size     0   2.19k     159     160  159.93  158.58       0  158.58
# String:
# Databases    loadtest
# Hosts        192.168.0.9
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `loadtest` LIKE 'sbtest23'\G
#    SHOW CREATE TABLE `loadtest`.`sbtest23`\G
UPDATE sbtest23 SET c='34687144716-21423942504-47610582398-10509211856-75392001994-55359681530-97613250617-41262877067-76451927676-70915317903' WHERE id=4717805\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  c='34687144716-21423942504-47610582398-10509211856-75392001994-55359681530-97613250617-41262877067-76451927676-70915317903' from sbtest23 where  id=4717805\G

# Query 32: 0.00 QPS, 0.00x concurrency, ID 0xDDBF88031795EC65EAB8A8A8BEEFF705 at byte 159358
# This item is included in the report because it matches --outliers.
# Scores: V/M = 0.02
# Time range: 2024-06-20T03:00:18 to 2024-06-20T07:35:55
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      10
# Exec time      0     52s      5s      6s      5s      5s   321ms      5s
# Lock time      0    10us       0     2us     1us     1us       0     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0      10       1       1       1       1       0       1
# Query size     0     369      36      37   36.90   36.69    0.50   36.69
# String:
# Databases    loadtest
# Hosts        192.168.0.9 (6/60%), 192.168.0.43 (4/40%)
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `loadtest` LIKE 'sbtest21'\G
#    SHOW CREATE TABLE `loadtest`.`sbtest21`\G
DELETE FROM sbtest21 WHERE id=4295284\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  sbtest21 WHERE id=4295284\G

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

INSERT INTO sbtest33 (id, k, c, pad) VALUES (4104021, 5021939, '53760848582-61772455757-13756174941-26340673050-49215508093-02614923825-17307273142-19544845219-97933526313-59521997160', '64542834346-20908256378-17685105766-32329763748-20082021238')；
UPDATE sbtest23 SET c='34687144716-21423942504-47610582398-10509211856-75392001994-55359681530-97613250617-41262877067-76451927676-70915317903' WHERE id=4717805；
DELETE FROM sbtest21 WHERE id=4295284；

可将结果分为三部分：

第一部分：总体概要信息

该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小
# 2251.6s user time, 5.5s system time, 133.95M rss, 298.91M vsz
分析结果生成的时间
# Current date: Wed Jul 17 16:34:40 2024
主机名
# Hostname: toolkit
分析的文件所在路径
# Files: /data/mysql-log/mysql-slow/mysql-slow.log
分析的 SQL 数量统计，本示例中总共存在的慢 SQL 有 17.12M 条
total 为总语句数量。
unique 为唯一查询数量，即对查询条件进行参数化以后，统计的总共有多少个不同的查询。
# Overall: 17.12M total, 998 unique, 7.32 QPS, 0.02x concurrency _________
本次分析中所以慢 SQL 所在的时间段。
# Time range: 2024-06-19T07:57:46 to 2024-07-16T09:28:30
SQL 执行时间          总时间 最短时间  最长时间 平均时间  95%个数  标准偏差 中位数
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
语句执行时间
# Exec time         51426s    47us     52s     3ms    16ms    76ms   185us
锁占用时间
# Lock time            81s       0     26s     4us     2us     9ms     1us
发送到客户端的行数
# Rows sent        382.85M       0   1.06M   23.45   80.10   1.66k       0
select语句扫描行数
# Rows examine      40.91G       0  22.48M   2.51k  11.91k  51.86k   36.69
查询的字符数
# Query size         4.17G       6 511.86k  261.69  313.99   3.16k  174.84

参数说明如下：

Current date：分析结果生成的时间。
Hostname：主机名。
Files：分析的文件所在路径。
Overall：分析的 SQL 数量统计。
- 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
# ==== =================================== =============== ======== ======
#   22 0x6C545CFB55365122F1256A27240AEFC7    85.0967  0.2%       16  5.3185  0.02 INSERT sbtest?
#   25 0x410C2605CF6B250BE96B374065B13356    70.5435  0.1%       14  5.0388  0.00 UPDATE sbtest?
#   32 0xDDBF88031795EC65EAB8A8A8BEEFF705    51.7845  0.1%       10  5.1784  0.02 DELETE sbtest?
# MISC 0xMISC                              2053.0152  4.0%  1049587  0.0020   0.0 <977 ITEMS>

参数说明如下：

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 22: 0.00 QPS, 0.01x concurrency, ID 0x6C545CFB55365122F1256A27240AEFC7 at byte 93966
# This item is included in the report because it matches --outliers.
# Scores: V/M = 0.02
# Time range: 2024-06-20T03:00:18 to 2024-06-20T07:41:55
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          0      16
# Exec time      0     85s      5s      6s      5s      6s   343ms      5s
# Lock time      0    29us     1us    11us     1us     1us     2us     1us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0   3.87k     247     248  247.75  246.02       0  246.02
# String:
数据库名
# Databases    loadtest
执行主机
# Hosts        192.168.0.9 (12/75%), 192.168.0.43 (4/25%)
执行用户
# Users        root
查询时间占比
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `loadtest` LIKE 'sbtest33'\G
#    SHOW CREATE TABLE `loadtest`.`sbtest33`\G
INSERT INTO sbtest33 (id, k, c, pad) VALUES (4104021, 5021939, '53760848582-61772455757-13756174941-26340673050-49215508093-02614923825-17307273142-19544845219-97933526313-59521997160', '64542834346-20908256378-17685105766-32329763748-20082021238')\G

Query 22 是此次分析结果中出现的慢 SQL

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

Databases：SQL 执行的数据库。
Users：SQL 执行的用户。
Query_time distribution：查询时长的分布。

如下是 SQL 语句的相关执行计划，但是对于非 select 语句通常不能再次执行来查看执行计划，因此 pt-query-digest 会尝试将 SQL 转化为等效的 select 语句然后展示出来。

# Tables
#    SHOW TABLE STATUS FROM `loadtest` LIKE 'sbtest21'\G
#    SHOW CREATE TABLE `loadtest`.`sbtest21`\G
DELETE FROM sbtest21 WHERE id=4295284\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  sbtest21 WHERE id=4295284\G

使用 pt-query-digest 工具分析 MySQL 慢日志

一、前言

二、安装 pt-query-digest

三、确认MySQL配置

四、分析慢日志

五、分析结果示例

第一部分：总体概要信息

第二部分：SQL 概要信息

第三部分：SQL 详细信息

六、其它常用命令

热门文章

最新文章

相关课程

相关电子书

相关实验场景

推荐镜像

热门

活动广场

任务中心

开发者评测

高校计划

乘风者计划

训练营

阿里云MVP

话题

直播

下载

镜像站

技术资料

插件

使用 pt-query-digest 工具分析 MySQL 慢日志

一、前言

二、安装 pt-query-digest

三、确认MySQL配置

四、分析慢日志

五、分析结果示例

第一部分：总体概要信息

第二部分：SQL 概要信息

第三部分：SQL 详细信息

六、其它常用命令

热门文章

最新文章

相关课程

相关电子书

相关实验场景

推荐镜像