处理网络超时问题的最佳实践

对于云上的用户来讲,业务日志里面报超时问题处理起来每每比价棘手,由于1) 问题点可能在云基础设施层,也有可能在业务软件层,须要排查的范围很是广;2) 这类问题每每是不可复现问题,抓到现场比较难。在本文里就分析下如何来分辨和排查这类问题的根本缘由。html

业务超时 != 网络丢包

因为业务的形态不一样,软件实现语言和框架的不一样,业务日志中打印出的信息多是各不相同,好比以下关键字:java

"SocketTimeOut", "Read timed out", "Request timeout" 等linux

从形式看都属于网络超时这一类,可是须要明确一个概念:这类问题是发生的缘由是请求超过了设定的timeout时间,这个设置有可能来自客户端,服务器端或者网络中间节点,这是直接缘由。网络丢包可能会致使超时,可是并非充分条件。总结业务超时和网络丢包的关系以下:git

网络丢包可能形成业务超时,可是业务超时的缘由不必定是丢包。github

明确了这个因果关系后,咱们再来看怎么分析业务超时。若是武断地将业务超时等同于网络抖动丢包,那这个排查分析过程就彻底错过了业务软件层自己的缘由,很容易进入困局。redis

本文会从云基础设施层和业务软件层对业务超时作分析,整体来说基础设置层面的丢包缘由相对容易排查,阿里云有完善的底层监控,根据业务日志报错的对应时间段,从监控数据中能够肯定是否有基础设施网络问题。而业务层的超时一般是软件层面的设置,和软件实现及业务形态都有关系,这种每每是更加难以排查的。算法

网络丢包为何致使业务超时

网络抖动可能形成业务超时,其主要缘由是网络抖动会带来不一样程度的延迟。本文以互联网大部分应用以来的TCP为对象来介绍,一个丢包对数据传输的完整性实际上是没有影响的,由于TCP协议自己已经有精密的设计来处理丢包,乱序等异常状况。而且全部重传的处理都在内核TCP协议栈中完成,操做系统用户空间的进程对这个处理其实是不感知的。丢包惟一的反作用的就是会增长延迟,若是这段延迟的时间足够长,达到了应用进程设置的某个Timeout时间,那么在业务应用侧表现出来的就是业务超时。数据库

丢包出现时会不会发生超时,取决于应用进程的Timeout设置。好比数据传输中的只丢了一个TCP数据包,引起200 ms后的超时重传:服务器

  • 若是应用设置的Timeout为100 ms,TCP协议栈没有机会重传,应用就认为超时并关闭链接;
  • 若是应用设置的Timeout为500 ms,则TCP协议栈会完成重传,这个处理过程对应用进程透明。应用惟一的感知就是处理此次报文交互比基线处理时长多了200 ms,对于时间敏感度不是很是高的应用来讲这个影响很是小。

延迟到底有多大?

在设置应用进程Timeout时间时有没有能够参考的定量值呢?虽然TCP中的RTT/RTO都是动态变化的,但TCP丢包的产生的影响能够作必定的定量总结。网络

对丢包产生的延迟主要有以下两类:

  • TCP建连超时。若是网络抖动不幸丢掉了TCP的第一个建连SYN报文,对与不太老的内核版原本说,客户端会在1秒(Draft RFC 2988bis-02中定义)后重传SYN报文再次发起建连。1秒对于内网环境来讲很是大,对于阿里云一个区域的机房来讲,正常的RTT都是小个位数毫秒级别,1秒内若是没有丢包足够完成百个数据报的交互。
  • TCP中间数据包丢包。TCP协议处理中间的数据丢包有快速重传和超时重传两种机制。快速重传一般比较快,和RTT相关,没有定量的值。超时重传 (RTO, Retrasmission Timeout) 也和RTT相关,可是Linux中定义的RTO的最小值为,TCP_RTO_MIN = 200ms。因此在RTT比较小的网络环境下,即便RTT小于1ms,TCP超时重传的RTO最小值也只能是200ms。这类丢包带来的延迟相对小。

除了丢包,另一类比较常见的延迟是TCP Delayed ACK带来的延迟。这个和协议设计相关,和丢包其实没有关系,在这里一并总结如延迟定量部分。在交互式数据流+Nagle算法的场景下比较容易触发。Linux中定义的Delayed ACK的最小值TCP_DELACK_MIN是40 ms。

因此总结下来有以下几个定量时间能够供参考:

  • 40 ms, 在交互数据流中TCP Delayed ACK + Nagle算法开启的场景,最小delay值。
  • 200 ms,在RTT比较小的正常网络环境中,TCP数据包丢包,超时重传的最小值。
  • 1 s,较新内核版本TCP创建的第一个SYN包丢包时的重传时间,RFC2988bis中定义的initial RTO value TCP_TIMEOUT_INIT
  • 3 s, 较老内核版本TCP创建的第一个SYN包丢包时的重传时间,RFC 1122中定义的initial RTO value TCP_TIMEOUT_INIT

云基础设施网络丢包

基础设施网络丢包的缘由可能有多种,主要总结以下3类:

云基础设施网络抖动

网络链路,物理网络设备,ECS/RDS等所在的宿主机虚拟化网络都有可能出现软硬件问题。云基础设施已经作了完备的冗余,来保证出现问题时能快速隔离,切换和恢复。

现象: 由于有网络冗余设备并能够快速恢复,这类问题一般表现为某单一时间点网络抖动,一般为秒级。抖动的具体现象是在那个时段新建链接失败,已创建的链接中断,在业务上可能表现为超时。
影响面: 网络设备下一般挂不少主机,一般影响面比较大,好比同时影响多个ECS到RDS的链接。

云产品的限速丢包

不少网络云产品在售卖的时候有规格和带宽选项,好比ECS, SLB, NAT网关等。当云产品的流量或者链接数超过规格或者带宽限制时,也会出现丢包。这种丢包并不是云厂商的故障,而是实际业务流量规模和选择云产品规格时的误差所带来。这种问题一般从云产品提供的监控中就能分辨出来。

现象: 当流量或者链接数超过规格时,出现流量或者链接丢弃。问题可能间断并持续地出现,网络流量高峰期出现的几率更大。
影响面: 一般只影响单一实例。但对于NAT网关作SNAT的场景,可能影响SNAT后的多个实例。

运营商网络问题

在走公网的场景中,客户端和服务器之间的报文交互每每要通过多个AS (autonomous system)。若运营商中间链路出现问题每每会致使端到端丢包。

现象: 用双向mtr能够看到在链路中间某跳开始丢包。
影响面: 影响面可能较大,可能影响通过某AS链路的报文交互。可是对于单用户来讲看到的影响一般只是对特定实例。

应用设置的Timeout引起的超时

上面分析了几种基础设施由于异常或限速等缘由丢包致使应用超时的状况,整体来讲只要能找出丢包点,就基本能找出根因。但有些状况下,各类网络监控代表并无任何丢包迹象,这个时候就要从应用侧面来继续排查下了。由于应用的形态多样,下面以两个典型例子来讲明为何在没有网络丢包的状况下也会出现业务日志中的超时。

ECS云主机访问第三方API超时的例子

问题现象

用户云上ECS服务器须要经过HTTP协议访问第三方服务器的API,可是发现业务日志中时不时出现访问第三方API时的"Request timeout"报错,须要查出根因。

排查思路

  1. 根据基本思路,先从监控中查看ECS实例及链路有没有丢包。结果发现并无能和业务日志中出现timeout报错时间点吻合的丢包。
  2. 在这种状况下,只能进一步利用问题复现时的抓包来一探究竟了。

抓包分析

拿到抓包后,能够经过Wireshark的“分析-专家信息”或者以下表达式来过滤是否有重传。

tcp.analysis.retransmission

结果确实没有看到任何一个丢包,这个也反证了该问题并不是由丢包引发。若是不是丢包引发,那为何会产生问题呢?这时候须要进一步来分析抓包。

咱们能够注意到:在业务日志里其实有"Request Timeout"这样的关键字,从字面理解就是往外的HTTP请求超时。用HTTP协议的话来讲,能够翻译成:“HTTP请求已经发给对端,可是在一段时间内对端并无返回完整的响应”。沿着这个思路,咱们能够看下报文里是否存在只有HTTP请求而没有HTTP响应的状况。在Wireshark里,能够用以下方法过滤没有HTTP响应的HTTP请求:

http.request.method == GET && !http.response_in

果真,咱们发现了一些这样的HTTP请求。选择其中的一个HTTP请求,而后跟一下TCP stream看下报文交互的全过程以下:

根据抓包会有以下一些发现:

  • TCP stream中能够看到一个TCP链接上有2个HTTP请求,因此ECS访问第三方API是用的长链接。
  • 第一次HTTP GET请求(735号包),在65 ms后返回(778号包)。
  • 第二次HTTP GET请求(780号包)没有对应的HTTP响应返回 (咱们正是经过这个条件过滤的报文)。
  • 第954号包,客户端没等收到HTTP响应就主动FIN掉了TCP链接。这是个很异常的行为,而且是客户端发起的。仔细观察FIN和第二个HTTP GET请求发出的时间间隔,发现大约300 ms。接着查看其余没有响应的HTTP stream,这个时间间隔大约300 ms。

至此咱们有理由推断是ECS服务器在对第三方API发出HTTP请求300 ms后主动FIN掉了TCP链接。这多是程序中客户端设置的超时时间,业务程序超时后可能有本身的重试逻辑。

用户最后确认了业务软件中有该超时设置。

问题总结

1) 那这个300 ms的超时时间设置是否合理呢?
从抓包中能够看出,ECS对端API服务器的RTT大约7 ms左右,推断是一个同城的访问。对于个位数毫秒级别的RTT,300 ms的超时时间其实已经有必定余量了,而且甚至可能能够容许一次超时重传(200 ms)。

2) 问题的根因?
该问题主要是因为对端API服务器处理请求的速度不稳定形成。有些请求在几十毫秒内就处理返回完,有些300 ms都没有处理完。这个不稳定可能和API服务器的资源水位和压力相关,可是这个是黑盒,须要对端分析了。

3) 解决方案
1> 最佳解决方案是联系对端API服务器的owner找到根因并根除。
2> 临时解决方案是调整增大ECS上设置的客户端超时时间。

ECS内网访问自建Redis超时的例子

ECS访问云服务RDS/Cache或者自建数据库/Cache超时是另一类问题,下面用一个ECS内网访问字节Redis超时来讲明这类问题。

问题现象

ECS上用Redis客户端Jedis访问自建在ECS上的Redis服务器,偶尔会出现以下报错:

redis.clients.jedis.exceptions.JedisConnectionException: java.Net.SocketTimeoutException: Read timed out

排查思路

  1. 这类问题很常见的缘由是Redis慢查询,用户自查了Redis的大key和慢查询状况,没有发现时间特别长的查询。因此须要在网络层面进一步确认。
  2. 根据基本思路,先从监控中查看ECS实例及链路有没有丢包。结果发现并无能和"Read timed out"报错时间点吻合的丢包。
  3. 进一步利用问题复现时的抓包来一探究竟了。由于问题偶发,须要在客户端利用tcpdump -C -W参数部署循环抓包,问题出现后中止循环抓包来查看。

抓包分析

拿到抓包后,一样先看有没有丢包重传,结果是没有发现丢包重传。和上一个例子不一样,这个例子没有办法经过必定特征来过滤数据包。因此只能根据Jedis日志报错的时间点找到对应包的位置来进一步看有没有什么线索。

根据Jedis日志报错的时间点找到对应的报文,跟TCP stream看下报文交互的全过程以下(Jedis客户端是9.20,Redis服务器端是20.66):

根据抓包有以下一些发现:

  • 能够看到中间没有重传,网络上看起来是正常的。
  • 客户端利用长链接访问服务器端,在结束链接以前已经包了很是多的Redis请求和响应。
  • 181073 号包是服务器端FIN掉了链接,181078号包客户端接着发了TCP Reset。

上面这些信息量显然是不够说明为何有"Read timed out"的报错。最后一个从客户端发起的TCP Reset可能会是干扰项,能够看到这个TCP Reset是在收到服务器端的FIN而发出的。对于正常TCP四次回收结束链接的过程,客户端在收到服务器的FIN后应该也发送个FIN给服务器结束链接。可是TCP有个Linger选项,能够控制这个行为,设置了Linger选项后可让客户端直接回Reset,这样可让双方快速关闭这组socket, 避免主动关闭放进入长达60秒的TIME_WAIT状态。看起来是客户端的Linger设置形成的,搜了下Jedis代码,在Connection.java (以下)里果真有这个设置,这样就能结束为何客户端Reset掉TCP链接,这个行为是符合逻辑的。

socket = new Socket();
socket.setReuseAddress(true);
socket.setKeepAlive(true); // Will monitor the TCP connection is valid
socket.setTcpNoDelay(true); // Socket buffer Whether closed, to ensure timely delivery of data
socket.setSoLinger(true, 0); // Control calls close () method, the underlying socket is closed immediately

接着来看报文交互中的Redis命令是否正常。跟踪TCP stream能够看到ASCII形式的数据,以下:

能够看到客户端发了DEL命令后,又发了QUIT命令,能够对照报文看下。

  1. 客户端在181061号包发出了DEL命令。
  2. 在3.9 ms后收到了Redis服务器的ACK,注意这只是个ACK包,报文长度是0,说明没带任何payload数据。
  3. 第181070号包,客户端又发出了QUIT命令,注意这个包和DEL命令的包相差间隔时间大概200 ms。Quit命令用于关闭与当前客户端与Redis服务器的链接,一旦全部等待中的回复(若是有的话)顺利写入到客户端,链接就会被关闭。
  4. 第181072号包,也就是在QUIT命令发出161 ms后,Redis服务器端回复了":1"和"+OK"。其中":1"响应DEL命令,"+OK"响应QUIT命令。
  5. 第181073号包,Redis用FIN报文结束了这个TCP长链接。

如上所述,这个链接被中断的关键点是客户端给Redis服务器发送了QUIT命令,至于为何要发QUIT,而且是以前命令发出后200 ms没返回时发送QUIT,颇有多是有超时设置。查看另外几个TCP stream, 基本上都是以相似的模式结束了TCP长链接,基本上能够下这个结论了。

这个案例和第一个案例很相似,不一样之点是在抓包里咱们没法看到在超时时间事后客户端直接FIN掉链接,而是发了Redis QUIT命令,最终等到前面的命令执行完后才关闭链接。相比较第一种,这是一种更优雅的方法,前提是由于Redis存在QUIT命令,而且Jedis内化了这个操做。这个案例更清晰地说明了具体业务对链接行为的影响,须要利用报文来反推Redis客户端和服务器交互的行为。

总结

本文介绍了业务日志里面报超时问题处理起来须要考虑的两个层面:云基础设施层和业务软件层。有至关一部分的问题可能因为基础设施的网络丢包引发,经过网络监控和网络产品的云监控定位丢包点很重要,注意不要把业务超时等同于丢包;另外一类业务软件层Timeout设置致使的超时,发生比例相对少,但须要更普遍的排查,而且不要轻易忽略了这类缘由致使的超时。


原文连接 本文为云栖社区原创内容,未经容许不得转载。

相关文章
相关标签/搜索