京公网安备11010502063487号access log 里的 request_time 和 upstream_response_time 为什么不相等?差在哪一段?缓冲开关、慢 client、重试各会让它们怎样变化?这篇用 nginx 1.31.6 把 6 种情形逐个量出来。
情形 | $request_time ms | $upstream_connect_time ms | $upstream_header_time ms | $upstream_response_time ms | $status ------------------------------------------------------+------------------+---------------------------+--------------------------+----------------------------+-------- (1) 快上游 · 快 client | 3 | 0 | 2 | 3 | 200 (2) 慢上游(200 ms)· 快 client | 211 | 1 | 211 | 211 | 200 (3) 快上游 · 5 MB 响应 · 慢 client(2 MB/s)· buffering on | 2675 | 0 | 2 | 5 | 200 (4) 同 (3) · proxy_buffering off | 2613 | 1 | 4 | 2613 | 200 (5) 快上游 · 慢上传(POST 3 MB,1 MB/s)· request_buffering on | 3213 | 0 | 4 | 6 | 200 (6) 同 (5) · proxy_request_buffering off | 3208 | 1 | 3102 | 3102 | 200 $request_time 包含 client 一侧的时间(上传请求体、下载响应体),$upstream_* 只看 nginx 和上游之间。(3) 缓冲打开时,nginx 很快收完上游的 5 MB(upstream_response_time 小),再慢慢发给慢 client(request_time 大):两者的差就是 client 一侧耗掉的时间;(4) 关掉缓冲后上游被拖到 client 的速度,upstream_response_time 也变大。(5) 请求体缓冲打开时,nginx 先收完 3 MB 才去连上游,upstream_* 里不含上传时间;(6) 关掉请求缓冲边收边转,上游的响应时间包含了上传过程
request_time 含 client 一侧的上传与下载时间;缓冲决定这些时间会不会算进 upstream 时间。
$request_time ms | $upstream_addr | $upstream_status | $upstream_connect_time ms | $upstream_header_time ms | $upstream_response_time ms | $status -----------------+------------------------------+------------------+---------------------------+--------------------------+----------------------------+-------- 27 | 127.0.0.1:A(死的), 127.0.0.1:B | 502, 200 | - / 0 | - / 26 | 0 / 27 | 200 22 | 127.0.0.1:B | 200 | 0 | 21 | 21 | 200 21 | 127.0.0.1:A(死的), 127.0.0.1:B | 502, 200 | 0 / 0 | - / 20 | 0 / 20 | 200 29 | 127.0.0.1:B | 200 | 0 | 29 | 29 | 200 被轮询到 A 的请求有两项(先 A 后 B):A 那一项的状态是 502(连接被拒时 nginx 自己记的,不是上游真的回了 502),时间项里是 “-” 或 0;只打到 B 的请求只有一项。统计耗时时不能直接把这些字段当数字解析,要先按逗号拆开;同一个请求的 $request_time 是总耗时,不等于各项之和
字段是逗号分隔的列表,解析前要拆开并处理 “-”。
上游连接 | 请求 | $request_time ms | $upstream_connect_time ms | $upstream_header_time ms | $upstream_response_time ms
--------------+-------+------------------+---------------------------+--------------------------+---------------------------
keepalive(默认) | 第 1 个 | 260 | 1 | 159 | 260
| 第 2 个 | 267 | 0 | 160 | 267
| 第 3 个 | 253 | 0 | 152 | 252
每次新建连接 | 第 1 个 | 263 | 0 | 157 | 264
| 第 2 个 | 263 | 0 | 155 | 263
| 第 3 个 | 259 | 0 | 151 | 258
$upstream_header_time 是从发出请求到收到响应头(这里约 150 多 ms),$upstream_response_time 再加上收响应体的时间(这里约 260 ms)。$upstream_connect_time 在本机环回上建连接不到 1 ms,所以不管复用还是新建都显示 0(或 1),这个实验看不出连接复用对它的影响header_time 到响应头,response_time 到响应体收完;环回上 connect_time 看不出差别。