mirror of
https://github.com/screentinker/screentinker.git
synced 2026-08-13 13:53:12 -06:00
59489b3b20
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
58 lines
3 KiB
JavaScript
58 lines
3 KiB
JavaScript
// #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}`);
|
|
}
|
|
});
|