一、现象:监控全绿,P99 却间歇性 3 秒
先给结论:这次 P99 毛刺的根因不是慢 SQL、不是连接池打满、不是 GC,而是一个 @Transactional 方法里偷偷夹了三次 HTTP 调用——每次 200~800ms,把单请求的「连接持有时间」从 12ms 拉到 2~4 秒。连接池没满(active 长期 6~9 / 20)、pending 恒为 0,但按 Little's Law 一算,队列已经悄悄排到 5~6 个请求,P99 打到 3000ms 只是时间问题。
背景(已脱敏):2024 年 5 月,一个对账服务(Spring Boot 3.1.5,JDK 17,HikariCP 5.0.1,MySQL 8.0.36),单实例 8C16G,前置 3 副本。日常 QPS 约 300,白天 P50 稳定 14ms、P99 45ms。5 月 12 日下午 14:20 起,P99 开始间歇性飙到 2.8~3.4s,每天 14:00~15:30 高发、持续约 2 小时,网关 5xx 占比冲到 11%。
诡异的是,该看的全看了:
SHOW GLOBAL STATUS LIKE 'Threads_running'峰值才 9,MySQLmax_connections=1000,活跃连接 11;hikaricp_connections_active长期 6~9(maximumPoolSize=20),hikaricp_connections_pending恒为 0;- 慢查询日志(
long_query_time=1.0)一条没有,单条 SQL 的 P99 都 < 30ms; - CPU 22%、GC 暂停 P99 < 8ms,JVM 全绿。
按「连接池打满」的套路,这些指标全绿,根本不该 P99 3 秒。问题就出在:连接持有时间被拉长了,但拉长它的不是 DB。
二、根因:连接持有时间 = 事务从 BEGIN 到 COMMIT 的全部墙钟时间
HikariCP 借出连接后,这条连接在 close() 前一直占用;而 close() 在事务提交之后才触发。也就是说,一个 @Transactional 方法里夹了什么,连接就被持有多久——单条 SQL 再快也没用,整个事务的墙钟时间才决定占用时长。
用 Little's Law 算(思路同谢寒山在 HikariCP 那篇,但根因不同):
需要的并发连接数 ≈ QPS × 单请求连接持有时间
正常: 300 QPS × 12ms ≈ 3.6 个连接 → 池 20 绰绰有余,pending=0
出了事: 300 QPS × 2.5s ≈ 750 个连接需求
那为什么 active 才 8~9、pending 还是 0?因为 14:00 起 QPS 其实掉到了 ~40(上游对账任务错峰),40 QPS × 2.5s ≈ 100 个需求——仍远超 20。真正解释 pending=0 的是:请求没并发到,它们一个接一个串行过,每个都「拿得到连接」,只是拿到时前面那位还没还。 所以 active 不高、pending 为 0,但每个请求都在等前一个事务 COMMIT,这段等待被计进了 P99。
那 2.5s 从哪来?Arthas 一 trace 就露馅:
[arthas@123]$ trace com.xxx.reconcile.ReconcileService doReconcile '#cost > 1000'
`---[1248.62ms] com.xxx.reconcile.ReconcileService : doReconcile()
+---[0.82ms] com.xxx.mapper.ReconcileMapper : selectByBatch()
+---[412.30ms] com.xxx.rpc.FeeCalcClient : calc() # HTTP 调用 1
+---[0.55ms] com.xxx.mapper.ReconcileMapper : updateStatus()
+---[690.12ms] com.xxx.rpc.NotifyClient : push() # HTTP 调用 2
+---[148.77ms] com.xxx.rpc.AuditClient : log() # HTTP 调用 3
`---[0.41ms] com.xxx.mapper.ReconcileMapper : markDone()
三次下游 HTTP 调用(费用计算、通知、审计)合计 1.25s,加上事务里两次 FLUSH 的锁等待,单请求持有连接 2.4~2.8s。而这三次的下游在 14:00 恰好进入它们自己的批处理窗口,RT 从 60ms 涨到 400~700ms——抖动源在下游,代价由我的连接池付。
三、具体做法:把 RPC 移出事务,并给「事务持有时间」加护栏
第一步:把三次 HTTP 调用挪出 @Transactional。 拆成「事务内只写库」+「事务外发 RPC」:
// 改法:事务外编排
public ReconcileResult doReconcile(BatchId id) {
long fee = feeCalcClient.calc(rowsOf(id)); // 1) 先算,不占连接
long finalFee = doReconcileInTx(id, fee); // 2) 事务内只写库(updateStatus + markDone)
notifyClient.push(id, finalFee); // 3) 提交后再发通知
auditClient.log(id, finalFee); // 4) 提交后再写审计
return new ReconcileResult(id, finalFee);
}
改完当天 P99 从 2.8s 回落到 52ms,pending 依旧 0,active 回落到 3~4。
第二步:给「事务持有时间」加可观测护栏。 光改这一次不够,要把「持有时间」显式化:
-- 看当前最久的活跃事务(MySQL 8.0)
SELECT trx_id, trx_state, trx_started,
TIMESTAMPDIFF(SECOND, trx_started, NOW()) AS held_sec
FROM information_schema.innodb_trx
ORDER BY trx_started ASC LIMIT 5;
配合 HikariCP leak-detection-threshold=3000(借出超 3s 打 WARN 栈),以及 Prometheus 上把 hikaricp_connections_usage(借出时长直方图)的 P99 设成告警线——告警线定在「正常持有时间 × 5」,这次就是 12ms × 5 = 60ms,超了立刻查事务边界。
四、踩过的坑 / 反直觉
- 「pending=0 + active 没满」≠「连接池健康」。 连接池有两种病:一种是「拿不到」(pending 堆积),另一种是「拿到了但拿到时前面那位还没还」(串行排队)。后者 pending 恒为 0、监控全绿,只有 P99 在抖。判据不是 active/max 占比,而是借出时长直方图的 P99。
- 慢日志里没有慢 SQL,不代表没有慢事务。 单条 SQL 都 <30ms,但一个事务里串了 5 条 SQL + 3 次 HTTP,整体 2.5s。慢日志只记「单条」,不记「事务」。
- 抖动源在下游,代价在我这付。 14:00 的毛刺不是我的 SQL 变慢,是下游费用服务进批处理窗口。这类「别人慢、我付钱」的抖动,靠我自己的慢日志永远查不出来,必须 trace 到方法级。
- 把 RPC 移出事务后,要重新想「一致性」。 通知/审计从「事务内同步」变成「事务外异步」,失败语义变了。我加了一个本地 outbox 表兜底(写业务库和写 outbox 同事务,outbox 由独立 worker 消费发 RPC),而不是裸调。
五、结论与可复用清单
- 连接持有时间 = 事务 BEGIN 到 COMMIT 的全部墙钟时间,里面夹的每一次网络 IO、每一次锁等待都算。
- 两个判据:看
hikaricp_connections_usageP99(持有时间),别只看 active/pending;看innodb_trx里held_sec超阈值的活跃事务。 - 护栏:
leak-detection-threshold按「正常持有 × 5」设;Prometheus 对持有时间 P99 告警。 - 改法:事务内只写库,RPC / 通知 / 审计移到事务外,失败用 outbox + 异步 worker 兜底。
- 诊断三板斧:Arthas
trace ... '#cost > 1000'找事务方法里藏的网络调用;information_schema.innodb_trx看最久事务;下游 RT 曲线对齐抖动时段。
留个开放问题给大家: 你们团队对「事务里能不能发 RPC」有没有明文规范?我见过两种极端——一种是「绝对禁止」,另一种是「只要 RT 可控就行」。如果下游 RT 从 60ms 漂到 600ms,你的「可控」还成立吗?你们是用静态扫描(ArchUnit 规则)卡,还是靠 code review 盯?欢迎带你们的判据来聊。