【nginx】nginx日志输出耗时request_time和upstream_response_time介绍

日志格式

对于一个常见的日志输出内容。
log_format main ‘$remote_addr|$time_local]|$request|$request_time|$upstream_response_time|’
‘$status|$body_bytes_sent|$http_referer’
了解这个内容主要原因是 最近在看服务耗时告警，发现后台和nginx接入层俩个地方负载都比较低，但有部分告警一直报，有些请求耗时非常长。看了下请求的耗时部分有的是比较高，这个就很奇怪。因此研究下nginx的耗时输出介绍。

耗时字段介绍

1、请求分段
为了下文比较好的说明耗时，先简单把整个处理分为一下几个过程：
用户请求 ->［1 Nginx 与客户端连接完成］［2后台链接建立和服务处理］［3发送响应］［4客户端接收响应完成］［5关闭 Nginx 连接］

2、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接受到客户端第一个字节的时间作为开始，到客户端接受到所有服务端响应数据为止。这个过程包括上面1-5所有环节的耗时。

3、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.

这个解释其实说的不太明确，从另外一个官方文档看到一个比较明确的说明。(https://docs.nginx.com/nginx/admin-guide/monitoring/logging/)
The time between establishing a connection and receiving the last byte of the response body from the upstream server
这个说明就比较明确了，这个时间包括和后台建立链接以及接受后台所有响应数据的时间。这里的耗时只包括上面说的2-3俩个的耗时。

4、俩个时间比较
从上面可以看出，request_time因为包括从客户端接受请求数据，以及发送给客户端的数据。因此这个耗时除了和后台服务性能有关之外，和客户端到你服务之间的这个网络情况也有关系，其实一般情况就是公网。这部分是无法通过服务性能优化缓解的。
对于后台研发，应该主要优化的是upstream_response_time，这个主要就是后台的性能直观体现了。

从上面的耗时环节介绍也可以看出，一般情况下request_time的时长会大于upstream_response_time，但有时候还会出现upstream_response_time小于request_time。从so上回答可以看到，这种情况的原因是因为俩者计算耗时的输入是不一样的。
request_time是通过gettimeofday()
upstream_response_time是通过clock_gettime(CLOCK_MONOTONIC_COARSE)