描述

nginx的日志经常要记录服务器处理请求的时间，作为日后优化的参考。

先看一下官网关于$request_time与$upstream_response_time描述：

• $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

指的就是从接受用户请求的第一个字节到发送完响应数据的时间，即包括接收请求数据时间、程序响应时间、输出响应数据时间。

• $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向后端（php-cgi、java、node js等等)建立连接开始到接受完数据然后关闭连接为止的时间。

可以看出，$request_time肯定比$upstream_response_time值大，在GET请求中，基本相差无几，但是在POST请求的时候，$request_time一般会比$upstream_response_time大，因为nginx要先把客户端传来的数据都拿到了，才会把数据一起交给后端处理。举个例子，在处理表单、上传图片时，如果数据量大，或者用户网络较差，nginx会等待比较长的时间，$request_time与$upstream_response_time的差值会比较明显。

示例

比如 log_format 如下：

log_format main '$time_local | $status | $body_bytes_sent | $content_length | $remote_addr '
                                     '| $request_time | $upstream_response_time | "$request" | "$http_user_agent" | "$http_referer" | "$http_x_forwarded_for" | $remote_user';

配置 server 的 access_log 格式为 main

access_log access.log main;

access.log 的日志：

11/Dec/2019:22:04:41 +0800 | 200 | 735 | 410 | 192.168.8.234 | 0.028 | 0.027 | "POST /update HTTP/1.1" | "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36" | "" | "-" | -
11/Dec/2019:22:18:14 +0800 | 200 | 4583 | - | 192.168.8.234 | 0.025 | 0.025 | "GET / HTTP/1.1" | "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36" | "-" | "-" | -

总结

在使用nginx的access.log日志查看哪些接口比较慢的话，可以在log_format中加入$upstream_response_time，能更准确地找出问题。