一个笔记查询接口的平均响应时间为 80 ms,偶尔却要等五秒。CPU 看起来不高,调大 Nginx 超时后投诉也没有消失。问题可能发生在建立上游连接、数据库查询、应用排队、响应传输,甚至客户端上传请求的阶段。
本文从日志设计开始,把“慢”拆成可提出假设的阶段。所有数字与故障均为演示场景,配置需要在隔离环境验证后再应用,不代表某台服务器已经完成这些改造。
平均值为什么容易骗人
假设一分钟内有 990 个请求耗时 50 ms,另有 10 个请求耗时 4 s。平均耗时为 (990×0.05+10×4)/1000=0.0895 s,看起来只有 89.5 ms,但仍有 1% 用户经历了四秒等待。此时平均值不适合回答最慢用户的体验问题。
观察分位数也要保留样本数量。每分钟只有 20 个请求时,p99 很大程度受单个样本影响。还要区分端点、方法、状态码和响应体大小:把小型健康检查与大型导出混在一起,会让业务退化被高频快请求稀释。
第一组观测可以选择端点级请求量、p50、p95、错误数与在途请求数,时间粒度一致。它比一条“总体平均延迟”更容易发现突发与排队之间的关联。
还可以用一个稳态近似估算排队风险:到达速率每秒五十次,平均在系统停留两秒,平均在途量约为一百。若应用只容许二十个并发,就必须解释剩余请求在哪里排队,以及队列是否有上限。这个近似要求观察窗口较稳定,不能直接拿突发瞬间套公式;它的用途是发现容量解释中的数量级错误。客户端若只在上次请求完成后才发送下一次,慢下来时也会自动降低发压速率,压测结果便可能低估真实固定到达负载下的排队。
记录能关联的时间,而不是更多隐私
$request_time 从读取客户端首批字节开始,到发送响应并记录日志结束,单位为秒,精度为毫秒。它不是纯粹的应用计算耗时。JSON 日志应使用 escape=json,避免引号等字符破坏格式。Nginx 访问日志模块
下面是放在 http 上下文中的示例。只记录规范化路径 $uri,不记录查询串、Authorization 和 Cookie,避免笔记搜索内容或令牌进入普通访问日志。
1 | log_format latency escape=json |
上游相关字段保持字符串,是因为未访问上游时可能为 -,多次尝试时也可能包含多个值。把它强行写成 JSON 数字,会让某些错误请求恰好失去可解析日志。请求 ID 应由可信边界产生并传给应用,应用也记录同一 ID;否则只能按时间大致猜测是哪一次慢查询。
三种上游时间不能随意相加
上游连接时间、收到响应首部的时间、收到完整上游响应的时间,分别由 $upstream_connect_time、$upstream_header_time 和 $upstream_response_time 表达。它们不是三个互不重叠的独立耗时段;重试或内部跳转还可能产生多组值。Nginx 上游时间变量
对于单次普通代理请求,假设日志为 uct=0.002、uht=2.100、urt=2.150、rt=2.180,更合理的初步假设是“应用开始返回首部之前的等待占主要部分”,而不是把四个数字相加得到总耗时。应再用同一请求 ID 对照应用的排队与数据库 span。
如果 uct 明显增长,先观察后端是否仍监听、连接队列是否饱和以及网络路径;若 uht 高而 uct 稳定,优先检查应用排队和依赖;若 urt-uht 很大,查看响应体大小和上游生成速度。这些只是缩小范围的推断,不是单凭一个差值就能证明某个模块有缺陷。
另一个例子是 rt=8.0、urt=0.08,大响应体发往慢客户端可能形成这种差距。但请求体接收、缓冲策略和其他阶段也会影响结果,不能把差值直接命名为“网络耗时”。需要对照下载速率、响应大小和客户端测试。
超时应该是预算,而不是统一改成 60 秒
假设产品希望常规查询在 3 秒内给出结果。可以为应用内部工作设置 2 秒总体截止时间,为代理及返回留出余量,并让客户端截止时间略大于服务端预算。数据库调用必须拿到“剩余时间”,否则前面排队 1.8 秒后,数据库又从头获得 2 秒,整体预算就失效了。
proxy_connect_timeout 约束与上游建立连接的阶段;proxy_read_timeout 约束相邻两次读取之间的等待,并不是整个响应从头到尾的总时长限制。上游持续分块输出时,总响应时间可以超过该数值。Nginx 代理超时定义
因此不能声称下面配置实现了“接口严格三秒结束”。它只是一个普通短查询路由的网络阶段保护示例,总体截止时间仍应由应用和客户端共同实现。
1 | location /api/notes/ { |
导出、SSE 和长轮询应有独立预算。为一个持续十分钟的导出扩大所有路由超时,会让普通故障更久占用连接。如果导出不需要实时完成,可以改为提交任务、查询状态、下载结果,让交互请求保持短时。
重试会把局部慢放大成整体慢
某个只读请求第一次等待 1.5 秒,重试又等 1.5 秒,加上连接与传输,客户端三秒预算已经耗尽。若客户端、代理、应用三层都各重试两次,最坏尝试数会呈乘法增长,而不是简单增加两次。
应先定义谁拥有重试权,再决定哪些错误可以重试。写入请求尤其要考虑幂等键和“后端已完成、客户端未收到”的状态;把 POST 自动重放可能重复创建数据。即使是 GET,重试也应受剩余预算、次数和后端负载约束,而不是保证一定执行到成功。
客户端中断对应的日志状态,也不能简单算作服务端业务异常。应关联用户主动取消、网络变化与上游仍在执行的任务。如果客户端已经离开而昂贵任务继续计算,应用层取消传播可能比增加 worker 更值得优先处理。
在测试环境逐个改变故障变量
创建只在回环地址暴露的测试后端,分别模拟连接失败、首部前等待两秒、快速首部后缓慢传输,以及正常响应。每次保持相同 URL 和请求体,确认日志字段随预期变化。测试后端不应暴露公网,也不要在生产路由加入故意延迟。
客户端可以记录 DNS、连接、TLS、首字节和总耗时,帮助发现代理日志看不到的阶段。curl 写出变量说明
1 | curl --silent --show-error --output /dev/null --max-time 5 \ |
这些 curl 时间多数是从请求开始累计到阶段完成,不能不加区分地相加。HTTP 回环测试没有 TLS 阶段,也无法代表用户到机房的网络体验。进一步做公网采样时,应记录地区、网络类型、连接是否复用,并限制频率。
验收条件应与用户问题一致
如果修复的是应用排队,就固定请求混合比例,在相同并发下比较队列长度与 p95;如果改的是大文件传输,就比较不同带宽客户端的总时间、内存和临时文件开销。单次 curl 快了十毫秒,不能证明高峰故障已经消失。
我希望最后得到的解释是“高峰时图像任务占满应用工作池,使普通查询在返回首部前排队”,并能用相同请求 ID、队列曲线和复现测试支持它。日志的价值是把一个模糊的“网站慢”变成可证伪的工程假设,再让每次配置调整都有清楚的目的。