先把当时的情况摆出来。压测时接口明明要 1.8 秒,access.log 里 request_time 和 upstream_response_time 两列却全是 0.000,整份日志看上去每个请求都瞬间返回。Nginx 版本 1.20,log_format 是从旧机器上整段拷过来的,升级过一次配置后这两个字段就一直不对。

排查方向其实有限,先把可能性排一排。log_format 里字段名拼成了 $requesttime 变量不存在解析为空。还有一种是日志被 upstream 的缓存层接管 上游命中缓存后毫秒级返回真实耗时被掩盖。

还有一种情况,时间单位配置改了仍按秒记录 小于一秒的值一律显示为 0.000。另外,字段位置在引号外 被 nginx 当成字面量输出成固定字符串。

第一件事是确认当前生效的 log_format 定义

nginx -T | grep -A3 'log_format main'

单独打一行测试日志看字段是否被解析

curl -s -o /dev/null -w '%{time_total}\n' https://www.example.com/

随后改成毫秒单位并补上上游耗时

log_format main '$remote_addr $request_time $upstream_response_time $status';

剩下的就是重载配置后抽查慢请求

awk '$2>1.0 {print}' access.log | head -20

恢复的判定其实很直接。重载之后日志里开始出现 0.8 到 2.3 之间的真实耗时,按耗时排序能直接看到那几个慢查询接口,与压测结果一致。

提醒一点。耗时字段全为零通常不是没有慢请求,而是字段没被解析出来,先验证变量名再怀疑性能。同一份配置在测试环境跑通,不代表线上没事,两边的默认值经常不一样。

作者 9823189