TCP发送缓存阻塞(Send-Q不为0)问题

现象:

CEPH集群近来遇到一个重启一个节点上的所有OSD进程之后,总会有一两个PG的状态卡在peering或者是activating阶段,但是经过大概900多秒后重新建立链接后,集群可恢复ok。打开OSD和MS的日志发现消息并没有阻塞在软件层,而是软件层已经将调用了sendmsg系统调用往外发,但是对端还是没有收到消息。

定位过程:

通过ss -ipnome | grep ceph-osd 命令过滤发送端和接收端的tcpinfo信息:

发送端:

2020-06-13 14:56:03 ESTAB,0,139680,2020::16:3109:6820,2020::16:3100:48608,users:((“ceph-osd”,pid=55696,fd=70)),rtt:1.445/0.881,lastsnd:66550,lastrcv:539,lastack:539
2020-06-13 15:01:03 ESTAB,0,142560,2020::16:3109:6820,2020::16:3100:48608,users:((“ceph-osd”,pid=55696,fd=70)),rtt:1.445/0.881,lastsnd:121377,lastrcv:1357,lastack:1357
2020-06-13 15:06:04 ESTAB,0,144000,2020::16:3109:6820,2020::16:3100:48608,users:((“ceph-osd”,pid=55696,fd=70)),rtt:1.445/0.881,lastsnd:50178,lastrcv:2170,lastack:2170

接收端:

2020-06-13 14:56:03 ESTAB,0,0,2020::16:3100:48608,2020::16:3109:6820,users:((“ceph-osd”,pid=40468,fd=597)),rtt:1.478/2.851,lastsnd:977,lastrcv:281805,lastack:977
2020-06-13 15:01:04 ESTAB,0,0,2020::16:3100:48608,2020::16:3109:6820,users:((“ceph-osd”,pid=40468,fd=597)),rtt:0.492/0.88,lastsnd:1835,lastrcv:582713,lastack:1835
2020-06-13 15:06:05 ESTAB,0,0,2020::16:3100:48608,2020::16:3109:6820,users:((“ceph-osd”,pid=40468,fd=597)),rtt:2.232/4.311,lastsnd:2659,lastrcv:883587,lastack:2659

可以观察到发送端send-Q不减少,甚至是继续增大,send-Q在建立链接之后表示的含义是当前滑动窗口里sendbuffer里的字节数,sendbuffer只有在接收到对端的ack之后才会清理掉,所以可以断定发送端是没有接收到对端的回复的ack报文的。

常见的TCP发送端send-Q不减少都是因为接收端接收缓存满了给发送端回复win=0的反压报文,发送端不再给接收端发送报文导致send-Q不减少,但是通过接收端的tcpinfo信息来看,接收端的接收缓存为空,所以不是该问题导致的;还有一种可能就是接收端接收线程挂住了,但是接收线程挂住之后按理说接收缓存不应该为0,结合接收端OSD的ms日志来看,接收端处理消息的线程并没有挂住,所以该假设也不成立。

复现抓包:

经过大量的复现,同时抓包,由于出问题的集群规模较大(40个节点每个节点14块盘),没法单抓某张网卡的报文,所以只能在出现问题后迅速抓包,这样就只能抓到出问题后的报文信息,下面是接收端抓到的报文信息( 发送端 2020::16:3109 、 接收端2020::16:3100 ):

27 2020-06-13 15:03:08.503568 2020::16:3100 2020::16:3109 TCP 119 48608 > 6820 [PSH, ACK] Seq=367183868 Ack=798178296 Win=110 Len=9 SLE=798237336 SRE=798257496 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
28 2020-06-13 15:03:08.503622 2020::16:3109 2020::16:3100 TCP 1514 6820 > 48608 [ACK] Seq=798257496 Ack=367183877 Win=683 Len=144029
29 2020-06-13 15:03:08.503629 2020::16:3100 2020::16:3109 TCP 110 [TCP Dup ACK 27#1] 48608 > 6820 [ACK] Seq=367183877 Ack=798178296 Win=110 Len=0 SLE=798237336 SRE=798258936 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
30 2020-06-13 15:03:14.504574 2020::16:3100 2020::16:3109 TCP 119 48608 > 6820 [PSH, ACK] Seq=367183877 Ack=798178296 Win=110 Len=9 SLE=798237336 SRE=798258936 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
….
70 2020-06-13 15:05:14.524574 2020::16:3100 2020::16:3109 TCP 119 48608 > 6820 [PSH, ACK] Seq=367184057 Ack=798178296 Win=110 Len=9 SLE=798237336 SRE=798258936 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
71 2020-06-13 15:05:14.524651 2020::16:3109 2020::16:3100 TCP 1514 6820 > 48608 [ACK] Seq=798258936 Ack=367184066 Win=683 Len=1440
72 2020-06-13 15:05:14.524660 2020::16:3100 2020::16:3109 TCP 110 [TCP Dup ACK 70#1] 48608 > 6820 [ACK] Seq=367184066 Ack=798178296 Win=110 Len=0 SLE=798237336 SRE=798260376 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
73 2020-06-13 15:05:20.525568 2020::16:3100 2020::16:3109 TCP 119 48608 > 6820 [PSH, ACK] Seq=367184066 Ack=798178296 Win=110 Len=9 SLE=798237336 SRE=798260376 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
….
110 2020-06-13 15:07:08.543645 2020::16:3109 2020::16:3100 TCP 74 6820 > 48608 [ACK] Seq=798260376 Ack=367184237 Win=683 Len=0
111 2020-06-13 15:07:11.723229 2020::16:3100 2020::16:3109 TCP 110 48608 > 6820 [FIN, ACK] Seq=367184237 Ack=798178296 Win=110 Len=0 SLE=798237336 SRE=798260376 SLE=798234456 SRE=798235896 SLE=798231576 SRE=798233016 SLE=798225816 SRE=798230136
112 2020-06-13 15:07:11.723270 2020::16:3109 2020::16:3100 TCP 74 6820 > 48608 [RST] Seq=798178296 Win=0 Len=0

可以看到其实发送端一直在给接收端发送报文,而且发送端可以正常处理接收端的报文,但是接收端给发送端回复的 ack = 798178296,此时发送端的seq= 798260376 已经远远大于接收端最后一次接收到发送端报文的序列号了,由此可以断定tcp没有触发重发机制,导致了通讯中断了,由于没有出问题的现场,无法确认 798178296 后的报文是没收到还是没发送,所以需要继续抓包分析。

调整发送缓存大小:

最初怀疑是不是跟服务器的tcp读写缓存相关,但是服务器配置的最大的发送缓存和接收缓存都已经非常大,按理说也不会有影响。由于不了解/proc/sys/net/ipv4/tcp_wmem和/proc/sys/net/core/wmem_max 的区别,误以为ipv4用的是 ipv4 目录下的配置,而ipv6用的是core目录下的配置,而core目录配置下的发送缓存才200k,所以修改 /proc/sys/net/core/wmem_max 为很小的值去复现(需同步修改 /proc/sys/net/core/wmem_default),问题没有出现,后来经过测试发现ipv4和ipv6都是用的 /proc/sys/net/ipv4目录下的配置。

将 /proc/sys/net/ipv4/tcp_wmem配置在小集群上(三节点每个节点15块5.5T盘)修改为最大不超过30k,重启一个节点的OSD后,出现了peering卡住的现象,这个时候我还是比较蠢,这其实是一个问题,不管TCP大小修改为多小,最多就是消息发送缓慢,而不是卡住不发送,改小了发送缓存后,抓包分析。由于报文比较多,所以tcpdump命令会有丢失报文的问题,在抓了两次报文复现之后,发现故障后的报文在发送端和接收端都没有抓到(发送端wireshark显示似乎是工具没有抓到这个报文,接收端显示似乎是工具没有抓到到这个报文),此时还是怀疑是tcp的问题但是无从分析起。

结论:

疯狂google后发现有人遇到了类似的问题,原来是tcp的bug, 内核修复了后该问题不再出现。 https://access.redhat.com/security/vulnerabilities/tcpsack

附当时搜到的博客: https://runsisi.com/2019-12-19/tcp-sack-hang

发表评论

电子邮件地址不会被公开。 必填项已用*标注