【项目排坑记】根据主键update耗时却要10s的排查历程

本文已参与「掘力星计划」，赢取创作大礼包，挑战创作激励金。

---

一、前言

大家好，我是你的朋友浪漫先生。

二、问题描述

    2022年7月2x日，窗外夕阳将落不落，余晖洒落在街道上，远处的热浪仿佛在说：嘿，欢迎来到烤箱中的瑞士卷—成都！

    “嘿！”，我回过神来看到一只洁白纤细的手落在我的肩膀上，眼光从窗外收回顺着手臂快速扭跟过去，然后看到脸色暗淡夹杂着些许痘痘的测试妹纸一脸的严肃！“昨天晚上上线后，这个后台执行更新信息非常缓慢，这里肯定有问题！”

三、问题分析

    “好的，我排查一下”。三步并作两步回到工位，掀开MacBook Pro的盖子、打开显示器的电源、输入链路日志跟踪系统地址、复制traceId、查看日志…… 这一套操作熟悉得令人心疼。

    排查日志初步发现实际调用了两次，第一次执行时间接近10s，调用超时，第二次执行时间接近5s。你肯定也想到了，RPC调用retry设置了值。对RPC配置检查之后确实设置的是retry=1，实际项目中，增、删、改等操作不应设置retry。

通过调用链排查发现update执行非常耗时。聪明的你一定也第一时间怀疑update语句有性能问题。把update语句拿出来：

update table set a=#{1},b=#{2},... where id =#{0} (id主键)

    这下傻眼了，根据主键id更新怎么可能要执行10s？

    masaga？！！

    为了验证我的猜想，command + 空格、键入idea并回车、打开对应的工程、定位到对应的方法处、迅速浏览一遍并思索片刻之后，真相大白！

    服务B执行完update语句之后，事务commit之前，还有两个异步通知任务，使用的是spring的@Async注解，自定义的线程池，跟踪日志中的线程标志，排查过程中发现有的异步任务居然由原线程执行！进一步分析日志发现这种现象并不是一直发生，有时又是由异步线程执行。开始排查线程池，线程池果然设置了callRunner的失败策略。

    所以，由原线程执行时，事务的范围如下：

    定位到原因之后，修改线程池参数为常见策略，初始和最大线程数相同，队列数9999，保证线程池的线程充足性。

    修复

    灰度

    招呼测试妹纸测试

    自信满满，悠闲喝水

四、梅开二度

    “在高并发场景下，复现了这个问题，你快看一下”！测试妹纸对我投来鄙视的眼光犀利的说道：“修复好了，再喊我回归哈，拜拜～”。

    奇怪，为什么这么平常的一个update语句，怎么会执行这么长时间呢？难道出发了框架的bug导致事务提交延迟？不对不对，这个方向想偏了～也没有其他地方在更新这个表了呀？不可能有表锁，更不可能有行锁呀……

masaga？！！

    根据表锁以及行锁的思路，为了验证我的内心OS猜想，立即使用 show processlist 进行了连接查询，果然有重大发现，除了服务B有连接之外，还有服务A的连接。而服务A又是服务B的上游系统！系统架构如下：

    执行顺序如下：

顺序	服务	执行动作	关键点
1	服务A	执行update语句	数据库 行锁 lock
2	服务A	调用服务B	RPC 调用
3	服务B	执行update语句	数据库 行锁 waiting
4	服务A	调用服务B超时	RPC timeout
5	服务A	再次调用服务B	RPC retry
6	服务A	调用调用服务B再次超时	RPC timeout
7	服务A	PRC调用超时异常	数据库 事务回滚 行锁 unlock
8	服务B	执行	数据库 行锁 竞争

    不被人信任的滋味很难受！为了重新赢回测试妹纸对我的信任，这次的bug修复只需成功不许失败！

五、解决方案

    知道病根之后，问题就很简单了。

    最理想的方案     对微服务架构进行重构，但这样做带来的收益不高，现在手上还有优先级更高的事情要做。

    最实际的方案     是将服务A对服务B的调用和服务A的事务分离出来。这样就不存在锁竞争的问题了。

六、总结

    看到了这里，你心里是不是已经在想：我靠，大厂的系统架构真的很垃圾，我都是关着灯的～（走错片场～）

    其实这个系统变成这样是有历史原因的，如果当初的开发者能够采用DDD的思想或者能够明白微服务的对象高内聚思想，或许今天就不会发生在我身上这场研发与测试之间的信任危机。

    夕阳落下，夜晚笼罩着大地。路旁的小猫咪悠然站了起来，张大嘴巴打个哈欠的同时伸了个懒腰，然后走向3号门口，等待着心地善良的加班儿投食猫粮。“验证通过，早点下班”。不远处传来测试妹纸的声音，夹杂着中央空调吹出的风声。

---