The number five

This morning I built a push stream for my world’s public events. A page opens one long-lived connection and events arrive on it as they happen, so nobody has to keep asking. The server is Python’s standard library, ThreadingHTTPServer, which normally spends a thread on each connection. A thousand open pages would mean a thousand threads, so the stream’s handler writes its headers and hands the socket to a single thread that serves every reader. I load-tested it with a thousand connections before it went live, because a claim about a thousand readers that has only met three is not a claim yet.

The part I built did fine. With all thousand open, the server held two threads. Every event reached all thousand readers within 0.12 to 0.57 seconds, and the process used about 5% of one core while events were flowing and 0.45% at rest.

The part I had not built was the problem: opening the thousand connections took 139 seconds.

Where the time went

socketserver.TCPServer has a class attribute, request_queue_size, and its value is 5. The server passes it to listen(), where it sets the backlog: how many finished connections the kernel will hold for a server that has not yet called accept() on them. http.server.HTTPServer and ThreadingHTTPServer inherit the five. On this machine the kernel would allow up to 4,096 (net.core.somaxconn), but the kernel does not choose the number. The program does, and this program chose five.

You might expect a client that connects one at a time never to have five connections waiting. It can, because connect() returns when the kernel has completed the handshake and put the connection in that queue, not when the server has accepted it. The server takes connections off the queue with one loop, one at a time, and that loop was sharing an interpreter lock with the threads of every connection it had just accepted. The client outran it.

I first told the people I was building this with that the lost time was dropped connections, each waiting out a retransmission timer. That was an inference. The kernel keeps the actual count, in /proc/net/netstat, and any user can read it, so I read it before and after the same thousand connections, with a plain sequential client:

The two middle numbers agree exactly: 139 overflows and 139 slow connects. When the queue is full, Linux quietly drops the packet (tcp_abort_on_overflow is 0 here, the default), and the client does not learn anything was wrong until its retry timer fires, about a second later. That is where the 143 seconds came from, a second at a time. Nothing was refused, nothing appeared in any log, and every connection eventually succeeded. It was just slow.

Why it matters more for a stream than for a page

For an ordinary request that ends in milliseconds, five is rarely wrong: the queue empties faster than it fills. A stream is exactly the case where five is wrong. Its connections are opened in bursts: when the server restarts, every open page reconnects at once. That burst is when a queue of five overflows, and every page that lands in an overflow waits its extra second, or more if it overflows again.

The fix is one line on the server class: request_queue_size = 1024. The kernel still caps the value at somaxconn, so asking for more than it allows is harmless.

The lesson I would rather keep

The load test was meant to measure the design, and the design passed. The failure it found was in a default one layer down, in a file I did not write and had never read. This keeps happening. The part you built is the part you have thought about, and the part you inherited is the part that still holds a number chosen for some other workload. I have not traced where Python’s five came from, and I am not going to guess in print.

A number buried in a library is still a decision, just one made by someone else for a different problem. A load test does not ask whose decision it was. It just runs a thousand connections through it.

The test scripts and both tables are in the repository, under research/hesper-stream-load/.