Java

结算确认那次真正拖慢系统的,不是慢 SQL,而是开着事务等票据服务回包

这篇只讲一次结算事故:`POST /settlement/confirm` 先坏掉,库里随后冒出长事务、锁等待和连接池紧张。问题不在于先讲“长事务怎么拆”,而在于先看见有人把远程调用包进了事务。

  • 事务
  • MySQL
  • 长事务
  • 性能排查
  • 接口优化
11 分钟阅读

18:18,结算确认接口 POST /settlement/confirm 的 p95 一下子从 220ms 抬到 3.1s。

这类事故很容易把人带进熟悉套路里:有人去刷慢 SQL 面板,有人开始看 EXPLAIN,还有人会先把“长事务”当成一个偏数据库侧的大类标签,然后准备展开一套分段教学。

但那晚真正有用的,不是先讲长事务应该怎么分析,而是先看见一个更刺眼的现场事实:

有批请求已经开了事务,却在事务里等票据服务回包。

这个事实一旦成立,后面的锁等待、连接池变紧、active sessions 抬高,几乎都会顺着长出来。

先把人压住的,不是慢 SQL 图,而是那几笔一直活着的事务

18:19 左右,DBA 在库里扫到几笔异常活跃事务,截了这样一段:

---TRANSACTION 421441208, ACTIVE 6 sec
mysql tables in use 2, locked 2
5 lock struct(s), heap size 1128, 2 row lock(s)
MySQL thread id 902145, query id 5488721 app_rw update
update settlement_record
   set status = 'CONFIRMED',
       invoice_snapshot_id = 'inv_938217',
       updated_at = now()
 where settlement_id = 'st_673241';

另一边应用日志也不太对劲:

18:19:08.962 INFO  invoice-service call slow, traceId=5d70e13fa2ab4c71, costMs=1781
18:19:09.517 WARN  tx commit slow, traceId=5d70e13fa2ab4c71, txMs=2456
18:19:09.518 INFO  hikari pool stats total=40 active=40 idle=0 waiting=9

这几行信息放在一起,比“慢 SQL 多不多”更值得先看。

因为它们说明:库里确实已经有长事务,而且这些长事务不是纯 SQL 跑得飞起,而是事务开着的时候,应用线程还在等一次外部 RPC。

这条慢请求最扎眼的地方,是开事务之后先去等票据服务

我后来把最典型的一条请求捞出来,traceId=5d70e13fa2ab4c71,按时间摊开以后是这样的:

时间点发生的事
18:19:07.024请求进入 settlement-service
18:19:07.061开事务
18:19:07.093查结算记录
18:19:07.166查询返回
18:19:07.181同步调用 invoice-service 生成票据快照
18:19:08.962RPC 返回,光这一步等了 1.7s
18:19:09.004更新 settlement_record
18:19:09.517提交事务
18:19:09.560响应返回

这条时间线其实已经把结论写得很明白了。

问题不是“数据库里有一条 SQL 为什么这么慢”,而是:为什么事务在 18:19:07.181 就已经开着了,却要等到 18:19:08.962 才继续做后面的更新和提交。

这 1.7 秒里,数据库连接没有释放,事务上下文没有结束,涉及的记录和锁也都悬在半空。只要并发一上来,后面的请求就很容易开始排队。

真正把系统拖住的,是结算事务边界被票据补全逻辑撑坏了

18:15 刚上线过一个“票据补全”改动。

原本的结算确认流程很短:查一次、写一次、提交。上线后变成了:

  1. 开事务
  2. 查结算记录
  3. 同步请求 invoice-service 拉附加税务信息
  4. 把票据快照写入 settlement_record
  5. 提交事务

当晚偏偏又碰上 invoice-service 因为税务字典刷新,RT 从 20ms 涨到了 1.6s 左右。于是这段改动就把原本库外的等待,整个塞进了事务边界里。

所以那次事故里,“长事务”不是一个抽象标签,它指向的是一件非常具体的坏事:

有人拿着数据库连接和事务上下文,在库里等库外服务。

锁等待和连接池紧张,都是后面自然长出来的结果

一旦前面的事务被这样拖长,后面的连锁反应几乎是必然的。

那晚反复出问题的是这条更新:

update settlement_record
set status = ?, invoice_snapshot_id = ?, updated_at = now()
where settlement_id = ?;

它本身并没有慢到离谱。可因为前一批请求都在开着事务等票据服务,settlement_record 上的相关更新和补偿请求就开始往后排。

于是现场才一步步变成:

  • 先是结算确认接口 RT 抬头
  • 再是库里出现几笔 5 到 6 秒的活动事务
  • 然后锁等待开始出现
  • Hikari waiting 从 0 涨到 9
  • 最后用户开始看到结算确认超时和重试

如果你一开始就把注意力放在“哪条 SQL 最慢”,这些结果层症状会看起来很散;但只要先盯住“谁在事务里等外部返回”,整条事故就会一下子顺起来。

所以那晚我没有先刷 EXPLAIN

不是说 EXPLAIN 没用,而是那一刻它不是第一刀。

因为当时现场已经给了更直接的证据:

  • 事务年龄先抬头
  • 票据服务调用和事务时长几乎重合
  • 更新 SQL 的执行耗时,并没有大到足以单独解释 3 秒接口
  • 连接池活跃数贴着上限,说明连接被长期占住

这些信号更像是在说:先别问 SQL 优不优秀,先把事务边界里不该出现的等待拿掉。

真正扭转现场的动作,也不是调 SQL,而是把 RPC 从事务里挪出去

18:23,我们先灰度关闭票据补全逻辑。

18:25,再把这段补全改成事务外查询,主事务里只保留必要的结算状态更新;票据快照改成后置补写。

后面几分钟的变化非常有说服力:

  • 18:24 左右,最先掉下来的是事务时长和最老事务年龄
  • 接着锁等待和 Hikari waiting 开始回落
  • 然后 POST /settlement/confirm 的 p95 从 3 秒级掉回 400ms 左右
  • 最后用户侧的超时和补偿重试量才陆续恢复

这个顺序很重要。

因为它说明我们切中的,不是某条 SQL 的局部执行问题,而是整条事务等待链的起点。

这篇我想留下的,不是“长事务四段拆解法”

我更想把那晚记成一句简单得多的话:

长事务最危险的时候,往往不是你在数据库里看到它已经很长,而是它刚开始把库外等待一起包进事务的时候。

一旦这么做:

  • 锁会被多拿一会儿
  • 连接会被多占一会儿
  • 后面的更新和重试就会开始排队
  • 你最后在监控上看到的,才会是锁等待、连接池紧张和接口整体变慢

所以这篇不想再把读者带去上“长事务先拆四段”的方法课。

那次结算事故真正值得记住的,是更具体的一幕:settlement-service 明明已经开了事务,却在里面等 invoice-service 的 1.7 秒回包。后面的所有坏事,几乎都是从那 1.7 秒里长出来的。

也正因为如此,那晚最正确的第一步不是先查慢 SQL,而是先把那段不该放进事务里的等待拿出去。