ProductionAdvanced

Slow requests, idle server

“Requests to your API take 3 seconds at p99, but the server sits at 5% CPU and the handler itself measures 20 ms. Where can the other 2.98 seconds be, and how would you find them?”

What this tests

  • A request timeline with every stage before and after the handler
  • Recognition of protocol timers by their exact values (1 s, 3 s, 5 s, 200 ms, 40 ms)
  • Per-hop measurement rather than guessing
  • Distinguishing network, kernel, queueing and client-side causes

Answers by level

Read the beginner answer first and notice what is missing.

The handler’s 20 ms is measured from the moment the framework calls it — a request has a long life before and after that point, and none of it burns CPU. Lay out the timeline (Where the Time Goes: The Request Timeline): client DNS lookup → TCP handshake → TLS handshake → request bytes cross the network → the kernel’s accept queue → the application’s own queue (thread pool, event loop) → the handler → response bytes written to the socket buffer → transferred to the client → parsed. "Idle CPU plus slow requests" means the request is *waiting*, and each stage has a characteristic wait.

Exact values are fingerprints. A p99 of ~1 s or ~3 s is the signature of a lost SYN: Linux retransmits at 1 s, then 3 s, then 7 s, so a handshake whose first SYN was dropped — by a full accept queue, a conntrack table at capacity, or a firewall — completes at exactly 1 or 3 s (The Three-Way Handshake, TCP Debugging: Reading the Handshake on the Wire). Check nstat -az TcpExtListenOverflows TcpExtListenDrops and ss -ltn for Recv-Q at the backlog limit. Steps of ~200 ms or multiples are retransmission timeouts on established connections (RTO_MIN, Packet Loss: Duplicate ACKs, Fast Retransmit and the RTO); ~40 ms per small write is the Nagle + delayed-ACK interaction; exactly 5 s is the glibc DNS resolver timeout — the first nameserver in resolv.conf is dead or drops UDP, or an AAAA lookup goes unanswered; 1–3 RTTs of extra latency on *every* request means no keep-alive, so each request re-runs the TCP and TLS handshakes (Keep-Alive and Connection Reuse).

Queueing without CPU is the other big family. A thread pool of 32 workers all blocked on a downstream call with a 3 s timeout serves 20 ms handlers with a 3 s wait — the thread-pool queue length, not CPU, is the saturated resource (The Thread Pool Server). An event loop stalled on a synchronous call queues everything behind it. A slow client or a small socket buffer makes write() fast (it copies into the kernel) but the *transfer* slow, so server-side timing ends before the client has received anything; the LB then reports a long response time the app never saw (What Happens When the Receiver Is Slow). And on the client side, browsers queue requests beyond six per host — DevTools shows that as "Stalled" — and a proxy in between may buffer.

Find it by measuring each hop, not the handler. From a client: curl -w "%{time_namelookup} %{time_connect} %{time_appconnect} %{time_starttransfer} %{time_total}" splits DNS, TCP, TLS and time-to-first-byte. At the balancer: ALB request_processing_time/target_processing_time/response_processing_time, or nginx $request_time versus $upstream_connect_time, $upstream_header_time, $upstream_response_time — the gap between request_time and upstream_response_time is client or network. On the server: ss -ti for retrans, rto and cwnd per connection, thread-pool and event-loop lag metrics, and a distributed-tracing span opened at the *ingress* rather than in the handler. Compare p50 to p99: a flat p50 with a spiky p99 at round values is a timer; a smeared p99 is a queue.

Green flags · Red flags

Strong green flag · Suggests accept-queue overflow from a slow accept() as a hypothesis for a clean 1–3 s p99 and knows how to prove it with nstat and ss -ltn.
Green flags
  • Draws the full timeline from DNS to last byte and locates the handler’s 20 ms within it
  • Recognises 1 s / 3 s as SYN retransmits and 200 ms as RTO and names the kernel counters
  • Considers queueing on a pool or event loop as latency without CPU
  • Proposes per-hop measurement: curl -w, LB timing fields, ss -ti
  • Reads p50 vs p99 shape as a diagnostic
Red flags
  • Adds more logging inside the handler
  • Assumes CPU idle means the server is not the bottleneck
  • Cannot name any stage between the client and the handler
  • Treats "check for packet loss" as the whole plan with no tool

Follow-up questions

F1
The p99 is exactly 1.02 s and p99.9 exactly 3.02 s. What is the 20 ms?
F2
p99 is high only for the first request each client makes in a minute. Why?
F3
Timing at the LB shows target_processing_time is 20 ms but response_processing_time is 2.9 s. Where is the time?

Scenario

A Node.js service reports 20 ms handler latency, 5% CPU and a p99 of 3.0 s that began after a change that made accept() happen only between batches of work. Explain the mechanism end-to-end, the exact counters that confirm it, and why raising somaxconn is not the fix.

Learn this topic