e3677dddd9
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>
104 lines
4.4 KiB
Markdown
104 lines
4.4 KiB
Markdown
# 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.
|