碰到一个奇怪的问题, tcp 抓包看数据已经发送, access log 看 14s 之后才正常处理 - V2EX
V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
DeadLion
V2EX    NGINX

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

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

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

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

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

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

    第 1 条附言    2023-08-17 17:41:23 +08:00
    最终的结果是,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     Solana     4981 人在线   最高记录 6679       Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 44ms UTC 01:19 PVG 09:19 LAX 17:19 JFK 20:19
    Do have faith in what you're doing.
    ubao msn snddm index pchome yahoo rakuten mypaper meadowduck bidyahoo youbao zxmzxm asda bnvcg cvbfg dfscv mmhjk xxddc yybgb zznbn ccubao uaitu acv GXCV ET GDG YH FG BCVB FJFH CBRE CBC GDG ET54 WRWR RWER WREW WRWER RWER SDG EW SF DSFSF fbbs ubao fhd dfg ewr dg df ewwr ewwr et ruyut utut dfg fgd gdfgt etg dfgt dfgd ert4 gd fgg wr 235 wer3 we vsdf sdf gdf ert xcv sdf rwer hfd dfg cvb rwf afb dfh jgh bmn lgh rty gfds cxv xcv xcs vdas fdf fgd cv sdf tert sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf shasha9178 shasha9178 shasha9178 shasha9178 shasha9178 liflif2 liflif2 liflif2 liflif2 liflif2 liblib3 liblib3 liblib3 liblib3 liblib3 zhazha444 zhazha444 zhazha444 zhazha444 zhazha444 dende5 dende denden denden2 denden21 fenfen9 fenf619 fen619 fenfe9 fe619 sdf sdf sdf sdf sdf zhazh90 zhazh0 zhaa50 zha90 zh590 zho zhoz zhozh zhozho zhozho2 lislis lls95 lili95 lils5 liss9 sdf0ty987 sdft876 sdft9876 sdf09876 sd0t9876 sdf0ty98 sdf0976 sdf0ty986 sdf0ty96 sdf0t76 sdf0876 df0ty98 sf0t876 sd0ty76 sdy76 sdf76 sdf0t76 sdf0ty9 sdf0ty98 sdf0ty987 sdf0ty98 sdf6676 sdf876 sd876 sd876 sdf6 sdf6 sdf9876 sdf0t sdf06 sdf0ty9776 sdf0ty9776 sdf0ty76 sdf8876 sdf0t sd6 sdf06 s688876 sd688 sdf86