系统间歇性超时问题的分析与解决

【系统症状】

后台系统A平均访问量约13K/min，峰值约30K/min。系统超时时间设置为500ms。系统每隔10分钟左右，会出现几十个请求包的超时。但该超时只持续1~2分钟又会自动恢复，百思不得其解。B系统访问A系统的超时视图如下所示：

【寻医问药】

请教了身边的几个同事，分析可能原因如下：

1、机器跨IDC访问，网络抖动造成。

2、依赖的外部接口多，外部接口本身访问比较慢。

3、使用strace调试进程发现，系统调用write占了约20%开销，因为怀疑打本地日志造成IO瓶颈问题。

【寻找病因】

机器跨IDC访问，网络抖动造成？

分析：假设这个原因成立，则把A系统部署到B系统同一个机房，则不会出现超时。通过实验，把A系统部署到与B系统同一个机房，问题依然重现，因此问题并非网络抖动造成，否定这个猜想。

依赖的外部接口多，外部接口本身访问比较慢？

分析：将外部的访问时间在日志中进行打印出来进行分析。采集了一段时间数据，查询接口返回的时间相对较短，因此，也否定了这个猜想。

打本地日志造成IO瓶颈问题？

分析：将本地日志改成网络日志，观察近一个小时。结果符合预期，几乎没有超时问题。因此，可以大致断定是打本地日志造成了B系统的超时问题。哈哈，终于找到原因了。超时情况如下图所示：



可是，为什么是间歇性抽风？因为访问量是相对平滑，如果是因为IO，那为什么不是均匀性超时？

【深入分析】

深入阅读了日志模块代码CLog类的实现，有一个惊喜的发现。当本地日志文件数到达最大值的时候，CLog类会将最旧的文件进行删除，使用的是rename系统调用。每次文件大小到达最大值的时候，系统必须要删除最旧的一个文件才能继续运行。因此，进程在删除文件的时候，必定陷入了同步等待过程，这时候便导致超时的出现。因此，当写满一个文件的时候，也就是系统抽风来临的时候。统计了一个数据，因为日志量很大，约10分钟左右写满一个日志文件，与超时间隔相符。

证明：将本地日志全部删除，在日志文件未到达最大值的时候，观察B系统超时情况，没有超时，与预期相符。

解决方案：1、将本地日志改成网络日志。这样是最直接的解决办法。2、若一定要打本地日志，不要等到服务进程去删除文件，使用脚本监控进行删除本地日志。

【小结】

当确定是本地日志导致超时的情况下，只是模糊的看到了真相。其实我们并没有触及真相，无法解释为何是间歇性超时？因此我继续往前走，找到了真正的原因。在解决问题、请教同事的过程中学到了不少。若发现分析有误或有补充的地方，欢迎与我联系。