plantegg

java tcp mysql performance network docker Linux

一次网络连接残留的分析

本来放在知识星球的收费文章,也网络直播给星球成员讲解过这个问题以及这篇文章的内容,作删减和调整后也发博客吧

问题描述

LVS TCP 探活一般是 3 次握手(验证服务节点还在)后立即发送一个 RST packet 来断开连接(效率高,不需要走四次挥手),但是在我们的LVS 后面的 RS 上发现有大量的探活连接残留,需要分析为什么?

一通分析下来发现是 RST 包 和第三次握手的 ack 到达对端乱序了,导致 RST 被drop 掉了。但是还需要进一步分析 drop 的时候和 RST 包里面带的 timestamp 有没有关系?

可以用 Scapy 来实验验证如下 4 个场景:

  1. 正常三次握手,然后发送 RST 看看是否被 drop —— 期望 RST 不被 drop,连接正常释放,作为对比项
  2. 正常 2 次握手,然后立即发送 RST(正常带 timestamp),再发送 ack(制造乱序),看看 RST 会不会被 drop,如果 RST drop 后连接还能正常握手成功并残留吗?
  3. 正常 2 次握手,然后立即发送 RST(不带 timestamp),再发送 ack(制造乱序),看看 RST 会不会被 drop
  4. 正常 2 次握手,然后立即发送 RST(带 timestamp,但是 timestamp 为 0),再发送 ack(制造乱序),看看 RST 会不会被 drop

重现场景构造如下:通过客户端+服务端来尝试重现,客户端用 scapy 来构造任意网络包,服务端通过 python 起一个 WEB 服务

客户端

因为最新的 scapy 需要 python3.7 ,可以搞一个内核版本较高的 Linux 来测试(星球统一 99 块的实验 ECS 就符合要求),安装命令大概是这样:yum install python3-scapy

用 scapy 脚本构造如上 3 个场景的网络包,代码和使用帮助我放到这里了:https://github.com/plantegg/programmer_case/commit/e71ade38050c48170c7d6fb5922f78188a96435b#diff-3d18b8aa76586e6c59227e020ba22ef1ef8c5416764d0a923b198ad824996eda

如果需要构造带 timestamp 的RST 用如下代码段,乱序通过调整 ack和 RST 的顺序来实现

1
2
3
4
5
6
7
8
9
10
11
# 构造 ACK 包
ack = TCP(sport=source_port,
dport=target_port,
flags='A',
seq=syn_ack.ack,
ack=syn_ack.seq + 1,
options=[('NOP', None), ('NOP', None),
('Timestamp', (int(time.time()), 0))]) //重点调整这里的时间戳,以及 rst 和 ack 包的顺序

# 发送 ACK
send(ip/ack)

在scapy 机器上drop 掉OS 自动发送的 RST(因为连接是 scapy 伪造的,OS 收到 syn+ack 后会 OS系统会发 RST(这个 RST不带 timestamp))

1
2
3
4
iptables -A OUTPUT -p tcp --dport 8000 --tcp-flags RST RST  ! --tcp-option 8 -j DROP

//清理
iptables -D OUTPUT -p tcp --dport 8000 --tcp-flags RST RST ! --tcp-option 8 -j DROP

scapy 构造的包流程,可以看到不走内核 tcp 协议栈,也不走 nf_hook(防火墙),不受上面的 iptables 规则限制,所以能发送到服务端:

1
2
3
4
5
6
7
8
9
10
***************** c7d8ea00 ***************
[100167.011693] [__dev_queue_xmit ] TCP: 172.26.137.131:8146 -> 172.26.137.130:8000 seq:12346, ack:0, flags:R
[100167.011702] [dev_hard_start_xmit ] TCP: 172.26.137.131:8146 -> 172.26.137.130:8000 seq:12346, ack:0, flags:R *skb is successfully sent to the NIC driver*
[100167.011714] [consume_skb ] TCP: 172.26.137.131:8146 -> 172.26.137.130:8000 seq:12346, ack:0, flags:R *packet is freed (normally)*

***************** c700e300 ***************
[100167.024811] [__dev_queue_xmit ] TCP: 172.26.137.131:8146 -> 172.26.137.130:8000 seq:12346, ack:2680597246, flags:A
[100167.024821] [dev_hard_start_xmit ] TCP: 172.26.137.131:8146 -> 172.26.137.130:8000 seq:12346, ack:2680597246, flags:A *skb is successfully sent to the NIC driver*
[100167.024891] [consume_skb ] TCP: 172.26.137.131:8146 -> 172.26.137.130:8000 seq:12346, ack:2680597246, flags:A *packet is freed (normally)*

Server 端

先记住一个知识点,后面看内核调用堆栈会用得上确认是否被丢包

一个网络包正常处理流程最后调 consume_skb 来释放,如果网络包需要 Drop 就调 kfree_skb 来丢包

server端 安装 netstrace来监控包是否被drop,并通过 python 拉起一个端口:

1
python -m http.server 8000

tcpdump 确认 8000 端口收到的包

在 8000端口机器上执行抓包验证收到的包顺序和所携带的 timestamp,包含 3 个场景的包:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
#tcpdump -i eth0 port 8000 -nn
//场景 2:正常 2 次握手,然后立即发送 RST(带 timestamp)
13:56:26.614701 IP 172.26.137.131.54321 > 172.26.137.130.8000: Flags [S], seq 2754757912, win 8192, options [mss 1460,nop,nop,TS val 1732514186 ecr 0], length 0
13:56:26.614815 IP 172.26.137.130.8000 > 172.26.137.131.54321: Flags [S.], seq 1579697129, ack 2754757913, win 65160, options [mss 1460,nop,nop,TS val 2888180099 ecr 1732514186], length 0
13:56:26.633997 IP 172.26.137.131.54321 > 172.26.137.130.8000: Flags [R], seq 2754757913, win 8192, options [mss 1460,nop,nop,TS val 1732514186 ecr 0], length 0 //留意端口号 54321 和 seq 2754757913 跟 nettrace 对应
13:56:26.654954 IP 172.26.137.131.54321 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [nop,nop,TS val 1732514186 ecr 0], length 0
13:56:26.655042 IP 172.26.137.130.8000 > 172.26.137.131.54321: Flags [R], seq 1579697130, win 0, length 0

//场景 3:正常 2 次握手,然后立即发送 RST(不带 timestamp), 注意这里的 tcp options 是 null
13:56:28.993723 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [S], seq 54243194, win 8192, options [mss 1460,nop,nop,TS val 1732514188 ecr 0], length 0
13:56:28.993809 IP 172.26.137.130.8000 > 172.26.137.131.12345: Flags [S.], seq 1983242893, ack 54243195, win 65160, options [mss 1460,nop,nop,TS val 2888182478 ecr 1732514188], length 0
13:56:29.012982 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [R], seq 54243195, win 8192, length 0 //留意端口号 12345 和 seq 54243195 跟 nettrace 对应
13:56:29.029886 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [nop,nop,TS val 1732514189 ecr 0], length 0
13:56:29.029983 IP 172.26.137.130.8000 > 172.26.137.131.12345: Flags [R], seq 1983242894, win 0, length 0 //OS 触发
13:56:29.050888 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [R], seq 54243195, win 8192, length 0

//场景 1:正常握手,然后 RST
13:56:30.399672 IP 172.26.137.131.22345 > 172.26.137.130.8000: Flags [S], seq 1038081714, win 8192, options [mss 1460,nop,nop,TS val 1732514190 ecr 0], length 0
13:56:30.399770 IP 172.26.137.130.8000 > 172.26.137.131.22345: Flags [S.], seq 3263478059, ack 1038081715, win 65160, options [mss 1460,nop,nop,TS val 2888183884 ecr 1732514190], length 0
13:56:30.426005 IP 172.26.137.131.22345 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [nop,nop,TS val 1732514190 ecr 0], length 0
13:56:30.448876 IP 172.26.137.131.22345 > 172.26.137.130.8000: Flags [R], seq 1038081715, win 8192, length 0

场景 1:正常三次握手后再 RST,作为对比

netstrace 命令和结果

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
#netstat -P 8000
***************** c22c8c00,c22c8000 ***************
[4912187.018483] [__ip_local_out ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018485] [nf_hook_slow ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *ipv4 in chain: OUTPUT*
[4912187.018487] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *iptables table:, chain:OUTPUT*
[4912187.018489] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *iptables table:, chain:OUTPUT*
[4912187.018493] [ip_output ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018495] [nf_hook_slow ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *ipv4 in chain: POST_ROUTING*
[4912187.018496] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *iptables table:, chain:POSTROU*
[4912187.018499] [ip_finish_output ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018502] [ip_finish_output2 ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018506] [__dev_queue_xmit ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018510] [dev_hard_start_xmit ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *skb is successfully sent to the NIC driver*
[4912187.018512] [skb_clone ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018516] [tpacket_rcv ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA
[4912187.018519] [consume_skb ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *packet is freed (normally)*
[4912187.018533] [consume_skb ] TCP: 172.26.137.130:8000 -> 172.26.137.131:22345 seq:3263478059, ack:1038081715, flags:SA *packet is freed (normally)*

***************** c22c8a00,c22c8f00 ***************
[4912187.044742] [napi_gro_receive_entry] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044749] [dev_gro_receive ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044751] [__netif_receive_skb_core] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044753] [tpacket_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044758] [ip_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044760] [ip_rcv_core ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044762] [skb_clone ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044766] [nf_hook_slow ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *ipv4 in chain: PRE_ROUTING*
[4912187.044769] [nft_do_chain ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *iptables table:, chain:PREROUT*
[4912187.044772] [ip_rcv_finish ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044776] [ip_route_input_slow ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044781] [fib_validate_source ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044785] [ip_local_deliver ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044786] [nf_hook_slow ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *ipv4 in chain: INPUT*
[4912187.044787] [nft_do_chain ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *iptables table:, chain:INPUT*
[4912187.044789] [nft_do_chain ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *iptables table:, chain:INPUT*
[4912187.044791] [ip_local_deliver_finish] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044794] [tcp_v4_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044806] [tcp_child_process ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044810] [tcp_rcv_state_process] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *TCP socket state has changed*
[4912187.044813] [tcp_ack ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044818] [__kfree_skb ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044825] [packet_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A
[4912187.044827] [consume_skb ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:A *packet is freed (normally)*

***************** c22c8900,c22c8a00 ***************
[4912187.067611] [napi_gro_receive_entry] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067617] [dev_gro_receive ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067622] [__netif_receive_skb_core] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067624] [tpacket_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067628] [ip_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067630] [ip_rcv_core ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067631] [skb_clone ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067634] [nf_hook_slow ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R *ipv4 in chain: PRE_ROUTING*
[4912187.067636] [nft_do_chain ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R *iptables table:, chain:PREROUT*
[4912187.067639] [ip_rcv_finish ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067640] [ip_local_deliver ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067642] [nf_hook_slow ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R *ipv4 in chain: INPUT*
[4912187.067643] [nft_do_chain ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R *iptables table:, chain:INPUT*
[4912187.067644] [nft_do_chain ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R *iptables table:, chain:INPUT*
[4912187.067646] [ip_local_deliver_finish] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067648] [tcp_v4_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067650] [tcp_filter ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067651] [tcp_v4_do_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067653] [tcp_rcv_established ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067659] [__kfree_skb ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067685] [packet_rcv ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R
[4912187.067687] [consume_skb ] TCP: 172.26.137.131:22345 -> 172.26.137.130:8000 seq:1038081715, ack:3263478060, flags:R *packet is freed (normally)* //RST packet 被正常处理,没有发生 drop

场景 2:正常 2 次握手,然后立即发送 RST(带 timestamp)

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
#netstat -P 8000
//场景 2:正常 2 次握手,然后立即发送 RST(带 timestamp)—— RST 被 drop 了
***************** c22c8900,c22c8300 *************** //8000 端口回复的 syn+ack
[4912183.233533] [__ip_local_out ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233535] [nf_hook_slow ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *ipv4 in chain: OUTPUT*
[4912183.233537] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *iptables table:, chain:OUTPUT*
[4912183.233538] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *iptables table:, chain:OUTPUT*
[4912183.233541] [ip_output ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233542] [nf_hook_slow ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *ipv4 in chain: POST_ROUTING*
[4912183.233543] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *iptables table:, chain:POSTROU*
[4912183.233546] [ip_finish_output ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233549] [ip_finish_output2 ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233552] [__dev_queue_xmit ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233555] [dev_hard_start_xmit ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *skb is successfully sent to the NIC driver*
[4912183.233557] [skb_clone ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233561] [tpacket_rcv ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA
[4912183.233565] [consume_skb ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *packet is freed (normally)*
[4912183.233581] [consume_skb ] TCP: 172.26.137.130:8000 -> 172.26.137.131:54321 seq:1579697129, ack:2754757913, flags:SA *packet is freed (normally)*

***************** c22c8000,c22c8c00 ***************//客户端发送的 RST 比 ack 先到
[4912183.252733] [napi_gro_receive_entry] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252741] [dev_gro_receive ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252743] [__netif_receive_skb_core] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252745] [tpacket_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252749] [ip_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252750] [ip_rcv_core ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252752] [skb_clone ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252757] [nf_hook_slow ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *ipv4 in chain: PRE_ROUTING*
[4912183.252759] [nft_do_chain ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *iptables table:, chain:PREROUT*
[4912183.252761] [ip_rcv_finish ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252765] [ip_route_input_slow ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252771] [fib_validate_source ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252773] [ip_local_deliver ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252775] [nf_hook_slow ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *ipv4 in chain: INPUT*
[4912183.252777] [nft_do_chain ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *iptables table:, chain:INPUT*
[4912183.252779] [nft_do_chain ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *iptables table:, chain:INPUT*
[4912183.252782] [ip_local_deliver_finish] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252783] [tcp_v4_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252789] [kfree_skb ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *tcp_v4_rcv+0x65* *packet is dropped by kernel* //被 drop 了
[4912183.252792] [packet_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R
[4912183.252794] [consume_skb ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:R *packet is freed (normally)*

***************** c22c8900,c22c8200 ***************
[4912183.273690] [napi_gro_receive_entry] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273697] [dev_gro_receive ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273700] [__netif_receive_skb_core] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273701] [tpacket_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273705] [ip_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273707] [ip_rcv_core ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273708] [skb_clone ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273711] [nf_hook_slow ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *ipv4 in chain: PRE_ROUTING*
[4912183.273714] [nft_do_chain ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *iptables table:, chain:PREROUT*
[4912183.273716] [ip_rcv_finish ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273719] [ip_route_input_slow ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273724] [fib_validate_source ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273726] [ip_local_deliver ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273728] [nf_hook_slow ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *ipv4 in chain: INPUT*
[4912183.273733] [nft_do_chain ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *iptables table:, chain:INPUT*
[4912183.273735] [nft_do_chain ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *iptables table:, chain:INPUT*
[4912183.273737] [ip_local_deliver_finish] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273738] [tcp_v4_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273742] [__inet_lookup_listener] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273744] [tcp_filter ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273746] [tcp_v4_do_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273750] [tcp_rcv_state_process] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *TCP socket state has changed*
[4912183.273754] [tcp_v4_send_reset ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273798] [kfree_skb ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *tcp_v4_do_rcv+0x6c* *packet is dropped by kernel*
[4912183.273801] [packet_rcv ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A
[4912183.273803] [consume_skb ] TCP: 172.26.137.131:54321 -> 172.26.137.130:8000 seq:2754757913, ack:1579697130, flags:A *packet is freed (normally)*

场景 3:正常 2 次握手,然后立即发送 RST(不带 timestamp)

可以看到 RST 被 drop 然后 握手失败

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
***************** c22c8900,c22c8f00 ***************
[4912185.612533] [__ip_local_out ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612535] [nf_hook_slow ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *ipv4 in chain: OUTPUT*
[4912185.612536] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *iptables table:, chain:OUTPUT*
[4912185.612538] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *iptables table:, chain:OUTPUT*
[4912185.612539] [ip_output ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612541] [nf_hook_slow ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *ipv4 in chain: POST_ROUTING*
[4912185.612542] [nft_do_chain ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *iptables table:, chain:POSTROU*
[4912185.612544] [ip_finish_output ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612546] [ip_finish_output2 ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612547] [__dev_queue_xmit ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612550] [dev_hard_start_xmit ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *skb is successfully sent to the NIC driver*
[4912185.612552] [skb_clone ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612555] [tpacket_rcv ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA
[4912185.612558] [consume_skb ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *packet is freed (normally)*
[4912185.612573] [consume_skb ] TCP: 172.26.137.130:8000 -> 172.26.137.131:12345 seq:1983242893, ack:54243195, flags:SA *packet is freed (normally)*

***************** c22c8f00,c22c8800 ***************
[4912185.631719] [napi_gro_receive_entry] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631726] [dev_gro_receive ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631728] [__netif_receive_skb_core] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631730] [tpacket_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631734] [ip_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631736] [ip_rcv_core ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631737] [skb_clone ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631744] [nf_hook_slow ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *ipv4 in chain: PRE_ROUTING*
[4912185.631746] [nft_do_chain ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *iptables table:, chain:PREROUT*
[4912185.631748] [ip_rcv_finish ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631754] [ip_route_input_slow ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631759] [fib_validate_source ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631762] [ip_local_deliver ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631763] [nf_hook_slow ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *ipv4 in chain: INPUT*
[4912185.631765] [nft_do_chain ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *iptables table:, chain:INPUT*
[4912185.631767] [nft_do_chain ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *iptables table:, chain:INPUT*
[4912185.631770] [ip_local_deliver_finish] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631772] [tcp_v4_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631777] [kfree_skb ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *tcp_v4_rcv+0x65* *packet is dropped by kernel*
[4912185.631780] [packet_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R
[4912185.631783] [consume_skb ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:R *packet is freed (normally)*

***************** c22c8600,c22c8100 ***************
[4912185.648623] [napi_gro_receive_entry] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648630] [dev_gro_receive ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648632] [__netif_receive_skb_core] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648633] [tpacket_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648637] [ip_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648639] [ip_rcv_core ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648640] [skb_clone ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648643] [nf_hook_slow ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *ipv4 in chain: PRE_ROUTING*
[4912185.648645] [nft_do_chain ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *iptables table:, chain:PREROUT*
[4912185.648647] [ip_rcv_finish ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648650] [ip_route_input_slow ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648656] [fib_validate_source ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648659] [ip_local_deliver ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648660] [nf_hook_slow ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *ipv4 in chain: INPUT*
[4912185.648662] [nft_do_chain ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *iptables table:, chain:INPUT*
[4912185.648664] [nft_do_chain ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *iptables table:, chain:INPUT*
[4912185.648667] [ip_local_deliver_finish] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648672] [tcp_v4_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648677] [__inet_lookup_listener] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648679] [tcp_filter ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648681] [tcp_v4_do_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648685] [tcp_rcv_state_process] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *TCP socket state has changed*
[4912185.648689] [tcp_v4_send_reset ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648739] [kfree_skb ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *tcp_v4_do_rcv+0x6c* *packet is dropped by kernel*
[4912185.648741] [packet_rcv ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A
[4912185.648743] [consume_skb ] TCP: 172.26.137.131:12345 -> 172.26.137.130:8000 seq:54243195, ack:1983242894, flags:A *packet is freed (normally)*

上面三个场景都没能重现问题,所以继续构造场景 4

场景 4 timestamp 不递增

保证 tcp options 里面有 timestamp,且不递增,这时终于重现了连接残留:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
//这表示有 tcp 连接残留在 8000 端口上,而实际上期望连接要因为有 RST 而被释放
#netstat -ant |grep 8000
tcp 4 0 0.0.0.0:8000 0.0.0.0:* LISTEN
tcp 0 0 172.26.137.130:8000 172.26.137.131:19723 ESTABLISHED


//此时对应的抓包,注意这里 Server 端也没有回复 RST,前面 3 个场景 Server 端 8000 都会回 RST,从而不会残留
//连接残留:ts 为 0,RST 被忽略,导致连接残留
16:09:55.669693 IP 172.26.137.131.19723 > 172.26.137.130.8000: Flags [S], seq 12345, win 8192, options [TS val 1732608595 ecr 0,eol], length 0
16:09:55.669708 IP 172.26.137.130.8000 > 172.26.137.131.19723: Flags [S.], seq 3736478060, ack 12346, win 65160, options [mss 1460,nop,nop,TS val 2982589154 ecr 1732608595], length 0
16:09:55.687943 IP 172.26.137.131.19723 > 172.26.137.130.8000: Flags [R], seq 12346, win 8192, options [TS val 0 ecr 2982589154,eol], length 0
16:09:55.703896 IP 172.26.137.131.19723 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [TS val 1732608595 ecr 0,eol], length 0

//连接残留:ts 没递增,RST 被忽略,导致连接残留
17:18:26.739344 IP 172.26.137.131.59541 > 172.26.137.130.8000: Flags [S], seq 12345, win 8192, options [TS val 1732612706 ecr 0,eol], length 0
17:18:26.739358 IP 172.26.137.130.8000 > 172.26.137.131.59541: Flags [S.], seq 3510510105, ack 12346, win 65160, options [mss 1460,nop,nop,TS val 2986700224 ecr 1732612706], length 0
17:18:26.756574 IP 172.26.137.131.59541 > 172.26.137.130.8000: Flags [R], seq 12346, win 8192, options [mss 1460,TS val 1732611916 ecr 0,eol], length 0
17:18:26.870569 IP 172.26.137.131.59541 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [TS val 1732612706 ecr 0,eol], length 0

不会导致连接残留的情况:

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
28
//连接不残留, ts 递增
16:24:33.516952 IP 172.26.137.131.19544 > 172.26.137.130.8000: Flags [S], seq 12345, win 8192, options [TS val 1732609473 ecr 0,eol], length 0
16:24:33.516967 IP 172.26.137.130.8000 > 172.26.137.131.19544: Flags [S.], seq 1834771950, ack 12346, win 65160, options [mss 1460,nop,nop,TS val 2983467001 ecr 1732609473], length 0
16:24:33.539178 IP 172.26.137.131.19544 > 172.26.137.130.8000: Flags [R], seq 12346, win 8192, options [TS val 1732609473 ecr 0,eol], length 0
16:24:33.556153 IP 172.26.137.131.19544 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [TS val 1732609473 ecr 0,eol], length 0
16:24:33.556164 IP 172.26.137.130.8000 > 172.26.137.131.19544: Flags [R], seq 1834771951, win 0, length 0

//连接不残留, 有 options 但是没有 ts
17:05:16.217333 IP 172.26.137.131.22567 > 172.26.137.130.8000: Flags [S], seq 12345, win 8192, options [TS val 1732611916 ecr 0,eol], length 0
17:05:16.217351 IP 172.26.137.130.8000 > 172.26.137.131.22567: Flags [S.], seq 3503286934, ack 12346, win 65160, options [mss 1460,nop,nop,TS val 2985909702 ecr 1732611916], length 0
17:05:16.229589 IP 172.26.137.131.22567 > 172.26.137.130.8000: Flags [R], seq 12346, win 8192, options [mss 1460], length 0
17:05:16.346564 IP 172.26.137.131.22567 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [TS val 1732611916 ecr 0,eol], length 0
17:05:16.346578 IP 172.26.137.130.8000 > 172.26.137.131.22567: Flags [R], seq 3503286935, win 0, length 0

//连接不残留,options 为 null
16:29:38.618811 IP 172.26.137.131.33190 > 172.26.137.130.8000: Flags [S], seq 12345, win 8192, options [TS val 1732609778 ecr 0,eol], length 0
16:29:38.618824 IP 172.26.137.130.8000 > 172.26.137.131.33190: Flags [S.], seq 1867663284, ack 12346, win 65160, options [mss 1460,nop,nop,TS val 2983772103 ecr 1732609778], length 0
16:29:38.647039 IP 172.26.137.131.33190 > 172.26.137.130.8000: Flags [R], seq 12346, win 8192, length 0
16:29:38.670061 IP 172.26.137.131.33190 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [TS val 1732609778 ecr 0,eol], length 0
16:29:38.670073 IP 172.26.137.130.8000 > 172.26.137.131.33190: Flags [R], seq 1867663285, win 0, length 0

//连接不残留, 有 options ,但 ts 为 nop
17:37:37.476343 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [S], seq 2331525453, win 8192, options [mss 1460,nop,nop,TS val 1732613857 ecr 0], length 0
17:37:37.476460 IP 172.26.137.130.8000 > 172.26.137.131.12345: Flags [S.], seq 230155727, ack 2331525454, win 65160, options [mss 1460,nop,nop,TS val 2987850961 ecr 1732613857], length 0
17:37:37.494579 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [R], seq 2331525454, win 8192, options [nop,nop,eol], length 0
17:37:37.511431 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [nop,nop,TS val 1732613857 ecr 0], length 0
17:37:37.511546 IP 172.26.137.130.8000 > 172.26.137.131.12345: Flags [R], seq 230155728, win 0, length 0
17:37:37.526369 IP 172.26.137.131.12345 > 172.26.137.130.8000: Flags [R], seq 2331525454, win 8192, length 0

结论

最终重现的必要条件:内核在三次握手阶段(TCP_NEW_SYN_RECV),收到的RST 包里有 timestamp 且不递增 就会丢弃 RST

注意:

  • 如果 RST 的 seq 不递增也会导致连接残留,这属于 seq 回绕了 // /proc/net/netstat 中没找到 有哪个指标对应的监控
  • 要区分 timestamp 没有和 timestamp 为 0 的情况,为 0 表示有,大概率回绕了//场景 1-3 都忽略了这个问题
  • options=[(‘NOP’, None), (‘NOP’, None)]) 表示没有 timestamp,也不能重现问题
  • 以上案例 2/3/4 场景下 nettrace 看到的 RST 都被 drop 了,但是不妨碍连接的释放 //这个还需要分析为什么连接 RST 起作用了但是还是会 drop RST 包
  • 如果出现连接残留,也会导致全连接队列增大直到溢出
  • 三次握手成功后的通信阶段(established),此时只校验 RST 的 seq 有没有回绕,不校验 timestamp,这样连接能正确释放
1
2
3
4
5
6
//三次握手成功,如果 RST 带的 timestamp 不递增也会正确触发释放连接,也就是 ESTABLISHED  时只校验 RST 的 seq 有没有回绕,不校验 timestamp
//如下抓包的连接被正确释放了,所以 LVS 会用这个逻辑来释放连接,但是一旦乱序就嗝屁了
12:19:58.588218 IP 172.26.137.131.1406 > 172.26.137.130.8000: Flags [S], seq 2800159571, win 8192, options [mss 1460,nop,nop,TS val 1732681198 ecr 0], length 0
12:19:58.588233 IP 172.26.137.130.8000 > 172.26.137.131.1406: Flags [S.], seq 3011503126, ack 2800159572, win 65160, options [mss 1460,nop,nop,TS val 3055192072 ecr 1732681198], length 0
12:19:58.606594 IP 172.26.137.131.1406 > 172.26.137.130.8000: Flags [.], ack 1, win 8192, options [nop,nop,TS val 1732681198 ecr 0], length 0
12:19:58.624392 IP 172.26.137.131.1406 > 172.26.137.130.8000: Flags [R], seq 2800159572, win 8192, options [nop,nop,TS val 0 ecr 0], length 0

对应的内核 commit

Server 在握手的第三阶段(TCP_NEW_SYN_RECV),等待对端进行握手的第三步回 ACK时候,如果收到RST 内核会对报文进行PAWS校验,如果 RST 带的 timestamp(TVal) 不递增就会因为通不过 PAWS 校验而被扔掉

问题引入:https://github.com/torvalds/linux/commit/7faee5c0d514162853a343d93e4a0b6bb8bfec21 这个 commit 去掉了TCP_SKB_CB(skb)->when = tcp_time_stamp,导致 3.18 的内核版本linger close主动发送的 RST 中 ts_val为0

问题修复:修复的commit在 675ee231d960af2af3606b4480324e26797eb010,直到 4.10 才合并进内核

监控

对应这种握手阶段连接建立如何监控呢?

从内核代码 net/ipv4/tcp_minisocks.c/tcp_check_req 函数会对报文调用 tcp_paws_reject 函数进行 paws_reject 检测,tcp_paws_reject 如果返回值为true,则 tcp_check_req 返回NULL,并且记录 LINUX_MIB_PAWSESTABREJECTED 计数

可以观察 /proc/net/netstat 中的监控指标:PAWSEstab

1
2
3
4
5
//内核中的指标
SNMP_MIB_ITEM("PAWSEstab", LINUX_MIB_PAWSESTABREJECTED)

//尝试了 5 次 RST的 timestamp 不递增导致的残留,监控到这个值每次变化累加 1
TcpExt:PAWSEstab 1 -> 1 -> 1 -> 1 -> 1

虽然三次握手没有完成,但是在服务端连接已经是 ESTABLISHED,所以这里的统计指标还是 PAWSEstab,可以通过 netstat -s 来查看:

1
2
#netstat -s |grep -E -i "timestamp|paws"
71 packets rejected in established connections because of timestamp //无论是三次握手阶段的 RST 还是握手成功后的请求只要 timestamp 不递增就会 drop

这个指标对应在 netstat 源码(net-tools) 中的解释:

1
2
{"PAWSEstab", N_("%llu packets rejected in established connections because of timestamp"), opt_number},
{"PAWSPassive", N_("%llu passive connections rejected because of time stamp"), opt_number},

总结

星球里之前也写过 scapy 的入门以及使用案例: scapy 重现网络问题真香

就像学英语的时候要精读,分析 case 也需要深挖,可以挖上一到两周,不要每天假学习(似乎啥都看了,当时啥都懂,过几个月啥都不懂)

掌握技能比掌握知识点和问题的原因更重要

nettrace 也真的很好用/很好玩,可以帮你学到很多内核知识

参考资料

https://cloud.tencent.com/developer/article/2210423

为什么你的 SYN 包被丢 net.ipv4.tcp_tw_recycle

从一个fin 卡顿问题到 scapy 的使用

tcp会偶尔3秒timeout的分析以及如何用php规避这个问题

这是一篇好文章,随着蘑菇街的完蛋,蘑菇街技术博客也没了,所以特意备份一下这篇

  • 作者:蚩尤

  • 时间:May 27, 2014

2年前做一个cache中间件调用的时候,发现很多通过php的curl调用一个的服务会出现偶尔的connect_time超时, 表现为get_curlinfo的connect_time在3秒左右, 本来没怎么注意, 因为客户端的curl_timeout设置的就是3秒, 某天, 我把这个timeout改到了5秒后, 发现了一个奇怪的现象, 很多慢请求依旧表现为connect_time在3秒左右..看来这个3秒并不是因为客户端设置的timeout引起的.于是开始查找这个原因.


首先, 凭借经验调整了linux内核关于tcp的几个参数

1
2
net.core.netdev_max_backlog = 862144
net.core.somaxconn = 262144

经过观察发现依旧会有3秒超时, 而且数量并没有减少.

第二步, 排除是大并发导致的问题, 在一台空闲机器上也部署同样的服务, 仅让线上一台机器跑空闲机器的服务, 结果发现依旧会有报错.排除并发导致的问题.

最后, 通过查了大量的资料才发现并不是我们才遇到过这个问题, 而且这个问题并不是curl的问题, 它影响到所有tcp的调用, 网上各种说法, 但结论都指向linux内核对于tcp的实现.(某些版本会出现这些问题), 有兴趣的可以看下下面这两个资料.
资料1
资料2

一看深入到linux内核..不管怎样修改的成本一定很大..于是乎, 发挥我们手中的php来规避这个问题的时间到了.

原本的代码, 简单实现,常规curl调用:

1
2
3
4
5
6
7
8
9
10
function curl_call($p1, $p2 ...) {
$ch = curl_init();
curl_setopt($ch, CURLOPT_TIMEOUT, 5);
curl_setopt($ch, CURLOPT_URL, 'http://demon.at');
$res = curl_exec($ch);
if (false === $res) {
//失败..抛异常..
}
return $res;
}

可以看出, 如果用上面的代码, 无法避免3秒connect_time的问题..这种实现对curl版本会有要求(CURLOPT_CONNECTTIMEOUT_MS),主要的思路是,通过对链接时间进行毫秒级的控制(因为超时往往发生在connect的时候),加上失败重试机制,来最大限度保证调用的正确性。所以,下面的代码就诞生了:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
function curl_call($p1, $p2, $times = 1) {
$ch = curl_init();
curl_setopt($ch, CURLOPT_TIMEOUT, 5);
curl_setopt($ch, CURLOPT_URL, 'http://demon.at');
$curl_version = curl_version();
if ($curl_version['version_number'] >= 462850) {
curl_setopt($ch, CURLOPT_CONNECTTIMEOUT_MS, 20);
curl_setopt($ch, CURLOPT_NOSIGNAL, 1);
} else {
throw new Exception('this curl version is too low, version_num : '
. $curl_version['version']);
}
$res = curl_exec($ch);
curl_close($ch);
if (false === $res) {
if (curl_errno($ch) == CURLE_OPERATION_TIMEOUTED
and $times != 最大重试阀值 ) {
$times += 1;
return curl_call($p1, $p2, $times);
}
}

return $res;
}

上面这段代码只是一个规避的简单实例, 一些小细节并没有可以完善..比如抛出异常常以后curl资源的手动释放等等..这里不做讨论..当然还漏了一点要说的是,对重试次数最好加上限制 :)

说明一下上面几个数字值的含义:

1
2
462850 //因为php的CURLOPT_CONNECTTIMEOUT_MS需要 curl_version 7.16.2,这个值就是这个版本的数字版本号,还需要注意的是, php版本要大于5.2.3
20 //连接超时的时间, 单位:ms

这样这个问题就这样通过php的代码来规避开了.
如果有对这个问题有更好的解决方法,欢迎指教.


总结

tcp connect 的流程是这样的
1、tcp发出SYN建链报文后,报文到ip层需要进行路由查询
2、路由查询完成后,报文到arp层查询下一跳mac地址
3、如果本地没有对应网关的arp缓存,就需要缓存住这个报文,发起arp请求
4、arp层收到arp回应报文之后,从缓存中取出SYN报文,完成mac头填写并发送给驱动。

问题在于,arp层缓存队列长度默认为3。如果你运气不好,刚好赶上缓存已满,这个报文就会被丢弃。

TCP层发现SYN报文发出去3s(默认值)还没有回应,就会重发一个SYN。这就是为什么少数连接会3s后才能建链。

幸运的是,arp层缓存队列长度是可配置的,用 sysctl -a | grep unres_qlen 就能看到,默认值为3。

tcpdump 抓包卡顿分析

背景

从 192.168.104.1 上执行 ping 192.168.104.4 -c 1 ping 命令很快通了, 同时在ubuntu 机(192.168.104.4) 上抓包

在192.168.104.4 上的 tcpdump 要卡很久(几十秒)后才输出几十秒前抓到的包 :(,最一开始以为是自己通过 lima 虚拟化的 ubuntu 机器慢 or tcpdump 初始化慢导致的,但是发现等了几十秒后能看到几十秒前抓到的包,感觉有点诡异,所以分析了一下原因。

既然几十秒后能看到几十秒前的包,说明抓包正常,只是哪里卡了,所以用 strace 看看卡在了哪里。

下文用到的主要的 Debug 命令:

1
2
3
//-r 打印相对时间
//-s 256 表示--string-limit,设置 limit 为 256,可以显示 sendto(下图黄底) 系统调用完整的 DNS 查询字符串(下图绿线)
strace -r -s 256 tcpdump -i eth0 icmp

分析步骤如下:

步骤 1

如下图是 strace -r -s 256 tcpdump -i eth0 icmp 命令的输出 ,发现抓到包后对 IP 192.168.104.4 去做了 DNS 解析,而这个解析发给 127.0.0.53 后长时间没有响应,5 秒超时后并重试(下图红框),导致多次 5 秒超时卡顿:

image-20241008144023596

于是在 /etc/hosts 添加 192.168.104.4 localhost 后不再对 192.168.104.4 进行解析,但是仍然会对对端的 IP 192.168.104.1 进行解析:

image-20241008144145663

上图说明:

  • 上图最后一个绿线表示 tcpdump 抓到了 ping 包(ICMP 协议包)
  • \0011\003104\003168\003192 表示:192.168.104.1 ,\0011 前面的 \001 表示 1 位,1 表示 ip 地址值的最后一个 //把整个双引号内容丢给 GPT 会给你一个很好的解释

步骤 2

从上面两个图中的 connect 内核函数可以看到每次都把 ip 丢给了 127.0.0.53 这个特殊 IP 来解析,下面是 GPT 给出的解释,我试了下将 DNSStubListener=no(修改配置文件:/etc/systemd/resolved.conf 后执行 systemctl restart systemd-resolved) 后 tcpdump 完全不卡了:

systemd-resolved:

  1. systemd-resolved 是一个系统服务,负责为本地应用程序提供网络名称解析。
  2. 它作为一个本地 DNS 解析器和缓存,可以提高 DNS 查询的效率。
  3. systemd-resolved 支持多种 DNS 协议,如 DNSSEC、DNS over TLS 等。
  4. 它可以管理多个网络接口的 DNS 设置,适合复杂的网络环境。

DNSStubListener 参数:

  1. DNSStubListener 是 systemd-resolved 的一个功能,默认情况下是启用的(yes)。
  2. 当启用时,systemd-resolved 会在本地 127.0.0.53 地址上运行一个 DNS 存根监听器。
  3. 这个存根监听器会接收本地应用程序的 DNS 查询请求,然后转发给实际的 DNS 服务器。
  4. 当设置 DNSStubListener=no 时:
    • 存根监听器被禁用。
    • 本地应用程序的 DNS 查询将直接发送到配置的 DNS 服务器,而不经过 systemd-resolved

现在 tcpdump 虽然不卡了,但是抓包的时候通过 strace 看到还是会走 DNS 解析流程,这个时候的 DNS 解析都发给了 192.168.104.2:53 (配置在 /etc/resolv.conf 中),也就是 systemd-resolved 的 127.0.0.53:53 udp 端口虽然在监听,但是不响应任何查询导致了超时,而 192.168.104.2:53 服务正常

这个时候的 strace 日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
     0.000308 socket(AF_INET, SOCK_DGRAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_IP) = 5 //SOCK_DGRAM UDP 模式
0.000134 setsockopt(5, SOL_IP, IP_RECVERR, [1], 4) = 0
0.000414 connect(5, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.104.2")}, 16) = 0 //目标主机 192.168.104.2
0.000373 ppoll([{fd=5, events=POLLOUT}], 1, {tv_sec=0, tv_nsec=0}, NULL, 0) = 1 ([{fd=5, revents=POLLOUT}], left {tv_sec=0, tv_nsec=0})
0.000348 sendto(5, "e\323\1\0\0\1\0\0\0\0\0\0\0014\003104\003168\003192\7in-addr\4arpa\0\0\f\0\1", 44, MSG_NOSIGNAL, NULL, 0) = 44 //发送 DNS 查询,这里可能会超时等待
0.000610 ppoll([{fd=5, events=POLLIN}], 1, {tv_sec=5, tv_nsec=0}, NULL, 0) = 1 ([{fd=5, revents=POLLIN}], left {tv_sec=4, tv_nsec=999999042})
0.000203 ioctl(5, FIONREAD, [44]) = 0
//这次 0.000136 秒后收到了响应
0.000136 recvfrom(5, "e\323\201\200\0\1\0\0\0\0\0\0\0014\003104\003168\003192\7in-addr\4arpa\0\0\f\0\1", 1024, 0, {sa_family=AF_INET, sin_port=htons(53), sin_addr=inet_addr("192.168.104.2")}, [28 => 16]) = 44
0.000462 close(5) = 0
0.000249 write(1, "17:01:20.316738 IP 192.168.104.1 > 192.168.104.4: ICMP echo request, id 31, seq 1, length 64\n", 9317:01:20.316738 IP 192.168.104.1 > 192.168.104.4: ICMP echo request, id 31, seq 1, length 64
) = 93
0.000306 newfstatat(AT_FDCWD, "/etc/localtime", {st_mode=S_IFREG|0644, st_size=561, ...}, 0) = 0
0.000269 write(1, "17:01:20.316795 IP 192.168.104.4 > 192.168.104.1: ICMP echo reply, id 31, seq 1, length 64\n", 9117:01:20.316795 IP 192.168.104.4 > 192.168.104.1: ICMP echo reply, id 31, seq 1, length 64

步骤 3

到这里大概理解这是 tcpdump 引入的 DNS 反查,看了下 tcpdump 帮助完全可以用 -n 参数彻底关闭 DNS 反查 IP:

tcpdump 命令可以关闭 DNS 反查功能。要禁用 DNS 反查,你可以使用 -n 选项;// 我用 tcpdump -n 这么久真没留意这个 -n 具体干啥的,每次都是条件反射写上去的 :(

小结

其实很多应用中会偶尔卡顿,网络操作超时就是典型的导致这种卡顿的原因,从 CPU 资源使用率上还发现不了。比如日常 ssh 连服务器有时候就会卡 30 秒

关于 GSSAPIAuthentication 解释如下,一看也是需要走网络进行授权认证,如果没有配置 kerberos 服务就会卡在网络等待上:

[!TIP]

SSH 中的 GSSAPIAuthentication(Generic Security Services Application Program Interface Authentication)是一种身份验证机制,主要用于实现单点登录(Single Sign-On, SSO)功能。它允许用户在已经通过 Kerberos 认证的环境中,无需再次输入密码就可以登录到支持 GSSAPI 的 SSH 服务器。

类似的网络卡顿/DNS 解析卡顿是很常见的,大家掌握好 Debug 手段。

实际生产中可能没这么好重现也不太好分析,比如我就碰到过 Java 程序都卡在 DNS 解析的问题,Java 中这个 DNS 解析是串行的,所以一般可以通过 jstack 看看堆栈,多个锁窜行等待肯定不正常;多次抓到 DNS 解析肯定也不正常

比如下面这个 jstack 堆栈正常是不应该出现的,如果频繁出现就说明在走 DNS 查机器名啥的

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
"Diagnose@diagnose-2-61" #616 daemon prio=5 os_prio=0 tid=0x00007f7668ba6000 nid=0x2fc runnable [0x00007f75dbea8000]
java.lang.Thread.State: RUNNABLE
at java.net.Inet4AddressImpl.lookupAllHostAddr(Native Method)
at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:870)
at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1312)
at java.net.InetAddress$NameServiceAddresses.get(InetAddress.java:818)
- locked <0x0000000500340c10> (a java.net.InetAddress$NameServiceAddresses)
at java.net.InetAddress.getAllByName0(InetAddress.java:1301)
at java.net.InetAddress.getAllByName0(InetAddress.java:1221)
at java.net.InetAddress.getHostFromNameService(InetAddress.java:640)
at java.net.InetAddress.getHostName(InetAddress.java:565)
at java.net.InetAddress.getHostName(InetAddress.java:537)
at java.net.InetSocketAddress$InetSocketAddressHolder.getHostName(InetSocketAddress.java:82)
at java.net.InetSocketAddress$InetSocketAddressHolder.access$600(InetSocketAddress.java:56)
at java.net.InetSocketAddress.getHostName(InetSocketAddress.java:345)
at io.grpc.internal.ProxyDetectorImpl.detectProxy(ProxyDetectorImpl.java:127)
at io.grpc.internal.ProxyDetectorImpl.proxyFor(ProxyDetectorImpl.java:118)
at io.grpc.internal.InternalSubchannel.startNewTransport(InternalSubchannel.java:207)
at io.grpc.internal.InternalSubchannel.obtainActiveTransport(InternalSubchannel.java:188)
- locked <0x0000000500344d38> (a java.lang.Object)
at io.grpc.internal.ManagedChannelImpl$SubchannelImpl.requestConnection(ManagedChannelImpl.java:1130)
at io.grpc.PickFirstBalancerFactory$PickFirstBalancer.handleResolvedAddressGroups(PickFirstBalancerFactory.java:79)
at io.grpc.internal.ManagedChannelImpl$NameResolverListenerImpl$1NamesResolved.run(ManagedChannelImpl.java:1032)
at io.grpc.internal.ChannelExecutor.drain(ChannelExecutor.java:73)
at io.grpc.internal.ManagedChannelImpl$4.get(ManagedChannelImpl.java:403)
at io.grpc.internal.ClientCallImpl.start(ClientCallImpl.java:238)

"Check@diagnose-1-107" #849 daemon prio=5 os_prio=0 tid=0x00007f600ee44200 nid=0x3e5 runnable [0x00007f5f12545000]
java.lang.Thread.State: RUNNABLE
at java.net.Inet4AddressImpl.lookupAllHostAddr(Native Method)
at java.net.InetAddress$2.lookupAllHostAddr(InetAddress.java:870)
at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1312)
at java.net.InetAddress$NameServiceAddresses.get(InetAddress.java:818)
- locked <0x000000063ee00098> (a java.net.InetAddress$NameServiceAddresses)
at java.net.InetAddress.getAllByName0(InetAddress.java:1301)
at java.net.InetAddress.getAllByName(InetAddress.java:1154)
at java.net.InetAddress.getAllByName(InetAddress.java:1075)
at java.net.InetAddress.getByName(InetAddress.java:1025)
at *.*.*.*.*.check.Utils.isIPv6(Utils.java:59)
at *.*.*.*.*.check.checker.AbstractCustinsChecker.getVipCheckPoint(AbstractCustinsChecker.java:189)
at *.*.*.*.*.*.*.MySQLCustinsChecker.getVipCheckPoint(MySQLCustinsChecker.java:160)
at *.*.*.*.*.*.*.MySQLCustinsChecker.getCheckPoints(MySQLCustinsChecker.java:133)
at *.*.*.*.*.check.checker.AbstractCustinsChecker.checkNormal(AbstractCustinsChecker.java:314)
at *.*.*.*.*.check.checker.CheckExecutorImpl.check(CheckExecutorImpl.java:186)
at *.*.*.*.*.check.checker.CheckExecutorImpl.lambda$0(CheckExecutorImpl.java:118)
at *.*.*.*.*.check.checker.CheckExecutorImpl$$Lambda$302/130696248.call(Unknown Source)
at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)
at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)
at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:879)

这里以后可以加更多的 DNS 解析卡顿/网络卡顿导致的问题案例……

教科书级的根因推导——必做题

问题描述

A服务访问 B 服务,突然在某个时间点有个访问毛刺,RT 从50 ms飙到了80 ms,如下图

image-20240607210416189

这个时候发现网络连接数也从10000 涨到了 11000

image-20240607210602281

当时的QPS 一直是 2万,没有任何明显变化,任何其它指标都没有变化

请回答问题

  1. 到底是 B服务慢了所以 RT 上涨,RT 上涨后触发了新建连接,还是突然大量新建导致 B服务慢了,请写出你的详细推导
  2. 你如何在A 端来验证这个问题;你又如何在 B段来证明这个问题

我的分析

首先是所有其他指标都正常,查下来看到的变化就是RT、总连接数同时抖了,所以以下分析都是基于在这个情形下,这两个指标到底谁是因、谁是果

分析的基本原则就是星球里最重要的概念:QPS、并发、RT 的关系

为什么说连接数上涨是根因?

抖动前 rt 50ms,QPS 2万,计算下来一个连接能扛的 QPS 是20( 1000ms/50ms =20 QPS 1秒等于1000ms)

1000个活跃连接就可以扛住这 2万的QPS,而总连接数在抖动前是10000,也就是连接数的水位只需要10% 就够了。按照抖动时的rt 80ms 则这10000个连接是可以扛 12.5万QPS 才会触发连接数不够创建新连接(理想值,也就是在QPS 到12.5万的80% 之前触发连接数不够的概率极小极小)

一个很关键的点:新建连接是业务端的行为,除非服务端太慢导致连接不够才会触发客户端新建,否则都是业务端的锅

几个注意的地方:

  • 另外一个注意下抖动的时候也没有触发业务端有超时报错(80ms 只是平均值),如果真有超时报错可能会丢掉老连接,创建或者取新连接重试
  • 实际上连接有总连接数、活跃连接数,总连接就是我们这里说的1万,活跃连接对应的就是 1000——也就是你随机去看业务状态,有1000个连接在忙着做业务处理/查询,还有9000个连接在睡大觉

如何验证?

  1. 让客户建1000-2000 个新连接看看——应该会触发RT 飚一下,但不一定是充分条件,实际在同一个客户的其他实例上也有抖动的场景里没有触发新建连接——相当于间接验证
  2. 或者让客户在他们的网卡上加 30ms模拟抖动从50ms加到80ms,看会不会触发新建几百个连接,如果没有触发新建说明RT 这个幅度的上涨不会触发新建连接

不知道我解释清楚了没有

为什么你的连接不均衡了?

场景

假如你有两个Redis 服务,挂载在一个LVS 下,然后客户端使用的Jedis,Jedis 配置的最大连接池是200个连接,最小是100个(也就是超过100个,当闲置一段时间后就释放掉)。然后过一阵假设来了一个访问高峰,把连接数打到200,过一会高峰过去连接就会释放到100,客户端每次取连接然后随便 get 以下就归还连接

场景构造小提示

  1. 用Jedis;
  2. 构造流量一波一波,就是有流量高峰(触发新建连接)、有流量低峰(触发连接释放),如此反复
  3. 不需要太大流量把Redis 节点打到出现瓶颈

如下图:

image-20240618202012463

期待场景:在这个过程中,Jedis 每次取一个连接随便get 一个key 就行了,无论怎么折腾两个Redis Service 的连接数基本是均衡的,实际也确实是这样

比如可以这样设置Jedis 参数(你也可以随便改),也可以用你们生产环境

1
2
3
4
5
6
7
8
9
JedisPoolConfig config = new JedisPoolConfig();
config.setMaxIdle(100);
config.setMaxTotal(200);
config.setMinEvictableIdleTimeMillis(3000);
config.setTimeBetweenEvictionRunsMillis(1000);
config.setTestOnBorrow(false);
config.setTestOnReturn(false);
config.setTestWhileIdle(false);
config.setTestOnCreate(false);

验证代码

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
import com.taobao.eagleeye.redis.clients.jedis.Jedis;
import com.taobao.eagleeye.redis.clients.jedis.JedisPool;
import com.taobao.eagleeye.redis.clients.jedis.JedisPoolConfig;

public class JedisPoolTest {
// 初始化连接超时时间
private static final int DEFAULT_CONNECTION_TIMEOUT = 5000;
// 查询超时时间
private static final int DEFAULT_SO_TIMEOUT = 2000;
private static final JedisPoolConfig config = new JedisPoolConfig();
private static JedisPool jedisPool = null;

public static void main(String args[]) {
// 代理连接地址,用控制台上的"代理地址"。
String host = "redis";
int port = 6379;
//String password = "1234";

// 设置参考上面
config.setMaxTotal(xx);
config.setMaxIdle(xx);
config.setMinIdle(xx);


// 只需要初始化一次
try {
jedisPool = new JedisPool(config, host, port,
DEFAULT_CONNECTION_TIMEOUT, DEFAULT_SO_TIMEOUT, password, 0, null);
try (Jedis jedis = jedisPool.getResource()) {
if (!"PONG".equals(jedis.ping())) {
throw new RuntimeException("Init Failed");
}
}
} catch (Exception e) {
// 如果有exception,说明初始化失败。
e.printStackTrace();
}

// 每次 API 查询都像下面这么写
Jedis jedis = null;
try {
jedis = jedisPool.getResource(); // 查询前获取一个连接
String ret = jedis.set("key", "value");
if ("OK".equals(ret)) {
System.out.println(ret);
// SET success
}
} catch (Exception e) {
e.printStackTrace();
// 连接错误,超时等情况
} finally {
if (jedis != null) {
// 查询结束后还回连接池,不是销毁连接
// 必须尽快还回,否则会导致连接池资源不够
jedis.close();
}
}

// 只需要最后程序退出时调用一次,不需要每次查询完之后都调用
jedisPool.close();
}
}

运行如上代码,应该看到一个负载均衡正常环境——符合预期

不均衡重现

背景里描述的是完全符合预期的,假设实际使用中两个 Redis中的一个节点的CPU有一个降频了/争抢/温度高 等种种原因,导致这个节点处理更慢了

如何模拟其中一个节点突然慢了(这些手段在之前的星球案例重现里都反复使用过了)

  1. 你可以把Redis 进程绑到一个核上,然后在这这个核上跑一个死循环故意让;
  2. 或者,也可以在这个节点上给网络延迟加200ms 进去

这个时候你再重新跑背景描述里的代码,一段时间后你会看到下图中红线对应的 Redis 节点上的连接数越来越高,QPS 越来越高(别用太大的压力,导致这个节点的访问超时哈)

image-20240618203121532

到这里就算是问题重现出来了

重现确认注意:

如果只是看到瞬间连接数不均衡这应该没有重现出来,因为节点慢了所以 active 要变高才会维系住同样的QPS,这是符合预期的。

期望的是长期运行后慢的节点上统计意义上的连接数越来越多、QPS 越来越大

比如下图是重现过程中的连接数监控,可以看到橙色线对应的Redis 节点上的连接越来越多:

img

下图是对应的QPS 监控,问题Redis 节点(黄色线)的QPS 比另外一个节点大很多,长期下去会导致问题节点成为瓶颈:

img

重现脚本和代码

以下涉及的脚本、代码提交到 github,这些脚本、手段在我们之前的实验、案例都反复出现过了,我就不给了

参考星球里扒老师的操作(不含客户端Java代码):https://malleable-elbow-b9f.notion.site/redis-f7dfcecb7f7441e1ba96f4da3ca8aee8?pvs=4

星球里橘橘球用python 3.8 实现了一个python 版本的:https://github.com/gongyisheng/playground/blob/dev/network/lvs_case/readme.md

好奇同学用Java/Jedis 和Go两个版本(Go 版本是没有Jedis,也能重现问题)的实现代码:https://github.com/haoqixu/case-reproduction-240618

docker

用 docker起两个Redis 节点

1
2
//这里提供Redis docker run脚本

ipvsadm

1
//创建一个 LVS,将上面的两个Redis 加入到负载均衡里面

Java 客户端代码

完整代码应该很简单,就是一个Java + Jedis 的HelloWorld 上传到 github,别人下载代码后,自己配置一个 LVS + Redis 的负载均衡环境就能重现以上问题

tc qdisc

1
//给其中的一个 节点构造 200ms 的延时 

也可以跑死循环抢 CPU

分析

原因:Jedis 连接池使用的是 apache commons-pool 这个组件,默认从连接池取连接使用的是 LIFO(last in first out) ,如果两个节点负载正常两个节点上的连接基本能保持在队列里交叉均衡;如果连接闲置久了释放的时候就是均衡释放的

但如果有一个节点处理慢了,那么这个节点的连接被取出来使用的时候必然需要更多的时间在连接池外面处理请求,用完归还的时候就会更高概率出现在队列的顶部,导致下次首先被取出来使用,长期下去就会出现快的节点上的连接慢慢被释放,慢的节点的连接越来越多,进而慢的节点的QPS 越来越高,最后这个节点崩了

泛化问题

针对这个问题就一定是Jedis 和 Redis 才有吗?本质是我们没法期望所有节点一样快,导致连接归还一定有慢的,进而只要是取连接用 LIFO(last in first out) 就会有这个问题,Jedis/Lettuce/MySQL dbcp 都用了 apache commons-pool 这个组件来实现连接池功能,而 apache commons-pool 默认就是 LIFO ,所以这些组件全部中枪。应该是用的 LinkedBlockingDeque 队列,它有有 FIFO 和 FILO 两种策略

那么没有用 apache-commons-pools 的就安全吗?也不一定,得看取连接的逻辑,一般都是 LIFO,比如 Druid 连接池的实现用的 stack ,也就是 stack 顶部的几个连接被反复使用,可能底部连接完全用不到的情况。 且Druid 还不提供接口去设置是不是 stack/queue(LIFO/FIFO)

你们的微服务只要是用连接池大概率也会有同样的问题

那么有什么好办法来解决类似的问题吗?Druid 有个设置 phyTimeoutMillis 和 phyMaxUseCount (就是一个长连接用多久、或者执行了多少次SQL ) 来将长连接主动断开,这就有概率修复这个问题;

另外如果LVS 用的 WLC 均衡算法也可以fix 这个问题,见参考资料。

php听说有个功能,进程跑一段时间后自行销毁重建;担心内存泄漏啥的 —— 是不是很像遇到问题就重启,又不是不work,不优雅但是管用,有点像通信基站半夜重启

内核 epoll 的线程也是 FILO

参考:Why does one NGINX worker take all the load? (链接里提供完整的最简测试重现代码)

唤醒时容易最是唤醒最后几个线程(一般一个线程对应一个核),在并发压力不大时某几个线程总是被唤醒->归还->唤醒(再次取出分配执行任务)

epoll的accept模型为LIFO,倾向于唤醒最活跃的进程。多进程场景下:默认的accept是FIFO,进程加入到监听socket等待队列的尾部,唤醒时从头部开始唤醒;epoll的accept是LIFO,在epoll_wait时把进程加入到监听socket等待队列的头部,唤醒时从头部开始唤醒。

影响:当并发数较小时,只有最后几个进程会被唤醒,它们使用的CPU时间会远高于其它进程。当并发数较大时,所有的进程都有机会被唤醒,各个进程之间的差距不大。内核社区中关于epoll accept是使用LIFO还是RR有过讨论,在4.9内核和最新版本中使用的都是LIFO。

image.png

你看虽然是一次 Jedis 客户端在某些条件下导致的问题,只要你去通用化问题的本质就可以发现很容易地跳出来看到各个不同场景下同样会引起的问题,无招胜有招啊

参考资料

https://plantegg.github.io/categories/LVS/ 强调下这次的不均衡和我这个链接里的两篇文章描述的毫无关系,只是接着这个机会可以重温一下导致不均衡的其它原因,做个汇总

一次抓包分析过程——Wireshark 新手上车

问题

网友尝试做星球第一个必做实验的时候,什么内核参数都没改,发现请求经常会停滞 100ms,这种要怎么判断是局域网的网络问题还是应用问题呢? 服务是 python3 -m http.server 启动的,看上去没有出现什么重传、窗口也没看到什么问题

因为不能提供环境给我,我尝试对这个抓包进行了分析,因为只有客户端抓包,所以分析结果是没有结论的,但分析过程比较适合入门 Wireshark,适合刚加入星球的、没分析过网络包的同学可以参考,熟手请忽略

分析

整个抓包 28MB,跨度 600 毫秒,看得出带宽很大、RTT 极小(到Wireshark 里看看前几个包的交互 RT 就知道了)

image-20240715093847359

详细分析

看第一次卡 100ms 之前的抓包,在100ms 以前客户端ack 了所有Server 发出来的的tcp包(红框),也就是说每一个发给客户端的包客户端都ack 完毕,证明客户端处理足够快,但是 8089端口不继续发包而是等了100ms再继续发,如下图:

image-20240715094218182

到这里的结论:

不是因为发送buffer、接收buffer太小导致的卡;也不是因为拥塞窗口导致的,就是Server 端没有发包。大概率是Server 进程卡了,或者Server 进程读取物理文件往OS buffer 写这些环节卡了(可以在服务端通过 strace -tt 看看进程在这 100 毫秒有没有往内核怼数据)

所以要继续在 Server 端来分析这个问题

怎么快速定位到红框、红线这里的包?

到 Time Sequence 图上点平台两边的点都可以自动跳转到这里,每个点代表一个网络包,横坐标代表时间

其它分析

将如下 Time Sequence 图使劲放大,从第一个包开始看,可以观察到教科书所说的慢启动

image-20240715095134352

整体看的话,慢启动几乎可以忽略,毕竟这个抓包是下载一个巨大的文件,如果是一个小文件这个慢启动还是影响很大的,如下图,红框部分看起来微不足道

image-20240715095506381

把时间范围放大,继续看,在卡之前红色箭头很长的,代表带宽、buffer有能力一次发送很多网络包,但是后面每次只发一点点网络包(绿色箭头长度)就卡了

image-20240715095647702

重现

我用 python3 当服务端未能重现这个卡100ms 的现象,拉取都很丝滑

image-20240715101505977

非常细节地去分析的话,也是能看到一些小问题的,比如1.9ms的卡顿、比如zero_window

image-20240715103928266

重现的时候,有1.9ms 这样的卡顿,但是不算有规律,因为这么小在整个传输过程中影响不大

image-20240715103708750

我重现的时候正好抓到了 seq 回绕,seq 是个 32位的无符号整数,到了最大值就从0又开始:

image-20240715115500312

此时的 Time Sequence:

image-20240715115655516

建议

可以用实验1里面的一些手段debug 一下Server 为什么卡了,除了 strace -tt 还可以用 ebpf 试试看看 Server 的调度上哪里顿了 100ms

新手如何通过Wireshark 来看抓包?

首先不要纯粹为了学习去看,而是要问你的问题是什么?如果网络传输速度慢,我们就看 Time Sequence(斜率越陡速度越快),去看为什么发送端不发包了

  • 如正文里的卡顿平台,在250ms内差不多要卡240ms 不发包,速度自然不行
  • 我重现抓包中的zero Windows
  • 达到网络BDP 瓶颈了,去看拥塞窗口在最大值的时候会丢包,触发降速

里面可以看、要看的东西太多,所以我也说不上要看什么,而是要问你的问题是什么

一次故障的诊断过程–Sysbench

背景

我们的数据库需要做在线升级丝滑的验证,所以构造了一个测试环境,客户端Sysbench 用长连接一直打压力,Server 端的数据库做在线升级,这个在线升级会让 MySQL Server进程重启,毫无疑问连接会断开重连,所以期望升级的时候 Sysbench端 QPS 跌0几秒钟然后快速恢复

但是每次升级都是 Sysbench端 QPS 永久跌0,再也不能恢复,所以需要分析为什么,问题出在哪里?有人说是服务端的问题因为只有服务端做了变更

整个测试过程中 Sysbench 是配置的1-2个连接去压 MySQL Server

Sysbench 介绍

以下介绍来自 ChatGPT-4,用过Sysbench的同学可以跳过这节:

Sysbench 是一个适用于多个系统的多线程基准测试工具,被广泛用于评估不同系统服务的性能,包括数据库系统(如 MySQL、PostgreSQL)、文件I/O、CPU性能以及线程调度。

对于MySQL数据库,Sysbench 可以执行包括但不限于以下类型的测试:

  • OLTP (Online Transaction Processing) 测试: 这是最常见的数据库基准测试类型,模拟在线事务处理工作负载,包括事务性的Insert、Update、Delete和Select操作。
  • 点查找测试: 测试数据库针对特定索引的单行查找性能。
  • 简单写测试: 测试数据库进行插入操作的性能。
  • 复杂的选择查询测试: 运行复杂的Select查询,包含多个表和多个条件,测试数据库的读取性能。
  • 非事务性查询测试: 类似于事务查询测试,但不在事务框架内进行。

Sysbench使用Lua脚本语言进行测试案例的开发,它预置了一些标准的测试模板如oltp_read_onlyoltp_read_writeoltp_write_only等,这些可以针对数据库执行标准的过程以及自定义的工作负载。

进行Sysbench压力测试的基本步骤包括:

  1. 安装Sysbench。
  2. 准备测试数据集,这通常涉及Sysbench创建数据库及表,然后填充数据。
  3. 执行测试,Sysbench以定义的并发线程数向数据库发送请求。
  4. 收集并分析结果,例如吞吐量(每秒事务数)、延迟以及一致性。

一个简单的Sysbench测试命令可以是这样:

1
2
3
4
5
/usr/local/bin/sysbench --debug=on --mysql-user='root' --mysql-password='123' --mysql-db='test' --mysql-host='127.0.0.1' --mysql-port='3307' --tables='16'  --table-size='10000' --range-size='5' --db-ps-mode='disable' --skip-trx='on' --mysql-ignore-errors='all' --time='11080' --report-interval='1' --histogram='on' --threads=2 oltp_read_write prepare

/usr/local/bin/sysbench --debug=on --mysql-user='root' --mysql-password='123' --mysql-db='test' --mysql-host='127.0.0.1' --mysql-port='3307' --tables='16' --table-size='10000' --range-size='5' --db-ps-mode='disable' --skip-trx='on' --mysql-ignore-errors='all' --time='11080' --report-interval='1' --histogram='on' --threads=2 oltp_read_write run

sysbench oltp_read_write --table-size=100000 --mysql-db=testdb --mysql-user=root --mysql-password=password cleanup

这个命令序列分别准备数据、运行测试和清理环境。运行测试部分变量--threads=4表示使用4个线程,--time=60表示测试持续时间60秒。

使用Sysbench时,请确保执行的测试与你的用例相关,并考虑到可能的性能差异。例如,如果目标是测试Web应用程序的数据库后端,确保测试的查询和事务能够反映真实的使用案例。

Sysbench的使用可以参考这个链接

Sysbench 编译

github 下载源代码

以5.10(ALinux3/CentOS8) 为例

1
2
3
4
5
6
7
8
yum install libtool -y //configure.ac:61: error: possibly undefined macro: AC_PROG_LIBTOOL
yum install mysql-devel -y

然后:
./autogen.sh ; ./configure ; make ; make install

起压力重现命令:
sysbench --mysql-user='root' --mysql-password='123' --mysql-db='test' --mysql-host='127.0.0.1' --mysql-port='3306' --tables='16' --table-size='10000' --range-size='5' --db-ps-mode='disable' --skip-trx='on' --mysql-ignore-errors='all' --time='1180' --report-interval='1' --histogram='on' --threads=1 oltp_read_only run --verbosity=5

分析

研发人员第一反应重启了Sysbench 所在的ECS 然后恢复了,但是也没有了现场,我告诉他们等有了现场通知我,不要重启。今天终于再次重现了,我连上ECS 速度看了几个指标,通过 top 看到Sysbench 进程占用CPU 400%(整个 ECS 是4核),如图:

image-20240320173723799

再进一步看看 sys 都在干什么,用 perf top -p 16329 可以看到:

img

确实是内核态在网络里面有网络方面的函数占比很高,且 spin_lock 严重,所以速度用 ss -s 和 netstat -anto 看看网络连接情况:

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
28
29
# ss -s
Total: 41682
TCP: 41498 (estab 5241, closed 1, orphaned 0, timewait 0)

Transport Total IP IPv6
RAW 0 0 0
UDP 8 5 3
TCP 41497 41495 2 //用了几万个连接了,这不正常
INET 41505 41500 5
FRAG 0 0 0

# netstat -anto | head -30 //确实可以看到几万个连接,几乎都是 CLOSE_WAIT 状态
Active Internet connections (servers and established)
注意第二列一直都是——79,Recv-Q的意思是3306端发给Sysbench的内容79字节,但这79自己还在 OS 的tcp buffer 中,等待Sysbench 读走
Proto Recv-Q Send-Q Local Address Foreign Address State Timer
tcp 79 0 192.168.0.1:48743 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:32747 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:40838 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:40190 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:58337 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:23976 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:41687 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:57214 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:30464 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:2015 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:16032 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:47188 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:3054 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)
tcp 79 0 192.168.0.1:46344 192.168.20.220:3306 CLOSE_WAIT off (0.00/0/0)

延伸:Recv-Q 和 netstat 定位性能案例可以看这篇

内核代码

前文通过 perf top 可以看到 __inet_check_established 这个函数占用非常高

不符合正常逻辑,github 内核源码地址(我只加了注释)

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
//connect()时进行随机端口四元组可用性的判断
//如果本地地址和目标地址组成的元组之前已经存在了,则返回错误码EADDRNOTAVAIL: Cannot assign requested address
//这个时候即使设置了REUSEADDR也要报错
/* called with local bh disabled */
static int __inet_check_established(struct inet_timewait_death_row *death_row,
struct sock *sk, __u16 lport,
struct inet_timewait_sock **twp)
{
struct inet_hashinfo *hinfo = death_row->hashinfo;
struct inet_sock *inet = inet_sk(sk);
__be32 daddr = inet->inet_rcv_saddr;
__be32 saddr = inet->inet_daddr;
int dif = sk->sk_bound_dev_if;
struct net *net = sock_net(sk);
int sdif = l3mdev_master_ifindex_by_index(net, dif);
INET_ADDR_COOKIE(acookie, saddr, daddr);
const __portpair ports = INET_COMBINED_PORTS(inet->inet_dport, lport);
unsigned int hash = inet_ehashfn(net, daddr, lport,
saddr, inet->inet_dport);
//inet_ehash_bucket存放ESTABLISHED状态的socket 哈希表
struct inet_ehash_bucket *head = inet_ehash_bucket(hinfo, hash);
spinlock_t *lock = inet_ehash_lockp(hinfo, hash);
struct sock *sk2;
const struct hlist_nulls_node *node;
struct inet_timewait_sock *tw = NULL;

spin_lock(lock);
//遍历检查四元组是否冲突
sk_nulls_for_each(sk2, node, &head->chain) {
if (sk2->sk_hash != hash)
continue;
//INET_MATCH 执行四元组比较
if (likely(INET_MATCH(sk2, net, acookie,
saddr, daddr, ports, dif, sdif))) {
if (sk2->sk_state == TCP_TIME_WAIT) {
tw = inet_twsk(sk2);
if (twsk_unique(sk, sk2, twp))
break;
}
goto not_unique;
}
}

……

not_unique:
spin_unlock(lock);
return -EADDRNOTAVAIL; //Cannot assign requested address错误,在510行看到了下一节 telnet/strace 中的错误信息


// #define EADDRNOTAVAIL 227 /* Cannot assign requested address */

到这里可以很清楚说明问题在客户端而不是服务端,但是要回答:

  1. 为什么CPU这么高,CPU都在忙什么
  2. 什么原因会导致 CLOSE_WAIT 状态
  3. 为什么Sysbench 要疯狂创建4万多个连接;

所以接下来我们就来分别回答这三个问题

为什么CPU这么高,CPU都在忙什么

首先用 strace -p Sysbench-pid 看看 Sysbench 进程都在忙什么,下图最上面是 Sysbench 在疯狂不断地 connect:

image-20240320174806093

从上图最上面的Strace 来看 Sysbench在疯狂创建连接,但是在Connect 的时候报错:无法指定被请求的地址

那接下来我就要ping 一下 192.168.20.220 这个IP 是OK的,再然后telnet 192.168.20.220 22 发现没报错但是也没有 SSH 让我输密码,于是看了下 cat /proc/sys/net/ipv4/ip_local_port_range 是4万个Local Port 可用,这个时候可以去看看我这篇关于可用端口的经典文章

于是我改了下Port Range范围多加了1万Port 上去,然后很快看到如图 ss -s 就有5万连接了,说明你给多少Port 都不够用

同时我也用 telnet 192.168.20.220 3306 报错是:Cannot assign requested address —— 这个报错和 无法指定被请求的地址 很像了,到这里可以看到做一个基本结论:

  1. 之所以内核 sys CPU 跑高到 100%,是因为当Local Port 用完,又要新建连接的时候内核会用死循环去找可用端口,导致CPU 跑高(这也是为什么telnet 22端口不会报错,也不会正常出来SSH login——因为抢不到CPU 资源去走选端口的流程)
  2. Cannot assign requested address无法指定被请求的地址 报错是找不到可用端口导致的,还没有走到三次握手,也就是和服务端无关

继续验证:

image-20240320180024067

上图是先把local port 增多,然后立即 telnet 3306 发现成功了!这更是证明了上面的结论2

到这里分析清楚了为什么CPU 高—— Sysbench疯狂建连接导致端口用完,内核要用死循环不断去找可用端口导致了CPU使用率高,因为是内核态的行为所以表现出来就是 sys CPU 100%

而telnet 22端口不报这个错,是因为 22端口的可用端口几万个没有被使用掉,但是22端口也没让我输密码,这里应该是telnet 22时抢不到CPU 造成TCP 三次握手缓慢,但绝对不会报 Cannot assign requested address 错误

什么原因会导致 CLOSE_WAIT 状态

在将这个问题前还是请先去看看 CLOSE_WAIT 代表了什么含义: 为什么这么多CLOSE_WAIT

当同事们看到几万个连接的时候第一反应就是能不能改改这两 Linux 的系统参数:tcp_tw_reuse, tcp_tw_recycle 让端口/连接快速回收?

有没有你们都是这种同事,看到一个现象条件反射得出这个结论,这都是略知皮毛的经验太多了导致

我在 《为什么这么多CLOSE_WAIT》一文中反复提到这张图,以及学霸是怎么从这张图推断原因的:

image.png

看完上面这个图和我的 《为什么这么多CLOSE_WAIT》就应该知道 CLOSE_WAIT 就是 Sysbench 没有调 Socket.close 导致的 和内核没有关系,所以改啥内核参数也没有用,因为在这次问题中很多研发同学看到 CLOSE_WAIT 第一反应是去改这些参数:

1
2
net.ipv4.tcp_tw_recycle = 0
net.ipv4.tcp_tw_reuse = 0

如何进一步证明是Sysbench的问题呢?可以抓包看看:

image-20240320181258965上图是在 Sysbench 所在ECS 上抓包可以看到所有连接都是这样,注意第四个包是 Server端在3次握手成功后发了 Server Greeting 给客户端 Sysbench,此时Sysbench 应该发自己的账号密码来 Login但是抓包永远卡在这里,也就是Sysbench 建立完连接后跑了,不搭理服务端发了什么,这也是为什么最前面的 netstat -anto 看到 Recv-Q 这列总是79,这79长度的内容就是 Server 发给Sysbench 的 Server Greeting 内容,本该Sysbench 去读走 Server Greeting 然后按照MySQL 协议发账号密码,但是不,此时Sysbench 颠了,不管这个连接了,又去创建新连接于是重复上面的过程;直到本地端口用完,sys CPU 干到 100%

其实上面这个抓包的连接状态是 ESTABLISHED 状态,为什么最终看到的是 CLOSE_WAIT 呢,因为 Server发了 Server Greeting 后有一个超时时间,迟迟等不到Sysbench Client的账号密码就会发 FIN 给Client 端请求断开这个连接,导致Client断的连接状态从 ESTABLISHED 进入 CLOSE_WAIT ,这从上面的 TCP 状态图完全可以推导出来,扩大抓包时间的话会抓到 Server 发过来的 FIN 包

你要看不懂这个抓包,可以找个正常的MySQL-client 连 Server抓一次包,有个正常的对比会很幸福,我丢一个正常的给大家对比参考,上面错在 Sysbench 没有发如下红框的包:

img

Server 一重启就去看 netstat 的话确实都是 ESTABLISHED:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
# netstat -anto | head -30 |grep -E "State|:3306 "
Proto Recv-Q Send-Q Local Address Foreign Address State Timer
tcp 78 0 192.168.0.1:46344 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:44592 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:45908 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:44166 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:59484 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:60720 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:53436 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:58690 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:35932 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:53944 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:59758 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:53676 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:59304 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:41848 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:44312 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:56654 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:3516 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:39316 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:55074 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:59476 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)
tcp 78 0 192.168.0.1:48854 192.168.20.220:3306 ESTABLISHED off (0.00/0/0)

此时端口还够的时候去 strace 看到Sysbench 确实在疯狂 connect 建连接,也不像端口不够的时候会报错:

image-20240320184307103

到这里就可以回答:什么原因会导致 CLOSE_WAIT 状态?因为Sysbench 没有去正常 Login MySQL,MySQL-Server 等了 10 秒也没等到 Sysbenche login 就主动 close 了,而 Sysbench client 一直没有调 Socket.close 来关闭这个连接导致这个连接在 Sysbench 端一直是CLOSE_WAIT 且永久残留为 CLOSE_WAIT

为什么Sysbench 要疯狂创建4万多个连接

为什么Sysbench 要疯狂创建4万多个连接,且还在不停地创建,这就要涉及到 Sysbench 具体代码逻辑(这个版本的 Sysbench 被我厂同事魔改过) ,在一猛子扎进去看代码逻辑前,我换了个开源的 Sysbench 版本(Update 20240325 其实是换了个压测环境,用了不同的Sysbench而已),问题就消失了 —— 有时候猛干不如取巧

到此可以说明问题的原因就是:这个 Sysbench 版本在连接异常断开(Server升级主动断开连接)后,新建连接逻辑错误,疯狂建连接引起的

Update 20240327

后来经过网友 扒皮哥和 haoqixu的耐心分析,发现这个问题不完是 Sysbench 本身代码的问题,Sysbench 依赖 libmysqlclient.so 包去连MySQL-Server 和处理MySQL 协议等,而这个 Bug 存在 libmysqlclient.so 中,准确来说是MariaDB的 libmysqlclient 中(和版本没关系,最新版还有这个问题),如果换成MySQL Community的 libmysqlclient 就不存在这个问题了。划重点:无论你怎么更换 Sysbench 版本这个问题也无法解决

另外 MySQL 社区和 MariaDB 的 libmysqlclient 只是接口一样,实现完全可以不同,MariaDB 要求连接重连的时候先 close 再init 后才能使用,而MySQL 社区版本没有这个要求,所以改 Sysbench 重连的代码也可以 fix 这个问题

这个问题也有人怀疑过OS 的问题,比如换个OS 就好了,但我始终坚持是 Sysbench的问题,因为建连接后不读走TCP buffer里的内容都是业务层面的逻辑(相对于OS Sysbench和libmysqlclient 都是业务层),所以这个错误肯定不在OS

但是很多人换了 OS 就正常了,其实这里不是你只换了 OS,而是换 OS 的时候你顺便把 libmysqlclient 也换了你自己都不知道,这就是我们常说的瞎蒙蒙对了,但是这种经验却是错误的

更换 libmysqlclient 来验证:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
yum remove  mariadb-devel -y //删掉 mariadb-devel 所带的 libmysqlclient 18
rpm -i https://dev.mysql.com/get/mysql80-community-release-el8-9.noarch.rpm
yum install mysql-community-devel -y //安装 mysql-community-deve ,会带上 libmysqlclient 21
./configure
make install

# 查看依赖
objdump -x /usr/local/bin/sysbench |grep libmysqlclient

NEEDED libmysqlclient.so.21
required from libmysqlclient.so.21:
0x03532d60 0x00 08 libmysqlclient_21.0
0000000000000000 F *UND* 0000000000000000 mysql_stmt_next_result@@libmysqlclient_21.0
0000000000000000 F *UND* 0000000000000000 mysql_errno@@libmysqlclient_21.0
... 省略若干
0000000000000000 F *UND* 0000000000000000 mysql_server_end@@libmysqlclient_21.0

自己编译 libmariadb.so

通过下载 mariadb-connector-c-3.3 源码,自己独立编译,新生成的 so 包不再导致CPU飙高,但是TPS 永远跌零,而通过yum 安装的是mariadb-connector-c-3.2.6

此时抓包,可以看到3.3 收到Server Greeting 后也不发送账号密码,但是直接 RST 了连接,这样使得连接被释放,占用端口被释放,CPU不会飙高,但是连接永远无法创建成功,TPS 永远跌零

1
2
3
4
5
6
7
mariadb-connector-c-3.3 抓包:
15100 Mar 27, 2024 17:07:53.422009421 CST 0.001052729 49548 3306 0 49548 → 3306 [SYN] Seq=0 Win=65495 Len=0 MSS=65495 SACK_PERM=1 TSval=1021766452 TSecr=0 WS=128
15101 Mar 27, 2024 17:07:53.422013946 CST 0.000004525 3306 49548 0 3306 → 49548 [SYN, ACK] Seq=0 Ack=1 Win=65483 Len=0 MSS=65495 SACK_PERM=1 TSval=1021766452 TSecr=1021766452 WS=128
15102 Mar 27, 2024 17:07:53.422018506 CST 0.000004560 49548 3306 0 49548 → 3306 [ACK] Seq=1 Ack=1 Win=65536 Len=0 TSval=1021766452 TSecr=1021766452
15103 Mar 27, 2024 17:07:53.422116125 CST 0.000097619 49548 3306 0 49548 → 3306 [FIN, ACK] Seq=1 Ack=1 Win=65536 Len=0 TSval=1021766452 TSecr=1021766452
15104 Mar 27, 2024 17:07:53.422146191 CST 0.000030066 3306 49548 77 Server Greeting proto=10 version=8.2.0 //Server Greeting
15105 Mar 27, 2024 17:07:53.422155229 CST 0.000009038 49548 3306 0 49548 → 3306 [RST] Seq=2 Win=0 Len=0

image-20240327171929387

此时:

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
28
29
30
31
32
33
34
35
#ldd /usr/local/bin/sysbench
linux-vdso.so.1 (0x00007ffc3a736000)
libmariadb.so.3 => /lib64/libmariadb.so.3 (0x00007f3ce6352000)
libdl.so.2 => /lib64/libdl.so.2 (0x00007f3ce634b000)
libm.so.6 => /lib64/libm.so.6 (0x00007f3ce6205000)
libgcc_s.so.1 => /lib64/libgcc_s.so.1 (0x00007f3ce61ea000)
libpthread.so.0 => /lib64/libpthread.so.0 (0x00007f3ce61c8000)
libc.so.6 => /lib64/libc.so.6 (0x00007f3ce5fec000)
libssl.so.1.1 => /lib64/libssl.so.1.1 (0x00007f3ce5f53000)
libcrypto.so.1.1 => /lib64/libcrypto.so.1.1 (0x00007f3ce5c58000)
/lib64/ld-linux-x86-64.so.2 (0x00007f3ce63f1000)
libz.so.1 => /lib64/libz.so.1 (0x00007f3ce5c3e000)

#objdump -x /usr/local/bin/sysbench |grep libmysqlclient
0x0f735338 0x00 04 libmysqlclient_18

#rpm -q --whatprovides /lib64/libmariadb.so.3
mariadb-connector-c-3.2.6-1.al8.x86_64

#yum info mariadb-connector-c-3.2.6-1.al8.x86_64
上次元数据过期检查:0:23:09 前,执行于 2024年03月27日 星期三 16时53分17秒。
已安装的软件包
名称 : mariadb-connector-c
版本 : 3.2.6
发布 : 1.al8
架构 : x86_64
大小 : 545 k
源 : mariadb-connector-c-3.2.6-1.al8.src.rpm
仓库 : @System
来自仓库 : alinux3-updates
概况 : The MariaDB Native Client library (C driver)
URL : http://mariadb.org/
协议 : LGPLv2+
描述 : The MariaDB Native Client library (C driver) is used to connect
: applications developed in C/C++ to MariaDB and MySQL databases.

Sysbench 建连接堆栈,当端口不够的时候很容易抓到 connect 函数,因为connect 需要lookup 可用端口:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
#pstack 1448113
Thread 3 (Thread 0x7f9a0b23c640 (LWP 1448115)):
#0 0x00007f9a0b9722bb in connect () from /lib64/libpthread.so.0
#1 0x00007f9a0bb02b00 in pvio_socket_internal_connect (pvio=0x7f99fa5db270, name=0x7f99fc0247c0, namelen=16) at /root/mariadb-connector-c-3.2.6/plugins/pvio/pvio_socket.c:642
#2 0x00007f9a0bb02d76 in pvio_socket_connect_sync_or_async (pvio=0x7f99fa5db270, name=0x7f99fc0247c0, namelen=16) at /root/mariadb-connector-c-3.2.6/plugins/pvio/pvio_socket.c:750
#3 0x00007f9a0bb03499 in pvio_socket_connect (pvio=0x7f99fa5db270, cinfo=0x7f9a0b23b3d0) at /root/mariadb-connector-c-3.2.6/plugins/pvio/pvio_socket.c:919
#4 0x00007f9a0bb15277 in ma_pvio_connect (pvio=0x7f99fa5db270, cinfo=0x7f9a0b23b3d0) at /root/mariadb-connector-c-3.2.6/libmariadb/ma_pvio.c:484
#5 0x00007f9a0bb0b59c in mthd_my_real_connect (mysql=0x7f99fc01ff50, host=0x14e4110 "127.0.0.1", user=0x14e27c0 "root", passwd=0x14e40c0 "123", db=0x14e28f0 "test", port=3306, unix_socket=0x0, client_flag=65536) at /root/mariadb-connector-c-3.2.6/libmariadb/mariadb_lib.c:1462
#6 0x00007f9a0bb0affb in mysql_real_connect (mysql=0x7f99fc01ff50, host=0x14e4110 "127.0.0.1", user=0x14e27c0 "root", passwd=0x14e40c0 "123", db=0x14e28f0 "test", port=3306, unix_socket=0x0, client_flag=65536) at /root/mariadb-connector-c-3.2.6/libmariadb/mariadb_lib.c:1301
#7 0x000000000041b5d0 in mysql_drv_real_connect (db_mysql_con=0x7f99fc01fbf0) at drv_mysql.c:405
#8 0x000000000041cc6c in mysql_drv_reconnect (sb_con=0x0) at drv_mysql.c:815
#9 check_error (sb_con=sb_con@entry=0x7f99fc0210a0, func=func@entry=0x486637 "mysql_drv_query()", query=query@entry=0x7f99fc0207f0 "SELECT c FROM sbtest16 WHERE id=5031", counter=counter@entry=0x7f99fc0210c8) at drv_mysql.c:894
#10 0x000000000041d1d1 in mysql_drv_query (rs=0x7f99fc0210c8, len=<optimized out>, query=0x7f99fc0207f0 "SELECT c FROM sbtest16 WHERE id=5031", sb_conn=<optimized out>) at drv_mysql.c:1071
#11 mysql_drv_query (rs=0x7f99fc0210c8, len=<optimized out>, query=0x7f99fc0207f0 "SELECT c FROM sbtest16 WHERE id=5031", sb_conn=<optimized out>) at drv_mysql.c:1051
#12 mysql_drv_execute (stmt=<optimized out>, rs=<optimized out>) at drv_mysql.c:1040
#13 0x000000000040f32a in db_execute (stmt=0x7f99fc021270) at db_driver.c:517

修复

改下Sysbench 代码 ./src/drivers/mysql/drv_mysql.c 加一行就可以解决这个问题:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
static int mysql_drv_reconnect(db_conn_t *sb_con)
{
db_mysql_conn_t *db_mysql_con = (db_mysql_conn_t *) sb_con->ptr;
MYSQL *con = db_mysql_con->mysql;

log_text(LOG_DEBUG, "Reconnecting zhejian");

DEBUG("mysql_close(%p)", con);
mysql_close(con);
mysql_init(con); //add by ren

//这个死循环在反复创建新连接用光 port range
while (mysql_drv_real_connect(db_mysql_con))
{
if (sb_globals.error)
return DB_ERROR_FATAL;

usleep(1000);
}

log_text(LOG_DEBUG, "Reconnected");

return DB_ERROR_IGNORABLE;
}

重现

只有sysbench 编译时依赖 libmariadb.so 才会有问题

1
2
3
4
5
#ldd /usr/local/bin/sysbench
linux-vdso.so.1 (0x00007ffee0f93000)
libmariadb.so.3 => /lib64/libmariadb.so.3 (0x00007fecb3f9d000)

yum install mariadb-devel

卸载掉 mysql-devel 重新安装 mariadb-devel, 再编译 sysbench

sysbench 源码下载:https://github.com/akopytov/sysbench

总结

问题结论:mariadb 的 connect lib库对 libmysql 接口实现得有问题,当连接异常断开后会进入死循环疯狂创建连接导致了这个问题

这里涉及很多技巧:top/ss -s/strace/netstat/telnet 以及很多基础知识 local port range/ CLOSE_WAIT ,会折腾很重要,折腾的前提是会解锁各种姿势

难的是如何恰到好处地应用这些技巧和正确应用这些知识,剩下的分析推进就很符合逻辑了

另外我之前强调的在一个错误面前反复折腾不断缩小范围的能力也很重要,比如换个版本确认总比你看代码快吧

从这篇文章可以看出我真是个好教练,一次故障诊断涉及2-3个知识点,3-5个小命令,2-4次逻辑推断,最后完美定位问题,把各个知识的解读、各种命令的灵活使用展现的淋漓尽致。

接下来就是如何在我们的统一实验 ECS 上重现这个问题并保证让大家跟着实际操作

其实开始的时候问题没有这么清晰,每次升级才能稳定重现,后来想要定位问题就必须降低重现难度,考虑到重启客户端ECS 就能恢复,于是:

  • 不再重启ECS,只重启 Sysbench —— 能恢复
  • 不真正升级只重启Server —— 问题能稳定重现,重现容易很多了
  • 不重启 Server,只是kill掉Sysbench 的一条连接 —— 能重现
  • 将Sysbench 连接数从最开始100个,改成2个压 Server,然后 kill 掉 Sysbench 的一条连接 —— 能重现

到最后稳定重现方案就是 Sysbench 用两个连接压 Server,然后到 Server 上随便kill 掉其中一条连接,这个问题能稳定重现;重现后重启Sysbench 就能稳定恢复

参考资料

一个类似的bughttps://bugs.mysql.com/bug.php?id=88428

内核笔记

分人分析得再好也是别人的,自己积累的一点点终究是自己的;端口不够的时候CPU 拉高我之前碰到过,所以在内核的代码里写了点笔记,这次Sysbench 问题又碰到了,所以正好看到我上次的笔记:https://github.com/plantegg/linux/blob/3157b476f8216d2655c1c85bad53c975190689ba/net/ipv4/inet_hashtables.c#L447

我的意思是可以拉个Linux 内核较新的代码分支,自己随便哪天学到点啥在上面注释一下,commit,时间久了慢慢就串起来了,如下图错误码和strace 看到的错误信息就是一致的

直播总结:

关于可用端口一文,搞懂这个概念(到底有多少可用端口)只是开始;还需要借助案例去理解;天杀的Google 把端口分为奇偶数两部分,简直是神助攻,给了我们无穷Case 来加深端口不够时候系统什么表现的映像;今天直播的案例是端口全不够了,这种非常明显的异常更好发现;如果端口还够只是偶数用完了,但每次都要扫描一遍偶数,发现偶数没有可用端口再去扫描奇数就能找到可用端口,这导致的是每次可能有点卡顿,但是又不报错,因为过于隐晦这在业务层面带来的危害更加大

同样是学TCP状态流转(ESTABLISHED TIME_WAIT CLOSE_WAIT ),有人看一次就能推理,但大多数都是普通人,看过了还瞎猜,不管啥都想的是 tcp_reuse/tcp_recycle,还处在使劲蒙的状态

ping/telnet/strace/tcpdump 几乎都会用,但是如何恰到好处地去用,报错是什么状态、没任何输出是什么状态

然后就是过程分析中的一些推理。先从最根本的现象QPS 跌0开始撸

三个版本:

不同的 libmysqlclient 版本 现象
yum install mariadb-devel (libmariadb.so 3.2.6) 永远跌零,耗尽端口、CPU高
手工编译 mariadb-connector-c-3.3(libmariadb.so 3.3) 永远跌零,但是不费端口、不耗CPU
yum install MySQL-devel(libmysqlclient 哪个版本都行) 正常

手工编译 libmariadb.so 后 CPU 不飙高,但是TPS 一直跌0,也会疯狂重建连接(每1ms 去建一次连接), 还是没处理对,不过会reset 连接释放端口

如果一个分析推理要求很高的逻辑能力(or 智商),那复制性就不强,没有太大的学习价值(主要是学不会),我们尽量多去学1+1=2这样的逻辑推理,时间久了你就会了1+2=3

真正的高手肯定不只是流于表象:

  1. 啊,连不上了
  2. 啊,服务器有问题
  3. 啊,CPU高
  4. 啊,too many Connection

天翼云老哥一年前也发现了这个问题并给了解决办法,但是阅读量只有55 https://www.ctyun.cn/developer/article/405333884604485 ——文章过于简单,如果去学习的话只能看到一个结论

进一步总结

如果3306 端口被防火墙drop,那么:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[root@plantegg 11:25 /root]
#mysql -h127.0.0.1 --ssl-mode=DISABLED -uroot -p123 test
mysql: [Warning] Using a password on the command line interface can be insecure.

…… 卡着,不报错


strace 看到是这样:
futex(0x55b99f129518, FUTEX_WAKE_PRIVATE, 2147483647) = 0
getpid() = 1511313
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("127.0.0.1")}, 16

一直卡在这里

Too many connections

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
28
29
30
31
getpid()                                = 1515762
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
setsockopt(3, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
recvfrom(3, "\27\0\0\0\377\20\4Too many connections", 16384, 0, NULL, NULL) = 27
shutdown(3, SHUT_RDWR) = 0
close(3) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
write(2, "ERROR 1040 (HY000): ", 20ERROR 1040 (HY000): ) = 20
write(2, "Too many connections", 20Too many connections) = 20

#mysql -h127.0.0.1 --ssl-mode=DISABLED -uroot -p123 test
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 1040 (HY000): Too many connections

用完端口后:
getpid() = 1515928
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 EADDRNOTAVAIL (Cannot assign requested address)
shutdown(3, SHUT_RDWR) = -1 ENOTCONN (Transport endpoint is not connected)
close(3) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
write(2, "ERROR 2003 (HY000): ", 20ERROR 2003 (HY000): ) = 20
write(2, "Can't connect to MySQL server on"..., 54Can't connect to MySQL server on '127.0.0.1:3306' (99)) = 54
write(2, "\n", 1
) = 1
write(1, "\7", 1) = 1
#mysql -h127.0.0.1 --ssl-mode=DISABLED -uroot -p123 test
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1:3306' (99)

如果是服务端3306 没起:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
socket(AF_INET, SOCK_STREAM, IPPROTO_TCP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 ECONNREFUSED (Connection refused)
shutdown(3, SHUT_RDWR) = -1 ENOTCONN (Transport endpoint is not connected)
close(3) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0), ...}) = 0
write(2, "ERROR 2003 (HY000): ", 20ERROR 2003 (HY000): ) = 20
write(2, "Can't connect to MySQL server on"..., 55Can't connect to MySQL server on '127.0.0.1:3306' (111)) = 55
write(2, "\n", 1
) = 1
write(1, "\7", 1) = 1
rt_sigaction(SIGQUIT, {sa_handler=SIG_IGN, sa_mask=[QUIT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f20ab9f0a60}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGINT, {sa_handler=SIG_IGN, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f20ab9f0a60}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
rt_sigaction(SIGHUP, {sa_handler=SIG_IGN, sa_mask=[HUP], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f20ab9f0a60}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
exit_group(1) = ?
+++ exited with 1 +++

[root@plantegg 11:54 /root]
#mysql --show-warnings=FALSE -h127.0.0.1 --ssl-mode=DISABLED -uroot -p123 test
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1:3306' (111)

账号密码权限错误

1
2
#mysql --show-warnings=FALSE -h127.0.0.1 --ssl-mode=DISABLED -uroot -p1234 test
ERROR 1045 (28000): Access denied for user 'root'@'127.0.0.1' (using password: YES)

telnet

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
//正常telnet ,能看到 Greeting以及输密码信息
#telnet 127.0.0.1 3306
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
I
8.2.0�#[6Y
@+5=,mi?%#caching_sha2_password^]

//当MySQL-Server 的连接数不够了时
#telnet 127.0.0.1 3306
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
Too many connectionsConnection closed by foreign host.

//当客户端本地可用端口不够,三次握手还没开始
#telnet 127.0.0.1 3306
Trying 127.0.0.1...
telnet: connect to address 127.0.0.1: Cannot assign requested address

99 VS 111

在MySQL错误信息中,ERROR 2003 (HY000)是一个通用的连接失败错误。错误之后的括号中的数字代表的是系统级别的错误码,与MySQL本身的错误代码不同,它们来自于操作系统,表示尝试建立网络连接时遇到了错误。错误码99111 具体代表以下含义:

  • (99):这个错误码通常与网络配置相关。在大多数情况下,这个错误产生于Linux系统,并对应于EADDRNOTAVAIL错误,意义是”Cannot assign requested address”。当尝试绑定到无法分配的本地地址时,就会遇到这个错误。在尝试连接到MySQL服务器时,如果客户端使用了一个不存在的网络接口,例如,错误配置的TCP端口或地址,就有可能产生这个错误。
  • (111):这个错误码同样在Linux系统中更常见,对应于ECONNREFUSED错误,意义是”Connection refused”。当连接请求被远程主机或中间网络设施(如防火墙)明确拒绝时,就会遇到这个错误。在MySQL的上下文中,(111)错误可能表明MySQL服务没有在指定地址或端口上运行,或是防火墙设置阻止了连接。这也可能表明MySQL配置中的bind-address参数错误,设置为了仅允许本地连接。

解决错误99通常需要确保客户端是在向正确配置的地址发起连接,而解决错误111则可能需要检查MySQL服务是否运行、防火墙的设置以及my.cnfmy.inibind-address参数的配置。

image-20240328122311991

抓包解读

服务端主动断开

如下图是出问题的其中一次抓包,我们可以通过这个抓包来详细解析问题出在哪里。这是Sysbench(38692端口) 主动连MySQL Server(3306 端口),3次TCP 握手正常后Server 发送了 Server Greeting(截图中第四个包),然后Sysbench所在的Linux OS 38692端口回复了ack(这个ack 动作不需要Sysbench参与,完全由OS 来处理),这个时候 Sysbench应该读走这个 Server Greeting包并按MySQL 协议发送客户端账号密码,但是没有,过了10秒钟后(图中绿框) Server 再次发送了 1159 错误也就是图中红框,1159表示 Server等了10秒钟也没等到Client的账号密码,于是超时报错

image-20240407103809182

客户端非正常主动断开

如下图,Server 端回复了 Greeting,本该JDBC Client 发起 login 流程,但是因为这里Server 是 8.0,但是 JDBC Driver 用的5.7 导致兼容性问题,Client 主动断开了

image-20240704084229482

这是 Server 认为通信异常,于是返回:Error message: Got an error reading communication packets 即1158 报错

延伸

类似的分析手段,解决其他问题

体验抓包分析,的确……很快就找到了问题点。local_infile=0 时,libmariadb 会在 login 包中设置标志位为 0,但是 libmysqlclient 仍然是 1,这是诡异点1。Server DB产品 在标志位为 0 时会报登录信息错误,这是诡异点2。

image-20240403144037002

这条研发人员根据重现的抓包很快定位到了是Server DB产品的Bug,简单来说 Server DB产品对MySQL 协议实现得不好,如图的flag设置为0的话就会被当成 MySQL ping 协议来处理,感叹下还是抓包好使,要不还得去看账号权限啥的

换个MySQL Client 就糊弄过去了;

但是如果去分析就能发现就那一个bit的差异,一定是Server 导致了问题,Server研发在铁的证据面前快速定位是产品bug,但是你如果不会抓包分析,一看报错是账号、权限错误就寄了——程序员对别人说的一个字都不要信,只信自己看到的

再回想想我们平时放弃的那些问题、那些撕逼撕不清楚的锅等等

参考资料

sysbench benchmark MySQL 时候,为什么 kill 连接后,sysbench 没有重连 https://exfly.github.io/why-sysbench-dont-reconnect-after-kill/

LittleFatz:https://www.wolai.com/3cXBGNzWkW7oqKJQ5VKM3X

WindSoilde*:https://articles.zsxq.com/id_9a8b4f87zv6l.html

@邹扒皮.com:https://articles.zsxq.com/id_d27pgzmhuq08.html 最佳作业

最终问题的修复也有星球成员提交给社区并被合并了:https://github.com/akopytov/sysbench/pull/528/files

如果你觉得看完对你很有帮助可以通过如下方式找到我

find me on twitter: @plantegg

知识星球:https://t.zsxq.com/0cSFEUh2J

开了一个星球,在里面讲解一些案例、知识、学习方法,肯定没法让大家称为顶尖程序员(我自己都不是),只是希望用我的方法、知识、经验、案例作为你的垫脚石,帮助你快速、早日成为一个基本合格的程序员。

争取在星球内:

  • 养成基本动手能力
  • 拥有起码的分析推理能力–按我接触的程序员,大多都是没有逻辑的
  • 知识上教会你几个关键的知识点
image-20240324161113874

历时5年的net_write_timeout 报错分析

全网关于 JDBC 报错:net_write_timeout 的最好/最全总结

前言

上一次为了讲如何分析几百万个抓包,所以把这个问题中的一部分简化写了这篇抓包篇:https://articles.zsxq.com/id_lznw3w4zieuc.html 建议你先去看看把场景简化下,然后本篇中的分析涉及抓包部分就不再啰嗦讲解,请看抓包篇

问题描述

用户为了做数据分析需要把160个DB中的数据迁移到另外一个只读库中,有专门的迁移工具,但是这个迁移工具跑一阵后总是报错,报错堆栈显示是Tomcat 到DB之间的连接出了异常:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of 'net_write_timeout' on the server.
at sun.reflect.GeneratedConstructorAccessor150.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3749)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3649)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4090)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:972)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:2123)
at com.mysql.jdbc.RowDataDynamic.nextRecord(RowDataDynamic.java:374)
at com.mysql.jdbc.RowDataDynamic.next(RowDataDynamic.java:354)
at com.mysql.jdbc.RowDataDynamic.close(RowDataDynamic.java:155)
at com.mysql.jdbc.ResultSetImpl.realClose(ResultSetImpl.java:6726)
at com.mysql.jdbc.ResultSetImpl.close(ResultSetImpl.java:865)
at com.alibaba.druid.pool.DruidPooledResultSet.close(DruidPooledResultSet.java:86)

这个异常堆栈告诉我们Tomcat 到Database之间的连接异常了,似乎是 net_write_timeout 超时导致的

对应业务结构:

image-20230706210452742

net_write_timeout 原理简介

先看下 net_write_timeout的解释:

The number of seconds to wait for a block to be written to a connection before aborting the write. 只针对执行查询中的等待超时,网络不好,tcp buffer满了(应用迟迟不读走数据)等容易导致mysql server端报net_write_timeout错误,指的是mysql server hang在那里长时间无法发送查询结果。

报这个错就是DB 等了net_write_timeout这么久没写数据,可能是Tomcat 端卡死没有读走数据。

但是根据我多年来和这个报错打交道的经验告诉我:这个报错不只是因为net_write_timeout 超时导致的,任何Tomcat 到 DB间的连接断开了,都报这个错误,原因是JDBC 驱动搞不清楚断开的具体原因,统统当 net_write_timeout 了

一定要记住这个原理。如果这里不理解可以进一步阅读:https://wx.zsxq.com/dweb2/index/topic_detail/412251415855228

分析

首先把Tomcat 集群从负载均衡上摘一个下来,这样没有业务流量干扰更利于测试和分析日志

然后让迁移数据工具直接连这个没有流量的节点,问题仍然稳定重现。

进一步提取迁移工具的SQL,然后走API手工提交给Tomcat 执行,问题仍然稳定重现,现在重现越来越简单了,效率高多了。

Tomcat 上抓包

因为没有业务流量干扰,抓包很干净,但是因为DB 节点太多,所以量还是很大的,分析如抓包篇:https://articles.zsxq.com/id_lznw3w4zieuc.html

如下图红框所示的地方可以看到MySQL Server 传着传着居然带了个 fin 包在里面,表示MySQL Server要断开连接了,无奈Client只能也发送quit 断开连接。红框告诉我们一个无比有力的证据MySQL Server 在不应该断开的地方断开了连接,问题在 MySQL Server 端

image-20230620141017987

看起来是Database 主动端开了连接,因为这个过程Tomcat 不需要发任何东西给 Database。这个现象5年前在其它用户场景下就抓到过了,最后问题也不了了之,这次希望搞清楚

Database 分析

打开 DB 日志,捞取全量日志可以看到 DB 断开的原因是收到了kill Query!

有这个结果记住上面抓包图,以后类似这样莫名起来 DB 主动断开大概率就是 kill Query 导致的(经验攒得不容易!)

Database 抓包

确实能抓到kill,而且从用户账号来看就是从 Tomcat 发过去的!

继续分析Tomcat 抓包

从 DB 分析来看还是有人主动 kill 导致的,所以继续分析Tomcat的抓包看是不是因为代码bug导致Tomcat 发了kill 给DB

大海捞针,搜 kill,找Tomcat 发给DB的tcp length 长度是16-20的(刚好容纳kill id) 总的来说就是找不到,很神奇

由于 DB上记录的 Tomcat IP、port 都被中间链路转换过几次了,根本没办法一一对应搞清楚是哪个Tomcat 节点发出来的

继续尝试重现

分析完Tomcat 业务代码后感觉业务不会去kill,于是灵机一动在没有流量的Tomcat上跑了一个Sleep 600秒,不用任何数据,神奇的问题也稳定重现了,这下大概知道什么原因了,肯定是客户自己加了慢查询监控逻辑,一旦发现慢查询就 kill

于是问客户是不是有这种监控,果然有,停掉后反复重试不再有问题!

测试环境手工触发kill,然后能抓到下发的kill Query 给Database

image-20230707150658392

未解谜题

为什么没在Tomcat 抓到发给Database的 kill ?

我反复去重现了,如果是我手工触发Tomcat kill是可以清晰地抓到Tomcat 会发160个kill 给Database,但是我任其自然等待用户监控来杀就一定抓不到kill 下发给DB

我猜和 Tomcat 集群有关,首先用户监控是走的LVS,通过其中一个Tomcat 可以查询到所有 Tomcat 上的请求,然后发起 kill

但因为节点太多无法证实!当然业务监控也可以监控DB 然后直接发kill,但是和抓包看到的发起kill的用户不对,发起 kill 的用户是Tomcat独一无二的。

JDBC驱动报错 net_write_timeout 结论

Application was streaming results when the connection failed. Consider raising value of ‘net_write_timeout’ on the server. - com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of ‘net_write_timeout’ on the server.

这个报错不一定是 net_write_timeout 设置过小导致的,JDBC 在 streaming 流模式下只要连接异常就会报如上错误,比如:

  • 连接被 TCP reset
  • RDS 前端自带的Proxy 主动断开连接
  • 连接因为某种原因(比如 QueryTimeOut) 触发 kill Query导致连接中断
  • RDS 端因为kill 主动断开连接 //比如用户监控RDS、DRDS脚本杀掉慢查询

net_write_timeout:表示这么长时间RDS/DN 无法写数据到网络层发给DRDS/CN,原因是DRDS/CN 长时间没将数据读走

总结

首先一个错误现象对应多个完全不一样的错误原因是非常头疼的,这个问题反反复复在多个场景下出现,当然原因各异,但是这个传数据途中 DB 主动 fin连接还是第一次碰到并搞清楚,同样主动 fin 不一定是kill,但是我们要依照证据推进问题,既然是DB fin就有必要先从DB 来看原因。

从这个问题你可以先从什么是JDBC 流模式出发(mysql –quick 就是流模式,你可以快速查一个大数据试试;然后去掉–quick 对比一下),结合网络buffer 来了解流模式:https://plantegg.github.io/2020/07/03/MySQL%20JDBC%20StreamResult%20%E5%92%8C%20net_write_timeout/

然后从流模式来学习MySQL 的 net_write_timeout,假如你的代码报了 net_write_timeout 你会分析吗?

最后从连接断开去总结,比如网络不好、比如内核bug、比如DB crash、比如 kill、比如……都会导致连接断开,但这一切对业务来说只有 net_write_timeout 一个现象

这个问题分享出来是因为非常综合,我惊抱怨 socketTimeout、Communication failure等异常,这些异常也挺常见导致的原因多种,但是和 net_write_timeout 比起来还是不如 net_write_timeout 更综合,所以分享给大家,建议这几篇一起阅读效果最好!

实验模拟 Consider raising value of ‘net_write_timeout’

使用 Java MySQL JDBC Driver 的同学经常碰到如下错误堆栈,到底这个错误是 net_write_timeout 设置太小还是别的原因也会导致这个问题?需要我们用实验验证一下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of 'net_write_timeout' on the server.
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:500)
at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:481)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:990)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:873)
at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1996)
at com.mysql.jdbc.RowDataDynamic.nextRecord(RowDataDynamic.java:374)
at com.mysql.jdbc.RowDataDynamic.next(RowDataDynamic.java:354)
at com.mysql.jdbc.ResultSetImpl.next(ResultSetImpl.java:6312)
at Test.main(Test.java:38)
Caused by: java.io.EOFException: Can not read response from server. Expected to read 8 bytes, read 3 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3519)
... 8 more

JDBC 驱动对这个错误有如下提示(坑人):

Application was streaming results when the connection failed. Consider raising value of ‘net_write_timeout’ on the server. - com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Application was streaming results when the connection failed. Consider raising value of ‘net_write_timeout’ on the server.

实验中的一些说明:

  1. netTimeoutForStreamingResults=1 表示设置 net_write_timeout 为 1 秒,客户端会发送 set net_write_timeout=1 给数据库
  2. conn.setAutoCommit(false); //流式读取必须要 关闭自动提交
  3. stmt.setFetchSize(Integer.MIN_VALUE);

以上 2/3是触发流式读取的必要条件,第一条不设置默认是 600 秒,比较难等 :)

如果确实是 net_write_timeout 太小超时了, RDS 直接发 fin(但是 fin 前面还有一堆 response 包也在排队),然后 RDS 日志先报错:

1
2024-11-28T14:33:03.447397Z 12 [Note] Aborted connection 12 to db: 'test' user: 'root' host: '172.26.137.130' (Got timeout writing communication packets)

此时客户端还慢悠悠地读,RDS 没有回任何错误信息给客户端,客户端读完所有 Response 然后直接读到连接断开就报 Consider raising value of ‘net_write_timeout’ on the server 了,如果客户端读的慢,比如要 10 分钟实际连接在 RDS 上 10 分钟前就进入 fin 了,但是 10 分钟后客户端才报错

1
2
3
4
5
6
7
8
9
10
#netstat -anto | grep "3307"
tcp6 0 0 :::3307 :::* LISTEN off (0.00/0/0)
tcp6 0 140192 172.26.137.120:3307 172.26.137.130:51216 ESTABLISHED probe (0.04/0/0)
2024年 11月 28日 星期四 15:01:43 CST

//1秒中后此时 数据库感知到超时于是调用 close 断开连接,触发发送 fin给客户端,但是 fin 也需要排队,所以 140192增加了 1 变成140193
tcp6 0 0 :::3307 :::* LISTEN off (0.00/0/0)
tcp6 0 140193 172.26.137.120:3307 172.26.137.130:51216 FIN_WAIT1 probe (0.58/0/1)
2024年 11月 28日 星期四 15:01:44 CST

重现代码,数据库上构造一个大表,比如 10万行就行,能堆满默认的 tcp buffer size:

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.sql.Statement;
import java.sql.PreparedStatement;

/*
* 编译:
* javac -cp /root/java/*:. Test.java
* 运行:
* java -cp .:./mysql-connector-java-5.1.45.jar Test "jdbc:mysql://gf1:3307/test?useSSL=false&useServerPrepStmts=true&cachePrepStmts=true&connectTimeout=500&socketTimeout=1700&netTimeoutForStreamingResults=1" root 123 "select *, id from streaming " 3000
* netTimeoutForStreamingResults=1 表示RDS 等超过 1 秒都因为 tcp buffer 满无法继续发送数据就断开连接
* */
public class Test {
private static String url;
private Str name;

public static void main(String args[]) throws NumberFormatException, InterruptedException, ClassNotFoundException {
Class.forName("com.mysql.jdbc.Driver");
url = args[0];
String user = args[1];
String pass = args[2];
String sql = args[3];
String interval = args[4];
try {
Connection conn = DriverManager.getConnection(url, user, pass);
while (true) {

conn.setAutoCommit(false);
Statement stmt = conn.createStatement();
stmt.setFetchSize(Integer.MIN_VALUE);

long start = System.currentTimeMillis();
ResultSet rs = stmt.executeQuery(sql);
int count=0;
while (rs.next()) {
System.out.println("id:"+rs.getInt("id")+" count:"+count);
count++;
if(count<3) //1 秒后数据库端连接就已经关闭了,但是因为客户端读得慢,需要不 sleep 后才能读到 fin 然后报错,所以报错可以比实际晚很久
Thread.sleep(1500);
}
rs.close();
stmt.close();
Thread.sleep(Long.valueOf(interval));
break;
}
conn.close();
} catch (SQLException e) {
e.printStackTrace();
}
}
}

Consider raising value of ‘net_write_timeout’ 这个报错数据库端不会返回任何错误码给客户端,只是发 fin 断开连接,对客户端来说这条连接是 net_write_timeout 超时了 还是 被kill(或者其他原因) 是没法区分的,所以不管什么原因,只要连接异常 MySQL JDBC Driver 就抛 net_write_timeout 错误

如图,3 秒钟后 fin 包混在数据库 response 就被发到了客户端,实际2 秒前数据库已经报错了,也就是客户端和数据库端报错时间会差 2 秒(具体差几秒取决于重现代码里 sleep 多久然后-1)

image-20241128151324385

实验总结

这个报错不一定是 net_write_timeout 设置过小导致的,JDBC 在 streaming 流模式下只要连接异常就会报如上错误,比如:

  • 连接被 TCP reset
  • RDS 前端自带的Proxy 主动断开连接
  • 连接因为某种原因(比如 QueryTimeOut) 触发 kill Query导致连接中断
  • RDS 端因为kill 主动断开连接 //比如用户监控RDS 脚本杀掉慢查询
  • 开启流式读取后,只要客户端在读取查询结果没有结束就读到了 fin 包就会报这个错误

可以将 netTimeoutForStreamingResults 设为 0 或者 100,然后在中途 kill 掉 MySQL 上的 SQL,你也会在客户端看到同样的错误, kill SQL 是在 MySQL 的报错日志中都是同样的:

1
2024-11-28T07:33:12.967012Z 23 [Note] Aborted connection 23 to db: 'test' user: 'root' host: '172.26.137.130' (Got an error writing communication packets)

所以你看一旦客户端出现这个异常堆栈,除了抓包似乎没什么好办法,其实抓包也只能抓到数据库主动发了 fin 什么原因还是不知道,我恨这个没有错误码一统江湖的报错

net_write_timeout 后 RDS 直接发 fin(有时 fin 前面还有一堆 response 包也在排队),然后 rds 日志先报错:2024-11-28T06:33:03.447397Z 12 [Note] Aborted connection 12 to db: ‘test’ user: ‘root’ host: ‘172.26.137.130’ (Got timeout writing communication packets)

客户端慢悠悠地读,RDS 没有传任何错误信息给客户端,客户端读完所有 response 然后直接读到连接断开就报 Consider raising value of ‘net_write_timeout’ on the server 了,如果客户端读的慢,比如要 10 分钟实际连接在 RDS 上 10 分钟前就进入 fin 了,但是 10 分钟后客户端才报错

进阶阅读:https://plantegg.github.io/2024/09/25/%E4%B8%80%E4%B8%AA%E5%8E%86%E6%97%B65%E5%B9%B4%E7%9A%84%E9%97%AE%E9%A2%98%E5%88%86%E6%9E%90/https://x.com/plantegg/status/1867535551337050153

长连接黑洞重现和分析

这是一个存在多年,遍及各个不同的业务又反反复复地在集团内部出现的一个问题,本文先通过重现展示这个问题,然后从业务、数据库、OS等不同的角度来分析如何解决它,这个问题值得每一位研发同学重视起来,避免再次踩到

背景

为了高效率应对故障,本文尝试回答如下一些问题:

  • 为什么数据库crash 重启恢复后,业务还长时间不能恢复?
  • 我依赖的业务做了高可用切换,但是我的业务长时间报错
  • 我依赖的服务下掉了一个节点,为什么我的业务长时间报错
  • 客户做变配,升级云服务节点规格,为什么会导致客户业务长时间报错

目的:希望通过这篇文章尽可能地减少故障时长、让业务快速从故障中恢复

重现

空说无凭,先也通过一次真实的重现来展示这个问题

LVS+MySQL 高可用切换

OS 默认配置参数

1
2
3
4
5
6
#sysctl -a |grep -E "tcp_retries|keepalive"
net.ipv4.tcp_keepalive_intvl = 30
net.ipv4.tcp_keepalive_probes = 5
net.ipv4.tcp_keepalive_time = 10
net.ipv4.tcp_retries1 = 3
net.ipv4.tcp_retries2 = 15 //主要是这个参数,默认以及alios 几乎都是15

LVS 对外服务端口是3001, 后面挂的是 3307,假设3307是当前的Master,Slave是 3306,当检测到3307异常后会从LVS 上摘掉 3307挂上 3306做高可用切换

undefined

切换前的 LVS 状态

1
2
3
4
5
6
7
8
#ipvsadm -L --timeout
Timeout (tcp tcpfin udp): 900 120 300
#ipvsadm -L -n
IP Virtual Server version 1.2.1 (size=4096)
Prot LocalAddress:Port Scheduler Flags
-> RemoteAddress:Port Forward Weight ActiveConn InActConn
TCP 127.0.0.1:3001 rr
-> 127.0.0.1:3307 Masq 1 0 0

Sysbench启动压力模拟用户访问,在 31秒的时候模拟管控检测到 3307的Master无法访问,所以管控执行切主把 3306的Slave 提升为新的 Master,同时到 LVS 摘掉 3307,挂上3306,此时管控端着冰可乐、翘着二郎腿,得意地说,你就看吧我们管控牛逼不、我们的高可用牛逼不,这一套行云流水3秒钟不到全搞定

切换命令如下:

1
2
#cat del3307.sh
ipvsadm -d -t 127.0.0.1:3001 -r 127.0.0.1:3307 ; ipvsadm -a -t 127.0.0.1:3001 -r 127.0.0.1:3306 -m

此时Sysbench运行状态,在第 32秒如期跌0:

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
28
#/usr/local/bin/sysbench --debug=on --mysql-user='root' --mysql-password='123' --mysql-db='test' --mysql-host='127.0.0.1' --mysql-port='3001' --tables='16'  --table-size='10000' --range-size='5' --db-ps-mode='disable' --skip-trx='on' --mysql-ignore-errors='all' --time='11080' --report-interval='1' --histogram='on' --threads=1 oltp_read_write run
sysbench 1.1.0 (using bundled LuaJIT 2.1.0-beta3)

Running the test with following options:
Number of threads: 1
Report intermediate results every 1 second(s)
Debug mode enabled.

Initializing random number generator from current time


Initializing worker threads...

DEBUG: Worker thread (#0) started
DEBUG: Reporting thread started
DEBUG: Worker thread (#0) initialized
Threads started!

[ 1s ] thds: 1 tps: 51.89 qps: 947.00 (r/w/o: 739.44/207.56/0.00) lat (ms,95%): 35.59 err/s 0.00 reconn/s: 0.00
[ 2s ] thds: 1 tps: 60.03 qps: 1084.54 (r/w/o: 841.42/243.12/0.00) lat (ms,95%): 22.28 err/s 0.00 reconn/s: 0.00
…………
[ 29s ] thds: 1 tps: 68.00 qps: 1223.01 (r/w/o: 952.00/271.00/0.00) lat (ms,95%): 16.12 err/s 0.00 reconn/s: 0.00
[ 30s ] thds: 1 tps: 66.00 qps: 1188.00 (r/w/o: 924.00/264.00/0.00) lat (ms,95%): 16.71 err/s 0.00 reconn/s: 0.00
[ 31s ] thds: 1 tps: 67.00 qps: 1203.96 (r/w/o: 937.97/265.99/0.00) lat (ms,95%): 17.95 err/s 0.00 reconn/s: 0.00
[ 32s ] thds: 1 tps: 22.99 qps: 416.85 (r/w/o: 321.88/94.96/0.00) lat (ms,95%): 15.55 err/s 0.00 reconn/s: 0.00
[ 33s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 34s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 35s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00

5分钟后故障报告大批量涌进来,客户:怎么回事,我们的业务挂掉10分钟了,报错都是访问MySQL 超时,赶紧给我看看,从监控确实看到10分钟后客户业务还没恢复:

1
2
3
4
[ 601s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 602s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 603s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 604s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00

这时 oncall 都被从被窝里拎了起来,不知谁说了一句赶紧恢复吧,先试试把应用重启,5秒钟后应用重启完毕,业务恢复,大家开心地笑了,又成功防御住一次故障升级,还是重启大法好!

在业务/Sysbench QPS跌0 期间可以看到 3307被摘掉,3306 成功挂上去了,但是没有新连接建向 3306,业务/Sysbench 使劲薅着 3307

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
#ipvsadm -L -n --stats -t 127.0.0.1:3001
Prot LocalAddress:Port Conns InPkts OutPkts InBytes OutBytes
-> RemoteAddress:Port
TCP 127.0.0.1:3001 2 660294 661999 78202968 184940K
-> 127.0.0.1:3306 0 0 0 0 0

#ipvsadm -Lcn | head -10
IPVS connection entries
pro expire state source virtual destination
TCP 13:11 ESTABLISHED 127.0.0.1:33864 127.0.0.1:3001 127.0.0.1:3307

#netstat -anto |grep -E "Recv|33864|3001|33077"
Proto Recv-Q Send-Q Local Address Foreign Address State Timer
tcp 0 248 127.0.0.1:33864 127.0.0.1:3001 ESTABLISHED probe (33.48/0/8)
tcp6 0 11 127.0.0.1:3307 127.0.0.1:33864 ESTABLISHED on (49.03/13/0)

直到 900多秒后 OS 重试了15次发现都失败,于是向业务/Sysbench 返回连接异常,触发业务/Sysbench 释放异常连接重建新连接,新连接指向了新的 Master 3306,业务恢复正常

1
2
3
4
5
6
7
[ 957s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
DEBUG: Ignoring error 2013 Lost connection to MySQL server during query,
DEBUG: Reconnecting
DEBUG: Reconnected
[ 958s ] thds: 1 tps: 53.00 qps: 950.97 (r/w/o: 741.98/208.99/0.00) lat (ms,95%): 30.26 err/s 0.00 reconn/s: 1.00
[ 959s ] thds: 1 tps: 64.00 qps: 1154.03 (r/w/o: 896.02/258.01/0.00) lat (ms,95%): 22.69 err/s 0.00 reconn/s: 0.00
[ 960s ] thds: 1 tps: 66.00 qps: 1184.93 (r/w/o: 923.94/260.98/0.00) lat (ms,95%): 25.28 err/s 0.00 reconn/s: 0.00

到这里重现了故障中经常碰到的业务需要900多秒才能慢慢恢复,这个问题也就是 TCP 长连接流量黑洞

如果我们把 net.ipv4.tcp_retries2 改成5 再来做这个实验,就会发现业务/Sysbench 只需要20秒就能恢复了,也就是这个流量黑洞从900多秒变成了20秒,这回 oncall 不用再被从被窝里拎出来了吧:

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
[ 62s ] thds: 1 tps: 66.00 qps: 1191.00 (r/w/o: 924.00/267.00/0.00) lat (ms,95%): 17.63 err/s 0.00 reconn/s: 0.00
[ 63s ] thds: 1 tps: 63.00 qps: 1123.01 (r/w/o: 874.00/249.00/0.00) lat (ms,95%): 17.63 err/s 0.00 reconn/s: 0.00
[ 64s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 65s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 66s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 67s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 68s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 69s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 70s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 71s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 72s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 73s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 74s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 75s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 76s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 77s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 78s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 79s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 80s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 81s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
[ 82s ] thds: 1 tps: 0.00 qps: 0.00 (r/w/o: 0.00/0.00/0.00) lat (ms,95%): 0.00 err/s 0.00 reconn/s: 0.00
DEBUG: Ignoring error 2013 Lost connection to MySQL server during query,
DEBUG: Reconnecting
DEBUG: Reconnected
[ 83s ] thds: 1 tps: 26.00 qps: 457.01 (r/w/o: 357.01/100.00/0.00) lat (ms,95%): 16.41 err/s 0.00 reconn/s: 1.00
[ 84s ] thds: 1 tps: 60.00 qps: 1086.94 (r/w/o: 846.96/239.99/0.00) lat (ms,95%): 26.68 err/s 0.00 reconn/s: 0.00
[ 85s ] thds: 1 tps: 63.00 qps: 1134.02 (r/w/o: 882.01/252.00/0.00) lat (ms,95%): 23.10 err/s 0.00 reconn/s: 0.00

LVS + Nginx 上重现

NGINX上重现这个问题:https://asciinema.org/a/649890 3分钟的录屏,这个视频构造了一个LVS 的HA切换过程,LVS后有两个Nginx,模拟一个Nginx(Master) 断网后,将第二个Nginx(Slave) 加入到LVS 并将第一个Nginx(Master) 从LVS 摘除,期望业务能立即恢复,但实际上可以看到之前的所有长连接都没有办法恢复,进入一个流量黑洞

TCP 长连接流量黑洞原理总结

TCP 长连接在发送包的时候,如果没收到ack 默认会进行15次重传(net.ipv4.tcp_retries2=15, 这个不要较真,会根据RTO 时间大致是15次),累加起来大概是924秒,所以我们经常看到业务需要15分钟左右才恢复。这个问题存在所有TCP长连接中(几乎没有业务还在用短连接吧?),问题的本质和 LVS/k8s Service 都没关系

我这里重现带上 LVS 只是为了场景演示方便

这个问题的本质就是如果Server突然消失(宕机、断网,来不及发 RST )客户端如果正在发东西给Server就会遵循TCP 重传逻辑不断地TCP retran , 如果一直收不到Server 的ack,大约重传15次,900秒左右。所以不是因为有 LVS 导致了这个问题,而是在某些场景下 LVS 有能力处理得更优雅,比如删除 RealServer的时候 LVS 完全可以感知这个动作并 reset 掉其上所有长连接

为什么在K8S 上这个问题更明显呢,K8S 讲究的就是服务不可靠,随时干掉POD(切断网络),如果干POD 之前能kill -9(触发reset)、或者close 业务触发断开连接那还好,但是大多时候啥都没干,有强摘POD、有直接隔离等等,这些操作都会导致对端只能TCP retran

怎么解决

业务方

业务方要对自己的请求超时时间有控制和兜底,不能任由一个请求长时间 Hang 在那里

比如JDBC URL 支持设置 SocketTimeout、ConnectTimeout,我相信其他产品也有类似的参数,业务方要设置这些值,不设置就是如上重现里演示的900多秒后才恢复

SocketTimeout

只要是连接有机会设置 SocketTimeout 就一定要设置,具体值可以根据你们能接受的慢查询来设置;分析、AP类的请求可以设置大一点

最重要的:任何业务只要你用到了TCP 长连接一定要配置一个恰当的SocketTimeout,比如 Jedis 是连接池模式,底层超时之后,会销毁当前连接,下一次重新建连,就会连接到新的切换节点上去并恢复

RFC 5482 TCP_USER_TIMEOUT

RFC 5482 中增加了TCP_USER_TIMEOUT这个配置,通常用于定制当 TCP 网络连接中出现数据传输问题时,可以等待多长时间前释放网络资源,对应Linux 这个 commit

TCP_USER_TIMEOUT 是一个整数值,它指定了当 TCP 连接的数据包在发送后多长时间内未被确认(即没有收到 ACK),TCP 连接会考虑释放这个连接。

打个比方,设置 TCP_USER_TIMEOUT 后,应用程序就可以指定说:“如果在 30 秒内我发送的数据没有得到确认,那我就认定网络连接出了问题,不再尝试继续发送,而是直接断开连接。”这对于确保连接质量和维护用户体验是非常有帮助的。

在 Linux 中,可以使用 setsockopt 函数来设置某个特定 socket 的 TCP_USER_TIMEOUT 值:

1
2
int timeout = 30000; // 30 seconds
setsockopt(sock, IPPROTO_TCP, TCP_USER_TIMEOUT, (char *)&timeout, sizeof(timeout));

在这行代码中,sock 是已经 established 的 TCP socket,我们将该 socket 的 TCP_USER_TIMEOUT 设置为 30000 毫秒,也就是 30 秒。如果设置成功,这个 TCP 连接在发送数据包后 30 秒内如果没有收到 ACK 确认,将开始进行 TCP 连接的释放流程。

TCP_USER_TIMEOUT 相较 SocketTimeout 可以做到更精确(不影响慢查询),SocketTimeout 超时是不区分ACK 还是请求响应时间的,但是 TCP_USER_TIMEOUT 要求下层的API、OS 都支持。比如 JDK 不支持 TCP_USER_TIMEOUT,但是 Netty 框架自己搞了Native 来实现对 TCP_USER_TIMEOUT 以及其它OS 参数的设置,在这些基础上Redis 的Java 客户端 lettuce 依赖了 Netty ,所以也可以设置 TCP_USER_TIMEOUT

原本我是想在Druid 上提个feature 来支持 TCP_USER_TIMEOUT,这样集团绝大部分业务都可以无感知解决掉这个问题,但查下来发现 JDK 不支持设置这个值,想要在Druid 里面实现设置 TCP_USER_TIMEOUT 的话,得像 Netty 一样走Native 绕过JDK 来设置,这对 Druid 而言有点重了

ConnectTimeout

这个值是针对新连接创建超时时间设置,一般设置3-5秒就够长了

连接池

建议参考这篇 《数据库连接池配置推荐》 这篇里的很多建议也适合业务、应用等,你把数据库看成一个普通服务就好理解了

补充下如果用的是Druid 数据库连接池不要用它来设置你的 SocketTimeout 参数,因为他有bug 导致你觉得设置了但实际没设置上,2024-03-16号的1.2.22这个Release 才fix,所以强烈建议你讲 SocketTimeout 写死在JDBC URL 中简单明了

OS 兜底

假如业务是一个AP查询/一次慢请求,一次查询/请求就是需要半个小时,将 SocketTimeout 设置太小影响正常的查询,那么可以将如下 OS参数改小,从 OS 层面进行兜底

1
2
net.ipv4.tcp_retries2 = 8
net.ipv4.tcp_syn_retries = 4

keepalive

keepalive 默认 7200秒太长了,建议改成20秒,可以在OS 镜像层面固化,然后各个业务可以 patch 自己的值;

如果一条连接限制超过 900 秒 LVS就会Reset 这条连接,但是我们将keepalive 设置小于900秒的话,即使业务上一直闲置,因为有 keepalive 触发心跳包,让 LVS 不至于 Reset,这也就避免了当业务取连接使用的时候才发现连接已经不可用被断开了,往往这个时候业务抛错误的时间很和真正 Reset 时间还差了很多,不好排查

在触发 TCP retransmission 后会停止 keepalive 探测

LVS

如果你们试用了aliyun的SLB,当摘除节点的时候支持你设置一个时间,过了这个时间 aliyun的SLB 就会向这些连接的客户端发 Reset 干掉这些流量,让客户端触发新建连接,从故障中快速恢复,这是一个实例维度的参数,建议云上所有产品都支持起来,管控可以在购买 aliyun的SLB 的时候设置一个默认值:

connection_drain_timeout

其它

神奇的900秒

上面阐述的长连接流量黑洞一般是900+秒就恢复了,有时候我们经常在日志中看到 CommunicationsException: Communications link failure 900秒之类的错误,恰好 LVS 也是设置的 900秒闲置 Reset

1
2
#ipvsadm -L --timeout
Timeout (tcp tcpfin udp): 900 120 300

为什么这个问题这几年才明显暴露

  • 工程师们混沌了几十年
  • 之前因为出现频率低重启业务就糊弄过去了
  • 对新连接不存在这个问题
  • 有些连接池配置了Check 机制(Check机制一般几秒钟超时 fail)
  • 微服务多了
  • 云上 LVS 普及了
  • k8s service 大行其道

我用的 7层是不是就没有这个问题了?

幼稚,你4层都挂了7层还能蹦跶,再说一遍只要是 TCP 长连接就有这个问题

极端情况

A 长连接 访问B 服务,B服务到A网络不通,假如B发生HA,一般会先Reset/断开B上所有连接(比如 MySQL 会去kill 所有processlist;比如重启MySQL——假如这里的B是MySQL),但是因为网络不通这里的reset、fin网络包都无法到达A,所以B是无法兜底这个异常场景, A无法感知B不可用了,会使用旧连接大约15分钟

最可怕的是 B 服务不响应,B所在的OS 还在响应,那么在A的视角 网络是正常的,这时只能A自己来通过超时兜底

总结

这种问题在 LVS 场景下暴露更明显了,但是又和LVS 没啥关系,任何业务长连接都会导致这个 900秒左右的流量黑洞,首先要在业务层面重视这个问题,要不以后数据库一挂掉还得重启业务才能从故障中将恢复,所以业务层面处理好了可以避免900秒黑洞和重启业务,达到快速从故障中恢复

再强调下这个问题如果去掉LVS/k8s Service/软负载等让两个服务直连,然后拔网线也会同样出现

最佳实践总结:

  • 如果你的业务支持设置 SocketTimeout 那么请一定要设置,但不一定适合分析类就是需要长时间返回的请求
  • 最好的方式是设置 OS 层面的 TCP_USER_TIMEOUT 参数,只要长时间没有 ack 就报错返回,但 JDK 不支持直接设置
  • 如果用了 ALB/SLB 就一定要配置 connection_drain_timeout 这个参数
  • OS 镜像层面也可以将 tcp_retries2 设置为5-10次做一个兜底
  • 对你的超时时间做到可控、可预期

假如你的业务不是 Java,而是 Python 的话,请参考Java/Python超时参数对照表:

功能 JDBC (Java) mysql-connector-python PyMySQL
连接建立超时 connectTimeout connect_timeout connect_timeout
读写操作超时 socketTimeout connection_timeout read_timeout/write_timeout
连接池等待超时 poolTimeout pool_timeout 需手动实现

相关故障和资料

ALB 黑洞问题详述:https://mp.weixin.qq.com/s/BJWD2V_RM2rnU1y7LPB9aw

数据库故障引发的“血案” :https://www.cnblogs.com/nullllun/p/15073022.html 这篇描述较细致,推荐看看

tcp_retries2 的解释:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
tcp_retries1 - INTEGER
This value influences the time, after which TCP decides, that
something is wrong due to unacknowledged RTO retransmissions,
and reports this suspicion to the network layer.
See tcp_retries2 for more details.

RFC 1122 recommends at least 3 retransmissions, which is the
default.

tcp_retries2 - INTEGER
This value influences the timeout of an alive TCP connection,
when RTO retransmissions remain unacknowledged.
Given a value of N, a hypothetical TCP connection following
exponential backoff with an initial RTO of TCP_RTO_MIN would
retransmit N times before killing the connection at the (N+1)th RTO.

The default value of 15 yields a hypothetical timeout of 924.6
seconds and is a lower bound for the effective timeout.
TCP will effectively time out at the first RTO which exceeds the
hypothetical timeout.

RFC 1122 recommends at least 100 seconds for the timeout,
which corresponds to a value of at least 8.

tcp_retries2 默认值为15,根据RTO的值来决定,相当于13-30分钟(RFC1122规定,必须大于100秒),但是这是很多年前的拍下来古董参数值,现在网络条件好多了,尤其是内网,个人认为改成 5-10 是比较恰当 azure 建议:https://learn.microsoft.com/en-us/azure/azure-cache-for-redis/cache-best-practices-connection ,Oracle RAC的建议值是3:https://access.redhat.com/solutions/726753

十年后数据库还是不敢拥抱NUMA-续篇

背景

十年后数据库还是不敢拥抱NUMA, 这篇经典的纠正大家对NUMA 认知的文章一晃发布快3年了,这篇文章的核心结论是:

  • 之所以有不同的NUMA Node 是不同的CPU Core 到不同的内存距离远近不一样所决定的,这是个物理距离
  • 程序跑在不同的核上要去读写内存可以让性能差异巨大,所以我们要尽量让一个程序稳定跑在一个Node 内
  • 默认打开NUMA Node 其实挺好的

写这个续篇是我收到很多解释,因为跨Node 导致性能抖动,所以集团在物理机OS 的启动参数里设置了 numa=off ,也就是不管BIOS 中如何设置,我们只要在OS 层面设置一下 numa=off 就能让程序稳定下来不再抖了!

我这几年也认为这是对的,只是让我有点不理解,既然不区分远近了,那物理上存在的远近距离(既抖动)如何能被消除掉的呢?

所以这个续篇打算通过测试来验证下这个问题

设置

BIOS 中有 numa node 设置的开关(注意这里是内存交错/交织),不同的主板这个BIOS设置可能不一样,但是大同小异,基本都有这个参数

img

Linux 启动引导参数里也可以设置numa=on(默认值)/off ,linux 引导参数设置案例:

1
2
#cat /proc/cmdline
BOOT_IMAGE=/vmlinuz-3.10.0-327.x86_64 ro crashkernel=auto vconsole.font=latarcyrheb-sun16 vconsole.keymap=us BIOSdevname=0 console=tty0 console=ttyS0,115200 scsi_mod.scan=sync intel_idle.max_cstate=0 pci=pcie_bus_perf ipv6.disable=1 rd.driver.pre=ahci numa=on nosmt=force

注意如上的 numa=on 也可以改为 numa=off

看完全置篇要记住一条铁律:CPU到内存的距离是物理远近决定的,你软件层面做些设置是没法优化这个距离,也就是没法优化这个时延 (这是个核心知识点,你要死死记住和理解,后面的一切实验数据都回过头来看这个核心知识点并揣摩)

实验

测试机器CPU,如下是BIOS numa=on、cmdline numa=off所看到的,一个node

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
#lscpu
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 96
On-line CPU(s) list: 0-95
Thread(s) per core: 2
Core(s) per socket: 24
Socket(s): 2
NUMA node(s): 1
Vendor ID: GenuineIntel
CPU family: 6
Model: 85
Model name: Intel(R) Xeon(R) Platinum 8163 CPU @ 2.50GHz
Stepping: 4
CPU MHz: 2500.000
CPU max MHz: 3100.0000
CPU min MHz: 1000.0000
BogoMIPS: 4998.89
Virtualization: VT-x
L1d cache: 32K
L1i cache: 32K
L2 cache: 1024K
L3 cache: 33792K
NUMA node0 CPU(s): 0-95

测试工具是lmbench,测试命令:

1
for i in $(seq 0 6 95); do echo core:$i; numactl -C $i -m 0 ./bin/lat_mem_rd -W 5 -N 5 -t 64M; done >lat.log 2>&1

上述测试命令始终将内存绑定在 node0 上,然后用不同的物理core来读写这块内存,按照前一篇 这个时延肯定有快慢之分

BIOS和引导参数各有两种设置方式,组合起来就是四种,我们分别设置并跑一下内存时延,测试结果:

BIOS ON BIOS OFF
cmdline numa=on(默认值) NUMA 开启,内存在Node内做交织,就近有快慢之分 bios 关闭后numa后,OS层面完全不知道下层的结构,默认全局内存做交织,时延是个平均值
cmdline numa=off 交织关闭,效果同上 同上

测试原始数据如下(测试结果文件名 lat.log.BIOSON.cmdlineOff 表示BIOS ON,cmdline OFF ):

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
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
//从下面两组测试来看,BIOS层面 on后,不管OS 层面是否on,都不会跨node 做交织,抖动存在
//BIOS on 即使在OS层面关闭numa也不跨node做内存交织,抖动存在
//默认从内存高地址开始分配空间,所以0核要慢
#grep -E "core|64.00000" lat.log.BIOSON.cmdlineOff
core:0 //第0号核
64.00000 100.717 //64.0000为64MB, 100.717 是平均时延100.717ns 即0号核访问node0 下的内存64MB的平均延时是100纳秒
core:24
64.00000 68.484
core:48
64.00000 101.070
core:72
64.00000 68.483
#grep -E "core|64.00000" lat.log.BIOSON.cmdlineON
core:0
64.00000 67.094
core:24
64.00000 100.237
core:48
64.00000 67.614
core:72
64.00000 101.096

//从下面两组测试来看只要BIOS off了内存就会跨 node 交织,大规模测试下内存 latency 是个平均值
#grep -E "core|64.00000" lat.log.BIOSOff.cmdlineOff //BIOS off 做内存交织,latency就是平均值
core:0
64.00000 85.657 //85 恰好是最大100,最小68的平均值
core:24
64.00000 85.741
core:48
64.00000 85.977
core:72
64.00000 86.671

//BIOS 关闭后numa后,OS层面完全不知道下层的结构,默认一定是做交织
#grep -E "core|64.00000" lat.log.BIOSOff.cmdlineON
core:0
64.00000 89.123
core:24
64.00000 87.137
core:48
64.00000 87.239
core:72
64.00000 87.323

从数据可以看到在BIOS 设置ON后,无论 OS cmdline 启动参数里是否设置了 ON 还是 OFF,内存延时都是抖动且一致的(这个有点诧异,说好的消除抖动的呢?)。如果BIOS 设置OFF后内存延时是个稳定的平均值(这个比较好理解)

疑问

  • 内存交错时为什么 lmbench 测试得到的时延是平均值,而不是短板效应的最慢值?

测试软件只能通过大规模数据的读写来测试获取一个平均值,所以当一大块内存读取时,虽然通过交织大块内存被切分到了快慢物理内存上,但是因为规模大慢的被平均掉了。(欢迎内核大佬指正)

  • 什么是内存交织?

我的理解假如你有8块物理内存条,如果你有一个int 那么只能在其中一块上,如果你有1MB的数据那么会按cacheline 拆成多个块然后分别放到8块物理内存条上(有快有慢)这样带宽更大,最后测试得到一个平均值

如果你开启numa那么只会就近交织,比如0-3号内存条在0号core所在的node,OS 做内存交织的时候只会拆分到这0-3号内存条上,那么时延总是最小的那个,如上测试中的60多纳秒。

这个问题一直困扰了我几年,所以我最近再次测试验证了一下,主要是对 BIOS=on 且 cmdline=off 时有点困扰

Intel 的 mlc 验证

测试参数: BIOS=on 同时 cmdline off

Intel 的 mlc 验证下,这个结果有点意思,latency稳定在 145 而不是81 和 145两个值随机出现,应该是mlc默认选到了0核,对应lmbench的这组测试数据(为什么不是100.717, 因为测试方法不一样):

1
2
3
4
5
6
7
8
9
10
11
12
//如下是
//从下面两种测试来看,BIOS层面 on后,不管OS 层面是否on,都不会跨node 做交织,抖动存在
//BIOS on 即使在OS层面关闭numa也不跨node做内存交织,抖动存在
#grep -E "core|64.00000" lat.log.BIOSON.cmdlineOff
core:0
64.00000 100.717
core:24
64.00000 68.484
core:48
64.00000 101.070
core:72
64.00000 68.483

此时对应的mlc

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
28
29
30
31
32
33
34
35
36
#./mlc
Intel(R) Memory Latency Checker - v3.9
Measuring idle latencies (in ns)...
Numa node
Numa node 0
0 145.8 //多次测试稳定都是145纳秒

Measuring Peak Injection Memory Bandwidths for the system
Bandwidths are in MB/sec (1 MB/sec = 1,000,000 Bytes/sec)
Using all the threads from each core if Hyper-threading is enabled
Using traffic with the following read-write ratios
ALL Reads : 110598.7
3:1 Reads-Writes : 93408.5
2:1 Reads-Writes : 89249.5
1:1 Reads-Writes : 64137.3
Stream-triad like: 77310.4

Measuring Memory Bandwidths between nodes within system
Bandwidths are in MB/sec (1 MB/sec = 1,000,000 Bytes/sec)
Using all the threads from each core if Hyper-threading is enabled
Using Read-only traffic type
Numa node
Numa node 0
0 110598.4

Measuring Loaded Latencies for the system
Using all the threads from each core if Hyper-threading is enabled
Using Read-only traffic type
Inject Latency Bandwidth
Delay (ns) MB/sec
==========================
00000 506.00 111483.5
00002 505.74 112576.9
00008 505.87 112644.3
00015 508.96 112643.6
00050 574.36 112701.5

当两个参数都为 on 时的mlc 测试结果:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
#./mlc
Intel(R) Memory Latency Checker - v3.9
Measuring idle latencies (in ns)...
Numa node
Numa node 0 1
0 81.6 145.9
1 144.9 81.2

Measuring Peak Injection Memory Bandwidths for the system
Bandwidths are in MB/sec (1 MB/sec = 1,000,000 Bytes/sec)
Using all the threads from each core if Hyper-threading is enabled
Using traffic with the following read-write ratios
ALL Reads : 227204.2
3:1 Reads-Writes : 212432.5
2:1 Reads-Writes : 210423.3
1:1 Reads-Writes : 196677.2
Stream-triad like: 189691.4

说明:mlc和 lmbench 测试结果不一样,mlc 时81和145,lmbench测试是68和100,这是两种测试方法的差异而已,但是快慢差距基本是一致的

结论

在OS 启动引导参数里设置 numa=off 完全没有必要、也不能解决抖动的问题,反而设置了 numa=off 只能是掩耳盗铃,让用户看不到 NUMA 结构

0%