使用 pt-query-digest 工具分析 MySQL 慢日志
【摘要】 使用 pt-query-digest 工具分析 MySQL 慢日志
一、前言
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
六、其它常用命令
【版权声明】本文为华为云社区用户原创内容，转载时必须标注文章的来源（华为云社区）、文章链接、文章作者等基本信息， 否则作者和本社区有权追究责任。如果您发现本社区中有涉嫌抄袭的内容，欢迎发送邮件进行举报，并提供相关证据，一经查实，本社区将立刻删除涉嫌侵权内容，举报邮箱：
cloudbbs@huaweicloud.com
- 点赞
- 收藏
- 关注作者
评论（0）