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

打开这篇文章的你，想必对于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服务，从与上游服务开始创建链接，到接收完响应返回的最后一个字节，所通过的时间。单位为秒。

结合以上释义，即可获得时序图：

从上图中咱们不可贵出以下结论

• 程序真正的运行时间 = $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或者别的什么，这里的设计算是反直觉么？