mirror of
https://github.com/screentinker/screentinker.git
synced 2026-08-14 06:16:20 -06:00
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
141 lines
7.3 KiB
JavaScript
141 lines
7.3 KiB
JavaScript
// Off-main-thread WAL checkpointer — main-thread controller.
|
|
//
|
|
// SQLite's default auto-checkpoint runs a synchronous, fsync-heavy checkpoint inline on the
|
|
// write that trips the 1000-page threshold; on slow storage that blocks the event loop for
|
|
// ~600-750ms on a ~60s beat (the periodic p99 spike). We disable inline auto-checkpoint on
|
|
// the MAIN connection and delegate checkpointing to a worker_threads worker that opens its
|
|
// OWN connection (see wal-checkpointer-worker.js) so the fsync blocks the worker, not the loop.
|
|
//
|
|
// FAILURE MODE this file closes: with wal_autocheckpoint=0, if the worker dies NOTHING
|
|
// checkpoints and the WAL grows until the disk fills. So an unexpectedly-dead worker is
|
|
// respawned (bounded retry); if it can't be kept alive, we re-enable a conservative inline
|
|
// autocheckpoint on the main connection as a degraded-but-safe fallback (occasional inline
|
|
// stall << unbounded WAL growth).
|
|
const path = require('path');
|
|
const fs = require('fs');
|
|
const { Worker } = require('worker_threads');
|
|
const config = require('../config');
|
|
|
|
let worker = null;
|
|
let mainDb = null;
|
|
let mainDbPath = null;
|
|
let stopping = false; // true only during our own stopWalCheckpointer() teardown
|
|
let fallbackEngaged = false; // true once we've given up on the worker and re-armed inline autocheckpoint
|
|
const respawnAt = []; // timestamps (ms) of recent respawns, for the rate window
|
|
|
|
function spawnWorker() {
|
|
const w = new Worker(path.join(__dirname, 'wal-checkpointer-worker.js'), {
|
|
workerData: {
|
|
dbPath: mainDbPath, // string only (thread-safe handoff)
|
|
intervalMs: config.walCheckpointIntervalMs,
|
|
highWaterBytes: config.walCheckpointHighWaterMB * 1024 * 1024,
|
|
starvationRuns: config.walCheckpointStarvationRuns,
|
|
starvationFloorBytes: config.walCheckpointStarvationFloorMB * 1024 * 1024, // #240
|
|
escalateCooldownMs: config.walCheckpointEscalateCooldownMs, // #240
|
|
},
|
|
});
|
|
w.on('message', (m) => { if (m && m.log) console.log('[wal-checkpoint] ' + m.log); });
|
|
w.on('error', (e) => console.error('[wal-checkpoint] worker error:', e && e.message)); // 'exit' handles recovery
|
|
w.on('exit', (code) => onWorkerExit(code));
|
|
// A worker thread cannot outlive its process; unref() also ensures it never KEEPS the
|
|
// process alive during shutdown — so there's no orphaned worker/connection either way.
|
|
w.unref();
|
|
return w;
|
|
}
|
|
|
|
// Called on every worker 'exit'. Distinguishes our intentional teardown (stopping=true —
|
|
// stay silent, no respawn) from an unexpected death (respawn, then fall back if exhausted).
|
|
function onWorkerExit(code) {
|
|
worker = null;
|
|
if (stopping || fallbackEngaged) return; // clean stop, or we've already given up — no noise
|
|
console.warn(`[wal-checkpoint] worker died unexpectedly (code ${code}) — attempting respawn`);
|
|
scheduleRespawn();
|
|
}
|
|
|
|
function scheduleRespawn() {
|
|
if (stopping || fallbackEngaged) return;
|
|
const now = Date.now();
|
|
while (respawnAt.length && now - respawnAt[0] > config.walCheckpointRespawnWindowMs) respawnAt.shift();
|
|
if (respawnAt.length >= config.walCheckpointRespawnMax) {
|
|
engageFallback(); // too many respawns in the window -> give up
|
|
return;
|
|
}
|
|
respawnAt.push(now);
|
|
const t = setTimeout(() => {
|
|
if (stopping || fallbackEngaged) return;
|
|
try {
|
|
worker = spawnWorker();
|
|
console.warn(`[wal-checkpoint] worker respawned (${respawnAt.length}/${config.walCheckpointRespawnMax} in window)`);
|
|
} catch (e) {
|
|
console.error('[wal-checkpoint] respawn spawn failed: ' + (e && e.message));
|
|
scheduleRespawn(); // count this failure too
|
|
}
|
|
}, config.walCheckpointRespawnBackoffMs);
|
|
if (t.unref) t.unref(); // never let the backoff timer hold the process open
|
|
}
|
|
|
|
// Degraded-but-safe: re-arm a conservative inline autocheckpoint on the MAIN connection so
|
|
// the WAL can never grow unbounded, and reclaim the backlog the dead worker left behind.
|
|
function engageFallback() {
|
|
if (fallbackEngaged) return;
|
|
fallbackEngaged = true;
|
|
try { mainDb.pragma(`wal_autocheckpoint = ${config.walCheckpointFallbackPages}`); } catch (_) {}
|
|
// #240: reclaim the dead worker's backlog, but pick the CHEAPEST form that does the job.
|
|
// The old unconditional TRUNCATE ran a blocking, fsync-heavy checkpoint on the MAIN
|
|
// thread — on slow storage a single multi-second loop stall, and one that only ever
|
|
// happens on a degraded server that can least afford it. PASSIVE reclaims what it can
|
|
// without blocking; the blocking form is reserved for a WAL that is genuinely over the
|
|
// high-water mark, where leaving it is the worse of the two risks.
|
|
const over = walBytes() > config.walCheckpointHighWaterMB * 1024 * 1024;
|
|
try { mainDb.pragma(`wal_checkpoint(${over ? 'TRUNCATE' : 'PASSIVE'})`); } catch (_) {}
|
|
console.error(`[wal-checkpoint] worker unrecoverable — re-enabled inline autocheckpoint as fallback (backlog reclaim: ${over ? 'TRUNCATE' : 'PASSIVE'})`);
|
|
}
|
|
|
|
// #240: the fallback is STICKY for the life of the process — once engaged, checkpoints are
|
|
// back on the main thread until a restart. That is exactly the shape of "it degrades with
|
|
// uptime and a restart fixes it", so it must be visible on /api/status rather than inferable
|
|
// only from a log line that may have rolled.
|
|
function getCheckpointerState() {
|
|
return { worker: !!worker, fallbackEngaged, respawns: respawnAt.length, walBytes: walBytes() };
|
|
}
|
|
|
|
function walBytes() {
|
|
try { return mainDbPath ? fs.statSync(mainDbPath + '-wal').size : 0; } catch (_) { return 0; }
|
|
}
|
|
|
|
// Call ONCE at boot, after the DB is open + migrated. `db` is the main connection (used to
|
|
// flip the pragma, do the one-time handoff checkpoint, and arm the fallback if needed).
|
|
// `dbPath` is the STRING the worker uses to open its own handle — the main handle is never shared.
|
|
function startWalCheckpointer(db, dbPath) {
|
|
if (worker) return worker;
|
|
mainDb = db;
|
|
mainDbPath = dbPath;
|
|
stopping = false;
|
|
fallbackEngaged = false;
|
|
respawnAt.length = 0;
|
|
|
|
// From now on the main thread NEVER inline-checkpoints (removes the loop-blocking fsync).
|
|
db.pragma('wal_autocheckpoint = 0');
|
|
// Hand the worker a clean WAL (one-time, at boot; explicit checkpoints are independent of
|
|
// wal_autocheckpoint, so this still works at 0). Also reclaims any WAL a prior crash left.
|
|
try { db.pragma('wal_checkpoint(TRUNCATE)'); } catch (_) { /* best-effort */ }
|
|
|
|
worker = spawnWorker();
|
|
console.log(`[wal-checkpoint] off-thread checkpointer started (every ${config.walCheckpointIntervalMs}ms; escalate >${config.walCheckpointHighWaterMB}MB or ${config.walCheckpointStarvationRuns} growing runs; respawn max ${config.walCheckpointRespawnMax}/${config.walCheckpointRespawnWindowMs}ms)`);
|
|
return worker;
|
|
}
|
|
|
|
// Graceful teardown: mark intentional (so onWorkerExit stays silent), ask the worker to stop
|
|
// (clears its timer + closes its connection), then force-terminate as a backstop. Safe when not started.
|
|
async function stopWalCheckpointer() {
|
|
stopping = true;
|
|
if (!worker) return;
|
|
const w = worker;
|
|
worker = null;
|
|
try { w.postMessage({ stop: true }); } catch (_) {}
|
|
await new Promise((r) => setTimeout(r, 150)); // let it close its handle cleanly
|
|
try { await w.terminate(); } catch (_) {}
|
|
}
|
|
|
|
module.exports = { startWalCheckpointer, stopWalCheckpointer, getCheckpointerState, _getWorker: () => worker };
|