screentinker/server/test/wal-checkpoint-starvation-floor.test.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

132 lines
7.3 KiB
JavaScript

// #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');
});