网络延迟或数据提交超时(处理网络超时问题的最佳实践)

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

业务超时 != 网络丢包

由于业务的形态不同,软件实现语言和框架的不同,业务日志中打印出的信息可能是各不相同,比如如下关键字:

"socketTimeOut", "Read timed out", "Request timeout" 等

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

网络丢包可能造成业务超时,但是业务超时的原因不一定是丢包。

明确了这个因果关系后,我们再来看怎么分析业务超时。如果武断地将业务超时等同于网络抖动丢包,那这个排查分析过程就完全错过了业务软件层本身的原因,很容易进入困局。

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

  • 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):

网络延迟或数据提交超时(处理网络超时问题的最佳实践)(1)

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

  • 可以看到中间没有重传,网络上看起来是正常的。
  • 客户端利用长连接访问服务器端,在结束连接之前已经包了非常多的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形式的数据,如下:

网络延迟或数据提交超时(处理网络超时问题的最佳实践)(2)

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

网络延迟或数据提交超时(处理网络超时问题的最佳实践)(3)

  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设置导致的超时,发生比例相对少,但需要更广泛的排查,并且不要轻易忽略了这类原因导致的超时。

作者:怀知

,

免责声明:本文仅代表文章作者的个人观点,与本站无关。其原创性、真实性以及文中陈述文字和内容未经本站证实,对本文以及其中全部或者部分内容文字的真实性、完整性和原创性本站不作任何保证或承诺,请读者仅作参考,并自行核实相关内容。文章投诉邮箱:anhduc.ph@yahoo.com

    分享
    投诉
    首页