转载本文请联系BUG解决公众号。前言最近解决了一个难题。由于调查过程很有趣，所以我以此为基础写了这篇文章。错误站点这是一个偶然的性能问题。每天上百万的交易请求中，平均耗时在300ms左右，但总有100多个交易会超过1s，这让我们99.99线的业务耗时监控非常尴尬。如下图所示：为了不断改进，消除这个尴尬的指标，笔者开始探究这100多个请求笔慢的原因。首先寻找一张支票。由于作者写的框架保留了traceId，所以很容易找到这个请求的整个调用链接。而且每次请求的耗时是通过框架中的拦截器计算在性能日志中的。这样就很方便分析链接是哪里耗时了。性能日志中的一个例子如下图所示：2020-09-0115:06:59.010[abcdefg,A->B,Dubbo-thread-1,ipA->ipB]B.facade,cost10ms拉出一个整个调用链接后，发现先调用C系统的B系统比较慢。下面几个环节还有几个调用比较慢，所以先忽略三千七二十一，先分析系统B对系统C的调用，我们从监控系统可以看出，正常的B系统调用C系统平均只需要20ms，这次耗时增加了10倍！正常思维，C系统当然有问题，毕竟慢了10倍！去C系统看看性能日志，2020-09-0115:06:59.210[abcdefg,B->C,Dubbo-thread-1,ipB->ipC]C.facade,cost20ms打脸，没想到只有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而是少用了看，上下扫了一眼。顿时，好象挨着的几个请求都很慢，慢也没有区别！也就是说，B系统在这个时间点调用任意一个系统，都需要几倍甚至十倍的时间！终于找到突破口了，应该是B系统本身或者环境有问题！于是作者用awk统计了系统B在这个小时内每分钟的平均调用时间，使用了如下命令：catperformancelog|grep'时间点|awk-F'''{print$2,$5}'|......|awk-F'''{sum[$1]+=$3;count[$1]+=1}END{for(iinsum){printi,sum[i]/count[i]}}'发现15:002015:012115:021515:0330......15:06172.415:07252.415:08181.415:102015:102115:1022在15:06-15:08三分钟内，通话时间暴涨！但奇怪的是，B系统有几十台机器，只有这台会在这段时间暴涨。这个时候有定时任务吗？笔者昨天搜索了系统B的日志，发现在同一时间段内，依旧暴涨！然后搜索其他慢调用，比如E->F，发现也是在15:06-15:08报错！于是笔者心生一计，直接用awk计算了白天所有系统间调用慢机的平均耗时（不包括晚上的小流量），发现：所有调用慢机,非常巧合的是在每小时的06-08分钟内慢慢地被调用。再观察慢请求，发现都分布在06-08这个时间段的不同时间！定时任务？第一反应是有定时任务，查看所有调用机器的crontab没有问题。我问有没有安排相应的开发，没有安排，而且由于耗时的原因，每秒的请求数反而变小了。我检查了机器监控，一切正常。思路陷入僵局，突然作者灵光一闪。我们的应用程序都在KVM虚拟机上。会不会是宿主机有问题？于是我联系了SA，看看这些机器的hosts到底是怎么回事。每台慢下来的机器的主机都有Redis！原来慢下来的机器是和Redis合办的！登录对应的Redis服务器，发现此时CPU确实出现了秒杀。.而且这个尖峰对整个主机的CPU没有影响（毕竟主机有64核）。crontab-l，有一个定时任务，脚本名是Backup！它的开始时间是从06分钟开始备份到GlusterFS磁盘，CPU占用率从06分钟=>07分钟开始上升到峰值=>08分钟，下降幅度和耗时曲线一模一样！原来Redis备份到Gluster磁盘占用了大量的IO操作，所以宿主机上的其他应用在做IO操作的时候会变得很慢，这会导致系统对inter的平均耗时调用将激增近10倍，最终导致请求高耗时。为什么调用请求超时1s的概率这么低？因为我们每个应用都有几十台机器在线，基本上每次调用只有几十毫秒。所以，只有当这个请求连续落在三个或更多与Redis合办的系统中时，请求才会超过1s，这样才能被我们的统计脚本监控到，那些大量的正常请求才完全拉平平均值。解决方案我们把对应宿主机上的在线实时链接系统用Redis迁移过来，就没有1s这种尴尬了。综上所述，当遇到问题，思路陷入僵局时，可以使用一些脚本工具，比如grep，awk或者其他工具，分析很多日志，不断寻找规律，从无序中寻找顺序，这样往往会产生意想不到的结果影响！
