Instrumenting nginx Request Timing to Find Where p99 Latency Actually Comes From

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

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

What the built-in timing variables already tell you

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

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

The gap $request_time − $upstream_response_time 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 is flat, your bottleneck is the network path or client-side transfer, not the application.

Instrument the two gaps nginx does not expose

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

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
}

In the server or location block, mark the boundaries around the proxy call:

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 }

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))) } restricted to 127.0.0.1.

Build a structured log format for percentile analysis

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

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"}';

Reload with nginx -t && systemctl reload nginx, generate load for ten minutes, then compute p50 and p99 directly:

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}'

Note that $upstream_response_time 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 for the specific location you are measuring.

Separate queue time from service time

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:

• In nginx, p99 of $upstream_connect_time above 20 ms on loopback is a red flag.
• In PHP-FPM, set request_slowlog_timeout = 5s and read the slowlog for requests that never even reach the application.
• ss -lnt '( sport = :9000 )' — a non-zero Send-Q on the listen socket confirms a full accept queue.
• During the test, run pidstat -u -p $(pgrep -d, php-fpm8.3) 1 10 to see whether workers are CPU-busy or blocked in D state.

If connect time is high and workers are blocked in D, the problem is disk I/O, and no amount of nginx tuning will help. If workers are busy on CPU, the fix is more children or a faster path; if the accept queue is full and CPU is idle, you have an I/O or lock contention problem hiding behind it.

Attribute the gap to database calls with request IDs

Generate a request ID at the edge and pass it to PHP, then log it in your database layer:

map $request_id $proxied_req_id { default $request_id; }
proxy_set_header X-Request-ID $proxied_req_id;

In PHP, log $_SERVER['HTTP_X_REQUEST_ID'] alongside each query’s duration. Now a slow nginx entry maps to a specific set of queries without guesswork. This is the single highest-value change when a page shows high $upstream_header_time but flat CPU usage — almost always a query waiting on a lock or a table scan.

Turn the numbers into a decision rule

After a week of data, classify each slow request against the timing table above. Requests with high $upstream_header_time and low CPU are application or database problems. Requests with high $upstream_connect_time are pool sizing problems. Requests with a large gap between $request_time and $upstream_response_time are network or client problems, frequently large uncompressed payloads — check whether gzip or brotli is enabled for that content type. Requests with high post-upstream time on small responses point to sendfile or TLS record sizing issues.

Keep the raw JSON logs for at least 72 hours and rotate them by size, not by day, because high-traffic hours can produce a gigabyte in a few hours. The measurement layer described here complements the broader approaches in the hosting tier performance comparison — instrumentation is what makes a plan upgrade decision provable instead of speculative.