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

本文涉及的产品
RDS MySQL Serverless 基础系列,0.5-2RCU 50GB
云数据库 RDS MySQL,集群系列 2核4GB
推荐场景:
搭建个人博客
云数据库 RDS MySQL,高可用系列 2核4GB
简介: 【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
目录
相关文章
|
11天前
|
canal 消息中间件 关系型数据库
Canal作为一款高效、可靠的数据同步工具,凭借其基于MySQL binlog的增量同步机制,在数据同步领域展现了强大的应用价值
【9月更文挑战第1天】Canal作为一款高效、可靠的数据同步工具,凭借其基于MySQL binlog的增量同步机制,在数据同步领域展现了强大的应用价值
88 4
|
20天前
|
SQL 关系型数据库 MySQL
【揭秘】MySQL binlog日志与GTID:如何让数据库备份恢复变得轻松简单?
【8月更文挑战第22天】MySQL的binlog日志记录数据变更,用于恢复、复制和点恢复;GTID为每笔事务分配唯一ID,简化复制和恢复流程。开启binlog和GTID后,可通过`mysqldump`进行逻辑备份,包含binlog位置信息,或用`xtrabackup`做物理备份。恢复时,使用`mysql`命令执行备份文件,或通过`innobackupex`恢复物理备份。GTID模式下的主从复制配置更简便。
89 2
|
16天前
|
存储 JSON 关系型数据库
MySQL与JSON的邂逅:开启大数据分析新纪元
MySQL与JSON的邂逅:开启大数据分析新纪元
|
19天前
|
存储 分布式计算 大数据
【Flume的大数据之旅】探索Flume如何成为大数据分析的得力助手,从日志收集到实时处理一网打尽!
【8月更文挑战第24天】Apache Flume是一款高效可靠的数据收集系统,专为Hadoop环境设计。它能在数据产生端与分析/存储端间搭建桥梁,适用于日志收集、数据集成、实时处理及数据备份等多种场景。通过监控不同来源的日志文件并将数据标准化后传输至Hadoop等平台,Flume支持了性能监控、数据分析等多种需求。此外,它还能与Apache Storm或Flink等实时处理框架集成,实现数据的即时分析。下面展示了一个简单的Flume配置示例,说明如何将日志数据导入HDFS进行存储。总之,Flume凭借其灵活性和强大的集成能力,在大数据处理流程中占据了重要地位。
32 3
|
20天前
|
应用服务中间件 Linux nginx
在Linux中,如何统计ip访问情况?分析 nginx 访问日志?如何找出访问页面数量在前十位的ip?
在Linux中,如何统计ip访问情况?分析 nginx 访问日志?如何找出访问页面数量在前十位的ip?
|
20天前
|
SQL 关系型数据库 MySQL
在Linux中,mysql 数据备份工具有哪些?
在Linux中,mysql 数据备份工具有哪些?
|
11天前
|
API C# 开发框架
WPF与Web服务集成大揭秘:手把手教你调用RESTful API,客户端与服务器端优劣对比全解析!
【8月更文挑战第31天】在现代软件开发中,WPF 和 Web 服务各具特色。WPF 以其出色的界面展示能力受到欢迎,而 Web 服务则凭借跨平台和易维护性在互联网应用中占有一席之地。本文探讨了 WPF 如何通过 HttpClient 类调用 RESTful API,并展示了基于 ASP.NET Core 的 Web 服务如何实现同样的功能。通过对比分析,揭示了两者各自的优缺点:WPF 客户端直接处理数据,减轻服务器负担,但需处理网络异常;Web 服务则能利用服务器端功能如缓存和权限验证,但可能增加服务器负载。希望本文能帮助开发者根据具体需求选择合适的技术方案。
40 0
|
11天前
|
C# Windows 监控
WPF应用跨界成长秘籍:深度揭秘如何与Windows服务完美交互,扩展功能无界限!
【8月更文挑战第31天】WPF(Windows Presentation Foundation)是 .NET 框架下的图形界面技术,具有丰富的界面设计和灵活的客户端功能。在某些场景下,WPF 应用需与 Windows 服务交互以实现后台任务处理、系统监控等功能。本文探讨了两者交互的方法,并通过示例代码展示了如何扩展 WPF 应用的功能。首先介绍了 Windows 服务的基础知识,然后阐述了创建 Windows 服务、设计通信接口及 WPF 客户端调用服务的具体步骤。通过合理的交互设计,WPF 应用可获得更强的后台处理能力和系统级操作权限,提升应用的整体性能。
27 0
|
13天前
|
存储 消息中间件 监控
Java日志详解:日志级别,优先级、配置文件、常见日志管理系统ELK、日志收集分析
Java日志详解:日志级别,优先级、配置文件、常见日志管理系统、日志收集分析。日志级别从小到大的关系(优先级从低到高): ALL < TRACE < DEBUG < INFO < WARN < ERROR < FATAL < OFF 低级别的会输出高级别的信息,高级别的不会输出低级别的信息
|
14天前
|
算法 关系型数据库 程序员
第一周算法设计与分析:A : log2(N)
这篇文章介绍了解决算法问题"输入一个数N,输出log2N(向下取整)"的三种编程思路,包括使用对数函数和幂函数的转换方法,以及避免浮点数精度问题的整数逼近方法。

热门文章

最新文章