From e99eb2f879e92a96263912488086bb423043df9d Mon Sep 17 00:00:00 2001 From: lidge-jun <243035832+lidge-jun@users.noreply.github.com> Date: Thu, 12 Nov 2026 11:48:09 +0900 Subject: [PATCH] fix(usage): restore the short filter-index busy back-off #8479 lengthened the active index read's SQLITE_BUSY schedule from [10, 25, 50] ms to nine delays totaling about 6.4 s, plus a synchronous 250 ms busy timeout per attempt. A filtered request that meets a held index write lock therefore waited 9-13 s before degrading to the streaming read (2.7 s before #8479), and the macOS dev batch timed out the contention test at 20 s. The streaming read answers the same request, so the long wait only held dashboard requests and the event loop. Restore the original schedule, assert the scheduled busy delays stay bounded (deterministic, through the retry-delay hook), and return the contention test to the default timeout. The two-process rebuild test, which passed on the short schedule before #8479, still passes. --- src/usage/filter-index.ts | 11 +++++++---- structure/usage-client-attribution.md | 3 ++- tests/usage/usage-filter-index.test.ts | 13 ++++++++++--- 3 files changed, 19 insertions(+), 8 deletions(-) diff --git a/src/usage/filter-index.ts b/src/usage/filter-index.ts index 5b048e30265..72f90161a51 100644 --- a/src/usage/filter-index.ts +++ b/src/usage/filter-index.ts @@ -97,7 +97,10 @@ const SQLITE_BUSY_TIMEOUT_MS = 250; const RETAINED_WAL_LIMIT_BYTES = 4 * 1024 * 1024; const BATCH_BUSY_RETRIES = 3; const BATCH_BUSY_RETRY_MS = 5; -const BUSY_RETRY_DELAYS_MS = [10, 25, 50, 100, 200, 400, 800, 1_600, 3_200] as const; +// Contention is retried briefly and then degrades to the streaming read, which answers the same +// request from the ledger. A longer wait only holds a dashboard request (and, through SQLite's +// synchronous busy timeout, the event loop) behind another writer. +const BUSY_RETRY_DELAYS_MS = [10, 25, 50] as const; // A rebuild-required error resolves as soon as the competing publish settles, so it retries on // the original short schedule instead of parking behind the long busy backoff. const REBUILD_RETRY_DELAYS_MS = [10, 25, 50] as const; @@ -1570,9 +1573,9 @@ export async function readUsageFilterCandidates( continue; } if (isBusyError(error)) { - // Contention, including a peer still creating the projection, is waited out rather than - // read as a foreign file. The bound is the BUSY_RETRY_DELAYS_MS sum (about 6.4 s) plus up - // to ten busy timeouts before the request falls back to the streaming read. + // Contention, including a peer still creating the projection, is waited out briefly rather + // than read as a foreign file. The bound is the BUSY_RETRY_DELAYS_MS sum (85 ms) plus up to + // four busy timeouts before the request falls back to the streaming read. const delay = BUSY_RETRY_DELAYS_MS[attempt]; if (delay === undefined) return null; testHooks?.beforeBusyRetry?.({ dbPath: path, attempt }); diff --git a/structure/usage-client-attribution.md b/structure/usage-client-attribution.md index 387b3a1bbf9..5a23a051ab3 100644 --- a/structure/usage-client-attribution.md +++ b/structure/usage-client-attribution.md @@ -133,7 +133,8 @@ projection read-only, requires this projection's full table set rather than a co table, and only uses it when it is current for the exact ledger revision; otherwise it streams, and it never creates, writes or registers anything. The passive read makes a single attempt and degrades to the streaming scan on any error; it does not retry. Only the active index read -(`readUsageFilterCandidates`) retries contention on nine delays totaling about 6.4 s and runs a +(`readUsageFilterCandidates`) retries contention on three short delays (85 ms, plus SQLite's +250 ms busy timeout per attempt) before streaming, and runs a foreign or unsafe open and a rebuild-required read through three short delays before degrading. Any other index-side failure -- unwritable home, diff --git a/tests/usage/usage-filter-index.test.ts b/tests/usage/usage-filter-index.test.ts index 0ecd44da494..b466567d16a 100644 --- a/tests/usage/usage-filter-index.test.ts +++ b/tests/usage/usage-filter-index.test.ts @@ -1345,19 +1345,26 @@ describe("filtered usage index availability", () => { appendRows([{ ...syntheticRow(99), requestId: "late", provider: "kimi" }]); const lock = new Database(usageFilterIndexPath(testDir)); lock.exec("BEGIN IMMEDIATE"); + // The busy back-off is bounded and short: a held lock degrades to the streaming read instead of + // holding the request for seconds. Record the scheduled delays rather than timing the run. + const busyDelays: number[] = []; + setUsageFilterIndexTestHooksForTests({ + beforeRetryDelay: ({ delayMs }) => { busyDelays.push(delayMs); }, + }); try { const result = await getFilteredUsageAggregate({ provider: "openai" }); expect(summary(result).summary.requests) .toBe(rows.filter(row => row.provider === "openai").length); // Contention is an index problem, not a ledger failure: the request still answers. expect(result.filterIndex).toBeUndefined(); + expect(busyDelays.length).toBeGreaterThan(0); + expect(busyDelays.reduce((sum, delay) => sum + delay, 0)).toBeLessThanOrEqual(250); } finally { + setUsageFilterIndexTestHooksForTests(null); lock.exec("ROLLBACK"); lock.close(); } - // Sustained contention exhausts the extended busy-retry window before degrading to the - // streaming read, which takes several seconds by design; the default 5s timeout is too tight. - }, 20_000); + }); test("an unchanged filtered read releases its index reader", async () => { const rows = Array.from({ length: 5 }, (_, index) => syntheticRow(index));