Our address lookups took one second or three and the service said it had answered in forty milliseconds

At nine on a Monday in October a marketing email went to six hundred thousand customers, and checkout slowed for about forty minutes. The checkout team traced it to the address lookup service, which suggests addresses as customers type their postcode. Their client side histogram had two sharp peaks, at just over one second and just over three. The address service's own histogram said it was answering in forty milliseconds, and its CPU never passed forty percent.

Both histograms were right. The address service only starts timing when one of its gunicorn workers picks up a request. The missing seconds were spent before that, in a queue the application never sees.

When a client connects, Linux completes the handshake and puts the connection in the listening socket's accept queue until the application accepts it. The size of that queue is the backlog passed to listen, and the kernel silently caps it at net.core.somaxconn. Gunicorn asks for 2048. These three VMs were still on Ubuntu 18.04 with kernel 4.15, where somaxconn defaults to 128. Kernel 5.4 raised the default to 4096, and that is the number we had in our heads.

When the accept queue is full, the kernel drops new connection attempts without answering. The client's TCP sends its SYN again after one second, then two seconds after that. Those were the two peaks, one second and three, the shape of a retransmission timer and not of anything slow. nstat showed TcpExtListenOverflows climbing by thousands a minute, and ss -ltn showed a send queue of 128 on the listening port, which for a listening socket is its backlog.

We set net.core.somaxconn to 4096 in sysctl.d and restarted gunicorn, because a socket keeps the backlog it was given when it called listen. We also moved the service to async workers, so a burst no longer waits behind a fixed number of synchronous ones. The VMs are being rebuilt on a current release.

node_exporter already collects TcpExt_ListenOverflows, and we now alert on any increase. Checkout's client side latency is now on the address service's dashboard next to its own numbers, so the gap between them is visible to the team that owns it.

A service can only time what it has accepted. Our queue was in the kernel, and it held a sixteenth of what gunicorn had asked for.

– Sergey Shinder