Files
windy-git/docs/incidents/2026-08-12-login-latency-analysis.md
Grant Whitmer e3677dddd9
All checks were successful
check / gate (push) Successful in 18s
canary / probe (push) Successful in 24s
docs: measure WHY login takes 18s — it is not 468 call sites
The SOTU scopes the child-process DB bridge as 468 call sites and multi-week.
Measurement says otherwise.

  bare node -e '0'  on Kit 0 (4 vCPU, load 20): 1.70-1.99s
  bare node -e '0'  on Veron 1 (24 cores, idle): 0.01s

170x, and node startup is essentially the whole per-query cost — adding pg
connect and a real query to a bare node boot adds only ~0.2-1.2s on top of
~1.8s of interpreter start.

Login makes 9 such forks. 9 x 1.8s = 16s. Observed: 17-25s.

Two independent multipliers compound: the adapter forks per query (9x) and the
box is saturated so each fork costs 1.8s instead of 0.01s (170x).

The consequence: you do not need to touch 468 call sites. querySyncViaChild is
ONE function and its interface does not change — replace the per-query
execFileSync with a persistent worker holding a pg.Pool. All 468 call sites get
faster without being edited, including the mail-lookup that caused today's
outage.

Also measured: 54 containers, 301% CPU of 400%, load 20. dev/demo is 55% of
that — real relief, honestly not a fix. 42 non-dev containers on 4 cores is the
actual condition.

Not implemented here on purpose: sync-over-async with Atomics in the most
critical file in the ecosystem, at the end of a long session, on a box that
already had an outage today, deserves a fresh session and a load test.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-08-12 19:05:25 -04:00

4.4 KiB
Raw Blame History

Why login takes 18 seconds — measured, 2026-08-12

The SOTU calls the child-process DB bridge "the single largest stability liability under #8" and scopes the fix as 468 call sites, multi-week.

That scoping is wrong, and the measurements below say so. You do not need to touch 468 call sites. You need to stop spawning a node process per query, which is one function.

The measurements

One login makes 9 synchronous queries, each spawning node -e via execFileSync (postgres-adapter.ts:114):

# query source
1 findUserByEmail statements.ts:11
2 mfa_secrets lookup auth.ts inline
3 findDevice statements.ts:24
4 touchDevice or countDevices + addDevice statements.ts:25-35
5 updateUserSeen statements.ts:20
6 generateTokens → scope rows auth.ts:220
7 generateTokens → product rows auth.ts:229
8 getDeviceList auth.ts:384
9 logAuditEvent INSERT identity-service.ts:43

What each fork actually costs, measured inside the running container:

Kit 0 (4 vCPU, load ~20) Veron 1 (24 cores, idle)
bare node -e "0" 1.70 – 1.99 s 0.01 s
node + pg connect + SELECT 1 1.89 – 3.19 s —

Node startup is 170× slower on Kit 0, and it is essentially the entire cost. Adding a Postgres connect and a real query to a bare node start adds only ~0.2–1.2 s on top of ~1.8 s of interpreter boot.

9 forks x ~1.8 s = ~16 s.   Observed login: 17–25 s.

The conclusion that matters

There are two independent multipliers, and they compound:

  1. The adapter forks a process per query — 9x on the login path.
  2. The box is saturated, so each fork costs 1.8 s instead of 0.01 s — 170x.

Either one alone is survivable. Together they turn a sub-second operation into eighteen seconds, and on 2026-08-12 they turned a retry loop into an ecosystem-wide auth outage.

Connection pooling barely helps. The connection is not the cost; the interpreter boot is. PgBouncer, pg.Pool on the sync path, or a warmer Postgres would all leave ~1.8 s per query untouched.

Box census (measured same day)

54 containers, 301% CPU of 400% available, load average 20 on 4 vCPU
containers CPU
dev / demo / test 12 55%
everything else 42 246%

Top consumers: windymail-migrate-stalwart 31%, scenemachine-db-prod 30%, account-server-account-postgres 27%, windy-synapse 25%, windy-directory 20%.

Be honest about this number: stopping every dev/demo container reclaims 55% of 301% — it takes the box from 75% to 61% steady CPU. That is real relief and it is not a fix. Forty-two non-dev containers on four cores is the actual condition.

What to do, in value order

  1. Stop forking a node process per query. querySyncViaChild (postgres-adapter.ts:114) is one function, and its interface — querySync(sql, params) — does not change. Replace the per-query execFileSync with a persistent worker holding a pg.Pool, using worker_threads + SharedArrayBuffer + Atomics.wait for the synchronous block. Every one of the 468 call sites gets faster without being edited, including the mail-lookup route that caused today's outage. Expected: login 18 s → well under 1 s, on this box, unchanged.
  2. Then migrate route families to the async path at leisure. The sync path is still labelled legacy and should still die — but as cleanup, not as an emergency.
  3. Separately, unload Kit 0. Move dev/demo off the box that runs identity, the CA, mail, Matrix and the broker. This is worth doing on its own merits regardless of the adapter.

Do not do #2 first. Migrating handlers one family at a time is weeks of edits to the most critical code in the ecosystem, and it leaves every un-migrated call site paying 1.8 s a query the whole time.

Why this was not implemented in this session

Replacing the sync bridge is a subtle change (Atomics.wait, structured-clone limits, worker lifecycle, failure fallback) in the single most critical file in the ecosystem, made at the end of a long session, on a box that had already had one outage that day. It deserves a fresh session, a real load test, and a rehearsed rollback — not a tired commit.

The measurement is the deliverable. It converts a "multi-week, 468 call sites" job into a one-function change, and that is worth more than a rushed attempt.