数据库 CPU 正常但 active sessions 很高那次,我是怎么把会话堆积拆回等待链的?
一次库存中心事故里,数据库 CPU 只有三成多,active sessions 却一路冲高。真正有用的不是盯着 CPU 争论数据库忙不忙,而是把 active sessions 拆成锁等待、事务年龄、连接归还和回退后的回落顺序。
19:27,库存中心的几个接口一起开始发抖。
最先吵起来的不是慢 SQL,而是一张很让人别扭的图:
- 数据库 CPU 只有 34%
- 可 active sessions 从 23 跳到了 79
- 应用侧获取连接时间、接口 RT 也一起变差
这种场景特别容易陷进一句空争论:数据库 CPU 不高,那 active sessions 高是不是也没那么重要?
我现在基本不会这么看。因为 active sessions 真正难的地方,从来不是“它高不高”,而是 它里面堆着的到底是执行,还是等待。
那晚后来能收住,就是因为我没停在“数据库忙不忙”这层,而是把这批会话重新拆回了一条等待链。
我先判断:这些会话是在跑,还是在等?
19:25 到 19:31 这 6 分钟里,数据库和应用侧的关键指标是这样:
| 指标 | 19:25 | 19:30 |
|---|---|---|
| MySQL CPU | 27% | 34% |
| 平均 DB RT | 26ms | 41ms |
| active sessions | 23 | 79 |
| lock wait sessions | 0 | 24 |
| oldest transaction age | 180ms | 7.2s |
| Hikari 获取连接 p95 | 10ms | 590ms |
这张表本身已经很说明问题。
如果 active sessions 主要是执行型堆积,通常 CPU、I/O 或稳定慢 SQL 会更扎眼;可这次最夸张的是 lock wait sessions 和 oldest transaction age。所以我很快就把方向收到了:会话不是主要在跑,而是在等。
traceId 也能看到,请求慢不是慢在执行量,而是慢在排队等前一个事务出库
我抓了一条典型慢请求:traceId=98be6d3f10ef49c2
| 时间点 | 事件 |
|---|---|
| 19:29:11.004 | 请求进入 stock-center |
| 19:29:11.037 | 拿到连接 |
| 19:29:11.061 | 执行 update stock_reserve ... |
| 19:29:12.484 | SQL 返回 |
| 19:29:12.612 | 提交事务 |
| 19:29:12.659 | 返回响应 |
单看这条请求,好像就是更新语句慢了 1.4 秒。但再往数据库里看,同一时间点它其实是在等前面的事务释放锁,而不是自己真的在疯狂执行 1.4 秒。
也就是说,这次 active sessions 变高,不是“很多 SQL 都在很努力地跑”,而是“很多会话出不来”。
把会话堆积钉死的,是这批热点库存键和长事务
反复出现的问题都在这张表上:
update stock_reserve
set reserved_qty = reserved_qty + ?,
updated_at = now()
where sku_id = ? and warehouse_id = ?;
19:24 刚好上线了一批“活动库存预热”任务,也在并发改同一组热点 sku_id + warehouse_id。而且那批任务的写法是:
- 先查活动规则
- 开事务
- 同步调价格中心拿促销快照
- 再更新
stock_reserve - 最后写预热审计日志
价格中心 RT 抬到 800ms 左右以后,这批事务全都被拖长。于是等待链就长成了这样:
- 预热任务长事务先占住热点库存行
- 在线预占、释放、校准请求都开始等锁
- active sessions 被一层层挂高
- 连接归还变慢
- 应用侧获取连接 p95 跟着抬头
所以那张“CPU 不高但 active sessions 很高”的图,背后并不神秘,它只是把一条等待链浓缩成了一个数字。
为什么我没有先按“慢 SQL 执行型问题”去追
因为那晚有三件事都不支持这个方向。
CPU 不配合
34% 的 CPU 当然不是没负载,但也远远没到能解释 79 个 active sessions 都在拼命执行的程度。
慢日志不够集中
慢日志有增长,但没有一批稳定跑到 2、3 秒的 SQL。更多是大量 1 秒左右的更新,长相更像“被等出来”的慢,而不是“自己算出来”的慢。
锁等待和事务年龄太抢眼
lock wait sessions 从 0 到 24,oldest transaction age 到 7.2s,这已经足够说明问题主要在等待链,而不是纯执行层。
回退动作之后,回落顺序也证明 active sessions 只是结果层
19:32,我们先暂停“活动库存预热”任务;19:34,再把价格中心快照查询挪出事务,只保留必要的库存更新。
后面几分钟里,指标的回落顺序很有说服力:
| 时间 | 先回落的指标 | 后回落的指标 |
|---|---|---|
| 19:33 | oldest transaction age、lock wait sessions | - |
| 19:34 | active sessions、Hikari 获取连接 p95 | - |
| 19:35 | 库存预占接口 p95 | 订单确认 RT |
| 19:36 | 用户超时和重试量 | 基本恢复 |
这条顺序说明,active sessions 本身不是起点。最先掉下来的,是前面的事务年龄和锁等待;然后才是 active sessions 这层结果。
所以后来我再看 active sessions,会先拆这几层
- 它更像执行型堆积,还是等待型堆积?
lock wait、transaction age有没有一起抬头?- active sessions 高之前,是不是先有长事务或热点写冲突?
- 动作之后,最先回落的是等待源,还是 active sessions 自己?
把这几层拆开,active sessions 就不会再只是一个吓人的数字。
那晚真正的结论其实很简单:数据库 CPU 正常,不代表数据库方向没事;这次 active sessions 高,是因为一批热点库存事务和事务内慢下游把会话挂在等待链上了。
你只盯 CPU,会觉得它们不矛盾;你把等待链摊开以后,反而会觉得它们本来就该同时出现。