From 7a67101edfbfffb2a60b69f8909eb31a0ceaedb4 Mon Sep 17 00:00:00 2001 From: Jean-Philippe Sirois Date: Wed, 12 Aug 2026 17:11:44 -0300 Subject: [PATCH] feat(remote): say why a statistics refresh was skipped The statistics refresh runs on every 60s schema poll and has four ways to decline, all of them silent. A project that had not captured statistics for five days looked identical in the logs to one refreshing on schedule, and the logs from that window cannot tell us which guard was responsible. Each early return now reports itself: no baseline, a refresh already in flight and for how long, a backoff and how much is left, or no drift and how long until the daily floor. The no-drift line carries the near miss. detectDrift returns the table that came closest to the ratio without reaching it, because a refresh that never fires reads the same whether the database is quiet or one table is sitting just under the threshold, and those want opposite fixes. On the project that went quiet, the closest table was at 42% of a 50% ratio. Reporting every poll would bury the log, and reporting only changes would hide a steady state from any window that opens after it settled, which is the position the five-day gap left us in. Lines are emitted on change and then on a 30-minute heartbeat. Co-Authored-By: Claude --- src/remote/remote.ts | 85 +++++++++++++++++++++++++++++++++- src/remote/stats-drift.test.ts | 32 +++++++++++++ src/remote/stats-drift.ts | 14 +++++- 3 files changed, 127 insertions(+), 4 deletions(-) diff --git a/src/remote/remote.ts b/src/remote/remote.ts index 95c1c8e..7caab03 100644 --- a/src/remote/remote.ts +++ b/src/remote/remote.ts @@ -25,6 +25,8 @@ import { QueryLoader } from "./query-loader.ts"; import { SchemaLoader } from "./schema-loader.ts"; import { baselineFromDump, + DEFAULT_REFRESH_FLOOR_MS, + DEFAULT_SIZE_DRIFT_RATIO, detectDrift, isPastRefreshFloor, type StatsBaseline, @@ -94,6 +96,19 @@ export class Remote extends EventEmitter { private statsBaseline?: StatsBaseline; /** Guards against a second drift dump starting while one is in flight. */ private refreshingStats = false; + /** When the in-flight refresh started, so a wedged one can say how long. */ + private refreshingSince?: number; + /** + * The last reason a poll declined to refresh, and when it was reported. + * + * The check runs every 60s and almost always declines, so reporting each one + * would bury the log. Reporting only changes would hide a steady state from + * any window that opens after it settled, which is exactly the position a + * five-day statistics gap left us in. Both, then: on change, and on a slow + * heartbeat. + */ + private lastSkippedRefresh?: { reason: string; loggedAt: number }; + private static readonly SKIP_LOG_INTERVAL_MS = 30 * 60 * 1000; /** * When this analyzer last pushed a dump, for the daily floor. A drift- * triggered push updates it too, so the two triggers can't dump twice in @@ -406,23 +421,57 @@ export class Remote extends EventEmitter { * production statistics. */ private async refreshStatsIfStale(source: Connectable): Promise { - if (!this.statsBaseline || this.refreshingStats) { + if (!this.statsBaseline) { + this.noteSkippedRefresh( + "no drift baseline, so nothing can trigger a dump", + ); + return; + } + if (this.refreshingStats) { + this.noteSkippedRefresh( + `a refresh has been in flight for ${ + since(this.refreshingSince) + }; nothing else can start while it is`, + ); return; } // Back off after a failure. `lastStatsPushAt` only advances on success, so // without this a dump that keeps throwing (a statement_timeout on a large // pg_statistic read, say) would be retried on every 60s poll. if (this.retryStatsAfter !== undefined && Date.now() < this.retryStatsAfter) { + this.noteSkippedRefresh( + `backed off for another ${ + duration(this.retryStatsAfter - Date.now()) + } after a failed refresh`, + ); return; } const connector = this.sourceManager.getConnectorFor(source); const reltuples = await connector.getReltuplesByTable(); const verdict = detectDrift(this.statsBaseline, { reltuples }); - const pastFloor = isPastRefreshFloor(this.lastStatsPushAt, Date.now()); + const now = Date.now(); + const pastFloor = isPastRefreshFloor(this.lastStatsPushAt, now); if (!verdict.drifted && !pastFloor) { + // The near-miss matters: a table sitting just under the ratio means the + // threshold is what is holding the refresh back, not a quiet database. + const closest = verdict.closest + ? `closest was ${verdict.closest.table} at ${ + Math.round(verdict.closest.ratio * 100) + }% of ${Math.round(DEFAULT_SIZE_DRIFT_RATIO * 100)}%` + : "no table was eligible"; + this.noteSkippedRefresh( + `no drift (${closest}), and ${ + this.lastStatsPushAt === undefined + ? "the daily floor is unarmed" + : `${ + duration(DEFAULT_REFRESH_FLOOR_MS - (now - this.lastStatsPushAt)) + } until the daily floor` + }`, + ); return; } + this.refreshingSince = Date.now(); this.refreshingStats = true; try { log.info( @@ -443,6 +492,26 @@ export class Remote extends EventEmitter { } } + /** + * Reports why a poll declined to refresh the statistics. + * + * Every early return above used to be silent, so a project that had not + * captured statistics for days looked identical in the logs to one that + * refreshed on schedule. + */ + private noteSkippedRefresh(reason: string): void { + const now = Date.now(); + const last = this.lastSkippedRefresh; + if ( + last && last.reason === reason && + now - last.loggedAt < Remote.SKIP_LOG_INTERVAL_MS + ) { + return; + } + this.lastSkippedRefresh = { reason, loggedAt: now }; + log.info(`Statistics refresh skipped: ${reason}`, "remote"); + } + private async dumpSourceStats(source: Connectable): Promise { const pg = this.sourceManager.getOrCreateConnection( source, @@ -643,3 +712,15 @@ const PgStatStatementsStatus = { type PgStatStatementsStatus = typeof PgStatStatementsStatus[keyof typeof PgStatStatementsStatus]; + +/** Rounded to the largest unit that still reads as a number, for log lines. */ +function duration(ms: number): string { + if (ms <= 0) return "0s"; + if (ms < 60_000) return `${Math.round(ms / 1000)}s`; + if (ms < 3_600_000) return `${Math.round(ms / 60_000)}m`; + return `${(ms / 3_600_000).toFixed(1)}h`; +} + +function since(startedAt: number | undefined): string { + return startedAt === undefined ? "an unknown time" : duration(Date.now() - startedAt); +} diff --git a/src/remote/stats-drift.test.ts b/src/remote/stats-drift.test.ts index b04aed2..15e227c 100644 --- a/src/remote/stats-drift.test.ts +++ b/src/remote/stats-drift.test.ts @@ -178,3 +178,35 @@ describe("isPastRefreshFloor", () => { expect(isPastRefreshFloor(NOW - 500, NOW, 1_000)).toBe(false); }); }); + +/** + * A refresh that never fires reads the same from outside whether the database + * is quiet or one table is sitting just under the ratio. The first calls for + * patience and the second for a different threshold, so the verdict carries the + * near miss. + */ +describe("detectDrift — the closest table that did not drift", () => { + it("names the table nearest the ratio, and how far it moved", () => { + const baseline = baselineFromDump([table("users", BIG), table("teams", BIG)]); + + const verdict = detectDrift(baseline, { + reltuples: reltuples({ users: BIG * 0.6, teams: BIG * 0.95 }), + }); + + expect(verdict.drifted).toBe(false); + // users moved 40%, teams 5%. The threshold is 50%, so neither fires. + expect(verdict.drifted === false && verdict.closest).toEqual({ + table: "public.users", + ratio: expect.closeTo(0.4, 5), + }); + }); + + it("reports no closest table when none was eligible", () => { + // Both sides below the row floor, so Size Drift never considers them. + const baseline = baselineFromDump([table("tiny", 10)]); + + const verdict = detectDrift(baseline, { reltuples: reltuples({ tiny: 900 }) }); + + expect(verdict.drifted === false && verdict.closest).toBeUndefined(); + }); +}); diff --git a/src/remote/stats-drift.ts b/src/remote/stats-drift.ts index 4b95dd3..f7194db 100644 --- a/src/remote/stats-drift.ts +++ b/src/remote/stats-drift.ts @@ -34,7 +34,13 @@ export interface SourceReltuples { } export type DriftVerdict = - | { drifted: false } + /** + * `closest` is the table that came nearest to the ratio without reaching it, + * absent when no table was eligible. A refresh that never fires looks the + * same from outside whether nothing moved or one table sat just under the + * threshold, and those call for opposite fixes. + */ + | { drifted: false; closest?: { table: TableKey; ratio: number } } | { drifted: true; kind: "shape" | "size"; reason: string }; /** @@ -116,6 +122,7 @@ export function detectDrift( }; } + let closest: { table: TableKey; ratio: number } | undefined; for (const [key, now] of current.reltuples) { const before = baseline.reltuples.get(key); if (before === undefined) continue; @@ -133,9 +140,12 @@ export function detectDrift( }%)`, }; } + if (!closest || moved > closest.ratio) { + closest = { table: key, ratio: moved }; + } } - return { drifted: false }; + return { drifted: false, closest }; } function summarize(keys: TableKey[]): string {