diff --git a/changelog.d/fixes/13218-wal-busy-counter.md b/changelog.d/fixes/13218-wal-busy-counter.md new file mode 100644 index 0000000000..7b82d5a484 --- /dev/null +++ b/changelog.d/fixes/13218-wal-busy-counter.md @@ -0,0 +1 @@ +- **fix(db):** the WAL checkpoint busy counter reported by `/api/monitoring/health` now survives restarts — busy checkpoints are counted in memory and persisted from the next clean maintenance tick or at shutdown, never with a write while the database is contended ([#13218](https://github.com/diegosouzapw/OmniRoute/pull/13218)) — thanks @maxmad64bis diff --git a/src/lib/db/walMaintenance.ts b/src/lib/db/walMaintenance.ts index d884720a27..659500a19f 100644 --- a/src/lib/db/walMaintenance.ts +++ b/src/lib/db/walMaintenance.ts @@ -41,6 +41,9 @@ const DEFAULT_WAL_PASSIVE_INTERVAL_MS = 5 * 60 * 1000; const DEFAULT_WAL_GUARD_MAX_BYTES = 256 * 1024 * 1024; const RETRY_DELAY_MS = 60_000; +export const WAL_BUSY_NAMESPACE = "walMaintenance"; +export const WAL_BUSY_KEY = "busyTotal"; + let walTimer: NodeJS.Timeout | null = null; let walPassiveTimer: NodeJS.Timeout | null = null; let retryTimer: NodeJS.Timeout | null = null; @@ -49,13 +52,44 @@ let busyStreak = 0; let busyTotal = 0; let lastBusyAt: string | null = null; let lastOkAt: string | null = null; +// Busy events counted in memory but not yet added to the persisted counter. +let pendingBusyDelta = 0; +// The handle the running scheduler was started with; used for the shutdown flush. +let activeDb: SqliteAdapter | null = null; +/** + * Count one busy checkpoint. Memory only, on purpose: a busy checkpoint means the + * database is contended RIGHT NOW, and a write here would wait up to `busy_timeout` + * (2s) on the event loop. The increment is persisted later by flushBusyTotal() from + * a non-busy scheduler tick or at shutdown. + */ function recordBusy(): void { busyStreak++; busyTotal++; + pendingBusyDelta++; lastBusyAt = new Date().toISOString(); } +/** + * Add the pending busy events to the persisted counter. Best-effort and single-shot: + * any failure (locked, closed, missing table) keeps the delta pending for the next + * non-busy tick — there is no retry loop. The additive UPSERT stays correct when + * several processes share the database file. + */ +export function flushBusyTotal(db: SqliteAdapter | null): boolean { + if (pendingBusyDelta === 0 || !db || !db.open) return false; + try { + db.prepare( + "INSERT INTO key_value(namespace, key, value) VALUES(?, ?, ?) " + + "ON CONFLICT(namespace, key) DO UPDATE SET value = CAST(value AS INTEGER) + excluded.value" + ).run(WAL_BUSY_NAMESPACE, WAL_BUSY_KEY, pendingBusyDelta); + pendingBusyDelta = 0; + return true; + } catch { + return false; + } +} + function recordOk(): void { busyStreak = 0; lastOkAt = new Date().toISOString(); @@ -207,6 +241,7 @@ function schedulePassiveRetry(db: SqliteAdapter): void { logCheckpointOutcome(outcome, "PASSIVE", busyStreak); } else if (outcome.ok) { recordOk(); + flushBusyTotal(db); } else { logCheckpointOutcome(outcome, "PASSIVE", busyStreak); } @@ -239,6 +274,7 @@ function startWalPassiveScheduler( isBuildPhase: isNextBuildPhase(), }); if (stats.skipped) return; + if (!stats.busy && stats.ok) flushBusyTotal(db); if (stats.busy || (stats.checkpointedFrames ?? 0) > 0) { console.log( `[DB] WAL passive checkpoint (busy=${stats.busy ? 1 : 0} logFrames=${stats.logFrames} ` + @@ -273,8 +309,13 @@ export function startWalMaintenance( sqliteFile: string | null, env: NodeJS.ProcessEnv = process.env ): void { + // stopWalMaintenance() flushes what it can and zeroes session state, so capture the + // in-memory total first; the gate stays before any DB touch. + const priorBusyTotal = busyTotal; stopWalMaintenance(); if (sqliteFile === null || isCloud || isNextBuildPhase() || isAutomatedTestProcess()) return; + activeDb = db; + busyTotal = mergeBusyTotal(priorBusyTotal, loadPersistedBusyTotal(db)); const intervalMs = getWalMaintenanceIntervalMs(env); if (intervalMs <= 0) { startWalPassiveScheduler(db, sqliteFile, env); @@ -294,6 +335,7 @@ export function startWalMaintenance( schedulePassiveRetry(db); } else if (outcome.ok) { recordOk(); + flushBusyTotal(db); console.log( `[DB] Periodic SQLite WAL checkpoint completed (TRUNCATE) in ${Date.now() - startedAtMs}ms ` + `(walMbBefore=${formatWalMb(walBeforeBytes)} walMbAfter=${formatWalMb(getWalFileSizeBytes(sqliteFile))} ` + @@ -311,6 +353,10 @@ export function startWalMaintenance( } export function stopWalMaintenance(): void { + // Shutdown / restart: best-effort persist of busy events not flushed by a tick. + flushBusyTotal(activeDb); + activeDb = null; + pendingBusyDelta = 0; if (walTimer) { clearInterval(walTimer); walTimer = null; @@ -334,6 +380,27 @@ export function getWalMaintenanceState(): WalMaintenanceState { return { ticks, busyStreak, busyTotal, lastBusyAt, lastOkAt }; } +export function loadPersistedBusyTotal(db: SqliteAdapter): number { + try { + const row = db + .prepare("SELECT value FROM key_value WHERE namespace = ? AND key = ?") + .get(WAL_BUSY_NAMESPACE, WAL_BUSY_KEY) as { value: unknown } | undefined; + const n = Number(row?.value); + return Number.isFinite(n) && n >= 0 ? Math.floor(n) : 0; + } catch (error) { + // Boot read-path, not the hot scheduler path: never fail silently. + console.warn(`[DB] WAL busy counter unreadable, starting from 0: ${String(error)}`); + return 0; + } +} + +export function mergeBusyTotal(prior: number, loaded: number): number { + // Both inputs floored, non-finite or negative → 0 (matches load fallback). + const p = Number.isFinite(prior) && prior > 0 ? Math.floor(prior) : 0; + const l = Number.isFinite(loaded) && loaded > 0 ? Math.floor(loaded) : 0; + return Math.max(p, l); +} + export function __resetForTests(): void { stopWalMaintenance(); } diff --git a/tests/unit/wal-maintenance.test.ts b/tests/unit/wal-maintenance.test.ts index 8447de2829..0ae01c1ce3 100644 --- a/tests/unit/wal-maintenance.test.ts +++ b/tests/unit/wal-maintenance.test.ts @@ -164,3 +164,170 @@ test("start is silent and stateless under the test-process gate", async () => { test.beforeEach(async () => { (await import("../../src/lib/db/walMaintenance.ts")).__resetForTests(); }); + +test("mergeBusyTotal keeps the max, floors at 0", async () => { + const { mergeBusyTotal } = await import("../../src/lib/db/walMaintenance.ts"); + assert.equal(mergeBusyTotal(5, 3), 5); + assert.equal(mergeBusyTotal(3, 5), 5); + assert.equal(mergeBusyTotal(0, 0), 0); + assert.equal(mergeBusyTotal(-2, -7), 0); + assert.equal(mergeBusyTotal(2.9, 1), 2); +}); + +test("loadPersistedBusyTotal reads the key, falls back to 0", async () => { + const { loadPersistedBusyTotal } = await import("../../src/lib/db/walMaintenance.ts"); + const store = new Map([["walMaintenance/busyTotal", "41"]]); + const db = { + pragma: () => [{ busy: 0, log: 0, checkpointed: 0 }], + prepare: (_sql: string) => ({ + get: () => { + const v = store.get("walMaintenance/busyTotal"); + return v === undefined ? undefined : { value: v }; + }, + run: () => {}, + }), + }; + assert.equal(loadPersistedBusyTotal(db as never), 41); + store.set("walMaintenance/busyTotal", "abc"); + assert.equal(loadPersistedBusyTotal(db as never), 0); + store.delete("walMaintenance/busyTotal"); + assert.equal(loadPersistedBusyTotal(db as never), 0); +}); + +test("flushBusyTotal is a no-op with nothing pending or no open handle", async () => { + const { flushBusyTotal } = await import("../../src/lib/db/walMaintenance.ts"); + let prepared = 0; + const db = { + open: true, + prepare: () => { + prepared++; + return { run: () => {} }; + }, + }; + assert.equal(flushBusyTotal(db as never), false); + assert.equal(flushBusyTotal(null), false); + assert.equal(prepared, 0); +}); + +/** + * The scheduler is gated off inside test runners (isAutomatedTestProcess), so the real boot + * wiring runs in a child Node process that is not a test process. It drives the actual + * startWalMaintenance()/stopWalMaintenance() against a real SQLite file; only the checkpoint + * pragma result is scripted (busy vs clean) so contention can be produced on demand. Module + * paths travel through env vars so no argv token makes the child look like a test runner. + */ +const CHILD_SCRIPT = ` +const { startWalMaintenance, stopWalMaintenance, getWalMaintenanceState } = await import(process.env.WAL_MODULE_URL); +const { tryOpenSync } = await import(process.env.DRIVER_MODULE_URL); +const file = process.env.WAL_DB_FILE; +const sleep = (ms) => new Promise((r) => setTimeout(r, ms)); +const real = tryOpenSync(file); +if (!real) { console.log("WALCHILD " + JSON.stringify({ skipped: true })); process.exit(0); } +let mode = "busy"; +const writes = []; +const db = { + get open() { return real.open; }, + pragma: (s, o) => s.startsWith("wal_checkpoint") + ? [mode === "busy" ? { busy: 1, log: 5, checkpointed: 0 } : { busy: 0, log: 0, checkpointed: 0 }] + : real.pragma(s, o), + prepare: (sql) => { if (/INSERT/i.test(sql)) writes.push(mode); return real.prepare(sql); }, + exec: (sql) => real.exec(sql), + close: () => real.close(), +}; +const persisted = () => Number(real.prepare("SELECT value FROM key_value WHERE namespace='walMaintenance' AND key='busyTotal'").get()?.value ?? 0); +const env = { OMNIROUTE_WAL_TRUNCATE_INTERVAL_MS: "60", OMNIROUTE_WAL_PASSIVE_INTERVAL_MS: "0" }; +const out = {}; +startWalMaintenance(db, file, env); +out.restoredAtBoot = getWalMaintenanceState().busyTotal; +await sleep(400); +out.afterBusy = { total: getWalMaintenanceState().busyTotal, persisted: persisted(), writes: writes.length }; +mode = "ok"; +await sleep(300); +out.afterOkTick = { total: getWalMaintenanceState().busyTotal, persisted: persisted(), busyWrites: writes.filter((m) => m === "busy").length }; +mode = "busy"; +await sleep(300); +out.beforeStop = { total: getWalMaintenanceState().busyTotal, persisted: persisted() }; +mode = "stopping"; +stopWalMaintenance(); +out.afterStop = { persisted: persisted(), busyWrites: writes.filter((m) => m === "busy").length, stopWrites: writes.filter((m) => m === "stopping").length }; +startWalMaintenance(db, file, env); +out.restoredAfterRestart = getWalMaintenanceState().busyTotal; +stopWalMaintenance(); +real.close(); +console.log("WALCHILD " + JSON.stringify(out)); +process.exit(0); +`; + +test("boot wiring: restores the persisted total, never writes on a busy tick, flushes on a clean tick and at stop", async (t) => { + const { spawnSync } = await import("node:child_process"); + const fs = await import("node:fs"); + const os = await import("node:os"); + const path = await import("node:path"); + const { pathToFileURL } = await import("node:url"); + const { tryOpenSync } = await import("../../src/lib/db/adapters/driverFactory.ts"); + + const dir = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-wal-boot-")); + const file = path.join(dir, "storage.sqlite"); + const seed = tryOpenSync(file); + if (!seed) { + fs.rmSync(dir, { recursive: true, force: true }); + t.skip("no sync SQLite driver available"); + return; + } + try { + seed.exec( + "CREATE TABLE IF NOT EXISTS key_value (namespace TEXT NOT NULL, key TEXT NOT NULL, value TEXT NOT NULL, PRIMARY KEY (namespace, key))" + ); + seed + .prepare( + "INSERT INTO key_value (namespace, key, value) VALUES ('walMaintenance', 'busyTotal', '41')" + ) + .run(); + seed.close(); + + const repoRoot = path.resolve(import.meta.dirname, "../.."); + const env: NodeJS.ProcessEnv = { + ...process.env, + WAL_MODULE_URL: pathToFileURL(path.join(repoRoot, "src/lib/db/walMaintenance.ts")).href, + DRIVER_MODULE_URL: pathToFileURL(path.join(repoRoot, "src/lib/db/adapters/driverFactory.ts")) + .href, + WAL_DB_FILE: file, + NODE_ENV: "production", + }; + delete env.VITEST; + delete env.NODE_TEST_CONTEXT; + const child = spawnSync( + process.execPath, + ["--import", "tsx/esm", "--input-type=module", "-e", CHILD_SCRIPT], + { cwd: repoRoot, env, encoding: "utf8", timeout: 120_000 } + ); + const line = (child.stdout || "").split("\n").find((l) => l.startsWith("WALCHILD ")); + assert.ok(line, `child produced no result (status ${child.status}): ${child.stderr}`); + const out = JSON.parse(line.slice("WALCHILD ".length)); + if (out.skipped) { + t.skip("child could not open a sync SQLite driver"); + return; + } + + assert.equal(out.restoredAtBoot, 41, "boot restores the persisted counter"); + assert.ok(out.afterBusy.total > 41, "busy ticks are counted in memory"); + assert.equal(out.afterBusy.writes, 0, "no database write on the busy path"); + assert.equal(out.afterBusy.persisted, 41, "persisted value untouched while contended"); + + assert.equal(out.afterOkTick.busyWrites, 0); + assert.equal( + out.afterOkTick.persisted, + out.afterOkTick.total, + "a clean tick flushes the delta" + ); + + assert.ok(out.beforeStop.total > out.afterOkTick.total, "more busy ticks after the flush"); + assert.equal(out.beforeStop.persisted, out.afterOkTick.total, "still no write while busy"); + assert.equal(out.afterStop.busyWrites, 0); + assert.equal(out.afterStop.stopWrites, 1, "exactly one flush at stop"); + assert.equal(out.afterStop.persisted, out.beforeStop.total, "stop flushes the remaining delta"); + assert.equal(out.restoredAfterRestart, out.beforeStop.total, "restart restores the full total"); + } finally { + fs.rmSync(dir, { recursive: true, force: true }); + } +});