Nginx日志规则以及根据日志进行性能问题判断的思路
背景
Nginx是开源方案里面能实现反向代理 负载均衡的首选.
但是有时候性能出问题比较难以分析和定位, 不知道是不是nginx的瓶颈
性能问题的种类其实非常多,核心其实就是等待事件和等待事件.
回到nginx的主题, 其实本质就是 nginx自己处理和 后端服务器处理时间以及网络延迟等事项
最近看了一些文档,想着总结一下nginx的日志处理便于分析和定位问题原因.
日志格式
log_format 用来定义日志的格式
access_log 用于指定日志的具体路径.
这里主要是想一些简单的处理,便于完善, 暂时不考虑安全相关
log_format main '远程地址: $remote_addr 请求url: $request 请求发生时间: [$time_local] 状态: $status 请求体大小: $body_bytes_sent 浏览器信息: $http_user_agent 请求总用时: $request_time 后端服务总耗时: upstream_response_time 代理建立连接用时: $upstream_connect_time 代理发送header的用时:upstream_header_time 客户端浏览器种类: $http_user_agent 后端服务器地址: $upstream_addr 后端服务器状态: $upstream_status '
注意格式可以自己选择定义, 其实不建议这么长, 可能影响性能.
用中文的目的是便于非专业人士查看,
简单的模板
worker_processes auto;
events {
worker_connections 10250;
}
http {
include mime.types;
default_type application/octet-stream;
sendfile on;
gzip on;
keepalive_timeout 65;
log_format main '远程地址: $remote_addr 请求发生时间: [$time_iso8601] 状态: $status 请求总用时: $request_time 后端服务总耗时: $upstream_response_time 代理建立连接用时: $upstream_connect_time 代理发送header的用时: $upstream_header_time 后端服务器地址: $upstream_addr 链接序列号: $connection 当前链接的请求数: $connection_requests 请求体大小: $body_bytes_sent 后端服务器状态: $upstream_status 请求url: $request ' ;
access_log /usr/local/nginx/logs/access_log.log main;
server {
listen 80;
server_name localhost ;
location /{
proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
proxy_set_header REMOTE-HOST $remote_addr;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
proxy_pass http://127.0.0.1:5200/;
}
}
}
请求状态数分析
可以简单查询不同状态的数量.
cat logs/access_log.log |awk '{print $6}' |sort |uniq -c |sort -k1hr
包含请求url查看状态等信息
cat logs/access_log.log |awk '{printf "%-20s%-20s%-20.60s\n", $6,$26,$27}' |sort |uniq -c |sort -k1hr |head -n 10
查看时间最长请求的url 注意是倒序排列.
cat logs/access_log.log |awk '{printf "%-20s%-20s%-20s%-20.60s\n", $8,$22,$26,$27}' |sort -k1h
查看body最大的请求
cat logs/access_log.log |awk '{printf "%-20s%-20s%-20.60s\n", $22,$26,$27}' |sort -k1h
几个参数的理解-connection
第一部分:
链接序列号: $connection
当前链接的请求数: $connection_requests
我理解这里的链接, 应该是TCP的链接信息.
不明白 ngnx 还是 http的协议限制.
好像最多使用六个tcp链接
cat access_log.log |awk '{print $18}' |sort |uniq -c |sort -k1h
3 7
3 9
5 1
7 6
10 4
12 10
对应另外一个netstat的信息为:
netstat -ano |grep 80 |grep 192.168.1.2
tcp 0 0 10.110.xx.xx:80 192.168.1.2:27481 TIME_WAIT timewait (35.04/0/0)
tcp 0 0 10.110.xx.xx:80 192.168.1.2:27479 TIME_WAIT timewait (35.04/0/0)
tcp 0 0 10.110.xx.xx:80 192.168.1.2:27478 TIME_WAIT timewait (35.04/0/0)
tcp 0 0 10.110.xx.xx:80 192.168.1.2:27482 TIME_WAIT timewait (35.04/0/0)
tcp 0 0 10.110.xx.xx:80 192.168.1.2:27480 TIME_WAIT timewait (35.04/0/0)
tcp 0 0 10.110.xx.xx:80 192.168.1.2:27476 TIME_WAIT timewait (35.04/0/0)
经过一段时间的运行会发现
链接会超时之后自动 进入timewait的状态
然后每一个链接最多发送 100个请求, 然后就会关闭重新进行三步握手.
所以理论上一个tcp最多服用100次..
应该有时间进行一下简单处理
几个参数的理解-time
博客园上面的大佬:
https://www.cnblogs.com/AcAc-t/p/nginx_request_time_upstream_respone_time_analysis.html
里面文章讲的非常详细, 这里参考学习一下:
首先详细拆分一下一个完整HTTP请求(非keep alive)生命周期的多个阶段（以下C指代客户端，N指代nginx服务器，S指代上游server）：
1.C向N发起TCP三次握手建立连接成功，C开始向N通过TCP发送HTTP请求具体数据(header/body...)
2.N开始接收到C发送的数据到全部接收完成
3.N作为代理向S发起TCP三次握手并建立连接成功，N开始向S发送HTTP数据
4.S开始接收N发送的数据并全部接收完成
5.S业务代码根据业务规则进行处理完成并生成HTTP响应结果
6.S开始将响应结果发送给N
7.N开始接收响应结果并接收header部分完成
8.N接收S返回的全部响应结果完成，准备关闭该连接
9.N开始向C返回全部的HTTP响应结果并发送完成
10.C开始接收N返回的数据并全部接收完成
11.N向C发起四次挥手关闭TCP连接
经过源码追溯最终可以得出request_time、upstream_response_time、upstream_connect_time与upstream_header_time四个指标的关系为:
1. upstream_header_time = upstream_connect_time(阶段3) + N向S发送数据被接收完成时间(阶段4) + S业务代码处理数据返回并被N接收完header部分数据的时间(阶段5~7)
2. upstream_response_time = upstream_header_time + N接收完S除header部分剩余全部数据的时间(阶段8)
3. request_time = N开始接收C全部数据并完成的时间(阶段2) + upstream_response_time + N向C send响应数据并完成(阶段9)
至于一开始对于文档解释request_time 接收第一个字节的、发送完最后一个字节的具体定义，在阅读过程中也有了答案：
HTTP是应用层协议，其建立于传输层的TCP协议之上，而TCP是保证有序和可靠的--
其每一个有效数据包都必须收到对端的ACK确认才算发送成功，因此站在N的角度看待数据接收与发送完成，可以得出以下结论：
1. 其所谓的接收第一个字节时刻必然是属于C发向N的第一个TCP有效数据包被接收时刻--
不会包括三次握手纯SYN/ACK包--除非第三个握手包已经带了有效数据。
2. 所谓的发送完最后一个字节时刻，则由于N使用send发送响应给C，指的是调用send函数发送完数据的时刻
仅代表数据已成功写入协议栈buffer，并不代表N已经接收到了C确认收到所有数据的ack。