The code ran in three milliseconds and the request took two hundred
Published by RodHat
The ticket arrived from one of the app teams: the internal RPC service was “slow.” P99 latency was sitting at 210ms. The SLA was 50ms. Violations had been accumulating for six weeks, and now it was an incident.
I pulled the service’s own timing metrics. The request handler logged elapsed time from receipt to send. Three milliseconds average. Five milliseconds p99. The code was not slow.
Database pool query time: two milliseconds average. Serialization and deserialization: under a millisecond. I added every internal timing counter available and they still summed to under 10ms per request. The service was doing its job in under 10ms. Something else was eating 200ms.
Ruling out the network
First suspicion: something between the client and the server. Maybe a load balancer inserting latency, maybe a misconfigured kernel buffer, maybe the client was in a different availability zone with actual WAN latency in the path.
Checked the topology: client and server on the same host. Not the same rack, the same host. UNIX domain socket would have been faster, but this was TCP/IP to localhost. Loopback. You do not get 200ms of network latency on 127.0.0.1.
$ ping -c 10 127.0.0.1
PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.033 ms
...
--- 127.0.0.1 ping statistics ---
10 packets transmitted, 10 received, 0% packet loss
round-trip min/avg/max = 0.023/0.031/0.047 ms0.031ms RTT. The problem was not the wire.
Timing the wire
When internal timers say fast and external timers say slow, the only way to know what actually happened is to look at the packets. Even on loopback.
$ tcpdump -i lo -w /tmp/rpc-capture.pcap port 9200 &
# run client workload for 60 seconds
$ kill %1tcpdump with a ring buffer so it does not eat memory on a busy service. Opened the capture in Wireshark. Filtered for a single request/response pair. The sequence:
0.000000 CLIENT -> SERVER [PSH, ACK] len=48 (request payload)
0.000031 CLIENT -> SERVER [PSH, ACK] len=48 (second packet of same request)
0.200148 SERVER -> CLIENT [ACK] len=0 (pure ACK, no data)
0.200199 SERVER -> CLIENT [PSH, ACK] len=512 (response payload)The server received the request at time zero. The server sent its ACK at 0.200 seconds. Two hundred milliseconds later. Not the response, just the ACK confirming receipt. The response followed immediately after the ACK.
The server was sitting on its acknowledgment for 200ms.
Delayed ACK
TCP does not require every received segment to be immediately acknowledged. RFC 1122 permits the receiver to delay an ACK by up to 500ms, though implementations cap it at 200ms and trigger on the second unacknowledged segment. The idea: the ACK can be piggybacked on the next outbound data segment, saving a round trip on interactive protocols where the server was going to respond anyway.
On Linux the delayed ACK timer defaults to 40ms. The kernel waits for either a second incoming segment, an outgoing data segment to piggyback on, or the timer to expire. When the timer fires first: a 40ms ACK delay.
So why was this showing 200ms instead of 40ms?
Nagle’s algorithm
John Nagle specified it in 1984, RFC 896. The algorithm: if there is unacknowledged data in flight, buffer new small sends until either the send buffer grows to a full segment (MSS) or the outstanding data gets acknowledged.
Excellent for reducing small-packet congestion on wide-area networks. A disaster for request/response protocols where the sender writes small messages in sequence.
Here is the interaction that produces 200ms:
The server processed the request and called send() twice. Once for the response header (small: a length-prefixed frame), once for the response body. The server sent the header. Nagle on the server held the body: unacknowledged data in flight, body is small, wait for an ACK. The client received the header but its delayed ACK timer started: wait for a second incoming segment or 200ms, whichever comes first. The server was waiting for an ACK to release the body. The client was waiting for more data to arrive before sending the ACK. Neither moved without the other.
The client’s delayed ACK timer fired at 200ms. That ACK unstuck Nagle on the server. The server sent the body. Total elapsed: 200ms.
This is not a bug. Both algorithms are doing exactly what they are specified to do. They just do not compose.
This specific failure mode has been documented since at least 1990. It shows up in every environment that combines Nagle-enabled server sockets with multi-write response framing. It shows up reliably, with a 200ms floor, every time.
Finding it in the socket
$ ss -tin dst 127.0.0.1:9200 | head -20ss shows TCP internals including the current socket options. cubic wscale:7,7 rto:200 rtt:0.055/0.027 ato:40 mss:65483 pmtu:65535 rcvmss:536 advmss:65483 cwnd:10 bytes_sent:...
ato:40 is the delayed ACK timeout in milliseconds. This confirmed the server’s ACK timer was active. There was no nodelay in the flags, which confirmed Nagle was enabled. Both conditions required for the deadlock.
The fix
int flag = 1;
setsockopt(client_fd, IPPROTO_TCP, TCP_NODELAY, &flag, sizeof(flag));TCP_NODELAY disables Nagle’s algorithm on the socket. Small writes go out immediately, no buffering. The server sends both parts of the response back to back without waiting for an ACK. The client receives both segments, and its delayed ACK fires immediately on receipt of the second segment rather than sitting on the timer.
This went in on the server side, applied to every accepted connection. Two lines. P99 latency dropped from 210ms to 6ms within the minute.
You can also set it on the client side. It does not matter which end kills Nagle, since the deadlock only needs one participant to opt out. Setting it on the server is cleaner because you own that code and the fix is in one place regardless of which client connects.
Eighteen months
The service was not originally built for this traffic pattern. When it was new, requests were larger and the server was responding in a single send() call. Single send, no Nagle stall, latency was fine. The protocol evolved toward smaller, more frequent messages. The server-side framing split into header-then-body. Nobody noticed when the latency floor appeared because p99 went from 8ms to 210ms and the SLA was 200ms: over the SLA immediately, but only just, and only at p99.
Six weeks of SLA violations before it became an incident. The team that owned the client had noticed the latency was high but assumed it was the server being legitimately busy.
The pattern where a number looks acceptable in isolation while the real constraint is invisible until you check against spec tends to survive because nobody runs the comparison until something breaks a threshold.
The relevant documentation is in tcp(7). TCP_NODELAY has been there since the socket API existed. Every HTTP client library and every database driver sets it by default, which is why you do not usually hit this on HTTP services. You hit it on custom binary protocols where the developer never read tcp(7).
Set TCP_NODELAY on every socket that implements a request/response protocol. The only reason not to is bulk data transfer, where Nagle’s batching genuinely helps, and that case looks nothing like what you are probably building. If you do not know why you are not setting it, set it.