MySQL 自建数据库慢日志分析

前言

慢 SQL 是指 MySQL 中执行时间超过指定阈值的语句将被记录到 Slow log 文件中的查询。慢 SQL 的风险是可能随时都会因为某种原因而被触发，并且根据 DBA 的工作经验，数据库最常出现的问题，都是因为慢查询导致数据库慢了，进而导致整个实例雪崩，从而导致了线上故障。因此需要定期治理优化，避免数据库内慢 SQL 堆积很多。

云上数据库，都会提供慢 SQL 的分析功能，使用起来也非常便捷，本篇文章主要讨论自建 MySQL 慢 SQL 如何分析。

1. 参数介绍

1.1 慢日志参数

MySQL 中的慢查询参数如下：

• long_query_time：慢 SQL 阈值，SQL 耗时大于该值会被存储到慢日志中。
• slow_query_log_file：慢日志存储的路径。
• slow_query_log：是否开启慢日志。
• log_slow_admin_statements：是否将 DDL 语句也写入到慢日志，推荐开启。
• log_queries_not_using_indexes：是否将未使用索引的 SQL 写入到慢日志，即使没超过阈值。
• log_output：有 FILE 和 TABLE 两个选项，FILE 表示记录到文件中，TABLE 记录到 mysql.slow_log 表中。

1.2 慢日志切割

为了避免慢日志过大，不仅分析时间长还会消耗服务器资源，更多的是采集后上传的集中服务器统一分析，需要先对慢日志进行切割，本小节介绍切割思路。

1. 先关闭慢日志：

   set global slow_query_log=0;
   1

2. 对日志进行重命名或移除：

   mv /data/mysql/log/mysql-slow.log /data/mysql/log/mysql-old-slow.log
   1

3. 再次开启慢日志：

   set global slow_query_log=1;
   1

2. pt-query-digest

pt-query-digest 含在 Percona Toolkit 中，安装方法可参考 Percona Toolkit Install 这篇文章的 1.1 小节。

2.1 离线分析

使用方法非常简单，直接指定 Slow log 日志路径即可。

pt-query-digest /data/mysql/log/slow.log
1

输出的报告非常详细，分为三部分，分析数据汇总、SQL 指纹列表、SQL 详情。

下方为分析数据汇总，首先输出工具分析日志时的耗时 CPU 及内存。接着打印了服务器的主机名、当前系统时间以及被分析的文件。

# 40.8s user time, 500ms system time, 62.94M rss, 255.45M vsz
# Current date: Wed Apr 24 14:24:18 2024
# Hostname: 172-16-104-56
# Files: ./slow.log
# Overall: 186.41k total, 488 unique, 0.01 QPS, 0.23x concurrency ________
# Time range: 2023-10-25T20:04:08 to 2024-04-24T12:47:59
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time        3550982s      1s   2908s     19s     27s     11s     24s
# Lock time            77s       0   205ms   414us   247us     3ms    73us
# Rows sent        492.10M       0  12.13M   2.70k   3.69k 130.80k       0
# Rows examine       1.78T       0 143.65M   9.99M  15.15M   7.13M  15.15M
# Query size       182.06M      17 893.24k   1.00k  563.87   9.77k  174.84
1
2
3
4
5
6
7
8
9
10
11
12
13

• Overall：一共分析了 186.41k 个 Slow SQL，形式不一样的有 488 个，后面的 QPS 表示被分析 SQL 的数量除以时间范围 concurrency 表示被分析的 SQL 总耗时除以时间范围。
• Time range: Slow log 的时间范围。
• Attribute： 分别给出了 Exec time (执行时间)、Lock time (锁等待时间)、Rows sent (返回客户端总行数)、Rows examine(存储引擎检索的行数)、Query size(SQL 语句文本大小) 五个维度的 total(汇总值)、min(最小值)、max(最大值)、avg(平均值)、95%(95% 查询等于或小于该值)、stddev(标准差)、median(中位数) 等信息。

以下是第二部分 SQL 指纹列表信息，从中可以看到哪个 SQL 耗时最高然后再到详细列表中查找。

# Profile
# Rank Query ID                            Response time   Calls  R/Call  
# ==== =================================== =============== ====== ========
#    1 0x1F3DF74A0FB6D75DF7EE8A4DF97B3ADA  3018133.2433... 122738  24.5900  0.41 SELECT sku_price
#    2 0xCC7FB22A44D4CAD79264BD6D86639C71  128737.4054 ...  16619   7.7464  3.92 SELECT product
#    3 0x96066CBEEFBD4B6761FEC4D79C13AF50  104551.7744 ...   8400  12.4466  1.85 SELECT product
#    4 0x76012B6D3A94358E3DE7446AB2A9E779  73329.0292  ...   5372  13.6502  2.02 SELECT product
#    5 0x6DBFEFE50E3D5CFB209EB13F331CEFB7  67403.5812  ...   4299  15.6789  0.79 SELECT product
#    6 0x0532AA67135641A67F2E9297710D201F  33958.2081  ...   2149  15.8019  0.66 SELECT product
#    7 0xAE6B4B13A66F041AC6E01BD10DA19112  23221.0245  ...   3408   6.8137  5.20 SELECT product
1
2
3
4
5
6
7
8
9
10

• Rank：排名，越靠前代表总执行时长最高。
• Query ID：每一类 SQL 的指纹，查看 SQL 详细执行情况会用到。
• Response time：总执行时长。
• Calls：总执行次数。
• R/Call：平均执行时间。
• Other：剩下的是平均方差，一般而言平均方差越大，代表 SQL 执行时间波动越大。接下来是 SQL 操作类型以及表名。

接下来介绍 SQL 详情部分，该部分会按照 SQL 列表中的顺序展示 SQL 语句以及详细的执行信息。

# Query 1: 0.04 QPS, 1.00x concurrency, ID 0x1F3DF74A0FB6D75DF7EE8A4DF97B3ADA at byte 101023918
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.41
# Time range: 2023-12-05T14:16:31 to 2024-01-09T14:24:29
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         65  122738
# Exec time     84 3018133s      1s     90s     25s     29s      3s     24s
# Lock time     12     10s    37us    54ms    77us    93us   311us    66us
# Rows sent      0 479.68k       0    1000    4.00       0   56.36       0
# Rows examine  99   1.76T 338.41k  15.22M  15.02M  15.15M   1.46M  15.15M
# Query size    11  20.62M     172     184  176.20  174.84    0.64  174.84
# String:
# Databases    xxxxx
# Hosts        127.0.0.1
# Users        test_user
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  #
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `xxxxx` LIKE 'sku_price'\G
#    SHOW CREATE TABLE `xxxxx`.`sku_price`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM sku_price WHERE (vendor_id = 11111 AND enabled = 1 AND sku_id > 0) ORDER BY sku_id ASC limit 1000\G
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30

第一行 ID 就是第二部分中的 Query ID，然后就是此类 SQL 的耗时分析，数据库名称、来源、用户等信息。Query_time distribution 给出了当前 SQL 执行耗时的分布情况，从这里可以非常直观的看出 SQL 执行时间是否稳定。

2.2 在线分析

上面的方法是分析历史的慢 SQL，下面的方法是基于会话分析当前的 SQL。比如当前数据库负载比较高，或者你想查看当前正在执行慢 SQL 信息，可以使用下面方法。

pt-query-digest --processlist h=127.0.0.1,P=3306,u=root,p=abc123  --run-time 60s --interval 0.1
1

命令行中的 --processlist 表示在线采集会话中的 SQL，–run-time 表示采集周期 --interval 表示采集间隔，默认 0.1 秒。

在线分析的输出结果与离线分析的相同，在此不多赘述。

2.3 常用参数

下面介绍 pt-query-digest 的常用参数：

• –since & --until：分析指定时间段的慢 SQL。

  # 指定时间范围
  pt-query-digest --since='2024-04-22 01:00:00' --until='2024-04-22 16:00:00' slow.log
  # 分析最近 12 小时的慢 SQL
  pt-query-digest --since=12h slow.log
  1
  2
  3
  4

• –limit： 按照总执行耗时排序，只输出指定比例或指定数量的分析结果，默认 95%。

• –review、–history： 支持将分析结果导入到数据库中。

• –output： 指定查询结果的分析输出格式，默认为 report，支持的选项有：slowlog、json、json-anon、secure-slowlog。

常用的方法是通过 output=json 对慢日志进行分析，然后将结果集中到分析服务器，然后将慢日志切割。

总结

本篇文章介绍了如何通过 pt-query-digest 对慢日志进行分析，并介绍如何解读分析结果，为后续的 SQL 优化工作奠定了基础。