Skip to content

fix(server): unblock startup readiness and cut SQLite write amplification - #54

Merged
tusharbhardwaj-bk merged 3 commits into
expbkmainfrom
fix/bkt3-startup-backfill-and-sqlite-write-amplification
Aug 6, 2026
Merged

fix(server): unblock startup readiness and cut SQLite write amplification#54
tusharbhardwaj-bk merged 3 commits into
expbkmainfrom
fix/bkt3-startup-backfill-and-sqlite-write-amplification

Conversation

@tusharbhardwaj-bk

@tusharbhardwaj-bk tusharbhardwaj-bk commented Aug 6, 2026

Copy link
Copy Markdown

bkt3.dev disconnected every user for over two minutes on every restart, and the box was writing ~150 GB/day for ~80 MB/day of real data. Three independent causes, fixed here.

Phase A — the startup ownership backfill (fork-only)

Evidence. Journal from the live host: Listening on http://…:18083 at 15:11:14, then ownership backfill complete + T3 Code server is ready. at 15:13:40 — 146 s, on every boot. The trace file held a single sql.execute span of 97.9 s annotated startup.phase: "ownership.backfill", running the UPDATE projection_threads … SET owner_user_id = (…) pass.

It had nothing to do. All 334 rows in projection_threads and all 8 in projection_projects already had owner_user_id set — zero ownerless rows. It never got cheaper because the hot clause was WHERE (owner_user_id IS NULL OR owner_user_id = :admin), and 266 of the 334 threads are admin-owned, so they were re-processed forever. Each row then drove correlated subqueries filtering orchestration_events on event_type with json_extract on the payload — and there is no index on event_type. Every existing index leads with aggregate_kind, so those subqueries scanned a 258,840-row / 874 MB table repeatedly.

Changes.

  1. Cheap guard. planOwnershipBackfill checks for any ownerless row and whether the one-time repair is recorded. In steady state it logs at debug and returns.
  2. The admin repair runs at most once. OR owner_user_id = :admin exists to undo a historical bulk assignment to the admin — inherently a one-time migration concern, not a per-boot one. It is now gated on a durable marker.
  3. Index on orchestration_events(event_type, stream_id), migration 1007 in the fork's 1000+ lane (current max was 1006).
  4. Off the blocking path. The pass moves from runStartupPhase(...) to forkParked(runStartupPhase(...)), the pattern already used for welcome.autobootstrap in the same file, so readiness can never wait on it again.

Fail-soft semantics are unchanged: it still never crashes startup, and a failure leaves the marker absent so the next boot retries.

Marker mechanism. A two-column maintenance_markers (marker TEXT PRIMARY KEY, completed_at TEXT NOT NULL) table, created in the same migration. The alternatives were worse: projection_state is keyed by projector and means "last applied sequence", so overloading it would lie to the projection pipeline; a column on environment_users would tie a database-wide fact to a user row; and the migrations table cannot express "ran, but only after an admin could be resolved". A dedicated table is three lines and the next one-time repair can reuse it.

Measured against a VACUUM INTO snapshot of the live 1.86 GB database:

before after
EXPLAIN QUERY PLAN, both subqueries SCAN transferred / SCAN created EXISTS SEARCH … USING COVERING INDEX idx_orchestration_events_event_type_stream (event_type=? AND stream_id=?)
repair pass over 266 admin-owned rows 55,780 ms 3 ms
steady-state guard n/a (146 s full pass) <1 ms

The index build itself costs 6.4 s cold on that database — a one-time migration cost on the next deploy. The first boot after this lands still runs the admin repair once (now indexed, and off the readiness path); every boot after that takes the guard.

Phase B — SQLite pragmas (upstream-owned file)

apps/server/src/persistence/Layers/Sqlite.ts set only journal_mode = WAL and foreign_keys = ON, leaving synchronous=FULL (an fsync per COMMIT) and wal_autocheckpoint=1000 — a ~4 MB checkpoint that re-copies WAL frames into the 1.86 GB main database, doubling every byte written. Added: synchronous = NORMAL, wal_autocheckpoint = 10000, cache_size = -65536, journal_size_limit = 67108864.

Safety of synchronous = NORMAL: it cannot corrupt a WAL-mode database — recovery replays the WAL on open. The only exposure is losing the last few committed transactions to a power loss or kernel panic. A clean process restart, or even a process crash, loses nothing.

These are hardcoded with comments rather than made configurable: the setup layer is shared with SqlitePersistenceMemory and has no ServerConfig in scope, and there is no existing env pattern for storage-engine knobs.

Phase C — trace volume, without blinding the dashboard

The tracer emitted a span for every SQL statement, each carrying the full db.query.text. One observed window held 61,175 sql.execute spans, roughly 70–80% of all trace bytes, rotating a 10 MB file about every 40 seconds.

The stopgap on the host (T3CODE_TRACE_MIN_LEVEL=Warn) silences the trace file completely — and diagnostics/TraceDiagnostics.ts reads that same NDJSON to power the in-app dashboard, so Top Span Names / Slowest Spans / Most Common Failures went dark.

Instead, makeTraceSink now takes an optional retain predicate applied before buffering, and the server passes retainSlowSqlSpans(config.traceSqlSlowMs). Fast successful sql.execute spans are dropped; anything at or above the threshold is kept, as are failed and interrupted spans, which is what the dashboard's failure panels count. Tracing stays at Info and every non-SQL span is untouched.

Configurable via T3CODE_TRACE_SQL_SLOW_MS, default 250; 0 disables the filter and records every statement. Losing slow-query visibility was not acceptable — a 97.9 s span is exactly how Phase A was found — so the threshold retains it.

Deploy follow-up: once this ships, remove the host drop-in /etc/systemd/system/t3-bkmain.service.d/60-trace.conf so the trace level returns to Info.

Expected effect

  • Startup readiness: ~146 s → near-instant, on every boot.
  • Physical writes: large reduction from removing the per-commit fsync, the 4 MB checkpoint amplification, and the bulk of trace bytes.

Upstream split

Phase A files are fork-only. Phase B (persistence/Layers/Sqlite.ts) and Phase C (packages/shared/src/observability.ts plus the server config plumbing) are upstream-owned, and their diffs are kept minimal and self-contained so each can go up as a separate upstream PR later. They are in separate commits here for that reason.

Verification

Scoped local runs only (shared dev host; CI owns the full suite):

  • vp test run apps/server/src/orchestration/ownershipBackfill.test.ts packages/shared/src/observability.test.ts apps/server/src/cli/config.test.ts apps/server/src/environment/ServerEnvironment.test.ts — 34 passed
  • vp test run apps/server/src/bin.test.ts — 17 passed
  • vp run --filter t3 typecheck and --filter @t3tools/shared typecheck — clean
  • vp lint on the changed files — clean
  • EXPLAIN QUERY PLAN and timings above, against a read-only VACUUM INTO snapshot of the live database

New test coverage: the four planOwnershipBackfill skip/repair states and the repairAdminAssignments: false path; retainSlowSqlSpans behaviour and the sink honouring retain.

Written by Claude Opus 5 in Claude Code.


View with [code]smith Autofix with [code]smith
Need help on this PR? Tag @codesmith-bot with what you need. Autofix is disabled.

tusharbhardwaj-bk and others added 3 commits August 6, 2026 15:46
On bkt3.dev the startup ownership backfill took 146 s on every restart,
so each deploy disconnected everyone for over two minutes. All 334
threads and 8 projects already had an owner: the pass re-selected the 266
admin-owned rows forever because its WHERE clause treats "owned by the
admin" as work to redo, and each row drove correlated subqueries over a
258k-row event log with no index on event_type.

Three changes: a cheap guard that returns immediately when no row is
ownerless and the one-time admin repair is recorded; a durable marker so
that repair runs at most once instead of on every boot; and an index on
orchestration_events(event_type, stream_id). The pass also moves to
forkParked, alongside welcome.autobootstrap, so it can never hold
readiness again. Fail-soft semantics are unchanged.

Measured on a VACUUM INTO snapshot of the live database: the repair pass
goes from 55.8 s to 3 ms, and the new steady-state guard from 146 s to
under a millisecond.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The server writes roughly 150 GB/day physically for about 80 MB/day of
logical data. Two SQLite defaults cause most of it: synchronous=FULL
fsyncs on every COMMIT, and wal_autocheckpoint=1000 copies the WAL back
into a 1.86 GB main database every ~4 MB, so every byte is written at
least twice.

synchronous=NORMAL cannot corrupt a WAL database — recovery replays the
WAL on open. The only exposure is losing the last few committed
transactions to a power cut or kernel panic; a clean process restart or
crash loses nothing.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The tracer emits one span per SQL statement, each carrying the full
query text. One observed window held 61,175 sql.execute spans, roughly
70-80% of all trace bytes, rotating a 10 MB file every 40 seconds.

Raising T3CODE_TRACE_MIN_LEVEL to Warn silences the file completely and
takes the in-app diagnostics dashboard down with it, since it reads the
same NDJSON. Instead the sink now takes a retain predicate, and the
server drops sql.execute spans that finished faster than
T3CODE_TRACE_SQL_SLOW_MS (default 250 ms). Slow statements and failures
are kept — a 97.9 s span is exactly how the ownership backfill was
found.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@tusharbhardwaj-bk
tusharbhardwaj-bk force-pushed the fix/bkt3-startup-backfill-and-sqlite-write-amplification branch from 1af9a58 to 66e2f03 Compare August 6, 2026 16:47
@tusharbhardwaj-bk
tusharbhardwaj-bk changed the base branch from bkmain to expbkmain August 6, 2026 17:56
@tusharbhardwaj-bk
tusharbhardwaj-bk merged commit 22c6668 into expbkmain Aug 6, 2026
8 of 13 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant