Nginx日志中的请求处理时间如何分析

Nginx日志中的请求处理时间分析

一关键时间字段与含义

$request_time：从读取客户端第一个字节开始，到向客户端发送完最后一个字节结束的总耗时，单位为秒（毫秒精度）。它包含了网络传输、Nginx处理、上游处理与回传的总时长。
$upstream_response_time：Nginx与上游（后端）交互的耗时（建立连接/SSL握手、等待与接收响应头、接收响应体），单位为秒（毫秒精度）；若请求未到上游，通常为**“-”**。
$upstream_connect_time：与上游建立连接（含SSL握手）的耗时；$upstream_header_time：从上游接收响应头的耗时。
典型关系与定位思路：
- 静态资源或命中缓存时，常见**$upstream_response_time 为 “-”**，$request_time 主要体现 Nginx 本地处理与传输。
- 若 $request_time ≈ $upstream_response_time 且数值较大，瓶颈多在上游服务（如应用代码、数据库）。
- 若 $upstream_connect_time 明显偏大，可能是网络链路或上游负载问题。
- 若出现 $request_time 很小（如 0.000）且状态码为 499，同时 $upstream_response_time 为 “-”，多为客户端提前断开（上传未完成或主动取消）。

二日志格式与采集建议

在 http 块中定义包含时间字段的日志格式，并在需要的 server/location 中启用：
- 建议同时输出 $request_time 与 $upstream_response_time，必要时补充 $upstream_connect_time / $upstream_header_time 以细化定位。
- 时间字段可用 $time_local（如：17/Jan/2017:17:14:08 +0800）或 $time_iso8601（如：2017-01-17T16:51:42+08:00），便于后续在 ELK/Logstash 中解析。
- 示例（combined 基础上扩展）：
```
log_format main_ext '$remote_addr - $remote_user [$time_local] "$request" '
                  '$status $body_bytes_sent "$http_referer" '
                  '"$http_user_agent" "$http_x_forwarded_for" '
                  'rt=$request_time uct=$upstream_connect_time '
                  'uht=$upstream_header_time urt=$upstream_response_time '
                  'up=$upstream_addr';
access_log /var/log/nginx/access.log main_ext;
```
- 若采用 JSON 格式，便于直接被 Logstash/ES 解析与聚合分析。

三命令行快速分析

找出最慢的 N 条请求（假设 $request_time 在最后一列）：
```
awk '$NF > 3 {print $0}' access.log | sort -kNF -nr | head -20
```

按 URL 汇总并查看 P95/P99 分位耗时（需 $request_time 为第 11 列，按实际列号调整）：

awk '{url=$7; gsub(/\?.*/,"",url); dur=$11; sum[url]+=dur; cnt[url]++; times[url][NR]=dur}
     END {
       for (u in sum) {
         n=cnt[u]; asort(times[u]); p95=times[u][int(n*0.95)]; p99=times[u][int(n*0.99)];
         printf "%-60s %8.3f %8.3f %8.3f %6d\n", u, sum[u]/n, p95, p99, n
       }
     }' access.log | sort -k2 -nr | head

统计上游耗时超过阈值的请求（假设 $upstream_response_time 为第 12 列）：
```
awk '$12 > 5 {print $0}' access.log | sort -k12 -nr | head
```

按分钟统计请求量与平均耗时（假设 $time_local 为第 4 列）：

awk -F: '{m=$2":"$3; c[m]++; t[m]+=$NF} END {for (x in c) printf "%s %d %.3f\n", x, c[x], t[x]/c[x]}' access.log | sort

使用 GoAccess 生成可视化报告（按实际日志格式配置 time/date/log-format）：
```
goaccess /var/log/nginx/access.log --log-format=COMBINED
```
以上命令中的列号与阈值可按你的 log_format 调整。

四可视化与长期观测

GoAccess：交互式查看 Top URLs、状态码分布、请求时间指标 等，适合临时排查与周报。
ELK/Logstash/Elasticsearch/Kibana：
- 时间解析：
  - $time_iso8601 使用 match => ["message", "%{TIMESTAMP_ISO8601:locals}"] 与 date { match => ["locals", "ISO8601"] }。
  - $time_local 使用 match => ["message", "%{HTTPDATE:logdate}"] 与 date { match => ["logdate", "dd/MMM/yyyy:HH:mm:ss Z"] }。
- 在 Kibana 中基于 @timestamp 绘制 P50/P95/P99 耗时曲线，按 URL/上游/状态码/地区 等维度聚合，建立慢请求告警。

五常见现象与定位路径

$upstream_response_time 为 “-”：未走到上游，多为静态资源/缓存命中或本地错误；结合 $status 判断是否为缓存/本地处理路径。
$request_time 与 $upstream_response_time 接近且很大：瓶颈在上游（应用逻辑、数据库、外部依赖）。
$upstream_connect_time 明显偏大：网络链路/上游过载/SSL握手慢，检查网络质量、连接复用与上游负载。
$request_time 很小但为 499，且 $upstream_response_time 为 “-”：客户端提前关闭（上传中断、超时、取消），关注客户端网络与超时设置。
$upstream_header_time 很小但 $upstream_response_time 很大：上游响应体回写慢（大文件、慢磁盘、带宽/代理瓶颈），结合 $body_bytes_sent 与网络监控排查。

最新问答

相关标签