老废物乐园

菜单

Administrator
发布于 2021-04-15 / 6414 阅读
103

一次数据库连接池耗尽导致的全线超时

#故障复盘#连接池

晚上八点半，所有接口一起超时

4 月 15 号晚上八点二十几分，告警群开始刷屏：订单服务全部接口超时，错误率 100%。

Pod 是活的，CPU 和内存都正常，CPU 只有 31%。但所有请求都在报同一个错：

2021-04-15 20:23:41.882 ERROR [http-nio-8080-exec-42] c.x.GlobalExceptionHandler
  : 系统异常
org.springframework.dao.DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is
org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available,
  request timed out after 30002ms (total=20, active=20, idle=0, waiting=87)

关键信息在最后一行括号里：

total=20    池子总共 20 个连接
active=20   全部在用
idle=0      空闲 0 个
waiting=87  还有 87 个线程在排队等连接

先看是什么在占着连接

HikariCP 本身不记录"哪个 SQL 占用了连接"，这是它相对 Druid 的一个短板。我当时用的是最原始的办法——直接查 MySQL：

mysql> SELECT id, user, host, db, command, time, state, LEFT(info, 80) AS sql_text
    -> FROM information_schema.processlist
    -> WHERE db = 'order_db' AND command != 'Sleep' ORDER BY time DESC LIMIT 20;
+-------+------+-----------------+------+---------+------+--------------+------------------------------------------+
| id    | user | host            | db   | command | time | state        | sql_text                                 |
+-------+------+-----------------+------+---------+------+--------------+------------------------------------------+
| 88231 | order| 10.0.1.31:44122 | order| Query   |   42 | Sending data | SELECT * FROM t_order_item WHERE create_t |
| 88234 | order| 10.0.1.31:44128 | order| Query   |   41 | Sending data | SELECT * FROM t_order_item WHERE create_t |
| ... 20 rows, 全部是同一条 SQL，time 都是 40 秒以上

20 条连接，全在执行同一条 SQL，已经跑了 40 多秒还没结束。

这条 SQL 从哪来的

把完整 SQL 拿出来看：

SELECT * FROM t_order_item
WHERE create_time >= '2021-03-01' AND create_time < '2021-04-01'
  AND merchant_id = 882341;

这是"商家订单导出"功能。那天是 4 月 15 号，正好可以导 3 月的账单，商家集中在这个时间点导出。

EXPLAIN 一下：

mysql> EXPLAIN SELECT * FROM t_order_item WHERE create_time >= ... AND merchant_id = 882341\G
***************************
           id: 1
  select_type: SIMPLE
        table: t_order_item
   partitions: NULL
         type: ALL              <-- 全表扫描
possible_keys: idx_merchant_id, idx_create_time
          key: NULL             <-- 索引一个没用上
         rows: 42318842
        Extra: Using where

扫 4231 万行。索引 idx_merchant_id 和 idx_create_time 都在，但优化器判断两个条件各自的选择性都不好，干脆全表扫。实际上建一个联合索引就能解决：

CREATE INDEX idx_merchant_time ON t_order_item(merchant_id, create_time);

mysql> EXPLAIN SELECT ... \G
         type: range
          key: idx_merchant_time
         rows: 12841

扫描行数从 4231 万降到 12841。

根因：慢 SQL 吃光了连接池，其他请求全被饿死

整个故障链条其实很短：

  1. 导出功能上线时没加联合索引，单条 SQL 要 40 秒以上
  2. 连接池只有 20 个连接，20 个商家同时导出就全被占满
  3. 其他所有需要数据库的请求排队，connectionTimeout 30 秒后超时
  4. Tomcat 的 200 个工作线程也跟着被占满，最后连不需要数据库的接口都不可用

一个次要功能的慢查询，拖垮了整个服务。这就是没有资源隔离的代价。

HikariCP 的参数怎么调

我们用的是 Spring Boot 2.4.3，默认连接池 HikariCP 3.4.5。

spring:
  datasource:
    hikari:
      maximum-pool-size: 20
      minimum-idle: 10
      connection-timeout: 30000
      idle-timeout: 600000
      max-lifetime: 1800000
      leak-detection-threshold: 60000
      connection-test-query: SELECT 1      # 驱动支持 JDBC4 的话可以不配
      validation-timeout: 5000

逐个说明我的理解：

maximum-pool-size 不是越大越好

HikariCP 官方文档里有一句很经典的话，大意是：如果你有 4 核的机器，连接池 10 个连接就够了，再多只会让数据库更慢。

原因是数据库连接是有代价的：每个连接对应 MySQL 的一个线程，连接越多，MySQL 的上下文切换、锁竞争、内存占用越大。几十个客户端各开 100 个连接，MySQL 要处理几千个线程，性能会断崖式下降。

官方给的参考公式：

connections = ((core_count * 2) + effective_spindle_count)

我们的情况：8 核 + SSD(有效磁盘数按 1~2 算)
= 8 * 2 + 2 = 18 ≈ 20

所以 20 这个数字是合理的。真正的问题不是池子太小，是慢 SQL 占用时间太长。把 20 调到 100 只会让故障晚 4 倍时间发生，同时让 MySQL 压力增加 5 倍。

leak-detection-threshold：连接泄漏检测

这个参数默认 0（关闭），我强烈建议打开。它检测的是"连接借出去多久没还"：

leak-detection-threshold: 60000     # 60 秒

超过阈值，HikariCP 会打一条 WARN 日志，带着借出连接时的完整堆栈：

2021-04-15 20:24:02.118 WARN  [HikariPool-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask
  : Apparent connection leak detected in com.xxx.OrderExportService.export
java.lang.Exception: Apparent connection leak detected
    at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128)
    at com.xxx.OrderExportService.export(OrderExportService.java:88)
    at com.xxx.ExportController.export(ExportController.java:42)
    ...

这次事故之后我们把这个参数设成了 60 秒。注意它的单位：Spring Boot 的 leak-detection-threshold 是毫秒，原生 HikariCP 的 leakDetectionThreshold 也是毫秒。设成 60000 才是 60 秒，写 60 的话会疯狂告警（因为几乎所有超过 60ms 的查询都会触发）。

它有一点性能开销（每次借出/归还都要记录堆栈），但只在超过阈值时才真正打日志，可以接受。

connection-timeout：多久算超时

默认 30 秒。这个数字应该小于上游给你的超时时间。我们的网关超时是 10 秒，那连接池还等 30 秒就毫无意义——网关早就断开了，请求白做。

我们改成了 8 秒，让请求快速失败，Tomcat 线程尽快释放。

max-lifetime 要小于 MySQL 的 wait_timeout

mysql> SHOW VARIABLES LIKE 'wait_timeout';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| wait_timeout  | 28800 |    -- 8 小时
+---------------+-------+

max-lifetime 默认 1800000（30 分钟），比 MySQL 的 8 小时短很多，这是对的。它的作用是让连接定期重建，避免长时间运行的连接出问题（比如 MySQL 端重启、网络抖动导致的半开连接）。

注意别设得比 MySQL 的 wait_timeout 长，否则连接会被 MySQL 单方面断开，客户端还以为是好的。

我们的四个改动

1. 加联合索引（治本）

这条 SQL 从 40 秒降到 180 ms。

2. 导出走独立的只读连接池（隔离）

慢查询是不可避免的，重点是别让它影响主流程。我们把导出、报表、运营后台这些"重查询"全部切到只读库，用独立的连接池：

@Configuration
public class DataSourceConfig {

    @Bean("masterDs")
    @ConfigurationProperties("spring.datasource.master")
    public DataSource masterDataSource() { return DataSourceBuilder.create().build(); }

    @Bean("replicaDs")
    @ConfigurationProperties("spring.datasource.replica")
    public DataSource replicaDataSource() { return DataSourceBuilder.create().build(); }

    @Bean("exportDs")
    @ConfigurationProperties("spring.datasource.export")
    public DataSource exportDataSource() { return DataSourceBuilder.create().build(); }
}

spring:
  datasource:
    master:
      jdbc-url: jdbc:mysql://10.0.1.10:3306/order_db
      hikari:
        maximum-pool-size: 20        # 主流程
        connection-timeout: 8000
        leak-detection-threshold: 30000
    export:
      jdbc-url: jdbc:mysql://10.0.1.12:3306/order_db   # 只读从库
      hikari:
        maximum-pool-size: 5         # 故意给很少
        connection-timeout: 30000
        leak-detection-threshold: 120000

导出池只给 5 个连接，而且慢一点没关系。它挂了也不影响下单。

3. 导出改成异步 + 限流

同步导出一个月的订单本来就不合理。改成提交任务 → 后台生成文件 → 短信通知下载。

// 同时最多 3 个导出任务在跑
Semaphore exportPermit = new Semaphore(3);

public String submitExport(Long merchantId, DateRange range) {
    if (!exportPermit.tryAcquire()) {
        throw new BizException("当前导出任务较多，请稍后再试");
    }
    ...
}

4. 把池的指标纳入监控

这是最该早做的一件事。Spring Boot Actuator 自带 HikariCP 的指标：

$ curl http://localhost:8080/actuator/metrics/hikaricp.connections.active
{"name":"hikaricp.connections.active","measurements":[{"statistic":"VALUE","value":18.0}],
 "availableTags":[{"tag":"pool","values":["HikariPool-1"]}]}

$ curl http://localhost:8080/actuator/metrics/hikaricp.connections.pending
{"name":"hikaricp.connections.pending","measurements":[{"statistic":"VALUE","value":0.0}]}

告警规则：

hikaricp_connections_active / maximum_pool_size > 0.8   持续 1 分钟  → 警告
hikaricp_connections_pending > 0                        持续 30 秒  → 严重告警
hikaricp_connections_usage_seconds 的 P99 > 1 秒        → 警告（说明有慢 SQL 占用）

第二条最关键。pending 是"正在排队等连接的线程数"，它大于 0 就意味着连接池已经不够用了，比接口超时早得多。

下篇预告

这篇先把《一次数据库连接池耗尽导致的全线超时》里的坑列了，下一篇写我们当时是怎么在线上工程里真正落地的——包括那次让领导拍桌的故障复盘。

参考

微服务架构中的韧性设计：Resil...
SkyWalking 链路追踪接入实践