screentinker/server/db/wal-checkpointer-worker.js
ScreenTinker 59489b3b20 #240: stop the morning wave buying itself a blocking checkpoint
Bold reported loop lag that grew with uptime and reset on restart. The
signature they saw — mean = p50 = p99 = max, identical to two decimals —
is not a fixed cost paid on every cycle. It is what an IntervalHistogram
window reports when it recorded exactly ONE delay: the mean is the raw
value, and every percentile returns the bucket ceiling above it.
Reproduced against their exact numbers (1329.07 / 1329.59). So the loop
took one long turn that swallowed the sampling second, episodically —
which is what they later confirmed independently.

The turn is ours, and it is now measured rather than theorised. Probing
the real worker against a real WAL with one reader mid-transaction: a
single main-thread write blocked for 4,936ms behind the worker's
wal_checkpoint(TRUNCATE), which then reported WAL 8.8MB -> 8.8MB. TRUNCATE
is the blocking form and its locks are held ACROSS connections, so moving
it to a worker kept the fsync off the loop but not the lock; and it does
not throw when it cannot get those locks, it returns busy=1 having sat on
SQLite's 5s busy timeout and reclaimed nothing. Five seconds of stalled
loop for zero benefit, and silent.

It was reached far too easily. The rule was "escalate if the WAL grew
across three consecutive 15s runs" — which any sustained 45-second write
burst satisfies. A customer's fleet powering on in the morning does it
daily.

Two gates, because either alone leaves the hole open. A size FLOOR, so a
WAL in the lower half of its budget can't buy a blocking checkpoint it has
nothing to reclaim from. And a COOLDOWN, because the floor alone fixes
nothing for Bold — their WAL already sits at 6.2MB against a 16MB
high-water, above any sane floor, so every burst would still escalate.
However long the pressure lasts, our own maintenance may now stall the
loop at most once per window. The high-water rule bypasses both and is
untouched: a runaway WAL is the one case worth blocking for, so the
"WAL cannot grow forever" invariant is exactly as strong as before.

A busy TRUNCATE now says so in the log instead of reading like a success.

Also softened the adjacent path: when the worker is declared
unrecoverable, engageFallback() re-arms inline autocheckpoint on the main
connection — a state that is STICKY for the life of the process, i.e.
exactly the shape of "degrades with uptime, a restart fixes it". It used
to also run an unconditional main-thread TRUNCATE on the way in; that now
happens only when the WAL is genuinely over high-water, and the fallback
state is served on /api/status rather than being inferable only from a log
line that may have rolled.

Telemetry, so the next report is self-explanatory: loop_lag carries
`samples` (~50 when healthy, 1 when a single turn swallowed the second),
`tick_gap_ms` measured on the WALL CLOCK independently of the histogram,
and `worst_tick_gap_ms`/`worst_tick_at` — monotone, so five-minute polling
can no longer miss an episode.

Band semantics are deliberately unchanged. A one-sample window during a
real stall is the correct trigger for the shed valve; suppressing it would
blind the protection at exactly the moment it is needed.

Separately, device_telemetry gets the age sweep it never had. The
per-heartbeat row cap only ever trims the device whose heartbeat is being
handled, so a device that STOPS reporting leaves its rows behind forever.
The new sweep is per-device (rides idx_telemetry_device rather than
scanning), chunked and yielding like the device_status_log one, and
defaults to 30 days to match the uptime report's own default window — so
it cannot remove rows that report would have shown.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014skWYXJUWhF73EvNPgB2AS
2026-08-06 20:22:21 -05:00

104 lines
5.4 KiB
JavaScript

// WAL checkpointer WORKER (worker_threads). Runs OFF the main event-loop thread so the
// synchronous, fsync-heavy checkpoint never blocks the loop (the ~60s p99 spike).
//
// CRITICAL: this worker opens its OWN better-sqlite3 Database() handle against the same
// file. better-sqlite3 handles are NOT thread-safe, so the main thread's handle is never
// shared into the worker — only the dbPath STRING is passed via workerData. SQLite WAL is
// designed for multiple connections to the same file, so a second connection checkpointing
// while the main connection writes is safe.
const { workerData, parentPort } = require('worker_threads');
const fs = require('fs');
const Database = require('better-sqlite3');
const { dbPath, intervalMs, highWaterBytes, starvationRuns, starvationFloorBytes, escalateCooldownMs } = workerData;
// Fault injection for TESTS ONLY (env-gated; inert in prod). Exits immediately on start so
// the controller's respawn / autocheckpoint-fallback path can be exercised deterministically.
if (process.env.WAL_CKPT_FAIL_START) process.exit(1);
// Fresh, worker-owned connection (NOT the main handle).
const db = new Database(dbPath);
db.pragma('busy_timeout = 5000'); // wait (on THIS worker thread) through the main writer's brief locks
db.pragma('wal_autocheckpoint = 0'); // this connection must never auto-checkpoint either
const walFile = dbPath + '-wal';
function walBytes() { try { return fs.statSync(walFile).size; } catch { return 0; } }
let lastBytes = 0;
let growthRuns = 0; // consecutive PASSIVE runs where the WAL failed to shrink
let lastTruncateAt = 0; // #240: when we last blocked for a TRUNCATE (0 = never)
let coolingReported = false;
let timer = null;
function tick() {
try {
// PASSIVE never blocks writers, but skips frames pinned by active readers/writers —
// so on its own it can perpetually under-checkpoint. That's what the guard below bounds.
db.pragma('wal_checkpoint(PASSIVE)', { simple: false });
const bytes = walBytes();
// --- STARVATION BOUND (this is where "WAL cannot grow forever" is enforced) ---
// Escalating forces a TRUNCATE, which BLOCKS until it has checkpointed everything and
// truncated the file to 0. #240: "fine here on the worker" was only ever half true —
// the fsync is off the loop, but SQLite's locks are held across CONNECTIONS, so the
// main thread's next statement waits it out in the busy handler. Hence the gates below.
if (bytes > lastBytes) growthRuns++; else growthRuns = 0;
const overHighWater = bytes > highWaterBytes;
// #240: TRUNCATE blocks ACROSS connections — the main thread's next statement waits in
// SQLite's busy handler for the whole checkpoint — so the growth signal alone must not
// be able to spend it. Two gates, because either on its own leaves the hole open:
// FLOOR: a WAL in the lower half of its budget has little to reclaim; blocking for it
// is pure cost. (Ungated, every morning fleet power-on wave bought a loop stall.)
// COOLDOWN: a WAL that already sits ABOVE the floor would otherwise escalate on every
// burst forever. However long the pressure lasts, we stall the loop at most once
// per window and let PASSIVE do the rest.
// overHighWater bypasses both — a runaway WAL is the one case worth blocking for.
const sinceLast = Date.now() - lastTruncateAt;
const starved = growthRuns >= starvationRuns && bytes >= starvationFloorBytes;
const cooling = starved && lastTruncateAt > 0 && sinceLast < escalateCooldownMs;
if (cooling && !overHighWater) {
// Report the transition only — a starved-and-cooling state persists for the whole
// window and this check runs every interval; one line, not a log flood.
if (!coolingReported) {
coolingReported = true;
post(`starvation escalation held off (WAL ${(bytes / 1e6).toFixed(1)}MB, last TRUNCATE ${Math.round(sinceLast / 1000)}s ago) — PASSIVE continues`);
}
lastBytes = bytes;
return;
}
if (overHighWater || starved) {
lastTruncateAt = Date.now();
coolingReported = false;
const r = db.pragma('wal_checkpoint(TRUNCATE)', { simple: false });
const after = walBytes();
// #240: TRUNCATE does NOT throw when it can't get the locks — it returns busy=1 having
// sat on SQLite's busy timeout for its full duration. Measured at ~4.9s with a single
// reader mid-transaction, reclaiming nothing, while every main-thread statement waited
// behind it. Say so plainly: a silent 5-second loss is the worst thing this can do.
const busy = Array.isArray(r) && r[0] && r[0].busy === 1;
post(`escalated TRUNCATE (${overHighWater ? 'high-water' : 'starvation'}): WAL ${(bytes / 1e6).toFixed(1)}MB -> ${(after / 1e6).toFixed(1)}MB${busy ? ' — BUSY: reclaimed nothing, blocked writers for the busy timeout' : ''}`);
growthRuns = 0;
lastBytes = after;
} else {
lastBytes = bytes;
}
} catch (e) {
post('checkpoint error: ' + (e && e.message));
}
}
function post(log) { try { parentPort && parentPort.postMessage({ log }); } catch (_) {} }
timer = setInterval(tick, intervalMs);
// Clean shutdown: stop the timer, close our connection, exit THIS worker thread.
parentPort && parentPort.on('message', (m) => {
if (m && m.stop) {
if (timer) { clearInterval(timer); timer = null; }
try { db.close(); } catch (_) {}
process.exit(0);
}
});