nginx request_time is fast, but users say it's slow

Update (2026-10-12): Starting with nginx 1.29.7 (1.30 on the stable branch), upstream keepalive is enabled by default (keepalive 32 local), proxy_http_version defaults to 1.1, and the Connection header is no longer sent by default (CHANGES). On 1.30 and later, the settings in the "Upstream keepalive" section are the defaults, so you don't need to add them. That section applies to 1.29.6 and earlier.

Your nginx $request_time looks fine in the dashboard — p95 is 120ms.

But users keep reporting that things "occasionally freeze." You've only been watching p95. Go down to p99 and you do find requests that took a few hundred milliseconds, but that number doesn't tell you where the time went. The upstream app team says "our side is fast." nginx looks fast too.

$request_time collapses everything that happened during the request into a single number. Because it's a total, you can find the slow requests but not the phase where the time was lost.

nginx does record timestamps at each intermediate checkpoint, though. Subtract them, and latency breaks into 4 distinct parts.

Inside $request_time

$request_time measures everything from when nginx reads the first byte from the client to when it finishes sending the last byte of the response¹. In a reverse proxy setup, that single number includes at least all of:

• time to establish a connection to the upstream backend
• time until the backend starts returning a response (backend processing time)
• time to receive the full response from the backend
• nginx's own processing and the time to send the response back to the client

All of this gets summed into one $request_time. So even if p95 is 120ms, you cannot tell from that number alone whether the breakdown is "20ms backend, 100ms sending" or "100ms connecting, 20ms everything else." Those scenarios call for completely different fixes, but $request_time erases the distinction.

The TLS handshake on the client side happens before $request_time starts, since the clock starts at "first byte received." If you suspect TLS overhead and stare at $request_time, it won't show up there.

Log configuration

The breakdown analysis below requires $upstream_connect_time, $upstream_header_time, and $upstream_response_time to be present in your access log. Open your own logs and there's a good chance none of these are there.

nginx's default combined log format doesn't include any of them. combined logs eight fields — remote address, user, timestamp, request line, status, response bytes, referer, and user agent. $request_time isn't even there².

Until you define a custom log_format and reload nginx, this breakdown isn't possible.

log_format latency '$remote_addr "$request" $status '
                   'rt=$request_time '
                   'uct=$upstream_connect_time '
                   'uht=$upstream_header_time '
                   'urt=$upstream_response_time';

access_log /var/log/nginx/access.log latency;

$upstream_header_time was added in nginx 1.7.10 and $upstream_connect_time in 1.9.1; earlier versions don't have them³.

After adding this and running nginx -s reload, the raw data you need starts appearing in logs. Logs written before the reload won't have these fields, so there's no way to retroactively see the breakdown for historical requests.

There's also an approach that captures timing directly from the kernel without touching the nginx config. ngxray explores that direction (currently in development).

The 4 parts

When nginx runs as a reverse proxy, each request passes through the points below. Of these, t2, t3, and t4 are where nginx stores the time spent on the upstream interaction in variables.

Point	What happens	Variable whose measurement ends here
t0	nginx reads the first byte of the request from the client
t1	nginx finishes reading the request and starts upstream processing
t2	The connection to the upstream is established (TLS handshake included if the upstream is HTTPS)4	$upstream_connect_time
t3	nginx finishes receiving the response headers from the upstream	$upstream_header_time
t4	nginx finishes receiving the full response from the upstream	$upstream_response_time
t5	nginx finishes sending the last byte of the response to the client	$request_time

$request_time and the three variables overlap as follows. The 1–4 on the bottom row are ①–④ in the table below.

t0     t1    t2        t3       t4     t5
|      |     |         |        |      |
$request_time
[======================================]
       $upstream_response_time
       [========================]
       $upstream_header_time
       [===============]
       $upstream_connect_time
       [=====]
<-4--> <-1-> <---2---> <--3---> <-4-->

All three variables are cumulative values measured from t1, and they're nested⁵.

Once you understand they're cumulative, subtraction gives you the individual intervals.

Part	Interval	Formula	What it measures
① Connect	t1–t2	$upstream_connect_time	Time to connect to upstream (TLS included)
② Backend processing	t2–t3	$upstream_header_time − $upstream_connect_time	Time until upstream starts responding (TTFB)
③ Response transfer	t3–t4	$upstream_response_time − $upstream_header_time	Time to receive the full response from upstream
④ Client + nginx internal	t0–t1, t4–t5	$request_time − $upstream_response_time	Request body read, nginx internals, sending to client

Which part is thick tells you where to look: ① is thick → upstream keepalive probably isn't configured; ② is thick → backend processing is the bottleneck; ③ is thick → look at transfer size or upstream bandwidth; ④ is thick → suspect client connection speed or response body size.

Clients on slow connections

Don't read ④ as "nginx is slow." It captures request body reading, rewrite/access phases, and the time to finish delivering the response to the client. When only clients on slow connections are slow, ①②③ stay small, and the time piles up only in the t4–t5 portion of ④. This assumes proxy_buffering is on (the default)⁶, where nginx holds the upstream response in buffers (writing any overflow to a temporary file) and reads all of it from the upstream without waiting for it to be sent to the client. If buffering is off, slow-client impact can bleed back into ③, so suspect both in that case.

And don't look at averages. Break each of the four parts into p50 / p95 / p99 separately. Then see which part's p99 stands out.

The numbers below are for illustration:

Part	p50	p95	p99
① Connect	1ms	2ms	3ms
② Backend processing	15ms	95ms	130ms
③ Response transfer	3ms	15ms	25ms
④ Client + nginx internal	2ms	8ms	380ms

Even when $request_time p95 looks clean at 120ms, the p99 for ④ alone can spike to 380ms. That slowness shows up in the p99 of $request_time too, but the total can't tell you whether it came from ② the backend or ④ the client side. Splitting p99 per part is what pins the source down to ④.

p99 aggregation

From the latency format defined above, this awk example computes p50 / p95 / p99 for part ④, client-side (rt - urt). Sorting is left to sort, so it runs on gawk and BSD awk alike.

awk '
# Skip multi-value lines (they cannot be subtracted) and count them
/(uct|uht|urt)=[^ ]*, /  { retry++; next }  # comma-separated: retry
/(uct|uht|urt)=[^ ]* : / { redir++; next }  # colon-separated: internal redirect
{
  rt = uct = uht = urt = ""
  for (i = 1; i <= NF; i++) {
    if ($i ~ /^rt=/)  rt  = substr($i, 4)
    if ($i ~ /^uct=/) uct = substr($i, 5)
    if ($i ~ /^uht=/) uht = substr($i, 5)
    if ($i ~ /^urt=/) urt = substr($i, 5)
  }
  # Also skip lines that never reached an upstream (value is "-")
  if (rt ~ /^[0-9.]+$/ && urt ~ /^[0-9.]+$/) print rt - urt
}
END { printf "excluded: retry=%d redirect=%d\n", retry, redir > "/dev/stderr" }
' /var/log/nginx/access.log | sort -n | awk '
function q(p,  i) { i = int(NR * p); if (i < NR * p) i++; return a[i < 1 ? 1 : i] }
{ a[NR] = $1 }
END { if (NR) printf "p50=%.3f  p95=%.3f  p99=%.3f\n", q(0.50), q(0.95), q(0.99) }'

The structure is the same for every other part. For ② backend processing, change the last condition and print so they check and output uht - uct; for ③ response transfer, urt - uht. Lines that never reached an upstream (value -) and lines with multiple values are excluded.

The excluded multi-value lines are counted separately on the excluded: line. Requests that hit a retry are a likely source of tail latency, yet they are missing from this p99. If retry isn't 0, pull those lines with grep 'urt=[^ ]*, ' /var/log/nginx/access.log and look at their rt= values separately.

In production you can run equivalent aggregations in Loki, CloudWatch Logs Insights, or Datadog log queries.

Upstream keepalive

When you break down the parts, you occasionally see a pattern where ②③④ are all small but $upstream_connect_time registers as non-zero on every single request. The responses themselves are lightweight, but there's a small constant overhead on every request.

The TCP connection to the upstream isn't being reused. When connections are kept alive and reused, $upstream_connect_time should be 0.000 for most requests after the first. If it's consistently non-zero on every request, nginx is creating a new connection for each one — keepalive to the upstream isn't configured.

The $upstream_* values are recorded with millisecond resolution, though⁷. If the upstream is on 127.0.0.1 or in the same VPC and a connection takes less than 1ms to open, you will see 0.000 even when every request opens a new connection. You can judge keepalive from uct= only when the round trip to the upstream takes milliseconds.

Two directives work together here:

upstream backend {
    server 127.0.0.1:3000;
    keepalive 32;
}

server {
    location / {
        proxy_pass http://backend;
        proxy_http_version 1.1;
        proxy_set_header Connection "";
    }
}

keepalive 32 sets the maximum number of idle connections each worker keeps in its cache. It doesn't limit the total number of connections to the upstream. proxy_http_version 1.1 and proxy_set_header Connection "" are required because HTTP/1.0 sends Connection: close by default, which causes the upstream to close the connection immediately. Without those two lines, keepalive does nothing⁸.

After adding the config and running nginx -s reload, check the uct= values in the access log, as long as the round trip to the upstream takes milliseconds. The first request on each worker will be non-zero since it's establishing the connection. If most subsequent requests show 0.000, connection reuse is working. When concurrent connections exceed each worker's idle-connection limit, some new connections will still appear.

Opening a new connection every time also leads to TIME_WAIT buildup and ephemeral port exhaustion, which this article doesn't cover.

Reading commas and colons

There's another pattern that breaks the subtraction: looking at a $upstream_* value and finding more than one number.

uct=0.001, 0.003 uht=0.012, 0.045 urt=0.012, 1.230

This isn't a broken log. nginx logs multiple values when a single request involves multiple upstream interactions⁹. The delimiter carries meaning.

• Comma-separated (0.001, 0.003): the request hit multiple upstream servers in sequence. The typical case is the first server failed and the second was tried as a retry/failover.
• Colon-separated (0.001 : 0.003): an internal redirect via X-Accel-Redirect or similar occurred, spanning multiple upstream groups.

If you treat this as a single value and compute $request_time − $upstream_response_time, the subtraction breaks completely. The string "0.012, 1.230" isn't a number.

If you drop comma-separated lines from the aggregation, requests that hit a retry disappear from it. If you compute from the first value only, the time spent on the retry lands in ④. Colon-separated values come from internal redirects and appear even when nothing is wrong. When a slow request shows comma-separated upstream times, investigate the retry before the interval breakdown.

How to check

First, check whether your access log includes $upstream_connect_time, $upstream_header_time, and $upstream_response_time. If you're still on combined, it doesn't. If they're there, lay out p50 / p95 / p99 for each of the 4 parts, including $request_time − $upstream_response_time. Then check whether $upstream_connect_time is non-zero on every request, and whether any requests have multiple $upstream_* values separated by commas or colons.

For broader observability — metrics exporters, log visualization tools, and the validation and testing tools that sit around nginx's config — there's a roundup of the nginx ecosystem that maps what fits where.

---

1. The nginx docs on $request_time. ↩

2. The definition of combined in the nginx docs on log_format. ↩

3. The nginx docs on $upstream_header_time and $upstream_connect_time. ↩

4. The nginx docs on $upstream_connect_time. ↩

5. In the nginx 1.30.5 source, nginx records u->start_time when it starts processing the upstream, and computes all three by subtracting it from the current time (connect, header, response). The nginx official blog describes $upstream_header_time as the time "between establishing a connection and …", which leaves it unclear whether $upstream_connect_time is included. The source shows that it is. ↩

6. The nginx docs on proxy_buffering. ↩

7. The nginx docs on the variables that hold upstream times ($upstream_connect_time and others). ↩

8. The nginx docs on keepalive. ↩

9. The nginx docs on $upstream_addr, which explain when commas and when colons are used. ↩