$request_time Looks Fast, But Users Say It''s Slow: Breaking nginx Latency into 4 Parts

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

But users keep reporting that things "occasionally freeze." You dig through the logs looking for slow requests and find nothing obvious. Overall p95 is healthy. The upstream app team says "our side is fast." nginx looks fast too. Yet the complaints are real. You don't know where to look.

$request_time collapses everything that happened during the request into a single number. Fast phases and slow phases all get averaged together, making it impossible to see where the time actually went.

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

The log variables covered here and what they measure are the same regardless of nginx version.

What one number hides

$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.

Also worth noting: 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.

Before you start: add variables to your log format

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.

The reason is simple: 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. Upstream timing variables are excluded by design.

Until you define a custom log_format and reload nginx, this breakdown is physically impossible. You can't subtract what doesn't exist. Fix the log definition first.

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;

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).

Breaking it into 4 parts

When nginx operates as a reverse proxy, it records three timestamps for the upstream interaction. These are the basis for the breakdown.

• $upstream_connect_time: time until the connection to the upstream is established (includes TLS handshake if the upstream is HTTPS)
• $upstream_header_time: time until nginx starts receiving the response headers from the upstream
• $upstream_response_time: time until nginx has received the full response from the upstream

All three are measured from the same starting point — the moment nginx begins processing the upstream. They're not three independent intervals; they're cumulative values. $upstream_response_time contains $upstream_header_time, and $upstream_header_time contains $upstream_connect_time. They're nested.

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

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

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 users on slow connections are the only ones complaining, ①②③ will look fine while ④ carries all the time. Slow clients only become visible through this breakdown. This assumes proxy_buffering is on (the default), where nginx buffers the full upstream response before sending 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. Whichever part has a spiking p99 is your answer.

For example, laying out p50 / p95 / p99 per part might reveal a distribution like this (these numbers are for illustration):

Part             p50     p95     p99
① connect         1ms     2ms     3ms
② backend        15ms    40ms    60ms
③ transfer        3ms     8ms    12ms
④ client+nginx    2ms     5ms   380ms   ← here

Even when $request_time p95 looks clean at 120ms, the p99 for ④ alone can spike to 380ms. That's what "occasionally freezes" actually is — buried in the overall average and p95, but visible as soon as you look at p99 per part.

Once you know which part is the problem, the next action follows directly: ① is thick → upstream keepalive probably isn't configured (covered in the next section); ② 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.

Even the nginx official blog's explanation writes that $upstream_header_time measures the time "between establishing a connection and …" — it's ambiguous whether that excludes $upstream_connect_time or includes it. Rather than memorizing each variable's exact definition, it's more reliable to internalize the structure: all three accumulate from the same origin, and you subtract to get intervals.

Computing p50/p95/p99 per part

"Look at p99 per part" is easy to say, but how do you actually get those numbers? Using the latency format defined above, here's an awk example to compute percentiles.

To extract percentiles for part ④, client-side (rt − urt):

awk '{
  for (i = 1; i <= NF; i++) {
    if ($i ~ /^rt=/)  { rt  = substr($i, 4) }
    if ($i ~ /^urt=/) { urt = substr($i, 5) }
  }
  if (rt != "" && urt != "" && urt + 0 >= 0) a[++n] = rt - urt
}
END {
  asort(a)
  printf "p50=%.3f  p95=%.3f  p99=%.3f\n",
    a[int(n * 0.50)], a[int(n * 0.95)], a[int(n * 0.99)]
}' /var/log/nginx/access.log

The structure is the same for every other part. For ② backend processing use uht - uct; for ③ response transfer use urt - uht.

In production you can run equivalent aggregations in Loki, CloudWatch Logs Insights, or Datadog log queries. The key is not "overall p95" but "p99 per part, listed separately." No matter how good a single number looks, the problem stays hidden until you split the breakdown and look at each part's p99.

When ① is always non-zero

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 near 0 (or -) after the first request. 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. This tends to get overlooked in long-running systems.

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 persistent connections the worker keeps in the pool. 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. The first request will be non-zero since it's establishing the connection. If subsequent requests show 0.000 or -, connection reuse is working.

Repeatedly opening new connections also leads to TIME_WAIT buildup and ephemeral port exhaustion, but that's a different layer of concern. For this article, the key read is: "① consistently non-zero = connections aren't being reused."

When the breakdown breaks: 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.

More importantly, multiple values are a signal of something abnormal. Two comma-separated values mean there was a retry — the first upstream attempt failed. That failure was buried in the average and invisible. When a slow request shows comma-separated upstream times, investigate the retry before worrying about the interval breakdown.

Closing: where is your time going?

Rather than wrapping this up as a checklist of solutions, here are questions to bring to your own logs.

1. Does your access log include $upstream_connect_time, $upstream_header_time, and $upstream_response_time? Are you still running the combined format?
2. Are you looking at p50 / p95 / p99 separately for each of the 4 parts, not just $request_time as a whole?
3. Have you ever computed $request_time − $upstream_response_time (part ④, client + nginx internal)?

4. Is $upstream_connect_time non-zero on every request?

5. Can you interpret what it means when $upstream_* has multiple values separated by commas or colons?

6. Can you explain "numbers look fast but users say slow" using per-part p99 rather than averages?

If any answer is no, you haven't broken down latency yet. As long as that's the case, "fast numbers, slow experience" stays a permanent contradiction.

$request_time doesn't lie. It just compresses too much into one number. Split it four ways and you can always pinpoint where the time went. Start by opening your access log and checking whether $upstream_response_time is even being recorded.

References (official documentation)

Every variable and behavior discussed here is documented in the official nginx docs.

• ngx_http_upstream_module: definitions of $upstream_connect_time, $upstream_header_time, $upstream_response_time; meaning of comma/colon separators; TLS handshake handling
• ngx_http_log_module: log_format and the default combined format definition
• Using NGINX Logging for Application Performance Monitoring: upstream timing variable usage
• nginx source ngx_http_upstream.c: confirmation that all three variables share the same origin (u->start_time) and the nested structure