#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
This commit is contained in:
ScreenTinker 2026-08-06 19:39:17 -05:00
parent 60deefd992
commit 59489b3b20
9 changed files with 353 additions and 15 deletions

View file

@ -226,6 +226,11 @@ module.exports = {
// is LOWER than the old hardcoded 7 days (the reporter's bloat happened under 7d);
// 2-3 days is plenty for the dashboard's 24h uptime view + diagnostics.
statusLogRetentionDays: parseFloat(process.env.STATUS_LOG_RETENTION_DAYS) || 3,
// #240 device_telemetry age retention (pruneTelemetryRetention in db/database.js). The
// per-heartbeat row cap only trims devices that are still reporting; this closes the
// rows left behind by ones that stopped. 30d matches the uptime report's default window,
// so it can only remove rows the report would not have shown anyway.
telemetryRetentionDays: parseFloat(process.env.TELEMETRY_RETENTION_DAYS) || 30,
// #146 HARD per-device row-count ceiling on device_status_log, enforced by the
// global sweep alongside the age delete above. Age-based retention can't bound a
// write storm (rows are all younger than the window), so a reconnect storm grew
@ -303,6 +308,24 @@ module.exports = {
// ...or escalate if the WAL grew across this many consecutive PASSIVE runs (PASSIVE not
// keeping up even below the high-water). Belt-and-suspenders with the MB bound above.
walCheckpointStarvationRuns: parseInt(process.env.WAL_CHECKPOINT_STARVATION_RUNS) || 3,
// #240: ...but growth alone is NOT starvation. Any sustained write burst — a fleet
// powering on in the morning — grows the WAL across several consecutive PASSIVE runs
// while it is still tiny. Escalating there buys nothing (there is nothing to reclaim)
// and costs a lot: TRUNCATE is the BLOCKING form, and it blocks across connections, so
// every main-thread statement issued during it sits in SQLite's busy handler (5s by
// default in better-sqlite3) — a multi-second loop stall at exactly the moment the
// fleet is reconnecting. So the growth signal may only escalate once the WAL is big
// enough for a blocking checkpoint to be worth it. The high-water mark above is
// unchanged and remains the hard backstop, so the WAL still cannot grow unbounded.
// Set at half the high-water mark: a WAL still in the lower half is not worth blocking
// for, and anything in the upper half is close enough to the backstop to be worth it.
walCheckpointStarvationFloorMB: parseFloat(process.env.WAL_CHECKPOINT_STARVATION_FLOOR_MB) || 8,
// #240: the floor alone is not enough — a WAL that already sits above it (Bold's was
// 6.2MB against a 16MB high-water) would still escalate on every burst. So the growth
// path is ALSO rate-limited: however long the write pressure lasts, our own maintenance
// may stall the loop at most once per this window. The high-water escalation is
// deliberately EXEMPT — that one is the runaway-WAL backstop and must never be delayed.
walCheckpointEscalateCooldownMs: parseInt(process.env.WAL_CHECKPOINT_ESCALATE_COOLDOWN_MS) || 300000,
// Worker-death handling: with autocheckpoint=0 a dead worker means nothing checkpoints and
// the WAL grows until the disk fills. An unexpectedly-dead worker is respawned up to
// RespawnMax times per RespawnWindowMs (with a small backoff); if that's exhausted we

View file

@ -1116,6 +1116,40 @@ function pruneTelemetry(deviceId) {
_delTelemetry.run(deviceId, config.statusLogPruneBatch);
}
// #240: the per-heartbeat cap above is the only thing that ever trimmed device_telemetry,
// and it only trims the device whose heartbeat is being handled — so a device that STOPS
// reporting (decommissioned, swapped, seasonally dark) leaves its rows behind forever and
// the table only ever grows. This is the matching age sweep, mirroring pruneStatusLog:
// per-device so it rides idx_telemetry_device(device_id, reported_at DESC) instead of
// scanning, chunked so a backlog trims across many bounded DELETEs, and yielding between
// devices so it can never own the loop.
//
// The retention default is deliberately LOOSER than the per-device cap (6000 rows ~= 25h
// for a device reporting every 15s) and matches the uptime report's default 30-day window,
// so this sweep cannot change a report that the row cap wasn't already truncating.
const _nextTelemetryDevice = db.prepare('SELECT device_id FROM device_telemetry WHERE device_id > ? ORDER BY device_id LIMIT 1');
const _delTelemetryOld = db.prepare('DELETE FROM device_telemetry WHERE rowid IN (SELECT rowid FROM device_telemetry WHERE device_id = ? AND reported_at < ? LIMIT ?)');
let _telemetryPruneRunning = false;
async function pruneTelemetryRetention(opts = {}) {
if (_telemetryPruneRunning) return 0;
if (opts.bandGate && config.maintenanceBandGateEnabled && currentBand() !== 'normal') return 0;
_telemetryPruneRunning = true;
try {
const batch = config.statusLogPruneBatch;
const cutoff = Math.floor(Date.now() / 1000) - Math.round(config.telemetryRetentionDays * 86400);
let total = 0, lastDev = '';
for (;;) {
const row = _nextTelemetryDevice.get(lastDev); // O(log n) seek to the next distinct device_id
if (!row) break;
lastDev = row.device_id;
total += (await chunkedDelete((lim) => _delTelemetryOld.run(lastDev, cutoff, lim).changes, { batch })).deleted;
await yieldTick(); // breathe between devices
}
if (total > 0) console.log(`[telemetry] pruned ${total} row(s) older than ${config.telemetryRetentionDays}d (per-device, batches of ${batch})`);
return total;
} catch (_) { return 0; } finally { _telemetryPruneRunning = false; }
}
// Prune old screenshots (keep only latest per device)
function pruneScreenshots(deviceId) {
const old = db.prepare(`
@ -1176,4 +1210,4 @@ try {
const { verifyAndRepairSchema } = require('../lib/schema-check');
verifyAndRepairSchema(db);
module.exports = { db, pruneTelemetry, pruneScreenshots, pruneStatusLog, getMaintenanceStats };
module.exports = { db, pruneTelemetry, pruneTelemetryRetention, pruneScreenshots, pruneStatusLog, getMaintenanceStats };

View file

@ -10,7 +10,7 @@ const { workerData, parentPort } = require('worker_threads');
const fs = require('fs');
const Database = require('better-sqlite3');
const { dbPath, intervalMs, highWaterBytes, starvationRuns } = workerData;
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.
@ -25,7 +25,9 @@ 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 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() {
@ -36,16 +38,47 @@ function tick() {
const bytes = walBytes();
// --- STARVATION BOUND (this is where "WAL cannot grow forever" is enforced) ---
// Either signal forces a TRUNCATE, which BLOCKS until it has checkpointed everything
// and truncated the file to 0. Blocking is fatal on the loop but FINE here on the worker.
// 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;
const starved = growthRuns >= starvationRuns;
// #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) {
db.pragma('wal_checkpoint(TRUNCATE)', { simple: false });
lastTruncateAt = Date.now();
coolingReported = false;
const r = db.pragma('wal_checkpoint(TRUNCATE)', { simple: false });
const after = walBytes();
post(`escalated TRUNCATE (${overHighWater ? 'high-water' : 'starvation'}): WAL ${(bytes / 1e6).toFixed(1)}MB -> ${(after / 1e6).toFixed(1)}MB`);
// #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 {

View file

@ -12,6 +12,7 @@
// 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');
@ -29,6 +30,8 @@ function spawnWorker() {
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); });
@ -77,8 +80,27 @@ function engageFallback() {
if (fallbackEngaged) return;
fallbackEngaged = true;
try { mainDb.pragma(`wal_autocheckpoint = ${config.walCheckpointFallbackPages}`); } catch (_) {}
try { mainDb.pragma('wal_checkpoint(TRUNCATE)'); } catch (_) {} // one-time reclaim of the dead-worker backlog
console.error('[wal-checkpoint] worker unrecoverable — re-enabled inline autocheckpoint as fallback');
// #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
@ -115,4 +137,4 @@ async function stopWalCheckpointer() {
try { await w.terminate(); } catch (_) {}
}
module.exports = { startWalCheckpointer, stopWalCheckpointer, _getWorker: () => worker };
module.exports = { startWalCheckpointer, stopWalCheckpointer, getCheckpointerState, _getWorker: () => worker };

View file

@ -16,6 +16,7 @@ const otaBreaker = require('../lib/ota-breaker');
const otaDownloadGuard = require('../lib/ota-download-guard');
const logCoalescer = require('../lib/log-coalescer');
const { getMaintenanceStats } = require('../db/database');
const { getCheckpointerState } = require('../db/wal-checkpointer'); // #240
const heartbeat = require('../services/heartbeat');
const appSettings = require('../lib/app-settings');
@ -47,6 +48,7 @@ router.get('/', (req, res) => {
ota_breaker: otaBreaker.stats(), // rateBackoff{Total,LastWindow}
ota_download: otaDownloadGuard.stats(), // inFlight, served/shed ThisWindow + Total
maintenance: getMaintenanceStats(), // deleted, ms, at, running, sweepsTotal
wal_checkpoint: getCheckpointerState(), // #240 worker alive?, sticky fallback?, respawns, WAL bytes
log_coalescer_buffer: logCoalescer._size(),
};
}

View file

@ -1,4 +1,4 @@
const { db, pruneStatusLog } = require('../db/database');
const { db, pruneStatusLog, pruneTelemetryRetention } = require('../db/database');
const config = require('../config');
const { deviceRoom, emitToWorkspace } = require('../lib/socket-rooms');
const statusLogWriter = require('../lib/status-log-writer');
@ -173,6 +173,7 @@ async function runMaintenance() {
await pruneProvisioningDevices();
await prunePlayLogs();
await pruneStatusLog({ bandGate: true }); // per-device chunked; own re-entrancy
await pruneTelemetryRetention({ bandGate: true }); // #240 device_telemetry age sweep (per-device chunked)
await pruneDeviceEvents(); // offline-cause log: incident-feed age retention (chunked)
await capDeviceEvents(); // offline-cause log: per-device incident row cap
await pruneUsageDaily(); // #146 BILLING rollup retention (chunked)

View file

@ -29,7 +29,23 @@ const LEVEL = { normal: 0, elevated: 1, critical: 2 };
let histogram = null;
let band = 'normal';
let calmSamples = 0;
let current = { mean_ms: 0, p50_ms: 0, p99_ms: 0, max_ms: 0, band: 'normal', sampled_at: 0 };
// #240: `samples` and the tick-gap fields exist to make ONE window's numbers
// interpretable. An IntervalHistogram window that recorded a single delay reports
// mean = p50 = p99 = max (the mean is the raw value, the percentiles are the bucket
// ceiling above it) — indistinguishable, from the numbers alone, from a fixed cost
// paid on every cycle. It is the opposite: one long loop turn. `samples` is the
// histogram's record count for the window (~50 at a 20ms resolution when healthy,
// 1 when a single turn swallowed the whole second), and tick_gap_ms is the
// WALL-CLOCK gap between consecutive sampler runs — ground truth for whether the
// loop is actually late, measured independently of the histogram.
let current = {
mean_ms: 0, p50_ms: 0, p99_ms: 0, max_ms: 0, samples: 0,
tick_gap_ms: 0, worst_tick_gap_ms: 0, worst_tick_at: 0,
band: 'normal', sampled_at: 0,
};
let lastSampleAt = 0; // wall clock of the previous sample() run
let worstTickGapMs = 0; // largest gap seen since process start...
let worstTickAt = 0; // ...and when (epoch seconds). Survives coarse polling.
const lagBuffer = []; // #146 Item E: pending telemetry rows, batch-inserted on flush
// Pure band-transition function (exported for deterministic unit tests). Given the
@ -65,18 +81,35 @@ const round2 = (x) => Math.round(x * 100) / 100;
const metric = (x) => (Number.isFinite(x) ? round2(x) : 0);
function sample() {
// #240: measure the sampler's OWN lateness first. This interval is armed for
// lagSampleIntervalMs, so any excess is loop delay that the histogram cannot
// misreport — if the histogram claims seconds of lag while this stays at the
// interval, the block did not happen where the histogram says it did.
const nowMs = Date.now();
const tickGap = lastSampleAt ? nowMs - lastSampleAt : config.lagSampleIntervalMs;
lastSampleAt = nowMs;
if (tickGap > worstTickGapMs) { worstTickGapMs = tickGap; worstTickAt = Math.floor(nowMs / 1000); }
const p99 = histogram.percentile(99) / NS_PER_MS;
const snap = {
mean_ms: metric(histogram.mean / NS_PER_MS),
p50_ms: metric(histogram.percentile(50) / NS_PER_MS),
p99_ms: metric(p99),
max_ms: metric(histogram.max / NS_PER_MS),
samples: histogram.count, // MUST be read before reset()
};
histogram.reset();
const prev = band;
[band, calmSamples] = nextBand(band, snap.p99_ms, calmSamples);
current = { ...snap, band, sampled_at: Math.floor(Date.now() / 1000) };
current = {
...snap,
tick_gap_ms: tickGap,
worst_tick_gap_ms: worstTickGapMs,
worst_tick_at: worstTickAt,
band,
sampled_at: Math.floor(nowMs / 1000),
};
// #146 Item E: BUFFER the telemetry row (batch-inserted on the flush interval) instead
// of a synchronous INSERT per sample — under DB contention (a bloated table slowing
@ -89,7 +122,9 @@ function sample() {
// COALESCED (one summarized line per flush) so a sustained-critical storm can't turn
// logging into its own loop hog. Healthy steady state stays quiet.
if (band !== prev) {
console.log(`[loop-lag] band=${band} (was ${prev}) mean=${snap.mean_ms}ms p99=${snap.p99_ms}ms max=${snap.max_ms}ms`);
// #240: samples + tick gap ride along on the band line — without them a one-sample
// window reads as a permanent per-cycle cost to whoever finds this in the logs.
console.log(`[loop-lag] band=${band} (was ${prev}) mean=${snap.mean_ms}ms p99=${snap.p99_ms}ms max=${snap.max_ms}ms samples=${snap.samples} tick_gap=${tickGap}ms`);
} else if (band !== 'normal') {
// #146 P3.7: coalesce repeats and carry the PEAK p99 over the window (not a random
// sample's) — the peak is the number that matters during an incident.

View file

@ -0,0 +1,57 @@
// #240 — a loop-lag window must report how many samples it is made of.
//
// The bug this closes is a reading bug, not a code bug. An IntervalHistogram window that
// recorded exactly ONE delay reports mean = p50 = p99 = max, with the mean sitting just
// below the identical percentiles (the mean is the raw value; the percentiles are the
// HdrHistogram bucket ceiling above it). From the four numbers alone that is
// indistinguishable from a fixed cost paid on every single cycle — and it was read that
// way on a production incident. It is the opposite: one long loop turn, once.
//
// So /api/status now carries `samples` and an independently-measured wall-clock tick gap.
// These assertions pin the arithmetic that makes the distinction real.
const { test } = require('node:test');
const assert = require('node:assert/strict');
const { createHistogram, monitorEventLoopDelay } = require('perf_hooks');
const NS = 1e6;
const r2 = (x) => Math.round(x * 100) / 100;
test('#240: one recorded sample produces the mean=p50=p99=max signature', () => {
const h = createHistogram();
h.record(1329070000); // 1329.07ms, the production reading
assert.equal(h.count, 1);
assert.equal(r2(h.mean / NS), 1329.07, 'mean is the raw value');
const p50 = r2(h.percentile(50) / NS), p99 = r2(h.percentile(99) / NS), max = r2(h.max / NS);
assert.equal(p50, p99);
assert.equal(p99, max, 'every percentile collapses onto the same bucket ceiling');
assert.ok(max > r2(h.mean / NS), 'the ceiling sits ABOVE the mean — the tell that count is 1');
});
test('#240: a busy window does NOT produce that signature — p50 stays at the floor', () => {
// Many small delays plus one big one: the real shape of an intermittent stall.
const h = createHistogram();
for (let i = 0; i < 49; i++) h.record(20000000); // 20ms, the resolution floor
h.record(1329070000); // one 1.3s stall
assert.equal(h.count, 50);
assert.notEqual(r2(h.percentile(50) / NS), r2(h.max / NS),
'with real samples in the window the median cannot equal the max');
assert.ok(r2(h.mean / NS) < r2(h.percentile(99) / NS), 'mean stays well under p99');
});
test('#240: an idle loop reports the RESOLUTION, not zero — the healthy baseline is the floor', async () => {
const h = monitorEventLoopDelay({ resolution: 20 });
h.enable();
await new Promise((r) => setTimeout(r, 250));
h.disable();
assert.ok(h.count > 5, 'the sampler should have recorded several ticks');
const mean = h.mean / NS;
assert.ok(mean >= 19 && mean < 60, `idle mean should sit at ~the 20ms resolution, got ${r2(mean)}`);
});
test('#240: getLag() carries samples and the independent tick-gap fields', () => {
const loopLag = require('../services/loop-lag');
const lag = loopLag.getLag();
for (const k of ['mean_ms', 'p50_ms', 'p99_ms', 'max_ms', 'samples', 'tick_gap_ms', 'worst_tick_gap_ms', 'worst_tick_at', 'band', 'sampled_at']) {
assert.ok(k in lag, `/api/status loop_lag must expose ${k}`);
}
});

View file

@ -0,0 +1,131 @@
// #240 — the WAL checkpointer's STARVATION escalation must be gated on WAL size.
//
// Why this test exists: TRUNCATE is the blocking checkpoint form and it blocks across
// connections, so a main-thread statement issued during one waits in SQLite's busy handler
// for its whole duration. The old rule escalated on growth ALONE — three consecutive
// PASSIVE runs where the WAL got bigger — which any sustained write burst satisfies. A
// customer's fleet powering on in the morning bought itself a multi-second event-loop
// stall against a WAL of a couple of MB, where a blocking checkpoint had nothing to
// reclaim in the first place.
//
// The decision is deliberately tested as the pure predicate the worker evaluates rather
// than by driving a real worker thread: the property that matters is WHEN we are willing
// to block, and that must not silently regress behind a timing-dependent test.
const { test } = require('node:test');
const assert = require('node:assert/strict');
const fs = require('fs');
const os = require('os');
const path = require('path');
const config = require('../config');
const MB = 1024 * 1024;
// The worker's escalation rule, kept in one place so the assertions below read as policy.
function shouldEscalate({ bytes, growthRuns, sinceLastTruncateMs, everTruncated,
highWaterBytes, starvationRuns, starvationFloorBytes, escalateCooldownMs }) {
const overHighWater = bytes > highWaterBytes;
const starved = growthRuns >= starvationRuns && bytes >= starvationFloorBytes;
const cooling = starved && everTruncated && sinceLastTruncateMs < escalateCooldownMs;
if (cooling && !overHighWater) return { overHighWater, starved, cooling, escalate: false };
return { overHighWater, starved, cooling, escalate: overHighWater || starved };
}
const RULE = {
highWaterBytes: config.walCheckpointHighWaterMB * MB,
starvationRuns: config.walCheckpointStarvationRuns,
starvationFloorBytes: config.walCheckpointStarvationFloorMB * MB,
escalateCooldownMs: config.walCheckpointEscalateCooldownMs,
sinceLastTruncateMs: Infinity,
everTruncated: false,
};
test('#240: a small WAL growing across runs no longer triggers the blocking TRUNCATE', () => {
// The morning-wave shape: sustained writes, WAL grew every run, still only 2MB.
const r = shouldEscalate({ ...RULE, bytes: 2 * MB, growthRuns: 5 });
assert.equal(r.escalate, false, 'growth alone must not escalate while the WAL is small');
});
test('#240: growth still escalates once the WAL is actually large', () => {
const r = shouldEscalate({ ...RULE, bytes: config.walCheckpointStarvationFloorMB * MB, growthRuns: config.walCheckpointStarvationRuns });
assert.equal(r.starved, true, 'at the floor, sustained growth is real starvation');
assert.equal(r.escalate, true);
});
test('#240: the high-water backstop is untouched — the WAL still cannot grow unbounded', () => {
// No growth signal at all (a single huge run), well over the high-water mark.
const r = shouldEscalate({ ...RULE, bytes: (config.walCheckpointHighWaterMB + 1) * MB, growthRuns: 0 });
assert.equal(r.overHighWater, true);
assert.equal(r.escalate, true, 'high-water must escalate regardless of the growth counter');
});
test('#240: the floor sits below the high-water mark, so the two rules cannot invert', () => {
assert.ok(
config.walCheckpointStarvationFloorMB < config.walCheckpointHighWaterMB,
'a floor at or above high-water would make the starvation rule dead code'
);
});
// The floor on its own does NOT close this. Bold's WAL sat at 6.2MB against a 16MB
// high-water — already above any sane floor — so a morning wave would still have escalated
// on every burst. The cooldown is what bounds how often our own maintenance may stall the
// loop, regardless of how long the write pressure lasts.
test('#240: a WAL already above the floor escalates ONCE, then holds off', () => {
const big = { ...RULE, bytes: 12 * MB, growthRuns: 5 };
const first = shouldEscalate({ ...big });
assert.equal(first.escalate, true, 'the first sustained-growth burst still escalates');
const during = shouldEscalate({ ...big, everTruncated: true, sinceLastTruncateMs: 30_000 });
assert.equal(during.cooling, true);
assert.equal(during.escalate, false, 'a second burst inside the cooldown must not stall the loop again');
const after = shouldEscalate({ ...big, everTruncated: true, sinceLastTruncateMs: config.walCheckpointEscalateCooldownMs + 1 });
assert.equal(after.escalate, true, 'once the window passes, escalation is available again');
});
test('#240: the cooldown never delays the runaway-WAL backstop', () => {
const runaway = {
...RULE, bytes: (config.walCheckpointHighWaterMB + 1) * MB, growthRuns: 5,
everTruncated: true, sinceLastTruncateMs: 1000, // deep inside the cooldown
};
const r = shouldEscalate(runaway);
assert.equal(r.escalate, true, 'over high-water must escalate even mid-cooldown — that rule is the safety net');
});
test('#240: the worker actually applies the floor it is handed', () => {
const src = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer-worker.js'), 'utf8');
assert.match(src, /growthRuns >= starvationRuns && bytes >= starvationFloorBytes/,
'worker starvation check must include the size floor');
assert.match(src, /starvationFloorBytes/, 'worker must destructure starvationFloorBytes from workerData');
assert.match(src, /sinceLast < escalateCooldownMs/, 'worker must apply the escalation cooldown');
const ctl = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer.js'), 'utf8');
assert.match(ctl, /starvationFloorBytes:\s*config\.walCheckpointStarvationFloorMB/,
'controller must pass the floor through workerData — an undefined floor would make every comparison false');
assert.match(ctl, /escalateCooldownMs:\s*config\.walCheckpointEscalateCooldownMs/,
'controller must pass the cooldown through workerData');
});
// Measured, not assumed: with a single reader mid-transaction, TRUNCATE returns busy=1
// after sitting on its 5s busy timeout and reclaims nothing (probe: WAL 8.8MB -> 8.8MB,
// worst main-thread write 4,936ms). That outcome must not be logged as a success.
test('#240: a TRUNCATE that reclaimed nothing says so', () => {
const src = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer-worker.js'), 'utf8');
assert.match(src, /busy === 1/, 'worker must inspect the checkpoint result');
assert.match(src, /reclaimed nothing/, 'a busy TRUNCATE must be reported as the loss it is');
});
test('#240: the unrecoverable-worker fallback no longer blocks the loop for a small WAL', () => {
const ctl = fs.readFileSync(path.join(__dirname, '..', 'db', 'wal-checkpointer.js'), 'utf8');
assert.match(ctl, /wal_checkpoint\(\$\{over \? 'TRUNCATE' : 'PASSIVE'\}\)/,
'fallback reclaim must pick TRUNCATE only when the WAL is over the high-water mark');
});
test('#240: /api/status exposes the sticky fallback state', () => {
const { getCheckpointerState } = require('../db/wal-checkpointer');
const s = getCheckpointerState();
// Not started in this process — the point is the shape, and that reading it is safe
// before startWalCheckpointer() has ever run (status is served during boot too).
assert.deepEqual(Object.keys(s).sort(), ['fallbackEngaged', 'respawns', 'walBytes', 'worker']);
assert.equal(s.fallbackEngaged, false);
assert.equal(typeof s.walBytes, 'number');
});