{"id":1459,"date":"2026-10-21T23:04:58","date_gmt":"2026-10-21T23:04:58","guid":{"rendered":"https:\/\/virtualserversvps.com\/blog\/?p=1459"},"modified":"2026-10-21T23:04:58","modified_gmt":"2026-10-21T23:04:58","slug":"instrumenting-nginx-request-timing-p99-latency-vps","status":"publish","type":"post","link":"https:\/\/virtualserversvps.com\/blog\/instrumenting-nginx-request-timing-p99-latency-vps\/","title":{"rendered":"Instrumenting nginx Request Timing to Find Where p99 Latency Actually Comes From"},"content":{"rendered":"\n

A slow page is rarely one slow thing. It is a sum of intervals: time queued in the accept backlog, time waiting for a free PHP-FPM worker, time spent in the application, time waiting on the database, and time spent copying the response back through the socket. Nginx can record most of these intervals per request through log_by_lua<\/code> and the built-in timing variables, which turns p99 latency debugging from guesswork into arithmetic. This tutorial builds that instrumentation, then shows how to read the output.<\/p>\n\n\n\n

Everything below assumes nginx 1.24+ with ngx_http_lua_module<\/code> (the libnginx-mod-http-lua<\/code> package on Debian and Ubuntu). It works identically on a virtual server running the standard nginx build<\/a> or on any provider with the module installed.<\/p>\n\n\n\n

What the built-in timing variables already tell you<\/h2>\n\n\n\n

Before adding any Lua, know which timings nginx exposes natively. Each is milliseconds, and each starts at a different point in the request lifecycle.<\/p>\n\n\n\n

Variable<\/th>What it measures<\/th>Typical suspect when high<\/th><\/tr><\/thead>
$request_time<\/td>First byte read to last byte sent<\/td>Total, including client slowness<\/td><\/tr>
$upstream_response_time<\/td>Connect + send + receive from backend<\/td>PHP-FPM queue, DB, app logic<\/td><\/tr>
$upstream_connect_time<\/td>TCP connect to backend<\/td>Backlog saturation, keepalive disabled<\/td><\/tr>
$upstream_header_time<\/td>Up to first response header byte<\/td>Application time before any output<\/td><\/tr>
$request_length<\/td>Bytes received from client<\/td>Large uploads, abuse<\/td><\/tr>
$body_bytes_sent<\/td>Bytes sent to client<\/td>Uncompressed payloads<\/td><\/tr><\/tbody><\/table><\/figure>\n\n\n\n

The gap $request_time − $upstream_response_time<\/code> is nginx-side overhead plus client transfer time. On a healthy LAN-proxied stack that gap should stay under 5 ms for small responses. If it exceeds 50 ms while $upstream_response_time<\/code> is flat, your bottleneck is the network path or client-side transfer, not the application.<\/p>\n\n\n\n

Instrument the two gaps nginx does not expose<\/h2>\n\n\n\n

Two intervals matter and are invisible in the default variables: time spent in the rewrite\/access phase before proxying, and time from upstream completion to the end of the request. Capture them with a small Lua block in the http<\/code> context.<\/p>\n\n\n\n

lua_shared_dict phase_timing 10m;

init_by_lua_block { require \"resty.core\" }

log_by_lua_block {
  local now = ngx.now() * 1000
  local start = ngx.ctx.app_start
  local up_end = ngx.ctx.upstream_end
  if start and up_end then
    local pre = (start - ngx.req.start_time() * 1000)
    local post = now - up_end
    local dict = ngx.shared.phase_timing
    dict:incr(\"pre_ms\", math.floor(pre), 0)
    dict:incr(\"post_ms\", math.floor(post), 0)
    dict:incr(\"req_count\", 1, 0)
  end
}<\/code><\/p>\n\n\n\n

In the server or location block, mark the boundaries around the proxy call:<\/p>\n\n\n\n

set_by_lua_block $app_mark { ngx.ctx.app_start = ngx.now() * 1000; return \"\" }
log_by_lua_block { ngx.ctx.upstream_end = ngx.now() * 1000 }<\/code><\/p>\n\n\n\n

These are coarse averages, not percentiles, but they are enough to answer the first question in any investigation: is latency being added before the backend, inside it, or after it? Expose the counters on a private status endpoint with content_by_lua_block { ngx.say(require(\"cjson\").encode(ngx.shared.phase_timing:get_keys(0))) }<\/code> restricted to 127.0.0.1<\/code>.<\/p>\n\n\n\n

Build a structured log format for percentile analysis<\/h2>\n\n\n\n

Human-readable logs cannot be aggregated. Emit JSON with every timing field so you can compute percentiles with jq<\/code> or ship them to Prometheus via a log exporter.<\/p>\n\n\n\n

log_format timing escape=json '{\"t\":\"$time_iso8601\",\"uri\":\"$uri\",\"status\":$status,'
' \"rt\":$request_time,\"urt\":$upstream_response_time,'
' \"uct\":$upstream_connect_time,\"uht\":$upstream_header_time,'
' \"sz\":$body_bytes_sent,\"up\":\"$upstream_addr\"}';<\/code><\/p>\n\n\n\n

Reload with nginx -t && systemctl reload nginx<\/code>, generate load for ten minutes, then compute p50 and p99 directly:<\/p>\n\n\n\n

jq -r 'select(.urt != null) | .urt' \/var\/log\/nginx\/timing.log | sort -n | awk '{a[NR]=$1} END {print \"p50=\"a[int(NR*0.5)]\" p99=\"a[int(NR*0.99)]\" n=\"NR}'<\/code><\/p>\n\n\n\n

Note that $upstream_response_time<\/code> can contain a comma-separated list when a request is retried against multiple upstreams. For percentile maths you need the total, so either sum the values in Lua or configure proxy_next_upstream off<\/code> for the specific location you are measuring.<\/p>\n\n\n\n

Separate queue time from service time<\/h2>\n\n\n\n

On a small instance the most common cause of rising p99 is PHP-FPM pool saturation: requests sit in the listen backlog until a worker frees up. Nginx sees that wait as upstream connect time, because the connection is accepted but no worker reads it. Cross-check the two sides:<\/p>\n\n\n\n