碰到一个奇怪的问题， tcp 抓包看数据已经发送， access log 看 14s 之后才正常处理

[DeadLion]

压测的时候发现有些请求响应超时，比例大概有 0.2%左右。后来 tcpdump 抓包发现 client 已经建立连接发送了请求，看请求的报文也是正常的。

然后压测端一直没收到响应，3s 主动断开请求了。

诡异的是根据 traceid 去查 access log ，发现有正常处理，但是日志的时间晚了 14s ，request_time 是正常 100+ms 。

这延迟的时间是啥情况？想不明白，请大神指点。

[cyhou]

async Access log ？

[des]

那和服务端抓包对比呢？

[mahone3297]

画出你的架构图，看数据到底卡在哪个地方了？前端 nginx ？后端 server ？

[julyclyde]

你 upstream 反应速度太慢导致的

[DeadLion]

@julyclyde request_time 包含了 upstream response time ，response time 也很短 100ms 以内。
@cyhou 比对了下相邻的一些请求时间 抓包时间和 access log 时间是同步的。
@des access log 一切正常，也就是说 ng 到 upstream 的时间应该都没问题。都是正常处理了的。
@mahone3297 很简单的架构，一个 ng 代理了微服务几个节点，另外一个压测机去压 ng 。ng 的 access 日志显示正常的，所有请求都处理了。没有超时的，抓包是在 ng 的机器上抓包，如上图所示，压测机的请求正常发过来了，但是 ng 没有立即响应，通过 access log 看，ng 是在 14 秒之后才收到这个请求。

[julyclyde]

@DeadLion 什么叫“14 秒之后才收到”呢？具体是指日志里哪个字段？

[DeadLion]

@julyclyde 打印日志的时间戳

[bantianys]

我觉得可以试试用 wireshark 在压测端和 NG 端分别抓包对比，对比的图表可以用 wireshark 的 http.time 过滤器对应的 IO Graph 。

[julyclyde]

@DeadLion access_log 是在处理完毕请求的时候记录的，不是在收到请求的时候记录的

[Georgedoe]

可能堆积在某个地方的队列里了