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 {