通过nginx访问日志来分析响应慢的问题

原创

mybabe0312 2021-08-14 08:22:34 博主文章分类：Java基础 ©著作权

文章标签 nginx日志 nginx分析慢 文章分类 Java 后端开发

©著作权归作者所有：来自51CTO博客作者mybabe0312的原创作品，请联系作者获取转载授权，否则将追究法律责任

首先来看下nginx的几个变量的含义

1. $upstream_connect_time

与上游服务建立连接所经过的时间,单位为秒。在使用SSL的情况下，握手过程所消耗的时间也会被记录下来。多次请求建立的时间，使用逗号与冒号分隔，格式可参考$upstream_addr变量。【来自“ngx_http_upstream_module”模块】

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.

2. $upstream_header_time

从上游服务接收响应头所经过的时间，单位为秒。多次请求响应的时间，使用逗号与冒号分隔，格式可参考$upstream_addr变量。【来自“ngx_http_upstream_module”模块】

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.

3. $upstream_queue_time

上游请求在上游队列中花费的时间，以秒为单位。【来自“ngx_http_upstream_module”模块】

keeps time the request spent in the upstream queue (1.13.9); 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.

4. $upstream_response_time

从上游服务接收响应内容所经过的时间，单位为秒。多次请求响应的时间，使用逗号与冒号分隔，格式可参考$upstream_addr变量。【来自“ngx_http_upstream_module”模块】

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.

5. $request_time

从发起请求的客户端获取到第一个字节开始，到返回给客户端最后一个字节后，日志写入文件所经过的时间，单位为秒。【来自“ngx_http_upstream_module”模块】

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建立连接同时nginx接收完请求数据。
建立Nginx连接（与上游服务） nginx建立与上游服务的连接。
发送响应上游服务器处理完请求并响应给nginx的耗时。
接收响应 nginx将请求响应给客户端的耗时。
关闭Nginx连接（其耗时可忽略不计）关闭与客户端的连接。

$request_time: 1+2+3+4 $upstream_response_time:2+3+4+5 所以可以得到以下的结果

上游服务执行耗时 = $upstream_header_time - $upstream_connect_time
数据响应到客户端耗时 = $request_time - $upstream_response_time

nginx中添加日志配置 1，在server中添加以下代码主要是为了提取cookie中的“x-token”参数

http{
	server{
		listen 8088;
		server_name www.dsf.com;
		# 设置日志文件路径
		access_log logs/o2oa_access.log cache;
	
		set $o2token "";
		if ($http_cookie ~* "x-token=(.+?)(?=;|$)") {
			set $o2token $1;
		}
	}
}

2，在http中添加日志

http{        
                    
    log_format  o2_access  '[$o2token] - [$remote_addr] - [$time_local] - [$request] - [$status] - [$body_bytes_sent] - [$http_user_agent] - [$request_uri] - [$upstream_addr] - [$http_cookie] - [$request_time] - [$upstream_connect_time] - [$upstream_header_time] - [$upstream_response_time]';                          
}

http{
    log_format  o2_access '[$o2token] - [$remote_addr] - [$time_local] - [$request] - [$status] - '
    											'[$body_bytes_sent] - [$http_user_agent] - [$request_uri] - [$upstream_addr] - [$http_cookie] - '
    											'[$request_time] - [$upstream_connect_time] - [$upstream_header_time] - [$upstream_response_time]';      
}

3，在location中覆盖默认的日志配置

http{
	server{
		location /wrdp/ {
			access_log logs/o2_access.log o2_access; 
			proxy_set_header   Host $host;
			proxy_set_header   X-Real-IP $remote_addr;
			... ...
		}
	}
}

附：nginx的访问日志里面出现的时间格式可能是这样的

01/Aug/2021:21:19:35 +0800

可通过如下访问转换成Java的Date类型

SimpleDateFormat dateFormat = new SimpleDateFormat("dd/MMM/yyyy:HH:mm:ss Z", Locale.ENGLISH);
java.util.Date date = dateFormat.parse(time) ;

DateTimeFormatter formatter =  DateTimeFormatter.ofPattern("dd/MMM/yyyy:HH:mm:ss Z", Locale.ENGLISH) ;
LocalDateTime localDateTime = LocalDateTime.parse(time,formatter) ;