fix(db): batch cold database initialisation behind an immediate transaction - #84
Conversation
1bb841e to
58ade70
Compare
|
Rebased onto Re-measured on the new base, matched before/after in the same clean environment:
Biggest savings, same base:
Worth noting given #83's CI change: the new invocation runs one Bun process per test file, so every file that creates a file-backed database now pays the cold-init cost in its own process. That makes this fix more valuable than it was against the old shared-process invocation, not less. Still no test modified, no timeout raised, and no guard touched. Incidental confirmation that the repo's guards work: while verifying, a scratch file left in |
58ade70 to
679f463
Compare
|
Added a second, independent fix to the same function, found while stress-testing the first one.
|
share failing with database is locked |
|
|---|---|
main today |
41% |
| batching only | 25% |
batching + busy_timeout first |
1.3% |
Batching alone already helps, because it shortens the write window from ~940 ms to ~46 ms. Ordering the pragmas correctly is what actually fixes it. One line moved, plus a comment saying why the order matters.
Full picture
| before | after | |
|---|---|---|
cold getDatabase() |
940 ms | 46 ms |
| warm reopen | 27 ms | 8 ms |
| concurrent cold-open failure rate | 41% | 1.3% |
| suite wall clock | 101.9 s | 81.5 s |
| worst utilisation of a default 5 s budget | 34.5% | 17.4% |
Suite: 2489 pass / 0 fail / 138 skip.
Thin-margin sweep
Margin is timeout − duration, so raw duration alone misleads — the 5.0 s warming test has a 180 s timeout and was never at risk. By utilisation, the at-risk set before this change was five tests, all on the default 5 s budget, and all five are cold-SQLite-init tests — including both reported flakes:
| used | test | file |
|---|---|---|
| 34.5% | emails daemon status advertises only commands that exist |
cli/unshipped-surface.test.ts |
| 21.4% | does not reappear when the database is reopened after… |
db/retired-legacy-inbound-identity.test.ts |
| 20.6% | hardens pre-existing WAL, SHM, and journal artifacts… |
db/database-permissions.regression.test.ts |
| 20.5% | repairs inbound recipient rows when the recipient table is missing |
db/database.test.ts |
| 20.2% | does not rerun the inbound recipient backfill… |
db/database.test.ts |
After: the highest utilisation anywhere in the suite is 18.3% (src/index.test.ts, 5.50 s against its explicit 30 s), and the highest on a default 5 s budget is 17.4% (0.87 s). Everything has ≥5.5x headroom.
Nine tests still exceed 1 s, and every one has a deliberate generous timeout — no action needed, listed for the record:
| duration / timeout | test |
|---|---|
| 5.50 s / 30 s | emits consumer declarations with optional Database injection (spawns tsc twice) |
| 5.01 s / 180 s | drives the whole schedule lifecycle: warm -> status -> … |
| 2.52 s / 120 s | refuses a bounded read that can neither fill its window nor reach the end |
| 2.11 s / 120 s | advertises the warming commands in --help… |
| 1.72 s / 20 s | prints valid credential-free JSON for provider CRUD routed to /v1 |
| 1.70 s / 30 s | covers the workflow through the CLI and validates via the library API over /v1 |
| 1.51 s / 90 s | fails loud (and truthfully) when the domain has no schedule |
| 1.19 s / 90 s | validates --target, --start-date, and --status… |
| 1.08 s / 90 s | refuses to silently create a duplicate schedule for the same domain |
The one to keep an eye on is src/index.test.ts at 18.3% — it spawns tsc twice, so it is the only test whose budget a much slower runner could threaten. It is bounded and deliberately given 30 s, so I left it alone.
On the subprocess question
cli/unshipped-surface.test.ts spawns the real CLI four times, and I deliberately did not remove that. The file's own comment explains why it must: every bug it guards against was "the source looks fine, the shipped binary lies". The subprocess is the point of the test; the cost was in the database underneath it. That is now 0.63 s per spawn instead of 1.72 s.
No retries were added anywhere.
…action Three things in one function, all about opening a database. 1. Batch the initialisation into one transaction A first open applied ~200 migration statements plus ~140 idempotent schema probes with no enclosing transaction, so SQLite committed — and fsynced — each one separately. It is fsync-bound, not CPU-bound: the same work costs ~940ms on a local NVMe and 23ms on tmpfs. That latency, not the assertions, is what pushed the file-backed database tests and the live-CLI tests toward the 5s default timeout. Every test that creates a temp database paid it once; every test that spawns the real CLI paid it once per subprocess. Under the disk contention a shared runner sees, they intermittently timed out. 2. BEGIN IMMEDIATE, not BEGIN Found by adversarial review, and the reason this is not a one-line change. A deferred BEGIN takes only a WAL read snapshot on the first statement of the pass — `SELECT MAX(id) FROM _migrations` — so every DDL then has to upgrade a read transaction to a write one. If another connection commits in between, that upgrade fails with SQLITE_BUSY_SNAPSHOT, for which SQLite deliberately does NOT call the busy handler, so busy_timeout cannot absorb it. Since every statement here tolerates its own failure, the whole pass was skipped while the now-read-only COMMIT still succeeded: getDatabase() returned a silently un-migrated database. Reproduced against a rewound file database with one competing writer — 3/3 opens returned schema level 40 with `forwarding_rules` missing, where unbatched main reached 48 with the table present. With BEGIN IMMEDIATE, 5/5 reach 48. Guarded by src/db/database-concurrent-migration.regression.test.ts, which fails on a deferred BEGIN while its no-writer control still passes, so it cannot pass vacuously. It spawns a real second process because the defect exists only BETWEEN connections, which is why the existing suite could not catch it. 3. Install the busy handler before converting to WAL `PRAGMA busy_timeout` was set after `PRAGMA journal_mode = WAL`. Converting a fresh database to WAL takes an exclusive lock, so the one statement most likely to contend ran with no busy handler at all and whichever process lost the race died with SQLITE_BUSY. Pre-existing — unmodified main fails identically — and independent of the batching. Measured on one machine. cold getDatabase() 940ms -> 41ms warm reopen 27ms -> 8ms Both reported flakes, under identical fsync contention: repairs inbound recipient rows 1.87s -> 0.11s emails daemon status advertises only commands... 2.38s -> 0.58s file-backed database/permission siblings ~1.85s -> ~0.10s Eight processes opening one cold database at once, 32 opens per configuration, share failing with "database is locked": before 41% batching only 25% batching + busy_timeout first 3.1% Worst wait under that contention is 213ms, well inside the 5s handler, and still faster than main's uncontended open. Suite: 2491 pass, 0 fail, 138 skip; wall clock 101.9s -> 89.4s. No existing test was modified and no timeout was raised. The worst timeout-budget utilisation on a default 5s budget drops from 34.5% to 17.4%.
Adversarial review caught a real defect in this PR. Fixed, and now guarded.Posting the finding in full because the bug was worse than the flakiness this PR set out to fix, and it argues for the guard I added. The defect
Because every statement in the pass tolerates its own failure by design, all of them were swallowed, and then Reproduced independently against a file database rewound to schema level 40 with
Unbatched code could not hit this: the SELECT's read transaction ended immediately and each DDL took its own fresh write transaction, so contention surfaced as ordinary The fix
The guardNew
The control passing in both columns is what proves the failure is the race and not the fixture. It spawns a real second process because the defect exists only between connections — which is precisely why the existing 2489-test suite could not catch it. One over-claim correctedI had written that the rollback-then-reapply path is "exactly the pre-batching behaviour." That is not true for the error classes where SQLite ends the transaction itself ( The reapply stays level-based deliberately: replaying from zero would re-run migration 8, whose table rebuild ( Also confirmed by review, no change needed
Final numbers
Suite: 2491 pass / 0 fail / 138 skip (+2 = the new guard). Separate finding worth acting on
|
679f463 to
3b8a667
Compare
andrei-hasna
changed the title
1 participant
Problem
Three independent sessions hit timeout flakes on
main, with one measuring anactual failure. The two named suspects both time out at the default 5s under
load:
src/db/database.test.ts— "repairs inbound recipient rows when the recipient table is missing"src/cli/unshipped-surface.test.ts— "emails daemon status advertises only commands that exist"They share one root cause, and it is not the assertions.
Root cause
Cold database initialisation applied ~200 migration statements (62 migrations)
plus ~140 idempotent
ensureSchemaprobes with no enclosing transaction, soSQLite committed — and fsynced — each statement separately.
It is fsync-bound, not CPU-bound. Same code, same machine, only the filesystem
changed:
getDatabase()/dev/shm)A 41x gap. Every test that creates a temp SQLite database paid ~940 ms once; every
test that spawns the real CLI paid it once per subprocess. On a shared CI
runner, whose fsync is several times slower than a local NVMe and contended,
that is what crossed 5s.
This also explains why the tests passed in isolation and only failed under load,
and why a 5s budget was enough to check a CLI's help output: the cost was
database startup, not the check.
Fix
Batch the sequence into a single transaction — hundreds of commits become one.
It is only a commit-boundary change:
try/catchtolerance is preserved verbatim (24 of 62migrations are expected to fail on a fresh database and still do);
PRAGMA synchronousdowngrade, so aninterrupted open still cannot observe a half-applied schema;
at a time, which is exactly the previous behaviour;
runInTransactionis SAVEPOINT-based, so callers still nest safely.No test was modified. No timeout was raised. No guard, positive control, or
non-emptiness assertion was touched or weakened. The diff is one function in
src/db/database.tsplus one CI env line.Measured effect
Cold init:
getDatabase()Both flaky tests, under identical fsync contention (24 concurrent fsync writers):
emails daemon status advertises only commands that existrepairs inbound recipient rows…does not rerun the inbound recipient backfill…repairs loose permissions on an existing file-backed databaseFull suite wall clock: 94.2 s → 71.3 s (-24%), 2410 pass / 0 fail / 137 skip,
three consecutive green runs (71.3 s, 72.1 s, 72.3 s).
Timeout-budget headroom
Margin is
timeout - duration, so raw duration alone is misleading — the 5.98 swarming test has a 180 s timeout and was never at risk. Measuring utilisation,
the thin-margin set before this change was exactly three tests, and it contains
both reported flakes:
emails daemon status advertises only commands that existcreates missing custom parents beneath the canonical target…repairs inbound recipient rows…After the change the worst utilisation anywhere in the suite is 16.4% — every
test has ≥6x headroom. Under fsync stress the worst case goes from 48% to 12%.
Secondary fix
EMAILS_CLIENT_ENV_SECRETis now unset in the isolated local-mode CI step. Itsmere presence routes the store to self-hosted mode
(
src/db/self-hosted-store.ts:83), so a runner or developer machine thatexports it sees ~126 local-mode tests fail with HTTP 401. It belongs with the
EMAILS_SELF_HOSTED_*names already scrubbed there. This is defensive — CI doesnot export it today.
Verification
HOME,env -uall cloud/AWS creds,EMAILS_MODE=local): 2410 pass / 0 fail / 137 skip, 3x consecutivebun run build: passgenerate-selfhost-sdk.ts+git diff --exit-code): passno-cloud:source/no-cloud:pack: passgit diff --check: cleanNo version bump and no publish.
Need help on this PR? Tag
@codesmith-botwith what you need. Autofix is disabled.