slowlog汇总报告工具slow-log-summary-摩杜云开发者社区

概念描述

在分析慢日志时，DBA 常用 Percona Toolkit 中的 pt-query-digest工具，该工具可对慢日志进行汇总分析，但是该工具首先需要去学习怎么使用及读懂分析结果，并且分析过程会耗费一定的时间。而且有些开发人员因为服务器权限问题，是无法获取到slowlog的，所以分享一个工具 slow-log-summary。
slow-log-summary 工具会生成一个HTML 格式的慢查询汇总报告。每一类 SQL 是一行。执行总耗时越久的 SQL，排名越靠前，也最值得优化，可读性方面非常好。对于开发人员，可直接从 performance_schema 中获取 SQL 的执行耗时分布情况，非常的方便实用。

测试验证

1. 下载安装

下载地址：https://github.com/slowtech/slow-log-summary ，可直接下载二进制包，也可进行源码编译。

二进制包安装
[root@mysql local]#wget https://github.com/slowtech/slow-log-summary/releases/download/v1.0.0/slow-log-summary-linux-amd64.tar.gz
[root@mysql local]#tar xf slow-log-summary-linux-amd64.tar.gz
[root@mysql local]# 
[root@mysql local]# ll
-rwxr-xr-x   1 root        root         8884200 Nov 27 12:40 slow-log-summary
-rw-r--r--   1 root        root         4789564 Nov 27 12:54 slow-log-summary-linux-amd64.tar.gz

2. 参数详解

[root@mysql local]# ./slow-log-summary --help
slow-log-summary version: 1.0.0
Usage:
slow-log-summary -source <source_type> -r <output_file> [other options]

Example:
./slow-log-summary -source perf -h 10.0.0.168 -P 3306 -u root -p '123456'  ----指定慢查询汇总报告来源为perf 的例子
./slow-log-summary -source slowlog -pt /usr/local/bin/pt-query-digest -slowlog /data/mysql/3306/data/n1-slow.log  ----指定慢查询汇总报告来源为慢日志 + pt-query-digest 的例子

Common Options:
  -help
    Display usage

Source Type Options:
  -source string
    Slow log source: 'perf' or 'slowlog' (default "perf")  ----指定慢查询汇总报告的来源。可设置 perf（performance_schema），也可设置 slowlog（慢日志 + pt-query-digest）

Output File Options:
  -r string
    Direct output to a given file (default "/tmp/slow-log-summary-20231128-150405.html")  ----慢查询汇总报告文件名。如果不指定，则默认为 "/tmp/slow-log-summary-当前时间.html"，例如 /tmp/slow-log-summary-20231128-150405.html

Options when source is 'perf':
  -h string
    MySQL host (default "localhost")  ----主机名，默认是 localhost
  -P int
    MySQL port (default 3306)  ----端口，默认是 3306
  -u string
    MySQL username (default "root")  ----用户名，默认是 root
  -p string
    MySQL password  ----密码
  -D string
    MySQL database (default "performance_schema")  ----库名，默认是 performance_schema

Options when source is 'slowlog': 用于基于慢日志和 pt-query-digest 方式可设置的参数
  -pt string
    Absolute path for pt-query-digest. Example: /usr/local/bin/pt-query-digest  ----pt-query-digest路径
  -slowlog string
    Absolute path for slowlog. Example: /var/log/mysql/node1-slow.log  ----指定 slow.log 文件路径
  -since string
    Parse only queries newer than this value, YYYY-MM-DD [HH:MM:SS]  ----分析指定时间段开始的慢日志
  -until string
    Parse only queries older than this value, YYYY-MM-DD [HH:MM:SS]  ----分析指定时间段结束的慢日志
  -yday
    Parse yesterday's slowlog  ----分析昨天的慢日志

当 source 设置为 slowlog 时，需要提前解压安装 Percona Toolkit 工具，因为该工具是基于 pt-query-digest 对慢日志进行分析，所以需要通过 -pt 设置 pt-query-digest 的绝对路径和 -slowlog 设置慢日志的绝对路径。

3. 使用方法

3.1 基于 performance_schema

[root@mysql local]# ./slow-log-summary -source perf -h 127.0.0.1 -P 3306 -u root -p 123456 -r slow-log-summary.html
Output written to file slow-log-summary.html

不在命令行中指定密码

[root@mysql local]# ./slow-log-summary -source perf -h 127.0.0.1 -P 3306 -u root
Enter MySQL password:
Output written to file /tmp/slow-log-summary-20231128-154212.html

3.2 基于慢日志和 pt-query-digest

[root@mysql local]# ./slow-log-summary -source slowlog -pt /usr/local/bin/pt-query-digest -slowlog /data/mysql/3306/data/slow.log

分析昨天的慢日志

[root@mysql local]# ./slow-log-summary -source slowlog -pt /usr/local/bin/pt-query-digest -slowlog /data/mysql/3306/data/slow.log -yday

分析指定时间段的慢日志

[root@mysql local]# ./slow-log-summary -source slowlog -pt /usr/local/bin/pt-query-digest -slowlog /data/mysql/3306/data/slow.log -since '2023-11-20 00:00:00' -until '2023-11-28 00:00:00'

4. 报告分析

4.1 基于 performance_schema

slowlog汇总报告工具slow-log-summary_慢sql

注意：

报告右上角的“生成时间”是中国时区时间，而报告中 SQL 的“第一次出现时间”和“最近一次出现时间”是原样输出，没有进行时区转换，具体是什么时区下的时间取决于实例的 time_zone。
Digest Text 的长度由 performance_schema_max_digest_length 参数控制，默认是 1024。
Sample SQL 的长度由 performance_schema_max_sql_text_length 参数控制，默认是 1024。
对于 MySQL 8.0 之前的版本，报告中只会显示 Digest Text（规范化语句摘要），不会显示 Sample SQL（一类 SQL 中一个具体的 SQL 语句）。Sample SQL 是 MySQL 8.0 才开始支持的。
对于 MySQL 8.0.31 开始的版本，报告中还会显示语句的最大内存使用量。
对于 MySQL 8.0.28 开始的版本，如果 performance_schema.setup_consumers 中 CPU 相关的配置开启了（默认没有开启），报告中还会显示语句的CPU平均耗时。

UPDATE performance_schema.setup_consumers SET ENABLED = 'YES' WHERE NAME='events_statements_cpu';

DigestPrefix 是 Digest 的前缀，我们可以基于该值从 performance_schema.events_statements_summary_by_digest 获取该类 SQL 更详细的统计信息。

4.2 基于慢日志和 pt-query-digest

slowlog汇总报告工具slow-log-summary_mysql_02

注意：

报告中的 Digest 是 Digest Text（规范化语句摘要）对应的哈希值。如果我们想看某一类 SQL 更详细的统计信息，可通过该类 SQL 的 Digest，去 pt-query-digest 的原始报告中找。MySQL 5.6，5.7 的 pt-query-digest 的原始报告中不会输出示例 SQL 的数据库名，所以，如果分析的是 MySQL 5.6，5.7 当慢日志，数据库名这一列会为空。
查询语句过短或过长 pt-query-digest 工具在解析查询语句时，可能会受到查询语句长度的影响。如果查询语句过短或过长，可能导致解析错误或显示不完整，如下：

5. 实现思路

5.1 基于 performance_schema

performance_schema 这种方式是直接读取 performance_schema.events_statements_summary_by_digest 表中的数据。
该表按照 SCHEMA_NAME 和 DIGEST 对 MySQL 服务端执行的 SQL 进行分类统计，会统计这类 SQL 性能相关的指标，例如总耗时、执行次数、扫描行数、发送行数等，具体指标如下所示。

mysql> select * from performance_schema.events_statements_summary_by_digest limit 1\G;
*************************** 1. row ***************************
                SCHEMA_NAME: NULL
                     DIGEST: 3900dc280937420a43d98635d81d0ff19e0e0690e51af79318ac54836efb6025
                DIGEST_TEXT: SET SESSION `group_replication_consistency` = `EVENTUAL`
                 COUNT_STAR: 1
             SUM_TIMER_WAIT: 225106000
             MIN_TIMER_WAIT: 225106000
             AVG_TIMER_WAIT: 225106000
             MAX_TIMER_WAIT: 225106000
              SUM_LOCK_TIME: 0
                 SUM_ERRORS: 0
               SUM_WARNINGS: 0
          SUM_ROWS_AFFECTED: 0
              SUM_ROWS_SENT: 0
          SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
     SUM_CREATED_TMP_TABLES: 0
       SUM_SELECT_FULL_JOIN: 0
 SUM_SELECT_FULL_RANGE_JOIN: 0
           SUM_SELECT_RANGE: 0
     SUM_SELECT_RANGE_CHECK: 0
            SUM_SELECT_SCAN: 0
      SUM_SORT_MERGE_PASSES: 0
             SUM_SORT_RANGE: 0
              SUM_SORT_ROWS: 0
              SUM_SORT_SCAN: 0
          SUM_NO_INDEX_USED: 0
     SUM_NO_GOOD_INDEX_USED: 0
               SUM_CPU_TIME: 0
      MAX_CONTROLLED_MEMORY: 8720
           MAX_TOTAL_MEMORY: 12204
            COUNT_SECONDARY: 0
                 FIRST_SEEN: 2023-11-29 15:48:44.242240
                  LAST_SEEN: 2023-11-29 15:48:44.242240
                QUANTILE_95: 229086765
                QUANTILE_99: 229086765
               QUANTILE_999: 229086765
          QUERY_SAMPLE_TEXT: SET SESSION group_replication_consistency= EVENTUAL
          QUERY_SAMPLE_SEEN: 2023-11-29 15:48:44.242240
    QUERY_SAMPLE_TIMER_WAIT: 225106000
1 row in set (0.09 sec)

ERROR: 
No query specified

该表是 MySQL 5.6 引入的，5.7 和 5.6 中的表结构基本一致，这里重点说说 MySQL 8.0 中新增的列：

QUANTILE_95，QUANTILE_99，QUANTILE_999：QUANTILE_95 表示 95% 的语句的执行耗时低于或等于这个值。相对于平均值，这些指标对业务更有参考意义。
QUERY_SAMPLE_TEXT，QUERY_SAMPLE_SEEN，QUERY_SAMPLE_TIMER_WAIT：MySQL 8.0 中引入的，给出了一个具体的 SQL、该 SQL 出现的时间和执行耗时情况。
在 MySQL 8.0 之前，没有具体的 SQL，只有这类 SQL 的 DIGEST_TEXT，有时候想找开发理论，却总有种证据不够充分的感觉。
MAX_CONTROLLED_MEMORY，MAX_TOTAL_MEMORY ：MySQL 8.0.31 中引入的，表示语句在执行过程中使用的最大受控内存量（由 connection_memory_limit 参数控制的内存）、最大内存量。
SUM_CPU_TIME：CPU_TIME 是 MySQL 8.0.28 中引入的，表示当前线程在 CPU 上消耗的时间，单位皮秒（picoseconds）。

注意：
events_statements_summary_by_digest 表的记录数由 performance_schema_digests_size 参数控制；该参数虽然是基于 max_connections、table_definition_cache、table_open_cache 的值动态生成，但对于生产系统，一般默认是 10000。如果记录数满了，Performance Schema 会将新的 SQL 的 SCHEMA_NAME 和 DIGEST 设置为 NULL，同时增加 Performance_schema_digest_lost 变量的值。如果我们看到表中 SCHEMA_NAME 和 DIGEST 为 NULL 的记录中的 COUNT_STAR（执行次数）的值比较大，可适当调大 performance_schema_digests_size 的值。

5.2 基于慢日志和 pt-query-digest

pt-query-digest 对慢日志进行分析后，生成的报告的内容如下：

# 110ms user time, 260ms system time, 19.32M rss, 175.73M vsz
# Current date: Thu Nov 23 13:13:01 2023
# Hostname: mysql
# Files: /usr/local/slow_20231123.log
# Overall: 139 total, 10 unique, 0.01 QPS, 0.07x concurrency _____________
# Time range: 2023-11-23T06:59:40 to 2023-11-23T11:06:54
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          1052s      1s     26s      8s     17s      6s      6s
# Lock time           28ms       0     8ms   199us   403us   668us   113us
# Rows sent         34.67k       0  11.07k  255.43   56.92   1.24k    0.99
# Rows examine     123.51M       0   9.78M 909.85k 871.90k   1.12M 871.90k
# Query size        20.88k      16     542  153.82  313.99   82.13  124.25

# Profile
# Rank Query ID                            Response time  Calls R/Call  V/
# ==== =================================== ============== ===== ======= ==
#    1 0x3253D9201887F473F4CD8E2AB05CDC35  953.2760 90.6%   116  8.2179  3.53 SELECT pipeline_inst
#    2 0xD134DC2852C0482280D223657EDFCB61   48.4747  4.6%     2 24.2373  0.16 UPDATE SELECT apallas_issue_detail amon_job
# MISC 0xMISC                               50.6865  4.8%    21  2.4136   0.0 <8 ITEMS>

# Query 1: 0.01 QPS, 0.09x concurrency, ID 0x3253D9201887F473F4CD8E2AB05CDC35 at byte 7583
# This item is included in the report because it matches --limit.
# Scores: V/M = 3.53
# Time range: 2023-11-23T08:18:14 to 2023-11-23T11:06:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         83     116
# Exec time     90    953s      2s     18s      8s     17s      5s      7s
# Lock time     81    22ms    50us     8ms   193us   167us   726us   113us
# Rows sent      0      97       0       3    0.84    1.96    0.88    0.99
# Rows examine  83 103.16M 910.39k 911.03k 910.67k 871.90k       0 871.90k
# Query size    67  14.16k     125     125     125     125       0     125
# String:
# Databases    torrent
# Hosts        10.51.129.32 (30/25%), 10.51.129.31 (29/25%)... 2 more
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+  ####################
# Tables
#    SHOW TABLE STATUS FROM `torrent` LIKE 'pipeline_inst'\G
#    SHOW CREATE TABLE `torrent`.`pipeline_inst`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM pipeline_inst WHERE is_deleted = 0 AND pre_json like concat('%','6614eb0e03cd43d3d0f4623cfbc9ded5c0c55425','%')\G

第一部分：总体统计结果。
Overall：总共有多少条查询。
Time range：查询执行的时间范围。
unique：唯一查询数量，即对查询条件进行参数化以后，总共有多少个不同的查询。
total：总计 min：最小 max：最大 avg：平均。
95%：把所有值从小到大排列，位置位于95%的那个数，这个数一般最具有参考价值。
median：中位数，把所有值从小到大排列，位置位于中间那个数。

# 该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小
# 110ms user time, 260ms system time, 19.32M rss, 175.73M vsz
# 工具执行时间
# Current date: Thu Nov 23 13:13:01 2023
# 运行分析工具的主机名
# Hostname: mysql
# 被分析的文件名
# Files: /usr/local/slow_20231123.log
# 语句总数量，唯一的语句数量，QPS，并发数
# Overall: 139 total, 10 unique, 0.01 QPS, 0.07x concurrency _____________
# 日志记录的时间范围
# Time range: 2023-11-23T06:59:40 to 2023-11-23T11:06:54
# 属性               总计      最小    最大    平均    95%  标准    中等
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# 语句执行时间
# Exec time          1052s      1s     26s      8s     17s      6s      6s
# 锁占用时间
# Lock time           28ms       0     8ms   199us   403us   668us   113us
# 发送到客户端的行数
# Rows sent         34.67k       0  11.07k  255.43   56.92   1.24k    0.99
# select语句扫描行数
# Rows examine     123.51M       0   9.78M 909.85k 871.90k   1.12M 871.90k
# 查询的字符数
# Query size        20.88k      16     542  153.82  313.99   82.13  124.25

第二部分：查询分组统计结果。
Rank：所有语句的排名，默认按查询时间降序排列，通过–order-by指定。
Query ID：语句的ID，（去掉多余空格和文本字符，计算hash值）。
Response：总的响应时间。
time：该查询在本次分析中总的时间占比。
calls：执行次数，即本次分析总共有多少条这种类型的查询语句。
R/Call：平均每次执行的响应时间。
V/M：响应时间Variance-to-mean的比率。
Item：查询对象。

# Profile
# Rank Query ID                            Response time  Calls R/Call  V/
# ==== =================================== ============== ===== ======= ==
#    1 0x3253D9201887F473F4CD8E2AB05CDC35  953.2760 90.6%   116  8.2179  3.53 SELECT pipeline_inst
#    2 0xD134DC2852C0482280D223657EDFCB61   48.4747  4.6%     2 24.2373  0.16 UPDATE SELECT apallas_issue_detail amon_job
# MISC 0xMISC                               50.6865  4.8%    21  2.4136   0.0 <8 ITEMS>

第三部分：每一种查询的详细统计结果。
由下面查询的详细统计结果，最上面的表格列出了执行次数、最大、最小、平均、95%等各项目的统计。
ID：查询的ID号，和上图的Query ID对应。
Databases：数据库名。
Users：各个用户执行的次数（占比）。
Query_time distribution ：查询时间分布, 长短体现区间占比，本例中1s-10s之间查询数量是10s以上的两倍。
Tables：查询中涉及到的表。
Explain：SQL语句。

# Query 1: 0.01 QPS, 0.09x concurrency, ID 0x3253D9201887F473F4CD8E2AB05CDC35 at byte 7583
# This item is included in the report because it matches --limit.
# Scores: V/M = 3.53
# Time range: 2023-11-23T08:18:14 to 2023-11-23T11:06:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         83     116
# Exec time     90    953s      2s     18s      8s     17s      5s      7s
# Lock time     81    22ms    50us     8ms   193us   167us   726us   113us
# Rows sent      0      97       0       3    0.84    1.96    0.88    0.99
# Rows examine  83 103.16M 910.39k 911.03k 910.67k 871.90k       0 871.90k
# Query size    67  14.16k     125     125     125     125       0     125
# String:
# Databases    torrent
# Hosts        10.51.129.32 (30/25%), 10.51.129.31 (29/25%)... 2 more
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+  ####################
# Tables
#    SHOW TABLE STATUS FROM `torrent` LIKE 'pipeline_inst'\G
#    SHOW CREATE TABLE `torrent`.`pipeline_inst`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM pipeline_inst WHERE is_deleted = 0 AND pre_json like concat('%','6614eb0e03cd43d3d0f4623cfbc9ded5c0c55425','%')\G

如果 SQL 是 DELETE、UPDATE 语句，pt-query-digest 还会将其转化为 SELECT 语句一并输出，因为在 MySQL 5.6 之前，EXPLAIN 命令不支持 DML 语句。如下：

slowlog汇总报告工具slow-log-summary_慢sql_03

slow-log-summary 报告中的排名、总耗时、耗时占比、总执行次数、Digest 实际上取的就是 pt-query-digest 工具生成的分析报告中的 Profile 部分的 Rank、Response time、Calls 和 Query ID，然后基于 Query ID 从明细部分拿到各类 SQL 的 Exec time(avg)、Rows sent(avg) 、Rows examine(avg) 和示例 SQL。

知识总结

slow-log-summary 工具这两种采集方式的优缺点：

1. performance_schema

优点：

简单方便，可远程获取。
对数据库性能影响较小。
性能相关的指标比较全面。
HTML 报告中只展示了一部分，如果需要其它指标，可以自行修改源。

缺点：

实例关闭，events_statements_summary_by_digest 中的数据就会被清空。
events_statements_summary_by_digest 不会记录 Prepared Statement。
有限的明细数据。虽然 mysql 执行过的 SQL 会存储在 events_statements_xxx 表中，但这些表的容量毕竟有限。一旦超过限制，之前的记录就会被覆盖。所以如果要基于明细数据来定位问题，很可能记录就不存在。

2. 慢日志 + pt-query-digest

优点：

会记录每条慢日志，方便我们定位问题。

缺点：

开启慢日志，对数据库性能会有一定的影响。
性能相关的指标较少。
慢日志存储在服务器上。如果没有服务器登录权限，分析起来就会比较麻烦。
需要安装pt-query-digest。而很多对安全比较敏感的环境禁止在服务器上下载和安装第三方工具。

参考文档

https://github.com/slowtech/slow-log-summary