连接池等待变长那晚,我怎么确认是数据库阶段慢了,不是应用拿着连接不放?
一次库存预占事故里,获取连接时间、连接持有时间和事务时长一起变差。真正有用的不是争论“数据库慢还是应用不放”,而是把借连接之后的时间拆开,看线程到底卡在库里还是库外。
20:06,库存预占接口 POST /inventory/reserve 的 p95 从 160ms 抬到 1.6s,Hikari 获取连接 p95 很快冲到 520ms。
值班群里马上分成两派:
- 一派说数据库慢了,连接当然回不来
- 一派说应用代码有问题,把连接拿着不放
这两种话我都听过很多次,也都可能对。但那晚真正把问题收窄的,不是哪一派声音更大,而是先把 连接借出去之后,线程到底在干什么 拆清楚。
我先把 4 段时间放到一起看
当时最有用的不是总量图,而是下面这 4 段时间:
- 获取连接耗时
- 连接持有时长
- 事务总时长
- SQL 执行时间
18:00 到 20:10 的事故窗口里,最典型的一组指标是这样:
| 指标 | 正常值 | 事故窗口 |
|---|---|---|
| 获取连接 p95 | 9ms | 520ms |
| 连接持有 p95 | 140ms | 1.42s |
| 事务总时长 p95 | 146ms | 1.47s |
| SQL 执行总耗时 p95 | 118ms | 1.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.488 | SQL 返回 |
| 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。结果就是:
- 回补任务先开事务锁住库存桶
- 在线预占请求进来后卡在
for update - active sessions 抬高
- 连接归还变慢
- Hikari
pending开始出现 - 后续请求在池前面排队
数据库当时的证据很清楚:
| 指标 | 20:02 | 20:08 |
|---|---|---|
| active sessions | 17 | 58 |
| lock wait sessions | 0 | 21 |
| oldest transaction age | 240ms | 8.6s |
| MySQL CPU | 24% | 29% |
Hikari pending | 0 | 13 |
这组数字也解释了为什么“数据库不高”这句话没法直接下结论。CPU 是不高,但锁等待和事务年龄已经把连接拖住了。
这次我怎么判断“数据库慢”和“应用拿着不放”
我后来越来越少空谈这个二选一,而是看下面这几个对照。
更像数据库阶段慢了的证据
- SQL 执行总耗时同步拉长
- 连接持有时长和 SQL 耗时一起拉长
- trace 里拿到连接后基本都待在数据库事务里
lock wait sessions、active sessions、transaction age一起抬高
更像应用拿着不放的证据
- SQL 时间一般,但事务和连接持有明显更长
- 事务里夹了 RPC / HTTP / MQ / 大对象处理
- 拿到连接以后,线程大段时间不在数据库里
- 重启或切流后单实例恢复特别明显,数据库侧证据却不强
那晚四条证据几乎都落在前一类,所以我没有继续在“是不是应用不放”这条线上耗太久。
回退动作之后,回落顺序也说明判断没跑偏
20:11,我们先暂停“预售库存回补”任务;20:13,再把那批热点 SKU 的库存预占切到分桶队列,避免在线请求和回补直接撞锁。
后面几分钟的回落顺序是这样:
| 时间 | 先回落的指标 | 后回落的指标 |
|---|---|---|
| 20:12 | lock wait sessions、oldest transaction age | - |
| 20:13 | SQL 执行耗时、active sessions | Hikari pending |
| 20:14 | 获取连接 p95、reserve 接口 p95 | - |
| 20:15 | timeout 和库存失败重试 | 基本恢复 |
这个顺序很关键。最先松的是锁等待和事务年龄,而不是应用线程池或别的本地资源;这说明真正卡住连接的,确实是数据库阶段的等待。
所以以后我会先问这句
后来我再碰到“连接池等待变长,到底是数据库慢还是应用拿着不放”时,第一句通常不是二选一,而是:
连接借出去之后,到归还之前,这个线程主要待在库里,还是待在库外?
如果答案更接近这次事故——线程拿到连接后基本一直在等锁、跑事务、等 SQL 返回——那我就继续往数据库等待链里追。
如果答案反过来——线程拿到连接后跑去等 RPC、做重计算、做消息确认——那才更像应用把连接带到了数据库之外的等待里。
别急着站队。把时间先拆开,很多争论其实自己就会结束。