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

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.

$request_time is a sum

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

The default log can't split it

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

Subtract to get 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.

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.

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

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.

Slow connections don't show in upstream times

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. 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. Then see which part's p99 stands out.

The numbers below are for illustration:

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

Getting p99 per part

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 isn't working

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.

A comma means a retry

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.

Check it in your own environment

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.

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