From 379fa285f8ad7fa93cfe0f65a1f0e9236faff833 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/18] feat(queue): order work by commit and snapshot timestamps --- CHANGELOG.md | 10 + 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 | 42 ++- 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 | 404 +++++--------------- src/component/stats.ts | 69 ++-- 17 files changed, 1451 insertions(+), 774 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 7a5e1feb..e9b04955 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,11 +1,21 @@ # 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.16 ### Patch Changes - 3202652: Preserve `ConvexError` data in failed job results (#257). + ## 0.4.15 - Upgrades @convex-dev/batch-worker to 0.3. Requires Convex 1.43 or later. diff --git a/README.md b/README.md index 7e45f777..f80cf668 100644 --- a/README.md +++ b/README.md @@ -277,6 +277,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 ab05c1a0..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,10 +114,19 @@ 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: 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 }); @@ -147,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, }); } }, @@ -177,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, }); } }), @@ -208,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 67d0d539..23e7f037 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, @@ -327,6 +330,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 }); @@ -410,6 +619,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({ @@ -543,10 +776,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, @@ -555,13 +790,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, @@ -569,7 +836,7 @@ 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(); // Date.now() is pinned per query, so allow a few ms of skew. assert(result.timeoutMs !== undefined); expect(Math.abs(result.timeoutMs - untilNextRecovery)).toBeLessThan(10); @@ -577,6 +844,242 @@ describe("loop", () => { }); }); + // ──────────────────────────────────────────────────────────────────── + // 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 45511c19..ad140cf1 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -23,46 +23,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, @@ -75,14 +71,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"), @@ -104,119 +93,127 @@ 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>>; const batchValidators = defineBatchWorkerValidators({ batch: batchFields }); -/** - * 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: batchValidators.vQueryArgs, returns: batchValidators.vQueryReturns, 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: @@ -229,20 +226,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: batchValidators.vMutationArgs, 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); @@ -261,22 +274,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); @@ -305,27 +339,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, @@ -333,12 +382,14 @@ async function queryPending( completionCursor, cancelationCursor, incomingCursor, + sweepCursor, maxParallelism, runningCount, }: { completionCursor: bigint; cancelationCursor: bigint; incomingCursor: bigint; + sweepCursor: bigint; maxParallelism: number; runningCount: number; }, @@ -351,30 +402,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 }; } /** @@ -407,8 +524,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 { @@ -453,43 +569,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 }); @@ -538,9 +645,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">, @@ -549,33 +672,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; - } - if (work.pendingStartId === undefined) { - await ctx.db.patch("work", workId, { pendingStartId: _id }); - } - 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))); } @@ -690,11 +829,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; @@ -703,8 +838,13 @@ 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); + // 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, @@ -729,7 +869,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 8a972170..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,16 +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 older work. + // 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 50e2c674..5f10806d 100644 --- a/src/component/shared.ts +++ b/src/component/shared.ts @@ -1,6 +1,6 @@ import type { Infer, Validator, Value, 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, @@ -169,17 +230,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 74f1caa3..c4a7fb6d 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"; // --------------------------------------------------------------------------- @@ -165,6 +165,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; @@ -258,11 +265,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, @@ -277,7 +288,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 @@ -313,10 +330,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; @@ -852,7 +869,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, @@ -863,10 +880,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 () => { @@ -913,7 +930,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; }); @@ -969,9 +989,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, @@ -1031,7 +1055,7 @@ describe("state machine", () => { await t.run(async (ctx) => { await ctx.db.insert("pendingCancelation", { workId, - segment, + segment: segment, }); }); @@ -1042,9 +1066,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", @@ -1052,7 +1076,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, @@ -1063,9 +1092,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, @@ -1079,10 +1112,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 () => { @@ -1121,9 +1176,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, @@ -1211,9 +1270,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, @@ -1231,12 +1294,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 }; }); @@ -1288,9 +1361,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 997ae3f6..3ec27176 100644 --- a/src/component/stats.test.ts +++ b/src/component/stats.test.ts @@ -1,331 +1,131 @@ 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); + 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, - 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 b2f263bf..1aede37d 100644 --- a/src/component/stats.ts +++ b/src/component/stats.ts @@ -5,14 +5,9 @@ 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"; /** @@ -70,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 ctx.db - .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, - 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(), - // Unused. Kept so calls scheduled by older versions still validate. + // @deprecated Unused; accepted so in-flight calls from older versions + // still validate. + startSegment: v.optional(v.int64()), + endSegment: v.optional(v.int64()), cursor: v.optional(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; }, }); @@ -158,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 }) => { @@ -184,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 f7d8a6f807bd6a75102792017b071d5d0ac45053 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 02/18] 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 2db1888a30476064b25f6831328955a7d12aa542 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 03/18] 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 c4a7fb6d..142523ad 100644 --- a/src/component/stateMachine.test.ts +++ b/src/component/stateMachine.test.ts @@ -1055,7 +1055,7 @@ describe("state machine", () => { await t.run(async (ctx) => { await ctx.db.insert("pendingCancelation", { workId, - segment: segment, + segment, }); }); From 7a0d3aa11377b4f4cda55912bfd7d3cb59938ed1 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 04/18] 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 23e7f037..f39499b1 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -384,6 +384,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; }); } @@ -479,6 +485,7 @@ describe("loop", () => { await initialize(); const workId = await enqueueLegacyWork(Date.now()); + await runLoop(); // upgrade await runLoop(); const o = await observe(); @@ -502,7 +509,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()); @@ -525,7 +532,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 ad140cf1..aa118db3 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -25,7 +25,7 @@ import { DEFAULT_MAX_PARALLELISM, eligibilityBound, fromTimestamp, - legacyRunAt, + fromSegment, maxBigint, MINUTE, MIN_TIMESTAMP, @@ -35,7 +35,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. @@ -74,7 +73,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(), @@ -83,18 +82,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; @@ -136,10 +133,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, }, @@ -180,14 +176,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, })), @@ -238,12 +234,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, { @@ -284,28 +282,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. @@ -349,10 +329,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; } @@ -360,7 +340,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, @@ -428,7 +408,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"; }; @@ -477,17 +457,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, }); } } @@ -508,7 +483,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) { @@ -572,9 +547,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; @@ -645,24 +620,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, @@ -675,16 +632,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; @@ -708,11 +665,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 5f10806d..af99e961 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 142523ad..50dbe7b4 100644 --- a/src/component/stateMachine.test.ts +++ b/src/component/stateMachine.test.ts @@ -290,7 +290,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 }); @@ -306,7 +306,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], }); @@ -316,7 +316,7 @@ describe("state machine", () => { if (state.pendingCancelation) { await ctx.db.insert("pendingCancelation", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); } @@ -781,7 +781,7 @@ describe("state machine", () => { const backlogWorkId = await makeDummyWork(ctx); await ctx.db.insert("pendingStart", { workId: backlogWorkId, - segment, + segment: toTimestamp(fromSegment(segment)), }); return backlogWorkId; }); @@ -932,7 +932,7 @@ describe("state machine", () => { }); await ctx.db.insert("pendingStart", { workId: id, - segment: seg, + segment: toTimestamp(fromSegment(seg)), }); return id; }); @@ -1055,7 +1055,7 @@ describe("state machine", () => { await t.run(async (ctx) => { await ctx.db.insert("pendingCancelation", { workId, - segment, + segment: toTimestamp(fromSegment(segment)), }); }); @@ -1079,16 +1079,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", { @@ -1195,7 +1195,7 @@ describe("state machine", () => { }); await ctx.db.insert("pendingCompletion", { workId: wId, - segment: seg, + segment: toTimestamp(fromSegment(seg)), retry: true, runResult: { kind: "failed", error: "test" }, }); @@ -1290,24 +1290,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)), }), }); @@ -1382,13 +1382,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 aa01ddbc647d33f48b1558c0b2f282ca1202993b 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 05/18] 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 f39499b1..310a9177 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -683,6 +683,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 aa118db3..93c43246 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -548,7 +548,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`); @@ -561,7 +560,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 14ebae293a33768a71395757d2ee3451a38f6193 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 06/18] 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 310a9177..33afc550 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, @@ -748,6 +753,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, { @@ -788,6 +811,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, }); @@ -831,7 +855,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 93c43246..d3ef8e40 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -23,7 +23,6 @@ import { import { type Config, DEFAULT_MAX_PARALLELISM, - eligibilityBound, fromTimestamp, fromSegment, maxBigint, @@ -198,7 +197,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) { @@ -453,7 +452,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 af99e961..d29a3c21 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 50141b1fb520745a564531b6068ee3b8e78fcf17 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 07/18] 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 1aede37d..955c2c0d 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 6165c0eae5c7353eb18355dcacfc451a22335fae 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 08/18] 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 33afc550..c067c9a8 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -298,6 +298,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(); @@ -1025,6 +1082,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 d3ef8e40..6ea6a3db 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -157,7 +157,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 @@ -281,15 +281,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); @@ -326,21 +322,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, @@ -363,14 +354,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 @@ -381,17 +372,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 3dc309c922f14310759bf9bd01ef4cd3f18fe3ab 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 09/18] 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 c067c9a8..5ce38e08 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -543,6 +543,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 6ea6a3db..be13cbc3 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -228,8 +228,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) { @@ -240,7 +239,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 76e3d78d41e515bf7600643612c4326332fa232b 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 10/18] 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 50dbe7b4..b11481d1 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, @@ -166,7 +169,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 { @@ -265,7 +268,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 5690550289f4ccf26d5aad9d14cbabb45a5284dd 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 11/18] 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 be13cbc3..862c73f8 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -390,9 +390,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; { @@ -406,8 +404,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") @@ -420,16 +418,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; @@ -791,9 +788,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 6a49d654df7d7a690f25cdb807562f5325807b28 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Mon, 26 Oct 2026 17:22:32 -0700 Subject: [PATCH 12/18] changelog update --- CHANGELOG.md | 4 ++-- README.md | 4 ---- 2 files changed, 2 insertions(+), 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e9b04955..45ef5c52 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,8 +1,8 @@ # Changelog -## Unreleased +## 0.5.0 (Unreleased) -- Orders queues by commit timestamp. Requires Convex 1.43 or later. +- Orders queues by commit timestamp. Requires 1.47 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. diff --git a/README.md b/README.md index f80cf668..7e45f777 100644 --- a/README.md +++ b/README.md @@ -277,10 +277,6 @@ 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. From 41966b1fdbf22007903137abae5c33930f492208 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Mon, 26 Oct 2026 17:43:00 -0700 Subject: [PATCH 13/18] drop paginator again --- src/component/stats.ts | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/src/component/stats.ts b/src/component/stats.ts index 955c2c0d..bac716b4 100644 --- a/src/component/stats.ts +++ b/src/component/stats.ts @@ -14,7 +14,6 @@ import { import { createLogger, type Logger, logLevel, shouldLog } from "./logging.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. @@ -78,7 +77,7 @@ export async function generateReport( return; } const currentSegment = toTimestamp(Date.now()); - const pendingStart = await paginator(ctx.db, schema) + const pendingStart = await ctx.db .query("pendingStart") .withIndex("segment", (q) => q @@ -97,9 +96,6 @@ export async function generateReport( }); } else { await ctx.scheduler.runAfter(0, internal.stats.calculateBacklogAndReport, { - startSegment: 0n, - endSegment: currentSegment, - cursor: pendingStart.continueCursor, report: state.report, running: state.running.length, logLevel, From b970448b6212206b71adf5643f65b344934f291f Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Mon, 26 Oct 2026 17:43:24 -0700 Subject: [PATCH 14/18] clean up test --- src/test.ts | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/src/test.ts b/src/test.ts index d93f175b..58cf0067 100644 --- a/src/test.ts +++ b/src/test.ts @@ -20,10 +20,7 @@ const modules = import.meta.glob("./component/**/*.ts"); export function register< Schema extends SchemaDefinition, >(t: TestConvex, name: string = "workpool") { - batchWorker.register( - t as unknown as TestConvex>, - `${name}/batchWorker`, - ); + batchWorker.register(t, `${name}/batchWorker`); return t.registerComponent(name, schema, modules) as unknown as ComponentApi; } export default { register, schema, modules }; From 161bf4f2e4b2daf094cb190f75039ae921efb3f3 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Mon, 26 Oct 2026 17:43:57 -0700 Subject: [PATCH 15/18] update peer deps --- package-lock.json | 2 +- package.json | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/package-lock.json b/package-lock.json index e70518a1..0a05a49a 100644 --- a/package-lock.json +++ b/package-lock.json @@ -43,7 +43,7 @@ "vitest": "5.1.0" }, "peerDependencies": { - "convex": "^1.43.0", + "convex": "^1.47.0", "convex-helpers": "^0.1.94" } }, diff --git a/package.json b/package.json index 445cce29..b2354367 100644 --- a/package.json +++ b/package.json @@ -71,7 +71,7 @@ } }, "peerDependencies": { - "convex": "^1.43.0", + "convex": "^1.47.0", "convex-helpers": "^0.1.94" }, "devDependencies": { From 708650f8b24dd6851fb5655bcec2aea64c76ef9f Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Mon, 26 Oct 2026 17:50:06 -0700 Subject: [PATCH 16/18] =?UTF-8?q?leverage=20snapshotTs=20=E2=89=A4=20Date.?= =?UTF-8?q?now=20in=20backend=20&=20tests?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- src/component/lib.ts | 4 +--- src/component/loop.test.ts | 27 ++++++++------------------- src/component/loop.ts | 9 +++------ src/component/shared.ts | 19 +------------------ 4 files changed, 13 insertions(+), 46 deletions(-) diff --git a/src/component/lib.ts b/src/component/lib.ts index a4bbf3b4..9e4f0413 100644 --- a/src/component/lib.ts +++ b/src/component/lib.ts @@ -22,9 +22,7 @@ import { vOnCompleteFnContext, retryBehavior, status as statusValidator, - maxBigint, MINUTE, - snapshotTs, toTimestamp, } from "./shared.js"; import { recordEnqueued } from "./stats.js"; @@ -118,7 +116,7 @@ export async function enqueueHandler( 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()); + const segment = toTimestamp(runAt); pendingStartId = await ctx.db.insert("pendingStart", { workId, segment, diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index 5ce38e08..088bc956 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -22,7 +22,6 @@ import { DEFAULT_MAX_PARALLELISM, fromSegment, fromTimestamp, - snapshotTs, toSegment, toTimestamp, WORKER_NAME, @@ -32,7 +31,7 @@ const SECOND = 1000; const MINUTE = 60 * SECOND; /** - * Drive getBatch and run in one transaction, as batch-worker does. Observe + * Drive getBatch and run in separate transactions, allowing snapshot changes. 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. @@ -118,25 +117,15 @@ describe("loop", () => { }); } - 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. */ + /** Run the query and mutation at potentially different snapshots. */ async function runLoop() { - await advanceClockToSnapshot(); - 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; + const result = await t.query(internal.loop.getBatch, { + name: WORKER_NAME, }); + if (result.kind === "work") { + await t.mutation(internal.loop.run, result.batch); + } + return result; } /** Pretend a worker finished a job by inserting pendingCompletion. */ diff --git a/src/component/loop.ts b/src/component/loop.ts index 862c73f8..c2392148 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -788,12 +788,9 @@ async function rescheduleJob( 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(). - const segment = maxBigint( - toTimestamp(Date.now() + nextAttempt), - snapshotTs(), - ); + // Date.now() is at least this mutation's snapshot, so retries cannot land + // behind the incoming cursor, which is bounded by the query's snapshot. + const segment = toTimestamp(Date.now() + nextAttempt); const pendingStartId = await ctx.db.insert("pendingStart", { workId: work._id, segment, diff --git a/src/component/shared.ts b/src/component/shared.ts index d29a3c21..5e7616d9 100644 --- a/src/component/shared.ts +++ b/src/component/shared.ts @@ -1,6 +1,6 @@ import type { Infer, Validator, Value, VAny } from "convex/values"; -import { jsonToConvex, v } from "convex/values"; +import { v } from "convex/values"; import { type Logger, logLevel } from "./logging.js"; export const fnType = v.union( @@ -62,23 +62,6 @@ export function fromTimestamp(timestamp: bigint): number { ); } -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; } From 086f1f851d42a25d68a8eddcd8a9fec117eea983 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Tue, 27 Oct 2026 13:56:01 -0700 Subject: [PATCH 17/18] feedback --- src/component/lib.test.ts | 32 ++++++ src/component/lib.ts | 9 +- src/component/loop.test.ts | 198 +++++++++++++++++++++++++++++++--- src/component/loop.ts | 45 +++++--- src/component/pendingStart.ts | 3 +- 5 files changed, 252 insertions(+), 35 deletions(-) diff --git a/src/component/lib.test.ts b/src/component/lib.test.ts index 5c7cae32..707e2222 100644 --- a/src/component/lib.test.ts +++ b/src/component/lib.test.ts @@ -362,6 +362,38 @@ describe("lib", () => { }); describe("status", () => { + it("temporarily reports queued and running legacy work as pending without queue pointers", async () => { + const { queuedId, runningId } = await t.run(async (ctx) => { + const work = { + fnType: "action" as const, + fnHandle: "testHandle", + fnName: "testFunction", + attempts: 0, + }; + const queuedId = await ctx.db.insert("work", work); + const runningId = await ctx.db.insert("work", work); + await ctx.db.insert("pendingStart", { + workId: queuedId, + segment: BigInt(Math.floor(Date.now() / 100)), + }); + return { queuedId, runningId }; + }); + expect(await t.query(api.lib.status, { id: queuedId })).toEqual({ + state: "pending", + previousAttempts: 0, + }); + expect(await t.query(api.lib.status, { id: runningId })).toEqual({ + state: "pending", + previousAttempts: 0, + }); + expect( + await t.query(api.lib.statusBatch, { ids: [queuedId, runningId] }), + ).toEqual([ + { state: "pending", previousAttempts: 0 }, + { state: "pending", previousAttempts: 0 }, + ]); + }); + it("should return finished state for non-existent work", async () => { const id = await t.mutation(api.lib.enqueue, { fnHandle: "testHandle", diff --git a/src/component/lib.ts b/src/component/lib.ts index 9e4f0413..c6329911 100644 --- a/src/component/lib.ts +++ b/src/component/lib.ts @@ -223,11 +223,10 @@ async function statusHandler(ctx: QueryCtx, { id }: { id: Id<"work"> }) { return { state: "finished" } as const; } 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; - } + // During migration, legacy work without a queue pointer reports pending, + // even if already running. This temporary approximation lasts until the + // work is upgraded, retried, or finished. + return { state: "pending", previousAttempts: work.attempts } as const; } if (await findPendingStart(ctx, work)) { return { state: "pending", previousAttempts: work.attempts } as const; diff --git a/src/component/loop.test.ts b/src/component/loop.test.ts index 088bc956..fa0e64ff 100644 --- a/src/component/loop.test.ts +++ b/src/component/loop.test.ts @@ -168,6 +168,139 @@ describe("loop", () => { return t.query(api.lib.status, { id: workId }); } + async function getWorkBatch() { + const result = await t.query(internal.loop.getBatch, { + name: WORKER_NAME, + }); + assert(result.kind === "work"); + return result.batch; + } + + describe("writes between the query and mutation", () => { + it("bounds the incoming cursor by the query snapshot", async () => { + await initialize(); + const runAt = Date.now() + SECOND; + const workId = await enqueueWork({}, { runAt }); + await runLoop(); // Verify the enqueue's scanTs before the work is due. + vi.setSystemTime(runAt); + const batch = await getWorkBatch(); + expect(batch.starts.map((s) => s.workId)).toEqual([workId]); + expect(batch.snapshotTs).toBeLessThan(toTimestamp(runAt)); + + // A commit after the query advances the mutation's snapshot past runAt. + vi.setSystemTime(runAt + 1); + const laterId = await enqueueWork(); + expect( + await t.query(async (ctx) => ctx.meta.getSnapshotTs()), + ).toBeGreaterThan(toTimestamp(runAt)); + await t.mutation(internal.loop.run, batch); + + expect((await observe()).segmentCursors!.incoming).toBe(batch.snapshotTs); + await runLoop(); + expect((await observe()).running.map((r) => r.workId)).toEqual([ + workId, + laterId, + ]); + }); + + it("does not retry or cancel work deleted after its events were selected", async () => { + await initialize(); + const retryId = await enqueueWork({ + retryBehavior: { maxAttempts: 3, initialBackoffMs: 100, base: 2 }, + }); + await runLoop(); + await simulateCompletion(retryId, { kind: "failed", error: "boom" }); + const canceledId = await enqueueWork(); + await t.mutation(api.lib.cancel, { id: canceledId }); + const batch = await getWorkBatch(); + expect(batch.completions).toHaveLength(1); + expect(batch.cancelations).toHaveLength(1); + + await t.run(async (ctx) => { + await ctx.db.delete("work", retryId); + await ctx.db.delete("work", canceledId); + }); + await t.mutation(internal.loop.run, batch); + + const o = await observe(); + expect(o.pendingCompletion).toHaveLength(0); + expect(o.pendingCancelation).toHaveLength(0); + expect(o.pendingStart.map((p) => p.workId)).toEqual([canceledId]); + // Consume the events and retire the completed attempt, without retrying + // missing work or scheduling a cancellation callback for it. + expect(o.running).toHaveLength(0); + const report = await t.query( + async (ctx) => (await ctx.db.query("internalState").unique())!.report, + ); + expect(report.completed).toBe(1); + expect(report.retries).toBe(0); + expect(report.canceled).toBe(0); + }); + + it("tolerates cleanup deleting a selected start", async () => { + await initialize(); + await enqueueWork(); + const batch = await getWorkBatch(); + await t.mutation(internal.danger.clearPending, { + before: Date.now() + MINUTE, + }); + await t.mutation(internal.loop.run, batch); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running).toHaveLength(0); + }); + + it("does not start work that finished after the query", async () => { + await initialize(); + const workId = await enqueueWork(); + const batch = await getWorkBatch(); + await simulateCompletion(workId, { kind: "success", returnValue: null }); + await t.mutation(internal.loop.run, batch); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running).toHaveLength(0); + expect(await statusOf(workId)).toMatchObject({ state: "finished" }); + }); + + it("honors a cancellation inserted after the query selected a start", async () => { + await initialize(); + const workId = await enqueueWork(); + const batch = await getWorkBatch(); + expect(batch.cancelations).toHaveLength(0); + await t.mutation(api.lib.cancel, { id: workId }); + await t.mutation(internal.loop.run, batch); + + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running).toHaveLength(0); + expect(await t.query((ctx) => ctx.db.get("work", workId))).toMatchObject({ + canceled: true, + }); + await runLoop(); // Consuming the request must not complete it twice. + expect( + await t.query( + async (ctx) => + (await ctx.db.query("internalState").unique())!.report.canceled, + ), + ).toBe(1); + }); + + it("does not retry work canceled after the query selected its completion", async () => { + await initialize(); + const workId = await enqueueWork({ + retryBehavior: { maxAttempts: 3, initialBackoffMs: 0, base: 2 }, + }); + await runLoop(); + await simulateCompletion(workId, { kind: "failed", error: "boom" }); + const batch = await getWorkBatch(); + await t.mutation(api.lib.cancel, { id: workId }); + await t.mutation(internal.loop.run, batch); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.running).toHaveLength(0); + }); + }); + // ──────────────────────────────────────────────────────────────────── // Forward progress: work moves through the pipeline // ──────────────────────────────────────────────────────────────────── @@ -445,6 +578,33 @@ describe("loop", () => { }); } + it("tolerates cleanup deleting a selected legacy start", async () => { + await initialize(); + await enqueueLegacyWork(Date.now()); + const batch = await getWorkBatch(); + expect(batch.upgrade?.starts).toHaveLength(1); + await t.mutation(internal.danger.clearPending, { + before: Date.now() + MINUTE, + }); + await t.mutation(internal.loop.run, batch); + const o = await observe(); + expect(o.pendingStart).toHaveLength(0); + expect(o.segmentCursors!.sweep).toBe(0n); + }); + + it("removes a legacy start if its work finished after the query", async () => { + await initialize(); + const workId = await enqueueLegacyWork(Date.now()); + const batch = await getWorkBatch(); + await simulateCompletion(workId, { + kind: "success", + returnValue: null, + }); + await t.mutation(internal.loop.run, batch); + expect((await observe()).pendingStart).toHaveLength(0); + expect(await statusOf(workId)).toMatchObject({ state: "finished" }); + }); + it("recovers legacy entries below all three persisted cursors", async () => { await initialize(); const completedId = await enqueueWork(); @@ -589,7 +749,9 @@ describe("loop", () => { await runLoop(); const idle = await runLoop(); assert(idle.kind === "idle"); - expect(idle.timeoutMs).toBe(startsAt - Date.now()); + expect(idle.timeoutMs).toBe( + startsAt - (await t.query(async () => Date.now())), + ); vi.setSystemTime(startsAt); await runLoop(); @@ -825,7 +987,7 @@ describe("loop", () => { // ──────────────────────────────────────────────────────────────────── describe("getBatch", () => { - it("waits for wall time when the snapshot clock is ahead", async () => { + it("starts committed work even when the fake wall clock lags the snapshot", async () => { await initialize(); const now = Date.now(); vi.setSystemTime(now + SECOND); @@ -835,11 +997,9 @@ describe("loop", () => { 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(); + // Convex (and convex-test) pins Date.now() to at least the snapshot. + assert(result.kind === "work"); + await t.mutation(internal.loop.run, result.batch); expect((await observe()).running.map((r) => r.workId)).toEqual([workId]); }); @@ -883,7 +1043,6 @@ 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, }); @@ -927,7 +1086,9 @@ describe("loop", () => { const second = await runLoop(); assert(second.kind === "idle"); - expect(second.timeoutMs).toBe(runAt - Date.now()); + expect(second.timeoutMs).toBe( + runAt - (await t.query(async () => Date.now())), + ); // It starts when it comes due, untouched in the meantime. vi.setSystemTime(runAt); @@ -1195,7 +1356,7 @@ describe("loop", () => { 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. + // Date.now() >= snapshot, so it's eligible next iteration. expect(retry.segment).toBeGreaterThanOrEqual(o.segmentCursors!.incoming); await runLoop(); o = await observe(); @@ -1205,15 +1366,26 @@ describe("loop", () => { 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 }); + // Use the transaction's clock: convex-test may pin it ahead of the + // external fake clock to preserve Date.now() >= snapshotTs. + const { runAt, workId } = await t.run(async (ctx) => { + const runAt = Date.now() + 0.5; + const workId = await enqueueHandler(ctx, createLogger("WARN"), { + fnType: "action", + fnHandle: "test_handle", + fnName: "test_handle", + fnArgs: {}, + runAt, + }); + return { runAt, workId }; + }); const entry = (await observe()).pendingStart.find( (p) => p.workId === workId, ); assert(entry); expect(entry.segment).toBe(toTimestamp(runAt)); - vi.setSystemTime(Date.now() + 1); + vi.setSystemTime(Math.ceil(runAt)); await runLoop(); expect((await observe()).running.map((r) => r.workId)).toEqual([workId]); }); diff --git a/src/component/loop.ts b/src/component/loop.ts index c2392148..18d7a7a1 100644 --- a/src/component/loop.ts +++ b/src/component/loop.ts @@ -29,7 +29,6 @@ import { MINUTE, MIN_TIMESTAMP, SECOND, - snapshotTs, toTimestamp, vResult, } from "./shared.js"; @@ -94,8 +93,10 @@ const vStart = v.object({ }); type Start = Infer; -// batch-worker calls getBatch and run in one transaction, sharing a snapshot. +// The query sees the previous worker mutation's writes, but other transactions +// may commit between getBatch and run. Revalidate candidates in the mutation. const batchFields = { + snapshotTs: 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(), @@ -114,6 +115,7 @@ export const getBatch = internalQuery({ args: batchValidators.vQueryArgs, returns: batchValidators.vQueryReturns, handler: async (ctx): Promise> => { + const snapshotTs = ctx.meta.getSnapshotTs(); const globals = await getGlobals(ctx); const state = await ctx.db.query("internalState").order("desc").first(); if (state?.segmentCursors.sweep === undefined) { @@ -125,6 +127,7 @@ export const getBatch = internalQuery({ return { kind: "work", batch: { + snapshotTs, recovery: false, completions: [], cancelations: [], @@ -173,6 +176,7 @@ export const getBatch = internalQuery({ if (hasWork) { const batch: Batch = { + snapshotTs, recovery: isRecoveryIter, completions: completions.map((c) => ({ pendingId: c._id, @@ -232,7 +236,8 @@ 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.pendingId); + const pending = await ctx.db.get("pendingStart", start.pendingId); + if (pending) await ctx.db.delete("pendingStart", pending._id); continue; } await ctx.db.patch("work", work._id, { @@ -321,13 +326,16 @@ export const run = internalMutation({ if (batch.cancelations.length > 0) { state.segmentCursors.cancelation = batch.cancelations.at(-1)!.segment; } - // Every selected start was handled. Cap at the snapshot so racing + // Every selected start was handled. Cap at the query snapshot so racing // commits remain ahead. Inclusive reads retain entries sharing a timestamp. - const snapshot = snapshotTs(); const lastStart = batch.starts.at(-1); if (lastStart) { - state.segmentCursors.incoming = - lastStart.segment < snapshot ? lastStart.segment : snapshot; + state.segmentCursors.incoming = maxBigint( + state.segmentCursors.incoming, + lastStart.segment < batch.snapshotTs + ? lastStart.segment + : batch.snapshotTs, + ); } // Entries left at the boundary stamp are revisited by an inclusive read. if (batch.sweepStop !== undefined) { @@ -376,14 +384,13 @@ async function queryPending( 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. + // Bound per-iteration writes. This is a capacity estimate: maxParallelism may + // change before run, allowing temporary excess parallelism. const startLimit = Math.min( MAIN_BATCH_SIZE, 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. + // Exclude starts whose work is completing or canceling in this batch. const excluded = new Set([ ...completed, ...cancelations.map((c) => c.workId), @@ -473,9 +480,12 @@ async function handleCompletions( ) { // Completions that were going to be retried but have since been canceled. const toCancel: CompleteJob[] = []; + const completedWork = new Set>(); await Promise.all( completed.map(async (c) => { await ctx.db.delete("pendingCompletion", c.pendingId); + if (completedWork.has(c.workId)) return; + completedWork.add(c.workId); const running = state.running.find((r) => r.workId === c.workId); if (!running) { @@ -514,9 +524,7 @@ async function handleCompletions( ); // We do this after so the stats above know if it was in progress. const before = state.running.length; - state.running = state.running.filter( - (r) => !completed.some((c) => c.workId === r.workId), - ); + state.running = state.running.filter((r) => !completedWork.has(r.workId)); const numCompleted = before - state.running.length; state.report.completed += numCompleted; console.debug(`[main] completed ${numCompleted} work`); @@ -643,7 +651,14 @@ async function handleStart( console.error(`Trying to start, but work not found: ${workId}`); continue; } - if (work.canceled) { + const pendingCancelation = await ctx.db + .query("pendingCancelation") + .withIndex("workId", (q) => q.eq("workId", workId)) + .first(); + if (work.canceled || pendingCancelation) { + if (!work.canceled) { + await ctx.db.patch("work", workId, { canceled: true }); + } console.debug(`[main] ${workId} was canceled (not starting)`); state.report.canceled++; await ctx.scheduler.runAfter(0, internal.complete.complete, { diff --git a/src/component/pendingStart.ts b/src/component/pendingStart.ts index 077cf5df..f60259bc 100644 --- a/src/component/pendingStart.ts +++ b/src/component/pendingStart.ts @@ -3,8 +3,7 @@ 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 + return work.pendingStartId !== undefined ? await ctx.db.get("pendingStart", work.pendingStartId) : null; - return doc?.workId === work._id ? doc : null; } From dc2793cd4899aa26c334db3eed2f478069ca3968 Mon Sep 17 00:00:00 2001 From: Ian Macartney <366683+ianmacartney@users.noreply.github.com> Date: Wed, 11 Nov 2026 12:31:51 -0800 Subject: [PATCH 18/18] Add changeset for commit-ordered queues --- .changeset/commit-ordered-queues.md | 14 ++++++++++++++ CHANGELOG.md | 10 ---------- 2 files changed, 14 insertions(+), 10 deletions(-) create mode 100644 .changeset/commit-ordered-queues.md diff --git a/.changeset/commit-ordered-queues.md b/.changeset/commit-ordered-queues.md new file mode 100644 index 00000000..e8712889 --- /dev/null +++ b/.changeset/commit-ordered-queues.md @@ -0,0 +1,14 @@ +--- +"@convex-dev/workpool": minor +--- + +Order queues by commit timestamp and recover near-term scheduled work that +commits behind the queue cursor. Requires Convex 1.47 or later. + +Queued work from older versions migrates automatically, preserving scheduled +start times. Large queues may briefly delay new work during migration. Before +upgrading from a version earlier than 0.4.15, deploy 0.4.15 and run +`npx convex run --component workpool migrations:backfillPendingStartIds`, +replacing `workpool` with each component instance's name. + +Downgrading after this upgrade is unsupported because the queue format changes. diff --git a/CHANGELOG.md b/CHANGELOG.md index 45ef5c52..7a5e1feb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,21 +1,11 @@ # Changelog -## 0.5.0 (Unreleased) - -- Orders queues by commit timestamp. Requires 1.47 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.16 ### Patch Changes - 3202652: Preserve `ConvexError` data in failed job results (#257). - ## 0.4.15 - Upgrades @convex-dev/batch-worker to 0.3. Requires Convex 1.43 or later.