All My Meters Said Innocent
Just after lunch on a Monday, an alert fired: FIX session disconnected. That was new. The session dropped at 09:30 NY time — the US market open, when the accumulated pre-market orders execute and a significant share of the day’s volume goes through in minutes. For a drop-copy session, a disconnection at the open is the expensive kind: trading carries on without you, and every trade that clears while you’re not listening has to be found and confirmed by hand the next day. At the open, that’s hundreds of trades per second. A few weeks earlier, we’d routed more traffic through this session.
The service itself was unremarkable. Python 3.11, QuickFIX — C++ under the hood — handling the sessions, Postgres storing the trades. One pod, one CPU, nothing fancy. And the dashboard said everything was fine.
It ran as a single Python process. One connection per venue, each feeding FIX messages in on its own ingest thread, which buffered them and wrote them to Postgres. A batch processor read those messages back out and turned them into trades. That was the whole system: ingest threads accumulating messages, a processor draining them into trades, a database in between. It had run this way for a long time, quietly, without anyone needing to think about it.
The database is the reflex suspect, so I went there. I pulled the save-time histogram: 0–500ms, three-quarters under 100ms. It looked healthy — not pristine, but healthy. I poked the indexes, found nothing damning, ran a couple of faster-insert tricks (UNNEST won the local benchmark and changed nothing real), and moved on. The histogram already contained the answer. Batches arrived every ~330 ms and three-quarters of saves cleared in under 100 ms — the occasional 500 ms tail was debt the next couple of saves repaid. I didn’t do that arithmetic at the time — I just saw a green-ish chart and crossed the database off. That’s the habit worth naming, because I’m about to lean on it again: trust the dashboard, move on to the next suspect. Here it cost nothing — the database really was innocent. It didn’t stay free.
The database's alibi.
The next cost that grows with message volume is parsing. Each message needs to be parsed — but parsing is core to QuickFIX, it runs in the C++ extension, and it’s been polished by dozens of systems carrying far heavier loads than ours. The microbenchmarks said the same: parse 4.2µs, toString 3µs, prod-formatted log 21.6µs, call it 32µs per message with headroom. A heavy market open runs under 100,000 messages, so even at that ceiling the entire per-message compute budget for an open is around 3.2 seconds of CPU. The messages were being rejected as older than 120 seconds — QuickFIX’s default cutoff — so the backlog was at least two minutes deep. Compute fell short of the symptom by a factor of nearly forty — per-message work was not the constraint.
The save tails told a different story. At market open they sat just above multiples of 100ms — 103.99, 211.37, 306.12, 325.97, 334.94ms against a 30–80ms median — the textbook CFS-throttling signature, 100ms being the scheduler period. CPU demand at open was running at about 2× the one-core allocation. So I raised the limit from one core to two and a half, on the same day.
CPU demand at market open, against a 1-core limit.
Reconstructed from production monitoring.
The next day was clean. For two more days it looked solved. The following Monday, the FIX session disconnected at market open. The bump had bought three days, not a fix. And the tell was in the gap: the saturation alarm had gone quiet — CPU utilisation looked fine now — but the lag came back anyway. There was headroom, and it didn’t help. Whatever the ceiling was, it wasn’t compute.
The next suspect was logging. Every incoming FIX message was being logged: of the ~100k log lines in a ten-minute open, about 70k were FIX messages.<br>My prior was that logging couldn’t be it — the same battle-tested pipe every system here has used for years. You don’t expect to be the one who breaks it. A local reproduction changed that: under a deliberately slow sink, lag grew with volume. Sync writes to a full pipe block, and an open is precisely when volume spikes. At one point that pushed my confidence to near 90% — high enough to warrant a definitive test, not a hunch.
So I stripped it back: FIX logging off, most other levels downgraded. Logged volume fell ~20x, to ~5k total in the same window. The next open lagged just the same. Twenty times less logging, identical result — not logging.
Eventually I stopped looking for causes and built the metric that actually mattered: the time between a message leaving the venue (tag 52, its sending timestamp) and the moment QuickFIX hands the message to our application code — the fromApp callback. I called it lag_ms, and it isn’t an arbitrary metric — it’s the exact quantity QuickFIX checks when deciding a session has gone stale.
The meter ran at the next market...