一个诡异的 200ms 延迟问题排查过程

jinchanchan

最近生产环境 Nginx 遇到了部分请求延迟增加200ms的情况，深入排查解决后觉得挺有意义的（包括排查过程），所以这里记录分享一下。
0x01 现象生产环境有 Nginx 网关，网关上游（upstream）是业务应用。统计发现 Nginx 的 P99 延迟比上游应用统计的 P99 延迟要多大约 100 多毫秒（不同接口时间可能不同）。

Qwen3.7Max 测了一波有点用不起啊！

Qwen3.7Max 测了一波有点用不起啊！

Qwen3.7Max 测了一波有点用不起啊！

0x02 200ms 的来源Nginx 中是通过内置 $request_time 变量来获取的单个请求的延迟，在生产环境开启日志记录，发现部分请求延迟超过 200ms，但是上游响应时间只有 20 毫秒左右（下图红圈中依次为：$request_time、$status 、$body_bytes_sent、$upstream_response_time）。也就是说这些请求在 Nginx 内部处理了超过 200ms，显然这不正常。

Qwen3.7Max 测了一波有点用不起啊！

0x03 深入排查通过日志确定了是 Nginx 的原因，那就从 Nginx 上查起。既然偶现延迟，那就先看是否是系统资源不足导致的问题。

3.1 系统资源

系统资源的排查比较简单，登陆 Nginx 所在的机器，使用 top 等命令（或者使用监控）分析 CPU、内存等资源。

Qwen3.7Max 测了一波有点用不起啊！

也可以通过 pidstat 命令指定查看 Nginx 进程的资源占用信息。

<font color="#333333"><font style="background-color:rgb(248, 248, 248)"><font face="Menlo, Monaco, Consolas, " "=""><font style="font-size: 12px">| grep nginx | grep -v grep | awk </font></font></font></font><font color="#dd1144"><font face="Menlo, Monaco, Consolas, " "=""><font style="font-size: 12px">'BEGIN {print "pidstat \\"} {print "-p "$2" \\"} END {print "1"}'</font></font></font><font color="#333333"><font style="background-color:rgb(248, 248, 248)"><font face="Menlo, Monaco, Consolas, " "=""><font style="font-size: 12px"> | bash</font></font></font></font>

Qwen3.7Max 测了一波有点用不起啊！

通过排查，并未发现系统资源不足的情况。
3.2 通过日志排查原因

Qwen3.7Max 测了一波有点用不起啊！

系统资源充足，只能从其它维度入手进行排查，既然延迟产生的频率不高，那有没有可能跟某一个其它指标相关联呢，如：上游服务、请求包大小等。这个可以通过日志入手，配合 awk 等命令进行统计。

Qwen3.7Max 测了一波有点用不起啊！

上图表明，延迟跟请求包大小没有关联，使用相同的办法统计延迟与上游服务、响应包大小等的关联数据，同样没有发现有任何关联关系。

3.3 抓包

一些简单、直接的排查方案没法确定问题，那就只能上大杀器：tcpdump 抓包了。其实 Nginx 延迟再高，也不至于超过 200ms，能让 Nginx 出现有如此高的延迟基本上也只有网络了。如果一开始就直接上抓包也是没有太大问题的。

直接在客户端和服务端使用 tcpdump 命令进行抓包：

Qwen3.7Max 测了一波有点用不起啊！

由于抓取到的是所有的请求包，要定位到某一个特定的请求会比较困难，好在请求 header 头中有一个 Request-Id 的头，在 Nginx 日志添加变量 $http_request_id 的输出，这样可以通过日志快速定位到某个请求：

Qwen3.7Max 测了一波有点用不起啊！

拿到请求ID，使用 tshark 命令过滤出包含请求ID的 TCP 连接。

tshark -r 1228_10.pcap -Y 'http contains "44aaf9b83bb24fed9f81d3bfcc0af605"' -e tcp.stream -e http.request.full_uri -T fields

随后在 wireshark 中使用 tcp.stream==212487 即可过滤出对应的 TCP 连接。最终的抓包（左边客户端、右边服务端）如下：

Qwen3.7Max 测了一波有点用不起啊！

我们分析一下右边服务端的抓包，主要问题在于 11 号和 12 号包顺序乱了，于是内核丢掉了两个包，并且发送了 13 号 ACK 包，告知客户端 6 号包之后的包没收到，客户端在等待 200ms 后重传 14 号 FIN 包。

q13829965214

寻某东ios拉码、破控高手，合作滴滴
Reverse Engineering Expert，The iOS API for JD.com，
Implement the integration with the CK API.，Place an order, check order status, add an address、
Real-name registration, code scanning/referral, etc.，
Can bypass risk controls
TxG:@wanbaolu9394
mail：13829965214@163.com