V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
NGINX
NGINX Trac
3rd Party Modules
Security Advisories
CHANGES
OpenResty
ngx_lua
Tengine
在线学习资源
NGINX 开发从入门到精通
NGINX Modules
ngx_echo
DeadLion
V2EX  ›  NGINX

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

  •  
  •   DeadLion · 2022-09-21 00:15:22 +08:00 · 1591 次点击
    这是一个创建于 554 天前的主题,其中的信息可能已经有所发展或是发生改变。

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

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

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

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

    第 1 条附言  ·  224 天前
    最终的结果是,Prometheus 插件在生成数据的时候会阻塞 worker 进程,因为 luavm 是单线程,所以阻塞的时候会影响到 worker 进程上的业务请求。
    10 条回复    2022-09-21 16:07:27 +08:00
    cyhou
        1
    cyhou  
       2022-09-21 00:20:32 +08:00 via Android
    async Access log ?
    des
        2
    des  
       2022-09-21 01:03:56 +08:00 via iPhone
    那和服务端抓包对比呢?
    mahone3297
        3
    mahone3297  
       2022-09-21 01:08:17 +08:00
    画出你的架构图,看数据到底卡在哪个地方了?前端 nginx ?后端 server ?
    julyclyde
        4
    julyclyde  
       2022-09-21 08:41:32 +08:00
    你 upstream 反应速度太慢导致的
    DeadLion
        5
    DeadLion  
    OP
       2022-09-21 09:40:39 +08:00
    @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
        6
    julyclyde  
       2022-09-21 10:31:37 +08:00
    @DeadLion 什么叫“14 秒之后才收到”呢?具体是指日志里哪个字段?
    DeadLion
        7
    DeadLion  
    OP
       2022-09-21 11:47:16 +08:00
    @julyclyde 打印日志的时间戳
    bantianys
        8
    bantianys  
       2022-09-21 12:17:49 +08:00
    我觉得可以试试用 wireshark 在压测端和 NG 端分别抓包对比,对比的图表可以用 wireshark 的 http.time 过滤器对应的 IO Graph 。
    julyclyde
        9
    julyclyde  
       2022-09-21 12:53:48 +08:00
    @DeadLion access_log 是在处理完毕请求的时候记录的,不是在收到请求的时候记录的
    Georgedoe
        10
    Georgedoe  
       2022-09-21 16:07:27 +08:00
    可能堆积在某个地方的队列里了
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   我们的愿景   ·   实用小工具   ·   3313 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 28ms · UTC 13:12 · PVG 21:12 · LAX 06:12 · JFK 09:12
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.