nginx 请求开始时间

nginx 请求开始时间

背景

用户反馈广告主平台上传视频满，在本地尝试重现，发现上传一个30M左右的视频大概花40s左右，多个视频上传还是串行，目前前端已经优化为了并行上传，但一个视频花费40s的问题还是需要解决，因此就想把每个步骤操作时间都记录一下排查问题

流程

浏览器 --> nginx --> server --> 3rd server

疑问

想在nginx日志配置中找到记录请求开始时间的变量，发现没有，一顿查阅得到的信息大致如下：

$time_local -  local time in the Common Log Format（官方文档，解释的不清不楚，是请求开始时间？还是请求处理时间？还是写这个请求日志的时间？）

具体解释如下：

The $time_local variable contains the time when the log entry is written.

when the HTTP request header is read, nginx does a lookup of the associated virtual server configuration. If the virtual server is found, the request goes through six phases:

server rewrite phase
location phase
location rewrite phase (which can bring the request back to the previous phase)
access control phase
try_files phase
log phase
Since the log phase is the last one, $time_local variable is much more colse to the end of the request than it's start.

意思就是这个$time_local 是很接近请求处理结束时间


那么怎么去拿到request start time呢？ 有这样的方式，如下：
$msec - $request_time ===   该条请求写日志时间戳 减去 请求处理时间 ，即请求开始时间


具体log format的变量解释官方解释如下：

$request_time – Full request time, starting when NGINX reads the first byte from the client and ending when NGINX sends the last byte of the response body
$upstream_connect_time – Time spent establishing a connection with an upstream server
$upstream_header_time – Time between establishing a connection to an upstream server and receiving the first byte of the response header
$upstream_response_time – Time between establishing a connection to an upstream server and receiving the last byte of the response body
$msec - time in seconds with a milliseconds resolution at the time of the log write

中文版本：

$remote_addr, $http_x_forwarded_for 记录客户端IP地址
$remote_user 记录客户端用户名称
$request 记录请求的URL和HTTP协议
$status 记录请求状态
$body_bytes_sent 发送给客户端的字节数，不包括响应头的大小； 该变量与Apache模块mod_log_config里的“%B”参数兼容。
$bytes_sent 发送给客户端的总字节数。
$connection 连接的序列号。
$connection_requests 当前通过一个连接获得的请求数量。
$msec 日志写入时间。单位为秒，精度是毫秒。
$pipe 如果请求是通过HTTP流水线(pipelined)发送，pipe值为“p”，否则为“.”。
$http_referer 记录从哪个页面链接访问过来的
$http_user_agent 记录客户端浏览器相关信息
$request_length 请求的长度（包括请求行，请求头和请求正文）。
$request_time 请求处理时间，单位为秒，精度毫秒； 从读入客户端的第一个字节开始，直到把最后一个字符发送给客户端后进行日志写入为止。
$time_iso8601 ISO8601标准格式下的本地时间。
$time_local 通用日志格式下的本地时间。

个人理解

个人理解，仅作参考，不保证正确性

nginx 过程时间节点
nginx接收到请求时间点（这里就是我们这次的目的） --> nginx 跟 upstream 建立连接 -- nginx 发送给upstream时间点 -- nginx 接受到upstream的时间点 --  nginx给出response的时间点
  

参考资料

http://www.ttlsa.com/linux/the-nginx-log-configuration/
http://nginx.org/en/docs/http/ngx_http_log_module.html
https://www.nginx.com/blog/using-nginx-logging-for-application-performance-monitoring/#var_upstream_response_time
https://nginx.org/en/docs/http/ngx_http_upstream_module.html?&_ga=2.132295757.2109258733.1589278738-1303059860.1589278738#var_upstream_response_time
https://serverfault.com/questions/532560/how-to-log-the-start-time-of-a-request-in-nginx/859293