logging - Windows 中的 Nginx $request_time 和 $upstream_response_time

Question

我在 Windows 上运行 Nginx 的访问日志中遇到了一些奇怪的问题。我在访问日志中包含了 $request_time 以及 $upstream_response_time(将 Django 作为 fcgi 上游运行)。我的理解是日志应该以毫秒为单位表示请求时间，但它的输出如下所示:

ip|date|request_time|upstream_response_time
xx.xx.xx.xxx|[29/Jan/2013:15:29:57 -0600]|605590388736.19374237|0.141
xx.xx.xx.xxx|[29/Jan/2013:15:30:39 -0600]|670014898176.19374237|0.156

知道这个巨大的数字是什么鬼吗!？

这是完整的日志格式(我删除了上面示例中的几列)

log_format  main  '$remote_addr|$time_local]|$request|$request_time|$upstream_response_time|'
                  '$status|$body_bytes_sent|$http_referer|'
                  '$http_user_agent';

使用管道分隔符。

Answer 1

所以正如你所建议的那样，答案是:

当您以 GET 方式向您的服务器 ( nginx + upstream ) 发出请求时， $request_time结果具有正常和可接受的值。发生这种情况是因为您的上游服务器没有参与其中，即使它参与了，它也能正常工作。

当您执行 POST 请求时，问题就开始了。根据 nginx doc 值 $request_time当所有数据已发送且连接已关闭(所有上游和代理也已关闭)时，将计算变量(仅在日志记录时可用)。只有这样信息才会附加到日志中。

那么如何检查一切是否正确呢？
首先向您的服务器发出 GET 请求并查看日志文件。注意完成调用并将日志信息添加到文件中真正需要多少时间 - 它应该是真正的值(value)。
接下来向您的服务器发出 POST 请求并再次查看日志文件。在这里，您可能会看到日志根本没有出现或在很长一段时间后出现。

这是什么意思？检查您的 nginx conf 和您的上游 conf，因为某处可能是连接未关闭且悬而未决的地方。您的操作系统或上游服务器可能会在一段时间后更新这些连接，但毕竟它可能会导致一些问题，而不仅仅是奇怪 $request_time值(value)。