My Avatar

JacketWoo

King Birds Fly Fast and Early!

linux-2.6.32版本内核引起的客户端超时问题总结

2016年08月28日 星期日, 发表于 北京

如果您对本文有任何的建议或者疑问, 可以给我发邮件(seuxfw1990@gmail.com)或者在 这里给我提 Issues, 谢谢! :)

1. 问题现象

前段时间在推RedisCluster的线上使用过程中,phpredis客户端在短连接下总是报出“connection timed out”的错误,但是连接请求量还没有达到让服务端丢弃连接请求的地步,而且报错的频率和客户机上的TimeWait插口的数量有关,当TimeWait插口的数量较少时,报错相对减少(所以目前线上的处理方案是改用长连接或者修改“net.ipv4.tcp_max_tw_buckets”参数来限制TimeWait插口数量)。后续和云盘,无线wifi,DBA等同事沟通发现, memcache, mysql等客户端均存在这个问题。

2. 问题结论

这是linux-2.6.32内核某版本之前的一个bug,线上机器的操作系统内核就有一部分是这个版本之前的,也就有了这个问题,如对于操作系统为centos6.2的机器,有的linux内核版本是”2.6.32-220”,而有的则是addops 提供的 “2.6.32-504”, 前者就有这个问题,而后者就修复了这个问题。

报“connection timed out”的错误,并不是连接建立失败,而是有的连接不是第一次建立就成功,而是第二次或第三次重试发SYN包后才建立起来的,连接的时间比较长,至少为第一次重试的时间(3s),这个远超我们设置的连接超时(100ms), 所以才会报“connection timed out”的错误。

至于为什么产生这种情况在下面解释。

3. 问题解决

在centos 6 系统上, 升级到addops 提供的linux-2.6.32-504 版本(centos7 系统上不存在这个问题)。

4. 问题分析

因为这个问题比较的普遍,不单单是phpredis客户端,许多客户端都有这个问题,所以就深入查了下, 现归纳下这个问题产生的几个条件: a. 并发,多进程或者多线程并发的建立连接 b. 设置了net.ipv4.tcp_tw_reuse和net.ipv4.tcp_timestamps内核参数 c. timewait比较的多 d. 连接比较的频繁 线上使用短连接的客户端基本上都满足上面的这几个条件。

4.1 tcmpdump 抓包分析

我们首先复现了这种情况(代码就补贴了,大体的思路,是让几个进程并发的不停连接某一个相同的远程IP:PORT, 打印出连接时间超过1s的连接信息),并对这种情况进行了tcmdump抓包。抓到得到某些片段如下(1.2.3.4和4.3.2.1分别是客户机和服务端的虚假IP,后面的代码片段中1.2.3.5也是客户端的虚假IP):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
1663272 16:36:14.165636 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [S], seq 1532617220, win 14480, options [mss 1460,sackOK,TS val 428842102 ecr 38019842        27,nop,wscale 7], length 0
1663273 16:36:14.165639 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [S], seq 1532617220, win 14480, options [mss 1460,sackOK,TS val 428842102 ecr 38019842        27,nop,wscale 7], length 0
1663319 16:36:14.165875 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [S.], seq 3618542484, ack 1532617221, win 14480, options [mss 1460,sackOK,TS val 38019        88727 ecr 428842102,nop,wscale 7], length 0
1663320 16:36:14.165880 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 1, win 114, options [nop,nop,TS val 428842102 ecr 3801988727], length 0
1663321 16:36:14.165890 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [P.], seq 1:129, ack 1, win 114, options [nop,nop,TS val 428842102 ecr 3801988727], le        ngth 128
1663346 16:36:14.166171 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [S.], seq 3618542484, ack 1532617221, win 14480, options [mss 1460,sackOK,TS val 38019        88728 ecr 428842102,nop,wscale 7], length 0
1663349 16:36:14.166180 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 1, win 114, options [nop,nop,TS val 428842102 ecr 3801988728,nop,nop,sack 1 {        0:1}], length 0
1663365 16:36:14.166424 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [.], ack 129, win 122, options [nop,nop,TS val 3801988728 ecr 428842102], length 0
1663789 16:36:14.173725 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [P.], seq 1:15, ack 129, win 122, options [nop,nop,TS val 3801988735 ecr 428842102], l        ength 14
1663791 16:36:14.173740 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 15, win 114, options [nop,nop,TS val 428842110 ecr 3801988735], length 0
1663794 16:36:14.173748 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [F.], seq 129, ack 15, win 114, options [nop,nop,TS val 428842110 ecr 3801988735], len        gth 0
1664028 16:36:14.177178 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [F.], seq 15, ack 130, win 122, options [nop,nop,TS val 3801988739 ecr 428842110], len        gth 0
1664029 16:36:14.177182 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 16, win 114, options [nop,nop,TS val 428842113 ecr 3801988739], length 0
1851605 16:36:17.166463 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [S], seq 1532617220, win 14480, options [mss 1460,sackOK,TS val 428845103 ecr 38019842        27,nop,wscale 7], length 0
1851652 16:36:17.167139 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [S.], seq 3665436820, ack 1532617221, win 14480, options [mss 1460,sackOK,TS val 38019        91729 ecr 428845103,nop,wscale 7], length 0
1851653 16:36:17.167146 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 1, win 114, options [nop,nop,TS val 428845103 ecr 3801991729], length 0
1851655 16:36:17.167177 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [P.], seq 1:129, ack 1, win 114, options [nop,nop,TS val 428845103 ecr 3801991729], le        ngth 128
1851668 16:36:17.167449 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [.], ack 129, win 122, options [nop,nop,TS val 3801991729 ecr 428845103], length 0
1852008 16:36:17.172664 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [P.], seq 1:15, ack 129, win 122, options [nop,nop,TS val 3801991734 ecr 428845103], l        ength 14
1852011 16:36:17.172671 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 15, win 114, options [nop,nop,TS val 428845109 ecr 3801991734], length 0
1852012 16:36:17.172677 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [F.], seq 129, ack 15, win 114, options [nop,nop,TS val 428845109 ecr 3801991734], len        gth 0
1852146 16:36:17.176198 IP 4.3.2.1.afs3-bos > 1.2.3.4.45822: Flags [F.], seq 15, ack 130, win 122, options [nop,nop,TS val 3801991738 ecr 428845109], len        gth 0
1852147 16:36:17.176203 IP 1.2.3.4.45822 > 4.3.2.1.afs3-bos: Flags [.], ack 16, win 114, options [nop,nop,TS val 428845112 ecr 3801991738], length 0

上面的片段是一个连接建立时间为3s左右的连接建立过程,虽然做了简化,并且剔除了其他无关的过程,但是有点乱不好看,第一列是行号,下面按行号解释下吧: 第1663272、1663273行,客户端连续两行发送了两个SYN,有点费解了,为啥连续发两个SYN,只间隔了3 us,而且seq号还一样; 第1663319行,服务端回了一个SYNACK; 第1663320行,客户端回了个ACK;这时候三次握手完成 第1663321行,客户端给服务单发送数据 第1663346行,服务端给客户端又回了个SYNACK,而且seq号和上个SYNCAK一样 第1663349行,客户端给服务端回1663346行的ACK 第1663365行,服务端给客户端回1663321行的ACK 第1663789行,服务端给客户端返回数据 第1663791行,客户端给服务端回1663789行的ACK 第1663794行,客户端发送FIN 第1664028行,服务端回FINACK 第1664029行,客户端回1664028行的ACK 第1851605行,客户端重发了一次SYN,这次的时间和前两个SYN时间间隔大约3s左右,seq号和前两次的一样 第1851652行,服务端回一个SYNACK 第1851653行,客户端回一个ACK 第1851655行,客户端发送数据 第1851668行,服务端回一个ACK 第1852008行,服务端给客户端发送数据 第1852011行,客户端回一个ACK 第1852012行,客户端发送FIN 第1852146行,服务端发送FINACK 第1852147行,客户端回ACK

从上可以看出,第1663273,1663346, 1663349, 虽然也进行了三次握手,但是连接貌似并没有建立起来,没有发送数据;而是3秒后重新发送了一次SYN,然后建立连接,发送数据;也就是说最开始虽然几乎同时发送了两个SYN包,但是只有一个连接建立起来且正常发送和接收数据,另一个连接并没有建立起来,而是等3s后,重新发送SYN,然后建立连接发送数据。

从上面的抓包中,我们看到了两个情况:

a. 报超时错误的连接,并不是建立不成功,而是需要3s延迟;

b. 连个连接请求发出的SYN包具有相同的序列号。正是这两个情况导致了我们的“connection timed out”错误。下面在linux内核里解释产生这个两个情况的原因。

4.2 linux 代码分析

4.2.1连接不是建立失败,而是需要3s左右的延迟

众所周知,connect()系统调用在执行过程中,如果之前本地没有绑定本地port, 它会为所使用的插口随机绑定一个本地port。在随机绑定本地port的过程当中,它会从本地的port_range中,随机的选择一个开始,然后依次遍历查询,直到找到一个可以被使用的port。下面是相关的代码片段:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
int __inet_hash_connect(....) { //in inet_hash_connect.c
	if (!sum) { //之前没有绑定本地port
	...
		for (i = 1; i <= remaining; i++) { //依次在port_range里遍历
			port = low + (i + offset) % remaining; //本次遍历到port
			spin_lock(&head->lock); //加锁,这个很重要,防止别的线程或者进程也遍历这个port
			...
			inet_bind_bucket_for_each(tb, node, &head->chain) { //依次遍历有哪些插口绑定到了这个port上
				if (!check_established(death_row, sk, port, &tw)) //查看这个port能不能被我们的插口使用
					goto ok; //表示这个port能够被我们的sock使用
			...
			}
			...
			spin_unlock(&head->lock); //解锁
		}
	...
ok:
	...
	inet_bind_hash(sk, tb, port); //把这个sock添加到绑定到该port所对应的链表的**头部**
**	spin_unlock(&head->lock);//解锁
**	inet_twsk_deschedule(tw, death_row); //**这里面会把port原来绑定的timewait插口移掉
	...
	} else {
	...
	}
	...
}

​ 注意上面代码中,注意开头有**的两行。正常来说,应该把移出timewait插口的逻辑放在自旋锁里面进行操作,这样后面来的线程才不会对我们已经选中的port上的timewait插口进行遍历,而导致重复使用。显然,这里忽略了这一点,顺序反了,导致我们对同一port进行了重复使用,最后的结果是,两个四元组(本地IP,被哪PORT,目标IP,目标PORT)相同的sock,绑定到了同一个本地PORT上,而这两个sock会被添加到保存绑定到该port上的插口链表的头部。

​ 自然的这两个sock会先后发出SYN包,而服务端也会先后回两次ACK包,这个在前一封邮件里都看到;而ack包在回来的时候,是怎么确定它是属于哪个插口的呢?它是从插口链表的头部开始查找,直到匹配的就退出,这样,上面两个四元组一样的sock,总是第一个被找到,而忽略第二个;一段时间后,第二个sock发现自己没有收到ack,它会再次发送一次SYN包(重试时间一般为3s), 因为我们我们是短连接,这时候,前一个sock建立的连接已经关闭,也就是说这时候这个sock是排在链表的首位的,它能够接收到远端发来的ACK包,三次握手完成,连接也就建立起来了,这就是为什么我们观察到的连接并不是建立失败,而是需要大约3s:

1
2
3
[wxf@myhost ~]$ grep -B 1 "local_port: 36112" ./ -r --color
./13-curTime: 1468236300.586346 microseconds, select time is 2999426 microseconds
./13:local_ip: 1.2.3.4, local_port: 36112

4.2.2 两个连接请求的SYN序列号相同

现在来看下上面代码中的check_established(death_row, sk, port, &tw)函数,这是个回调函数,他的作用检查所遍历到的port是否可用,下面是这个回调函数的代码片段:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
static int __inet_check_established(struct inet_timewait_death_row *death_row, //in inet_hashtables.c
                    struct sock *sk, __u16 lport,
                    struct inet_timewait_sock **twp)
{
	....
	sk_nulls_for_each(sk2, node, &head->twchain) { //遍历timewait插口
		 tw = inet_twsk(sk2);
		 if (INET_TW_MATCH(sk2, net, hash, acookie,
                    saddr, daddr, ports, dif)) { //检查四元组是否一样
	         if (twsk_unique(sk, sk2, twp)) //检查timewait状态的插口是否可以被重用 
		         goto unique;
		     else
			     goto uot_unique;  
         }
     ...
     sk_nulls_for_each(sk2, node, &head->chain) { //遍历非timewait状态的插口
     ...
     }
     ...
}

​ 从上面的代码可以看到,整个检查分为两个部分,首先检查出在timewait状态下的插口是否可以重用;如果没有相应的timewait插口或者相应的timewait插口不能够被重用,则需要检查我们使用这个port是否与已经使用的非timewait状态的插口冲突。上面的twsk_uniqure(…)函数也是个回调函数,它除了检查我们所选择的timewait插口是否可以被重用,还确定了我们要发送的SYN包的序列号,下面是这个回调函数的逻辑片段:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
int tcp_twsk_unique(struct sock *sk, struct sock *sktw, void *twp) 
{
	const struct tcp_timewait_sock *tcptw = tcp_twsk(sktw);
    struct tcp_sock *tp = tcp_sk(sk);
    if (tcptw->tw_ts_recent_stamp && //net.ipv4.tcp_timestamps内核参数要有效
        (twp == NULL || (sysctl_tcp_tw_reuse && // net.ipv4.tcp_tw_reuse内核参数要有效
                 get_seconds() - tcptw->tw_ts_recent_stamp > 1))) { //两次干呕间隔要香茶1s以上
        tp->write_seq = tcptw->tw_snd_nxt + 65535 + 2; //确定发送的SYN序列号
        if (tp->write_seq == 0)
            tp->write_seq = 1;
        tp->rx_opt.ts_recent       = tcptw->tw_ts_recent;
        tp->rx_opt.ts_recent_stamp = tcptw->tw_ts_recent_stamp;
        sock_hold(sktw);
        return 1;
    }

    return 0;
}

​ 从上面的代码可以看出,当新插口与timewait插口的时间差在1s以上,net.ipv4.tcp_tw_reuse和net.ipv4.tcp_timestamps内核参数也有效时,表示可以该timewait插口可以被重用,并且从新插口发出的SYN序列号是根据timewait插口的发送序列号来确定的,为:新SYN_seq = tw_seq + 65535+2。

​ 由于上面4.2.1说的情况,当有两个线程或者进程都遍历到这个timewait插口,都通过了可以重用这个Timewait插口的检查,那么它们接下来要发送SYN包的序列号也就都由这个timewait插口的发送序列号唯一确定了,也就相同了。

正如4.2.1和4.2.2所说,后面版本的linux内核修复这个bug的方式是将被选中的可复用timewait插口的移除操作放在在自旋锁解锁之前来执行

5. 验证过程

​ 线上的cento6.2机器,内核一部分为“2.6.32-220”,一部分为“2.6.32-504”,正如前面所说,前者是有这个bug的,后者则没有这个bug。分别在这个两个平台上验证(客户端的测试程序就用前面抓包的程序,打印出连接时间大于1s的连接时间等信息):

5.1 在内核为2.6.32-220的机器上:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
[wxf@myhost ~]$ uname -a
Linux myhost.xxx.xxx.xxx.xxx 2.6.32-220.7.1.el6.x86_64 #1 SMP Wed Mar 7 00:52:02 GMT 2012 x86_64 x86_64 x86_64 GNU/Linux
[wxf@myhost ~]$ gcc test.c -o test
[wxf@myhost ~]$ ./test 4.3.2.1 8222 4 &
[1] 36460
[wxf@myhost ~]$ ./test 4.3.2.1 8222 4 &
[2] 36466
[wxf@myhost ~]$ ./test 4.3.2.1 8222 4 &
[3] 36467
[wxf@myhost ~]$ curTime: 1472019271.735598 microseconds,Select time is 3000939 micro seconds
local_ip: 1.2.3.4, local_port: 22708, peer_ip: 4.3.2.1, peer_port: 8222

curTime: 1472019274.745404 microseconds,Select time is 3000140 micro seconds
local_ip: 1.2.3.4, local_port: 41296, peer_ip: 4.3.2.1, peer_port: 8222

curTime: 1472019275.668756 microseconds,Select time is 2999758 micro seconds
local_ip: 1.2.3.4, local_port: 22708, peer_ip: 4.3.2.1, peer_port: 8222

curTime: 1472019277.774717 microseconds,Select time is 2999923 micro seconds
local_ip: 1.2.3.4, local_port: 47417, peer_ip: 4.3.2.1, peer_port: 8222

“./test 4.3.2.1 8222 4 &”,4.3.2.1是远端的ip, 8222是远端的port, 4表示4s的连接超时 同时跑了3个客户端,没多久,就出现了连接时间为3s左右的情况。

5.2 在内核为2.6.32-504的机器上

1
2
3
4
5
6
7
8
9
[wxf@myhost1 ~]$ uname -a
Linux 1.2.3.5 2.6.32-504.8.1.el6.x86_64 #1 SMP Wed Jan 28 21:11:36 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
[wxf@myhost1 ~]$ gcc test.c -o test
[wxf@myhost1 ~]$ ./test 4.3.2.1 8222 4 &
[1] 14034
[wxf@myhost1 ~]$ ./test 4.3.2.1 8222 4 &
[2] 14035
[wxf@myhost1 ~]$ ./test 4.3.2.1 8222 4 &
[3] 14036

跑了很久也没有出现连接时间超过1s的情况。

5.1和5.2说明验证通过。