记一次线上请求偶尔变慢的排查

前言

最近解决了个比较棘手的问题，由于排查过程挺有意思，于是就以此为素材写出了本篇文章。

Bug现场

这是一个偶发的性能问题。在每天几百万比交易请求中，平均耗时大约为300ms，但总有那么100多笔会超过1s，让我们业务耗时监控的99.99线变得很尴尬。如下图所示:

为了精益求精,更为了消除这个尴尬的指标，笔者开始探寻起这100多慢请求笔的原因。

先找一笔看看

由于笔者写的框架预留了traceId,所以找到这笔请求的整个调用的链路还是非常简单的。而且通过框架中的拦截器在性能日志中算出了每一笔请求的耗时。这样，非常便于分析链路到底是在哪边耗时了。性能日志中的某个例子如下图所示:

2020-09-01 15:06:59.010 [abcdefg,A->B,Dubbo-thread-1,ipA->ipB] B.facade,cost 10 ms

拉出来一整条调用链路后，发现最前面的B系统调用C系统就比较慢。后面链路还有几个调用慢的，那先不管三七二十一，先分析B调用C系统吧。

我们从监控系统看出来正常的B系统调用C系统平均耗时只有20ms,这次的耗时增长了10倍！

正常思路，那当然是C系统有问题么，毕竟慢了10倍！去C系统的性能日志里面看看,

2020-09-01 15:06:59.210 [abcdefg,B->C,Dubbo-thread-1,ipB->ipC] C.facade,cost 20 ms

啪啪啪打脸，竟然只有20ms,和平均耗时差不多。难道问题在网络上?B到C之间由于丢包重传所以到了200ms?

甩给网络？

由于笔者对TCP协议还是比较了解的，tcp第一次丢包重传是200ms，那么加上C处理的时间20ms,即220ms必须得大于200ms。而由于Nagle和DelayAck造成的tcp延迟也仅仅是40ms,两者相加60ms远远小于200ms,所以这个200ms是丢包或者DelayAck的概率不大。

本着万一呢的态度,毕竟下绝对的判断往往会被打脸，看了下我们的监控系统，发现当时流量距离网卡容量只有1/10左右，距离打满网卡还有非常远的距离。

注意，这个监控的是由KVM虚拟机虚拟出来的网卡。看了这个流量，笔者感觉网络上问题的概率不大。

GC了？

笔者第二个想到的是GC了，但是观察了B和C的当时时刻的GC日志，非常正常，没有FullGC，youngGC也在毫秒级，完全不会有200ms这么长。TCP重传+双方都youngGC?这个也太巧了点吧，也不是不可用。不过详细的计算了时间点，并纳入了双方机器的时钟误差后，发现基本不可能。

再看看其它几笔

尽然这个问题每天有100多笔(当然了，也不排除其中混杂了其它不同的问题),那么就试试看看其它几笔，有没有什么共性。这一看，发现个奇怪的现象，就是有时候是A调用B慢，有时候是B调用C慢，还有时候是E调用F慢。他们唯一的共性就是耗时变长了，但是这个耗时增加的比例有5倍的，有10倍的，完全没有规律可循。

这不禁让笔者陷入了沉思。

寻找突破点

既然通用规律只有变慢，暂时无法进一步挖掘。那么还是去B系统上去看看情况吧，去对应B系统上故意不用grep而是用less看了下，上下扫了两眼。突然发现，貌似紧邻着的几条请求都很慢，而且是无差别变慢！也就是说B系统调用任何系统在这个时间点都有好几倍甚至十几倍的耗时！

终于找到了一个突破点，B系统本身或者其所属的环境应该有问题！于是笔者用awk统计了下 B系统这个小时内每分钟的平均调用时长，用了下面这条命令:

cat 性能日志 | grep '时间点 | awk -F ' ' '{print $2, $5}' |.......| awk -F ' ' '{sum[$1]+=$3;count[$1]+=1}END{for(i in sum) {print i,sum[i]/count[i]}}'

发现

15:00 20
15:01 21
15:02 15
15:03 30
.......
15:06 172.4
15:07 252.4
15:08 181.4
15:10 20
15:10 21
15:10 22

在15:06-15:08这三分钟之内，调用时间会暴涨！但奇怪的是B系统明明有几十台机器，只有这一台在这个时间段内会暴涨。难道这个时间有定时任务？笔者搜索了下B系统昨天的日志，发现在同样的时间段内，还是暴涨了！再接着搜索其它调用慢的，例如E->F,发现他们也在15:06-15:08报错！于是笔者，一横心，直接用awk算出了所有系统间调用慢机器白天内的所有分钟平均耗时(晚上的流量小不计入内),发现:

所有调用慢的机器，都非常巧的在每个小时06-08分钟之内调用慢。再观察下慢的请求，发现他们也全部是分布在不同小时的06-08分时间段内！

定时任务?

第一反应是有定时任务，查了下所有调用机器的crontab没有问题。问了下对应的开发有没有调度，没有调度，而且那个时间段由于耗时的原因，每秒请求数反而变小了。翻了下机器监控，也都挺正常。思维陷入了僵局，突然笔者灵光一闪，我们的应用全部是在KVM虚拟机上，会不会是宿主机出了问题。于是联系了下SA,看看这些机器的宿主机是个什么情况。

每个变慢的机器的宿主机都有Redis!

这一看就发现规律了，原来变慢的机器上都和Redis共宿主机！

登陆上对应的Redis服务器，发现CPU果然在那个时间点有尖峰。而这点尖峰对整个宿主机的CPU毫无影响(毕竟宿主机有64个核)。crontab -l 一下，果然有定时任务，脚本名为Backup!它起始时间点就是从06分开始往GlusterFS盘进行备份，从06分开始CPU使用率开始上升=>07分达到顶峰=>08分降下来，和耗时曲线完全一致！