From 5b3ca73f74c050b5244983cc9e71999c7e1a0c6d Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 15:57:13 -0700 Subject: [PATCH 01/15] build: require Convex commit timestamp support --- package-lock.json | 12 ++++++------ package.json | 4 ++-- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/package-lock.json b/package-lock.json index c2e34da2..9e68a1a1 100644 --- a/package-lock.json +++ b/package-lock.json @@ -26,7 +26,7 @@ "chokidar-cli": "3.0.0", "convex": "1.45.0", "convex-helpers": "0.1.111", - "convex-test": "0.0.53", + "convex-test": "^0.0.57-alpha.0", "eslint": "10.0.2", "eslint-plugin-react-hooks": "7.1.0-canary-3f0b9e61-20260317", "eslint-plugin-react-refresh": "0.5.0", @@ -42,7 +42,7 @@ "vitest": "5.0.0" }, "peerDependencies": { - "convex": "^1.36.1", + "convex": "^1.43.0", "convex-helpers": "^0.1.94" } }, @@ -3106,13 +3106,13 @@ } }, "node_modules/convex-test": { - "version": "0.0.53", - "resolved": "https://registry.npmjs.org/convex-test/-/convex-test-0.0.53.tgz", - "integrity": "sha512-bouZQTnTvZi8IHljHL++yClj1vcV+/9ZxEcd8JZz7RDxOfPkRKrkMgkk/xlX4M1EAiwcEJPNiQE7VJFvDM3lCQ==", + "version": "0.0.57-alpha.0", + "resolved": "https://registry.npmjs.org/convex-test/-/convex-test-0.0.57-alpha.0.tgz", + "integrity": "sha512-dTR6S4HTGwcETapH0zfmaHb81PuvIScF2pRBFgpjPXOOuErSrSF5uZT7SRYrbNCDO6jBuxkZH2RNVMK9a0GQtQ==", "dev": true, "license": "Apache-2.0", "peerDependencies": { - "convex": "^1.32.0" + "convex": "^1.43.0" } }, "node_modules/cross-spawn": { diff --git a/package.json b/package.json index 7a32856d..f19f30eb 100644 --- a/package.json +++ b/package.json @@ -72,7 +72,7 @@ } }, "peerDependencies": { - "convex": "^1.36.1", + "convex": "^1.43.0", "convex-helpers": "^0.1.94" }, "devDependencies": { @@ -90,7 +90,7 @@ "chokidar-cli": "3.0.0", "convex": "1.45.0", "convex-helpers": "0.1.111", - "convex-test": "0.0.53", + "convex-test": "^0.0.57-alpha.0", "eslint": "10.0.2", "eslint-plugin-react-hooks": "7.1.0-canary-3f0b9e61-20260317", "eslint-plugin-react-refresh": "0.5.0", From 76b31446c15720a7c296c0ce9ce5ad10f19b7023 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 15:57:13 -0700 Subject: [PATCH 02/15] feat(queue): order work by commit and snapshot timestamps --- CHANGELOG.md | 9 + README.md | 4 + src/component/README.md | 43 +-- src/component/complete.test.ts | 7 +- src/component/complete.ts | 10 +- src/component/danger.test.ts | 114 ++++++ src/component/danger.ts | 90 ++--- src/component/kick.test.ts | 7 +- src/component/lib.ts | 45 ++- src/component/loop.test.ts | 581 +++++++++++++++++++++++++++-- src/component/loop.ts | 552 +++++++++++++++++---------- src/component/pendingStart.ts | 10 + src/component/schema.ts | 36 +- src/component/shared.ts | 85 ++++- src/component/stateMachine.test.ts | 161 +++++--- src/component/stats.test.ts | 418 +++++---------------- src/component/stats.ts | 70 ++-- 17 files changed, 1455 insertions(+), 787 deletions(-) create mode 100644 src/component/danger.test.ts create mode 100644 src/component/pendingStart.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index 895346c2..a735324b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,14 @@ # Changelog +## Unreleased + +- Orders queues by commit timestamp. Requires Convex 1.43 or later. +- Recovers near-term scheduled work that commits behind the queue cursor. +- Migrates queued work from older versions automatically, preserving scheduled + start times. Large queues may briefly delay new work during migration. +- Downgrading after this upgrade is unsupported because the queue format + changes. + ## 0.4.12 - Adds onCompleteExcludeKinds to filter callbacks by result kind (#237). Use diff --git a/README.md b/README.md index 2cfdc670..9936d24d 100644 --- a/README.md +++ b/README.md @@ -276,6 +276,10 @@ can learn about [here](https://docs.convex.dev/get-started). Run `npm create convex` or follow any of the [quickstarts](https://docs.convex.dev/home) to set one up. +Workpool orders its internal queues by +[commit timestamp](https://docs.convex.dev/database/advanced/commit-timestamp), +so it needs `convex` 1.43 or later. + ### Install the component See [`example/`](./example/convex/) for a working demo. diff --git a/src/component/README.md b/src/component/README.md index 90bf262c..e3108073 100644 --- a/src/component/README.md +++ b/src/component/README.md @@ -1,22 +1,13 @@ # Workpool: implementation notes and high-level architecture -Concepts: - -- `segment`: A slice of time to process work. All work is bucketed into one. - This enables us to batch work and avoid database conflicts. -- `generation`: A monotonically increasing counter owned by batch-worker to - ensure only one loop chain runs for a worker at a time. The old workpool - generation field is deprecated and only accepted for pre-migration docs. -- "Retention" is used to refer to situations where a query might have to read - over a lot of "tombstones" - deleted data that hasn't been vacuumed from the - underlying database yet. If there are frequent deletions, scanning across them - can delay a query. Because of our delete-heavy queuing strategy, we have to be - careful. Strategies are below. -- Cursors: A pointer to the last processed place in a table. In our case, they - might allow data to be written before them if out-of-order writes happen, so - we need to account for finding those "missed" writes on some granularity. We - choose to wait until there isn't any immediate work to do before those scans. - They help avoid retention issues. +- `segment`: a nanosecond timestamp. Immediate work uses its enqueue commit + timestamp; scheduled work uses its start time. +- Cursors: inclusive positions in the pending queues that skip deleted rows. The + incoming cursor never passes the snapshot. A separate `scanTs` cursor recovers + near-term scheduled enqueues that commit behind it. +- `generation`: batch-worker's counter that permits only one active loop chain. +- Tombstones: deleted rows that remain in storage until vacuumed. Advancing + cursors avoids repeatedly reading them. ## Data state machine @@ -52,14 +43,12 @@ a 10-second idle cooldown instead of the normal 2 seconds. This keeps batch-worker's status `running` for longer at full throttle, so most enqueue pings are no-ops rather than racing an idle transition. -## Retention optimization strategy +## Storage and reads -- Producers (Client, Worker, Recovery) write to a future "segment". -- Consumers (`run`) read the current segment. - - On conflicts, producers will write to progressively higher segments, while - the main loop will continue to read the segment originally called with. This - means conflicts are less likely on each retry. -- Patch singletons to avoid tombstones. -- Use segements & cursors to bound reads to latest data. - - Do scans outside of the critical path (during load). -- Do point reads otherwise. +- Store one queue document per work item and delete it when the work starts or + cancels. +- Read queues through bounded index ranges and point-read work documents. +- Keep the incoming cursor at or below the transaction snapshot so later commits + remain reachable. Re-key future legacy buckets during upgrade. +- Limit the sweep's boundary read to entries behind the incoming cursor, so + large batches of future work are not repeatedly scanned. diff --git a/src/component/complete.test.ts b/src/component/complete.test.ts index 4b9a33f0..5237c6ff 100644 --- a/src/component/complete.test.ts +++ b/src/component/complete.test.ts @@ -79,8 +79,11 @@ describe("complete", () => { }, ); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + }, lastRecovery: 0n, report: { completed: 0, diff --git a/src/component/complete.ts b/src/component/complete.ts index 20ec9b81..80fc84e8 100644 --- a/src/component/complete.ts +++ b/src/component/complete.ts @@ -5,12 +5,7 @@ import { internal } from "./_generated/api.js"; import { internalMutation, type MutationCtx } from "./_generated/server.js"; import { kickMainLoop } from "./kick.js"; import { createLogger } from "./logging.js"; -import { - getCurrentSegment, - type OnCompleteArgs, - type RunResult, - vResult, -} from "./shared.js"; +import { type OnCompleteArgs, type RunResult, vResult } from "./shared.js"; import { recordCompleted } from "./stats.js"; import { assert } from "convex-helpers"; @@ -214,12 +209,11 @@ export async function completeHandler( ? "retry" : "complete", ); - const segment = getCurrentSegment(); await Promise.all( pendingCompletions.map((completion) => ctx.db.insert("pendingCompletion", { ...completion, - segment, + segment: ctx.db.vars.commitTs, }), ), ); diff --git a/src/component/danger.test.ts b/src/component/danger.test.ts new file mode 100644 index 00000000..e5fddc57 --- /dev/null +++ b/src/component/danger.test.ts @@ -0,0 +1,114 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import type { TransactionLimits } from "convex/server"; +import { internal } from "./_generated/api.js"; +import type { Id } from "./_generated/dataModel.js"; +import { INITIAL_STATE } from "./loop.js"; +import { setupTest } from "./setup.test.js"; +import { toSegment, toTimestamp } from "./shared.js"; + +describe("danger cleanup", () => { + let t: ReturnType; + beforeEach(() => { + vi.useFakeTimers(); + t = setupTest(); + }); + afterEach(() => vi.useRealTimers()); + + async function enqueueWork(count: number, payloadBytes = 10) { + return t.run(async (ctx) => { + const workIds: Id<"work">[] = []; + for (let i = 0; i < count; i++) { + const payloadId = await ctx.db.insert("payload", { + args: { data: "x".repeat(payloadBytes) }, + }); + const workId = await ctx.db.insert("work", { + fnType: "action", + fnHandle: "test", + fnName: "test", + attempts: 0, + payloadId, + payloadSize: payloadBytes, + }); + workIds.push(workId); + const pendingStartId = await ctx.db.insert("pendingStart", { + workId, + segment: toTimestamp(Date.now()), + }); + await ctx.db.patch("work", workId, { pendingStartId }); + } + return workIds; + }); + } + + it.each([ + [250, 10, { documentsRead: 100 }], + [250, 10, { documentsWritten: 100 }], + [8, 800_000, { bytesRead: 4_000_000 }], + ])( + "resumes cleanup when a transaction budget is reached (%i works)", + async (count, payloadBytes, transactionLimits) => { + const ids = await enqueueWork(count, payloadBytes); + const before = Date.now() + 1; + vi.advanceTimersByTime(10); + const newerIds = await enqueueWork(1); + + await t.run((ctx) => + ctx.runMutation( + internal.danger.clearPending, + { before }, + { + transactionLimits: transactionLimits as TransactionLimits, + }, + ), + ); + await t.run(async (ctx) => { + const remaining = (await ctx.db.query("pendingStart").collect()) + .map((p) => p.workId) + .filter((id) => ids.includes(id)); + expect(remaining.length).toBeGreaterThan(0); + expect(remaining.length).toBeLessThan(count); + for (const id of remaining) + expect(await ctx.db.get("work", id)).not.toBeNull(); + }); + await t.finishAllScheduledFunctions(vi.runAllTimers); + await t.run(async (ctx) => { + expect( + (await ctx.db.query("work").collect()).map((w) => w._id), + ).toEqual(newerIds); + expect((await ctx.db.query("pendingStart").unique())!.workId).toBe( + newerIds[0], + ); + expect(await ctx.db.query("payload").collect()).toHaveLength(1); + }); + }, + ); + + it("removes legacy queue entries even below a persisted cursor", async () => { + await t.run(async (ctx) => { + const workId = await ctx.db.insert("work", { + fnType: "action", + fnHandle: "test", + fnName: "test", + attempts: 0, + }); + await ctx.db.insert("pendingStart", { + workId, + segment: toSegment(Date.now()), + }); + await ctx.db.insert("internalState", { + ...INITIAL_STATE, + segmentCursors: { + incoming: toSegment(Date.now() + 60_000), + completion: 0n, + cancelation: 0n, + }, + }); + }); + await t.mutation(internal.danger.clearOldWork, { before: Date.now() + 1 }); + await t.finishAllScheduledFunctions(vi.runAllTimers); + await t.run(async (ctx) => { + expect(await ctx.db.query("work").collect()).toHaveLength(0); + expect(await ctx.db.query("pendingStart").collect()).toHaveLength(0); + }); + }); +}); diff --git a/src/component/danger.ts b/src/component/danger.ts index bf91148b..7a4a8758 100644 --- a/src/component/danger.ts +++ b/src/component/danger.ts @@ -1,10 +1,10 @@ -import { v, getConvexSize } from "convex/values"; +import { v } from "convex/values"; +import { kickMainLoop } from "./kick.js"; import { internal } from "./_generated/api.js"; -import { internalMutation } from "./_generated/server.js"; +import { internalMutation, type MutationCtx } from "./_generated/server.js"; +import { findPendingStart } from "./pendingStart.js"; const DEFAULT_OLDER_THAN = 1000 * 60 * 60 * 24; -const MAX_ROWS_READ = 100; -const MAX_BYTES_READ = 4_000_000; export const clearPending = internalMutation({ args: { @@ -14,41 +14,25 @@ export const clearPending = internalMutation({ handler: async (ctx, args) => { const time = args.before ?? Date.now() - (args.olderThan ?? DEFAULT_OLDER_THAN); - let i = 0, - totalBytes = 0, - hasMore = false, - nextTime; console.log("Clearing pending before", new Date(time).toUTCString()); for await (const entry of ctx.db .query("pendingStart") .withIndex("by_creation_time", (q) => q.lte("_creationTime", time)) .order("desc")) { - i++; const work = await ctx.db.get("work", entry.workId); - totalBytes += - getConvexSize(entry) + getConvexSize(work) + (work?.payloadSize ?? 0); - if (i > MAX_ROWS_READ || totalBytes > MAX_BYTES_READ) { - hasMore = true; - nextTime = entry._creationTime; - console.log(`Continuing after ${i} entries, ${totalBytes} bytes`); - break; - } - await ctx.db.delete("pendingStart", entry._id); if (work) { - // Clean up any large data stored separately - if (work.payloadId) { - await ctx.db.delete("payload", work.payloadId); - } + if (work.payloadId) await ctx.db.delete("payload", work.payloadId); await ctx.db.delete("work", work._id); } + await ctx.db.delete("pendingStart", entry._id); + if (await usedHalfTransactionBudget(ctx)) { + await ctx.scheduler.runAfter(0, internal.danger.clearPending, { + before: entry._creationTime, + }); + return; + } } - if (hasMore) { - await ctx.scheduler.runAfter(0, internal.danger.clearPending, { - before: nextTime, - }); - } else { - console.log(`Done clearing pending entries. ${i} in the last batch.`); - } + console.log("Done clearing pending entries."); }, }); @@ -60,20 +44,16 @@ export const clearOldWork = internalMutation({ handler: async (ctx, args) => { const time = args.before ?? Date.now() - (args.olderThan ?? DEFAULT_OLDER_THAN); - let i = 0, - totalBytes = 0, - hasMore = false, - nextTime; console.log("Clearing old work before", new Date(time).toUTCString()); for await (const entry of ctx.db .query("work") .withIndex("by_creation_time", (q) => q.lte("_creationTime", time)) .order("desc")) { - i++; - const pendingStart = await ctx.db - .query("pendingStart") - .withIndex("workId", (q) => q.eq("workId", entry._id)) - .unique(); + if (entry.pendingStartId === undefined) { + // The upgrade pass removes orphaned legacy queue entries. + await kickMainLoop(ctx, "kick"); + } + const pendingStart = await findPendingStart(ctx, entry); const pendingCompletion = await ctx.db .query("pendingCompletion") .withIndex("workId", (q) => q.eq("workId", entry._id)) @@ -82,18 +62,6 @@ export const clearOldWork = internalMutation({ .query("pendingCancelation") .withIndex("workId", (q) => q.eq("workId", entry._id)) .unique(); - totalBytes += - getConvexSize(entry) + - getConvexSize(pendingStart) + - getConvexSize(pendingCompletion) + - getConvexSize(pendingCancelation) + - (entry.payloadSize ?? 0); - if (i > MAX_ROWS_READ || totalBytes > MAX_BYTES_READ) { - hasMore = true; - nextTime = entry._creationTime; - console.log(`Continuing after ${i} entries, ${totalBytes} bytes`); - break; - } if (pendingStart) { await ctx.db.delete("pendingStart", pendingStart._id); } @@ -118,13 +86,21 @@ export const clearOldWork = internalMutation({ .join(", ")})`, ); await ctx.db.delete("work", entry._id); + if (await usedHalfTransactionBudget(ctx)) { + await ctx.scheduler.runAfter(0, internal.danger.clearOldWork, { + before: entry._creationTime, + }); + return; + } } - if (hasMore) { - await ctx.scheduler.runAfter(0, internal.danger.clearOldWork, { - before: nextTime, - }); - } else { - console.log(`Done clearing old work. ${i} in the last batch.`); - } + console.log("Done clearing old work."); }, }); + +/** Leave headroom to finish the current document and schedule another batch. */ +async function usedHalfTransactionBudget(ctx: MutationCtx) { + const metrics = await ctx.meta.getTransactionMetrics(); + return Object.values(metrics).some( + ({ used, remaining }) => used >= remaining, + ); +} diff --git a/src/component/kick.test.ts b/src/component/kick.test.ts index 7d533440..14ecd6cf 100644 --- a/src/component/kick.test.ts +++ b/src/component/kick.test.ts @@ -33,8 +33,11 @@ describe("kickMainLoop", () => { }, ); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + }, lastRecovery: 0n, report: { completed: 0, diff --git a/src/component/lib.ts b/src/component/lib.ts index a6005b63..929b9f13 100644 --- a/src/component/lib.ts +++ b/src/component/lib.ts @@ -19,15 +19,17 @@ import { boundScheduledTime, vConfig, fnType, - getCurrentSegment, - max, vOnCompleteFnContext, retryBehavior, status as statusValidator, - toSegment, + maxBigint, + MINUTE, + snapshotTs, + toTimestamp, } from "./shared.js"; import { recordEnqueued } from "./stats.js"; import { getOrUpdateGlobals } from "./config.js"; +import { findPendingStart } from "./pendingStart.js"; const INLINE_METADATA_THRESHOLD = 8_000; // 8KB threshold const MAX_DOC_SIZE = 1_000_000; // Some buffer for 1MiB actual limit @@ -57,7 +59,8 @@ export const enqueue = mutation({ return await enqueueHandler(ctx, console, itemArgs); }, }); -async function enqueueHandler( +/** Exported for tests, so they enqueue exactly what the public API writes. */ +export async function enqueueHandler( ctx: MutationCtx, console: Logger, { runAt, ...workArgs }: ObjectType, @@ -111,11 +114,21 @@ async function enqueueHandler( // Store the work item const workId = await ctx.db.insert("work", workItem); - - await ctx.db.insert("pendingStart", { + const now = Date.now(); + const scheduled = runAt > now; + // Scheduled keys stay at or above the snapshot, which bounds the cursor. + const segment = scheduled + ? maxBigint(toTimestamp(runAt), snapshotTs()) + : ctx.db.vars.commitTs; + const pendingStartId = await ctx.db.insert("pendingStart", { workId, - segment: max(toSegment(runAt), getCurrentSegment()), + segment, + // Only near-term starts can commit behind the cursor. + ...(scheduled && (segment as bigint) <= toTimestamp(now + 5 * MINUTE) + ? { scanTs: ctx.db.vars.commitTs } + : {}), }); + await ctx.db.patch("work", workId, { pendingStartId }); recordEnqueued(console, { workId, fnName: workArgs.fnName, runAt }); return workId; } @@ -146,7 +159,7 @@ export const cancel = mutation({ await kickMainLoop(ctx, "cancel"); await ctx.db.insert("pendingCancelation", { workId: id, - segment: getCurrentSegment(), + segment: ctx.db.vars.commitTs, }); } }, @@ -176,13 +189,12 @@ export const cancelAll = mutation({ if (shouldCancel.some((c) => c)) { await kickMainLoop(ctx, "cancel"); } - const segment = getCurrentSegment(); await Promise.all( pageOfWork.map(({ _id }, index) => { if (shouldCancel[index]) { return ctx.db.insert("pendingCancelation", { workId: _id, - segment, + segment: ctx.db.vars.commitTs, }); } }), @@ -207,11 +219,14 @@ async function statusHandler(ctx: QueryCtx, { id }: { id: Id<"work"> }) { if (!work) { return { state: "finished" } as const; } - const pendingStart = await ctx.db - .query("pendingStart") - .withIndex("workId", (q) => q.eq("workId", id)) - .unique(); - if (pendingStart) { + if (work.pendingStartId === undefined) { + // Old running jobs have no queue pointer; queued jobs get one during upgrade. + const state = await ctx.db.query("internalState").order("desc").first(); + if (!state?.running.some((r) => r.workId === id)) { + return { state: "pending", previousAttempts: work.attempts } as const; + } + } + if (await findPendingStart(ctx, work)) { return { state: "pending", previousAttempts: work.attempts } as const; } const pendingCompletion = await ctx.db diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index 86296898..a04ea998 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -11,16 +11,19 @@ import { import { api, components, internal } from "./_generated/api.js"; import type { Doc, Id } from "./_generated/dataModel.js"; import { - RECOVERY_PERIOD_SEGMENTS, + RECOVERY_PERIOD_NS, SATURATED_STATUS_COOLDOWN, STATUS_COOLDOWN, } from "./loop.js"; +import { enqueueHandler } from "./lib.js"; +import { createLogger } from "./logging.js"; import { setupTest } from "./setup.test.js"; import { DEFAULT_MAX_PARALLELISM, fromSegment, - getCurrentSegment, + fromTimestamp, toSegment, + toTimestamp, WORKER_NAME, } from "./shared.js"; @@ -28,24 +31,10 @@ const SECOND = 1000; const MINUTE = 60 * SECOND; /** - * Behavior tests for the main loop, now driven by @convex-dev/batch-worker. - * Designed around what an external observer can see: - * - * - api.lib.status — public-facing state of a single work item - * - pending* tables — work in flight that the loop will process - * - state.running — slots currently occupied by workers - * - * The loop's lifecycle (running/idle/scheduled), generation guard, and - * liveness recovery are owned by batch-worker and are NOT asserted here. - * - * Setup conventions: - * - vi.useFakeTimers() so time advances deterministically - * - The loop is driven manually via runLoop(): query `getBatch`, and if it - * returns work, run the `main` worker mutation with that batch. This is - * exactly what batch-worker does for us in production. - * - simulateCompletion() pretends a worker finished its job by calling - * internal.complete.complete (how production gets work into - * pendingCompletion), so it's the correct seam for testing. + * Drive getBatch and run in one transaction, as batch-worker does. Observe + * public status, queue contents, and running jobs; simulate completions through + * the production completion handler. batch-worker tests cover loop liveness. + * Move time with setSystemTime so scheduled dummy workers never execute. */ describe("loop", () => { let t: ReturnType; @@ -79,8 +68,12 @@ describe("loop", () => { } await t.run(async (ctx) => { await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, lastRecovery: 0n, report: { completed: 0, @@ -96,23 +89,30 @@ describe("loop", () => { } /** - * Insert a work doc + pendingStart at the given segment (default: now). - * Bypasses the public enqueue API to keep tests focused on the loop. + * Enqueue work through the real `enqueueHandler`, so what the tests write + * can't drift from what the public API writes. `runAt` holds the work until + * then; the default runs it as soon as the loop sees it. `segment` instead + * writes a raw entry pinned to that ordering value, e.g. to give several + * entries the same one the way a single batch enqueue does. */ async function enqueueWork( overrides: Partial>> = {}, - segment = getCurrentSegment(), + { runAt, segment }: { runAt?: number; segment?: bigint } = {}, ): Promise> { return t.run(async (ctx) => { - const workId = await ctx.db.insert("work", { + const workId = await enqueueHandler(ctx, createLogger("WARN"), { fnType: "action", fnHandle: "test_handle", fnName: "test_handle", fnArgs: {}, - attempts: 0, + runAt: runAt ?? Date.now(), ...overrides, }); - await ctx.db.insert("pendingStart", { workId, segment }); + if (segment !== undefined) { + // Pin the ordering value, e.g. to simulate a shared commit stamp. + const work = (await ctx.db.get("work", workId))!; + await ctx.db.patch("pendingStart", work.pendingStartId!, { segment }); + } return workId; }); } @@ -123,13 +123,15 @@ describe("loop", () => { * result so tests can inspect the idle/work decision. */ async function runLoop() { - const result = await t.query(internal.loop.getBatch, { - name: WORKER_NAME, + return t.run(async (ctx) => { + const result = await ctx.runQuery(internal.loop.getBatch, { + name: WORKER_NAME, + }); + if (result.kind === "work") { + await ctx.runMutation(internal.loop.run, result.batch); + } + return result; }); - if (result.kind === "work") { - await t.mutation(internal.loop.run, result.batch); - } - return result; } /** Pretend a worker finished a job by inserting pendingCompletion. */ @@ -159,6 +161,7 @@ describe("loop", () => { .collect(); return { running: state?.running ?? [], + segmentCursors: state?.segmentCursors, lastRecovery: state?.lastRecovery ?? 0n, pendingStart, pendingCompletion, @@ -316,6 +319,212 @@ describe("loop", () => { expect(o.running.map((r) => r.workId)).not.toContain(finished); }); + it("doesn't drop work that shares a commit timestamp with the cursor", async () => { + // A batch enqueue commits every row at the same commit timestamp, so the + // cursor lands in the middle of a group whenever capacity cuts one short. + await initialize({ maxParallelism: 2 }); + const sharedTimestamp = toTimestamp(Date.now()); + const ids = []; + for (let i = 0; i < 4; i++) { + ids.push(await enqueueWork({}, { segment: sharedTimestamp })); + } + + const started: Id<"work">[] = []; + for (let i = 0; i < 4; i++) { + await runLoop(); + const o = await observe(); + expect(o.segmentCursors!.incoming).toBe(sharedTimestamp); + for (const r of o.running) { + if (!started.includes(r.workId)) started.push(r.workId); + } + for (const r of o.running) { + await simulateCompletion( + r.workId, + { kind: "success", returnValue: null }, + 0, + ); + } + } + await runLoop(); + + // All four ran even though the cursor sat on their shared timestamp. + expect(new Set(started)).toEqual(new Set(ids)); + expect((await observe()).pendingStart).toHaveLength(0); + }); + }); + + // ──────────────────────────────────────────────────────────────────── + // Entries written before commit-timestamp ordering + // ──────────────────────────────────────────────────────────────────── + + describe("upgrade from segment ordering", () => { + /** A pendingStart as an older version wrote it: a 100ms bucket, no runAt. */ + async function enqueueLegacyWork(runAt: number): Promise> { + return t.run(async (ctx) => { + const workId = await ctx.db.insert("work", { + fnType: "action", + fnHandle: "test_handle", + fnName: "test_handle", + fnArgs: {}, + attempts: 0, + }); + await ctx.db.insert("pendingStart", { + workId, + // max(toSegment(runAt), now), as `enqueue` used to compute it. + segment: toSegment(Math.max(runAt, Date.now())), + }); + return workId; + }); + } + + it("recovers legacy entries below all three persisted cursors", async () => { + await initialize(); + const completedId = await enqueueWork(); + await runLoop(); + await simulateCompletion(completedId, { + kind: "success", + returnValue: null, + }); + const readyId = await enqueueLegacyWork(Date.now()); + const canceledId = await enqueueLegacyWork(Date.now()); + const runAt = Date.now() + 100 * SECOND; + const futureId = await enqueueLegacyWork(runAt); + await t.run(async (ctx) => { + const state = (await ctx.db.query("internalState").unique())!; + const cursor = toSegment(runAt + SECOND); + await ctx.db.patch("internalState", state._id, { + segmentCursors: { + incoming: cursor, + completion: cursor, + cancelation: cursor, + }, + }); + const completion = (await ctx.db.query("pendingCompletion").unique())!; + await ctx.db.patch("pendingCompletion", completion._id, { + segment: toSegment(Date.now()), + }); + await ctx.db.insert("pendingCancelation", { + workId: canceledId, + segment: toSegment(Date.now()), + }); + }); + + await runLoop(); + await runLoop(); + const o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([readyId]); + expect(o.pendingCompletion).toHaveLength(0); + expect(o.pendingCancelation).toHaveLength(0); + expect(o.pendingStart).toHaveLength(1); + expect(o.pendingStart[0].workId).toBe(futureId); + expect(o.pendingStart[0].segment).toBe( + toTimestamp(fromSegment(toSegment(runAt))), + ); + expect(o.segmentCursors!.sweep).toBeDefined(); + }); + + it.each([true, false])( + "upgrades multiple batches while paused (existing state: %s)", + async (existingState) => { + await initialize({ maxParallelism: 0 }); + await t.run(async (ctx) => { + const state = (await ctx.db.query("internalState").unique())!; + if (existingState) { + await ctx.db.patch("internalState", state._id, { + segmentCursors: { + incoming: toSegment(Date.now()), + completion: 0n, + cancelation: 0n, + }, + }); + } else { + await ctx.db.delete("internalState", state._id); + } + }); + const ids: Id<"work">[] = []; + for (let i = 0; i < 70; i++) + ids.push(await enqueueLegacyWork(Date.now() + 60_000)); + await runLoop(); + expect((await observe()).segmentCursors!.sweep).toBeUndefined(); + await runLoop(); + const o = await observe(); + expect(o.segmentCursors!.sweep).toBe(0n); + expect(o.pendingStart).toHaveLength(70); + expect(o.running).toHaveLength(0); + await t.run(async (ctx) => { + for (const id of ids) { + const work = (await ctx.db.get("work", id))!; + expect(work.pendingStartId).toBeDefined(); + expect( + await ctx.db.get("pendingStart", work.pendingStartId!), + ).not.toBeNull(); + } + }); + expect((await runLoop()).kind).toBe("idle"); + }, + ); + + it("starts work that was already due", async () => { + await initialize(); + const workId = await enqueueLegacyWork(Date.now()); + + await runLoop(); + + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + expect(await statusOf(workId)).toMatchObject({ state: "running" }); + }); + + it("keeps holding work scheduled for later, rather than starting it early", async () => { + await initialize(); + const runAt = Date.now() + 100 * SECOND; + const workId = await enqueueLegacyWork(runAt); + // The old format only recorded the time to a 100ms bucket. + const startsAt = fromSegment(toSegment(runAt)); + + await runLoop(); + + // Not started — and rewritten as a real timestamp, so the next scan + // leaves it alone until it's due. + let o = await observe(); + expect(o.running).toHaveLength(0); + expect(o.pendingStart[0].segment).toBe(toTimestamp(startsAt)); + + await runLoop(); // the sweep verifies the re-keyed entry, once + const idle = await runLoop(); + assert(idle.kind === "idle"); + expect(idle.timeoutMs).toBe(startsAt - Date.now()); + + vi.setSystemTime(startsAt); + await runLoop(); + o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + }); + + it("reports work that predates the pendingStartId pointer as pending", async () => { + await initialize(); + const workId = await enqueueLegacyWork(Date.now() + 100 * SECOND); + expect(await statusOf(workId)).toMatchObject({ state: "pending" }); + }); + + it("drops the entry of canceled work that predates the pendingStartId pointer", async () => { + await initialize(); + const runAt = Date.now() + 100 * SECOND; + const workId = await enqueueLegacyWork(runAt); + await runLoop(); // re-keys it to its start time + await runLoop(); // the sweep verifies the re-keyed entry + + await t.mutation(api.lib.cancel, { id: workId }); + await runLoop(); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running).toHaveLength(0); + }); + }); + + describe("capacity", () => { it("does not start new work when running.length already exceeds maxParallelism", async () => { // Edge case: maxParallelism was lowered while jobs were running. await initialize({ maxParallelism: 2 }); @@ -397,6 +606,30 @@ describe("loop", () => { }); }); + it("starts the retry once its backoff elapses, and advances past it", async () => { + await initialize(); + const workId = await enqueueWork({ + retryBehavior: { maxAttempts: 3, initialBackoffMs: 100, base: 2 }, + }); + await runLoop(); + await simulateCompletion(workId, { kind: "failed", error: "boom" }, 0); + await runLoop(); + await runLoop(); // the sweep verifies the retry's entry, once + + // Still held back by the backoff: nothing to start yet. + expect((await runLoop()).kind).toBe("idle"); + expect((await observe()).pendingStart).toHaveLength(1); + + // Once the backoff elapses it starts from the not-yet-due lane, and the + // lane's cursor moves past it so its tombstone isn't rescanned. + vi.setSystemTime(Date.now() + SECOND); + await runLoop(); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + expect(o.segmentCursors?.incoming).toBeGreaterThan(0n); + }); + it("does NOT re-enqueue a failed job that was canceled before retry processed", async () => { await initialize(); const workId = await enqueueWork({ @@ -530,10 +763,12 @@ describe("loop", () => { expect(result.batch.recovery).toBe(false); }); - it("idles with a timeoutMs when only future-scheduled work remains", async () => { + it("idles with a timeoutMs when only far-future work remains", async () => { await initialize(); - const future = getCurrentSegment() + 1000n; // 100s out - await enqueueWork({}, future); + // Ordered by its start time, so beyond the sweep's one-time + // verification the loop never has to look at it. + await enqueueWork({}, { runAt: Date.now() + 10 * MINUTE }); + await runLoop(); // the sweep verifies the entry, once const result = await t.query(internal.loop.getBatch, { name: WORKER_NAME, @@ -542,13 +777,45 @@ describe("loop", () => { expect(result.timeoutMs).toBeGreaterThan(0); }); + it("sweeps near-future work once, then idles until it's due", async () => { + await initialize(); + const runAt = Date.now() + 100 * SECOND; + // Keyed at its start time directly; the sweep just verifies its enqueue + // committed in order, once, and never rewrites it. + const workId = await enqueueWork({}, { runAt }); + + const first = await runLoop(); + assert(first.kind === "work"); + expect(first.batch.starts).toHaveLength(0); + expect(first.batch.sweepStarts).toHaveLength(0); + expect(first.batch.sweepStop).toBeDefined(); + + let o = await observe(); + expect(o.running).toHaveLength(0); + expect(o.pendingStart[0].segment).toBe(toTimestamp(runAt)); + // The sweep cursor covers its commit stamp now. + expect(o.segmentCursors!.sweep).toBe(o.pendingStart[0].scanTs as bigint); + + const second = await runLoop(); + assert(second.kind === "idle"); + expect(second.timeoutMs).toBe(100 * SECOND); + + // It starts when it comes due, untouched in the meantime. + vi.setSystemTime(runAt); + await runLoop(); + o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + }); + it("idles with a timeoutMs for the next recovery scan when that's sooner than future work", async () => { await initialize(); await enqueueWork(); await runLoop(); // start it: running=1, lastRecovery=now // Future work well past the ~1min recovery period. - await enqueueWork({}, getCurrentSegment() + toSegment(5 * MINUTE)); + await enqueueWork({}, { runAt: Date.now() + 10 * MINUTE }); + await runLoop(); // the sweep verifies the entry, once const result = await t.query(internal.loop.getBatch, { name: WORKER_NAME, @@ -556,12 +823,248 @@ describe("loop", () => { assert(result.kind === "idle"); const { lastRecovery } = await observe(); const untilNextRecovery = - fromSegment(lastRecovery + RECOVERY_PERIOD_SEGMENTS) - Date.now(); + fromTimestamp(lastRecovery + RECOVERY_PERIOD_NS) - Date.now(); expect(result.timeoutMs).toBe(untilNextRecovery); expect(result.timeoutMs).toBeLessThan(5 * MINUTE); }); }); + // ──────────────────────────────────────────────────────────────────── + // Scheduled work: keyed at its start time, invisible until due + // ──────────────────────────────────────────────────────────────────── + + describe("scheduled work", () => { + it("never lets a scheduled backlog sit in front of ready work", async () => { + // A bulk enqueue of near-future work sorts above the eligibility bound, + // so it costs the ready item below nothing — no re-keying, no waiting. + await initialize({ maxParallelism: 3 }); + const runAt = Date.now() + 100 * SECOND; + for (let i = 0; i < 70; i++) await enqueueWork({}, { runAt }); + const readyId = await enqueueWork(); + + await runLoop(); + + const o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([readyId]); + expect(o.pendingStart).toHaveLength(70); + for (const p of o.pendingStart) { + expect(p.segment).toBe(toTimestamp(runAt)); + expect(p.scanTs).toBeDefined(); + } + // The sweep verified all 70 in one pass; nothing left to do before the + // sooner of their due time and the next stuck-job recovery check. + const idle = await runLoop(); + assert(idle.kind === "idle"); + expect(idle.timeoutMs).toBeLessThanOrEqual(100 * SECOND); + }); + + it("starts due scheduled work and ready work in eligibility order", async () => { + await initialize({ maxParallelism: 1 }); + const scheduledId = await enqueueWork({}, { runAt: Date.now() + SECOND }); + const readyId = await enqueueWork(); + vi.setSystemTime(Date.now() + SECOND); + + // The ready item became eligible first: its commit precedes the runAt. + await runLoop(); + let o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([readyId]); + + await simulateCompletion( + readyId, + { kind: "success", returnValue: null }, + 0, + ); + await runLoop(); + o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([scheduledId]); + }); + + it("starts scheduled work once it's due, without ever rewriting it", async () => { + await initialize(); + const workId = await enqueueWork({}, { runAt: Date.now() + SECOND }); + + vi.setSystemTime(Date.now() + SECOND); + await runLoop(); + + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + }); + + it("holds due work while saturated, and starts it as capacity frees", async () => { + await initialize({ maxParallelism: 1 }); + const firstId = await enqueueWork(); + await runLoop(); // fills the only slot + const dueId = await enqueueWork({}, { runAt: Date.now() + SECOND }); + vi.setSystemTime(Date.now() + 2 * SECOND); + + await runLoop(); // the sweep verifies the new entry, once + const idle = await runLoop(); + expect(idle.kind).toBe("idle"); // saturated: nothing can start + expect((await observe()).pendingStart).toHaveLength(1); + + // A completion frees the slot; the same iteration starts the work. + await simulateCompletion( + firstId, + { kind: "success", returnValue: null }, + 0, + ); + await runLoop(); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([dueId]); + }); + }); + + // ──────────────────────────────────────────────────────────────────── + // The out-of-order sweep: entries whose enqueue lost the race + // ──────────────────────────────────────────────────────────────────── + + describe("out-of-order sweep", () => { + /** + * A near-future enqueue whose commit took longer than its delay: the + * entry appears with a `segment` the cursor already passed, where the + * segment scan will never see it. Its `scanTs` commit stamp is how the + * sweep finds it. + */ + async function enqueueBehindCursor(cursor: bigint): Promise> { + return t.run(async (ctx) => { + const workId = await ctx.db.insert("work", { + fnType: "action", + fnHandle: "test_handle", + fnName: "test_handle", + fnArgs: {}, + attempts: 0, + }); + const pendingStartId = await ctx.db.insert("pendingStart", { + workId, + segment: cursor - 1n, + scanTs: ctx.db.vars.commitTs, + }); + await ctx.db.patch("work", workId, { pendingStartId }); + return workId; + }); + } + + it("starts an entry whose enqueue lost the race with the cursor", async () => { + await initialize({ maxParallelism: 2 }); + // Run something so the incoming cursor is somewhere real. + const readyId = await enqueueWork(); + await runLoop(); + const cursor = (await observe()).segmentCursors!.incoming; + expect(cursor).toBeGreaterThan(0n); + + const lostId = await enqueueBehindCursor(cursor); + + await runLoop(); + const o = await observe(); + expect(o.running.map((r) => r.workId)).toContain(lostId); + expect(o.pendingStart).toHaveLength(0); + // Its commit stamp is covered, so the sweep never re-reads it. + expect(o.segmentCursors!.sweep).toBeGreaterThan(0n); + expect(readyId).toBeDefined(); + }); + + it("waits for capacity to retire an out-of-order entry, without losing it", async () => { + await initialize({ maxParallelism: 1 }); + const firstId = await enqueueWork(); + await runLoop(); // fills the only slot + const cursor = (await observe()).segmentCursors!.incoming; + const lostId = await enqueueBehindCursor(cursor); + + // Saturated: the entry can't start, so the sweep leaves its stamp + // uncovered rather than passing it. + const idle = await runLoop(); + expect(idle.kind).toBe("idle"); + expect((await observe()).pendingStart.map((p) => p.workId)).toEqual([ + lostId, + ]); + + await simulateCompletion( + firstId, + { kind: "success", returnValue: null }, + 0, + ); + await runLoop(); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toEqual([lostId]); + }); + + it("caps the cursor at the snapshot when starting wall-keyed work", async () => { + await initialize(); + const runAt = Date.now() + SECOND; + const workId = await enqueueWork({}, { runAt }); + await runLoop(); // sweep verifies the entry + // Nothing commits between here and the read, so the snapshot stays + // below the key while the wall clock says it's due. + vi.setSystemTime(runAt); + await runLoop(); + + let o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + // The cursor stops at the snapshot, not the wall-clock key: a commit + // racing this iteration could land between the two. + expect(o.segmentCursors!.incoming).toBeLessThanOrEqual( + toTimestamp(runAt), + ); + + // Work committing after that snapshot is still found. + const laterId = await enqueueWork(); + await runLoop(); + o = await observe(); + expect(o.running.map((r) => r.workId)).toContain(laterId); + }); + }); + + // ──────────────────────────────────────────────────────────────────── + // Cursor invariant: an entry is never left behind the cursor + // + // Loop-written keys stay at or above the snapshot, which caps the cursor. + // ──────────────────────────────────────────────────────────────────── + + describe("cursor invariant", () => { + it("starts a retry whose backoff is shorter than the cursor's resolution", async () => { + await initialize(); + const workId = await enqueueWork({ + retryBehavior: { maxAttempts: 3, initialBackoffMs: 0, base: 2 }, + }); + await runLoop(); + await simulateCompletion(workId, { kind: "failed", error: "boom" }, 0); + // A ready entry enqueued after the completion sorts above a wall-clock + // retry key, so a cursor advancing to it would strand the retry. + const laterId = await enqueueWork(); + + await runLoop(); + let o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([laterId]); + const retry = o.pendingStart.find((p) => p.workId === workId); + assert(retry); + // Raised to the snapshot instead, so it's eligible next iteration. + expect(retry.segment).toBeGreaterThanOrEqual(o.segmentCursors!.incoming); + await runLoop(); + o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running.map((r) => r.workId)).toContain(workId); + }); + + it("keeps a sub-millisecond runAt exact and starts it within a millisecond", async () => { + await initialize(); + const runAt = Date.now() + 0.5; + const workId = await enqueueWork({}, { runAt }); + const entry = (await observe()).pendingStart.find( + (p) => p.workId === workId, + ); + assert(entry); + expect(entry.segment).toBe(toTimestamp(runAt)); + + vi.setSystemTime(Date.now() + 1); + await runLoop(); + expect((await observe()).running.map((r) => r.workId)).toEqual([workId]); + }); + }); + // ──────────────────────────────────────────────────────────────────── // Recovery: stuck running jobs get cleaned up // ──────────────────────────────────────────────────────────────────── diff --git a/src/component/loop.ts b/src/component/loop.ts index e446b295..62614cc8 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -20,46 +20,42 @@ import { import { type Config, DEFAULT_MAX_PARALLELISM, - fromSegment, - getCurrentSegment, + eligibilityBound, + fromTimestamp, + legacyRunAt, + maxBigint, MINUTE, + MIN_TIMESTAMP, SECOND, - type RunResult, - toSegment, + snapshotTs, + toTimestamp, vResult, } from "./shared.js"; import { generateReport, recordCompleted, recordStarted } from "./stats.js"; +import { assert } from "convex-helpers"; +import { findPendingStart } from "./pendingStart.js"; const CANCELLATION_BATCH_SIZE = 64; // the only queue that can get unbounded. const RECOVERY_BATCH_SIZE = 32; const START_BATCH_SIZE = 32; -// Cap per-iteration completions + starts. Larger batches push per-iteration -// latency up without buying throughput: the loop re-fires immediately while -// it's draining, so smaller cheaper iterations carry the same work in aggregate. +// Bound per-iteration work to keep loop latency low. const MAIN_BATCH_SIZE = 64; const RECOVERY_THRESHOLD_MS = 5 * MINUTE; // attempt to recover jobs this old. -export const RECOVERY_PERIOD_SEGMENTS = toSegment(1 * MINUTE); // how often to check. -// While the queue is idle we keep the loop warm for this long (measured from -// when it last saw work) so a trickle of new work doesn't thrash the run -// status, re-polling this often during that window — preserving the old loop's -// cooldown behavior, now expressed via batch-worker's idle hints. +export const RECOVERY_PERIOD_NS = toTimestamp(MINUTE); // how often to check. +// Keep an idle loop warm briefly to avoid status churn under light traffic. export const STATUS_COOLDOWN = 2 * SECOND; // At full capacity, keep batch-worker's status stable longer so enqueue pings // generally observe `running` and no-op instead of racing an idle transition. export const SATURATED_STATUS_COOLDOWN = 10 * SECOND; export const COOLDOWN_CHECK_INTERVAL = 200; -// Buffer applied when querying with cursors. Transactions that started -// before ours may still be running and commit inserts at segments behind -// a previously advanced cursor — the buffer lets us pick those up. Most -// commits land within milliseconds, so a small buffer covers nearly all -// of them. The minute-cadence recovery iteration scans from segment 0 -// (the start of each pending table) to catch any very-late commit that -// fell behind even this buffer. -const CURSOR_BUFFER_SEGMENTS = toSegment(15 * SECOND); export const INITIAL_STATE: WithoutSystemFields> = { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, lastRecovery: 0n, report: { completed: 0, @@ -72,14 +68,7 @@ export const INITIAL_STATE: WithoutSystemFields> = { running: [], }; -// ── The work query / worker mutation contract with batch-worker ──────────── -// `getBatch` (the work query) decides whether there's work to do and, if so, -// hands a `batch` to `run` (the worker mutation). batch-worker drives the -// loop: it runs `getBatch`, runs `run` with the batch, re-runs to drain, and -// sleeps/idles per the hints `getBatch` returns. batch-worker also owns the -// generation guard (one loop chain at a time) and the liveness monitor that -// restarts the loop if it dies — so this module no longer schedules or -// recovers itself. +// batch-worker owns loop scheduling, generation checks, and liveness recovery. const vCompletion = v.object({ _id: v.id("pendingCompletion"), @@ -101,118 +90,126 @@ const vStart = v.object({ _id: v.id("pendingStart"), workId: v.id("work"), segment: v.int64(), + // Decoded from a legacy 100ms bucket; not stored. + legacyStartTime: v.optional(v.number()), }); type Start = Infer; -/** The shape `getBatch` hands to `run`. */ +// batch-worker calls getBatch and run in one transaction, sharing a snapshot. const batchFields = { - // The segment at query time — what "now" was when the batch was built. - segment: v.int64(), + upgrade: v.optional(v.object({ starts: v.array(vStart), done: v.boolean() })), // Whether this iteration should run the periodic work-recovery scan. recovery: v.boolean(), completions: v.array(vCompletion), cancelations: v.array(vCancelation), starts: v.array(vStart), + // Due entries behind the incoming cursor, and the last inspected scanTs. + sweepStarts: v.array(vStart), + sweepStop: v.optional(v.int64()), }; type Batch = Infer>>; -/** - * The work query (batch-worker contract). Decides whether there's work to do, - * and hands `run` a batch when there is. When there's nothing to do, returns - * `idle` with hints for when to look again (next future start / next recovery - * scan), plus a short cooldown so a trickle of work doesn't thrash the loop. - * - * batch-worker runs this as a snapshot read while draining and re-reads it with - * a real dependency before going idle, so we just read the tables directly. - */ +/** Return a batch or idle hints. batch-worker confirms idle with a tracked read. */ export const getBatch = internalQuery({ args: { name: v.string() }, returns: vBatchResult(v.object(batchFields)), handler: async (ctx): Promise> => { const globals = await getGlobals(ctx); - const state = await ctx.db.query("internalState").unique(); + const state = await ctx.db.query("internalState").order("desc").first(); + if (state?.segmentCursors.sweep === undefined) { + const docs = await ctx.db + .query("pendingStart") + .withIndex("segment", (q) => q.lt("segment", MIN_TIMESTAMP)) + .take(MAIN_BATCH_SIZE); + if (state || docs.length > 0) + return { + kind: "work", + batch: { + recovery: false, + completions: [], + cancelations: [], + starts: [], + sweepStarts: [], + upgrade: { + starts: docs.map((doc) => ({ + _id: doc._id, + workId: doc.workId, + segment: doc.segment as bigint, + legacyStartTime: legacyRunAt(doc.segment as bigint), + })), + done: docs.length < MAIN_BATCH_SIZE, + }, + }, + }; + } const running = state?.running ?? INITIAL_STATE.running; const cursors = state?.segmentCursors ?? INITIAL_STATE.segmentCursors; const lastRecovery = state?.lastRecovery ?? INITIAL_STATE.lastRecovery; - const segment = getCurrentSegment(); + const nowTs = toTimestamp(Date.now()); - // Once per recovery period (≈1min), scan from segment 0 to catch any - // very-late commit that fell behind the cursor buffer, and to recover any - // stuck running jobs. Otherwise scan from the cursors (minus a buffer for - // out-of-order inserts that landed behind the cursor since the last scan). + // Periodically recover stuck workers; pending queues use their own cursors. const isRecoveryIter = - running.length > 0 && segment - lastRecovery >= RECOVERY_PERIOD_SEGMENTS; - const queryArgs = isRecoveryIter - ? { - completionCursor: 0n, - cancelationCursor: 0n, - incomingCursor: 0n, - maxParallelism: globals.maxParallelism, - runningCount: running.length, - } - : { - completionCursor: cursors.completion - CURSOR_BUFFER_SEGMENTS, - cancelationCursor: cursors.cancelation - CURSOR_BUFFER_SEGMENTS, - incomingCursor: cursors.incoming - CURSOR_BUFFER_SEGMENTS, - maxParallelism: globals.maxParallelism, - runningCount: running.length, - }; - - const { allStarts, cancelations, completions } = await queryPending( - ctx, - queryArgs, - ); - const starts = allStarts.filter((s) => s.segment <= segment); - + running.length > 0 && nowTs - lastRecovery >= RECOVERY_PERIOD_NS; + + const { starts, sweepStarts, sweepStop, cancelations, completions } = + await queryPending(ctx, { + completionCursor: cursors.completion, + cancelationCursor: cursors.cancelation, + incomingCursor: cursors.incoming, + sweepCursor: cursors.sweep ?? 0n, + maxParallelism: globals.maxParallelism, + runningCount: running.length, + }); + + // The sweep counts as work when it found entries to start or moved past + // new documents; re-verifying the live documents at its inclusive + // boundary is not progress and must not keep the loop awake. const hasWork = completions.length > 0 || cancelations.length > 0 || starts.length > 0 || + sweepStarts.length > 0 || + (sweepStop !== undefined && sweepStop > (cursors.sweep ?? 0n)) || isRecoveryIter; if (hasWork) { const batch: Batch = { - segment, recovery: isRecoveryIter, completions: completions.map((c) => ({ _id: c._id, workId: c.workId, runResult: c.runResult, retry: c.retry, - segment: c.segment, + segment: c.segment as bigint, })), cancelations: cancelations.map((c) => ({ _id: c._id, workId: c.workId, - segment: c.segment, - })), - starts: starts.map((s) => ({ - _id: s._id, - workId: s.workId, - segment: s.segment, + segment: c.segment as bigint, })), + starts, + sweepStarts, + sweepStop, }; return { kind: "work" as const, batch }; } - // Nothing to do now. Figure out when to wake up next: the sooner of the - // earliest future-scheduled start and (if jobs are running) the next - // recovery scan. A ping still wakes us sooner. - const futureStart = allStarts.find((s) => s.segment > segment); + // Wake for the next scheduled start or recovery scan. Enqueues and + // completions can wake us sooner, including when all slots are occupied. + const futureStart = await ctx.db + .query("pendingStart") + .withIndex("segment", (q) => q.gt("segment", eligibilityBound())) + .first(); const waits: number[] = []; if (futureStart) { - waits.push(fromSegment(futureStart.segment) - Date.now()); + waits.push(fromTimestamp(futureStart.segment as bigint) - Date.now()); } if (running.length > 0) { - const nextRecovery = lastRecovery + RECOVERY_PERIOD_SEGMENTS; - waits.push(fromSegment(nextRecovery) - Date.now()); + const nextRecovery = lastRecovery + RECOVERY_PERIOD_NS; + waits.push(fromTimestamp(nextRecovery) - Date.now()); } const timeoutMs = waits.length > 0 ? Math.max(0, Math.min(...waits)) : undefined; - // Go (interruptibly) idle after the short cooldown. batch-worker confirms - // with a real read before going idle, and every enqueue/complete/cancel - // pings us to wake a waiting loop promptly. `timeoutMs` is a backstop for - // future-scheduled work and the periodic recovery scan. return { kind: "idle" as const, cooldownMs: @@ -225,20 +222,36 @@ export const getBatch = internalQuery({ }, }); -/** - * The worker mutation (batch-worker contract). Processes one batch from - * `getBatch`: applies completions, cancelations, the periodic recovery scan, - * and starts new work — then advances the cursors and persists state. - * Returning `null` tells batch-worker to re-run immediately to keep draining. - */ +/** Process a batch and persist its cursors. Returning null keeps draining. */ export const run = internalMutation({ args: batchFields, returns: v.null(), handler: async (ctx, batch) => { const state = await getOrCreateState(ctx); + if (batch.upgrade) { + // Repair old pointers and keys once, before normal cursors can pass them. + const snapshot = snapshotTs(); + for (const start of batch.upgrade.starts) { + const work = await ctx.db.get("work", start.workId); + if (!work) { + await ctx.db.delete("pendingStart", start._id); + continue; + } + await ctx.db.patch("work", work._id, { pendingStartId: start._id }); + await ctx.db.patch("pendingStart", start._id, { + segment: maxBigint(toTimestamp(start.legacyStartTime!), snapshot), + }); + } + await ctx.db.patch("internalState", state._id, { + segmentCursors: batch.upgrade.done + ? { ...INITIAL_STATE.segmentCursors } + : { ...state.segmentCursors, sweep: undefined }, + }); + return null; + } const globals = await getGlobals(ctx); const console = createLogger(globals.logLevel); - const segment = getCurrentSegment(); + const nowTs = toTimestamp(Date.now()); const compLabel = `[main] pendingCompletion(${batch.completions.length})`; console.time(compLabel); @@ -257,22 +270,43 @@ export const run = internalMutation({ if (state.running.length === 0) { // If there's nothing active, reset lastRecovery. - state.lastRecovery = segment; + state.lastRecovery = nowTs; } else if (batch.recovery) { // Otherwise schedule recovery for any old jobs. const recoveryLabel = `[main] recovery(${state.running.length})`; console.time(recoveryLabel); await handleRecovery(ctx, state, console); console.timeEnd(recoveryLabel); - state.lastRecovery = segment; + state.lastRecovery = nowTs; + } + + // Modern entries are due by either clock. Legacy buckets can still + // represent future work, which must be re-keyed before advancing. + const now = Date.now(); + const isDue = (s: Start) => + s.legacyStartTime === undefined || s.legacyStartTime <= now; + const all = [...batch.starts, ...batch.sweepStarts]; + const notYet = all.filter((s) => !isDue(s)); + // Oldest first: `segment` is when an entry became eligible, and a swept + // entry has been eligible since its (past) start time. + const eligible = all + .filter(isDue) + .sort( + (a, b) => + (a.legacyStartTime ?? fromTimestamp(a.segment)) - + (b.legacyStartTime ?? fromTimestamp(b.segment)), + ); + if (notYet.length > 0) { + const promoteLabel = `[main] promote(${notYet.length})`; + console.time(promoteLabel); + await promoteScheduled(ctx, notYet); + console.timeEnd(promoteLabel); } - // ── Start new work ── // Slice to actual available capacity (completions may have freed slots). // Guard against negative numbers in case running.length > maxParallelism. const actualCapacity = globals.maxParallelism - state.running.length; - const pending = - actualCapacity > 0 ? batch.starts.slice(0, actualCapacity) : []; + const pending = actualCapacity > 0 ? eligible.slice(0, actualCapacity) : []; const startLabel = `[main] pendingStart(${pending.length})`; console.time(startLabel); await handleStart(ctx, state, pending, console, globals); @@ -301,27 +335,42 @@ export const run = internalMutation({ } // Advance cursors to skip tombstones on next scan, but only for the - // queues we actually drained this iteration. + // queues we actually drained this iteration. The batches came back in + // commit order, so the last entry is the furthest we read. if (batch.completions.length > 0) { state.segmentCursors.completion = batch.completions.at(-1)!.segment; } if (batch.cancelations.length > 0) { state.segmentCursors.cancelation = batch.cancelations.at(-1)!.segment; } - if (pending.length > 0) { - state.segmentCursors.incoming = pending.at(-1)!.segment; - } else if (actualCapacity > 0 && batch.starts.length === 0) { - // No more pending work to start and we had capacity — advance to now. - state.segmentCursors.incoming = segment; + // Advance only across handled entries, capped at the snapshot so racing + // commits remain ahead. Inclusive reads retain entries sharing a timestamp. + const handled = new Set([...pending, ...notYet].map((s) => s._id)); + const snapshot = snapshotTs(); + for (const start of batch.starts) { + if (!handled.has(start._id)) break; + state.segmentCursors.incoming = + start.segment < snapshot ? start.segment : snapshot; + } + // Advance the sweep only after handling every entry it selected. + // Entries left at the boundary stamp are revisited by an inclusive read. + if ( + batch.sweepStop !== undefined && + batch.sweepStarts.every((s) => handled.has(s._id)) + ) { + state.segmentCursors.sweep = maxBigint( + state.segmentCursors.sweep ?? 0n, + batch.sweepStop, + ); } - await ctx.db.replace("internalState", state._id, state); - // Return null: batch-worker re-runs `getBatch` immediately to drain, and - // idles (per getBatch's hints) once there's nothing left. return null; }, }); +// Bound sweep reads per iteration. +const SWEEP_DOC_BATCH = 256; + /** Read the three pending tables the loop processes. */ async function queryPending( ctx: QueryCtx, @@ -329,12 +378,14 @@ async function queryPending( completionCursor, cancelationCursor, incomingCursor, + sweepCursor, maxParallelism, runningCount, }: { completionCursor: bigint; cancelationCursor: bigint; incomingCursor: bigint; + sweepCursor: bigint; maxParallelism: number; runningCount: number; }, @@ -347,30 +398,96 @@ async function queryPending( .query("pendingCancelation") .withIndex("segment", (q) => q.gte("segment", cancelationCursor)) .take(CANCELLATION_BATCH_SIZE); - // Available slots after we process this batch's completions, plus 1 - // for the +1 trick (detect overflow vs. a future-scheduled retry). - // Cap at MAIN_BATCH_SIZE so a single iteration's per-item writes - // (delete pendingStart + scheduler.runAfter) don't grow unbounded. + // Available slots after we process this batch's completions. Cap at + // MAIN_BATCH_SIZE so a single iteration's per-item writes (delete + // pendingStart + scheduler.runAfter) don't grow unbounded. const startLimit = Math.min( MAIN_BATCH_SIZE, Math.max(0, maxParallelism - runningCount + completions.length), ); - const excludedIds = [ + // Work completing or canceling this iteration is skipped when reading; the + // same iteration removes those entries, so the cursors may pass them. + const excluded = new Set([ ...completions.map((c) => c.workId), ...cancelations.map((c) => c.workId), - ]; - const allStarts = - startLimit === 0 - ? [] - : await ctx.db - .query("pendingStart") - .withIndex("segment", (q) => q.gte("segment", incomingCursor)) - // eslint-disable-next-line @convex-dev/no-filter-in-query - .filter((q) => - q.and(...excludedIds.map((id) => q.neq(q.field("workId"), id))), - ) - .take(startLimit + 1); - return { completions, cancelations, allStarts }; + ]); + + // Rescue scheduled entries that committed behind the incoming cursor. + // Revisit only that subset at the boundary scanTs, then inspect later stamps. + // The compound index sorts behind-cursor entries first within each stamp, + // so stopping midway is safe and future entries need not be rescanned. + const sweepStarts: Start[] = []; + let sweepStop: bigint | undefined; + { + let docs = 0; + const take = (doc: Doc<"pendingStart">): "more" | "stop" => { + const segment = doc.segment as bigint; + if (!excluded.has(doc.workId)) { + if (sweepStarts.length >= startLimit) return "stop"; + sweepStarts.push({ _id: doc._id, workId: doc.workId, segment }); + } + return ++docs >= SWEEP_DOC_BATCH ? "stop" : "more"; + }; + + // (1) Out-of-order entries left at the boundary stamp. Nothing at or above + // the cursor is read, so a bulk enqueue sharing this stamp costs nothing. + let boundaryDone = true; + for await (const doc of ctx.db + .query("pendingStart") + .withIndex("scanTs", (q) => + q.eq("scanTs", sweepCursor).lt("segment", incomingCursor), + )) { + if (take(doc) === "stop") { + boundaryDone = false; + break; + } + } + + // (2) Later stamps. Reaching one is what lets the cursor move off the + // boundary; until then it stays put and (1) repeats, which is cheap. + if (boundaryDone) { + for await (const doc of ctx.db + .query("pendingStart") + .withIndex("scanTs", (q) => q.gt("scanTs", sweepCursor))) { + const scanTs = doc.scanTs as bigint; + const behind = (doc.segment as bigint) < incomingCursor; + // Not behind: the segment scan owns it. Pass over it so the cursor can + // advance, without reading its entries. + if (behind && take(doc) === "stop") break; + sweepStop = scanTs; + if (!behind && ++docs >= SWEEP_DOC_BATCH) break; + } + } + } + + // Entries the sweep starts take slots first; only fetch ready work for the + // slots left over. Everything eligible, oldest first. Inclusive reads retain + // entries sharing a timestamp when capacity cuts a batch short. + const readyLimit = Math.max(0, startLimit - sweepStarts.length); + const starts: Start[] = []; + if (readyLimit > 0) { + const stream = ctx.db + .query("pendingStart") + .withIndex("segment", (q) => + q.gte("segment", incomingCursor).lte("segment", eligibilityBound()), + ); + for await (const doc of stream) { + const segment = doc.segment as bigint; + // A document from before commit-timestamp ordering keeps its start time + // in `segment`; recovering it here means `run` handles it like any + // other not-yet-due entry and re-keys it as a timestamp. + const legacyStartTime = legacyRunAt(segment); + if (excluded.has(doc.workId)) continue; + if (starts.length >= readyLimit) break; + starts.push({ + _id: doc._id, + workId: doc.workId, + segment, + legacyStartTime, + }); + } + } + return { completions, cancelations, starts, sweepStarts, sweepStop }; } /** @@ -403,8 +520,7 @@ async function handleCompletions( console.warn(`[main] ${c.workId} is gone, but trying to complete`); return; } - const retried = await rescheduleJob(ctx, work, console); - if (retried) { + if (await rescheduleJob(ctx, work, console)) { state.report.retries++; recordCompleted(console, work, "retrying", undefined); } else { @@ -449,43 +565,34 @@ async function handleCancelation( if (canceled.length) { console.debug(`[main] attempting to cancel ${canceled.length}`); } - const canceledWork: Set> = new Set(); - const runResult: RunResult = { kind: "canceled" }; - const jobs = toCancel.concat( - ...( - await Promise.all( - canceled.map(async ({ _id, workId }) => { - if (!(await ctx.db.get("pendingCancelation", _id))) { - return null; - } - await ctx.db.delete("pendingCancelation", _id); - if (canceledWork.has(workId)) { - // We shouldn't have multiple pending cancelations for the same work. - console.error(`[main] ${workId} already canceled`); - return null; - } - const work = await ctx.db.get("work", workId); - if (!work) { - console.warn(`[main] ${workId} is gone, but trying to cancel`); - return null; - } - // Ensure it doesn't retry. - await ctx.db.patch("work", workId, { canceled: true }); - // Ensure it doesn't start. - const pendingStart = await ctx.db - .query("pendingStart") - .withIndex("workId", (q) => q.eq("workId", workId)) - .unique(); - if (pendingStart && !canceledWork.has(workId)) { - state.report.canceled++; - await ctx.db.delete("pendingStart", pendingStart._id); - canceledWork.add(workId); - return { workId, runResult, attempt: work.attempts }; - } - return null; - }), - ) - ).flatMap((r) => (r ? [r] : [])), + const canceledWork = new Set>(); + const jobs: CompleteJob[] = [...toCancel]; + await Promise.all( + canceled.map(async ({ _id, workId }) => { + if (!(await ctx.db.get("pendingCancelation", _id))) return; + await ctx.db.delete("pendingCancelation", _id); + if (canceledWork.has(workId)) { + console.error(`[main] ${workId} already canceled`); + return; + } + canceledWork.add(workId); + const work = await ctx.db.get("work", workId); + if (!work) { + console.warn(`[main] ${workId} is gone, but trying to cancel`); + return; + } + // Prevent retries even if the work is already running. + await ctx.db.patch("work", workId, { canceled: true }); + const pendingStart = await findPendingStart(ctx, work); + if (!pendingStart) return; + await ctx.db.delete("pendingStart", pendingStart._id); + state.report.canceled++; + jobs.push({ + workId, + runResult: { kind: "canceled" }, + attempt: work.attempts, + }); + }), ); if (jobs.length) { await ctx.scheduler.runAfter(0, internal.complete.complete, { jobs }); @@ -534,9 +641,25 @@ async function handleRecovery( } } -/** - * Starts pending work. - */ +/** Convert future legacy buckets to timestamps at or above this snapshot. */ +async function promoteScheduled(ctx: MutationCtx, notYet: Start[]) { + const snapshot = snapshotTs(); + await Promise.all( + notYet.map(async ({ _id, workId, legacyStartTime }) => { + assert(legacyStartTime); + if (!(await ctx.db.get("pendingStart", _id))) return; + if (await ctx.db.get("work", workId)) { + await ctx.db.patch("work", workId, { pendingStartId: _id }); + } + await ctx.db.patch("pendingStart", _id, { + segment: maxBigint(toTimestamp(legacyStartTime), snapshot), + // No `scanTs`: written by the loop, it can't be out of order. + }); + }), + ); +} + +/** Remove handled queue entries and start eligible work. */ async function handleStart( ctx: MutationCtx, state: Doc<"internalState">, @@ -545,30 +668,49 @@ async function handleStart( { logLevel }: Config, ) { console.debug(`[main] scheduling ${pending.length} pending work`); - const starts = ( - await Promise.all( - pending.map(async ({ _id, workId, segment }) => { - if (state.running.some((r) => r.workId === workId)) { - console.error(`[main] ${workId} already running (skipping start)`); - return null; - } - // Guard against a pendingStart a concurrent cancelation removed. - if (!(await ctx.db.get("pendingStart", _id))) { - return null; - } - const work = await ctx.db.get("work", workId); - await ctx.db.delete("pendingStart", _id); - if (!work) { - console.error(`Trying to start, but work not found: ${workId}`); - return null; - } - return { - work, - lagMs: Date.now() - fromSegment(segment), - }; - }), - ) - ).flatMap((r) => (r ? [r] : [])); + const entries = await Promise.all( + pending.map(async (entry) => { + const [doc, work] = await Promise.all([ + ctx.db.get("pendingStart", entry._id), + ctx.db.get("work", entry.workId), + ]); + return { ...entry, doc, work }; + }), + ); + const starts: { work: Doc<"work">; lagMs: number }[] = []; + for (const { _id, workId, segment, legacyStartTime, doc, work } of entries) { + if (!doc) continue; + await ctx.db.delete("pendingStart", _id); + if (state.running.some((r) => r.workId === workId)) { + console.error(`[main] ${workId} already running (skipping start)`); + continue; + } + if (!work) { + console.error(`Trying to start, but work not found: ${workId}`); + continue; + } + if (work.canceled) { + console.debug(`[main] ${workId} was canceled (not starting)`); + state.report.canceled++; + await ctx.scheduler.runAfter(0, internal.complete.complete, { + jobs: [ + { + workId, + runResult: { kind: "canceled" as const }, + attempt: work.attempts, + }, + ], + }); + continue; + } + if (work.pendingStartId === undefined) { + await ctx.db.patch("work", workId, { pendingStartId: _id }); + } + starts.push({ + work, + lagMs: Date.now() - (legacyStartTime ?? fromTimestamp(segment)), + }); + } state.running.push(...(await beginWorkBatch(ctx, starts, console, logLevel))); } @@ -683,11 +825,7 @@ async function rescheduleJob( console.warn(`[main] ${work._id} has no retryBehavior so not retrying`); return false; } - const existing = await ctx.db - .query("pendingStart") - .withIndex("workId", (q) => q.eq("workId", work._id)) - .first(); - if (existing) { + if (await findPendingStart(ctx, work)) { // Not sure why this would ever happen, but ensure uniqueness explicitly. console.error(`[main] ${work._id} already in pendingStart so not retrying`); return false; @@ -696,12 +834,18 @@ async function rescheduleJob( work.retryBehavior.initialBackoffMs * Math.pow(work.retryBehavior.base, work.attempts - 1); const nextAttempt = withJitter(backoffMs); - const startTime = Date.now() + nextAttempt; - const segment = toSegment(startTime); - await ctx.db.insert("pendingStart", { + // Raised to at least the snapshot, which the cursor may reach this run, so + // the retry can't land behind it; a backoff shorter than the clocks' skew + // just starts next iteration. + const segment = maxBigint( + toTimestamp(Date.now() + nextAttempt), + snapshotTs(), + ); + const pendingStartId = await ctx.db.insert("pendingStart", { workId: work._id, segment, }); + await ctx.db.patch("work", work._id, { pendingStartId }); return true; } @@ -721,7 +865,7 @@ async function getGlobals(ctx: QueryCtx) { } async function getOrCreateState(ctx: MutationCtx) { - const state = await ctx.db.query("internalState").unique(); + const state = await ctx.db.query("internalState").order("desc").first(); if (state) return state; const globals = await getGlobals(ctx); const console = createLogger(globals.logLevel); diff --git a/src/component/pendingStart.ts b/src/component/pendingStart.ts new file mode 100644 index 00000000..077cf5df --- /dev/null +++ b/src/component/pendingStart.ts @@ -0,0 +1,10 @@ +import type { Doc } from "./_generated/dataModel.js"; +import type { QueryCtx } from "./_generated/server.js"; + +/** Follow the queue pointer, which may reference an entry already deleted. */ +export async function findPendingStart(ctx: QueryCtx, work: Doc<"work">) { + const doc = work.pendingStartId + ? await ctx.db.get("pendingStart", work.pendingStartId) + : null; + return doc?.workId === work._id ? doc : null; +} diff --git a/src/component/schema.ts b/src/component/schema.ts index bf2d16c9..564019f8 100644 --- a/src/component/schema.ts +++ b/src/component/schema.ts @@ -7,25 +7,34 @@ import { retryBehavior, vResult, } from "./shared.js"; +import { deprecated } from "convex-helpers/validators"; -// Represents a slice of time to process work. -const segment = v.int64(); +// When a queue entry becomes eligible, in nanoseconds since the epoch: the +// commit timestamp of the enqueue for ready work, or the start time for +// scheduled work. +const segment = v.commitTs(); +// Epoch time in nanoseconds. CommitTs resolves to this after committing. +const timestamp = v.int64(); export default defineSchema({ // Written from kickLoop, read everywhere. globals: defineTable(vConfig), // Singleton, only read & written by `run`. internalState: defineTable({ - // @deprecated batch-worker now owns the generation guard. We keep writing - // `0n` for rollback compatibility with older workpool versions. - generation: v.optional(v.int64()), + /** @deprecated batch-worker now owns the generation guard. */ + generation: deprecated, // Track where we've scanned to, so we skip tombstones on re-scan. + // Legacy cursors used 100ms buckets. segmentCursors: v.object({ - incoming: segment, - completion: segment, - cancelation: segment, + incoming: timestamp, + completion: timestamp, + cancelation: timestamp, + // Cursor into scanTs. Absent until legacy queue pointers and cursors are upgraded. + sweep: v.optional(timestamp), }), - lastRecovery: segment, + // When the loop last checked for stuck jobs, in nanoseconds. + // Legacy 100ms buckets are interpreted as long ago. + lastRecovery: timestamp, report: v.object({ completed: v.number(), // finished running, counts retries & failures succeeded: v.number(), // finished successfully, regardless of retries @@ -57,14 +66,19 @@ export default defineSchema({ onComplete: v.optional(vOnCompleteFnContext), retryBehavior: v.optional(retryBehavior), canceled: v.optional(v.boolean()), + // May point to a deleted entry after starting, or be absent on legacy work. + pendingStartId: v.optional(v.id("pendingStart")), }), - // Written on enqueue & rescheduled for retry, read & deleted by `main`. + // Work waiting to start, one document per work item. pendingStart: defineTable({ workId: v.id("work"), segment, + // The enqueue's commit timestamp, present iff the document could have + // committed out of order (a scheduled start within five minutes). + scanTs: v.optional(v.commitTs()), }) - .index("workId", ["workId"]) + .index("scanTs", ["scanTs", "segment"]) .index("segment", ["segment"]), // Written by complete, read & deleted by `main`. diff --git a/src/component/shared.ts b/src/component/shared.ts index 6c778a76..fd6af81b 100644 --- a/src/component/shared.ts +++ b/src/component/shared.ts @@ -1,6 +1,6 @@ import type { Infer, Validator, VAny } from "convex/values"; -import { v } from "convex/values"; +import { jsonToConvex, v } from "convex/values"; import { type Logger, logLevel } from "./logging.js"; export const fnType = v.union( @@ -19,6 +19,7 @@ export const HOUR = 60 * MINUTE; export const DAY = 24 * HOUR; export const YEAR = 365 * DAY; +// Decode the 100ms buckets used before commit-timestamp ordering. export function toSegment(ms: number): bigint { return BigInt(Math.floor(ms / SEGMENT_MS)); } @@ -27,14 +28,74 @@ export function getCurrentSegment(): bigint { return toSegment(Date.now()); } -export function getNextSegment(): bigint { - return toSegment(Date.now()) + 1n; -} - export function fromSegment(segment: bigint): number { return Number(segment) * SEGMENT_MS; } +// A commit timestamp is nanoseconds since the epoch, so a wall-clock time +// converts into the same ordering as one. This is what lets a single index hold +// both "ready as soon as it commits" and "not before this time". +const NS_PER_MS = 1_000_000n; + +/** + * A wall-clock time on the commit-timestamp scale, preserving any fractional + * milliseconds exactly: the whole and fractional parts convert separately, so + * no precision is lost multiplying a large float. Round-trips through + * `fromTimestamp`. + */ +export function toTimestamp(ms: number): bigint { + const whole = Math.floor(ms); + return ( + BigInt(whole) * NS_PER_MS + + BigInt(Math.round((ms - whole) * Number(NS_PER_MS))) + ); +} + +/** + * Back to (possibly fractional) milliseconds, dividing the whole and + * remainder parts separately so large values don't lose precision. + */ +export function fromTimestamp(timestamp: bigint): number { + return ( + Number(timestamp / NS_PER_MS) + + Number(timestamp % NS_PER_MS) / Number(NS_PER_MS) + ); +} + +declare const Convex: { + syscall: (op: string, jsonArgs: string) => string; +}; + +/** + * The snapshot this transaction reads at, in nanoseconds on the + * commit-timestamp clock. Everything stamped at or below it is visible here, + * and everything that commits later is stamped above it. + * + * TODO(convex): replace with `ctx.meta.getSnapshotTs()` once a released + * `convex` exposes it; this is the syscall it wraps. + */ +export function snapshotTs(): bigint { + const json = Convex.syscall("1.0/getSnapshotTs", "{}"); + return jsonToConvex(JSON.parse(json)) as bigint; +} + +export function maxBigint(a: bigint, b: bigint): bigint { + return a > b ? a : b; +} + +/** Work is eligible when either the snapshot or the wall clock reaches its key. */ +export function eligibilityBound(): bigint { + return maxBigint(snapshotTs(), toTimestamp(Date.now())); +} + +// Separates legacy 100ms buckets from timestamps within the scheduling bounds. +export const MIN_TIMESTAMP = toTimestamp(Date.UTC(2000, 0, 1)); + +/** Decode a legacy start time, or return undefined for a modern timestamp. */ +export function legacyRunAt(segment: bigint): number | undefined { + return segment < MIN_TIMESTAMP ? fromSegment(segment) : undefined; +} + export const vConfig = v.object({ maxParallelism: v.number(), logLevel, @@ -166,17 +227,3 @@ export function boundScheduledTime(ms: number, console: Logger): number { } return ms; } - -/** - * Returns the smaller of two bigint values. - */ -export function min(a: T, b: T): T { - return a > b ? b : a; -} - -/** - * Returns the larger of two bigint values. - */ -export function max(a: T, b: T): T { - return a < b ? b : a; -} diff --git a/src/component/stateMachine.test.ts b/src/component/stateMachine.test.ts index d0826f8c..37d4ba16 100644 --- a/src/component/stateMachine.test.ts +++ b/src/component/stateMachine.test.ts @@ -15,11 +15,11 @@ import { DEFAULT_MAX_PARALLELISM, fromSegment, getCurrentSegment, - getNextSegment, + toTimestamp, SECOND, WORKER_NAME, } from "./shared.js"; -import { RECOVERY_PERIOD_SEGMENTS } from "./loop.js"; + import { setupTest } from "./setup.test.js"; // --------------------------------------------------------------------------- @@ -166,6 +166,13 @@ const S12_CANCELED_AWAITING_COMPLETE: CompositeState = { // --------------------------------------------------------------------------- const ACTION_RECOVERY_THRESHOLD_MS = 5 * 60 * 1000; +/** One recovery period in the 100ms buckets `runLoop` picks times with. */ +const RECOVERY_PERIOD_SEGMENTS = 600n; + +/** The bucket after the current one, as older versions computed it. */ +function getNextSegment(): bigint { + return getCurrentSegment() + 1n; +} describe("state machine", () => { let t: ReturnType; @@ -259,11 +266,15 @@ describe("state machine", () => { // Set up internalState const lastRecovery = opts?.oldForRecovery - ? getCurrentSegment() - RECOVERY_PERIOD_SEGMENTS - 1n - : getCurrentSegment(); + ? toTimestamp(Date.now() - 61 * SECOND) + : toTimestamp(Date.now()); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, lastRecovery, report: { completed: 0, @@ -278,7 +289,13 @@ describe("state machine", () => { // pendingStart if (state.pendingStart) { - await ctx.db.insert("pendingStart", { workId: wId, segment: seg }); + const pendingStartId = await ctx.db.insert("pendingStart", { + workId: wId, + segment: seg, + }); + if (await ctx.db.get("work", wId)) { + await ctx.db.patch("work", wId, { pendingStartId }); + } } // pendingCompletion @@ -314,10 +331,10 @@ describe("state machine", () => { async function observeState(workId: Id<"work">): Promise { return t.run(async (ctx) => { const work = await ctx.db.get("work", workId); - const ps = await ctx.db - .query("pendingStart") - .withIndex("workId", (q) => q.eq("workId", workId)) - .first(); + const ps = + (await ctx.db.query("pendingStart").collect()).find( + (p) => p.workId === workId, + ) ?? null; const state = await ctx.db.query("internalState").unique(); const inRunning = state?.running.some((r) => r.workId === workId) ?? false; @@ -853,7 +870,7 @@ describe("state machine", () => { expect(s.running).toBe(false); }); - it("pendingStart + running for same workId -> skips start but leaves pendingStart", async () => { + it("pendingStart + running for same workId -> skips start and drops the pendingStart", async () => { const { workId, segment } = await setupState({ work: { attempts: 0, hasRetryBehavior: false, fnType: "action" }, pendingStart: true, @@ -864,10 +881,10 @@ describe("state machine", () => { await runLoop(segment); const s = await observeState(workId); expect(s.running).toBe(true); - // BUG: handleStart skips the start but does NOT delete the pendingStart - // entry (returns null before the delete call). This means the orphaned - // pendingStart will be picked up again on the next loop iteration. - expect(s.pendingStart).toBe(true); + // The pendingStart is spurious — the work is already running — and the + // ready lane's cursor has moved past it, so it has to be deleted here or + // it would sit in the table unread forever. + expect(s.pendingStart).toBe(false); }); it("duplicate pendingCompletion via complete.complete -> BUG: attempts still incremented", async () => { @@ -914,7 +931,10 @@ describe("state machine", () => { fnArgs: {}, attempts: 0, }); - await ctx.db.insert("pendingStart", { workId: id, segment: seg }); + await ctx.db.insert("pendingStart", { + workId: id, + segment: seg, + }); return id; }); @@ -970,9 +990,13 @@ describe("state machine", () => { }, ); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, - lastRecovery: getCurrentSegment(), + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, + lastRecovery: toTimestamp(Date.now()), report: { completed: 0, succeeded: 0, @@ -1032,7 +1056,7 @@ describe("state machine", () => { await t.run(async (ctx) => { await ctx.db.insert("pendingCancelation", { workId, - segment, + segment: segment, }); }); @@ -1043,9 +1067,9 @@ describe("state machine", () => { expect(s.pendingCompletion).toBe(false); }); - it("multiple cancels for same work -> BUG: crashes with double delete", async () => { + it("multiple cancels for the same work complete it once", async () => { const seg = getNextSegment(); - await t.run>(async (ctx) => { + const workId = await t.run>(async (ctx) => { const wId = await ctx.db.insert("work", { fnType: "action", fnHandle: "h", @@ -1053,7 +1077,12 @@ describe("state machine", () => { fnArgs: {}, attempts: 0, }); - await ctx.db.insert("pendingStart", { workId: wId, segment: seg }); + await ctx.db.patch("work", wId, { + pendingStartId: await ctx.db.insert("pendingStart", { + workId: wId, + segment: seg, + }), + }); await ctx.db.insert("pendingCancelation", { workId: wId, segment: seg, @@ -1064,9 +1093,13 @@ describe("state machine", () => { }); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, - lastRecovery: getCurrentSegment(), + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, + lastRecovery: toTimestamp(Date.now()), report: { completed: 0, succeeded: 0, @@ -1080,10 +1113,32 @@ describe("state machine", () => { return wId; }); - // BUG: handleCancelation processes duplicate pendingCancelation entries - // in parallel. Both find the same pendingStart and try to delete it, - // causing a "Delete on non-existent doc" crash. - await expect(runLoop(seg)).rejects.toThrow(); + await runLoop(seg); + expect(await observeState(workId)).toMatchObject({ + pendingStart: false, + pendingCancelation: false, + running: false, + work: { canceled: true }, + }); + await t.run(async (ctx) => { + const state = (await ctx.db.query("internalState").unique())!; + expect(state.report.canceled).toBe(1); + const completions = ( + await ctx.db.system.query("_scheduled_functions").collect() + ).filter((f) => f.name === "complete:complete"); + expect(completions).toHaveLength(1); + expect(completions[0].args).toEqual([ + { + jobs: [ + { + workId, + runResult: { kind: "canceled" }, + attempt: 0, + }, + ], + }, + ]); + }); }); it("complete(success) + cancel interleaved -> cancel is no-op (work already gone)", async () => { @@ -1122,9 +1177,13 @@ describe("state machine", () => { }, ); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, - lastRecovery: getCurrentSegment(), + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, + lastRecovery: toTimestamp(Date.now()), report: { completed: 0, succeeded: 0, @@ -1212,9 +1271,13 @@ describe("state machine", () => { }); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, - lastRecovery: getCurrentSegment(), + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, + lastRecovery: toTimestamp(Date.now()), report: { completed: 0, succeeded: 0, @@ -1232,12 +1295,22 @@ describe("state machine", () => { retry: false, runResult: { kind: "success", returnValue: null }, }); - await ctx.db.insert("pendingStart", { workId: w2, segment: seg }); + await ctx.db.patch("work", w2, { + pendingStartId: await ctx.db.insert("pendingStart", { + workId: w2, + segment: seg, + }), + }); await ctx.db.insert("pendingCancelation", { workId: w2, segment: seg, }); - await ctx.db.insert("pendingStart", { workId: w3, segment: seg }); + await ctx.db.patch("work", w3, { + pendingStartId: await ctx.db.insert("pendingStart", { + workId: w3, + segment: seg, + }), + }); return { w1, w2, w3 }; }); @@ -1289,9 +1362,13 @@ describe("state machine", () => { }, ); await ctx.db.insert("internalState", { - generation: 0n, - segmentCursors: { incoming: 0n, completion: 0n, cancelation: 0n }, - lastRecovery: getCurrentSegment(), + segmentCursors: { + incoming: 0n, + completion: 0n, + cancelation: 0n, + sweep: 0n, + }, + lastRecovery: toTimestamp(Date.now()), report: { completed: 0, succeeded: 0, diff --git a/src/component/stats.test.ts b/src/component/stats.test.ts index 9bcc56cf..3ec27176 100644 --- a/src/component/stats.test.ts +++ b/src/component/stats.test.ts @@ -1,345 +1,131 @@ -import { paginator } from "convex-helpers/server/pagination"; import { convexTest } from "convex-test"; -import { - afterEach, - assert, - beforeEach, - describe, - expect, - it, - vi, -} from "vitest"; +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import { internal } from "./_generated/api.js"; -import type { Logger } from "./logging.js"; +import type { Id } from "./_generated/dataModel.js"; +import { createLogger } from "./logging.js"; +import { INITIAL_STATE } from "./loop.js"; import schema from "./schema.js"; -import { getCurrentSegment } from "./shared.js"; +import { toSegment, toTimestamp } from "./shared.js"; +import { generateReport } from "./stats.js"; const modules = import.meta.glob("./**/*.ts"); +const setupTest = () => convexTest(schema, modules); -// Create a proper Logger mock -function createLoggerMock(): Logger { - return { - event: vi.fn(), - debug: vi.fn(), - info: vi.fn(), - warn: vi.fn(), - error: vi.fn(), - time: vi.fn(), - timeEnd: vi.fn(), - }; -} - -describe("stats", () => { - async function setupTest() { - const t = convexTest(schema, modules); - return t; - } - - let t: Awaited>; +describe("stats reports", () => { + let t: ReturnType; + let stateId: Id<"internalState">; + const reports = () => + vi.mocked(console.info).mock.calls.map(([line]) => JSON.parse(line)); beforeEach(async () => { vi.useFakeTimers(); - t = await setupTest(); + vi.spyOn(console, "info").mockImplementation(() => {}); + t = setupTest(); + stateId = await t.run((ctx) => + ctx.db.insert("internalState", { + ...INITIAL_STATE, + report: { + ...INITIAL_STATE.report, + completed: 10, + succeeded: 6, + failed: 2, + retries: 2, + }, + }), + ); }); - afterEach(() => { + vi.restoreAllMocks(); vi.useRealTimers(); }); - describe("generateReport", () => { - it("should not generate a report when log level is above REPORT", async () => { - // Setup internal state - const stateId = await t.run(async (ctx) => { - return await ctx.db.insert("internalState", { - generation: 1n, - segmentCursors: { - incoming: 0n, - completion: 0n, - cancelation: 0n, - }, - lastRecovery: 0n, - report: { - completed: 0, - succeeded: 0, - failed: 0, - retries: 0, - canceled: 0, - lastReportTs: 0, - }, - running: [], - }); - }); - - // Mock the console.event function to track if it's called - const consoleMock = createLoggerMock(); - - // Get the state document - const state = await t.run(async (ctx) => { - return await ctx.db.get("internalState", stateId); + async function enqueue(segment: bigint) { + await t.run(async (ctx) => { + const workId = await ctx.db.insert("work", { + fnType: "action", + fnHandle: "test", + fnName: "test", + attempts: 0, }); - assert(state); - - // Call generateReport with a log level that won't trigger reporting - await t.run(async (ctx) => { - const { generateReport } = await import("./stats.js"); - await generateReport(ctx, consoleMock, state, { - maxParallelism: 10, - logLevel: "WARN", // Above REPORT level - }); - }); - - // Verify that console.event was not called - expect(consoleMock.event).not.toHaveBeenCalled(); + await ctx.db.insert("pendingStart", { workId, segment }); }); + } - it("should generate a report when backlog is small enough", async () => { - // Setup internal state - const stateId = await t.run(async (ctx) => { - return await ctx.db.insert("internalState", { - generation: 1n, - segmentCursors: { - incoming: 0n, - completion: 0n, - cancelation: 0n, - }, - lastRecovery: 0n, - report: { - completed: 10, - succeeded: 6, - failed: 2, - retries: 2, - canceled: 0, - lastReportTs: 0, - }, - running: [], - }); - }); - - // Create a few pending start items - await t.run(async (ctx) => { - // Create a work item - const workId = await ctx.db.insert("work", { - fnType: "mutation", - fnHandle: "testHandle", - fnName: "testFunction", - fnArgs: { test: true }, - attempts: 0, - }); - - // Create a pendingStart for the work - await ctx.db.insert("pendingStart", { - workId, - segment: 5n, // Some segment between 0 and currentSegment - }); - }); - - // Mock the console.event function to track if it's called - const consoleMock = createLoggerMock(); - - // Get the state document - const state = await t.run(async (ctx) => { - return await ctx.db.get("internalState", stateId); - }); - assert(state); - - // Call generateReport with REPORT log level - await t.run(async (ctx) => { - const { generateReport } = await import("./stats.js"); - await generateReport(ctx, consoleMock, state, { - maxParallelism: 10, - logLevel: "REPORT", // This should trigger reporting - }); - }); - - // Verify that console.event was called with the correct data - expect(consoleMock.event).toHaveBeenCalledWith("report", { - backlog: 1, // We created one pendingStart - running: 0, - completed: 10, - succeeded: 6, - failed: 2, - retries: 2, - canceled: 0, - failureRate: 0.4, // (failed + retries) / completed = (2 + 2) / 10 = 0.4 - permanentFailureRate: 0.25, // failed / (completed - retries) = 2 / (10 - 2) = 2/8 - lastReportTs: expect.any(Number), + async function report(logLevel: "REPORT" | "WARN" = "REPORT") { + await t.run(async (ctx) => { + const state = (await ctx.db.get("internalState", stateId))!; + await generateReport(ctx, createLogger(logLevel), state, { + maxParallelism: 10, + logLevel, }); }); + } - it("should schedule calculateBacklogAndReport when backlog is large", async () => { - // Setup internal state - const stateId = await t.run(async (ctx) => { - return await ctx.db.insert("internalState", { - generation: 1n, - segmentCursors: { - incoming: 0n, - completion: 0n, - cancelation: 0n, - }, - lastRecovery: 0n, - report: { - completed: 10, - succeeded: 8, - failed: 1, - retries: 1, - canceled: 0, - lastReportTs: 0, - }, - running: [], - }); - }); - - // Create more pending start items than maxParallelism - const maxParallelism = 50; - - // Create maxParallelism + 1 work items to trigger pagination - for (let i = 0; i < maxParallelism + 1; i++) { - await t.run(async (ctx) => { - // Create a work item - const workId = await ctx.db.insert("work", { - fnType: "mutation", - fnHandle: "testHandle", - fnName: `testFunction${i}`, - fnArgs: { test: i }, - attempts: 0, - }); - - // Create a pendingStart for the work - await ctx.db.insert("pendingStart", { - workId, - segment: 5n, // Some segment between 0 and currentSegment - }); - }); - } - - // Mock the console.event function - const consoleMock = createLoggerMock(); - - // Get the state document - const state = await t.run(async (ctx) => { - return await ctx.db.get("internalState", stateId); - }); - assert(state); - - // Call generateReport with REPORT log level - await t.run(async (ctx) => { - const { generateReport } = await import("./stats.js"); - await generateReport(ctx, consoleMock, state, { - maxParallelism, - logLevel: "REPORT", // This should trigger reporting - }); - }); - - // Verify that calculateBacklogAndReport was scheduled - await t.run(async (ctx) => { - const scheduledFunctions = await ctx.db.system - .query("_scheduled_functions") - .collect(); - - expect(scheduledFunctions.length).toBeGreaterThan(0); - - // Check that one of the scheduled functions is calculateBacklogAndReport - const calculateBacklogScheduled = scheduledFunctions.find( - (sf) => sf.name === "stats:calculateBacklogAndReport", - ); - expect(calculateBacklogScheduled).toBeDefined(); - assert(calculateBacklogScheduled); - - // Verify console.event was not called yet (will be called by calculateBacklogAndReport) - expect(consoleMock.event).not.toHaveBeenCalled(); - }); + it("skips reporting when disabled", async () => { + await report("WARN"); + expect(reports()).toEqual([]); + await t.run(async (ctx) => { + expect( + await ctx.db.system.query("_scheduled_functions").collect(), + ).toHaveLength(0); }); + }); - it("should calculate backlog and report correctly", async () => { - // Setup internal state - const stateId = await t.run(async (ctx) => { - return await ctx.db.insert("internalState", { - generation: 1n, - segmentCursors: { - incoming: 0n, - completion: 0n, - cancelation: 0n, - }, - lastRecovery: 0n, - report: { - completed: 10, - succeeded: 8, - failed: 1, - retries: 1, - canceled: 0, - lastReportTs: 0, - }, - running: [], - }); - }); - - // Create some pending start items - const currentSegment = getCurrentSegment(); - - // Create 3 work items - for (let i = 0; i < 3; i++) { - await t.run(async (ctx) => { - // Create a work item - const workId = await ctx.db.insert("work", { - fnType: "mutation", - fnHandle: "testHandle", - fnName: `testFunction${i}`, - fnArgs: { test: i }, - attempts: 0, - }); - - // Create a pendingStart for the work - await ctx.db.insert("pendingStart", { - workId, - segment: 5n, // Some segment between 0 and currentSegment - }); - }); - } - - // Get the state document - const state = await t.run(async (ctx) => { - return await ctx.db.get("internalState", stateId); - }); - assert(state); - - const cursor = await t.run(async (ctx) => { - return await paginator(ctx.db, schema) - .query("pendingStart") - .withIndex("segment", (q) => - q.gte("segment", 0n).lt("segment", currentSegment), - ) - .paginate({ - numItems: 1, - cursor: null, - }); - }); + it("counts queue documents including scheduled and legacy entries", async () => { + await enqueue(toTimestamp(Date.now())); + await enqueue(toSegment(Date.now())); + await enqueue(toTimestamp(Date.now() - 1000)); + await enqueue(toSegment(Date.now() + 60_000)); + await enqueue(toTimestamp(Date.now() + 60_000)); + await t.run(async (ctx) => + ctx.db.patch("internalState", stateId, { + segmentCursors: { + ...INITIAL_STATE.segmentCursors, + incoming: toTimestamp(Date.now()), + }, + }), + ); + await report(); + expect(reports()).toEqual([ + expect.objectContaining({ + event: "report", + backlog: 5, + running: 0, + failureRate: 0.4, + permanentFailureRate: 0.25, + }), + ]); + }); - // Call calculateBacklogAndReport directly - await t.mutation(internal.stats.calculateBacklogAndReport, { - startSegment: 0n, - endSegment: currentSegment, - cursor: cursor.continueCursor, - report: state.report, - running: state.running.length, + it("reports large queues without scanning documents or scheduling follow-up reports", async () => { + for (let i = 0; i < 300; i++) await enqueue(toTimestamp(Date.now())); + await t.run(async (ctx) => { + const state = (await ctx.db.get("internalState", stateId))!; + const before = await ctx.meta.getTransactionMetrics(); + await generateReport(ctx, createLogger("REPORT"), state, { + maxParallelism: 10, logLevel: "REPORT", }); + const after = await ctx.meta.getTransactionMetrics(); + expect(after.documentsRead.used - before.documentsRead.used).toBe(0); + expect( + await ctx.db.system.query("_scheduled_functions").collect(), + ).toHaveLength(0); + }); + expect(reports()).toEqual([expect.objectContaining({ backlog: 300 })]); + }); - // Verify that console.event was called with the correct data - // Note: We can't directly check the mock since it's created inside the mutation - // Instead, we can check if the function completed successfully - - // We can verify the function was executed by checking if any scheduled functions were created - await t.run(async (ctx) => { - const scheduledFunctions = await ctx.db.system - .query("_scheduled_functions") - .collect(); - - // Since our backlog is small, no additional scheduled functions should be created - const calculateBacklogScheduled = scheduledFunctions.find( - (sf) => sf.name === "stats:calculateBacklogAndReport", - ); - expect(calculateBacklogScheduled).toBeUndefined(); - }); + it("accepts reports scheduled by older versions", async () => { + await enqueue(toSegment(Date.now())); + await enqueue(toSegment(Date.now() + 60_000)); + await t.mutation(internal.stats.calculateBacklogAndReport, { + startSegment: 0n, + endSegment: toSegment(Date.now()), + cursor: "old cursor", + report: INITIAL_STATE.report, + running: 0, + logLevel: "REPORT", }); + expect(reports()).toEqual([expect.objectContaining({ backlog: 2 })]); }); }); diff --git a/src/component/stats.ts b/src/component/stats.ts index 6bbce9c4..b6167225 100644 --- a/src/component/stats.ts +++ b/src/component/stats.ts @@ -5,16 +5,10 @@ import { internalQuery, type MutationCtx, } from "./_generated/server.js"; -import { - type Config, - DEFAULT_MAX_PARALLELISM, - getCurrentSegment, - WORKER_NAME, -} from "./shared.js"; +import { type Config, DEFAULT_MAX_PARALLELISM, WORKER_NAME } from "./shared.js"; import { createLogger, type Logger, logLevel, shouldLog } from "./logging.js"; -import { components, internal } from "./_generated/api.js"; +import { components } from "./_generated/api.js"; import schema from "./schema.js"; -import { paginator } from "convex-helpers/server/pagination"; /** * Record stats about work execution. Intended to be queried by Axiom or Datadog. @@ -71,60 +65,40 @@ export async function generateReport( ctx: MutationCtx, console: Logger, state: Doc<"internalState">, - { maxParallelism, logLevel }: Config, + { logLevel }: Config, ) { if (!shouldLog(logLevel, "REPORT")) { - // Don't waste time if we're not going to log. return; } - const currentSegment = getCurrentSegment(); - const pendingStart = await paginator(ctx.db, schema) - .query("pendingStart") - .withIndex("segment", (q) => - q - .gte("segment", state.segmentCursors.incoming) - .lt("segment", currentSegment), - ) - .paginate({ - numItems: Math.max(maxParallelism, 10), - cursor: null, - }); - if (pendingStart.isDone) { - recordReport(console, { - ...state.report, - running: state.running.length, - backlog: pendingStart.page.length, - }); - } else { - await ctx.scheduler.runAfter(0, internal.stats.calculateBacklogAndReport, { - startSegment: 0n, - endSegment: currentSegment, - cursor: pendingStart.continueCursor, - report: state.report, - running: state.running.length, - logLevel, - }); - } + // Count queued work, including future work, without scanning documents. + recordReport(console, { + ...state.report, + running: state.running.length, + backlog: await (ctx.db.query("pendingStart") as any).count(), + }); } +/** Compatibility handler for reports already scheduled by older versions. */ export const calculateBacklogAndReport = internalMutation({ args: { - startSegment: v.int64(), - endSegment: v.int64(), + // @deprecated Unused; accepted so in-flight calls from older versions + // still validate. + startSegment: v.optional(v.int64()), + endSegment: v.optional(v.int64()), cursor: v.string(), report: schema.tables.internalState.validator.fields.report, running: v.number(), logLevel, }, + returns: v.null(), handler: async (ctx, args) => { - const pendingStart = await (ctx.db.query("pendingStart") as any).count(); - const console = createLogger(args.logLevel); recordReport(console, { ...args.report, running: args.running, - backlog: pendingStart, + backlog: await (ctx.db.query("pendingStart") as any).count(), }); + return null; }, }); @@ -159,7 +133,10 @@ export const running = internalQuery({ }), ), handler: async (ctx) => { - const internalState = await ctx.db.query("internalState").unique(); + const internalState = await ctx.db + .query("internalState") + .order("desc") + .first(); if (!internalState) return []; return Promise.all( internalState.running.map(async ({ workId, scheduledId, started }) => { @@ -185,7 +162,10 @@ export const diagnostics = internalQuery({ returns: v.any(), handler: async (ctx) => { const global = await ctx.db.query("globals").unique(); - const internalState = await ctx.db.query("internalState").unique(); + const internalState = await ctx.db + .query("internalState") + .order("desc") + .first(); const inProgressWork = internalState?.running.length ?? 0; const maxParallelism = global?.maxParallelism ?? DEFAULT_MAX_PARALLELISM; const pendingStart = await (ctx.db.query("pendingStart") as any).count(); From ca853b077d871b9249d9f9eab8e9dca8cdc9144f Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:01:51 -0700 Subject: [PATCH 03/15] docs(queue): name the persisted sweep cursor --- src/component/README.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/component/README.md b/src/component/README.md index e3108073..a2635d6a 100644 --- a/src/component/README.md +++ b/src/component/README.md @@ -3,8 +3,8 @@ - `segment`: a nanosecond timestamp. Immediate work uses its enqueue commit timestamp; scheduled work uses its start time. - Cursors: inclusive positions in the pending queues that skip deleted rows. The - incoming cursor never passes the snapshot. A separate `scanTs` cursor recovers - near-term scheduled enqueues that commit behind it. + incoming cursor never passes the snapshot. `segmentCursors.sweep` walks the + `scanTs` index to recover near-term scheduled enqueues that commit behind it. - `generation`: batch-worker's counter that permits only one active loop chain. - Tombstones: deleted rows that remain in storage until vacuumed. Advancing cursors avoids repeatedly reading them. From 87d9504e86988e76e5c5c7fa81705f96147c0f71 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:26:22 -0700 Subject: [PATCH 04/15] nit --- src/component/stateMachine.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/component/stateMachine.test.ts b/src/component/stateMachine.test.ts index 37d4ba16..453ecbbe 100644 --- a/src/component/stateMachine.test.ts +++ b/src/component/stateMachine.test.ts @@ -1056,7 +1056,7 @@ describe("state machine", () => { await t.run(async (ctx) => { await ctx.db.insert("pendingCancelation", { workId, - segment: segment, + segment, }); }); From 54a8dd6473628152e4b3fd8418da14cdb1e71cd2 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:31:45 -0700 Subject: [PATCH 05/15] refactor(queue): confine legacy handling to the upgrade pass --- src/component/loop.test.ts | 11 ++- src/component/loop.ts | 105 +++++++++-------------------- src/component/shared.ts | 5 -- src/component/stateMachine.test.ts | 32 ++++----- 4 files changed, 56 insertions(+), 97 deletions(-) diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index a04ea998..ea05f0d7 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -373,6 +373,12 @@ describe("loop", () => { // max(toSegment(runAt), now), as `enqueue` used to compute it. segment: toSegment(Math.max(runAt, Date.now())), }); + const state = await ctx.db.query("internalState").unique(); + if (state) { + await ctx.db.patch("internalState", state._id, { + segmentCursors: { ...state.segmentCursors, sweep: undefined }, + }); + } return workId; }); } @@ -468,6 +474,7 @@ describe("loop", () => { await initialize(); const workId = await enqueueLegacyWork(Date.now()); + await runLoop(); // upgrade await runLoop(); const o = await observe(); @@ -491,7 +498,7 @@ describe("loop", () => { expect(o.running).toHaveLength(0); expect(o.pendingStart[0].segment).toBe(toTimestamp(startsAt)); - await runLoop(); // the sweep verifies the re-keyed entry, once + await runLoop(); const idle = await runLoop(); assert(idle.kind === "idle"); expect(idle.timeoutMs).toBe(startsAt - Date.now()); @@ -514,7 +521,7 @@ describe("loop", () => { const runAt = Date.now() + 100 * SECOND; const workId = await enqueueLegacyWork(runAt); await runLoop(); // re-keys it to its start time - await runLoop(); // the sweep verifies the re-keyed entry + await runLoop(); await t.mutation(api.lib.cancel, { id: workId }); await runLoop(); diff --git a/src/component/loop.ts b/src/component/loop.ts index 62614cc8..40d8cceb 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -22,7 +22,7 @@ import { DEFAULT_MAX_PARALLELISM, eligibilityBound, fromTimestamp, - legacyRunAt, + fromSegment, maxBigint, MINUTE, MIN_TIMESTAMP, @@ -32,7 +32,6 @@ import { vResult, } from "./shared.js"; import { generateReport, recordCompleted, recordStarted } from "./stats.js"; -import { assert } from "convex-helpers"; import { findPendingStart } from "./pendingStart.js"; const CANCELLATION_BATCH_SIZE = 64; // the only queue that can get unbounded. @@ -71,7 +70,7 @@ export const INITIAL_STATE: WithoutSystemFields> = { // batch-worker owns loop scheduling, generation checks, and liveness recovery. const vCompletion = v.object({ - _id: v.id("pendingCompletion"), + pendingId: v.id("pendingCompletion"), workId: v.id("work"), runResult: vResult, retry: v.boolean(), @@ -80,18 +79,16 @@ const vCompletion = v.object({ type Completion = Infer; const vCancelation = v.object({ - _id: v.id("pendingCancelation"), + pendingId: v.id("pendingCancelation"), workId: v.id("work"), segment: v.int64(), }); type Cancelation = Infer; const vStart = v.object({ - _id: v.id("pendingStart"), + pendingId: v.id("pendingStart"), workId: v.id("work"), segment: v.int64(), - // Decoded from a legacy 100ms bucket; not stored. - legacyStartTime: v.optional(v.number()), }); type Start = Infer; @@ -132,10 +129,9 @@ export const getBatch = internalQuery({ sweepStarts: [], upgrade: { starts: docs.map((doc) => ({ - _id: doc._id, + pendingId: doc._id, workId: doc.workId, segment: doc.segment as bigint, - legacyStartTime: legacyRunAt(doc.segment as bigint), })), done: docs.length < MAIN_BATCH_SIZE, }, @@ -176,14 +172,14 @@ export const getBatch = internalQuery({ const batch: Batch = { recovery: isRecoveryIter, completions: completions.map((c) => ({ - _id: c._id, + pendingId: c._id, workId: c.workId, runResult: c.runResult, retry: c.retry, segment: c.segment as bigint, })), cancelations: cancelations.map((c) => ({ - _id: c._id, + pendingId: c._id, workId: c.workId, segment: c.segment as bigint, })), @@ -234,12 +230,14 @@ export const run = internalMutation({ for (const start of batch.upgrade.starts) { const work = await ctx.db.get("work", start.workId); if (!work) { - await ctx.db.delete("pendingStart", start._id); + await ctx.db.delete("pendingStart", start.pendingId); continue; } - await ctx.db.patch("work", work._id, { pendingStartId: start._id }); - await ctx.db.patch("pendingStart", start._id, { - segment: maxBigint(toTimestamp(start.legacyStartTime!), snapshot), + await ctx.db.patch("work", work._id, { + pendingStartId: start.pendingId, + }); + await ctx.db.patch("pendingStart", start.pendingId, { + segment: maxBigint(toTimestamp(fromSegment(start.segment)), snapshot), }); } await ctx.db.patch("internalState", state._id, { @@ -280,28 +278,10 @@ export const run = internalMutation({ state.lastRecovery = nowTs; } - // Modern entries are due by either clock. Legacy buckets can still - // represent future work, which must be re-keyed before advancing. - const now = Date.now(); - const isDue = (s: Start) => - s.legacyStartTime === undefined || s.legacyStartTime <= now; - const all = [...batch.starts, ...batch.sweepStarts]; - const notYet = all.filter((s) => !isDue(s)); - // Oldest first: `segment` is when an entry became eligible, and a swept - // entry has been eligible since its (past) start time. - const eligible = all - .filter(isDue) - .sort( - (a, b) => - (a.legacyStartTime ?? fromTimestamp(a.segment)) - - (b.legacyStartTime ?? fromTimestamp(b.segment)), - ); - if (notYet.length > 0) { - const promoteLabel = `[main] promote(${notYet.length})`; - console.time(promoteLabel); - await promoteScheduled(ctx, notYet); - console.timeEnd(promoteLabel); - } + // Merge the segment scan and sweep in eligibility order. + const eligible = [...batch.starts, ...batch.sweepStarts].sort((a, b) => + a.segment < b.segment ? -1 : a.segment > b.segment ? 1 : 0, + ); // Slice to actual available capacity (completions may have freed slots). // Guard against negative numbers in case running.length > maxParallelism. @@ -345,10 +325,10 @@ export const run = internalMutation({ } // Advance only across handled entries, capped at the snapshot so racing // commits remain ahead. Inclusive reads retain entries sharing a timestamp. - const handled = new Set([...pending, ...notYet].map((s) => s._id)); + const handled = new Set(pending.map((s) => s.pendingId)); const snapshot = snapshotTs(); for (const start of batch.starts) { - if (!handled.has(start._id)) break; + if (!handled.has(start.pendingId)) break; state.segmentCursors.incoming = start.segment < snapshot ? start.segment : snapshot; } @@ -356,7 +336,7 @@ export const run = internalMutation({ // Entries left at the boundary stamp are revisited by an inclusive read. if ( batch.sweepStop !== undefined && - batch.sweepStarts.every((s) => handled.has(s._id)) + batch.sweepStarts.every((s) => handled.has(s.pendingId)) ) { state.segmentCursors.sweep = maxBigint( state.segmentCursors.sweep ?? 0n, @@ -424,7 +404,7 @@ async function queryPending( const segment = doc.segment as bigint; if (!excluded.has(doc.workId)) { if (sweepStarts.length >= startLimit) return "stop"; - sweepStarts.push({ _id: doc._id, workId: doc.workId, segment }); + sweepStarts.push({ pendingId: doc._id, workId: doc.workId, segment }); } return ++docs >= SWEEP_DOC_BATCH ? "stop" : "more"; }; @@ -473,17 +453,12 @@ async function queryPending( ); for await (const doc of stream) { const segment = doc.segment as bigint; - // A document from before commit-timestamp ordering keeps its start time - // in `segment`; recovering it here means `run` handles it like any - // other not-yet-due entry and re-keys it as a timestamp. - const legacyStartTime = legacyRunAt(segment); if (excluded.has(doc.workId)) continue; if (starts.length >= readyLimit) break; starts.push({ - _id: doc._id, + pendingId: doc._id, workId: doc.workId, segment, - legacyStartTime, }); } } @@ -504,7 +479,7 @@ async function handleCompletions( const toCancel: CompleteJob[] = []; await Promise.all( completed.map(async (c) => { - await ctx.db.delete("pendingCompletion", c._id); + await ctx.db.delete("pendingCompletion", c.pendingId); const running = state.running.find((r) => r.workId === c.workId); if (!running) { @@ -568,9 +543,9 @@ async function handleCancelation( const canceledWork = new Set>(); const jobs: CompleteJob[] = [...toCancel]; await Promise.all( - canceled.map(async ({ _id, workId }) => { - if (!(await ctx.db.get("pendingCancelation", _id))) return; - await ctx.db.delete("pendingCancelation", _id); + canceled.map(async ({ pendingId, workId }) => { + if (!(await ctx.db.get("pendingCancelation", pendingId))) return; + await ctx.db.delete("pendingCancelation", pendingId); if (canceledWork.has(workId)) { console.error(`[main] ${workId} already canceled`); return; @@ -641,24 +616,6 @@ async function handleRecovery( } } -/** Convert future legacy buckets to timestamps at or above this snapshot. */ -async function promoteScheduled(ctx: MutationCtx, notYet: Start[]) { - const snapshot = snapshotTs(); - await Promise.all( - notYet.map(async ({ _id, workId, legacyStartTime }) => { - assert(legacyStartTime); - if (!(await ctx.db.get("pendingStart", _id))) return; - if (await ctx.db.get("work", workId)) { - await ctx.db.patch("work", workId, { pendingStartId: _id }); - } - await ctx.db.patch("pendingStart", _id, { - segment: maxBigint(toTimestamp(legacyStartTime), snapshot), - // No `scanTs`: written by the loop, it can't be out of order. - }); - }), - ); -} - /** Remove handled queue entries and start eligible work. */ async function handleStart( ctx: MutationCtx, @@ -671,16 +628,16 @@ async function handleStart( const entries = await Promise.all( pending.map(async (entry) => { const [doc, work] = await Promise.all([ - ctx.db.get("pendingStart", entry._id), + ctx.db.get("pendingStart", entry.pendingId), ctx.db.get("work", entry.workId), ]); return { ...entry, doc, work }; }), ); const starts: { work: Doc<"work">; lagMs: number }[] = []; - for (const { _id, workId, segment, legacyStartTime, doc, work } of entries) { + for (const { pendingId, workId, segment, doc, work } of entries) { if (!doc) continue; - await ctx.db.delete("pendingStart", _id); + await ctx.db.delete("pendingStart", pendingId); if (state.running.some((r) => r.workId === workId)) { console.error(`[main] ${workId} already running (skipping start)`); continue; @@ -704,11 +661,11 @@ async function handleStart( continue; } if (work.pendingStartId === undefined) { - await ctx.db.patch("work", workId, { pendingStartId: _id }); + await ctx.db.patch("work", workId, { pendingStartId: pendingId }); } starts.push({ work, - lagMs: Date.now() - (legacyStartTime ?? fromTimestamp(segment)), + lagMs: Date.now() - fromTimestamp(segment), }); } diff --git a/src/component/shared.ts b/src/component/shared.ts index fd6af81b..a781cc8a 100644 --- a/src/component/shared.ts +++ b/src/component/shared.ts @@ -91,11 +91,6 @@ export function eligibilityBound(): bigint { // Separates legacy 100ms buckets from timestamps within the scheduling bounds. export const MIN_TIMESTAMP = toTimestamp(Date.UTC(2000, 0, 1)); -/** Decode a legacy start time, or return undefined for a modern timestamp. */ -export function legacyRunAt(segment: bigint): number | undefined { - return segment < MIN_TIMESTAMP ? fromSegment(segment) : undefined; -} - export const vConfig = v.object({ maxParallelism: v.number(), logLevel, diff --git a/src/component/stateMachine.test.ts b/src/component/stateMachine.test.ts index 453ecbbe..be1e052d 100644 --- a/src/component/stateMachine.test.ts +++ b/src/component/stateMachine.test.ts @@ -291,7 +291,7 @@ describe("state machine", () => { if (state.pendingStart) { const pendingStartId = await ctx.db.insert("pendingStart", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); if (await ctx.db.get("work", wId)) { await ctx.db.patch("work", wId, { pendingStartId }); @@ -307,7 +307,7 @@ describe("state machine", () => { }; await ctx.db.insert("pendingCompletion", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), retry: state.pendingCompletion.retry, runResult: resultMap[state.pendingCompletion.resultKind], }); @@ -317,7 +317,7 @@ describe("state machine", () => { if (state.pendingCancelation) { await ctx.db.insert("pendingCancelation", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); } @@ -782,7 +782,7 @@ describe("state machine", () => { const backlogWorkId = await makeDummyWork(ctx); await ctx.db.insert("pendingStart", { workId: backlogWorkId, - segment, + segment: toTimestamp(fromSegment(segment)), }); return backlogWorkId; }); @@ -933,7 +933,7 @@ describe("state machine", () => { }); await ctx.db.insert("pendingStart", { workId: id, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); return id; }); @@ -1056,7 +1056,7 @@ describe("state machine", () => { await t.run(async (ctx) => { await ctx.db.insert("pendingCancelation", { workId, - segment, + segment: toTimestamp(fromSegment(segment)), }); }); @@ -1080,16 +1080,16 @@ describe("state machine", () => { await ctx.db.patch("work", wId, { pendingStartId: await ctx.db.insert("pendingStart", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }), }); await ctx.db.insert("pendingCancelation", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); await ctx.db.insert("pendingCancelation", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); await ctx.db.insert("internalState", { @@ -1196,7 +1196,7 @@ describe("state machine", () => { }); await ctx.db.insert("pendingCompletion", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), retry: true, runResult: { kind: "failed", error: "test" }, }); @@ -1291,24 +1291,24 @@ describe("state machine", () => { await ctx.db.insert("pendingCompletion", { workId: w1, - segment: seg, + segment: toTimestamp(fromSegment(seg)), retry: false, runResult: { kind: "success", returnValue: null }, }); await ctx.db.patch("work", w2, { pendingStartId: await ctx.db.insert("pendingStart", { workId: w2, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }), }); await ctx.db.insert("pendingCancelation", { workId: w2, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); await ctx.db.patch("work", w3, { pendingStartId: await ctx.db.insert("pendingStart", { workId: w3, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }), }); @@ -1383,13 +1383,13 @@ describe("state machine", () => { // Pending retry + pending cancel at the same time await ctx.db.insert("pendingCompletion", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), retry: true, runResult: { kind: "failed", error: "test" }, }); await ctx.db.insert("pendingCancelation", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); return wId; From 15b68566c021a71f18666f09e69444e073afd9d4 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:32:10 -0700 Subject: [PATCH 06/15] perf(queue): avoid redundant cancellation reads and writes --- src/component/loop.test.ts | 13 +++++++++++++ src/component/loop.ts | 5 +++-- 2 files changed, 16 insertions(+), 2 deletions(-) diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index ea05f0d7..913c1f54 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -670,6 +670,19 @@ describe("loop", () => { // ──────────────────────────────────────────────────────────────────── describe("cancellation", () => { + it("removes queued work even when it is already marked canceled", async () => { + await initialize(); + const workId = await enqueueWork({ canceled: true }); + await t.mutation(api.lib.cancel, { id: workId }); + + await runLoop(); + + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.pendingCancelation).toHaveLength(0); + expect(o.running).toHaveLength(0); + }); + it("removes a pendingStart cancellation before the work runs", async () => { await initialize(); const workId = await enqueueWork(); diff --git a/src/component/loop.ts b/src/component/loop.ts index 40d8cceb..19933fe1 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -544,7 +544,6 @@ async function handleCancelation( const jobs: CompleteJob[] = [...toCancel]; await Promise.all( canceled.map(async ({ pendingId, workId }) => { - if (!(await ctx.db.get("pendingCancelation", pendingId))) return; await ctx.db.delete("pendingCancelation", pendingId); if (canceledWork.has(workId)) { console.error(`[main] ${workId} already canceled`); @@ -557,7 +556,9 @@ async function handleCancelation( return; } // Prevent retries even if the work is already running. - await ctx.db.patch("work", workId, { canceled: true }); + if (!work.canceled) { + await ctx.db.patch("work", workId, { canceled: true }); + } const pendingStart = await findPendingStart(ctx, work); if (!pendingStart) return; await ctx.db.delete("pendingStart", pendingStart._id); From 1e36e7dee8800adbf94f83e5f2db7f94fae6b2e9 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:33:37 -0700 Subject: [PATCH 07/15] fix(queue): gate starts on wall-clock time --- src/component/loop.test.ts | 36 ++++++++++++++++++++++++++++++------ src/component/loop.ts | 7 ++++--- src/component/shared.ts | 5 ----- 3 files changed, 34 insertions(+), 14 deletions(-) diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index 913c1f54..1b12c072 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -22,6 +22,7 @@ import { DEFAULT_MAX_PARALLELISM, fromSegment, fromTimestamp, + snapshotTs, toSegment, toTimestamp, WORKER_NAME, @@ -117,12 +118,16 @@ describe("loop", () => { }); } - /** - * Drive one loop iteration the way batch-worker does: get the next batch, - * and if there's work, run the worker mutation with it. Returns the batch - * result so tests can inspect the idle/work decision. - */ + async function advanceClockToSnapshot() { + // convex-test advances commit timestamps even while the fake clock is frozen. + const snapshot = await t.query(async () => snapshotTs()); + const snapshotMs = Number((snapshot + 999_999n) / 1_000_000n); + if (snapshotMs > Date.now()) vi.setSystemTime(snapshotMs); + } + + /** Run getBatch and run in one transaction. */ async function runLoop() { + await advanceClockToSnapshot(); return t.run(async (ctx) => { const result = await ctx.runQuery(internal.loop.getBatch, { name: WORKER_NAME, @@ -735,6 +740,24 @@ describe("loop", () => { // ──────────────────────────────────────────────────────────────────── describe("getBatch", () => { + it("waits for wall time when the snapshot clock is ahead", async () => { + await initialize(); + const now = Date.now(); + vi.setSystemTime(now + SECOND); + const workId = await enqueueWork(); + vi.setSystemTime(now); + + const result = await t.query(internal.loop.getBatch, { + name: WORKER_NAME, + }); + expect(result.kind).toBe("idle"); + expect((await observe()).running).toHaveLength(0); + + vi.setSystemTime(now + SECOND); + await runLoop(); + expect((await observe()).running.map((r) => r.workId)).toEqual([workId]); + }); + it("returns idle when there's nothing to do", async () => { await initialize(); const result = await t.query(internal.loop.getBatch, { @@ -775,6 +798,7 @@ describe("loop", () => { it("returns a work batch when a pending start is ready", async () => { await initialize(); const workId = await enqueueWork(); + await advanceClockToSnapshot(); const result = await t.query(internal.loop.getBatch, { name: WORKER_NAME, }); @@ -818,7 +842,7 @@ describe("loop", () => { const second = await runLoop(); assert(second.kind === "idle"); - expect(second.timeoutMs).toBe(100 * SECOND); + expect(second.timeoutMs).toBe(runAt - Date.now()); // It starts when it comes due, untouched in the meantime. vi.setSystemTime(runAt); diff --git a/src/component/loop.ts b/src/component/loop.ts index 19933fe1..d2e0eb75 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -20,7 +20,6 @@ import { import { type Config, DEFAULT_MAX_PARALLELISM, - eligibilityBound, fromTimestamp, fromSegment, maxBigint, @@ -194,7 +193,7 @@ export const getBatch = internalQuery({ // completions can wake us sooner, including when all slots are occupied. const futureStart = await ctx.db .query("pendingStart") - .withIndex("segment", (q) => q.gt("segment", eligibilityBound())) + .withIndex("segment", (q) => q.gt("segment", toTimestamp(Date.now()))) .first(); const waits: number[] = []; if (futureStart) { @@ -449,7 +448,9 @@ async function queryPending( const stream = ctx.db .query("pendingStart") .withIndex("segment", (q) => - q.gte("segment", incomingCursor).lte("segment", eligibilityBound()), + q + .gte("segment", incomingCursor) + .lte("segment", toTimestamp(Date.now())), ); for await (const doc of stream) { const segment = doc.segment as bigint; diff --git a/src/component/shared.ts b/src/component/shared.ts index a781cc8a..b07f6d4e 100644 --- a/src/component/shared.ts +++ b/src/component/shared.ts @@ -83,11 +83,6 @@ export function maxBigint(a: bigint, b: bigint): bigint { return a > b ? a : b; } -/** Work is eligible when either the snapshot or the wall clock reaches its key. */ -export function eligibilityBound(): bigint { - return maxBigint(snapshotTs(), toTimestamp(Date.now())); -} - // Separates legacy 100ms buckets from timestamps within the scheduling bounds. export const MIN_TIMESTAMP = toTimestamp(Date.UTC(2000, 0, 1)); From 82089f738cf9485768db9de85759132cf0c7c16e Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:33:53 -0700 Subject: [PATCH 08/15] perf(stats): restore bounded backlog reporting in the loop --- src/component/stats.test.ts | 29 +++++++++++++++------- src/component/stats.ts | 49 +++++++++++++++++++++++++++++-------- 2 files changed, 59 insertions(+), 19 deletions(-) diff --git a/src/component/stats.test.ts b/src/component/stats.test.ts index 3ec27176..a6c4fdf1 100644 --- a/src/component/stats.test.ts +++ b/src/component/stats.test.ts @@ -71,8 +71,8 @@ describe("stats reports", () => { }); }); - it("counts queue documents including scheduled and legacy entries", async () => { - await enqueue(toTimestamp(Date.now())); + it("reports a small eligible backlog without scheduling a count", async () => { + await enqueue(toTimestamp(Date.now() - 500)); await enqueue(toSegment(Date.now())); await enqueue(toTimestamp(Date.now() - 1000)); await enqueue(toSegment(Date.now() + 60_000)); @@ -81,7 +81,7 @@ describe("stats reports", () => { ctx.db.patch("internalState", stateId, { segmentCursors: { ...INITIAL_STATE.segmentCursors, - incoming: toTimestamp(Date.now()), + incoming: toTimestamp(Date.now() - 1500), }, }), ); @@ -89,16 +89,21 @@ describe("stats reports", () => { expect(reports()).toEqual([ expect.objectContaining({ event: "report", - backlog: 5, + backlog: 2, running: 0, failureRate: 0.4, permanentFailureRate: 0.25, }), ]); + await t.run(async (ctx) => { + expect( + await ctx.db.system.query("_scheduled_functions").collect(), + ).toHaveLength(0); + }); }); - it("reports large queues without scanning documents or scheduling follow-up reports", async () => { - for (let i = 0; i < 300; i++) await enqueue(toTimestamp(Date.now())); + it("defers a large backlog count after a bounded read", async () => { + for (let i = 0; i < 300; i++) await enqueue(toTimestamp(Date.now() - 1000)); await t.run(async (ctx) => { const state = (await ctx.db.get("internalState", stateId))!; const before = await ctx.meta.getTransactionMetrics(); @@ -107,11 +112,17 @@ describe("stats reports", () => { logLevel: "REPORT", }); const after = await ctx.meta.getTransactionMetrics(); - expect(after.documentsRead.used - before.documentsRead.used).toBe(0); expect( - await ctx.db.system.query("_scheduled_functions").collect(), - ).toHaveLength(0); + after.documentsRead.used - before.documentsRead.used, + ).toBeLessThanOrEqual(11); + const scheduled = await ctx.db.system + .query("_scheduled_functions") + .collect(); + expect(scheduled).toHaveLength(1); + expect(scheduled[0].name).toBe("stats:calculateBacklogAndReport"); }); + expect(reports()).toEqual([]); + await t.finishAllScheduledFunctions(vi.runAllTimers); expect(reports()).toEqual([expect.objectContaining({ backlog: 300 })]); }); diff --git a/src/component/stats.ts b/src/component/stats.ts index b6167225..2bad28a0 100644 --- a/src/component/stats.ts +++ b/src/component/stats.ts @@ -5,10 +5,16 @@ import { internalQuery, type MutationCtx, } from "./_generated/server.js"; -import { type Config, DEFAULT_MAX_PARALLELISM, WORKER_NAME } from "./shared.js"; +import { + type Config, + DEFAULT_MAX_PARALLELISM, + WORKER_NAME, + toTimestamp, +} from "./shared.js"; import { createLogger, type Logger, logLevel, shouldLog } from "./logging.js"; -import { components } from "./_generated/api.js"; +import { components, internal } from "./_generated/api.js"; import schema from "./schema.js"; +import { paginator } from "convex-helpers/server/pagination"; /** * Record stats about work execution. Intended to be queried by Axiom or Datadog. @@ -65,20 +71,43 @@ export async function generateReport( ctx: MutationCtx, console: Logger, state: Doc<"internalState">, - { logLevel }: Config, + { maxParallelism, logLevel }: Config, ) { if (!shouldLog(logLevel, "REPORT")) { + // Don't waste time if we're not going to log. return; } - // Count queued work, including future work, without scanning documents. - recordReport(console, { - ...state.report, - running: state.running.length, - backlog: await (ctx.db.query("pendingStart") as any).count(), - }); + const currentSegment = toTimestamp(Date.now()); + const pendingStart = await paginator(ctx.db, schema) + .query("pendingStart") + .withIndex("segment", (q) => + q + .gte("segment", state.segmentCursors.incoming) + .lt("segment", currentSegment), + ) + .paginate({ + numItems: Math.max(maxParallelism, 10), + cursor: null, + }); + if (pendingStart.isDone) { + recordReport(console, { + ...state.report, + running: state.running.length, + backlog: pendingStart.page.length, + }); + } else { + await ctx.scheduler.runAfter(0, internal.stats.calculateBacklogAndReport, { + startSegment: 0n, + endSegment: currentSegment, + cursor: pendingStart.continueCursor, + report: state.report, + running: state.running.length, + logLevel, + }); + } } -/** Compatibility handler for reports already scheduled by older versions. */ +/** Count large backlogs outside the main loop. */ export const calculateBacklogAndReport = internalMutation({ args: { // @deprecated Unused; accepted so in-flight calls from older versions From 786a0d59d60cc379381aebf4ef98df22a8c34534 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:50:25 -0700 Subject: [PATCH 09/15] refactor(queue): select start capacity once per batch --- src/component/loop.test.ts | 80 ++++++++++++++++++++++++++++++++++++++ src/component/loop.ts | 45 ++++++++++----------- 2 files changed, 100 insertions(+), 25 deletions(-) diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index 1b12c072..b0db7e59 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -287,6 +287,63 @@ describe("loop", () => { // ──────────────────────────────────────────────────────────────────── describe("capacity", () => { + it.each(["duplicate", "non-running"] as const)( + "does not reserve a start slot for a %s completion", + async (extraCompletion) => { + await initialize({ maxParallelism: 2 }); + const finished = await enqueueWork(); + const stillRunning = await enqueueWork(); + await runLoop(); + await simulateCompletion(finished, { + kind: "success", + returnValue: null, + }); + await t.run(async (ctx) => { + const workId = + extraCompletion === "duplicate" + ? finished + : await ctx.db.insert("work", { + fnType: "action", + fnHandle: "test_handle", + fnName: "test_handle", + fnArgs: {}, + attempts: 0, + }); + await ctx.db.insert("pendingCompletion", { + workId, + runResult: { kind: "success", returnValue: null }, + retry: false, + segment: ctx.db.vars.commitTs, + }); + }); + const next = await enqueueWork(); + const overflow = await enqueueWork(); + + const result = await runLoop(); + assert(result.kind === "work"); + expect(result.batch.completions).toHaveLength(2); + expect([ + ...result.batch.sweepStarts, + ...result.batch.starts, + ]).toHaveLength(1); + expect((await observe()).running.map((r) => r.workId)).toEqual([ + stillRunning, + next, + ]); + expect(await statusOf(overflow)).toMatchObject({ state: "pending" }); + + await simulateCompletion(stillRunning, { + kind: "success", + returnValue: null, + }); + await runLoop(); + expect((await observe()).running.map((r) => r.workId)).toEqual([ + next, + overflow, + ]); + }, + ); + it("never starts more than maxParallelism in one iteration", async () => { await initialize({ maxParallelism: 3 }); for (let i = 0; i < 7; i++) await enqueueWork(); @@ -1010,6 +1067,29 @@ describe("loop", () => { expect(readyId).toBeDefined(); }); + it("starts sweep entries in segment order before the ready scan", async () => { + await initialize({ maxParallelism: 5 }); + const running = await enqueueWork(); + await runLoop(); + const cursor = (await observe()).segmentCursors!.incoming; + const newer = await enqueueBehindCursor(cursor); + const older = await enqueueBehindCursor(cursor - 1n); + const ready = await enqueueWork(); + const laterReady = await enqueueWork(); + + await runLoop(); + + const o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([ + running, + older, + newer, + ready, + laterReady, + ]); + expect(o.pendingStart).toHaveLength(0); + }); + it("waits for capacity to retire an out-of-order entry, without losing it", async () => { await initialize({ maxParallelism: 1 }); const firstId = await enqueueWork(); diff --git a/src/component/loop.ts b/src/component/loop.ts index d2e0eb75..be684d60 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -153,7 +153,7 @@ export const getBatch = internalQuery({ incomingCursor: cursors.incoming, sweepCursor: cursors.sweep ?? 0n, maxParallelism: globals.maxParallelism, - runningCount: running.length, + running, }); // The sweep counts as work when it found entries to start or moved past @@ -277,15 +277,11 @@ export const run = internalMutation({ state.lastRecovery = nowTs; } - // Merge the segment scan and sweep in eligibility order. - const eligible = [...batch.starts, ...batch.sweepStarts].sort((a, b) => + // Sweep entries precede the cursor; the segment scan is already ordered. + batch.sweepStarts.sort((a, b) => a.segment < b.segment ? -1 : a.segment > b.segment ? 1 : 0, ); - - // Slice to actual available capacity (completions may have freed slots). - // Guard against negative numbers in case running.length > maxParallelism. - const actualCapacity = globals.maxParallelism - state.running.length; - const pending = actualCapacity > 0 ? eligible.slice(0, actualCapacity) : []; + const pending = [...batch.sweepStarts, ...batch.starts]; const startLabel = `[main] pendingStart(${pending.length})`; console.time(startLabel); await handleStart(ctx, state, pending, console, globals); @@ -322,21 +318,16 @@ export const run = internalMutation({ if (batch.cancelations.length > 0) { state.segmentCursors.cancelation = batch.cancelations.at(-1)!.segment; } - // Advance only across handled entries, capped at the snapshot so racing + // Every selected start was handled. Cap at the snapshot so racing // commits remain ahead. Inclusive reads retain entries sharing a timestamp. - const handled = new Set(pending.map((s) => s.pendingId)); const snapshot = snapshotTs(); - for (const start of batch.starts) { - if (!handled.has(start.pendingId)) break; + const lastStart = batch.starts.at(-1); + if (lastStart) { state.segmentCursors.incoming = - start.segment < snapshot ? start.segment : snapshot; + lastStart.segment < snapshot ? lastStart.segment : snapshot; } - // Advance the sweep only after handling every entry it selected. // Entries left at the boundary stamp are revisited by an inclusive read. - if ( - batch.sweepStop !== undefined && - batch.sweepStarts.every((s) => handled.has(s.pendingId)) - ) { + if (batch.sweepStop !== undefined) { state.segmentCursors.sweep = maxBigint( state.segmentCursors.sweep ?? 0n, batch.sweepStop, @@ -359,14 +350,14 @@ async function queryPending( incomingCursor, sweepCursor, maxParallelism, - runningCount, + running, }: { completionCursor: bigint; cancelationCursor: bigint; incomingCursor: bigint; sweepCursor: bigint; maxParallelism: number; - runningCount: number; + running: Doc<"internalState">["running"]; }, ) { const completions = await ctx.db @@ -377,17 +368,21 @@ async function queryPending( .query("pendingCancelation") .withIndex("segment", (q) => q.gte("segment", cancelationCursor)) .take(CANCELLATION_BATCH_SIZE); - // Available slots after we process this batch's completions. Cap at - // MAIN_BATCH_SIZE so a single iteration's per-item writes (delete - // pendingStart + scheduler.runAfter) don't grow unbounded. + // Only completions for running jobs free slots, even if duplicated. + const completed = new Set(completions.map((c) => c.workId)); + const remainingRunning = running.filter( + (r) => !completed.has(r.workId), + ).length; + // Bound per-iteration writes. getBatch and run share a snapshot, so every + // selected start fits after completions are processed. const startLimit = Math.min( MAIN_BATCH_SIZE, - Math.max(0, maxParallelism - runningCount + completions.length), + Math.max(0, maxParallelism - remainingRunning), ); // Work completing or canceling this iteration is skipped when reading; the // same iteration removes those entries, so the cursors may pass them. const excluded = new Set([ - ...completions.map((c) => c.workId), + ...completed, ...cancelations.map((c) => c.workId), ]); From a1b3af03e6a62916a7131ec68f92d31f47913af4 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 16:55:09 -0700 Subject: [PATCH 10/15] fix(queue): preserve legacy start ordering during upgrade --- src/component/README.md | 2 +- src/component/loop.test.ts | 26 ++++++++++++++++++++++++++ src/component/loop.ts | 5 ++--- 3 files changed, 29 insertions(+), 4 deletions(-) diff --git a/src/component/README.md b/src/component/README.md index a2635d6a..5a577aed 100644 --- a/src/component/README.md +++ b/src/component/README.md @@ -49,6 +49,6 @@ pings are no-ops rather than racing an idle transition. cancels. - Read queues through bounded index ranges and point-read work documents. - Keep the incoming cursor at or below the transaction snapshot so later commits - remain reachable. Re-key future legacy buckets during upgrade. + remain reachable. Convert legacy buckets before resetting the cursors. - Limit the sweep's boundary read to entries behind the incoming cursor, so large batches of future work are not repeatedly scanned. diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index b0db7e59..d923b8b0 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -532,6 +532,32 @@ describe("loop", () => { }, ); + it("preserves the time ordering of overdue legacy work", async () => { + await initialize({ maxParallelism: 1 }); + const now = Date.now(); + const newer = await enqueueLegacyWork(now + 2 * SECOND); + const older = await enqueueLegacyWork(now + SECOND); + vi.setSystemTime(now + 3 * SECOND); + // Advance the snapshot past both scheduled times. + await t.run(async () => null); + + await runLoop(); // upgrade + await runLoop(); + + let o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([older]); + expect(o.pendingStart).toHaveLength(1); + expect(o.pendingStart[0].segment).toBe( + toTimestamp(fromSegment(toSegment(now + 2 * SECOND))), + ); + + await simulateCompletion(older, { kind: "success", returnValue: null }); + await runLoop(); + o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([newer]); + expect(o.pendingStart).toHaveLength(0); + }); + it("starts work that was already due", async () => { await initialize(); const workId = await enqueueLegacyWork(Date.now()); diff --git a/src/component/loop.ts b/src/component/loop.ts index be684d60..84f32f51 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -224,8 +224,7 @@ export const run = internalMutation({ handler: async (ctx, batch) => { const state = await getOrCreateState(ctx); if (batch.upgrade) { - // Repair old pointers and keys once, before normal cursors can pass them. - const snapshot = snapshotTs(); + // Preserve legacy times; cursors reset after the upgrade finishes. for (const start of batch.upgrade.starts) { const work = await ctx.db.get("work", start.workId); if (!work) { @@ -236,7 +235,7 @@ export const run = internalMutation({ pendingStartId: start.pendingId, }); await ctx.db.patch("pendingStart", start.pendingId, { - segment: maxBigint(toTimestamp(fromSegment(start.segment)), snapshot), + segment: toTimestamp(fromSegment(start.segment)), }); } await ctx.db.patch("internalState", state._id, { From 5c9f124a64d61ab84b1017f99f280678709c1b9c Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 9 Sep 2026 23:21:08 -0700 Subject: [PATCH 11/15] test(queue): derive recovery timing from the production period --- src/component/stateMachine.test.ts | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/src/component/stateMachine.test.ts b/src/component/stateMachine.test.ts index be1e052d..2b97d94d 100644 --- a/src/component/stateMachine.test.ts +++ b/src/component/stateMachine.test.ts @@ -11,10 +11,13 @@ import { import { api, internal } from "./_generated/api.js"; import type { Doc, Id } from "./_generated/dataModel.js"; import type { MutationCtx } from "./_generated/server.js"; +import { RECOVERY_PERIOD_NS } from "./loop.js"; import { DEFAULT_MAX_PARALLELISM, fromSegment, + fromTimestamp, getCurrentSegment, + toSegment, toTimestamp, SECOND, WORKER_NAME, @@ -167,7 +170,7 @@ const S12_CANCELED_AWAITING_COMPLETE: CompositeState = { const ACTION_RECOVERY_THRESHOLD_MS = 5 * 60 * 1000; /** One recovery period in the 100ms buckets `runLoop` picks times with. */ -const RECOVERY_PERIOD_SEGMENTS = 600n; +const RECOVERY_PERIOD_SEGMENTS = toSegment(fromTimestamp(RECOVERY_PERIOD_NS)); /** The bucket after the current one, as older versions computed it. */ function getNextSegment(): bigint { @@ -266,7 +269,7 @@ describe("state machine", () => { // Set up internalState const lastRecovery = opts?.oldForRecovery - ? toTimestamp(Date.now() - 61 * SECOND) + ? toTimestamp(Date.now() - SECOND) - RECOVERY_PERIOD_NS : toTimestamp(Date.now()); await ctx.db.insert("internalState", { segmentCursors: { From 98666b0a1882b47fe352066a3bc76677a215a868 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Tue, 15 Sep 2026 16:13:52 -0700 Subject: [PATCH 12/15] feedback --- src/component/lib.ts | 31 ++++++++++++++++++------------- src/component/loop.ts | 20 ++++++++------------ 2 files changed, 26 insertions(+), 25 deletions(-) diff --git a/src/component/lib.ts b/src/component/lib.ts index 929b9f13..a4bbf3b4 100644 --- a/src/component/lib.ts +++ b/src/component/lib.ts @@ -115,19 +115,24 @@ export async function enqueueHandler( // Store the work item const workId = await ctx.db.insert("work", workItem); const now = Date.now(); - const scheduled = runAt > now; - // Scheduled keys stay at or above the snapshot, which bounds the cursor. - const segment = scheduled - ? maxBigint(toTimestamp(runAt), snapshotTs()) - : ctx.db.vars.commitTs; - const pendingStartId = await ctx.db.insert("pendingStart", { - workId, - segment, - // Only near-term starts can commit behind the cursor. - ...(scheduled && (segment as bigint) <= toTimestamp(now + 5 * MINUTE) - ? { scanTs: ctx.db.vars.commitTs } - : {}), - }); + let pendingStartId: Id<"pendingStart">; + if (runAt > now) { + // Scheduled keys stay at or above the snapshot, which bounds the cursor. + const segment = maxBigint(toTimestamp(runAt), snapshotTs()); + pendingStartId = await ctx.db.insert("pendingStart", { + workId, + segment, + // Only near-term starts can commit behind the cursor. + ...(segment <= toTimestamp(now + 5 * MINUTE) + ? { scanTs: ctx.db.vars.commitTs } + : {}), + }); + } else { + pendingStartId = await ctx.db.insert("pendingStart", { + workId, + segment: ctx.db.vars.commitTs, + }); + } await ctx.db.patch("work", workId, { pendingStartId }); recordEnqueued(console, { workId, fnName: workArgs.fnName, runAt }); return workId; diff --git a/src/component/loop.ts b/src/component/loop.ts index 84f32f51..8d4ab945 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -386,9 +386,7 @@ async function queryPending( ]); // Rescue scheduled entries that committed behind the incoming cursor. - // Revisit only that subset at the boundary scanTs, then inspect later stamps. - // The compound index sorts behind-cursor entries first within each stamp, - // so stopping midway is safe and future entries need not be rescanned. + // The scanTs index orders enqueues by commit time, then by segment. const sweepStarts: Start[] = []; let sweepStop: bigint | undefined; { @@ -402,8 +400,8 @@ async function queryPending( return ++docs >= SWEEP_DOC_BATCH ? "stop" : "more"; }; - // (1) Out-of-order entries left at the boundary stamp. Nothing at or above - // the cursor is read, so a bulk enqueue sharing this stamp costs nothing. + // At sweepCursor, revisit only entries behind incomingCursor. + // The index skips entries the normal segment scan can still reach. let boundaryDone = true; for await (const doc of ctx.db .query("pendingStart") @@ -416,16 +414,15 @@ async function queryPending( } } - // (2) Later stamps. Reaching one is what lets the cursor move off the - // boundary; until then it stays put and (1) repeats, which is cheap. + // Advance through newer scanTs values. The next iteration resumes at + // sweepStop using the restricted query above. if (boundaryDone) { for await (const doc of ctx.db .query("pendingStart") .withIndex("scanTs", (q) => q.gt("scanTs", sweepCursor))) { const scanTs = doc.scanTs as bigint; const behind = (doc.segment as bigint) < incomingCursor; - // Not behind: the segment scan owns it. Pass over it so the cursor can - // advance, without reading its entries. + // The normal segment scan handles entries at or above incomingCursor. if (behind && take(doc) === "stop") break; sweepStop = scanTs; if (!behind && ++docs >= SWEEP_DOC_BATCH) break; @@ -787,9 +784,8 @@ async function rescheduleJob( work.retryBehavior.initialBackoffMs * Math.pow(work.retryBehavior.base, work.attempts - 1); const nextAttempt = withJitter(backoffMs); - // Raised to at least the snapshot, which the cursor may reach this run, so - // the retry can't land behind it; a backoff shorter than the clocks' skew - // just starts next iteration. + // Keep retries at or above the snapshot so they cannot land behind the cursor. + // TODO: Remove the snapshot floor once convex-test guarantees snapshotTs <= Date.now(). const segment = maxBigint( toTimestamp(Date.now() + nextAttempt), snapshotTs(), From fd7a160b2f48d7ed865aa3ff7c3bd142635312da Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 15 Jul 2026 19:58:49 -0700 Subject: [PATCH 13/15] attempt recovery of wedged mutations --- src/component/complete.ts | 28 ++++++--- src/component/loop.ts | 47 +++++++++++--- src/component/recovery.test.ts | 109 +++++++++++++++++++++++++++++++++ src/component/recovery.ts | 38 +++++++++++- src/component/schema.ts | 14 ++++- src/component/stats.ts | 7 ++- 6 files changed, 221 insertions(+), 22 deletions(-) diff --git a/src/component/complete.ts b/src/component/complete.ts index 80fc84e8..228ab93c 100644 --- a/src/component/complete.ts +++ b/src/component/complete.ts @@ -5,7 +5,8 @@ import { internal } from "./_generated/api.js"; import { internalMutation, type MutationCtx } from "./_generated/server.js"; import { kickMainLoop } from "./kick.js"; import { createLogger } from "./logging.js"; -import { type OnCompleteArgs, type RunResult, vResult } from "./shared.js"; +import { type OnCompleteArgs } from "./shared.js"; +import { type RunResultInternal, vResultInternal } from "./schema.js"; import { recordCompleted } from "./stats.js"; import { assert } from "convex-helpers"; @@ -14,7 +15,7 @@ export type CompleteJob = Infer; const completeArgs = v.object({ jobs: v.array( v.object({ - runResult: vResult, + runResult: vResultInternal, workId: v.id("work"), attempt: v.number(), nonRetryable: v.optional(v.boolean()), @@ -34,7 +35,7 @@ export async function completeHandler( return; } const pendingCompletions: { - runResult: RunResult; + runResult: RunResultInternal; workId: Id<"work">; retry: boolean; }[] = []; @@ -114,12 +115,19 @@ export async function completeHandler( return; } const maxAttempts = work.retryBehavior?.maxAttempts; + // stuckInScheduler is always retried — the function never ran, so + // nonRetryable / maxAttempts gates don't apply. Main loop will + // re-enqueue with 0 backoff. const retry = - job.runResult.kind === "failed" && - !job.nonRetryable && - !!maxAttempts && - work.attempts < maxAttempts; + job.runResult.kind === "stuckInScheduler" || + (job.runResult.kind === "failed" && + !job.nonRetryable && + !!maxAttempts && + work.attempts < maxAttempts); if (!retry) { + // stuckInScheduler is always a retry, so it can't reach here. + assert(job.runResult.kind !== "stuckInScheduler"); + const terminalResult = job.runResult; let scheduledId = undefined; if ( work.onComplete && @@ -143,7 +151,7 @@ export async function completeHandler( const onCompleteArgs = { workId: work._id, context, - result: job.runResult, + result: terminalResult, }; if (job.runOnCompleteInline) { try { @@ -176,7 +184,7 @@ export async function completeHandler( // TODO: store failures in a table for later debugging } } - recordCompleted(console, work, job.runResult.kind, scheduledId); + recordCompleted(console, work, terminalResult.kind, scheduledId); // Clean up any large data that was stored separately. Deleting a // nonexistent doc throws; this cleanup must not fail the completion. @@ -220,7 +228,7 @@ export async function completeHandler( } } -function stripResult(result: RunResult): RunResult { +function stripResult(result: RunResultInternal): RunResultInternal { if (result.kind === "success") { return { kind: "success", returnValue: null }; } diff --git a/src/component/loop.ts b/src/component/loop.ts index 8d4ab945..bf03ab9d 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -28,9 +28,9 @@ import { SECOND, snapshotTs, toTimestamp, - vResult, } from "./shared.js"; import { generateReport, recordCompleted, recordStarted } from "./stats.js"; +import { vResultInternal } from "./schema.js"; import { findPendingStart } from "./pendingStart.js"; const CANCELLATION_BATCH_SIZE = 64; // the only queue that can get unbounded. @@ -61,6 +61,7 @@ export const INITIAL_STATE: WithoutSystemFields> = { failed: 0, retries: 0, canceled: 0, + conflicted: 0, lastReportTs: 0, }, running: [], @@ -71,7 +72,7 @@ export const INITIAL_STATE: WithoutSystemFields> = { const vCompletion = v.object({ pendingId: v.id("pendingCompletion"), workId: v.id("work"), - runResult: vResult, + runResult: vResultInternal, retry: v.boolean(), segment: v.int64(), }); @@ -304,6 +305,7 @@ export const run = internalMutation({ failed: 0, retries: 0, canceled: 0, + conflicted: 0, lastReportTs, }; } @@ -487,9 +489,21 @@ async function handleCompletions( console.warn(`[main] ${c.workId} is gone, but trying to complete`); return; } - if (await rescheduleJob(ctx, work, console)) { - state.report.retries++; - recordCompleted(console, work, "retrying", undefined); + const wasStuckInScheduler = c.runResult.kind === "stuckInScheduler"; + const retried = await rescheduleJob( + ctx, + work, + console, + wasStuckInScheduler, + ); + if (retried) { + if (wasStuckInScheduler) { + state.report.conflicted = (state.report.conflicted ?? 0) + 1; + recordCompleted(console, work, "retrying conflicted", undefined); + } else { + state.report.retries++; + recordCompleted(console, work, "retrying", undefined); + } } else { // We don't retry if it's been canceled in the mean time. state.report.canceled++; @@ -603,9 +617,16 @@ async function handleRecovery( ) ).flatMap((r) => (r ? [r] : [])); state.running = state.running.filter((r) => !missing.has(r.workId)); + // Pass scheduledAt so the recovery handler can measure scheduler lag + // (`Date.now() - scheduledAt` when it actually runs) and judge stuck + // mutations relative to current backlog. + const scheduledAt = Date.now(); for (let i = 0; i < jobs.length; i += RECOVERY_BATCH_SIZE) { const batch = jobs.slice(i, i + RECOVERY_BATCH_SIZE); - await ctx.scheduler.runAfter(0, internal.recovery.recover, { jobs: batch }); + await ctx.scheduler.runAfter(0, internal.recovery.recover, { + jobs: batch, + scheduledAt, + }); } } @@ -758,6 +779,7 @@ async function rescheduleJob( ctx: MutationCtx, work: Doc<"work">, console: Logger, + wasStuckInScheduler: boolean, ): Promise { const pendingCancelation = await ctx.db .query("pendingCancelation") @@ -771,7 +793,16 @@ async function rescheduleJob( if (work.canceled) { return false; } - if (!work.retryBehavior) { + // stuckInScheduler retries immediately and doesn't need retryBehavior — + // the function never ran, so user-configured backoff doesn't apply. + let backoffMs: number; + if (wasStuckInScheduler) { + backoffMs = 0; + } else if (work.retryBehavior) { + backoffMs = + work.retryBehavior.initialBackoffMs * + Math.pow(work.retryBehavior.base, work.attempts - 1); + } else { console.warn(`[main] ${work._id} has no retryBehavior so not retrying`); return false; } @@ -783,7 +814,7 @@ async function rescheduleJob( const backoffMs = work.retryBehavior.initialBackoffMs * Math.pow(work.retryBehavior.base, work.attempts - 1); - const nextAttempt = withJitter(backoffMs); + const nextAttempt = wasStuckInScheduler ? 0 : withJitter(backoffMs); // Keep retries at or above the snapshot so they cannot land behind the cursor. // TODO: Remove the snapshot floor once convex-test guarantees snapshotTs <= Date.now(). const segment = maxBigint( diff --git a/src/component/recovery.test.ts b/src/component/recovery.test.ts index f72452ec..dd53cdbb 100644 --- a/src/component/recovery.test.ts +++ b/src/component/recovery.test.ts @@ -555,6 +555,115 @@ describe("recovery", () => { }); }); + it("should re-enqueue a mutation pending past the stuck threshold", async () => { + const [workId, scheduledId] = await t.run(async (ctx) => { + const workId = await makeDummyWork(ctx, { fnType: "mutation" }); + const scheduledId = await makeDummyScheduledFunction(ctx, workId); + return [workId, scheduledId]; + }); + + // Mutation scheduled 11 minutes ago, recovery scheduled 0ms ago: above + // the 10-minute stuck threshold + 0 lag. + const scheduledTime = Date.now() - 11 * 60 * 1000; + await t.run(async (ctx) => { + ctx.db.system.get = patchedSystemGet(ctx.db, { + [scheduledId]: { + _id: scheduledId, + _creationTime: scheduledTime, + name: "internal/worker.runMutationWrapper", + args: [{}], + scheduledTime, + state: { kind: "pending" }, + }, + }); + await recoveryHandler(ctx, { + jobs: [{ scheduledId, workId, attempt: 0, started: scheduledTime }], + scheduledAt: Date.now(), + }); + }); + + await t.run(async (ctx) => { + const pendingCompletions = await ctx.db + .query("pendingCompletion") + .withIndex("workId", (q) => q.eq("workId", workId)) + .collect(); + expect(pendingCompletions).toHaveLength(1); + expect(pendingCompletions[0].runResult.kind).toBe("stuckInScheduler"); + expect(pendingCompletions[0].retry).toBe(true); + }); + }); + + it("should not re-enqueue a pending mutation within scheduler lag", async () => { + const [workId, scheduledId] = await t.run(async (ctx) => { + const workId = await makeDummyWork(ctx, { fnType: "mutation" }); + const scheduledId = await makeDummyScheduledFunction(ctx, workId); + return [workId, scheduledId]; + }); + + // Mutation pending 11min, but recovery itself was scheduled 5min ago + // (so scheduler lag = 5min). 11min < 10min + 5min, so not stuck yet. + const scheduledTime = Date.now() - 11 * 60 * 1000; + const recoveryScheduledAt = Date.now() - 5 * 60 * 1000; + await t.run(async (ctx) => { + ctx.db.system.get = patchedSystemGet(ctx.db, { + [scheduledId]: { + _id: scheduledId, + _creationTime: scheduledTime, + name: "internal/worker.runMutationWrapper", + args: [{}], + scheduledTime, + state: { kind: "pending" }, + }, + }); + await recoveryHandler(ctx, { + jobs: [{ scheduledId, workId, attempt: 0, started: scheduledTime }], + scheduledAt: recoveryScheduledAt, + }); + }); + + await t.run(async (ctx) => { + const pendingCompletions = await ctx.db + .query("pendingCompletion") + .withIndex("workId", (q) => q.eq("workId", workId)) + .collect(); + expect(pendingCompletions).toHaveLength(0); + }); + }); + + it("should not re-enqueue pending actions", async () => { + const [workId, scheduledId] = await t.run(async (ctx) => { + const workId = await makeDummyWork(ctx, { fnType: "action" }); + const scheduledId = await makeDummyScheduledFunction(ctx, workId); + return [workId, scheduledId]; + }); + + const scheduledTime = Date.now() - 60 * 60 * 1000; // 1h pending + await t.run(async (ctx) => { + ctx.db.system.get = patchedSystemGet(ctx.db, { + [scheduledId]: { + _id: scheduledId, + _creationTime: scheduledTime, + name: "internal/worker.runActionWrapper", + args: [{}], + scheduledTime, + state: { kind: "pending" }, + }, + }); + await recoveryHandler(ctx, { + jobs: [{ scheduledId, workId, attempt: 0, started: scheduledTime }], + scheduledAt: Date.now(), + }); + }); + + await t.run(async (ctx) => { + const pendingCompletions = await ctx.db + .query("pendingCompletion") + .withIndex("workId", (q) => q.eq("workId", workId)) + .collect(); + expect(pendingCompletions).toHaveLength(0); + }); + }); + it("should not process jobs with other scheduled states", async () => { // Create work and scheduled function const [workId, scheduledId] = await t.run(async (ctx) => { diff --git a/src/component/recovery.ts b/src/component/recovery.ts index 47436bbd..ce01aed6 100644 --- a/src/component/recovery.ts +++ b/src/component/recovery.ts @@ -2,6 +2,7 @@ import { type Infer, v } from "convex/values"; import { internalMutation, type MutationCtx } from "./_generated/server.js"; import { createLogger } from "./logging.js"; import { type CompleteJob, completeHandler } from "./complete.js"; +import { MINUTE } from "./shared.js"; const recoveryArgs = v.object({ jobs: v.array( @@ -12,8 +13,19 @@ const recoveryArgs = v.object({ started: v.number(), }), ), + // Time at which the main loop scheduled this recovery to run (≈ Date.now() + // at scheduling time, since we use runAfter(0, ...)). We use the delta vs. + // now to estimate how backlogged the scheduler is, then judge "stuck" + // relative to that lag — see MUTATION_STUCK_THRESHOLD_MS below. + scheduledAt: v.optional(v.number()), }); +// A mutation that's been "pending" in the scheduler for this long beyond the +// current scheduler lag is treated as stuck. We cancel and re-enqueue it so +// it can free up a workpool slot — staying pending past the scheduler's own +// backlog usually means a doc-write conflict the scheduler keeps losing. +const MUTATION_STUCK_THRESHOLD_MS = 10 * MINUTE; + /** * This can run when things fail because of server failures / restarts, or when * the user cancels scheduled jobs (from the dashboard). @@ -37,10 +49,12 @@ export const recover = internalMutation({ // only exported for testing export async function recoveryHandler( ctx: MutationCtx, - { jobs }: Infer, + { jobs, scheduledAt }: Infer, ) { const globals = await ctx.db.query("globals").unique(); const console = createLogger(globals?.logLevel); + // If scheduledAt is omitted (older callers, or tests), treat lag as 0. + const schedulerLagMs = scheduledAt ? Math.max(0, Date.now() - scheduledAt) : 0; const completionJobs: CompleteJob[] = []; for (let i = 0; i < jobs.length; i++) { const job = jobs[i]; @@ -99,6 +113,28 @@ export async function recoveryHandler( }); break; } + case "pending": { + // We only re-enqueue mutations. Actions sitting in pending usually + // mean an overloaded scheduler — cancelling them doesn't help. + if (work.fnType !== "mutation") { + break; + } + const pendingMs = Date.now() - scheduled.scheduledTime; + if (pendingMs < MUTATION_STUCK_THRESHOLD_MS + schedulerLagMs) { + break; + } + console.warn( + `${preamble} pending in scheduler for ${pendingMs}ms ` + + `(lag ${schedulerLagMs}ms, threshold ${MUTATION_STUCK_THRESHOLD_MS}ms) — re-enqueueing`, + ); + await ctx.scheduler.cancel(scheduled._id); + completionJobs.push({ + workId: job.workId, + runResult: { kind: "stuckInScheduler" }, + attempt: job.attempt, + }); + break; + } } } if (completionJobs.length > 0) { diff --git a/src/component/schema.ts b/src/component/schema.ts index 564019f8..f711e990 100644 --- a/src/component/schema.ts +++ b/src/component/schema.ts @@ -1,5 +1,5 @@ import { defineSchema, defineTable } from "convex/server"; -import { v } from "convex/values"; +import { v, type Infer } from "convex/values"; import { fnType, vConfig, @@ -16,6 +16,16 @@ const segment = v.commitTs(); // Epoch time in nanoseconds. CommitTs resolves to this after committing. const timestamp = v.int64(); +// Internal-only RunResult kinds, used by recovery → complete → main loop. +// External callers (worker, onComplete) only ever see vResult. +export const vResultInternal = v.union( + vResult, + // Mutation was canceled by recovery because it sat in the scheduler + // beyond the stuck threshold; main loop must re-enqueue it. + v.object({ kind: v.literal("stuckInScheduler") }), +); +export type RunResultInternal = Infer; + export default defineSchema({ // Written from kickLoop, read everywhere. globals: defineTable(vConfig), @@ -84,7 +94,7 @@ export default defineSchema({ // Written by complete, read & deleted by `main`. pendingCompletion: defineTable({ segment, - runResult: vResult, + runResult: vResultInternal, workId: v.id("work"), retry: v.boolean(), }) diff --git a/src/component/stats.ts b/src/component/stats.ts index 2bad28a0..97e011fc 100644 --- a/src/component/stats.ts +++ b/src/component/stats.ts @@ -54,7 +54,12 @@ export function recordStarted( export function recordCompleted( console: Logger, work: Doc<"work">, - status: "success" | "failed" | "canceled" | "retrying", + status: + | "success" + | "failed" + | "canceled" + | "retrying" + | "retrying conflicted", onCompleteScheduledFunctionId: Id<"_scheduled_functions"> | undefined, ) { console.event("completed", { From d57007ffc5747e9b10e418b3b3559c3cdd52590b Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 15 Jul 2026 20:07:59 -0700 Subject: [PATCH 14/15] fix merge artifacts breaking the build Resolve batch-worker merge leftovers in loop.ts: - vCompletion.runResult now uses vResultInternal so stuckInScheduler flows through the batch to handleCompletions. - Remove the duplicate backoffMs block left by the merge (it redeclared the variable and dereferenced possibly-undefined work.retryBehavior). --- src/component/loop.ts | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/src/component/loop.ts b/src/component/loop.ts index bf03ab9d..30f33a04 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -29,8 +29,8 @@ import { snapshotTs, toTimestamp, } from "./shared.js"; -import { generateReport, recordCompleted, recordStarted } from "./stats.js"; import { vResultInternal } from "./schema.js"; +import { generateReport, recordCompleted, recordStarted } from "./stats.js"; import { findPendingStart } from "./pendingStart.js"; const CANCELLATION_BATCH_SIZE = 64; // the only queue that can get unbounded. @@ -811,9 +811,6 @@ async function rescheduleJob( console.error(`[main] ${work._id} already in pendingStart so not retrying`); return false; } - const backoffMs = - work.retryBehavior.initialBackoffMs * - Math.pow(work.retryBehavior.base, work.attempts - 1); const nextAttempt = wasStuckInScheduler ? 0 : withJitter(backoffMs); // Keep retries at or above the snapshot so they cannot land behind the cursor. // TODO: Remove the snapshot floor once convex-test guarantees snapshotTs <= Date.now(). From 14a510a6b56fdf90b80dbc8b91cd999a4c3dc978 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Thu, 17 Sep 2026 23:24:31 -0700 Subject: [PATCH 15/15] Simplify stuck mutation recovery with commit-ordered retries --- src/component/complete.ts | 28 +++----- src/component/loop.test.ts | 117 +++++++++++++++++++++++++++++++++ src/component/loop.ts | 53 ++++++--------- src/component/recovery.test.ts | 75 ++++++++++++--------- src/component/recovery.ts | 25 +++++-- src/component/schema.ts | 14 +--- 6 files changed, 213 insertions(+), 99 deletions(-) diff --git a/src/component/complete.ts b/src/component/complete.ts index 228ab93c..80fc84e8 100644 --- a/src/component/complete.ts +++ b/src/component/complete.ts @@ -5,8 +5,7 @@ import { internal } from "./_generated/api.js"; import { internalMutation, type MutationCtx } from "./_generated/server.js"; import { kickMainLoop } from "./kick.js"; import { createLogger } from "./logging.js"; -import { type OnCompleteArgs } from "./shared.js"; -import { type RunResultInternal, vResultInternal } from "./schema.js"; +import { type OnCompleteArgs, type RunResult, vResult } from "./shared.js"; import { recordCompleted } from "./stats.js"; import { assert } from "convex-helpers"; @@ -15,7 +14,7 @@ export type CompleteJob = Infer; const completeArgs = v.object({ jobs: v.array( v.object({ - runResult: vResultInternal, + runResult: vResult, workId: v.id("work"), attempt: v.number(), nonRetryable: v.optional(v.boolean()), @@ -35,7 +34,7 @@ export async function completeHandler( return; } const pendingCompletions: { - runResult: RunResultInternal; + runResult: RunResult; workId: Id<"work">; retry: boolean; }[] = []; @@ -115,19 +114,12 @@ export async function completeHandler( return; } const maxAttempts = work.retryBehavior?.maxAttempts; - // stuckInScheduler is always retried — the function never ran, so - // nonRetryable / maxAttempts gates don't apply. Main loop will - // re-enqueue with 0 backoff. const retry = - job.runResult.kind === "stuckInScheduler" || - (job.runResult.kind === "failed" && - !job.nonRetryable && - !!maxAttempts && - work.attempts < maxAttempts); + job.runResult.kind === "failed" && + !job.nonRetryable && + !!maxAttempts && + work.attempts < maxAttempts; if (!retry) { - // stuckInScheduler is always a retry, so it can't reach here. - assert(job.runResult.kind !== "stuckInScheduler"); - const terminalResult = job.runResult; let scheduledId = undefined; if ( work.onComplete && @@ -151,7 +143,7 @@ export async function completeHandler( const onCompleteArgs = { workId: work._id, context, - result: terminalResult, + result: job.runResult, }; if (job.runOnCompleteInline) { try { @@ -184,7 +176,7 @@ export async function completeHandler( // TODO: store failures in a table for later debugging } } - recordCompleted(console, work, terminalResult.kind, scheduledId); + recordCompleted(console, work, job.runResult.kind, scheduledId); // Clean up any large data that was stored separately. Deleting a // nonexistent doc throws; this cleanup must not fail the completion. @@ -228,7 +220,7 @@ export async function completeHandler( } } -function stripResult(result: RunResultInternal): RunResultInternal { +function stripResult(result: RunResult): RunResult { if (result.kind === "success") { return { kind: "success", returnValue: null }; } diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index d923b8b0..d1b8f7f5 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -1220,6 +1220,123 @@ describe("loop", () => { // ──────────────────────────────────────────────────────────────────── describe("recovery", () => { + it("requeues a stuck mutation in commit order and frees its slot for queued work", async () => { + await initialize({ maxParallelism: 1 }); + const workId = await enqueueWork({ fnType: "mutation" }); + await runLoop(); + const original = (await observe()).running[0]; + const nextWorkId = await enqueueWork({ fnType: "mutation" }); + + vi.setSystemTime(Date.now() + 11 * MINUTE); + const recovery = { + jobs: [{ ...original, attempt: 0 }], + scheduledAt: Date.now(), + }; + await t.mutation(internal.recovery.recover, recovery); + // Concurrently scheduled recovery calls must not create extra retries. + await t.mutation(internal.recovery.recover, recovery); + expect((await observe()).pendingCompletion).toHaveLength(1); + expect(await statusOf(workId)).toEqual({ + state: "pending", + previousAttempts: 1, + }); + expect( + await t.run( + async (ctx) => + ( + await ctx.db.system.get( + "_scheduled_functions", + original.scheduledId, + ) + )?.state.kind, + ), + ).toBe("canceled"); + + await runLoop(); + let o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([nextWorkId]); + expect(o.pendingCompletion).toHaveLength(0); + expect(o.pendingStart).toHaveLength(1); + const retry = o.pendingStart[0]; + expect(retry.workId).toBe(workId); + expect(retry.segment).toBeGreaterThan(o.segmentCursors!.incoming); + expect(retry.scanTs).toBeUndefined(); + expect(await t.run((ctx) => ctx.db.get("work", workId))).toMatchObject({ + pendingStartId: retry._id, + attempts: 1, + }); + + // Old completions and recovery calls stay stale after the retry signal + // has been consumed, and cannot remove or requeue this work again. + await simulateCompletion( + workId, + { kind: "success", returnValue: null }, + 0, + ); + await t.mutation(internal.recovery.recover, recovery); + expect((await observe()).pendingCompletion).toHaveLength(0); + expect((await observe()).pendingStart).toHaveLength(1); + + await simulateCompletion(nextWorkId, { + kind: "success", + returnValue: null, + }); + await runLoop(); + o = await observe(); + expect(o.running.map((r) => r.workId)).toEqual([workId]); + expect(o.running[0].scheduledId).not.toBe(original.scheduledId); + expect(o.pendingStart).toHaveLength(0); + const scheduled = await t.run((ctx) => + ctx.db.system.get("_scheduled_functions", o.running[0].scheduledId), + ); + expect(scheduled?.args[0]).toMatchObject({ + attempt: 1, + fnType: "mutation", + }); + + await simulateCompletion( + workId, + { kind: "success", returnValue: null }, + 1, + ); + await runLoop(); + expect(await statusOf(workId)).toEqual({ state: "finished" }); + expect((await observe()).running).toHaveLength(0); + }); + + it.each(["before", "after"])( + "honors cancellation %s mutation recovery", + async (when) => { + await initialize({ maxParallelism: 1 }); + const workId = await enqueueWork({ fnType: "mutation" }); + await runLoop(); + const original = (await observe()).running[0]; + vi.setSystemTime(Date.now() + 11 * MINUTE); + if (when === "before") await t.mutation(api.lib.cancel, { id: workId }); + await t.mutation(internal.recovery.recover, { + jobs: [{ ...original, attempt: 0 }], + scheduledAt: Date.now(), + }); + if (when === "after") await t.mutation(api.lib.cancel, { id: workId }); + + await runLoop(); + const o = await observe(); + expect(o.running).toHaveLength(0); + expect(o.pendingStart).toHaveLength(0); + expect(o.pendingCompletion).toHaveLength(0); + }, + ); + + it("does not retry ordinary mutation failures", async () => { + await initialize(); + const workId = await enqueueWork({ fnType: "mutation" }); + await runLoop(); + await simulateCompletion(workId, { kind: "failed", error: "User error" }); + await runLoop(); + expect(await statusOf(workId)).toEqual({ state: "finished" }); + expect((await observe()).pendingStart).toHaveLength(0); + }); + it("flags a recovery iteration and advances lastRecovery for silent workers", async () => { await initialize(); // Pre-populate state.running with an old entry. diff --git a/src/component/loop.ts b/src/component/loop.ts index 30f33a04..bc43ca2d 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -28,8 +28,8 @@ import { SECOND, snapshotTs, toTimestamp, + vResult, } from "./shared.js"; -import { vResultInternal } from "./schema.js"; import { generateReport, recordCompleted, recordStarted } from "./stats.js"; import { findPendingStart } from "./pendingStart.js"; @@ -72,7 +72,7 @@ export const INITIAL_STATE: WithoutSystemFields> = { const vCompletion = v.object({ pendingId: v.id("pendingCompletion"), workId: v.id("work"), - runResult: vResultInternal, + runResult: vResult, retry: v.boolean(), segment: v.int64(), }); @@ -489,15 +489,9 @@ async function handleCompletions( console.warn(`[main] ${c.workId} is gone, but trying to complete`); return; } - const wasStuckInScheduler = c.runResult.kind === "stuckInScheduler"; - const retried = await rescheduleJob( - ctx, - work, - console, - wasStuckInScheduler, - ); - if (retried) { - if (wasStuckInScheduler) { + if (await rescheduleJob(ctx, work, console)) { + // Mutations only retry when recovery replaces a stuck scheduler run. + if (work.fnType === "mutation") { state.report.conflicted = (state.report.conflicted ?? 0) + 1; recordCompleted(console, work, "retrying conflicted", undefined); } else { @@ -779,7 +773,6 @@ async function rescheduleJob( ctx: MutationCtx, work: Doc<"work">, console: Logger, - wasStuckInScheduler: boolean, ): Promise { const pendingCancelation = await ctx.db .query("pendingCancelation") @@ -793,31 +786,27 @@ async function rescheduleJob( if (work.canceled) { return false; } - // stuckInScheduler retries immediately and doesn't need retryBehavior — - // the function never ran, so user-configured backoff doesn't apply. - let backoffMs: number; - if (wasStuckInScheduler) { - backoffMs = 0; - } else if (work.retryBehavior) { - backoffMs = - work.retryBehavior.initialBackoffMs * - Math.pow(work.retryBehavior.base, work.attempts - 1); - } else { - console.warn(`[main] ${work._id} has no retryBehavior so not retrying`); - return false; - } if (await findPendingStart(ctx, work)) { // Not sure why this would ever happen, but ensure uniqueness explicitly. console.error(`[main] ${work._id} already in pendingStart so not retrying`); return false; } - const nextAttempt = wasStuckInScheduler ? 0 : withJitter(backoffMs); - // Keep retries at or above the snapshot so they cannot land behind the cursor. - // TODO: Remove the snapshot floor once convex-test guarantees snapshotTs <= Date.now(). - const segment = maxBigint( - toTimestamp(Date.now() + nextAttempt), - snapshotTs(), - ); + // Recovery retries mutations immediately. The commit stamp keeps the new + // start ahead of the incoming cursor, without wall-clock ordering or a sweep. + let segment: bigint | typeof ctx.db.vars.commitTs = ctx.db.vars.commitTs; + if (work.fnType !== "mutation") { + if (!work.retryBehavior) { + console.warn(`[main] ${work._id} has no retryBehavior so not retrying`); + return false; + } + const backoffMs = + work.retryBehavior.initialBackoffMs * + Math.pow(work.retryBehavior.base, work.attempts - 1); + const nextAttempt = withJitter(backoffMs); + // Keep retries at or above the snapshot so they cannot land behind the cursor. + // TODO: Remove the snapshot floor once convex-test guarantees snapshotTs <= Date.now(). + segment = maxBigint(toTimestamp(Date.now() + nextAttempt), snapshotTs()); + } const pendingStartId = await ctx.db.insert("pendingStart", { workId: work._id, segment, diff --git a/src/component/recovery.test.ts b/src/component/recovery.test.ts index dd53cdbb..5d1e6292 100644 --- a/src/component/recovery.test.ts +++ b/src/component/recovery.test.ts @@ -588,8 +588,13 @@ describe("recovery", () => { .withIndex("workId", (q) => q.eq("workId", workId)) .collect(); expect(pendingCompletions).toHaveLength(1); - expect(pendingCompletions[0].runResult.kind).toBe("stuckInScheduler"); + expect(pendingCompletions[0].runResult.kind).toBe("failed"); expect(pendingCompletions[0].retry).toBe(true); + expect((await ctx.db.get("work", workId))?.attempts).toBe(1); + expect( + (await ctx.db.system.get("_scheduled_functions", scheduledId))?.state + .kind, + ).toBe("canceled"); }); }); @@ -630,39 +635,47 @@ describe("recovery", () => { }); }); - it("should not re-enqueue pending actions", async () => { - const [workId, scheduledId] = await t.run(async (ctx) => { - const workId = await makeDummyWork(ctx, { fnType: "action" }); - const scheduledId = await makeDummyScheduledFunction(ctx, workId); - return [workId, scheduledId]; - }); - - const scheduledTime = Date.now() - 60 * 60 * 1000; // 1h pending - await t.run(async (ctx) => { - ctx.db.system.get = patchedSystemGet(ctx.db, { - [scheduledId]: { - _id: scheduledId, - _creationTime: scheduledTime, - name: "internal/worker.runActionWrapper", - args: [{}], - scheduledTime, - state: { kind: "pending" }, - }, + it.each(["action", "query"] as const)( + "should not re-enqueue pending %s work", + async (fnType) => { + const [workId, scheduledId] = await t.run(async (ctx) => { + const workId = await makeDummyWork(ctx, { fnType }); + const scheduledId = await makeDummyScheduledFunction(ctx, workId); + return [workId, scheduledId]; }); - await recoveryHandler(ctx, { - jobs: [{ scheduledId, workId, attempt: 0, started: scheduledTime }], - scheduledAt: Date.now(), + + const scheduledTime = Date.now() - 60 * 60 * 1000; // 1h pending + await t.run(async (ctx) => { + ctx.db.system.get = patchedSystemGet(ctx.db, { + [scheduledId]: { + _id: scheduledId, + _creationTime: scheduledTime, + name: "internal/worker.runActionWrapper", + args: [{}], + scheduledTime, + state: { kind: "pending" }, + }, + }); + await recoveryHandler(ctx, { + jobs: [{ scheduledId, workId, attempt: 0, started: scheduledTime }], + scheduledAt: Date.now(), + }); }); - }); - await t.run(async (ctx) => { - const pendingCompletions = await ctx.db - .query("pendingCompletion") - .withIndex("workId", (q) => q.eq("workId", workId)) - .collect(); - expect(pendingCompletions).toHaveLength(0); - }); - }); + await t.run(async (ctx) => { + const pendingCompletions = await ctx.db + .query("pendingCompletion") + .withIndex("workId", (q) => q.eq("workId", workId)) + .collect(); + expect(pendingCompletions).toHaveLength(0); + expect((await ctx.db.get("work", workId))?.attempts).toBe(0); + expect( + (await ctx.db.system.get("_scheduled_functions", scheduledId)) + ?.state.kind, + ).toBe("pending"); + }); + }, + ); it("should not process jobs with other scheduled states", async () => { // Create work and scheduled function diff --git a/src/component/recovery.ts b/src/component/recovery.ts index ce01aed6..84e283ef 100644 --- a/src/component/recovery.ts +++ b/src/component/recovery.ts @@ -2,6 +2,7 @@ import { type Infer, v } from "convex/values"; import { internalMutation, type MutationCtx } from "./_generated/server.js"; import { createLogger } from "./logging.js"; import { type CompleteJob, completeHandler } from "./complete.js"; +import { kickMainLoop } from "./kick.js"; import { MINUTE } from "./shared.js"; const recoveryArgs = v.object({ @@ -54,8 +55,11 @@ export async function recoveryHandler( const globals = await ctx.db.query("globals").unique(); const console = createLogger(globals?.logLevel); // If scheduledAt is omitted (older callers, or tests), treat lag as 0. - const schedulerLagMs = scheduledAt ? Math.max(0, Date.now() - scheduledAt) : 0; + const schedulerLagMs = scheduledAt + ? Math.max(0, Date.now() - scheduledAt) + : 0; const completionJobs: CompleteJob[] = []; + let recoveredMutation = false; for (let i = 0; i < jobs.length; i++) { const job = jobs[i]; const preamble = `[recovery] Scheduled job ${job.scheduledId} for work ${job.workId}`; @@ -114,8 +118,8 @@ export async function recoveryHandler( break; } case "pending": { - // We only re-enqueue mutations. Actions sitting in pending usually - // mean an overloaded scheduler — cancelling them doesn't help. + // Only mutations have their effects and scheduler completion committed + // atomically. Queries can share an action batch, so leave those alone. if (work.fnType !== "mutation") { break; } @@ -128,15 +132,24 @@ export async function recoveryHandler( `(lag ${schedulerLagMs}ms, threshold ${MUTATION_STUCK_THRESHOLD_MS}ms) — re-enqueueing`, ); await ctx.scheduler.cancel(scheduled._id); - completionJobs.push({ + // This attempt never committed. Request a retry directly, without + // applying the action retry policy or invoking onComplete. Advancing + // attempts invalidates recovery calls still carrying the old attempt. + await ctx.db.patch("work", work._id, { attempts: work.attempts + 1 }); + await ctx.db.insert("pendingCompletion", { + segment: ctx.db.vars.commitTs, workId: job.workId, - runResult: { kind: "stuckInScheduler" }, - attempt: job.attempt, + runResult: { kind: "failed", error: "Mutation stuck in scheduler" }, + retry: true, }); + recoveredMutation = true; break; } } } + if (recoveredMutation) { + await kickMainLoop(ctx, "retry"); + } if (completionJobs.length > 0) { await completeHandler(ctx, { jobs: completionJobs }); } diff --git a/src/component/schema.ts b/src/component/schema.ts index f711e990..564019f8 100644 --- a/src/component/schema.ts +++ b/src/component/schema.ts @@ -1,5 +1,5 @@ import { defineSchema, defineTable } from "convex/server"; -import { v, type Infer } from "convex/values"; +import { v } from "convex/values"; import { fnType, vConfig, @@ -16,16 +16,6 @@ const segment = v.commitTs(); // Epoch time in nanoseconds. CommitTs resolves to this after committing. const timestamp = v.int64(); -// Internal-only RunResult kinds, used by recovery → complete → main loop. -// External callers (worker, onComplete) only ever see vResult. -export const vResultInternal = v.union( - vResult, - // Mutation was canceled by recovery because it sat in the scheduler - // beyond the stuck threshold; main loop must re-enqueue it. - v.object({ kind: v.literal("stuckInScheduler") }), -); -export type RunResultInternal = Infer; - export default defineSchema({ // Written from kickLoop, read everywhere. globals: defineTable(vConfig), @@ -94,7 +84,7 @@ export default defineSchema({ // Written by complete, read & deleted by `main`. pendingCompletion: defineTable({ segment, - runResult: vResultInternal, + runResult: vResult, workId: v.id("work"), retry: v.boolean(), })