如何通过 log_format 结合延迟变量毫秒级定位静态资源分发中的回源耗时-Nginx-PHP中文网

毫秒级定位静态资源回源耗时需拆解nginx upstream三阶段时间：$upstream_connect_time（建连）、$upstream_header_time（首行响应）、$upstream_response_time（完整响应），均精确到毫秒；配置log_format显式记录，并在proxy_pass location中启用，结合阈值对比快速定位网络、tls、源站处理或传输瓶颈。

如何通过 log_format 结合延迟变量毫秒级定位静态资源分发中的回源耗时

要毫秒级定位静态资源分发中的回源耗时，关键不是只看“总耗时”，而是拆解 Nginx 到上游（比如源站、CDN 回源节点）的完整链路时间，并确保日志能精确到毫秒、区分不同阶段。

你真正需要记录和比对的，是这三个 upstream 时间变量：

$upstream_connect_time：建连耗时（TCP + TLS 握手完成）
$upstream_header_time：从连接建立完成 → 收到响应首行（含请求发送 + 后端处理 + 响应头返回）
$upstream_response_time：从连接建立完成 → 收到完整响应体（即整个回源过程结束）

它们单位都是秒，但精度为毫秒（如 0.123 表示 123ms），无需额外转换或拼接，直接写入 log_format 即可保留毫秒小数。

配置支持毫秒精度的 log_format

在 http{} 块中定义日志格式，显式包含三个 upstream 时间变量：

log_format upstream_ms '[%time_local] $remote_addr "$request" '
  '$status $body_bytes_sent '
  '$upstream_addr $upstream_status '
  '$upstream_connect_time $upstream_header_time $upstream_response_time '
  '$request_time';

✅ 注意：$upstream_connect_time 自 Nginx 1.9.1 起可用；确认版本 ≥ 1.9.1 且启用了 http_upstream_module（默认已编译）
✅ upstream_ms 格式仅在启用 proxy_pass（或 fastcgi_pass 等）的 location 中生效；静态资源走 alias 或 root 时不触发 upstream，对应字段显示 -

然后在回源相关的 location 块中启用该格式：

location ~* \.(js|css|png|jpg|gif|webp|woff2?)$ {
  proxy_pass https://origin-server;
  proxy_set_header Host $host;
  access_log /var/log/nginx/upstream_static.log upstream_ms;
}

如何通过日志快速判断回源瓶颈在哪一环

拿到日志后，按以下逻辑逐段排查（单位均为秒，保留三位小数）：

若 $upstream_connect_time > 0.1（即 >100ms）：
- 检查源站网络可达性（ping、telnet 端口）、DNS 解析是否稳定（尤其 upstream 使用域名时）
- 排查防火墙、安全组、SLB 是否引入延迟或丢包
- 源站 TCP 连接队列是否积压（ss -s 查 synrecv）
若 $upstream_connect_time ≈ $upstream_header_time（例如 0.045 和 0.047）：
- 说明建连后几乎立刻收到响应头 → 源站处理极快，瓶颈不在业务逻辑，而在连接层或 TLS 层
- 可进一步检查是否启用了 TLS session reuse，或源站是否强制每次重握手
若 $upstream_header_time ≫ $upstream_connect_time（例如 0.020 vs 0.850）：
- 延迟集中在「请求发出→首字节返回」之间 → 关注三方面：
  - Nginx 发送请求是否卡顿（如 proxy_buffering off + 大 body 导致阻塞）
  - 源站业务处理慢（PHP/Node 执行久、数据库查询慢）
  - 源站响应头生成前有同步 I/O（如读磁盘、锁等待）
若 $upstream_response_time ≫ $upstream_header_time（例如 0.850 vs 2.300）：
- 说明首字节很快，但响应体传输慢 → 典型于大文件未启用 sendfile on 或 tcp_nopush off
- 检查源站带宽、Nginx 与源站间 MTU 不匹配、是否被限速（limit_rate 或 upstream 限流）

补充建议：让分析更直观

在日志中增加自定义字段标识是否命中缓存（避免把缓存命中的请求混入回源分析）：

set $cache_status $upstream_http_x_cache;  # 若源站返回 X-Cache: HIT
log_format upstream_ms '... $cache_status $upstream_connect_time ...';

对静态资源回源日志单独轮转（避免和全量 access.log 混合），便于用 awk/grep 快速提取：
```
# 查找回源超 500ms 的请求
awk '$12 > 0.5 {print}' /var/log/nginx/upstream_static.log
```

不复杂但容易忽略