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

本文涉及的产品
云数据库 RDS MySQL,集群系列 2核4GB
推荐场景:
搭建个人博客
RDS MySQL Serverless 基础系列,0.5-2RCU 50GB
RDS MySQL Serverless 高可用系列,价值2615元额度,1个月
简介: 【8月更文挑战第5天】使用 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配置

我们可以用以下命令查看慢查询次数
image.png
使用该命令只能查看慢查询次数,但是我们没有办法知道是哪些查询产生了慢查询,如果想要知道是哪些查询导致的慢查询,那么我们必须修改 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 也是我们指定的文件
image.png

只要查询时间大于 1s,查询语句都将存入日志文件
image.png
查看 mysql 安装目录下的 data 目录,该目录会产生一个慢查询日志文件:mysql_slow.log,该文件内容如下
image.png
在该日志文件中,我们可以知道慢查询产生的时间,最终产生了几行结果,测试了几行结果,以及运行语句是什么。

四、分析慢日志

步骤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=4717805DELETE 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

六、其它常用命令

image.png

相关实践学习
如何在云端创建MySQL数据库
开始实验后,系统会自动创建一台自建MySQL的 源数据库 ECS 实例和一台 目标数据库 RDS。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心,利用清洁计算为万物互联的新世界提供源源不断的能源动力,目前开服的区域包括中国(华北、华东、华南、香港)、新加坡、美国(美东、美西)、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程,来了解阿里云能够为你的业务带来哪些帮助 &nbsp; &nbsp; 相关的阿里云产品:云服务器ECS 云服务器 ECS(Elastic Compute Service)是一种弹性可伸缩的计算服务,助您降低 IT 成本,提升运维效率,使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
目录
相关文章
|
3天前
|
SQL 存储 关系型数据库
Mysql并发控制和日志
通过深入理解和应用 MySQL 的并发控制和日志管理技术,您可以显著提升数据库系统的效率和稳定性。
26 10
|
4天前
|
SQL 关系型数据库 MySQL
MySQL 窗口函数详解:分析性查询的强大工具
MySQL 窗口函数从 8.0 版本开始支持,提供了一种灵活的方式处理 SQL 查询中的数据。无需分组即可对行集进行分析,常用于计算排名、累计和、移动平均值等。基本语法包括 `function_name([arguments]) OVER ([PARTITION BY columns] [ORDER BY columns] [frame_clause])`,常见函数有 `ROW_NUMBER()`, `RANK()`, `DENSE_RANK()`, `SUM()`, `AVG()` 等。窗口框架定义了计算聚合值时应包含的行。适用于复杂数据操作和分析报告。
38 11
|
1月前
|
存储 Oracle 关系型数据库
【赵渝强老师】MySQL InnoDB的数据文件与重做日志文件
本文介绍了MySQL InnoDB存储引擎中的数据文件和重做日志文件。数据文件包括`.ibd`和`ibdata`文件,用于存放InnoDB数据和索引。重做日志文件(redo log)确保数据的可靠性和事务的持久性,其大小和路径可由相关参数配置。文章还提供了视频讲解和示例代码。
141 11
【赵渝强老师】MySQL InnoDB的数据文件与重做日志文件
|
15天前
|
SQL 存储 缓存
MySQL进阶突击系列(02)一条更新SQL执行过程 | 讲透undoLog、redoLog、binLog日志三宝
本文详细介绍了MySQL中update SQL执行过程涉及的undoLog、redoLog和binLog三种日志的作用及其工作原理,包括它们如何确保数据的一致性和完整性,以及在事务提交过程中各自的角色。同时,文章还探讨了这些日志在故障恢复中的重要性,强调了合理配置相关参数对于提高系统稳定性的必要性。
|
18天前
|
监控 应用服务中间件 定位技术
要统计Nginx的客户端IP,可以通过分析Nginx的访问日志文件来实现
要统计Nginx的客户端IP,可以通过分析Nginx的访问日志文件来实现
|
28天前
|
前端开发 数据处理 Android开发
Flutter前端开发中的调试技巧与工具使用方法,涵盖调试的重要性、基本技巧如打印日志与断点调试、常用调试工具如Android Studio/VS Code调试器和Flutter Inspector的介绍
本文深入探讨了Flutter前端开发中的调试技巧与工具使用方法,涵盖调试的重要性、基本技巧如打印日志与断点调试、常用调试工具如Android Studio/VS Code调试器和Flutter Inspector的介绍,以及具体操作步骤、常见问题解决、高级调试技巧、团队协作中的调试应用和未来发展趋势,旨在帮助开发者提高调试效率,提升应用质量。
45 8
|
1月前
|
SQL 关系型数据库 MySQL
【赵渝强老师】MySQL的全量日志文件
MySQL全量日志记录所有操作的SQL语句,默认禁用。启用后,可通过`show variables like %general_log%检查状态,使用`set global general_log=ON`临时开启,执行查询并查看日志文件以追踪SQL执行详情。
|
1月前
|
关系型数据库 MySQL 数据库
【赵渝强老师】MySQL的binlog日志文件
MySQL的binlog日志记录了所有对数据库的更改操作(不包括SELECT和SHOW),主要用于主从复制和数据恢复。binlog有三种模式,可通过设置binlog_format参数选择。示例展示了如何启用binlog、设置格式、查看日志文件及记录的信息。
|
1月前
|
SQL 关系型数据库 MySQL
【赵渝强老师】MySQL的慢查询日志
MySQL的慢查询日志用于记录执行时间超过设定阈值的SQL语句,帮助数据库管理员识别并优化性能问题。通过`mysqldumpslow`工具可查看日志。本文介绍了如何检查、启用及配置慢查询日志,并通过实例演示了慢查询的记录与分析过程。
120 3
|
1月前
|
监控 安全 网络安全
使用EventLog Analyzer日志分析工具监测 Windows Server 安全威胁
Windows服务器面临多重威胁,包括勒索软件、DoS攻击、内部威胁、恶意软件感染、网络钓鱼、暴力破解、漏洞利用、Web应用攻击及配置错误等。这些威胁严重威胁服务器安全与业务连续性。EventLog Analyzer通过日志管理和威胁分析,有效检测并应对上述威胁,提升服务器安全性,确保服务稳定运行。
下一篇
DataWorks