一个api的 rt 大涨问题排查

感谢同事[空蒙]投递此稿

mtop是移动接入网关平台,对客户端暴露api,后端接api实际的应用服务,有HSF,也有http的服务端。

之前进行了机房从杭州搬迁到上海,在搬迁的过程中,其中一个api的rt突然大涨,(之前平均的约210ms)

chart_2_

分析具体的原因了,当时正机房搬迁,首先考虑的就是是否此影响,是否发生了跨机房调用的导致,当时把整个杭州的后端服务全部干掉,确认没有跨机房调用,但rt还是没有降低,仍旧很高。

还是要整体性的分析,当前的情况,不存在跨机房的调用,暂仅发现此api存在rt大涨的情况,其他的api都已经实现搬迁,且rt没有存在这种异常的大涨情况。那后续就是重点分析这个api的请求从mtop到后端的每个链路是否存在问题。

此api是http的接入方式,mtop对http的接入服务,采用 vipserver(软负载均衡)分配具体机器+httpasyncclient异步callback调用模式。其他的模块与hsf服务调用是共用的,因此排查的范围缩减,此时查问题神器btrace出场。同事去写脚步监控分析对vipserver以及http调用链路上的耗时情况。

而我则在各种数据报表上分析查看(事实证明,完善的监控报表数据是非常有效的)

mtop有个机器性能的监控报表数据(之前出现过单机问题,但整体数据上无大幅波动。虽然按机器分析报表数据量比较大浪费存储,关键时刻显作用)

排查首先发现,发现上海包间1的速度快于包间2的速度,(一个2s,一个低于1s),那就先找pe把流量全部导到rt稍微好一点的机房,但结果rt也上涨了。

再分析发现此api杭州的调用才约550ms(跨机房调用到上海的服务端,为什么已经完全且流量到上海,可杭州机房还有流量呢?主要是客户端上有dns缓存防拦截技术),可上海的直接机房间调用需要1.4s以上。这非常不符合常规。

首先考虑是用户体验,550ms总比秒级的rt好,因此先把流量导到杭州,完成一半后,rt就降低到900多ms。此时网络那块排查说交换机存在一定错误,正在处理。后续rt又出现波动。

btrace此时分析结果是rt一切正常,同时排查这个api后端应用服务确认没有存在问题,直接在机器上curl 也是快速的。那就先考虑把此api流量全部且回杭州,切换完成后,rt降低到了450ms。这样对用户体验会好很多,但问题还要继续排查。

现在情况:
nginx(上海)===》mtop(上海)===》应用(上海)rt约1.4s
nginx(上海)===》mtop(杭州)===》应用(上海)rt约450ms

竟然绕道杭州比上海机房直接调用快,btrace分析方法的调用时间是正常的,mtop框架是基于servlet3异步+HSFcallback/http callbcak模式的(后端业务如果发生异常,rt耗时大涨,不会对mtop性能产生特别大的影响),因此剩下就要分析http的结果为什么慢了,此刻另一神器tcpdump登场

一抓包分析就发现好几个问题:
1、连接握手时候协商的窗口只有1460,报文都是1个窗口在发送,协商mss是1460,可实际都是834在发送数据

2、api结果数据比较大,发生的报文非常多,因为问题1,每次都只能一个报文发送应答后才接着发生,如果数据有40k,那差不多要传输50次,要50个RTT。
截取部分数据

3、上海机房的请求中经常看到超时重传,一超时重传最小+200ms(RTO虽然会由RTT计算确定,但当前内核限制了最小RTO是200ms,个人感觉在tcp协议设计是为防止网络拥塞,但内网环境完全可以减少这个值,由RTT计算,毕竟相对内网丢包概率低,rtt非常小)

问题1浪费了带宽,同时引起问题2狂发生报文,问题3会增加rt,但问题2又加剧了一个请求在问题3出现超时重传的概率。因此很多请求从发起到结束耗时超过1s,同时发现杭州机房也有问题1和2,但丢包比较少,因此rt情况比上海的好很多。而且上海到杭州多月5ms时延,问题2多次rtt发送,50次约导致250ms浪费,看上去和之前210ms的rt比较接近。

可为什么机器上直接curl速度正常,可程序调用就出现了上述报文的情况呢?分析tcp的参数,没有什么特别情况,那很大可能是应用上的问题,再看httpasyncclient的配置

screenshot
httpasyncclient在初始化时候,有对socket的SOSNDBUF和SORCVBUF设置,我们设置是1024,是否此值有关联呢?那就进行测试,把此值去掉取默认

果然协商的窗口变为5840,再换个机器,又成14600了。原来是不同版本的内核,对接收窗口的算法有些不同,具体大家有兴趣,可以查看对应版本内核的源码

linux3内核的窗口算法
screenshot

初始的接收窗口的取值(mss的整数倍):
(1)先考虑路由缓存中的RTAXINITRWND
(2)在考虑系统默认的TCP
DEFAULTINITRCVWND(10)
(3)最后考虑min(3/4 * skrcvbuf, windowclamp),如果这个值很低

测试有效了,马上就进行发布,mtop发布完成后,rt就降低到200ms,经过杭州绕一圈还比之前快了一点,再把流量全部切回上海,最终api的rt降低到约160ms。相比之前210ms,有50ms的rt降低。

同时因为这个参数小,如果revbuf满了,应用没有去取,那再有包过来,会直接丢弃,这样引起问题3加剧,更加导致rt增长。

至于网络上,为什么同样情况下上海机房http调用出现超时重传反而比杭州还多,网络的人正进一步分析排查

主要http接入的api不多,而且此api的数据比较大,进一步导致这问题,在处理完毕后其他http服务端的api也会带来rt的降低

唠叨那么,详细的介绍了整个问题的处理过程,rt也如第一张图曲线波动,回过头去分析总结这次排查的过程,主要一点点感受
1、排查问题的时候,一定要整体性的去思考,再每个节点的去分析。
2、对内核参数,要去深入的理解测试,对tcp参数的调整,要对不同版本内核对应测试分析效果

感谢同事们的全力支持和答疑 @陶辉 @毕玄 @炳天 @仲升 @洪志 @佑明等

参考资料:
http://blog.csdn.net/zhangskd/article/details/8588202
http://blog.csdn.net/zhangskd/article/details/8200048
http://blog.csdn.net/russell_tao/article/details/18711023
http://www.orczhou.com/index.php/2011/10/tcpip-protocol-start-rto/
http://www.ibm.com/developerworks/cn/linux/l-hisock.html

原创文章,转载请注明: 转载自并发编程网 – ifeve.com本文链接地址: 一个api的 rt 大涨问题排查

  • Trackback 关闭
  • 评论 (3)
  1. 能在线挂btrace,真是一种幸福。

  2. 看下来就是上海的机房的tcp滑动窗口太小了,buffer一满就发,结果导致tcp传输太频繁了,丢包重传,报文浪费严重?滑动窗口调大后就好了?

    工作中似乎也碰到过一次这样的情况,主要是语音处理缓冲区太小,结果性能太差。

    • 码农
    • 2014/09/01 11:01上午

    不会吧 我竟然看到btrace 正式环境阿里竟然让你用这个? 看来问题很严重 也看得出你们太幸福了 动态日志记录就不行么亲?随用随开的策略不更好?

return top