Java

连接池等待变长那晚,我怎么确认是数据库阶段慢了,不是应用拿着连接不放?

一次库存预占事故里,获取连接时间、连接持有时间和事务时长一起变差。真正有用的不是争论“数据库慢还是应用不放”,而是把借连接之后的时间拆开,看线程到底卡在库里还是库外。

  • 数据库连接池
  • HikariCP
  • MySQL
  • 长事务
  • 性能排查
13 分钟阅读

20:06,库存预占接口 POST /inventory/reserve 的 p95 从 160ms 抬到 1.6s,Hikari 获取连接 p95 很快冲到 520ms。

值班群里马上分成两派:

  • 一派说数据库慢了,连接当然回不来
  • 一派说应用代码有问题,把连接拿着不放

这两种话我都听过很多次,也都可能对。但那晚真正把问题收窄的,不是哪一派声音更大,而是先把 连接借出去之后,线程到底在干什么 拆清楚。

我先把 4 段时间放到一起看

当时最有用的不是总量图,而是下面这 4 段时间:

  • 获取连接耗时
  • 连接持有时长
  • 事务总时长
  • SQL 执行时间

18:00 到 20:10 的事故窗口里,最典型的一组指标是这样:

指标正常值事故窗口
获取连接 p959ms520ms
连接持有 p95140ms1.42s
事务总时长 p95146ms1.47s
SQL 执行总耗时 p95118ms1.31s

看到这张表以后,我第一反应就不是“应用把连接拿着不放”。因为如果大头主要耗在数据库之外,通常会出现一种很明显的长相:事务和连接持有很长,但 SQL 执行总耗时并不会一起变长。

可这次不是。事务、持连接和 SQL 耗时几乎一起被拉长,说明大头还在数据库阶段里。

traceId 里也能看出,连接拿到以后线程没有跑去等别的

我抽了一条最典型的慢请求:traceId=7bd44c6a2f4e48e1

时间点事件
20:06:18.044请求进入 inventory-service
20:06:18.071开始借连接
20:06:18.603成功拿到连接
20:06:18.621执行 select ... for update
20:06:19.488SQL 返回
20:06:19.506执行库存扣减更新
20:06:19.734提交事务
20:06:19.781返回响应

这条 trace 很有说服力。因为拿到连接之后,线程并没有去调 RPC、HTTP、MQ,也没有明显的大段本地计算;它几乎一路都待在数据库事务里。

这就把“应用拿着连接去等库外东西”这条线先压下去了。

为什么我没有先判成应用持连接过久

因为那晚应用侧最典型的几个高危信号都不成立。

没有事务里夹下游 RPC 的证据

这条链路里,库存校验和写库都在本地完成,没有同步调别的服务。调用图很短,没有那种“开着事务出去等 800ms RPC”的长相。

没有异常路径或手动连接管理问题

应用里用的是统一的数据访问层,没有手写 JDBC,也没有在报错栈里看到连接泄漏告警。重启单个实例后,症状能稍微缓一点,但 10 分钟后又回来,更像前面等待源没消失,而不是某条代码把连接永久吃掉。

连接持有时间和 SQL 时间同步变化

这点最关键。如果应用拿着连接不放,通常会看到:

  • SQL 时间一般
  • 事务时长很长
  • 连接持有时长跟着事务一起长

可这次不是,SQL 时间本身就已经很长了。

把根因钉死的,是这条 for update 和它背后的锁等待

反复出现的慢点是这条语句:

select available_qty
from inventory_bucket
where sku_id = ? and warehouse_id = ?
for update;

它的问题不是执行计划突然坏了,而是锁等待。

20:05 刚好有一批“预售库存回补”任务启动,和在线预占走的是同一组 sku_id + warehouse_id。结果就是:

  1. 回补任务先开事务锁住库存桶
  2. 在线预占请求进来后卡在 for update
  3. active sessions 抬高
  4. 连接归还变慢
  5. Hikari pending 开始出现
  6. 后续请求在池前面排队

数据库当时的证据很清楚:

指标20:0220:08
active sessions1758
lock wait sessions021
oldest transaction age240ms8.6s
MySQL CPU24%29%
Hikari pending013

这组数字也解释了为什么“数据库不高”这句话没法直接下结论。CPU 是不高,但锁等待和事务年龄已经把连接拖住了。

这次我怎么判断“数据库慢”和“应用拿着不放”

我后来越来越少空谈这个二选一,而是看下面这几个对照。

更像数据库阶段慢了的证据

  • SQL 执行总耗时同步拉长
  • 连接持有时长和 SQL 耗时一起拉长
  • trace 里拿到连接后基本都待在数据库事务里
  • lock wait sessionsactive sessionstransaction age 一起抬高

更像应用拿着不放的证据

  • SQL 时间一般,但事务和连接持有明显更长
  • 事务里夹了 RPC / HTTP / MQ / 大对象处理
  • 拿到连接以后,线程大段时间不在数据库里
  • 重启或切流后单实例恢复特别明显,数据库侧证据却不强

那晚四条证据几乎都落在前一类,所以我没有继续在“是不是应用不放”这条线上耗太久。

回退动作之后,回落顺序也说明判断没跑偏

20:11,我们先暂停“预售库存回补”任务;20:13,再把那批热点 SKU 的库存预占切到分桶队列,避免在线请求和回补直接撞锁。

后面几分钟的回落顺序是这样:

时间先回落的指标后回落的指标
20:12lock wait sessions、oldest transaction age-
20:13SQL 执行耗时、active sessionsHikari pending
20:14获取连接 p95、reserve 接口 p95-
20:15timeout 和库存失败重试基本恢复

这个顺序很关键。最先松的是锁等待和事务年龄,而不是应用线程池或别的本地资源;这说明真正卡住连接的,确实是数据库阶段的等待。

所以以后我会先问这句

后来我再碰到“连接池等待变长,到底是数据库慢还是应用拿着不放”时,第一句通常不是二选一,而是:

连接借出去之后,到归还之前,这个线程主要待在库里,还是待在库外?

如果答案更接近这次事故——线程拿到连接后基本一直在等锁、跑事务、等 SQL 返回——那我就继续往数据库等待链里追。

如果答案反过来——线程拿到连接后跑去等 RPC、做重计算、做消息确认——那才更像应用把连接带到了数据库之外的等待里。

别急着站队。把时间先拆开,很多争论其实自己就会结束。