前往小程序，Get更优阅读体验！
立即前往
文档建议反馈控制台
首页
学习
活动
专区
工具
TVP
最新优惠活动
文章/答案/技术大牛
发布
首页
学习
活动
专区
工具
TVP最新优惠活动
返回腾讯云官网
社区首页 >专栏 >技术分享 | 使用 pt-query-digest 分析慢日志

技术分享 | 使用 pt-query-digest 分析慢日志

作者头像
爱可生开源社区
发布于 2020-09-28 10:43:17
2K0
发布于 2020-09-28 10:43:17
举报
文章被收录于专栏：爱可生开源社区爱可生开源社区

作者：张伟

爱可生北京分公司 DBA 团队成员，负责 MySQL 日常问题处理和 DMP 产品维护。喜爱技术和开源数据库，喜爱运动、读书、电影，花草树木。

本文来源：原创投稿

*爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。

pt-query-digest 简介

子曰：“工欲善其事，必先利其器”

善于利用好的性能分析工具可以使运维效率事半功倍。pt-query-digest 属于 Percona Toolkit 工具集中较为常用的工具，用于分析 slow log，可以分析 MySQL 数据库的 binary log 、 general log 日志，同时也可以使用 show processlist 或从 tcpdump 抓取的 MySQL 协议数据来进行分析。

部署 Percona Toolkit

下载最新版本的 Percona Toolkit

代码语言：javascript
复制
[root@xxx ~]# wget https://www.percona.com/downloads/percona-toolkit/3.2.1/binary/redhat/7/x86_64/percona-toolkit-3.2.1-1.el7.x86_64.rpm
--2020-09-02 06:44:43--  https://www.percona.com/downloads/percona-toolkit/3.2.1/binary/redhat/7/x86_64/percona-toolkit-3.2.1-1.el7.x86_64.rpm
Resolving www.percona.com (www.percona.com)... 74.121.199.234
Connecting to www.percona.com (www.percona.com)|74.121.199.234|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: 17397876 (17M) [application/x-redhat-package-manager]
Saving to: ‘percona-toolkit-3.2.1-1.el7.x86_64.rpm’

100%[=====================================================================================================================================================>] 17,397,876  68.3KB/s   in 2m 37s

2020-09-02 06:47:27 (108 KB/s) - ‘percona-toolkit-3.2.1-1.el7.x86_64.rpm’ saved [17397876/17397876]

[root@xxx ~]# ls | grep percona-toolkit-3.2.1-1.el7.x86_64.rpm
percona-toolkit-3.2.1-1.el7.x86_64.rpm

PT 工具是使用 Perl 语言编写和执行的，所以需要系统中有 Perl 环境。安装相关的依赖包，

代码语言：javascript
复制
[root@xxx ~]# yum install perl-DBI.x86_64
[root@xxx ~]# yum install perl-DBD-MySQL.x86_64
[root@xxx ~]# yum install perl-IO-Socket-SSL.noarch
[root@xxx ~]# yum install perl-Digest-MD5.x86_64
[root@xxx ~]# yum install perl-TermReadKey.x86_64

安装 Percona Toolkit

代码语言：javascript
复制
[root@xxx ~]# rpm -iv percona-toolkit-3.2.1-1.el7.x86_64.rpm
warning: percona-toolkit-3.2.1-1.el7.x86_64.rpm: Header V4 RSA/SHA256 Signature, key ID 8507efa5: NOKEY
Preparing packages...
percona-toolkit-3.2.1-1.el7.x86_64

[root@xxx ~]# rpm -qa | grep percona
percona-toolkit-3.2.1-1.el7.x86_64

工具目录安装路径：/usr/bin

检查慢日志的相关配置

代码语言：javascript
复制
mysql> show variables like '%slow%';
+---------------------------+-------------------------------------+
| Variable_name             | Value                               |
+---------------------------+-------------------------------------+
| log_slow_admin_statements | ON                                  |
| log_slow_slave_statements | ON                                  |
| slow_launch_time          | 2                                   |
| slow_query_log            | ON                                  |
| slow_query_log_file       | /opt/mysql/data/7777/mysql-slow.log |
+---------------------------+-------------------------------------+
5 rows in set (0.01 sec)

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.01 sec)

由于更好测试慢日志文件的输出，此处将慢日志执行时间阈值调小。

代码语言：javascript
复制
mysql>  set global long_query_time=0.001000;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.001000 |
+-----------------+----------+
1 row in set (0.00 sec)

pt-query-digest 分析慢日志

代码语言：javascript
复制
[root@xxx 7777]# pt-query-digest   mysql-slow.log

# 3.6s user time, 100ms system time, 32.64M rss, 227.52M vsz
# Current date: Wed Sep  2 11:22:34 2020
# Hostname: xxx
# Files: mysql-slow.log
# Overall: 37.46k total, 17 unique, 576.26 QPS, 5.58x concurrency ________
# Time range: 2020-09-02T11:21:24 to 2020-09-02T11:22:29
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           363s     1ms   183ms    10ms    23ms     8ms     8ms
# Lock time             1s       0    34ms    35us    38us   603us       0
# Rows sent        182.14k       0     100    4.98    0.99   21.06       0
# Rows examine     491.83k       0   1.02k   13.45   97.36   56.85       0
# Query size        19.82M       5 511.96k  554.80   72.65  16.25k    5.75

# Profile
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0xFFFCA4D67EA0A788813031B8... 328.2315 90.4% 30520 0.0108  0.01 COMMIT
#    2 0xB2249CB854EE3C2AD30AD7E3...   8.0186  2.2%  1208 0.0066  0.01 UPDATE sbtest?
#    3 0xE81D0B3DB4FB31BC558CAEF5...   6.6346  1.8%  1639 0.0040  0.01 SELECT sbtest?
#    4 0xDDBF88031795EC65EAB8A8A8...   5.5093  1.5%   756 0.0073  0.02 DELETE sbtest?
# MISC 0xMISC                         14.6011  4.0%  3334 0.0044   0.0 <13 ITEMS>

# Query 1: 1.02k QPS, 10.94x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 26111916
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:29
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         81   30520
# Exec time     90    328s     1ms   129ms    11ms    23ms     8ms     9ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0 178.83k       6       6       6       6       0       6
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ###########################################################
# 100ms  #
#    1s
#  10s+
COMMIT\G

# Query 2: 41.66 QPS, 0.28x concurrency, ID 0xB2249CB854EE3C2AD30AD7E3079ABCE7 at byte 24161590
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          3    1208
# Exec time      2      8s     1ms   115ms     7ms    24ms     9ms     3ms
# Lock time     38   518ms    17us    34ms   428us    73us     2ms    36us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0   1.18k       1       1       1       1       0       1
# Query size     0  46.01k      39      39      39      39       0      39
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ##############
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
UPDATE sbtest1 SET k=k+1 WHERE id=50313\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  k=k+1 from sbtest1 where  id=50313\G

# Query 3: 56.52 QPS, 0.23x concurrency, ID 0xE81D0B3DB4FB31BC558CAEF5F387E929 at byte 22020829
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4    1639
# Exec time      1      7s     1ms    61ms     4ms    14ms     5ms     2ms
# Lock time      3    45ms    11us   958us    27us    44us    30us    23us
# Rows sent      0   1.60k       1       1       1       1       0       1
# Rows examine   0   1.60k       1       1       1       1       0       1
# Query size     0  57.62k      36      36      36      36       0      36
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ######
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT c FROM sbtest1 WHERE id=61690\G

# Query 4: 26.07 QPS, 0.19x concurrency, ID 0xDDBF88031795EC65EAB8A8A8BEEFF705 at byte 21045172
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.02
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2     756
# Exec time      1      6s     1ms   104ms     7ms    26ms    10ms     3ms
# Lock time     18   252ms    13us    19ms   333us    54us     2ms    26us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0     756       1       1       1       1       0       1
# Query size     0  25.10k      34      34      34      34       0      34
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  #################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
DELETE FROM sbtest1 WHERE id=50296\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  sbtest1 WHERE id=50296\G

分析 pt-query-digest 输出结果

第一部分：输出结果的总体信息

代码语言：javascript
复制
# 3.6s user time, 100ms system time, 32.64M rss, 227.52M vsz 
说明：
执行过程中在用户中所花费的所有时间
执行过程中内核空间中所花费的所有时间
pt-query-digest进程所分配的内存大小
pt-query-digest进程所分配的虚拟内存大小

# Current date: Wed Sep  2 11:22:34 2020 
说明：当前日期

# Hostname: xxx
说明：执行pt-query-digest的主机名

# Files: mysql-slow.log
说明：被分析的文件名

# Overall: 37.46k total, 17 unique, 576.26 QPS, 5.58x concurrency ________
说明：语句总数量，唯一语句数量，每秒查询量，查询的并发

# Time range: 2020-09-02T11:21:24 to 2020-09-02T11:22:29
说明：执行过程中日志记录的时间范围

# Attribute          total     min     max     avg     95%  stddev  median
说明：属性           总计     最小值  最大值  平均值   95%  标准差  中位数
# ============     ======= ======= ======= ======= ======= ======= =======

# Exec time           363s     1ms   183ms    10ms    23ms     8ms     8ms
说明：执行时间
# Lock time             1s       0    34ms    35us    38us   603us       0
说明：锁占用时间
# Rows sent        182.14k       0     100    4.98    0.99   21.06       0
说明：发送到客户端的行数
# Rows examine     491.83k       0   1.02k   13.45   97.36   56.85       0
说明：扫描的语句行数
# Query size        19.82M       5 511.96k  554.80   72.65  16.25k    5.75 
说明：查询的字符数

第二部分：输出队列组的统计信息

代码语言：javascript
复制
# Profile
说明：简况
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0xFFFCA4D67EA0A788813031B8... 328.2315 90.4% 30520 0.0108  0.01 COMMIT
#    2 0xB2249CB854EE3C2AD30AD7E3...   8.0186  2.2%  1208 0.0066  0.01 UPDATE sbtest?
#    3 0xE81D0B3DB4FB31BC558CAEF5...   6.6346  1.8%  1639 0.0040  0.01 SELECT sbtest?
#    4 0xDDBF88031795EC65EAB8A8A8...   5.5093  1.5%   756 0.0073  0.02 DELETE sbtest?
# MISC 0xMISC                         14.6011  4.0%  3334 0.0044   0.0 <13 ITEMS>

第三部分：输出每列查询的详细信息

代码语言：javascript
复制
# Query 1: 1.02k QPS, 10.94x concurrency, ID 0xFFFCA4D67EA0A788813031B8BBC3B329 at byte 26111916
说明：查询队列1：每秒查询量，查询的并发，队列1的ID值，26111916：表示文中偏移量（查看方法在下面‘偏1’中）

# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:29
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         81   30520
# Exec time     90    328s     1ms   129ms    11ms    23ms     8ms     9ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size     0 178.83k       6       6       6       6       0       6
说明：查询的详细说明，在第一部分/第二部分有相关参数说明
# String:
# Databases    test
说明：使用的数据库名称
# Hosts        10.186.60.147
说明：使用的主机IP
# Users        root
说明：使用的用户名
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ###########################################################
# 100ms  #
#    1s
#  10s+
说明：查询时间分布
COMMIT\G
说明：执行的慢语句信息
# Query 2: 41.66 QPS, 0.28x concurrency, ID 0xB2249CB854EE3C2AD30AD7E3079ABCE7 at byte 24161590
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          3    1208
# Exec time      2      8s     1ms   115ms     7ms    24ms     9ms     3ms
# Lock time     38   518ms    17us    34ms   428us    73us     2ms    36us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0   1.18k       1       1       1       1       0       1
# Query size     0  46.01k      39      39      39      39       0      39
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ##############
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
UPDATE sbtest1 SET k=k+1 WHERE id=50313\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select  k=k+1 from sbtest1 where  id=50313\G

# Query 3: 56.52 QPS, 0.23x concurrency, ID 0xE81D0B3DB4FB31BC558CAEF5F387E929 at byte 22020829
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.01
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          4    1639
# Exec time      1      7s     1ms    61ms     4ms    14ms     5ms     2ms
# Lock time      3    45ms    11us   958us    27us    44us    30us    23us
# Rows sent      0   1.60k       1       1       1       1       0       1
# Rows examine   0   1.60k       1       1       1       1       0       1
# Query size     0  57.62k      36      36      36      36       0      36
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  ######
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT c FROM sbtest1 WHERE id=61690\G

# Query 4: 26.07 QPS, 0.19x concurrency, ID 0xDDBF88031795EC65EAB8A8A8BEEFF705 at byte 21045172
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.02
# Time range: 2020-09-02T11:21:59 to 2020-09-02T11:22:28
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          2     756
# Exec time      1      6s     1ms   104ms     7ms    26ms    10ms     3ms
# Lock time     18   252ms    13us    19ms   333us    54us     2ms    26us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0     756       1       1       1       1       0       1
# Query size     0  25.10k      34      34      34      34       0      34
# String:
# Databases    test
# Hosts        10.186.60.147
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms  #################
# 100ms  #
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `test` LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `test`.`sbtest1`\G
DELETE FROM sbtest1 WHERE id=50296\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select * from  sbtest1 WHERE id=50296\G

偏 1：

可以利用偏移量在慢查询日志文件中到查找到具体的 SQL 语句，查找方法如下：

代码语言：javascript
复制
[root@xxx 7777]# tail -c +26111916 ./mysql-slow.log | head
# Time: 2020-09-02T11:22:21.062995-00:00
# User@Host: root[root] @  [10.186.60.147]  Id:  1177
# Query_time: 0.128524  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1599045741;
COMMIT;
# Time: 2020-09-02T11:22:21.063202-00:00
# User@Host: root[root] @  [10.186.60.147]  Id:  1179
# Query_time: 0.126925  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1599045741;
COMMIT;

在生产环境中，可根据输出的慢 SQL 详情进行合理的语句调整。

参考文档

  • https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html
  • https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

小女不才，如有不足欢迎指正，告辞。

技术分享 | MySQL 监控利器之 Pt-Stalk

技术分享 | Xtrabackup 备份中 Xtrabackup_binlog_info 文件记录的 GTID 信息是否准确？

技术分享 | Percona Toolkit 使用场景分享

本文参与 腾讯云自媒体分享计划，分享自微信公众号。
原始发表：2020-09-22，如有侵权请联系 cloudcommunity@tencent.com 删除
https
perl
云数据库 SQL Server
网络安全
html

本文分享自 爱可生开源社区 微信公众号，前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体分享计划  ，欢迎热爱写作的你一起参与！

https
perl
云数据库 SQL Server
网络安全
html
评论
登录后参与评论
0 条评论
热度
最新
登录 后参与评论
推荐阅读
LV.
文章
0
获赞
0
目录
  • 部署 Percona Toolkit
  • 检查慢日志的相关配置
  • pt-query-digest 分析慢日志
  • 分析 pt-query-digest 输出结果
  • 参考文档
相关产品与服务
云数据库 SQL Server
腾讯云数据库 SQL Server （TencentDB for SQL Server）是业界最常用的商用数据库之一，对基于 Windows 架构的应用程序具有完美的支持。TencentDB for SQL Server 拥有微软正版授权，可持续为用户提供最新的功能，避免未授权使用软件的风险。具有即开即用、稳定可靠、安全运行、弹性扩缩等特点。
产品介绍产品文档
云数据库采购特惠，高性能、高可靠、高安全，超值优惠等你享！
领券

腾讯云开发者

扫码关注腾讯云开发者

扫码关注腾讯云开发者

领取腾讯云代金券

热门产品

热门推荐

更多推荐

Copyright © 2013 - 2024 Tencent Cloud. All Rights Reserved. 腾讯云 版权所有 

深圳市腾讯计算机系统有限公司 ICP备案/许可证号：粤B2-20090059 深公网安备号 44030502008569

腾讯云计算（北京）有限责任公司 京ICP证150476号 |  京ICP备11018762号 | 京公网安备号11010802020287

问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档

Copyright © 2013 - 2024 Tencent Cloud.

All Rights Reserved. 腾讯云 版权所有

登录 后参与评论