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说明验证通过。