nginx日志普遍request_time普遍比upstream_response_time多5s左右，打开debug日志发现请求响应完客户端后过了近5s才打印access_log？想请问下nginx打印日志是有什么阻塞了吗？还是其他什么原因？

yi_mor

zchao1995

Hi！

你使用的是什么版本的 nginx，有什么特殊逻辑吗？

On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:

rt

spacewanderlzx

有在 log_by_lua 里面执行什么耗时的逻辑吗？
另外方便贴 debug 日志出来不？

在 2017年12月11日 下午7:56，tokers <zcha...@gmail.com> 写道：
> Hi！
> 你使用的是什么版本的 nginx，有什么特殊逻辑吗？
>
>
> On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:
>>
>> rt
>
> --
>

yi_mor

使用的是原始的nginx，版本是1.10.1，没有其他特殊的逻辑，是纯粹的代理到后端。

在 2017年12月11日星期一 UTC+8下午7:56:28，tokers写道：

Hi！
你使用的是什么版本的 nginx，有什么特殊逻辑吗？

On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:
rt

yi_mor

没有使用lua的模块，都是原生的nginx代理模块。

debug日志：

2017/12/11 14:17:01 [debug] 104925#0: *18879001 http write filter 0000000000000000
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http copy filter: 0 "/mcloud/mag/ProxyForText/idataws/PersonServlet?empNo=80010475&lang=en"
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http finalize request: 0, "/mcloud/mag/ProxyForText/idataws/PersonServlet?empNo=80010475&lang=en" a:1, c:1
2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer add: 18: 5000:1512973026950
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http lingering close handler
2017/12/11 14:17:01 [debug] 104925#0: *18879001 recv: fd:18 -1 of 4096
2017/12/11 14:17:01 [debug] 104925#0: *18879001 recv() not ready (11: Resource temporarily unavailable)
2017/12/11 14:17:01 [debug] 104925#0: *18879001 lingering read: -2
2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer: 18, old: 1512973026950, new: 1512973026950
2017/12/11 14:17:01 [debug] 104925#0: *18879001 post event 00007F6C0720C090
2017/12/11 14:17:01 [debug] 104925#0: *18879001 delete posted event 00007F6C0720C090
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http empty handler
2017/12/11 14:17:02 [debug] 104925#0: *18879001 post event 00007F6C0720C090
2017/12/11 14:17:02 [debug] 104925#0: *18879001 delete posted event 00007F6C0720C090
2017/12/11 14:17:02 [debug] 104925#0: *18879001 http empty handler
2017/12/11 14:17:06 [debug] 104925#0: *18879001 event timer del: 18: 1512973026950
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http lingering close handler
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http request count:1 blk:0
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http close request
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http log handler

中间02-06s没有debug日志。

在 2017年12月11日星期一 UTC+8下午10:53:00，Zexuan Luo写道：

有在 log_by_lua 里面执行什么耗时的逻辑吗？
另外方便贴 debug 日志出来不？

在 2017年12月11日下午7:56，tokers <zcha...@gmail.com> 写道：
> Hi！
> 你使用的是什么版本的 nginx，有什么特殊逻辑吗？
>
>
> On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:
>>
>> rt
>
> --
>

soul11201

1. 首先，不要大惊小怪，http://nginx.org/en/docs/http/ngx_http_core_module.html#lingering_time 这个值默认就是5s

2. access_log 本来就不是实时输出的，有内存缓冲，这是一定的,但具体怎么实现的我也不清楚，可能有点影响，主要原因是 1, 这条或许跟你这个问题一点关系也没有 :)

-----

http://blog.soul11201.com

在 2017年12月12日上午12:30，whust <yi...@126.com>写道：

没有使用lua的模块，都是原生的nginx代理模块。

debug日志：

2017/12/11 14:17:01 [debug] 104925#0: *18879001 http write filter 0000000000000000
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http copy filter: 0 "/mcloud/mag/ProxyForText/idataws/PersonServlet?empNo=80010475&lang=en"
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http finalize request: 0, "/mcloud/mag/ProxyForText/idataws/PersonServlet?empNo=80010475&lang=en" a:1, c:1
2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer add: 18: 5000:1512973026950
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http lingering close handler
2017/12/11 14:17:01 [debug] 104925#0: *18879001 recv: fd:18 -1 of 4096
2017/12/11 14:17:01 [debug] 104925#0: *18879001 recv() not ready (11: Resource temporarily unavailable)
2017/12/11 14:17:01 [debug] 104925#0: *18879001 lingering read: -2
2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer: 18, old: 1512973026950, new: 1512973026950
2017/12/11 14:17:01 [debug] 104925#0: *18879001 post event 00007F6C0720C090
2017/12/11 14:17:01 [debug] 104925#0: *18879001 delete posted event 00007F6C0720C090
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http empty handler
2017/12/11 14:17:02 [debug] 104925#0: *18879001 post event 00007F6C0720C090
2017/12/11 14:17:02 [debug] 104925#0: *18879001 delete posted event 00007F6C0720C090
2017/12/11 14:17:02 [debug] 104925#0: *18879001 http empty handler
2017/12/11 14:17:06 [debug] 104925#0: *18879001 event timer del: 18: 1512973026950
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http lingering close handler
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http request count:1 blk:0
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http close request
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http log handler

中间02-06s没有debug日志。

在 2017年12月11日星期一 UTC+8下午10:53:00，Zexuan Luo写道：

有在 log_by_lua 里面执行什么耗时的逻辑吗？
另外方便贴 debug 日志出来不？

在 2017年12月11日下午7:56，tokers <zcha...@gmail.com> 写道：
> Hi！
> 你使用的是什么版本的 nginx，有什么特殊逻辑吗？
>
>
> On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:
>>
>> rt
>
> --
>

zchao1995

1. 首先，不要大惊小怪，http://nginx.org/en/docs/http/ngx_http_core_module.html#lingering_time 这个值默认就是5s

我猜和这个应该无关，即使 nginx 检测到需要 lingering close，在给下游读事件设置好对应的 handler 和定时器之后，立刻就调用 ngx_http_close_request，继而调用到 ngx_http_free_request，然后各个日志的 handler 都会被执行，包括 access_log，那么 access_log 里包含的 $request_time 被“渲染”出来之后得到的值，就不会包含 lingering_timeout 了 :)

同意，但是和题主的问题应该无关，另外虽然 access_log 有 buffer，但是各个变量字段的“渲染”也是在放入 buffer 之前的，所以和 buffer 造成的延迟应该无关 :)

zchao1995

忽略第一条，不小心看错了 :)

On Tuesday, December 12, 2017 at 10:04:57 AM UTC+8, tokers wrote:

1. 首先，不要大惊小怪，http://nginx.org/en/docs/http/ngx_http_core_module.html#lingering_time 这个值默认就是5s

我猜和这个应该无关，即使 nginx 检测到需要 lingering close，在给下游读事件设置好对应的 handler 和定时器之后，立刻就调用 ngx_http_close_request，继而调用到 ngx_http_free_request，然后各个日志的 handler 都会被执行，包括 access_log，那么 access_log 里包含的 $request_time 被“渲染”出来之后得到的值，就不会包含 lingering_timeout 了 :)

2. access_log 本来就不是实时输出的，有内存缓冲，这是一定的,但具体怎么实现的我也不清楚，可能有点影响，主要原因是 1, 这条或许跟你这个问题一点关系也没有 :)

同意，但是和题主的问题应该无关，另外虽然 access_log 有 buffer，但是各个变量字段的“渲染”也是在放入 buffer 之前的，所以和 buffer 造成的延迟应该无关 :)

spacewanderlzx

你的客户端表现很奇怪，正常情况下 Nginx 应该不会走到 lingering close
环节的，只有在客户端还有数据读的时候下才会走到这一步。但事实上客户端并没有再发送数据，所以直到timeout之后Nginx才完全终结这个请求。
建议抓包看下实际的请求情况？

在 2017年12月12日 上午12:30，whust <yi...@126.com> 写道：
> 没有使用lua的模块，都是原生的nginx代理模块。
>
> debug日志：
>
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 http write filter
> 0000000000000000
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 http copy filter: 0
> "/mcloud/mag/ProxyForText/idataws/PersonServlet?empNo=80010475&lang=en"
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 http finalize request: 0,
> "/mcloud/mag/ProxyForText/idataws/PersonServlet?empNo=80010475&lang=en" a:1,
> c:1
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer add: 18:
> 5000:1512973026950
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 http lingering close handler
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 recv: fd:18 -1 of 4096
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 recv() not ready (11:
> Resource temporarily unavailable)
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 lingering read: -2
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer: 18, old:
> 1512973026950, new: 1512973026950
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 post event 00007F6C0720C090
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 delete posted event
> 00007F6C0720C090
> 2017/12/11 14:17:01 [debug] 104925#0: *18879001 http empty handler
> 2017/12/11 14:17:02 [debug] 104925#0: *18879001 post event 00007F6C0720C090
> 2017/12/11 14:17:02 [debug] 104925#0: *18879001 delete posted event
> 00007F6C0720C090
> 2017/12/11 14:17:02 [debug] 104925#0: *18879001 http empty handler
> 2017/12/11 14:17:06 [debug] 104925#0: *18879001 event timer del: 18:
> 1512973026950
> 2017/12/11 14:17:06 [debug] 104925#0: *18879001 http lingering close handler
> 2017/12/11 14:17:06 [debug] 104925#0: *18879001 http request count:1 blk:0
> 2017/12/11 14:17:06 [debug] 104925#0: *18879001 http close request
> 2017/12/11 14:17:06 [debug] 104925#0: *18879001 http log handler
>
>
> 中间02-06s没有debug日志。
>
>
> 在 2017年12月11日星期一 UTC+8下午10:53:00，Zexuan Luo写道：
>>
>> 有在 log_by_lua 里面执行什么耗时的逻辑吗？
>> 另外方便贴 debug 日志出来不？
>>
>> 在 2017年12月11日 下午7:56，tokers <zcha...@gmail.com> 写道：
>> > Hi！
>> > 你使用的是什么版本的 nginx，有什么特殊逻辑吗？
>> >
>> >
>> > On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:
>> >>
>> >> rt
>> >
>> > --
>> > --
>

zchao1995

另外题主 request_time 普遍比 upstream_response_time 多 5s 的请求，状态码也是正常的吗？

soul11201

题主，首先你该把配置贴出来或者贴到 gist 上个顺带贴个 nginx -V的输出。我们也能浮现一下。

-----

http://blog.soul11201.com

在 2017年12月12日上午10:28，tokers <zcha...@gmail.com>写道：

另外题主 request_time 普遍比 upstream_response_time 多 5s 的请求，状态码也是正常的吗？

--

yi_mor

状态码都是ok的。而且客户端也没有感觉请求慢

在 2017年12月12日星期二 UTC+8上午10:28:57，tokers写道：

另外题主 request_time 普遍比 upstream_response_time 多 5s 的请求，状态码也是正常的吗？

yi_mor

nginx就是原生的，最基本的几个模块。没有其他插件。配置也是最原生的nginx配置，

location /aaa/ {

proxy_pass http://10.0.0.0:80;

proxy_set_header Host $host;

proxy_set_header X-Forwarder-For $proxy_add_x_forward_for;

}

日志中出现这种异常的情况大概有1/5之一左右，其他的相同配置nginx却没出现这种情况，PS：这个日志有问题的代理是移动APP专用的。

在 2017年12月12日星期二 UTC+8下午12:03:01，soul11201写道：

题主，首先你该把配置贴出来或者贴到 gist 上个顺带贴个 nginx -V的输出。我们也能浮现一下。

-----
http://blog.soul11201.com

在 2017年12月12日上午10:28，tokers <zcha...@gmail.com>写道：
另外题主 request_time 普遍比 upstream_response_time 多 5s 的请求，状态码也是正常的吗？

--

zchao1995

你的 client 发来的请求采用的是什么 method？另外有携带 request body 吗？

yi_mor

GET/POST都有这种情况。POST请求是有request body的。

在 2017年12月12日星期二 UTC+8下午2:13:03，tokers写道：

你的 client 发来的请求采用的是什么 method？另外有携带 request body 吗？

dingdongnigetou

hi,

看你的日志，应该就是lingering close引起的，刚好5秒后才触发log：

2017/12/11 14:17:01 [debug] 104925#0: *18879001 lingering read: -2
2017/12/11 14:17:01 [debug] 104925#0: *18879001 event timer: 18, old: 1512973026950, new: 1512973026950
2017/12/11 14:17:01 [debug] 104925#0: *18879001 post event 00007F6C0720C090
2017/12/11 14:17:01 [debug] 104925#0: *18879001 delete posted event 00007F6C0720C090
2017/12/11 14:17:01 [debug] 104925#0: *18879001 http empty handler
2017/12/11 14:17:02 [debug] 104925#0: *18879001 post event 00007F6C0720C090
2017/12/11 14:17:02 [debug] 104925#0: *18879001 delete posted event 00007F6C0720C090
2017/12/11 14:17:02 [debug] 104925#0: *18879001 http empty handler
2017/12/11 14:17:06 [debug] 104925#0: *18879001 event timer del: 18: 1512973026950
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http lingering close handler
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http request count:1 blk:0
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http close request
2017/12/11 14:17:06 [debug] 104925#0: *18879001 http log handler

你可以设置下你的lingering_timeout，默认是5s，可以改为10s，然后看下是不是相差了10s。

On Monday, December 11, 2017 at 7:04:26 PM UTC+8, whust wrote:

rt