记一次坑爹的问题排查

我非常喜欢改bug，即使代码不是我写的。coding时就像creator，而debugging时就像detective，根据问题表象、触发条件、程序环境等信息，结合源代码，通过逻辑一步步推理出问题的可能原因，像极了案发现场面对尸体的名侦探，最终解决问题的那一刻（也可能还没解决）也是最爽的（如果几天都解决不了就一点都不爽了）。《全职猎人》中小杰有这么一句话，“了解一个人的最佳方式就是看他/她什么时候会发脾气”。人会无缘无故发脾气，言行举止有时随机性很大，但程序不会，就连生成的随机数也基本都是伪随机，出了问题肯定是有原因的，原因肯定在人身上（虽说之前有研究发现宇宙射线可能会导致计算机底层发生0和1的反转），某种意义上程序也确实比人更容易相处。

问题最初被测试发现是在昨天，她负责对我写的服务进行性能测试。服务主要用于对指定数据库进行探索，本来前台页面响应并渲染基本在秒级，但当表数量达到数千张时，有时（注意是偶现，不是必现）会出现页面响应时间长达数十秒。虽说我们产品是toB不是toC，但这种问题还是很严重的。奇怪的是，我本地环境完全无法复现，在她们测试环境也没法复现（为了保证性能测试数据的准确性，我只能等到她们不用时才上去测几把）。

既然是偶现，测试也没发现任何触发条件，我第一个想到的是jvm的垃圾回收，毕竟是性能测试，内存占用飙高是意料之中的。我开启了gc日志并重启，等了一段时间后却发现gc耗时并没有多久，full gc的频率也比较低。

就在我思考其他可能性时，secureCRT上突然蹦出了一句“ kernel:NMI watchdog: BUG: soft lockup - CPU#1 stuck for 21s! ”。绝逼是因为这个！但谨慎起见我先在本地环境开启监控，接连探索数千数万的表后，内存倒是飙高了，但是cpu稳得一逼，而且我调出测试环境后台日志发现这段时间没人在用服务，也就是说这个系统报错跟我的服务没关系。在测试环境上查到这台服务器除了我的服务外，只有mysql、zookeeper、kafka、h2以及另一个部门的全家桶。于是马上截图发测试甩锅，要么是那个部门的全家桶服务哪里在疯狂霸占cpu资源，触发了linux的看门狗，要么就是你们的服务器质量有问题。

然而因为没有实锤，测试并不信服（其实我自己也没信，因为之后调出服务器的系统日志发现cpu stuck的时间点和测试复现问题时的时间点对不上）。于是我一边支撑其他项目，一边继续优化代码，让她那边再复现时及时叫我，去她工位排查。

没多久就又发生了。在她工位开f12翻来覆去看请求数据，突然，我发现其中一个请求的响应数据中node数量竟然没有受限制，有几千个之多（按理说考虑到用户体验应该限制为最多几百个）。虽说当时满脑子的卧槽，但还是装作面露愁容，说我回去再排查下。坐定后立马开始检查代码，加日志，一遍又一遍测，但还是没法复现。

不过我终究还是把问题的原因跟测试说了，bug单要提就提吧，这次转测来不及改的话之后再排查。结果她跟我说她疑似发现问题的复现规律了，为了排除干扰有时会手动去mysql业务库里把当前数据删掉，然后再测，还说是我教的。 ∑(っ °Д °;)っ卧槽！！！印象中之前我这么说是因为她们通过nmon监控到服务在使用期间对服务器的磁盘io主要是写，几乎没有读，她觉得不正常。但其实那是因为mysql的缓存机制，另外redis也是走缓存，我当时说你们要不试下手动删除一条数据再使用服务看看会不会监控到明显的磁盘读io，但是我可没说这样可以测出正常的性能测试数据啊！实际场景中用户也不可能跑我们业务库来删数据玩啊摔！

我俩在各自环境上按照这种操作走了一遍，都复现了，真相终于大白。骚操作导致业务库和缓存数据出现不一致，导致对node的数量限制失败，前台页面点击时进一步触发算法重新绘制坐标（按照算法大佬的说法，时间复杂度几近立方级，node达到一定数量级后数量越多就慢得越明显，因为他那边暂时没时间优化，我就把算法的node传参做削减处理了），之所以难以发现是因为成千上万个node挤一堆和几百个node挤一堆看上去没啥区别。一是算法耗时，二是前端接收数据量暴增导致的渲染耗时，于是就有了这数十秒的请求响应时间。

最后，虽说算法耗时那么久，但成果是真的好看，好好学算法吧。