使用 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

相关实践学习
如何快速连接云数据库RDS MySQL
本场景介绍如何通过阿里云数据管理服务DMS快速连接云数据库RDS MySQL,然后进行数据表的CRUD操作。
全面了解阿里云能为你做什么
阿里云在全球各地部署高效节能的绿色数据中心,利用清洁计算为万物互联的新世界提供源源不断的能源动力,目前开服的区域包括中国(华北、华东、华南、香港)、新加坡、美国(美东、美西)、欧洲、中东、澳大利亚、日本。目前阿里云的产品涵盖弹性计算、数据库、存储与CDN、分析与搜索、云通信、网络、管理与监控、应用服务、互联网中间件、移动服务、视频服务等。通过本课程,来了解阿里云能够为你的业务带来哪些帮助 &nbsp; &nbsp; 相关的阿里云产品:云服务器ECS 云服务器 ECS(Elastic Compute Service)是一种弹性可伸缩的计算服务,助您降低 IT 成本,提升运维效率,使您更专注于核心业务创新。产品详情: https://www.aliyun.com/product/ecs
目录
相关文章
|
10天前
|
存储 SQL 关系型数据库
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log、原理、写入过程;binlog与redolog区别、update语句的执行流程、两阶段提交、主从复制、三种日志的使用场景;查询日志、慢查询日志、错误日志等其他几类日志
MySQL日志详解——日志分类、二进制日志bin log、回滚日志undo log、重做日志redo log
|
24天前
|
关系型数据库 MySQL 数据库连接
数据库连接工具连接mysql提示:“Host ‘172.23.0.1‘ is not allowed to connect to this MySQL server“
docker-compose部署mysql8服务后,连接时提示不允许连接问题解决
|
8天前
|
SQL 缓存 关系型数据库
MySQL原理简介—7.redo日志的底层原理
本文介绍了MySQL中redo日志和undo日志的主要内容: 1. redo日志的意义:确保事务提交后数据不丢失,通过记录修改操作并在系统宕机后重做日志恢复数据。 2. redo日志文件构成:记录表空间号、数据页号、偏移量及修改内容。 3. redo日志写入机制:redo日志先写入Redo Log Buffer,再批量刷入磁盘文件,减少随机写以提高性能。 4. Redo Log Buffer解析:描述Redo Log Buffer的内存结构及刷盘时机,如事务提交、Buffer过半或后台线程定时刷新。 5. undo日志原理:用于事务回滚,记录插入、删除和更新前的数据状态,确保事务可完整回滚。
|
20天前
|
机器学习/深度学习 人工智能 运维
智能日志分析:用AI点亮运维的未来
智能日志分析:用AI点亮运维的未来
140 15
|
20天前
|
监控 Oracle 关系型数据库
Mysql、Oracle审计日志的开启
通过上述步骤,可以在 MySQL 和 Oracle 数据库中启用和配置审计日志。这些日志对于监控数据库操作、提高安全性和满足合规性要求非常重要。确保正确配置审计参数和策略,定期查看和分析审计日志,有助于及时发现并处理潜在的安全问题。
38 11
|
1月前
|
SQL 关系型数据库 MySQL
MySQL事务日志-Undo Log工作原理分析
事务的持久性是交由Redo Log来保证,原子性则是交由Undo Log来保证。如果事务中的SQL执行到一半出现错误,需要把前面已经执行过的SQL撤销以达到原子性的目的,这个过程也叫做"回滚",所以Undo Log也叫回滚日志。
MySQL事务日志-Undo Log工作原理分析
|
1月前
|
存储 人工智能 JSON
RAG Logger:专为检索增强生成(RAG)应用设计的开源日志工具,支持查询跟踪、性能监控
RAG Logger 是一款专为检索增强生成(RAG)应用设计的开源日志工具,支持查询跟踪、检索结果记录、LLM 交互记录和性能监控等功能。
74 7
RAG Logger:专为检索增强生成(RAG)应用设计的开源日志工具,支持查询跟踪、性能监控
|
27天前
|
关系型数据库 MySQL 数据库
mysql慢查询每日汇报与分析
通过启用慢查询日志、提取和分析慢查询日志,可以有效识别和优化数据库中的性能瓶颈。结合适当的自动化工具和优化措施,可以显著提高MySQL数据库的性能和稳定性。希望本文的详解和示例能够为数据库管理人员提供有价值的参考,帮助实现高效的数据库管理。
39 11
|
9天前
|
缓存 NoSQL 关系型数据库
MySQL原理简介—4.深入分析Buffer Pool
本文介绍了MySQL的Buffer Pool机制,包括其作用、配置方法及内部结构。Buffer Pool是MySQL用于缓存磁盘数据页的关键组件,能显著提升数据库读写性能。默认大小为128MB,可根据服务器配置调整(如32GB内存可设为2GB)。它通过free链表管理空闲缓存页,flush链表记录脏页,并用LRU链表区分冷热数据以优化淘汰策略。此外,还探讨了多Buffer Pool实例、chunk动态调整等优化并发性能的方法,以及如何通过`show engine innodb status`查看Buffer Pool状态。关键词:MySQL内存数据更新机制。
|
2月前
|
存储 运维 监控
Linux--深入理与解linux文件系统与日志文件分析
深入理解 Linux 文件系统和日志文件分析,对于系统管理员和运维工程师来说至关重要。文件系统管理涉及到文件的组织、存储和检索,而日志文件则记录了系统和应用的运行状态,是排查故障和维护系统的重要依据。通过掌握文件系统和日志文件的管理和分析技能,可以有效提升系统的稳定性和安全性。
57 7