Nginx日志时间变量
简介
在Nginx作为反向代理期间，因为很多性能问题排查都会涉及到Nginx日志中反应服务器处理时间。并且在网上看到较详细的时间变量讲解的文档，此处记录一下，便于之后做分析使用(参考文档放置文末)。
本文提到的所有变量，如果需要区分，则均为ngx_http_upstream_module中的变量，不再做释义。如需要使用其他module中的参数，请参考nginx官方文档
Nginx中时间定义
$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变量。
流程说明
以上是Nginx官方给出的参数解读，但是看起来不是很清晰，但是可以通过下面的时序图作为参考
202405141553474.png
在这个时序图中可以看到
程序真正运行的时间 = $upstream_header_time - $upstream_context_time
在$request_time中包含了数据返回的时间以及日志打印的时间。
所以来说整个请求处理流程，如下所示
「1用户请求」「2建立Nginx连接」「3发送响应」「4接收响应」「5关闭Nginx连接」
$request_time = 1 + 2 + 3 + 4 + 5
$upstream_response_time = 2 + 3 + 4 + 5(「关闭Nginx连接」的操作耗时可以认为是0)
两者相差的就只有一个「用户请求」耗时。在正常的请求时间中，$request_time一般是等于或者大于$upstream_response_time
场景
场景1：Nginx日志出现大量超时告警，发现$upstream_header_time正常，但是$request_time和$upstream_response_time很大
分析：根据上图，这时候反应的是上游程序执行较慢，或发送数据量大，需要排查执行程序的相关慢日志；
场景2：Nginx日志出现大量超时告警，发现$request_time很大，但是upstream_response_time正常，说明程序执行完毕且正常返回，这时就要验证是数据返回过慢还是日志打印出现了阻塞
原因：
1、数据返回慢可以通过抓包分析，通常来说是用户网络引起的；
2、日志打印出现阻塞，可能是机器的IO出现问题，一般可以查看系统监控或者手动查看IO发现；
3、也可能是因为Nginx配置了相关的参数，导致了延迟关闭，这需要根据问题现象一步步排查；
4、也可能是返回给客户端的是https，大数据加解密耗时；
solution
把你的服务器放在high-speed network高性能网络上，让client能够快速访问
使用缓存CND、Nginx缓存
或者将你的服务器靠近用户，多IDC进行对不同区域用户服务。如：中国IDC、韩国IDC
去掉一些低效率算法，参考： Nagle's algorithm
调整服务器的TCP堆栈（参考 这篇文章）. 然而调整TCP堆栈不会有多大作用，因为内核默认配置已经做了优化调整了
除以上两个场景案例，还可以组合分析。
(1)、upstream_header_time小，$upstream_response_time大，可能是数据回写Nginx出了问题；
(3)、$request_time比$upstream_response_time大，考虑用户网络状态，或者传递的数据本身就大，当使用POST请求传参时，Nginx会先把request body缓存起来，而这些耗时都是累积到「1用户请求」，所以$request_time会比$upstream_response_time大
其他状况
$upstream_reponse_time比$request_time大，在官网上有个说明：https://forum.nginx.org/read.php?21,284448,284450#msg-284450
$upstream_response_time由clock_gettime(CLOCK_MONOTONIC_COARSE)计算，默认情况下，它可以过去4毫秒，相反，$request_time由gettimeofday()计算。 所以最终$upstream_response_time可能比$response_time更大。
测试案例
除了在日志中添加日志的方法之外，还可以通过CURL命令来分析请求耗时的情况
time_namelookup：DNS 域名解析的时候，就是把域名(http)转换成 ip 地址的过程
time_connect：TCP 连接建立的时间，就是三次握手的时间
time_appconnect：SSL/SSH 等上层协议建立连接的时间，比如 connect/handshake 的时间
time_redirect：从开始到最后一个请求事务的时间
time_pretransfer：从请求开始到响应开始传输的时间
time_starttransfer：从请求开始到第一个字节将要传输的时间
time_total：这次请求花费的全部时间
curl -o /dev/null -s -w speed_download:%{speed_download},"\n"time_namelookup:%{time_namelookup},"\n"time_connect:%{time_connect},"\n"time_pretransfer:%{time_pretransfer},"\n"time_starttransfer:%{time_starttransfer},"\n"time_total:%{time_total},"\n" "http://XXXX"
参考
超好用的Nginx日志时间变量——助你快速定位问题 - 掘金
Nginx - request_time和upstream_response_time的区别 - That's_it - 博客园
nginx优化之request_time 和upstream_response_time差别 - dongruiha - 博客园
Nginx - request_time和upstream_response_time详解
使用 curl 命令分析请求的耗时情况
