超好用的Nginx日志时间变量——助你快速定位问题

9,797 阅读3分钟

打开这篇文章的你,想必对于nginx的基础日志参数并不陌生,对于request_time参数更是熟悉得不能再熟悉了。不出意外的话,请求响应时间,这应该是现阶段你对它全部的认识了。其实,request_time的含义不仅仅是这样,并且,nginx中的日志时间变量,除了request_time,还有很多,如果配置得当的话,可以极大地提高排查问题的效率,尤其是超时问题。那么废话不多,let's begin。

注:本文提到的所有变量,如果需要区分,则均为ngx_http_upstream_module中的变量,不再做释义。如需要使用其他module中的参数,请参考nginx官方文档

先上官方定义

(以下英文释义均取自nginx官方文档,最后更新时间:2019-07-11)

$request_time

request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client

笔者直译:nginx服务,从发起请求的客户端获取到第一个字节开始,到返回给客户端最后一个字节后,日志写入文件所经过的时间。单位为秒。

$upstream_connect_time

keeps time spent on establishing a connection with the upstream server (1.9.1); the time is kept in seconds with millisecond resolution. In case of SSL, includes time spent on handshake. Times of several connections are separated by commas and colons like addresses in the $upstream_addr variable.

笔者直译:nginx服务,与上游服务建立连接所经过的时间。单位为秒。在使用SSL的情况下,握手过程所消耗的时间也会被记录下来。多次请求建立的时间,使用逗号与冒号分隔,格式可参考$upstream_addr变量。

$upstream_header_time

keeps time spent on receiving the response header from the upstream server (1.7.10); the time is kept in seconds with millisecond resolution. Times of several responses are separated by commas and colons like addresses in the $upstream_addr variable.

笔者直译:nginx服务,从上游服务接收响应头所经过的时间。单位为秒。多次请求响应的时间,使用逗号与冒号分隔,格式可参考$upstream_addr变量。

$upstream_response_time

keeps time spent on receiving the response from the upstream server; the time is kept in seconds with millisecond resolution. Times of several responses are separated by commas and colons like addresses in the $upstream_addr variable.

笔者直译:nginx服务,从上游服务接收响应内容所经过的时间。单位为秒。多次请求响应的时间,使用逗号与冒号分隔,格式可参考$upstream_addr变量。

定义解析

个人感觉官方的定义并不是很友好,首先,没有说明计算时间的起止点,其次,没有说明各个时间概念的关系,很容易让人迷惑。所以,笔者结合个人理解,对定义稍作解释,方便大家理解,如果有理解错误的地方,还望指出。

$request_time

(对于这个变量,官方的定义很准确,不再做其他释义)

nginx服务,从发起请求的客户端获取到第一个字节开始,到返回给客户端最后一个字节,日志写入文件后,所经过的时间。单位为秒。

$upstream_connect_time

nginx服务,从与上游服务开始建立连接,到连接建立成功,所经过的时间。单位为秒。

$upstream_header_time

nginx服务,从与上游服务开始建立连接,到接收到响应返回头的第一个字节,所经过的时间。单位为秒。

$upstream_response_time

nginx服务,从与上游服务开始建立连接,到接收完响应返回的最后一个字节,所经过的时间。单位为秒。


结合以上释义,便可得到时序图:

nginx时间变量关系图

从上图中我们不难得出如下结论

  • 程序真正的运行时间 = $upstream_header_time - $upstream_connect_time
  • $request_time 中包含了数据返回时间
  • $request_time 中包含了日志打印的时间

那么问题来了,这些结论有什么用呢?

场景举例

举个栗子

场景:nginx日志出现大量超时报警,这个时候发现$request_time、$upstream_header_time正常,但是$upstream_response_time很大

分析:根据上面的结论,这个时候便反映出是上游程序执行较慢,需要排查执行程序的相关慢日志

场景:同样是ngxin日志出现大量超时报警,这个时候发现$request_time很大,但是$upstream_response_time正常

分析:$upstream_response_time正常,说明程序执行完毕且正常返回,那么这个时候需要验证是数据返回过慢还是日志打印出现了阻塞。数据返回慢可以通过抓包分析,通常来说是用户网络原因引起的;日志打印出现阻塞,可能是机器io出现了问题,这个一般很容易发现,还有可能是nginx配置了相关参数,导致了延迟关闭,这里只要根据问题现象一步一步排查即可。


除了以上举的两个例子,还有各种组合可以分析,比如$upstream_connect_time很大,可能是网络通信出现了问题;$upstream_header_time很小,但是$upstream_response_time很大,可能是数据回写nginx出现了问题。不难看出,通过这些变量,便可以快速定位到问题环节,而不至于毫无头绪的到处排查,可以说是事半功倍。

勇敢的少年,相信这些变量可以帮助你不少,Hope you enjoy it!

最后有一个小题目留给你,为什么nginx所有的调用'下游',都叫做upstream(上游),而不是downstream或者别的什么,这里的设计算是反直觉么?