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 与网络监控排查。

声明：本文内容由网友自发贡献，本站不承担相应法律责任。对本内容有异议或投诉，请联系2913721942#qq.com核实处理，我们将尽快回复您，谢谢合作！