plantegg

java tcp mysql performance network docker Linux

发表于 更新于 分类于

AWS RDS MySQL 蓝绿部署升级完整指南

概述

本文档基于实际测试记录，详细介绍AWS RDS MySQL从5.7升级到8.0的蓝绿部署全过程。

测试环境:

  • 源版本: MySQL 5.7.44-rds.20251212
  • 目标版本: MySQL 8.0.40
  • 实例类型: db.m5.large (2vCPU, 8GB)
  • Multi-AZ: 启用
  • 区域: ap-southeast-1

蓝绿部署流程图

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
┌─────────────────────────────────────────────────────────────────────────────┐
│                         蓝绿部署升级完整流程                                  │
├─────────────────────────────────────────────────────────────────────────────┤
│                                                                             │
│  阶段1              阶段2              阶段3              阶段4              │
│  创建读副本          版本升级            配置备份            执行切换           │
│  ┌─────────┐       ┌─────────┐       ┌─────────┐       ┌─────────┐        │
│  │蓝环境    │       │绿环境    │       │绿环境    │       │绿环境    │        │
│  │MySQL5.7 │──复制─▶│MySQL5.7 │──升级─▶│MySQL8.0 │──切换─▶│MySQL8.0│        │
│  │(生产)    │       │(副本)   │        │(就绪)   │       │(新生产)  │        │
│  └─────────┘       └─────────┘       └─────────┘       └─────────┘        │
│       │                 │                 │                 ▲              │
│       │                 │                 │                 │              │
│       └─────────────────┴─────────────────┴─────────────────┘              │
│                        持续数据同步                                         │
│                                                                             │
│  耗时: 10-20分钟      耗时: 10-20分钟    耗时: 几分钟      耗时: 1-5分钟     	   │
│  业务影响: 零         业务影响: 零       业务影响: 零      业务影响: 短暂     		  │
└─────────────────────────────────────────────────────────────────────────────┘

前置条件

1. 检查当前实例状态

1
2
3
4
aws rds describe-db-instances \
    --db-instance-identifier mysql-test-57 \
    --query 'DBInstances[0].{Status:DBInstanceStatus,Version:EngineVersion,MultiAZ:MultiAZ}' \
    --profile default --region ap-southeast-1

2. 确认可升级的目标版本

1
2
3
4
5
aws rds describe-db-engine-versions \
    --engine mysql \
    --engine-version 5.7 \
    --query 'DBEngineVersions[0].ValidUpgradeTarget[?IsMajorVersionUpgrade==`true`].EngineVersion' \
    --profile default --region ap-southeast-1

3. 确保备份已启用

蓝绿部署要求源实例启用自动备份 (BackupRetentionPeriod > 0)

阶段1: 创建蓝绿部署

命令

1
2
3
4
5
aws rds create-blue-green-deployment \
    --blue-green-deployment-name mysql-57-to-80-upgrade \
    --source arn:aws:rds:XXXX:db:mysql-test-57 \
    --target-engine-version 8.0.40 \
    --profile default --region ap-southeast-1

参数说明

参数 说明
--blue-green-deployment-name 部署名称，用于标识
--source 源实例的ARN
--target-engine-version 目标MySQL版本

返回示例

1
2
3
4
5
6
7
8
9
10
11
{
    "BlueGreenDeployment": {
        "BlueGreenDeploymentIdentifier": "bgd-xen1mlsjdt6hlt8r",
        "Status": "PROVISIONING",
        "Tasks": [
            {"Name": "CREATING_READ_REPLICA_OF_SOURCE", "Status": "PENDING"},
            {"Name": "DB_ENGINE_VERSION_UPGRADE", "Status": "PENDING"},
            {"Name": "CONFIGURE_BACKUPS", "Status": "PENDING"}
        ]
    }
}

阶段2: 监控部署进度

查看部署状态

1
2
3
aws rds describe-blue-green-deployments \
    --blue-green-deployment-identifier bgd-xen1mlsjdt6hlt8r \
    --profile default --region ap-southeast-1

任务状态说明

任务 说明 预计耗时
CREATING_READ_REPLICA_OF_SOURCE 创建源实例的读副本 10-20分钟
DB_ENGINE_VERSION_UPGRADE 升级绿环境到目标版本 10-20分钟
CONFIGURE_BACKUPS 配置备份策略 几分钟

状态流转

1
PROVISIONING → AVAILABLE → SWITCHOVER_IN_PROGRESS → SWITCHOVER_COMPLETED

查看绿环境实例详情

1
2
3
4
5
# 绿环境实例名称格式: {源实例名}-green-{随机字符}
aws rds describe-db-instances \
    --db-instance-identifier mysql-test-57-green-b66gdf \
    --query 'DBInstances[0].{Status:DBInstanceStatus,Version:EngineVersion}' \
    --profile default --region ap-southeast-1

阶段3: 执行切换 (Switchover)

前置检查

确保部署状态为 AVAILABLE:

1
2
3
4
aws rds describe-blue-green-deployments \
    --blue-green-deployment-identifier bgd-xen1mlsjdt6hlt8r \
    --query 'BlueGreenDeployments[0].Status' \
    --profile default --region ap-southeast-1

执行切换命令

1
2
3
4
aws rds switchover-blue-green-deployment \
    --blue-green-deployment-identifier bgd-xen1mlsjdt6hlt8r \
    --switchover-timeout 300 \
    --profile default --region ap-southeast-1

参数说明

参数 说明
--blue-green-deployment-identifier 蓝绿部署ID
--switchover-timeout 切换超时时间(秒)，默认300

切换过程详解

1
2
3
4
5
6
7
8
9
10
11
切换时间线 (实测数据):
────────────────────────────────────────────────────────────────
08:33:35  切换开始，TPS正常 (~263)
08:33:51  TPS开始下降，出现错误 (err/s: 142)
08:33:52  TPS=0，写入完全阻塞
08:36:47  连接完全中断 (QPS=0)
08:37:00  DNS切换完成
08:37:30  切换完成，连接恢复
────────────────────────────────────────────────────────────────
总切换时间: ~4分钟
完全断连时间: ~28秒

切换期间的实例名称变化

1
2
3
4
5
6
7
切换前:
  mysql-test-57          → MySQL 5.7 (生产)
  mysql-test-57-green-xxx → MySQL 8.0 (绿环境)

切换后:
  mysql-test-57          → MySQL 8.0 (新生产，原绿环境)
  mysql-test-57-old1     → MySQL 5.7 (原生产，可用于回滚)

阶段4: 验证升级结果

检查切换状态

1
2
3
4
aws rds describe-blue-green-deployments \
    --blue-green-deployment-identifier bgd-xen1mlsjdt6hlt8r \
    --query 'BlueGreenDeployments[0].{Status:Status,StatusDetails:StatusDetails}' \
    --profile default --region ap-southeast-1

验证新版本

1
2
3
4
aws rds describe-db-instances \
    --db-instance-identifier mysql-test-57 \
    --query 'DBInstances[0].EngineVersion' \
    --profile default --region ap-southeast-1

连接验证

1
2
mysql -h mysql-test-57.XXX.rds.amazonaws.com \
    -P 3306 -u admin -p -e "SELECT VERSION();"

阶段5: 清理资源

删除蓝绿部署 (保留旧实例)

1
2
3
aws rds delete-blue-green-deployment \
    --blue-green-deployment-identifier bgd-xen1mlsjdt6hlt8r \
    --profile default --region ap-southeast-1

删除蓝绿部署 (同时删除旧实例)

1
2
3
4
aws rds delete-blue-green-deployment \
    --blue-green-deployment-identifier bgd-xen1mlsjdt6hlt8r \
    --delete-target \
    --profile default --region ap-southeast-1

手动删除旧实例 (如需要)

1
2
3
4
aws rds delete-db-instance \
    --db-instance-identifier mysql-test-57-old1 \
    --skip-final-snapshot \
    --profile default --region ap-southeast-1

回滚方案

如果升级后发现问题，可以快速回滚:

方法1: 切换回旧实例 (推荐)

在删除蓝绿部署前，旧实例 (mysql-test-57-old1) 仍然可用:

1
2
# 修改应用连接字符串指向旧实例
# mysql-test-57-old1.XXXX.amazonaws.com

方法2: 从快照恢复

1
2
3
4
aws rds restore-db-instance-from-db-snapshot \
    --db-instance-identifier mysql-test-57-restored \
    --db-snapshot-identifier <snapshot-id> \
    --profile default --region ap-southeast-1

实测性能数据

测试配置

  • sysbench oltp_read_write
  • 16表 × 100,000行
  • 8并发线程

性能对比

指标 MySQL 5.7 MySQL 8.0 变化
TPS 263 288 +9.5%
QPS 5,284 5,760 +9.0%
95%延迟 35ms 35ms 持平

切换影响

指标 数值
蓝绿部署总耗时 42分钟
切换总耗时 4分钟
完全断连时间 28秒
数据丢失 0

最佳实践

1. 时间选择

  • 选择业务低峰期执行切换
  • 预留足够的监控和回滚时间

2. 监控准备

  • 提前配置CloudWatch告警
  • 准备实时监控脚本

3. 应用适配

  • 确保应用支持MySQL 8.0语法
  • 测试连接池的重连机制
  • 配置合理的连接超时

4. 回滚准备

  • 保留旧实例至少24小时
  • 准备回滚脚本和流程

5. 通知机制

  • 提前通知相关团队
  • 准备故障升级流程

常见问题

Q1: 蓝绿部署创建失败

原因: 源实例未启用自动备份
解决: 

1
2
3
4
aws rds modify-db-instance \
    --db-instance-identifier mysql-test-57 \
    --backup-retention-period 7 \
    --apply-immediately

Q2: 切换超时

原因: 数据同步延迟过大
解决: 增加 --switchover-timeout 值，或等待复制追平

Q3: 切换后应用连接失败

原因: DNS缓存或连接池未刷新
解决: 重启应用或刷新连接池

参考命令汇总

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
# 1. 创建蓝绿部署
aws rds create-blue-green-deployment \
    --blue-green-deployment-name <name> \
    --source <source-arn> \
    --target-engine-version <version>

# 2. 查看部署状态
aws rds describe-blue-green-deployments \
    --blue-green-deployment-identifier <bgd-id>

# 3. 执行切换
aws rds switchover-blue-green-deployment \
    --blue-green-deployment-identifier <bgd-id> \
    --switchover-timeout 300

# 4. 删除部署
aws rds delete-blue-green-deployment \
    --blue-green-deployment-identifier <bgd-id>

基于实际测试环境: AWS ap-southeast-1, Account XXXX

发表于 更新于 分类于

问题：为什么你的 SYN 包被丢了——求答案

江湖有个传说：一旦设置了 net.ipv4.tcp_tw_recycle 在 NAT 场景下(多个客户端经过一个 LVS 访问一个服务端，NAT 后服务端看到的客户端是同一个 IP) 就会发生丢包

也可以看看这节：https://xiaolincoding.com/network/3_tcp/syn_drop.html#%E5%9D%91%E7%88%B9%E7%9A%84-tcp-tw-recycle

我们来重现和分析一下这个问题，这应该会是个连续剧，我会根据大家实验情况来推进后面的内容

客户端

我们默认 99 的 ECS 就行，默认配置。

1
yum install tcptraceroute //装一下这个工具，可以对端口进行探测

想要持续对端口探测，类似 ping 一样，就装一下下面的 shell 脚本(tcpping , tcpping 里面会调用 tcptraceroute )：

介绍：http://www.vdberg.org/~richard/tcpping.html

脚本我放仓库里了：https://github.com/plantegg/programmer_case/commit/7c59a7d3666db2fe5af9ba598104cd88cad52497

探测端口通不通：

1
tcpping -d 1.2.3.4 22

通的话会收到：

1
seq 0: tcp response from e237  <syn,ack>  0.088 ms

端口不存在肯定不通，且会被 RST

1
seq 3: tcp response from e237  <rst,ack>  0.076 ms

端口在但是偶尔不通，是今天的主角：

1
2
3
4
5
6
Thu Aug  8 16:48:44 CST 2024
traceroute to , 255 hops max, 60 byte packets
seq 13: tcp response from  <syn,ack>  28.850 ms //通
Thu Aug  8 16:48:52 CST 2024
traceroute to , 255 hops max, 60 byte packets
seq 21: no response (timeout)  //不通

服务端

建议找一个 3.10 内核的机器，4.13 开始已经没有 tcp_tw_recycle 这个参数了

1
2
3
4
5
6
#sysctl -a |egrep "recycle|timestamp"
net.ipv4.tcp_timestamps = 1
net.ipv4.tcp_tw_recycle = 1 //这个参数默认是 0，必须改成 1

#uname -r
3.10.0-1062.18.1.el7.x86_64  //我在阿里云上买的一个 CentOS7，版本只要是 4.12 之前的都行

实验步骤

  1. 服务端随便起一个 http 服务端口，比如 1234
  2. 在客户端上执行 tcpping -d 服务端 ip 1234 //这一步可以看到 100% 是通的
  3. 在客户端执行下 curl 服务端 ip:1234 //可以很快看到 tcpping 开始报偶尔通/偶尔不通

重现效果，如下图，本来一次都没有 timeout，但我 curl 一下立即就 timeout 了

img

请分析，为什么 curl 一下 tcpping 就不通了？

发表于 更新于 分类于

跨 Die 热迁移迁移导致的性能问题

场景

在 ARM 上，本来业务跑在 Die0 上，如果通过taskset 将 CPU 绑到 Die1，经过一段时间运行，内存也会慢慢随着释放/新分配慢慢都迁移到 Die1， 但是这之后仍然发现性能比在 Die0 上要差很多。而在 Intel X86 上没碰到过这个问题

分析

下图是内存带宽使用率监控数据，可以看到跨 Die 绑定后原来的 Die0 带宽急剧增加（7.5% -> 13%）这是因为内存都需要跨 Die 访问了，随着跨 Die 访问并慢慢将内存迁移到 Die1 后内存带宽使用率回落到 5%：

img

同时可以看到 CPU 使用率也从 35% 飙升到 76%，随着内存的迁移完毕，CPU 使用率回落到 48%，但仍然比最开始的 35% 高不少：

img

Intel X86 下跨 Die 迁移

Intel 基本都是一路就是一个 Die，所以你可以理解这里的跨 Die 就是跨路/Socket 迁移：

img

img

结论

ARM 比 X86 差这么多的原因是内存页表跨 Die 访问导致的，业务同学测试了开启 THP 负载的影响，从结果看，THP on 可有效降低cpu水位，但是依然存在跨die迁移cpu水位上升的问题。

alios 对应的 patch：https://gitee.com/anolis/cloud-kernel/pulls/2254/commits 不区分 x86 和 arm

页表是进程创建时在内核空间分配好的，所以迁移内存时并不会迁移页表。通过测试页表跨die迁移的poc，验证了跨die页表访问是导致本文所述问题的根本原因

课后作业：

去了解下内存页表/THP(透明大页)

学习 CPU 访问内存延时是怎么回事，然后学习 CPU 和内存速度的差异，最后再去看看大学的计算机组成原理

学习下 taskset/perf 等命令

发表于 更新于 分类于

CPU 使用率高就一定有效率吗？

背景

最近碰到一个客户业务跑在8C ECS 上，随着业务压力增加 CPU使用率也即将跑满，于是考虑将 8C 升级到16C，事实是升级后业务 RT 反而略有增加，这个事情也超出了所有程序员们的预料，所以我们接下来分析下这个场景

分析

通过采集升配前后、以前和正常时段的火焰图对比发现CPU 增加主要是消耗在 自旋锁上了：

image-20240202085410669

用一个案例来解释下自旋锁和锁，如果我们要用多线程对一个整数进行计数，要保证线程安全的话，可以加锁(synchronized), 这个加锁操作也有人叫悲观锁，抢不到锁就让出这个线程的CPU 调度(代价上下文切换一次，几千个时钟周期)

另外一种是用自旋锁(CAS、spin_lock) 来实现，抢不到锁就耍赖占住CPU 死磕不停滴抢(CPU 使用率一直100%)，自旋锁的设计主要是针对抢锁概率小、并发低的场景。这两种方案针对场景不一样各有优缺点

假如你的机器是8C，你有100个线程来对这个整数进行计数的话，你用synchronized 方式来实现会发现CPU 使用率永远达不到50%

image-20240202090428778

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
#taskset -a -c 56-63 java LockAccumulator 100 1000000000
累加结果: 1000000000 and time:84267

Performance counter stats for 'taskset -a -c 56-63 java -Djava.library.path=. LockAccumulator 100 100000000':

      17785.271791      task-clock (msec)         #    2.662 CPUs utilized
           110,351      context-switches          #    0.006 M/sec
            10,094      cpu-migrations            #    0.568 K/sec
            11,724      page-faults               #    0.659 K/sec
    44,187,609,686      cycles                    #    2.485 GHz
   <not supported>      stalled-cycles-frontend
   <not supported>      stalled-cycles-backend
    22,588,807,670      instructions              #    0.51  insns per cycle
     6,919,355,610      branches                  #  389.050 M/sec
        28,707,025      branch-misses             #    0.41% of all branches

如果我们改成自旋锁版本的实现，8个核CPU 都是100%

image-20240202090714845

以下代码累加次数只有加锁版本的10%，时间还长了很多，也就是效率产出实在是低

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 100 100000000
累加结果: 100000000
操作耗时: 106593 毫秒

 Performance counter stats for 'taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 100 100000000':

      85363.429249      task-clock (msec)         #    7.909 CPUs utilized
            23,010      context-switches          #    0.270 K/sec
             1,262      cpu-migrations            #    0.015 K/sec
            13,403      page-faults               #    0.157 K/sec
   213,191,037,155      cycles                    #    2.497 GHz
   <not supported>      stalled-cycles-frontend
   <not supported>      stalled-cycles-backend
    43,523,454,723      instructions              #    0.20  insns per cycle
    10,306,663,291      branches                  #  120.739 M/sec
        14,704,466      branch-misses             #    0.14% of all branches

代码

我放在了github 上，有个带调X86 平台 pause 指令的汇编，Java 中要用JNI 来调用，ChatGPT4帮我写的，并给了编译、运行方案：

1
2
3
4
5
6
7
8
9
10
javac SpinLockAccumulator.java
javah -jni SpinLockAccumulator

# Assuming GCC is installed and the above C code is in SpinLockAccumulator.c
gcc -shared -o libpause.so -fPIC SpinLockAccumulator.c

java -Djava.library.path=. SpinLockAccumulator

实际gcc编译要带上jdk的头文件：
gcc -I/opt/openjdk/include/ -I/opt/openjdk/include/linux/ -shared -o libpause.so  -fPIC SpinLockAccumulator.c

在MySQL INNODB 里怎么优化这个自旋锁

MySQL 在自旋锁抢锁的时候每次会调 ut_delay（底层会掉CPU指令，让CPU暂停一下但是不让出——避免上下文切换），发现性能好了几倍。这是MySQL 的官方文档：https://dev.mysql.com/doc/refman/5.7/en/innodb-performance-spin_lock_polling.html

所以我们继续在以上代码的基础上在自旋的时候故意让CPU pause(50个), 这个优化详细案例：https://plantegg.github.io/2019/12/16/Intel%20PAUSE%E6%8C%87%E4%BB%A4%E5%8F%98%E5%8C%96%E6%98%AF%E5%A6%82%E4%BD%95%E5%BD%B1%E5%93%8D%E8%87%AA%E6%97%8B%E9%94%81%E4%BB%A5%E5%8F%8AMySQL%E7%9A%84%E6%80%A7%E8%83%BD%E7%9A%84/

该你动手了

随便找一台x86 机器，笔记本也可以，macOS 也行，核数多一些效果更明显。只要有Java环境，就用我编译好的class、libpause.so 理论上也行，不兼容的话按代码那一节再重新编译一下

可以做的实验：

  • 重复我前面两个运行，看CPU 使用率以及最终耗时
  • 尝试优化待pause版本的自旋锁实现，是不是要比没有pause性能反而要好
  • 尝试让线程sleep 一下，效果是不是要好？
  • 尝试减少线程数量，慢慢是不是发现自旋锁版本的性能越来越好了

改变线程数量运行对比：

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
//自旋锁版本线程数对总时间影响很明显，且线程少的话性能要比加锁版本好，这符合自旋锁的设定:大概率不需要抢就用自旋锁
#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 1 100000000
累加结果: 100000000
操作耗时: 2542 毫秒

#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 2 100000000
累加结果: 100000000
操作耗时: 2773 毫秒

#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 4 100000000
累加结果: 100000000
操作耗时: 4109 毫秒

#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 8 100000000
累加结果: 100000000
操作耗时: 11931 毫秒

#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 16 100000000
累加结果: 100000000
操作耗时: 13476 毫秒


//加锁版本线程数变化对总时间影响不那么大
#taskset -a -c 56-63 java -Djava.library.path=. LockAccumulator 16 100000000
累加结果: 100000000 and time:9074

#taskset -a -c 56-63 java -Djava.library.path=. LockAccumulator 8 100000000
累加结果: 100000000 and time:8832

#taskset -a -c 56-63 java -Djava.library.path=. LockAccumulator 4 100000000
累加结果: 100000000 and time:7330

#taskset -a -c 56-63 java -Djava.library.path=. LockAccumulator 2 100000000
累加结果: 100000000 and time:6298

#taskset -a -c 56-63 java -Djava.library.path=. LockAccumulator 1 100000000
累加结果: 100000000 and time:3143

设定100并发下，改变机器核数对比：

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
//16核机器跑3次 耗时稳定在12秒以上，CPU使用率 1600%
#taskset -a -c 48-63 java -Djava.library.path=. SpinLockAccumulator 100 10000000
累加结果: 10000000
操作耗时: 12860 毫秒

#taskset -a -c 48-63 java -Djava.library.path=. SpinLockAccumulator 100 10000000
累加结果: 10000000
操作耗时: 12949 毫秒

#taskset -a -c 48-63 java -Djava.library.path=. SpinLockAccumulator 100 10000000
累加结果: 10000000
操作耗时: 13692 毫秒

//8核机器跑3次，耗时稳定5秒左右，CPU使用率 800%
#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 100 10000000
累加结果: 10000000
操作耗时: 6773 毫秒

#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 100 10000000
累加结果: 10000000
操作耗时: 5557 毫秒

#taskset -a -c 56-63 java -Djava.library.path=. SpinLockAccumulator 100 10000000
累加结果: 10000000
操作耗时: 2724 毫秒

总结

以后应该不会再对升配后CPU 使用率也上去了，但是最终效率反而没变展现得很惊诧了

从CPU 使用率、上下文切换上理解自旋锁(乐观锁)和锁(悲观锁)

MySQL 里对自旋锁的优化，增加配置 innodb_spin_wait_delay 来增加不同场景下DBA 的干预手段

这篇文章主要功劳要给 ChatGPT4 ，里面所有演示代码都是它完成的

相关阅读

流量一样但为什么CPU使用率差别很大 同样也是跟CPU 要效率，不过这个案例不是因为自旋锁导致CPU 率高，而是内存延时导致的

今日短平快，ECS从16核升配到48核后性能没有任何提升（Netflix） 也是CPU 使用率高没有产出，cacheline伪共享导致的

听风扇声音来定位性能瓶颈

你要是把这个案例以及上面三个案例综合看明白了，相当于把计算机组成原理就学明白了。这里最核心的就是“内存墙”，也就是内存速度没有跟上CPU的发展速度，导致整个计算机内绝大多场景下读写内存缓慢成为主要的瓶颈

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

find me on twitter: @plantegg

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

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

争取在星球内：

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

发表于 更新于 分类于

为什么你的 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/

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

find me on twitter: @plantegg

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

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

争取在星球内：

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

发表于 更新于 分类于

一次 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

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

find me on twitter: @plantegg

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

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

争取在星球内：

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

发表于 更新于 分类于

一次网络连接残留的分析

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

问题描述

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 的使用

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

find me on twitter: @plantegg

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

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

争取在星球内：

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

发表于 更新于 分类于

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 这个幅度的上涨不会触发新建连接

不知道我解释清楚了没有

0%