背景
最近公司对框架做了一波改造，改造后的应用上线后，在QPS到达一定程度的时候发现会有很多请求超时，从链路上看是我自己的服务造成的超时。但是从监控看我服务的请求量和响应时间都很正常，而从调用方的监控来看，服务一部分请求处于超时状态，于是我开始了两天的debug
Debug
首先请求超时，第一个反应就是是否有线程在阻塞。于是jstack看了一下发现并没有奇怪的等待(由于当时是在机器上看没有备份下来，这里就没有贴出来了)
然后决定dump一下数据，看看里边有没有比较可疑的地方。如下图我们看到所有线程都在等一个空队列，这应该属于正常现象，队列里都没有请求大家肯定在等了。但是这里有个疑点，请求量这么大为什么大家都在等一个空队列呢？请求应该已经进来了，不应该出现队列里没请求的情况。
dump数据
与此同时，我上线了一段新代码，在所有可能的耗时操作的前后都进行了计时打点，试图找到一个请求中最耗时的部分到底是哪。结果让人大跌眼镜，所有的请求耗时都特别短(ms级别)，理论上不可能造成客户端请求3秒超时的。
怀疑人生
到此我有些惊慌失措，毕竟上线ddl就像考试时站在你旁边一直盯着我的监考老师一样给我无限的压力。于是我开始看各种监控，QPS正常，响应时间正常，JVM正常，成功率下跌，【没有可用线程异常】增加，【客户端超时关闭连接异常】增加，CPU正常，网络IO正常，线程数正常，TCP连接数正常，磁盘读写增加。
终于到了下一个发布窗口，我决定召唤出Java排障的必杀利器Arthas。本着做点什么比啥都不做好，就像做物理大题的时候先写 “根据经典力学公式可得” 一样。于是在线上机器悄悄装了个Arthas，直接监控请求时长超过1s的10个请求(正常我的请求都在几毫秒之内)，结果还真的破案了！直接上Arthas破案图(怕被查水表，只截了最重要的部分)
Arthas命令:
trace xxx.xxx.ClassName methodName '#cost > 10' -n 10
最耗时的部分
trace的10个超时请求都是在Log:info()特别耗时！找到凶手对一个侦探来说只是第一步而已，它的作案手法才是作为侦探的目标。
确实，这个答案让我既高兴又费解，我的日志明明是异步打的啊，logback.xml中AsyncAppender写的贼6的不可能出现写日志阻塞请求的情况，而且我悄悄在线上悄悄debug实锤了logback读取的配置文件就是异步的配置文件，甚至还用接口证明了这个日志就是异步写的，这不科学！
回想发布窗口之前我看到的异常现象，和日志有关的磁盘读写增加。磁盘读写增加，增加的量是多少呢？看了一下监控着实令我震惊。图合在一起看不到什么，因为正常的曲线直接看不到了，所以分开贴一下图
正常的磁盘写
超时机器的磁盘写
到这里应该可以猜测一下问题的Root Cause了，日志量太多导致导致日志刷盘时大量占用CPU时间片，使得请求没有足够的时间片写入网络返回，这才使得我的每个计时打点的时间都很短，理论上请求很快就能处理完毕，但是由于没有时间片把数据刷到网卡使得客户端那边迟迟收不到返回。另外即便日志配置是异步的(通过上图也能看到日志每个一个固定的是时间段进行磁盘写)，它通过一个buffer存储日志再定期刷盘，但是实际刷盘依然是占用CPU时间片的。
发觉异常
那么问题来了，为什么之前的代码就没这个问题呢？请求量都一样，日志量应该也一样啊。后来发现，公司对框架做的改造会在其他地方多打几个日志文件，除此之外当程序发生业务异常时只会对最外层异常做处理，改造之后会对内部的每一个异常做处理。也就是说不仅一条日志写了多份文件，日志量也变多了不少。
那没事了
OK，这个案子总算是破了，在我做了一波没用日志精简以后，服务终于回到了往日的平静，一切都这么和谐，唯有头发又少了几根...
后记
Arthas真np(破音)! 建议大家都会使用这个工具 https://arthas.aliyun.com/doc/
网友评论