老废物乐园

菜单

Administrator
发布于 2018-12-12 / 452 阅读
2

从 slow query log 到 explain：慢 SQL 排查的标准流程

#SQL优化#explain

DBA 甩给我一个 2.3G 的慢日志文件，说"你们那边先看看"

双十二前一周，DBA 在群里发了条消息：订单库 QPS 涨了 3 倍，慢查询日志一天产生 2.3G，让各个业务方自查。我负责的订单模块首当其冲。

拿到日志文件的时候我是懵的，2.3G 文本，几百万行，根本没法用编辑器打开。这篇记录我当时摸索出来的处理流程。

第一步：确认慢日志是开着的

mysql> SHOW VARIABLES LIKE 'slow_query%';
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| slow_query_log      | ON                                   |
| slow_query_log_file | /data/mysql/data/mysql-slow.log      |
+---------------------+--------------------------------------+

mysql> SHOW VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+

如果没开，可以在线开（不需要重启）：

SET GLOBAL slow_query_log = 'ON';
SET GLOBAL long_query_time = 1;
SET GLOBAL log_queries_not_using_indexes = 'ON';      -- 记录没走索引的查询

要永久生效得改 my.cnf：

[mysqld]
slow_query_log = 1
slow_query_log_file = /data/mysql/data/mysql-slow.log
long_query_time = 1
log_queries_not_using_indexes = 1
log_output = FILE

long_query_time 设成 1 秒是我们那次的临时调整，平时设的是 2 秒。注意这个变量的精度：5.7 支持微秒级，可以设成 0.5。另外 log_queries_not_using_indexes 要谨慎开，全表扫描的小表查询也会被记进去，日志量会暴涨——我们开了一小时就收到 4G，赶紧关了。

还有个坑：在线改 long_query_time 之后，只对新建的连接生效，已经存在的连接还是用旧值。我们的连接池是长连接，改完之后半小时日志里才出现新阈值下的记录，我还以为没生效。

第二步：用 mysqldumpslow 做聚合

直接看原始日志是不现实的，MySQL 自带了聚合工具：

$ mysqldumpslow -s t -t 20 /data/mysql/data/mysql-slow.log

参数含义：-s 指定排序依据，-t 是取前 N 条。常用的排序方式：

  • t：总耗时（默认）
  • c：出现次数
  • r：单次返回行数
  • at：平均耗时

输出长这样：

Reading mysql slow query log from /data/mysql/data/mysql-slow.log
Count: 128432  Time=3.42s (439238s)  Lock=0.00s (12s)  Rows=1.0 (128432), root[root]@[10.0.2.31]
  SELECT * FROM t_order WHERE user_id = N AND status = N ORDER BY created_at DESC LIMIT N

Count: 89301  Time=2.11s (188425s)  Lock=0.00s (3s)  Rows=0.0 (0), root[root]@[10.0.2.32]
  SELECT count(*) FROM t_order o LEFT JOIN t_order_item i ON o.id = i.order_id WHERE o.shop_id = N

注意工具会把具体值替换成 N 和 S，把结构相同的 SQL 归为一类。第一条累计执行了 12.8 万次，总耗时 439238 秒（注意单位是秒，这是所有执行加起来），平均 3.42 秒——这就是最大的那一头。

我后来更喜欢用 percona 的 pt-query-digest，输出信息更全：

$ pt-query-digest --limit 10 /data/mysql/data/mysql-slow.log > report.txt

# Profile
# Rank Query ID           Response time      Calls   R/Call   V/M   Item
# ==== ================== ================== ======= ======== ===== ======
#    1 0x8F3A2B1C4D5E6F7A  439238.1200 62.1%  128432   3.4198  0.12 SELECT t_order
#    2 0x1A2B3C4D5E6F7A8B  188425.3400 26.6%   89301   2.1098  0.34 SELECT t_order t_order_item

第三步：看单条日志的完整信息

聚合之后还要看原始记录，因为里面有具体的执行环境：

# Time: 2018-12-11T14:23:07.412937Z
# User@Host: order[order] @  [10.0.2.31]  Id: 4821339
# Query_time: 3.420181  Lock_time: 0.000121  Rows_sent: 1  Rows_examined: 2148573
# Rows_affected: 0
SET timestamp=1544535787;
SELECT * FROM t_order WHERE user_id = 900120 AND status = 2
ORDER BY created_at DESC LIMIT 20;

四个关键数字：

  • Query_time: 3.420181：总耗时 3.42 秒。
  • Lock_time: 0.000121：等锁 0.12 毫秒，说明不是锁竞争的问题。如果这个值很大，就要去查有没有长事务堵着。
  • Rows_sent: 1：只返回了 1 行。
  • Rows_examined: 2148573：扫描了 214 万行。

扫描 214 万行只返回 1 行，这两个数字的比值是判断索引好坏最直观的指标。好的查询这个比值应该接近 1。

第四步：EXPLAIN 看执行计划

EXPLAIN SELECT * FROM t_order
WHERE user_id = 900120 AND status = 2
ORDER BY created_at DESC LIMIT 20\G

结果：

*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: t_order
   partitions: NULL
         type: ALL
possible_keys: idx_user_id
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 2148573
     filtered: 1.00
        Extra: Using where; Using filesort

逐列说下我怎么看：

type：访问类型，最重要的列

从好到坏：

system > const > eq_ref > ref > range > index > ALL
type含义出现场景
system表里只有一行极少见
const主键或唯一索引命中一行WHERE id = 1
eq_refjoin 时被驱动表走主键/唯一索引多表关联，最优的 join 类型
ref普通索引等值匹配，可能多行WHERE user_id = ?
range索引范围扫描BETWEEN、>、IN
index全索引扫描，遍历整棵索引树SELECT count(*) 走覆盖索引
ALL全表扫描要优化的信号

我的经验是：range 及以上通常可以接受，出现 index 和 ALL 就得看看了。上面这条 SQL 是 ALL。

possible_keys 和 key

possible_keys 是优化器认为可能用得上的索引，key 是实际决定用的索引。上面这条：可能用 idx_user_id，实际用了 NULL。

为什么不用？因为 SELECT * 要回表取全部字段，而 user_id = 900120 这个条件命中的行数很多（这个用户是批发商，有 3 万多笔订单），优化器估算下来，走索引再回表 3 万次的代价比直接全表扫描还高，于是放弃了。

这种"优化器主动放弃索引"的情况，可以用 FORCE INDEX 验证到底哪个快：

EXPLAIN SELECT * FROM t_order FORCE INDEX(idx_user_id)
WHERE user_id = 900120 AND status = 2\G

我测下来两种方式的实际耗时：全表扫 3.42 秒，强制走索引 4.81 秒。优化器是对的，问题不在索引选择上。真正的病根是排序。

rows 和 filtered

  • rows：预计要扫描的行数。上面是 2148573，跟慢日志里的 Rows_examined 对得上。
  • filtered：存储引擎返回的数据中，经过 WHERE 条件过滤后剩余百分比。1.00 表示只剩 1%。数值越低说明过滤掉的越多，索引越不给力。

Extra：补充说明，信息量最大的一列

Extra含义好坏
Using index覆盖索引，不用回表好
Using index conditionICP 优化，过滤下推到引擎层较好
Using whereserver 层再做一次过滤中性
Using filesort需要额外排序，可能落盘差，重点关注
Using temporary创建了临时表（group by / distinct 常见）差，重点关注
Using join bufferjoin 没走索引，用了块嵌套循环差

Using filesort 是我这条 SQL 的症结。ORDER BY created_at DESC 需要把 3 万条匹配记录全部取出，在内存或磁盘上排序，再取前 20 条。这个排序的开销占了大头。

验证一下排序是不是真的落盘了：

mysql> SHOW STATUS LIKE 'Sort%';
+-------------------+--------+
| Variable_name     | Value  |
+-------------------+--------+
| Sort_merge_passes | 847    |   ← 这个值大于 0 说明排序用了临时文件
| Sort_range        | 12     |
| Sort_rows         | 342811 |
| Sort_scan         | 2141   |
+-------------------+--------+

mysql> SHOW VARIABLES LIKE 'sort_buffer_size';
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| sort_buffer_size | 262144 |   ← 256KB，太小了

最终的优化

病根清楚了：需要一个能同时满足 user_id 过滤和 created_at 排序的索引，并且避免回表。

ALTER TABLE t_order ADD INDEX idx_user_status_time (user_id, status, created_at);

加完之后：

         type: range
          key: idx_user_status_time
      key_len: 13
         rows: 24
        Extra: Using where

type 从 ALL 变成 range，rows 从 214 万降到 24，Using filesort 消失了。key_len=13 = user_id(8) + status(1) + created_at(5)... 实际算出来是 14（datetime 5.7 是 5 字节，加上 tinyint 的 NULL 标志 1 字节），反正三个字段都用上了。

实测效果：

指标优化前优化后
平均耗时3420 ms11 ms
Rows_examined214857324
慢日志日增量2.3 GB140 MB
数据库 CPU峰值 87%峰值 34%

一个加速排查的补充工具

MySQL 5.7 支持在 explain 之后立刻执行 SHOW WARNINGS，能看到优化器改写后的 SQL，对理解"为什么索引没用上"很有帮助：

mysql> EXPLAIN SELECT * FROM t_order WHERE user_id = '900120' AND status = 2;
mysql> SHOW WARNINGS\G
*************************** 1. row ***************************
  Level: Note
   Code: 1003
Message: /* select#1 */ select `order`.`t_order`.`id` AS `id`, ...
         from `order`.`t_order`
         where ((`order`.`t_order`.`user_id` = 900120)
            and (`order`.`t_order`.`status` = 2))

我靠这个发现过一次隐式类型转换：user_id 是 bigint，我传了字符串 '900120'，看 warning 会发现它把常量转成了数字，这次侥幸没影响索引；但如果字段是 varchar 而你传了数字，warning 里会出现 cast(...)，那就是索引失效的铁证。

另外 5.7 还有 EXPLAIN FORMAT=JSON，输出的信息更详细，包括优化器估算的成本值：

EXPLAIN FORMAT=JSON SELECT ...\G
# "query_cost": "431245.60"

对比不同索引方案下的 query_cost，能定量地判断哪个更优，比拍脑袋强。

我现在的固定流程

  1. 慢日志确认开关和阈值；
  2. mysqldumpslow 或 pt-query-digest 聚合，按总耗时排序抓 top SQL；
  3. 看单条日志的 Rows_examined / Rows_sent 比值，判断是不是索引问题；
  4. EXPLAIN 看 type、key、rows、Extra；
  5. 有疑问就 SHOW WARNINGS 看改写后的 SQL；
  6. 改完索引或 SQL，再 explain 一次对比，并用真实数据验证耗时。

最后提醒一句：EXPLAIN 里的 rows 是估算值，基于索引的统计信息（cardinality）。如果统计信息过期，估算会严重偏离。我遇到过一次 rows 显示 200 但实际扫了 50 万行，用 ANALYZE TABLE t_order 刷新统计信息之后就准了。另外 EXPLAIN 不会真正执行 SQL，它给的是优化器的估算。想要各阶段（排序、临时表、发送数据）的真实耗时，可以开 profiling： 

SET profiling = 1;
SELECT ...;
SHOW PROFILES;
SHOW PROFILE FOR QUERY 1;

输出里能看到 Sending data、Sorting result 这些阶段分别花了多少时间，比只看总耗时更容易定位瓶颈在哪一步。

参考

数据库连接池参数怎么配？Druid...
@Autowired 注入失败的各...