一次数据库IO阻塞导致的线上事故

一。前言

这两天线上遇到一个错误警告，某个服务的一个接口持续报错，最后排查出来是一段sql的执行导致的，下面记录下具体原因和排查过程。

二。事发

这是生产日志预警，当收到这条消息，我就知道中午的干饭计划算是泡汤了

运维同学根据监控平台的数据已经定位了出问题的服务并第一时间重启，然而并没有起作用报错还在持续！！

我开始介入然后运维同学甩我两张图，一个接口一直再报错：

skywalking监控记录：

先介绍下业务服务business-service也就是报错的服务，这个服务是一个绩效考核系统，可以制定考核方案，方案中有很多节点，每个员工都会经过相应的考核分支节点，通过考核指标的打分，得分校准，绩效得分生成最后产出每个员工的绩效得分。问题就出在员工开启考核节点的接口。

根据错误日志说明数据库连接被关闭，第一时间想到了以下情况：

1.代码中可能出现了异常

2.网络问题导致连接超时中断

3.多个线程或事务竞争导致数据库连接资源被耗尽，导致部分线程超时而中断

到底是什么导致的呢？根据和运维同学的快速沟通排除网络问题就算是网络波动也不会持续报错，我们这种业务系统一般是不会出现高并发的，所以最后还是觉得是代码原因，但是这个接口和相关的功能几个迭代没更新过，而且之前也没出现过类似的问题，查看git提交记录也确实没有修改过这块逻辑。

这里补充一点，节点开启并不是同步的，因为考虑到需要支持上千员工，某些客户会存在上万员工的考核，我们把每个员工的节点开启作为一个事件消息推送到一个公共服务task-service，这个服务是基于MQ和消息表，来完成节点的开启任务，补偿重试，回调业务接口等。基于mq会平稳处理业务并且数据库连接池也做了限制，所以也不会是因为同一时间大量员工并发开启节点导致。

正当翻代码定位问题时，预警提示警报已经解除。什么都不干就好了？因为还有其他重要的事要做，就暂时提了个issues等待有空继续排查。

三。梅开二度

第二天上班屁股还没坐热，又收到了同样的警报，同样的问题。

有了昨天的经验，今天特意看了下grafana,kafka的监控，看下消息的情况：

可以从监控看到节点启动的队列消费出现了问题，从而导致消息有一定的积压，当然这只是表象，根源还是要找到什么问题导致数据库连接出了问题，还是要继续跟踪日志，这次有新发现：

四。破案

看到这错误日志，基本可以破案了，就是这个异常的超大sql导致数据库无法接收，并且阻塞了IO，进而拖慢了数据库，使数据库性能严重下滑，继而出现数据库连接关闭的情况。后面能自行恢复是因为开启任务已经消费完，错误代码不再执行，系统慢慢恢复了。

上面的sql其实就是根据节点id查询所有节点信息，那为啥会有这么多的id呢？经过跟踪代码发现有一个递归查询开启节点所有父节点的方法出现问题，导致计算出了重复的父节点，使用节点id的时候还没有去重，这个bug隐藏的很深，只有在父节点比较多并且是多路多级父节点才会容易出现。

期间有客户反馈系统怎么变慢了？我知道原因但是我不会说，我只能偷偷的上个hotfix，深藏功与名。

其实第一天出现这个问题也出现了这个日志：

第一次出问题，运维同学已经看到了这个错误，但是没和我说啊，我介入的时候已经有点晚了，当时数据库资源已经被耗的差不多了，才会出现很多连接关闭的错误。从而忽略了导致关闭的正真原因，这里也是大意了没有找更早的日志，走了弯路。

总结：

出现生产问题当然是非常糟糕的，要保证服务平稳运行，除了编码工作之外，全面的测试，完善的监控体系都至关重要