接口慢、CPU/GC/数据库都不高时，我是怎么沿一条隐藏等待链把问题找出来的？
一次下单接口变慢事故里，CPU、GC、数据库总量图都不吓人，真正拖时间的却是连接等待和事务里的额外停留。把时间线、traceId、pool pending、transaction age 和回退后的回落顺序对齐，隐藏卡点就不难找了。
19:12，订单提交接口 POST /api/order/submit 的 p95 从 180ms 抬到 2.4s。
第一眼看监控，其实很容易被带偏：
- 应用 CPU 只有 43%
- Full GC 还是 0
- MySQL CPU 28%
- 数据库 RT 平均 32ms
- 慢 SQL 面板也没突然爆掉
群里最先出现的几句判断，都是熟悉的那套：是不是网络抖了，是不是线程池卡了，是不是监控漏掉了哪张图。
但那晚真正的问题，不在“哪张总量图不正常”，而在一条很具体的等待链里：请求进应用很快，线程也没忙死，真正丢掉的 1 秒多时间，卡在了拿连接和持连接等待上。
我先把 6 分钟里的时间线摊平
先不猜原因，先把同一时间窗里最关键的指标放到一起。
| 时间 | 现象 | 数值 |
|---|---|---|
| 19:12:10 | submitOrder p95 开始抬头 | 180ms -> 910ms |
| 19:12:40 | Hikari 获取连接 p95 抬头 | 8ms -> 640ms |
| 19:13:00 | Hikari pending 开始出现 | 0 -> 17 |
| 19:13:20 | active sessions 抬高 | 21 -> 66 |
| 19:13:40 | 应用报连接等待超时前的慢请求激增 | trace 样本明显增加 |
| 19:14:10 | MySQL CPU 仍然平稳 | 28% |
这张表很重要，因为它先回答了一个问题：慢不是先从 CPU、GC、数据库总负载上冒出来的，而是先从连接获取这段冒出来的。
如果顺序反过来，比如先是 CPU 打满、或者慢 SQL 面板突然炸开，那排查入口就不是这一条了。
真正把我拉回主线的，是一条 traceId
那晚我抓了几十条慢请求，最有价值的是这条 trace：traceId=9f3e7c4a9d5b4d7b
| 时间点 | 事件 |
|---|---|
| 19:13:18.021 | 网关收到请求 |
| 19:13:18.034 | order-service access log 记到请求 |
| 19:13:18.052 | 业务代码进入 submit() |
| 19:13:19.311 | 才真正拿到数据库连接 |
| 19:13:19.337 | 第一条 SQL 发出 |
| 19:13:19.486 | SQL 返回 |
| 19:13:20.104 | 事务提交 |
| 19:13:20.171 | 响应返回 |
这条链一下就把“隐藏等待点”钉出来了。
请求进应用只花了十几毫秒，第一条 SQL 本身也只跑了 149ms，可总耗时却到了 2 秒左右。真正消失的时间，不在 CPU，不在 GC，也不在“数据库已经慢到跑不动”，而在 19:13:18.052 到 19:13:19.311 这段拿连接之前的等待，以及 拿到连接之后事务没有立刻结束的那段持有时间。
为什么我没有先去追线程池和网络
因为那晚这两条线都缺少第一现场证据。
线程池不像主因
同一时间窗里应用线程池是这样：
| 指标 | 19:10 | 19:14 |
|---|---|---|
biz-exec active | 47 / 200 | 59 / 200 |
biz-exec queue | 0 | 2 |
| Tomcat busy | 81 / 400 | 96 / 400 |
线程是忙了一点，但离“先排队把接口拖慢”还差得远。
网络也不像主因
下游建连时间、TLS 握手和 DNS 都很平：
connect timep95：11ms- TLS handshake p95：18ms
- DNS：缓存命中，没有抖动
如果问题主要在网络，请求往往会慢在出应用之前，或者同一个 trace 在对端根本看不到。可这批慢请求里，数据库连接拿到以后，SQL 很快就出去了，说明大头不在网络前半段。
真正的隐藏卡点，其实已经写在连接池和事务指标里了
再把应用和数据库两边的证据拼起来，等待链就完整了。
应用侧
| 指标 | 19:10 | 19:14 |
|---|---|---|
| Hikari active | 19 / 40 | 39 / 40 |
| Hikari idle | 21 | 1 |
| Hikari pending | 0 | 17 |
| 获取连接 p95 | 8ms | 640ms |
| 连接持有 p95 | 120ms | 1.74s |
数据库侧
| 指标 | 19:10 | 19:14 |
|---|---|---|
| active sessions | 21 | 66 |
| lock wait sessions | 0 | 18 |
| oldest transaction age | 180ms | 7.8s |
| DB RT 平均 | 29ms | 32ms |
这里最值得看的，不是 DB RT 平均值，而是 oldest transaction age 和 lock wait sessions。数据库没“打满”，不等于数据库方向没问题；这次是库里有一批会话在等锁、等事务结束，结果把连接归还速度拖慢了。
把根因钉死的，是这条 SQL 和它前面的长事务
样本里反复出现的是这条更新：
update promotion_usage
set used_count = used_count + 1,
updated_at = now()
where promotion_id = ? and user_id = ?;它本身不是超慢 SQL，问题在于它前面那段事务边界拉长了。
order-service 里有一段代码，先拿连接开事务，再去同步调用 pricing-service 补齐优惠快照，等快照回来了才真正更新 promotion_usage。19:11 刚上线的一个“优惠重算”开关，把这段 RPC 从 90ms 拉到了 900ms 左右，结果就变成：
- 连接先被借走
- 事务开着不提交
- 后面的更新开始遇到锁等待
- active sessions 抬高
- 连接归还变慢
- 后续请求开始在池子前面排队
这就是那晚的隐藏等待链。图上看 CPU 很稳，实际上时间全耗在“等”上了。
回退动作之后，回落顺序也证明我没看错
19:16，我们先灰度关掉“优惠重算”开关；19:18，再暂停一批正在跑的促销回填任务。
后面几分钟里的回落顺序非常干净：
| 时间 | 先回落的指标 | 后回落的指标 |
|---|---|---|
| 19:17 | oldest transaction age、lock wait sessions | - |
| 19:18 | Hikari pending、获取连接 p95 | - |
| 19:19 | submitOrder p95 | 网关超时 |
| 19:20 | 用户投诉量 | 基本恢复 |
如果我前面判断错了，比如其实是线程池或网络主因，这个回落顺序不会这么整齐。那晚最先恢复的，就是事务年龄、锁等待和连接获取时间，说明问题确实卡在这条等待链上。
这类“什么都不高但接口很慢”的现场，先别问谁打满了
那晚之后我对这类故障的第一反应就变成了另一句：
不要先问 CPU、GC、数据库谁打满了，先问 trace 里哪一段时间凭空消失了。
如果你也碰到这种现场，至少先把下面几样对齐：
- 一条慢请求的 traceId 时间线
- 获取连接耗时和
pending - active sessions、lock wait、transaction age
- 动作后的回落顺序
很多所谓“隐藏等待点”，其实并不神秘。它只是刚好不会在 CPU、GC、数据库总量图上大声喊出来，但会老老实实写在请求时间线和连接归还速度里。