1、环境
OS 版本和内核: CentOS Linux release 7.9.2009 3.10.0-1160.el7.x86_64
nginx 版本: nginx-1.14.2 (社区版)
upstream server(tomcat) 版本: apache tomcat 8.0.53
JDK 版本: Oracle jdk1.8.0_144
nginx 对客户端有启用保持连接；
nginx 与 upstream server 有启用保持连接；
HTTP/1.1
2、nginx 日志格式和tomcat日志格式
(1) nginx 日志格式
'$remote_addr - $remote_user [$time_iso8601] '
' "$request" $status $body_bytes_sent $bytes_sent '
' $request_trace_id '
' ["$upstream_addr" "$upstream_status" "$upstream_bytes_received" "$upstream_response_length" "$upstream_cache_status" '
' "$upstream_response_time" "$upstream_connect_time" "$upstream_header_time"] '
' "$request_time" "$http_referer" "$http_user_agent" "$http_x_forwarded_for" "$ssl_protocol"';
自定义的$request_trace_id:
#trace.setting
set $request_trace_id $http_x_request_id;
if ( $request_trace_id = '' ) {
set $request_trace_id $pid-$connection-$bytes_sent-$msec;
}
(2) tomcat 日志格式
"[%{Y-M-d H:m:s.S+z}t] real_ip:%{X-Real-IP}i remote:%h requestid:%{X-Request-ID}i first_line:"%r" status:%s bytes:%b cost:%Dms commit_time:%Fms Agent:"%{User-Agent}i" %{Connection}i %{Connection}o %{Keep-Alive}i %{Keep-Alive}o"
3、有问题的日志(nginx 和 tomcat 日志)
(1) nginx 日志
192.168.26.73 - cgpadmin [2021-09-09T09:58:23+08:00] "POST /cgp2-oauth/oauth/check_token HTTP/1.1" 200 12983 13364 6462-1025729-0-1631152697.976 ["127.0.0.1:8801" "200" "13353" "12991" "-" "5.026" "0.000" "5.026"] "5.026" "-" "Java/1.8.0_144" "-" "-"
1631152697.976 时间戳转换成时间是:
2021-09-09 09:58:17.976
(2) tomcat 日志
[2021-9-9 9:58:17.993+CST] real_ip:192.168.26.73 remote:127.0.0.1 requestid:6462-1025729-0-1631152697.976 first_line:"POST /cgp2-oauth/oauth/check_token HTTP/1.1" status:200 bytes:12991 cost:17ms commit_time:16ms Agent:"Java/1.8.0_144" - - - -
4、自己的分析和判断，以及提出问题
nginx 的几个时间:
变量
$request_time 5.026 秒
$upstream_response_time 5.026 秒
$upstream_header_time 0.000 秒
$upstream_connect_time 5.026 秒日志时间
nginx 开始处理 proxy_pass 转发的时刻: 2021-09-09 09:58:17.976
nginx 最后发完响应报文给客户端的时间(只管发完，不管客户接收是否完成): 2021-09-09T09:58:23
tomcat 的几个时间:
属性
%D 17 毫秒
%F 16 毫秒日志时间
tomcat 处理完成(把响应报文发完给nginx的时刻，只管发完，不管nginx 接收是否完成): 2021-9-9 9:58:17.993
分析出问题的阶段:
nginx 处理总耗时时长($request_time)是因为 upstream 处理耗时时长($upstream_response_time);
在upstream 处理中，nginx先准备好了请求报文的内容，然后与tomcat之间建立连接，这个连接时长很短(我这里节选的日志是
0，可能是因为保持连接的缘故，我看了其他连接，也都是很短有不为0的情况)，所以$upstream_header_time 基本可以确认大概
是 nginx与tomcat连接后"开始发请求报文到tomcat","tomcat接收"(我理解可能会有队列，tomcat接收)，"tomcat处理","tomcat返回
响应报文","nginx收到响应报文头的第一个字节" 这个过程之间的耗时时间长，开始分析是哪一段的问题
nginx 完成时刻记录时间是 9:58:23 (这里不知道毫秒，因为我用的是默认的变量)，而 upstream 总耗时时长是 5.026秒，tomcat
返回报文的时刻是 9:58:17.993，9:58:23 减去 5.026秒大概就是 9:58:18左右和tomcat返回报文时刻差不多，说明 nginx 和客户端之间
的耗时时长不长，基本可以确认nginx向tomcat建立连接时刻也差不多是 9:58:18 左右，我们刚好有 $request_trace_id，这个时刻
即为nginx开始处理反向代理时刻，它是2021-09-09 09:58:17.976，基本可以印证我们的猜想。而 tomcat 反向报文时刻是 9:58:17.993，
它减去tomcat内部自己处理时长(%D 17毫秒)，得到tomcat开始处理请求的时刻是 9:58:17.976这个时刻和我们 $request_trace_id 09:58:17.976
基本是一样的，说明nginx开始发请求报文到tomcat到tomcat从池中分类线程处理耗时基本没有。所以upstream处理时间5耗时是在 tomcat准备响应报文后，
把响应报文发给nginx，nginx收到响应报文头的第一个字节的时间(走127.0.0.1基本没有网络问题，而且监控也没有看到。
是否nginx也有队列？不是upstrem 是基于epoll实现的事件回调吗，)
这边系统有时候有前置的问题有时候有后置的问题(本例是后置的问题)，请大家给点思路，我好推进这个问题，谢谢！
5、参考文档
Using NGINX Logging for Application Performance Monitoring
Learn how to use the logging facility in NGINX and NGINX Plus for application performance monitoring (APM)
java - Tomcat log: what's the difference between %D and %F - Stack Overflow
I am using tomcat log to log the access info and the definitions of %D and %F in official doc is
%D - Time taken to process the request, in millis
%F - Time taken to commit the response, in mill...
https://stackoverflow.com/questions/42685694/tomcat-log-whats-the-difference-between-d-and-f
Module ngx_http_upstream_module
http://nginx.org/en/docs/http/ngx_http_upstream_module.html#variables
Apache Tomcat 8 Configuration Reference (8.0.53) - The Valve Component
https://tomcat.apache.org/tomcat-8.0-doc/config/valve.html
掘金
https://juejin.cn/post/6844903887757901832
nginx upstream模块完整逻辑源码分析 - 云+社区 - 腾讯云
1.启动upstream。
2.连接上游服务器。
3.向上游发送请求。
4.接收上游响应(包头/包体)。
5.结束请求。
https://cloud.tencent.com/developer/article/1778734
