关于redis集群线上以及测试环境出现read time out,connect time out的总结

原创内容,转载请注明出处

Posted by Weakyon Blog on December 19, 2014

time out这个问题是我刚实习的时候所有的业务组就都存在并且反应的。但是最近这段时间才定位了错误,固然这中间弄了小文件系统等等,但主要还是本人能力不太够导致的。

由于定位的时间拖得太长,导致大家对twemproxy-redis都有一种不稳定,不放心的看法,然而今天要为它正名:

代码没问题,一切都是网络不稳定惹的祸。

1 首先分析测试环境。

在测试组和同步业务的帮助下,我们拉来了device的数据进行测试(使用了ntpdate对所有机器进行了时间同步)

这个业务并发是不高的,每个key的value也相当的小,10多B罢了。然而在测试环境复现了read time out现象。随后我修改了proxy的代码,插入了log。

1

取460070000144258这个key。

在proxy上查到这个key记录

2

它的值是$11\r\n17800144258\r\n,符合redis协议没有问题。

Time 1的值是client请求传入proxy的时间,

Time 2的值是proxy使用nc_writev系统调用的时间

可以看到time1和time2的相差非常小,这已经算上了proxy和redis进行通讯的时间了

而后分析proxy上抓到的包,找到这个时间点的这个返回值的包。

3

从这里得到了56961端口

而后分析client上抓到的包

4

通过上下文的对比,确认这是同一个包,然而时间相差了3.1秒。

Redis配置的时候,标准配置超时时间是2秒,因此客户端报出read time out。

2 再来分析线上环境

线上环境有着测试环境无论如何也复现不出的connect time out,而且是24小时不间断毫无规律的报出的。

写了一个C-S测试程序,client部署jetty上,server部署proxy上,client每1秒10次connect server,server仅仅是死循环的accept。非常简单的逻辑。

跑了8小时,分析log。

5

这373的match经过检查,都是1秒左右的,其中存在一个3秒左右的。

connect系统调用要这么久。深层去挖,要么是消耗在内核时间,要么是消耗在网络中了。

于是写程序来分析这一堆乱序重传的包,计算出sync,sync_ack,ack三次握手的耗时。

6

355个,比起373来少了18个,这18个都是丢包以后所以未检测到完整3次握手的包。

比如:
66674 10:43:03.387110 IP 192.168.16.138.21703 > 192.168.18.233.12345: Flags [F.], seq 1, ack 2, win 115, length 0
66675 10:43:03.387180 IP 192.168.16.138.21705 > 192.168.18.233.12345: Flags [S], seq 2900037514, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 7], length 0
66676 10:43:04.417747 IP 192.168.16.138.21840 > 192.168.18.233.12345: Flags [S], seq 2493315631, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 7], length 0
66677 10:43:04.418333 IP 192.168.18.233.12345 > 192.168.16.138.21840: Flags [S.], seq 1454354311, ack 2493315632, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 7], length 0
 
搜索192.168.16.138.21705这个端口的握手完成的包
512959 12:35:21.437934 IP 192.168.16.138.21705 > 192.168.18.233.12345: Flags [S], seq 807898100, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 7], length 0
512960 12:35:21.441510 IP 192.168.18.233.12345 > 192.168.16.138.21704: Flags [F.], seq 1, ack 1, win 115, length 0
512961 12:35:21.441518 IP 192.168.16.138.21704 > 192.168.18.233.12345: Flags [.], ack 2, win 115, length 0
512962 12:35:21.441569 IP 192.168.18.233.12345 > 192.168.16.138.21704: Flags [.], ack 2, win 115, length 0
512963 12:35:21.441598 IP 192.168.18.233.12345 > 192.168.16.138.21705: Flags [S.], seq 1368040831, ack 807898101, win 14600, options [mss 1460,nop,nop,sackOK,nop,wscale 7], length 0
512964 12:35:21.441608 IP 192.168.16.138.21705 > 192.168.18.233.12345: Flags [.], ack 1, win 115, length 0

相差两个小时,这已经是端口重用而不是重传范围的包了。

而这个包的sync_ack以及ack都不存在,证明三次握手某个环节丢包了。

另外通过ping –f指令,可以看到大量的”.”存在,再次印证线上网络的问题。

少量的connect都如此,何况大并发的情况下的网络。

总结:

一 测试环境的网络波动是可容忍范围内的,只是提给测试组的单,要注意对于敏感应用来说的网络不确定性

二 线上环境比测试环境还不稳定些,以下是我的建议:

运维:

运维的同学定位下能否解决网络的问题。

有两个点可以看看:

1) 根据各个业务的反应,各台jetty报出time out的时间是相近的,这是什么原因

2) connect这里超时大部分都是1秒,这个1秒是否有什么原因

DBA: 目前read time out,connect time out暂时是无法消除的,而且每天出现的时间点和频度都不能确定,只能通过经验值来确定阀值,超过这个阀值说明业务故障(比如上周SYNC业务大量time out报错)。

业务:

大PV值的业务,如果time out过多影响了业务,可以尝试设大jedis-pool中timeout参数的值


后续追踪:

经过一周左右我和运维一起排查,确认是博通网卡虚拟化导致的延时,目前联系了供应商进行网卡驱动升级。

待续

19 Dec 2014