Your load test measured the watchdog, not the server

On 2026-08-05 I measured what four concurrent calls cost my MCP egress server and wrote down 4 concurrent = 85s. I believed that number for most of an afternoon and started sketching a lock split to fix it. The number had nothing to do with the server. A 90-second process watchdog was killing the server partway through the run, and my harness reported the time until the kill as latency. That’s the general failure. A load harness that can’t see what happened to each request will charge its own timeouts, kills and wedged state to the system under test, and the number it prints looks exactly like a real one.

The watchdog, and the number that pointed at it

The server is a subcommand of my CLI binary: vodou-core mcp-server. At startup the binary arms a 90-second watchdog. The watchdog exists for one-shot CLI commands, so a hung vodou-core call can’t sit around forever. When it fires, it force-exits the process with code 124. A few long-running modes (the daemon, the worker, the updater) are on an exemption list. mcp-server wasn’t. Nothing in the server’s handler asked for a timer. It got one because it ran as a subcommand of a binary that sets one for every subcommand.

I found it by reading the server’s own log, which I should have done first. This line was sitting there:

[oi] process watchdog: force-exiting after 90s (exit 124)

I should have caught it from the number alone. 85s is just under a round-number timer, and that’s what you get when a 90-second clock starts when the process boots and your first request lands a few seconds later. When a latency figure sits just under 30, 60, 90 or 120 seconds, look for a timer before you look at the code. On your own system, ps -o pid,etime,command -p <pid> taken before and after a run answers the question in one line. If etime went back to a few seconds, or the PID changed, the process you were measuring is gone and something started a new one.

4 concurrent = 85s, then two runs that never returned

The second and third runs hung indefinitely. The first run had wedged the daemon, so that part was real. But the harness was this:

for i in 1 2 3 4; do curl -s "$URL" -d '{}' >/dev/null & done
time wait

wait returns when every child returns. One child that never returns looks the same as a server that never responds. Nothing prints which child it was, or whether the other three finished in a second. curl had no --max-time, so the harness had no timeout of its own and couldn’t tell “slow” from “dead”. It also started each run straight after the one before, with nothing to check whether the previous run had left the server wedged. It had.

I rewrote the driver in Python with a per-request timeout, one recorded outcome per request, and a health probe after each run. The real numbers came out right away: 1, 4 and 8 concurrent took 1.25s, 6.5s and 13.2s. A run the next day gave 5721ms for 4 concurrent, which is consistent. Each request holds the server’s McpServer Mutex for the whole call, and about 1.2s of each call is a search on the daemon’s socket, which is itself a single server. So the queue is real and roughly linear, but it isn’t clean. Perfect serialisation predicts 5s and 10s, and I measured about 30% more than that. I didn’t track down where the extra time goes. What mattered was that the curve was a line and not a cliff. It also showed the lock split I’d been sketching would only have moved the queue from the Mutex to the daemon’s socket. The 85s and both hangs were produced by the measuring setup, not the server.

Coordinated omission in reverse: the load test timed the watchdog

Coordinated omission is the case where the load generator backs off while the server stalls, so the stall never gets measured and the percentiles look better than they are. Mine was the opposite, and it made the numbers look worse. A timer in the server’s own process killed it. The generator then hit a half-dead daemon, and every second of that was charged to the server. The rule that follows is the same either way. A failed request’s duration tells you how long it took something to give up, which is a different quantity from how long the work takes. It must not go into the latency numbers, and the harness can only keep it out if it records which requests failed.

A load harness records one outcome (ok, timeout, error) and one duration per request, probes health before and after every level, and checks that the process it started with is the process it ended with. Any latency it reports without all four is a measurement of the harness.

The check, against your own server. It needs only Python’s standard library plus lsof and ps:

import subprocess, sys, time, concurrent.futures as cf, urllib.request, urllib.error

PORT = int(sys.argv[1]) if len(sys.argv) > 1 else 8080
URL, HEALTH = f"http://127.0.0.1:{PORT}/call", f"http://127.0.0.1:{PORT}/health"
TIMEOUT, SETTLE = 30, 2

def server_identity():
    # PID + start time of whatever is listening on the port. A supervisor
    # restart changes both, even when /health says 200 afterwards.
    pid = subprocess.run(["lsof", "-ti", f"tcp:{PORT}", "-sTCP:LISTEN"],
                         capture_output=True, text=True).stdout.split()
    if not pid:
        return None
    start = subprocess.run(["ps", "-o", "lstart=", "-p", pid[0]],
                           capture_output=True, text=True).stdout.strip()
    return pid[0], start

def health():
    try:
        return urllib.request.urlopen(HEALTH, timeout=5).status
    except Exception as e:
        return type(e).__name__

def is_timeout(e):
    return isinstance(e, TimeoutError) or isinstance(getattr(e, "reason", None), TimeoutError)

def one(i):
    t = time.monotonic()
    try:
        urllib.request.urlopen(URL, data=b"{}", timeout=TIMEOUT).read()
        return "ok", time.monotonic() - t
    except (urllib.error.URLError, TimeoutError, OSError) as e:
        return ("timeout" if is_timeout(e) else "error"), time.monotonic() - t

base = None
for n in (1, 4, 8):
    before, id_before = health(), server_identity()
    if before != 200:
        print(n, "SKIPPED health_before=", before)
        continue
    with cf.ThreadPoolExecutor(n) as ex:
        r = list(ex.map(one, range(n)))
    time.sleep(SETTLE)
    after, id_after = health(), server_identity()
    counts = {k: sum(1 for s, _ in r if s == k) for k in ("ok", "timeout", "error")}
    mx = max(d for _, d in r)
    ok = (counts["ok"] == n and after == 200 and id_after == id_before
          and mx <= n * (base or mx) * 1.5)
    if n == 1 and ok:
        base = mx
    print(n, counts, "max=%.2fs" % mx, "health_after=", after,
          "restarted=", id_after != id_before, "PASS" if ok else "FAIL")

Two details in there cost me a traceback to learn. The first is the exception handling. When the server accepts the connection and then goes silent, urlopen doesn’t raise URLError. The read times out, and a bare TimeoutError escapes. My first version caught only URLError, so against a hung server it died with TimeoutError: timed out and printed no result at all, in exactly the case it existed to catch. The second is the pre-level probe. If a level starts against a server the previous level wedged, it gets skipped, not measured.

The pass rule, per level: every request ok, health_after= 200, restarted= False, and max(n) ≤ n × max(1) × 1.5. The 1.5 is a rule of thumb, not a law. It leaves room for queueing overhead like my 30% and still fails a cliff. My real numbers pass it: 6.5s ≤ 7.5s and 13.2s ≤ 15s. The 85s would have failed it several times over, even before the restart column caught it.

Here’s the output against a toy server whose /health answers instantly and whose /call accepts the connection and then sleeps forever:

import time
from http.server import ThreadingHTTPServer, BaseHTTPRequestHandler
class H(BaseHTTPRequestHandler):
    def do_GET(self):   # /health answers instantly
        self.send_response(200); self.end_headers(); self.wfile.write(b"ok")
    def do_POST(self):  # /call accepts the connection, then never answers
        time.sleep(10**6)
    def log_message(self, *a): pass
ThreadingHTTPServer(("127.0.0.1", 8081), H).serve_forever()

1 {'ok': 0, 'timeout': 1, 'error': 0} max=30.00s health_after= 200 restarted= False FAIL
4 {'ok': 0, 'timeout': 4, 'error': 0} max=30.01s health_after= 200 restarted= False FAIL
8 {'ok': 0, 'timeout': 8, 'error': 0} max=30.01s health_after= 200 restarted= False FAIL

Then against the failure from the title, in miniature. The same server serialises /call on a lock at 1.5s each, calls signal.alarm(6) at startup as its watchdog, and runs under while true; do python3 killed.py; done as its supervisor:

1 {'ok': 1, 'timeout': 0, 'error': 0} max=1.51s health_after= 200 restarted= False PASS
4 {'ok': 0, 'timeout': 0, 'error': 4} max=0.88s health_after= 200 restarted= True FAIL
8 {'ok': 0, 'timeout': 0, 'error': 8} max=3.46s health_after= 200 restarted= True FAIL

Look at the last two lines. health_after= 200 on both, because the supervisor had already brought a fresh process up. A health probe alone would have called that a healthy server that fails some requests. restarted= True is the only column that says the process you were measuring died during the run. That’s a different bug from “the server is slow”, with a different fix. If your harness can’t produce that line, don’t build anything on its latency numbers.