plantegg

java tcp mysql performance network docker Linux

发表于 更新于 分类于

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

本来这是我计划在知识星球里要写的连续剧，我打算好好多写几篇的(每篇都计划重现一个场景/坑点)，后来没看到任何一个同学参与，这样的话写了你们看完也没有体感，所以我直接公布答案吧，还能节省点你们的时间，记住干货就好：不要开 net.ipv4.tcp_tw_recycle

作为全网最权威/最全面的 net.ipv4.tcp_tw_recycle 问题分析还是从知识星球分享出来，希望更多的人避免踩坑

答案

首先不通了是因为服务端开启了 net.ipv4.tcp_tw_recycle，需要判断握手包的时间得保持递增(T2 - T1 >1)

tcpping 一直是通的，因为服务端没有记录到 T1，T1 是每次 FIN 断开时记录，T2 是每个 SYN 包中携带。当 curl 然后断开时走了 FIN 服务端记录下 T1，下次 tcpping 就可以比较了，所以有一半概率不通，直到 1 分钟后 T1 一直没有跟新，超过 60 秒的 T1 失效，后面连接正常

为什么要有 net.ipv4.tcp_tw_recycle？

net.ipv4.tcp_tw_recycle 是一个 Linux 内核参数，用于控制 TCP 连接的 TIME_WAIT 状态的处理方式。这个参数的主要作用是加速 TIME_WAIT 套接字的回收。

参考：Coping with the TCP TIME-WAIT state on busy Linux servers

PAWS(Protection Against Wrapped Sequences)

TCP 包的 seq 是有限的(4字节 32bit)，会在达到最大值后回绕到零，这种情况称为”seq回绕”，seq 回绕后怎么判断这个 seq 是重复的(丢弃) 还是可以接受的？

引入 PAWS 的目的是确保即使seq 回绕发生，也能正确地处理序列号，除了 seq 外额外在 TCP options 里面增加了 timestamp 来作为维护数据包的seq 正确的判断。时间戳随每个数据包发送，并且单调增加，因此即使序列号回绕，接收方也可以使用时间戳来确定数据包的真实顺序，这就是 PAWS

PAWS会检查syn 网络包的 timestamps ，来判断这个syn包的发送时间是否早于上一次同 ip/stream（3.10 是 per ip/4.10 是 per stream） 的 fin包，如果早就扔掉，这也是导致syn 握手失败的一个高发原因，尤其是在NAT场景下。原本 PAWS 是每个连接的维度，但同时开启tcp_timestamp和tcp_tw_recycle之后，PAWS就变成per host粒度了

1
2
3
timestamp为TCP/IP协议栈提供了两个功能：  
    a. 更加准确的RTT测量数据，尤其是有丢包时  -- RTTM  
    b. 保证了在极端情况下，TCP的可靠性        -- PAWS

不同 OS 内核版本因为 timestamp 生成不一样导致 PAWS 行为还不一样，通过参数来控制：net.ipv4.tcp_timestamps

服务端如何通过判断时间戳来丢包？

对同一个 src-ip 记录最后一次 FIN 包的时间戳为 T1，当这个 src-ip 有 SYN 包时取 SYN 包中的时间戳为 T2

如果 T2-T1 小于 1 就扔掉这个 SYN 包

一旦发生这种 SYN 包被丢弃，对应的监控指标(LINUX_MIB_PAWSPASSIVEREJECTED)：

1
2
3
4
5
6
7
8
9
10
11
12
//第二个指标包含第一个，passive connections rejected 了也一定会是 SYN dropped
#netstat -s |egrep "SYNs to LISTEN sockets dropped|passive connections rejected because"
    960055 passive connections rejected because of time stamp
    1049368 SYNs to LISTEN sockets dropped

#netstat -s |egrep "SYNs to LISTEN sockets dropped|passive connections rejected because"
    960535 passive connections rejected because of time stamp
    1049848 SYNs to LISTEN sockets dropped

#netstat -s |egrep "SYNs to LISTEN sockets dropped|passive connections rejected because"
    961015 passive connections rejected because of time stamp
    1050328 SYNs to LISTEN sockets dropped

这个指标也很重要，我喜欢这种

服务端丢包条件更多细节

服务端设置 net.ipv4.tcp_tw_recycle 为 1 是必要条件，然后同时满足了这两个条件：

  1. (u32)get_seconds() - tm->tcpm_ts_stamp < TCP_PAWS_MSL（=60）：容易满足，几乎总是满足。对比的是本地时间。收到syn的本地时间相比上次收包记录的本地时间，小于60s
  2. (s32)(tm->tcpm_ts - req->ts_recent) > TCP_PAWS_WINDOW（=1）：对比的是tcp时间戳，上次更新的tcp时间戳 - 这次syn的tcp时间戳，大于1（并且小于231）。也就是这次syn的tcp时间戳，如果小于上次记录到的时间戳（ms级），就会被丢掉。

这里tm和req对应什么？一个四元组，还是ip地址，还是其他？3.10对应的是ip地址(不同内核版本不一样)

上次记录的时间戳是什么？注意这里对比的都是tm时间，是在连接关闭相关阶段，通过tcp_remember_stamp或tcp_tw_remember_stamp函数记录的，具体情况比较多。

服务端将客户端的时间戳保存在哪里？

6u(2.6.32)代码：

由于inet_timewait_sock在连接进入tw状态会被释放掉，其中记录最近一次接收报文的timestamp信息会丢失；VJ 的思路，把此tcp stamp信息放入路由cache表的rtable中struct inet_peer中，rtable中只保srcIP，dstIP的PATH信息，没有端口号信息，也就是同src-dstIP(即使端口不同)的所有连接受同一个timestamp限制。

7u(3.10.0)代码：

3.5版本以后的内核版本不再使用rtable记录，tcp stamp信息改为存放在目标地址出接口net中存放的tcp_metrics_block，timestamp判断逻辑跟6u比增加了“如果之前有记录timestamp且在一个MSL内，而本次连接无timestamp时，请求被丢弃”的逻辑，这么修改的原因参见：

https://patchwork.ozlabs.org/patch/380021/

https://patchwork.ozlabs.org/patch/379163/

2017 年的这个讨论https://patchwork.ozlabs.org/project/netdev/patch/20170315203046.158791-1-soheil.kdev@gmail.com/ 要去掉这个全局存放，改成可以按客户端 port 来记录

客户端如何生成时间戳？

  • 3.10 内核是按 客户端 ip 来生成 timestamp，也就是不管跟谁通信都是全局单调递增
  • 4.19(4.12)是按 ip 对（per-destination timestamp**）**来生 timestamp ，也就是一对 ip 之间保证单调递增；
  • 4.10之前是 per-client 生成递增 timestamp ，4.10 改成 per-connection 生成递增 timestamp(导致了兼容 net.ipv4.tcp_tw_recycle问题严重)，4.11 改成 per-destination-host 生成递增 timestamp(downgrade to per-host timestamp offsets)；4.12 去掉 net.ipv4.tcp_tw_recycle 参数永远解决问题

有哪些场景会触发 net.ipv4.tcp_tw_recycle 丢包

服务端的内核参数 net.ipv4.tcp_tw_recycle(4.12内核 中删除这个参数了) 和 net.ipv4.tcp_timestamps 的值都为 1时，服务器会检查每一个 SYN报文中的时间戳（Timestamp，跟同一ip下最近一次 FIN包时间对比），若 Timestamp 不是递增的关系，就扔掉这个SYN包（诊断：netstat -s | grep “ passive connections rejected because of time stamp”），常见触发时间戳非递增场景：

  1. 4.10 内核，一直必现大概率性丢包。4.11 改成了 per-destination host的算法 //内核改来改去也是坑点
  2. tcpping 这种时间戳按连接随机的，必现大概率持续丢包
  3. 同一个客户端通过直连或者 NAT 后两条链路到同一个服务端，客户端生成时间戳是 by dst ip，导致大概率持续丢包
  4. 经过NAT/LVS 后多个客户端被当成一个客户端，小概率偶尔出现——通过 tc qdisc 可以来构造丢包重现该场景
  5. 网路链路复杂/链路长容易导致包乱序，进而出发丢包，取决于网络会小概率出现
  6. 客户端修改 net.ipv4.tcp_timestamps
    • 1->0，触发持续60秒大概率必现的丢包，60秒后恢复
    • 0->1 持续大概率一直丢包60秒; 60秒过后如果网络延时略高且客户端并发大一直有上一次 FIN 时间戳大于后续SYN 会一直概率性丢包持续下去；如果停掉所有流量，重启客户端流量，恢复正常
    • 2->1 丢包，情况同2
    • 1->2 不触发丢包

其它 SYN 连不上的场景延伸阅读：程序员如何学习和构建网络知识体系

一些特殊场景

这些特殊场景很可怕，不知不觉会产生 T2 不大于 T1 的情况，导致连接异常

DNAT/ENAT

请求经过 DNAT 后 Server 端看到的 src-ip 是 client 的 IP，客户端同时通过直连(绿色)和走 LVS(黑色)两条链路就会大概率不通：

image-20240822161109563

没有挥手断开场景

有些 HA 探测都是握手/select 1/ RESET 连接，不走 FIN 四次挥手(比如 Jedis，见小作业应用断开连接的时候如何让 OS 走 RST 流程：https://articles.zsxq.com/id_v0mhaadx3cx5.html )，Server 端没有机会记录 T1，也就永远不会触发丢包，看着一切正常，直到某天来了个用户 curl 一下系统就崩了

比如 Jedis 就是直接 RST 断开连接，从不走 FIN 四次挥手

延伸

如果服务端所用端口是 time_wait 状态，这时新连接 SYN 握手包刚好和 time_wait 的5元组重复，这个时候服务端不会回复 SYN+ACK 而是回复 time_wait 前的ack

其它

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 才合并进内核

参考资料

per-connection random offset：https://lwn.net/Articles/708021/

发表于 更新于 分类于

一次 Sysbench opening tables 卡慢的分析过程

背景

用 Sysbench 随便跑个压力，然后我用如下命令起压力，只达到了我预期的性能的 10%

1
sysbench --mysql-user=root --mysql-password=123 --mysql-db=sbtest --mysql-host=e237 --mysql-port=3306 --tables=64 --threads=256 --table-size=2000000 --range-size=5 --db-ps-mode=disable --skip-trx=on --mysql-ignore-errors=all --time=1200 --report-interval=1 --histogram=off oltp_point_select run

分析

看了下 MySQL 的进程状态，CPU 消耗很低，再看 processlist 都是 Opening tables，这问题我熟啊，table_open_cache 设置太小，直接干大 10 倍，悲催的是性能依然没有任何变化看了下 MySQL 的进程状态，CPU 消耗很低，再看 processlist 都是 Opening tables，这问题我熟啊，table_open_cache 设置太小，直接干大 10 倍，悲催的是性能依然没有任何变化

image-20241022175210162

image-20241023104502834

难道还有别的地方限制了？我去查了下 status 发现 Table_open_cache_overflows 一直是 0，从状态来看 table_open_cache 肯定够了：

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
#mysql -he237 -P3306 -uroot -p123 -e "show global status like '%open%' "
mysql: [Warning] Using a password on the command line interface can be insecure.
+----------------------------+---------+
| Variable_name              | Value   |
+----------------------------+---------+
| Com_ha_open                | 0       |
| Com_show_open_tables       | 0       |
| Innodb_num_open_files      | 48      |
| Open_files                 | 14      |
| Open_streams               | 0       |
| Open_table_definitions     | 159     |
| Open_tables                | 1161    |
| Opened_files               | 173     |
| Opened_table_definitions   | 138     |
| Opened_tables              | 1168    |
| Slave_open_temp_tables     | 0       |
| Table_open_cache_hits      | 8125315 |
| Table_open_cache_misses    | 1168    |
| Table_open_cache_overflows | 0       |
+----------------------------+---------+

#mysql -he237 -P3306 -uroot -p123 -e "show global status like '%Table_open%' "
mysql: [Warning] Using a password on the command line interface can be insecure.
+----------------------------+---------+
| Variable_name              | Value   |
+----------------------------+---------+
| Table_open_cache_hits      | 9039467 |
| Table_open_cache_misses    | 1170    |
| Table_open_cache_overflows | 0       |
+----------------------------+---------+

#mysql -he237 -P3306 -uroot -p123 -e "show global variables like '%Table_open%' "
mysql: [Warning] Using a password on the command line interface can be insecure.
+----------------------------+-------+
| Variable_name              | Value |
+----------------------------+-------+
| table_open_cache           | 8192  |
| table_open_cache_instances | 16    |
+----------------------------+-------+

这些有点难绷，因为我用的别人的 sysbench, 于是自己编译了一个重压性能一下就正常了，于是我开始 dump 别人的 sysbench 完整参数，最后发现是我使用的时候配置错误将：–tables=32 设置成了 –tables=64 也就是我的 database 总共只有 32 张表，而我压测的时候写成了 64 张，还有 32 张表不存在导致。

而别人的 sysbench 默认添加了：–mysql-ignore-errors=all 也就是把报错信息都忽略了，导致控制台看不到异常信息

碰到这种问题怎么办？

我们经常碰到业务代码把报错信息吃掉了(类似设置了 –mysql-ignore-errors=all )，同时 SQL 里面拼错了表明或者写错了 Database 名也导致表不存在

所以这里的必杀技(银弹) 抓包(或者堆栈热点分析)：

image-20241023101835801

上图中只要不是 1146 的都是表明正确的请求，可以看到 RT 是 0.1-0.2 毫秒之间；但是 response Error 1146 报错的 RT 就很大了，同时抓包里 1146 也给出了错误原因

1
2
3
4
5
+-------+------+---------------------------------------+
| Level | Code | Message                               |
+-------+------+---------------------------------------+
| Error | 1146 | Table 'sbtest.sbtest42' doesn't exist |
+-------+------+---------------------------------------+

正常时 50 万 QPS 的 RT：

1
2
3
	 time								port	avg_rt	svc_rt  up_rt    QPS  	drop	rtt
2024-10-23 10:14:57    P3306    227 	 228 	 0 	 532688 	 0 	 34
2024-10-23 10:14:58    P3306    227 	 228 	 0 	 533439 	 0 	 34

异常时 5 万 QPS 的 RT：

1
2
3
4
5
6
7
	 time								port	avg_rt	svc_rt  up_rt    QPS  	drop	rtt
2024-10-23 10:13:56    P3306    2201 	 2201 	 0 	 58910 	 0 	 34
2024-10-23 10:13:57    P3306    2195 	 2195 	 0 	 59141 	 0 	 34
2024-10-23 10:13:58    P3306    2203 	 2203 	 0 	 58923 	 0 	 34
2024-10-23 10:13:59    P3306    2190 	 2191 	 0 	 59266 	 0 	 34
2024-10-23 10:14:00    P3306    2198 	 2198 	 0 	 59018 	 0 	 34
2024-10-23 10:14:01    P3306    2242 	 2242 	 0 	 57926 	 0 	 34

从 RT 确实可以看出来是 3306 端口返回/响应慢了，我在 MySQLD 的日志里也搜索了，应该是没有记录这种 1146 错误

如果多看几次 processlist 的话还会发现 Opening table 的 SQL 对应的表明都是大于 31 的，表名小的 SQL 就不会出现 Opening table

总结

这个问题我第一时间没有想到抓包，显示根据经验 Opening tables 就是打开表慢了，然后调大 cache 参数，还不好用就觉得超出我的理解有点慌！

然后想到去比较参数/版本的差异，运气好发现了参数的差异；如果运气不好我重新编译然后复制白屏的命令参数估计还是发现不了。

所以我在想有什么更好的办法能识别这种问题，最后的结论居然还是抓个包看看，并且真管用，正好和这篇方法论呼应一下：https://articles.zsxq.com/id_mnp5z56gl0wi.html

延伸

很多时候开发很坑人，把业务异常堆栈吃了不输出，就拿这个例子来说也有业务写错表名，然后报错又不输出就会出现和问题一样的问题，导致分析问题的时候发现很奇怪好好的系统就是慢，这个时候除了抓包还可以通过 perf/jstack 去看看堆栈，抓下热点

推上也有一些讨论，可以参考下别人的思路：https://x.com/plantegg/status/1851066206163521712

发表于 更新于 分类于

一次网络连接残留的分析

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

问题描述

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_only、oltp_read_write、oltp_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 就能稳定恢复

参考资料

一个类似的bug 和 https://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本身的错误代码不同，它们来自于操作系统，表示尝试建立网络连接时遇到了错误。错误码99 和 111 具体代表以下含义：

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

解决错误99通常需要确保客户端是在向正确配置的地址发起连接，而解决错误111则可能需要检查MySQL服务是否运行、防火墙的设置以及my.cnf或my.ini中bind-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

发表于 更新于 分类于

历时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

0%