为什么「平均响应时间」是个几乎没有用的指标
打开任何一份监控面板，最先看到的往往是「平均响应时间 180ms」这样的数字。它看起来很让人安心，但它同时也是最会骗人的指标之一。原因很简单：平均值是长尾的敌人。假设一天有一万个请求，九千九百个都在 20ms 返回，剩下的一百个卡了 5 秒——平均下来是多少？
（9900×0.02 + 100×5）÷ 10000 ≈ 0.0698 秒，也就是 70ms。面板上一片绿，但真实情况是：每一百个访客里就有一个人盯着白屏等了五秒。对搜索引擎爬虫来说，抓取预算有限，遇到 5 秒的响应很可能直接放弃这个 URL；对真实用户来说，五秒基本等于关掉页面。
所以真正有价值的指标不是平均值，而是「超过某条线的请求有多少个」——也就是超过 300 毫秒、1 秒、5 秒的分桶计数。这篇文章讲的是怎么在不装任何重型监控组件的前提下，用 Nginx 自己的日志把这件事做起来：定义口径、低成本采集、正确处理「日志写入本身就是瓶颈」这个反身性问题，以及怎么定位到具体是哪一类请求慢。
为什么选 300 毫秒这条线？它大致是「用户仍然感觉是即时的」上限，也是 Google 的 Core Web Vitals 里 TTFB「良好」的门槛量级。低于它的延迟，用户基本不会有感知；跨过它之后，每一次翻倍都在成比例地损耗转化。
先统一口径：这三种「慢」是不同的问题
在采集之前必须先把概念分清，否则采到的数据无法解读。一个请求的耗时可以拆成四段，每段的病因完全不同：
- 排队时间：请求到了但没被处理，卡在 accept 队列或 worker 的连接数上限外。表现为「所有请求一起慢」，且与 PHP-FPM 进程池打满高度相关。
- 应用处理时间（
upstream_response_time）：Nginx 转给后端后，等后端开始返回的时间。这块是 PHP/数据库的地盘。 - 传输时间：后端已经开始吐数据，但吐得慢。大文件、慢速客户端、带宽不足都会拉长这段。
- 客户端读取时间（
request_time减去上面所有）：用户网络慢，服务端早已发完，但 TCP 窗口没空。这一段不该算在服务器账上。
Nginx 的 $request_time 是从读到请求第一个字节到写完响应最后一个字节的全过程，包含客户端读取；$upstream_response_time 只统计到后端响应头返回（严格说是从建立连接到收到响应头的时长）。两者相减就能大致判断「慢在服务端」还是「慢在客户端网络」。只看 request_time 会把用户的弱网也算成自己的锅，导致优化方向完全跑偏。
所以采集时必须同时记录这两个字段，以及 $upstream_addr（哪个后端）、$request_uri（哪个路径）、$status。少一个字段，事后就少一条归因线索。
低成本采集：从 log_format 开始，而不是从监控系统开始
很多人的第一反应是装 Prometheus + Grafana + exporter，为了一台个人站跑一套完整的可观测栈。这没错，但成本不低，而且大部分时候你只需要回答「哪个 URL 慢了」这一个问题。Nginx 日志本身就够用。
第一步：定义带耗时的 log_format
log_format timed '$remote_addr - $remote_user [$time_local] "$request" '
'$status $body_bytes_sent "$http_referer" "$http_user_agent" '
'rt=$request_time urt=$upstream_response_time uct=$upstream_connect_time '
'ua=$upstream_addr ustat=$upstream_status '
'host=$host uri=$request_uri';
注意 rt= urt= 这些前缀。一定要加键名前缀，否则后续用 awk 或正则提取时，会因为字段位置随 User-Agent 里的空格而漂移。$request_time 的值是秒，带三位小数（如 0.312），直接拿来做数值比较没问题。
还有一点：$upstream_response_time 在请求没走后端时（静态文件）是 -，在有多个上游重试时会是逗号分隔的列表（如 0.1, 0.3）。解析时必须处理这两种情况，否则脚本会在 - 上炸掉，或者把多次重试的时间算错。
第二步：按天切分，方便回溯
access_log /var/log/nginx/access-timed.log timed buffer=64k flush=5s;
buffer=64k flush=5s 是重点。默认 Nginx 每条日志同步写入（除非开了 buffer），高并发时这会变成真实的 I/O 压力——尤其在磁盘已经吃紧的时候，日志写入会加剧瓶颈，形成正反馈。flush=5s 保证即使缓冲没满，最多 5 秒也会落盘，兼顾了吞吐和「故障现场不丢数据」。
按天切割用 logrotate 就够，不需要额外组件：
# /etc/logrotate.d/nginx-timed
/var/log/nginx/access-timed.log {
daily
rotate 14
missingok
notifempty
compress
delaycompress
sharedscripts
postrotate
[ -f /run/nginx.pid ] && kill -USR1 $(cat /run/nginx.pid)
endscript
}
delaycompress 不能省：如果当天就把日志压成 .gz，你的实时分析脚本读当天文件时就抓不到压缩的那份。而 kill -USR1 是 Nginx 专用的「重开日志文件」信号，用它而不是 restart，才能做到不中断连接。
第三步：一个脚本算出慢请求排行榜
#!/bin/bash
# slow-top.sh — 300ms 慢请求分桶统计 + Top 路径
LOG="${1:-/var/log/nginx/access-timed.log}"
THRESH=${2:-0.300}
awk -v th="$THRESH" '
{
# 提取 rt= 与 uri=
rt=""; uri=""; st="";
for (i=1;i<=NF;i++) {
if ($i ~ /^rt=/) { rt=substr($i,4) }
if ($i ~ /^uri=/) { uri=substr($i,5) }
if ($i ~ /^ustat=/) { st=substr($i,7) }
}
if (rt=="") next
total++
# 分桶
if (rt+0 >= 5.0) b5++
else if (rt+0 >= 1.0) b1++
else if (rt+0 >= th) b300++
if (rt+0 >= th) { cnt[uri]++; if (rt+0 > max[uri]) max[uri]=rt+0 }
}
END {
printf "总请求 %d 慢(>=%.0fms) %d 超过1s %d 超过5s %d 慢请求占比 %.2f%%\n",
total, th*1000, b300+b1+b5, b1+b5, b5, (total?(b300+b1+b5)*100/total:0)
print "--- 慢请求 Top 15 路径 ---"
for (u in cnt) printf "%8d max=%6.2fs %s\n", cnt[u], max[u], u
}
' "$LOG" | head -25
这个脚本故意只依赖 awk，因为它能在任何 Linux 上直接跑，不需要装 Python、不必配虚拟环境。在服务器出问题、你 SSH 上去手忙脚乱的时候，「能立刻跑」比「功能完整」重要得多。
输出里最有信息量的不是「慢请求占比」，而是 Top 路径列表。因为慢往往是高度集中的：通常两三个 URL 就贡献了 80% 的慢请求。找到它们，问题基本就定位了一半。
反身性问题：日志采集本身会不会拖慢站点
这是个必须正面回答的问题，也是很多人不敢开详细日志的原因。
实测经验是：开启 buffer=64k flush=5s 之后，日志写入对吞吐的影响在正常流量下可以忽略——因为它把 syscall 次数降低了两个数量级。真正的风险不在写入，而在解析脚本：如果你写了个 cron 每分钟 awk 一遍几百 MB 的全天日志，那 CPU 确实会被吃掉。
三个避免方法：
- 增量读取：记住上次读到的字节偏移，只处理新增部分。
- 降频：慢请求统计每 5 分钟或每 15 分钟跑一次完全够用，它不是秒级告警指标。
- 限流：脚本加
nice -n 19和ionice -c3，把优先级压到最低。
# 增量扫描：只处理上次之后的新内容
STATE=/var/lib/slowmon/offset
mkdir -p "$(dirname "$STATE")"
OFF=$(cat "$STATE" 2>/dev/null || echo 0)
SIZE=$(stat -c %s /var/log/nginx/access-timed.log)
if [ "$SIZE" -lt "$OFF" ]; then OFF=0; fi # 日志被轮转，从头开始
tail -c +$((OFF+1)) /var/log/nginx/access-timed.log > /tmp/slow_delta.log
echo "$SIZE" > "$STATE"
nice -n 19 ionice -c3 /root/slow-top.sh /tmp/slow_delta.log
tail -c +N 是从第 N 个字节开始读（1-based，所以是 OFF+1），配合 stat -c %s 拿到的偏移量，就实现了「只读新增」。那个 if [ "$SIZE" -lt "$OFF" ] 的判断必须写——否则 logrotate 之后文件变小，脚本会从一个荒谬的偏移量开始读，永远读不到东西，而你会以为「没有慢请求」。这是一个非常安静的失败模式。
从「慢请求」到「为什么慢」：四层归因
找到慢 URL 只是第一步。接下来判断慢在哪一层，可以按下面的顺序逐层排除，每一层都有明确的证据。
第一层：是不是静态资源被当成了慢请求
先看慢请求里有多少是 .css、.js、图片。如果静态文件也慢，那问题在网络层或磁盘，不在应用。快速判断：
awk -F'uri=' '/rt=/{split($0,a,"uri=");split(a[2],b," ");if(b[1] ~ /\.(css|js|png|jpg|woff2)$/)print}' \
/var/log/nginx/access-timed.log | wc -l
静态文件慢通常有三个原因：一是 CDN 没生效或回源，二是磁盘 I/O 打满（用 iostat -x 1 看 %util 和 await），三是 sendfile 没开或 tcp_nopush 配置不当。如果 %util 长期贴着 100% 而 await 也在涨，那就是磁盘到顶了，再怎么调 Nginx 也没用。
第二层：是不是后端（PHP-FPM）排队
关键看 urt 是否也大。如果 rt=5.0 urt=4.8，说明时间全花在后端；如果 rt=5.0 urt=0.05，后端只用了 50ms，那 4.95 秒花在传输或客户端，跟后端无关。
# 后端慢 vs 传输慢的比例
awk '/rt=/{
match($0,/rt=[0-9.]+/); rt=substr($0,RSTART+3,RLENGTH-3)+0;
if (match($0,/urt=[0-9.]+/)) { urt=substr($0,RSTART+4,RLENGTH-4)+0 } else { urt=0 }
if (rt>=0.3) { if (urt>=rt*0.8) back++; else trans++ }
} END { printf "后端为主: %d 传输/客户端为主: %d\n", back, trans }' /var/log/nginx/access-timed.log
顺带一提，$upstream_connect_time 只统计建连的耗时。如果它是 1.0 以上，说明后端在 accept 队列里排队——这是 backlog 不够或 FPM 进程池满的典型信号。nginx 的 listen 443 backlog=2048 和 FPM 的 listen.backlog 需要一起看，只调一边无效。
第三层：是不是某类请求天然慢
慢请求往往高度集中在特定路径。常见的高耗时类型：
- 搜索页与分页深页：
?s=xxx和page=50这类，数据库要扫大量行。 - 后台接口：
/wp-admin/admin-ajax.php、/action/xmlrpc，这些是 POST，往往触发重活。 - XML-RPC / API 端点：被扫描器爆破时会大量命中，虽然单次快但并发高。
- 动态缩略图：每张图首次请求都要现算。
# 按 URL 前缀聚合慢请求
grep 'rt=' /var/log/nginx/access-timed.log \
| awk '{match($0,/rt=[0-9.]+/);if(substr($0,RSTART+3,RLENGTH-3)+0>=0.3)print}' \
| grep -oE 'uri=[^ ]+' | sed 's|uri=||' \
| awk -F'[?]' '{print $1}' | awk -F'/' '{print "/"$2}' \
| sort | uniq -c | sort -rn | head -10
这个聚合把 URL 收敛到「第一级路径」，能立刻看出是栏目问题还是全局问题。如果所有路径的慢请求数量差不多，那是基础设施问题；如果集中在某一两个前缀，那是代码问题。这个判断决定了你接下来该去看内核还是看慢查询日志。
第四层：抓一个现场
数据分析只能给方向，最终要落到一个具体请求上。两种方式：
# 方式一：找出仍在运行的慢请求
ss -tnp state established '( sport = :443 or sport = :80 )' | head -20
# 方式二：抓 PHP-FPM 现场（需要配置 request_slowlog_timeout）
grep -E 'request_slowlog_timeout|slowlog' /etc/php/*/fpm/pool.d/www.conf
tail -50 /var/log/php*-fpm-slow.log
request_slowlog_timeout = 3s 配合 slowlog，会在请求超过阈值时把 PHP 调用栈打出来。这是定位「代码里到底卡在哪一行」最直接的手段，成本极低，但很多站都没开。它只记录栈，不中断请求，对生产完全安全。
让「快」变得可验证：P95 与预算
做完上面这些，你还需要一个上线后的判断标准。不要用平均值，用分位数：
# 直接从日志算 P50/P90/P95/P99
awk '/rt=/{
match($0,/rt=[0-9.]+/); print substr($0,RSTART+3,RLENGTH-3)+0
}' /var/log/nginx/access-timed.log | sort -n | awk '
{ v[NR]=$1 }
END {
printf "P50=%.3fs P90=%.3fs P95=%.3fs P99=%.3fs n=%d\n",
v[int(NR*0.50)], v[int(NR*0.90)], v[int(NR*0.95)], v[int(NR*0.99)], NR
}'
把日志全量 sort 在几十万行时是几秒级，可接受；但如果你有上千万行，应该改用抽样（awk 'NR%10==0'）或维护一个固定大小的直方图。抽样对分位数的影响远小于对平均值的影响，这是抽样在这里可用的原因。
然后是「预算」的概念：给每条线定一个不超过的数字，比如「P95 TTFB 不超过 300ms、5xx 不超过 0.1%、超过 1s 的请求不超过 1%」。这三个数字写在巡检清单里，每天看一眼，超了就查。没有预算的监控会退化成「看到红色才慌」，而有预算的监控会告诉你「现在还没红，但已经在爬升」。
几个容易踩的坑
坑一：$request_time 的精度。它是毫秒精度的浮点，但 Nginx 在不同版本上输出的小数位数略有差异。awk 里务必用 +0 强制数值转换，否则字符串比较会得出 "10.0" < "9.0" 之类的结果。
坑二：keepalive 让耗时统计失真。开启 HTTP keepalive 后，一个 TCP 连接承载多个请求，$request_time 只算单个请求，这没问题；但如果你用 $connection_requests 却没意识到连接是复用的，就会误判并发数。
坑三：HTTP/2 下的 request_time。HTTP/2 多路复用下，多个请求共享一个连接，排队发生在流（stream）层面。$request_time 仍然按请求算，这一步没问题，但如果客户端主动取消（用户关页面），日志里会出现 499，且耗时可能很短——499 不是服务端错误，把它算进「慢请求」或「错误率」都会误判。
坑四：缓存命中掩盖了真实后端。如果前面有 CDN 或 proxy_cache，Nginx 日志里大部分请求根本没到后端，urt 是 -。这时候你看到「平均 20ms，非常健康」，但回源的 5% 请求可能已经慢到 3 秒了。要单独统计「urt 非 - 的请求」的耗时分布，那才是后端真实表现。
# 只统计真正回源的请求
awk '/urt=/{
match($0,/urt=[0-9.]+/);
if (RSTART>0) { t=substr($0,RSTART+4,RLENGTH-4)+0; if(t>0) { n++; if(t>=1) slow++ } }
} END { printf "回源 %d 个，其中 ≥1s 的 %d 个\n", n, slow }' /var/log/nginx/access-timed.log
小结：慢请求监控的三个层次
把整件事收拢一下，它其实是三层，成本递增但收益也递增：
- 看得见：加
log_format记录rt和urt，用awk算分桶和 Top 路径。成本半小时，能回答「哪些 URL 慢」。 - 分得清：对比
rt与urt，区分后端慢和传输慢；开 PHP-FPM 的slowlog，把慢落到具体调用栈。能回答「慢在哪一层」。 - 管得住：定预算、每日巡检、P95 趋势。能回答「现在是否偏离基线、偏离了多少」。
绝大多数个人站卡在第一层就停了，然后就陷入「感觉有点慢，但不知道哪慢」的状态，只能靠猜着改配置。而一旦把这三个字段记下来，绝大多数「网站慢」的问题都能在十分钟内定位到具体 URL 和具体层级。这件事的投入产出比，比任何一个缓存插件都高——因为你没法优化你测不到的东西。