Compare commits

...
Author SHA1 Message Date
review50-r3andClaude Opus 5.5 fbd4d7aa35 fix(daemon): execution view's candidate scan yields between rowid windows
The cooperative candidate read yielded only between returned rows. With a
mission filter that matches few rows, one native step scanned queue history
until the next match, so a sparse match could hold the event loop for the
whole walk. The read now runs the same statement over rowid windows of 256
inside one read transaction and yields between windows. The filter stays in
SQL, so the rows and their order are unchanged. Inside a transaction, or for a
memory or non-WAL database, the read is still one synchronous statement on the
main handle.

A projection that takes 250 ms or more now offers one record to the
slow-operation log: projection and candidate-read elapsed times, the candidate
read's longest synchronous stretch, and row and window counts. No row content.

Co-Authored-By: Claude Opus 5.5 <[email protected]>
2026-11-13 02:43:56 +00:00
4 changed files with 228 additions and 63 deletions

No files matched your search

@@ -1,9 +1,8 @@
import Database from "better-sqlite3";
/** Rows read per slice, and the time a slice may take, before yielding to the event loop. Both are soft: one native
* step or row conversion can take longer. */
const SLICE_ROWS = 64;
const SLICE_MS = 8;
/** Rowids one statement may cover before the read yields to the event loop. Soft: one large row's conversion, native
* I/O or a correlated subquery on a matching row can still make a window take longer. */
const WINDOW_ROWS = 256;
/**
* The main database file when the execution view's candidate read can run cooperatively on its own connection, or
@@ -18,45 +17,66 @@ export function cooperativeReadFile(db: Database.Database): string | null {
return db.pragma("journal_mode", { simple: true }) === "wal" ? main.file : null;
}
/** One cooperative read: its rows, the windows it read, and the longest synchronous stretch it ran between yields. */
export interface CooperativeRead<Row> {
rows: Row[];
windows: number;
longestStretchMs: number;
}
/**
* Reads every row of one SELECT on a new readonly connection to `file`, yielding to the event loop between slices so
* unrelated requests progress during a long scan. One cursor keeps one snapshot for the whole read. The cursor and
* the connection are closed before returning, on every path; a read error is rethrown as-is and no partial rows are
* returned.
* Reads every row of one SELECT over `table` (a table name from code, never input) on a new readonly connection, one
* rowid window at a time, yielding to the event loop between windows so unrelated requests progress during a long
* scan. `sql` reads one window: it binds the window's exclusive lower and inclusive upper rowid first
* (`table.rowid > ? AND table.rowid <= ?`), then `binds`. Each statement steps over at most `windowRows` rowids however
* few rows its filter matches; a cursor that yields between returned rows can scan the whole table in one step when
* matches are rare. One read transaction keeps one snapshot for every window, and rows come back in rowid order. The
* transaction and the connection end before returning, on every path; a read error is rethrown as-is and no partial
* rows are returned.
*/
export async function readRowsCooperatively<Row>(
file: string,
table: string,
sql: string,
binds: unknown[],
open: (file: string) => Database.Database = (path) => new Database(path, { readonly: true, fileMustExist: true }),
): Promise<Row[]> {
windowRows = WINDOW_ROWS,
): Promise<CooperativeRead<Row>> {
let reader: Database.Database | undefined;
let cursor: IterableIterator<unknown> | undefined;
let rows: Row[] = [];
let windows = 0, longestStretchMs = 0, stretchStart = performance.now();
const endStretch = () => { longestStretchMs = Math.max(longestStretchMs, performance.now() - stretchStart); };
let failure: { error: unknown } | undefined;
let cleanupFailure: { error: unknown } | undefined;
try {
reader = open(file);
cursor = reader.prepare(sql).iterate(...binds);
for (;;) {
const sliceStart = performance.now();
let read = 0;
let step = cursor.next();
while (!step.done) {
rows.push(step.value as Row);
if (++read >= SLICE_ROWS || performance.now() - sliceStart >= SLICE_MS) break;
step = cursor.next();
reader.exec("BEGIN");
// The first read takes the snapshot every window shares. Each scalar subquery seeks one end of the rowid b-tree;
// one SELECT of MIN and MAX together would scan a whole index instead.
const { lo, hi } = reader.prepare(`SELECT (SELECT MIN(rowid) FROM ${table}) AS lo, (SELECT MAX(rowid) FROM ${table}) AS hi`)
.get() as { lo: number | null; hi: number | null };
const window = reader.prepare(sql);
if (lo !== null && hi !== null) {
for (let after = lo - 1; after < hi;) {
const through = Math.min(after + windowRows, hi);
for (const row of window.all(after, through, ...binds)) rows.push(row as Row);
windows++;
after = through;
if (after < hi) {
endStretch();
await new Promise<void>((resolve) => setImmediate(resolve));
stretchStart = performance.now();
}
}
if (step.done) break;
await new Promise<void>((resolve) => setImmediate(resolve));
}
} catch (error) {
failure = { error };
} finally {
try { cursor?.return?.(); } catch (error) { cleanupFailure = { error }; }
try { if (reader?.inTransaction) reader.exec("ROLLBACK"); } catch (error) { cleanupFailure = { error }; }
try { reader?.close(); } catch (error) { cleanupFailure ??= { error }; }
}
if (failure) { rows = []; throw failure.error; }
if (cleanupFailure) { rows = []; throw cleanupFailure.error; }
return rows;
endStretch();
return { rows, windows, longestStretchMs };
}
+35 -11
View File
@@ -54,6 +54,7 @@ import { resolveLegacyTopologyRigsRoot } from "./user-settings/settings-store.js
import { BUILD_INFO, type BuildInfo } from "../build-info.js";
import { validateMissionComposition } from "./lifecycle-manifest.js";
import { cooperativeReadFile, readRowsCooperatively } from "./execution-candidate-reader.js";
import { recordSlowDiagnostic } from "./sync-site-wrap.js";
export const INDETERMINATE = "INDETERMINATE" as const;
export type Indeterminate = typeof INDETERMINATE;
@@ -748,6 +749,7 @@ async function gitAncestor(exec: ExecutionViewDeps["exec"], repoCtx: string, sha
}
export async function buildExecutionView(deps: ExecutionViewDeps, opts?: { mission?: string; rig?: string; project?: string }): Promise<Record<string, unknown>> {
const projectionStarted = performance.now();
const now = deps.now ?? (() => new Date());
const exec = deps.exec ?? defaultExec;
const buildInfo = deps.buildInfo ?? BUILD_INFO;
@@ -806,23 +808,30 @@ export async function buildExecutionView(deps: ExecutionViewDeps, opts?: { missi
// post_claim_motion feeds only derivePickup's legacy fallback, which pending and in-progress rows reach: a blocked row
// returns parked and a closed row terminal before the count is read. Every row and body is still selected here (the
// ladder, EC-3 and wave-map evidence need historical rows); only their unused history count is skipped.
const candidateSql = `SELECT qitem_id, source_session, destination_session, state, tags, body, summary, claimed_at,
const candidateSelect = `SELECT qitem_id, source_session, destination_session, state, tags, body, summary, claimed_at,
last_heartbeat, blocked_on, ts_created, ts_updated,
CASE WHEN queue_items.state IN ('pending','in-progress') THEN (SELECT COUNT(*) FROM queue_transitions t
WHERE t.qitem_id = queue_items.qitem_id
AND t.ts > queue_items.claimed_at
AND t.transition_note IS NOT 'claimed') ELSE 0 END AS post_claim_motion
FROM queue_items
WHERE (${missionWhere})`;
FROM queue_items`;
const candidateBinds = missionLikes.flatMap((like) => [like, like]);
// On a WAL database file this full scan runs on its own readonly cursor and yields between slices so unrelated
// work can run; a native open, prepare or step can still block, since the slice budget is soft. It sees committed
// data as of its first step. Inside a transaction, or for a memory or non-WAL database, it stays a synchronous
// read on the main handle (no await on that branch).
// On a WAL database file this full scan runs on its own readonly connection in rowid windows, yielding between
// windows so unrelated work can run even when few rows match; the same filter runs inside each window, so the rows
// are the ones the single statement returns. A native open, a large row or a window's matching rows can still
// block for a while, since the window bound is soft. It sees committed data as of its first read. Inside a
// transaction, or for a memory or non-WAL database, it stays one synchronous read on the main handle (no await on
// that branch).
const cooperativeFile = cooperativeReadFile(deps.db);
const candidateRows = cooperativeFile === null
? deps.db.prepare(candidateSql).all(...candidateBinds) as QueueRowLite[]
: await readRowsCooperatively<QueueRowLite>(cooperativeFile, candidateSql, candidateBinds);
const candidateStarted = performance.now();
const candidateRead = cooperativeFile === null
? null
: await readRowsCooperatively<QueueRowLite>(cooperativeFile, "queue_items",
`${candidateSelect} WHERE queue_items.rowid > ? AND queue_items.rowid <= ? AND (${missionWhere})`, candidateBinds);
const candidateRows = candidateRead
? candidateRead.rows
: deps.db.prepare(`${candidateSelect} WHERE (${missionWhere})`).all(...candidateBinds) as QueueRowLite[];
const candidateMs = performance.now() - candidateStarted;
const rows = candidateRows
.filter(row => mission === INDETERMINATE || rowBindsToMission(row.tags, missionRefs))
@@ -1357,7 +1366,7 @@ export async function buildExecutionView(deps: ExecutionViewDeps, opts?: { missi
df_margin: dfMargin,
};
return {
const view = {
...(opts?.project ? { project: opts.project, membership: "exact project:<id> queue tags and lifecycle identity; unscoped rows excluded" } : {}),
view: "execution",
readiness,
@@ -1410,4 +1419,19 @@ export async function buildExecutionView(deps: ExecutionViewDeps, opts?: { missi
q5_park: q5,
q6_parallelism: q6,
};
// Measurement only, for a slow projection: its elapsed time, the candidate read's elapsed time, and the candidate
// read's longest synchronous stretch, which a whole-view or awaited span cannot show. The main-handle read is one
// stretch. Counts and times only; no row content.
const projectionMs = performance.now() - projectionStarted;
recordSlowDiagnostic(projectionMs, {
schema: "openrig.execution-view/v1",
utc: new Date().toISOString(),
projectionMs,
candidateMs,
candidateRows: candidateRows.length,
candidateRead: candidateRead ? "windowed" : "main-handle",
candidateWindows: candidateRead?.windows ?? null,
candidateLongestStretchMs: candidateRead?.longestStretchMs ?? candidateMs,
});
return view;
}
+11 -1
View File
@@ -1,4 +1,4 @@
import type { SlowOperationInstrumentation } from "./slow-op-recorder.js";
import { SLOW_OPERATION_THRESHOLD_MS, type SlowOperationInstrumentation } from "./slow-op-recorder.js";
let recorder: SlowOperationInstrumentation | undefined;
@@ -21,3 +21,13 @@ export function runSyncSite<T>(site: string, fn: () => T): T {
export async function runAsyncSite<T>(site: string, fn: () => Promise<T>): Promise<T> {
return recorder?.runStage ? recorder.runStage(site, fn) : fn();
}
/**
* Offers one diagnostic record to the configured recorder's bounded log, only when `elapsedMs` reached the slow
* threshold, so a hot path adds no record per call. Measurement only: no recorder, a dropped record or a throwing
* recorder changes nothing for the caller.
*/
export function recordSlowDiagnostic(elapsedMs: number, record: Record<string, unknown>): void {
if (!(elapsedMs >= SLOW_OPERATION_THRESHOLD_MS)) return;
try { recorder?.recordDiagnostic?.(record); } catch { /* the recorder reports its own health */ }
}
@@ -17,6 +17,8 @@ import { viewsCustomSchema } from "../src/db/migrations/030_views_custom.js";
import { EventBus } from "../src/domain/event-bus.js";
import { ViewProjector } from "../src/domain/view-projector.js";
import { cooperativeReadFile, readRowsCooperatively } from "../src/domain/execution-candidate-reader.js";
import { buildExecutionView } from "../src/domain/execution-view.js";
import { configureSyncSiteRecorder, recordSlowDiagnostic } from "../src/domain/sync-site-wrap.js";
const dirs: string[] = [];
const handles: Database.Database[] = [];
@@ -53,42 +55,69 @@ function turns(): { count: () => number; stop: () => void } {
return { count: () => count, stop: () => { stopped = true; } };
}
/** One window of t, the way the execution view binds its windows: exclusive lower and inclusive upper rowid first. */
const WINDOW_SQL = "SELECT id, v FROM t WHERE id > ? AND id <= ? ORDER BY id";
describe("cooperative candidate reads", () => {
it("reads every row in order on its own connection, letting other callbacks run between slices", async () => {
it("reads every row in rowid order on its own connection, a window at a time, letting other callbacks run between windows", async () => {
const { file } = walTable(500);
const loop = turns(), reader = recordingOpen();
const rows = await readRowsCooperatively<{ id: number }>(file, "SELECT id, v FROM t ORDER BY id", [], reader.open);
const read = await readRowsCooperatively<{ id: number }>(file, "t", WINDOW_SQL, [], reader.open, 64);
loop.stop();
expect(reader.readers.map((db) => [db.readonly, db.open])).toEqual([[true, false]]); // readonly, and closed before returning
expect(rows.map((r) => r.id)).toEqual(Array.from({ length: 500 }, (_, i) => i + 1));
expect(reader.readers.map((db) => [db.readonly, db.open, db.inTransaction])).toEqual([[true, false, false]]); // readonly, and closed before returning
expect(read.rows.map((r) => r.id)).toEqual(Array.from({ length: 500 }, (_, i) => i + 1));
expect(read.windows).toBe(8);
expect(loop.count()).toBeGreaterThan(1);
});
it("keeps one snapshot for the whole read while writers commit between slices; the next read sees them", async () => {
const { file, db } = walTable(500);
// Runs at the reader's first yield, after its cursor has started.
setImmediate(() => db.transaction(() => {
db.prepare("UPDATE t SET v = 'changed' WHERE id = 1").run();
db.prepare("INSERT INTO t(id, v) VALUES (501, 'new')").run();
})());
const during = await readRowsCooperatively<{ id: number; v: string }>(file, "SELECT id, v FROM t ORDER BY id", []);
expect(during).toHaveLength(500);
expect(during[0]!.v).toBe(JSON.stringify({ a: 1 }));
const after = await readRowsCooperatively<{ id: number; v: string }>(file, "SELECT id, v FROM t ORDER BY id", []);
expect(after).toHaveLength(501);
expect(after[0]!.v).toBe("changed");
it("yields between windows even when the filter matches almost nothing", async () => {
const { file } = walTable(2000);
const loop = turns();
const read = await readRowsCooperatively<{ id: number }>(file, "t", "SELECT id FROM t WHERE id > ? AND id <= ? AND v LIKE ?", ['%"a":2000}%']);
loop.stop();
expect(read.rows).toEqual([{ id: 2000 }]);
expect(read.windows).toBe(8); // 2000 rowids, 256 per window
// A cursor that yields only between returned rows reaches its one match in a single native step, with no turn between.
expect(loop.count()).toBeGreaterThan(1);
});
it("rethrows a native error raised mid-read, returns nothing, and leaves no reader pinning the WAL", async () => {
it("reads an empty table as no rows, and steps over rowid gaps", async () => {
const { file, db } = walTable(0);
expect(await readRowsCooperatively(file, "t", WINDOW_SQL, [])).toMatchObject({ rows: [], windows: 0 });
db.prepare("INSERT INTO t(id, v) VALUES (1, 'a'), (1000, 'b')").run();
const read = await readRowsCooperatively<{ id: number }>(file, "t", WINDOW_SQL, []);
expect(read.rows.map((r) => r.id)).toEqual([1, 1000]);
expect(read.windows).toBe(4);
});
it("keeps one snapshot for every window while writers commit between windows; the next read sees them", async () => {
const { file, db } = walTable(500);
// Runs at the reader's first yield, after its first window: every change lands in a window it has not read yet.
setImmediate(() => db.transaction(() => {
db.prepare("UPDATE t SET v = 'changed' WHERE id = 500").run();
db.prepare("DELETE FROM t WHERE id = 400").run();
db.prepare("INSERT INTO t(id, v) VALUES (501, 'new')").run();
})());
const during = await readRowsCooperatively<{ id: number; v: string }>(file, "t", WINDOW_SQL, [], undefined, 64);
expect(during.rows.map((r) => r.id)).toEqual(Array.from({ length: 500 }, (_, i) => i + 1));
expect(during.rows.at(-1)).toEqual({ id: 500, v: JSON.stringify({ a: 500 }) });
const after = await readRowsCooperatively<{ id: number; v: string }>(file, "t", WINDOW_SQL, []);
expect(after.rows).toHaveLength(500);
expect(after.rows.some((r) => r.id === 400)).toBe(false);
expect(after.rows.slice(-2)).toEqual([{ id: 500, v: "changed" }, { id: 501, v: "new" }]);
});
it("rethrows a native error raised in a later window, returns nothing, and leaves no reader pinning the WAL", async () => {
const { file, db } = walTable(500, 300);
const reader = recordingOpen();
const read = readRowsCooperatively(file, "SELECT json_extract(v, '$.a') AS a FROM t ORDER BY id", [], reader.open);
const sql = "SELECT json_extract(v, '$.a') AS a FROM t WHERE id > ? AND id <= ? ORDER BY id";
const read = readRowsCooperatively(file, "t", sql, [], reader.open, 64);
await expect(read).rejects.toMatchObject({ name: "SqliteError", code: "SQLITE_ERROR" });
expect(reader.readers.map((db) => db.open)).toEqual([false]);
db.prepare("INSERT INTO t(id, v) VALUES (501, '{}')").run();
expect(db.pragma("wal_checkpoint(TRUNCATE)")).toEqual([{ busy: 0, log: 0, checkpointed: 0 }]);
db.prepare("DELETE FROM t WHERE id = 300").run();
expect(await readRowsCooperatively(file, "SELECT json_extract(v, '$.a') AS a FROM t ORDER BY id", [])).toHaveLength(500);
expect((await readRowsCooperatively(file, "t", sql, [])).rows).toHaveLength(500);
});
it("stays on the main handle inside a transaction and for memory or non-WAL databases", () => {
@@ -110,12 +139,18 @@ describe("the projector's execution queue", () => {
migrate(db, [coreSchema, bindingsSessionsSchema, rigArchiveSchema, eventsSchema, queueItemSummarySchema, queueItemsSchema, queueTransitionsSchema, queueTransitionWakesSchema, viewsCustomSchema]);
return db;
}
const insertRow = (db: Database.Database, id: string, state: string, tags: string[], body: string, claimedAt: string | null = "2026-10-25T11:00:00.000Z") =>
const insertRow = (db: Database.Database, id: string, state: string, tags: string[] | null, body: string, claimedAt: string | null = "2026-10-25T11:00:00.000Z") =>
db.prepare(`INSERT INTO queue_items (qitem_id, ts_created, ts_updated, source_session, destination_session, state, priority, tier, tags, body, claimed_at, last_heartbeat, blocked_on)
VALUES (?, '2026-10-25T10:00:00.000Z', '2026-10-25T10:00:00.000Z', 'lead@r', 'builder@r', ?, 'normal', 'light', ?, ?, ?, NULL, ?)`)
.run(id, state, JSON.stringify(tags), body, claimedAt, state === "blocked" ? "external:review" : null);
.run(id, state, tags && JSON.stringify(tags), body, claimedAt, state === "blocked" ? "external:review" : null);
const laneIds = (doc: Record<string, unknown>) => (doc.q1_lanes as Array<{ qitem_id: string }>).map((l) => l.qitem_id).sort();
const tick = () => new Promise<void>((resolve) => setImmediate(resolve));
// The free-disk reading is taken live at read time (fs.statfsSync); every other field must match.
const withoutLiveDisk = (doc: unknown) => {
const copy = structuredClone(doc) as { q6_parallelism?: { df_margin?: { available_kib?: unknown } } };
if (copy.q6_parallelism?.df_margin) delete copy.q6_parallelism.df_margin.available_kib;
return copy;
};
it("builds one execution at a time in arrival order, each reading fresh, and a failed build does not block the next", async () => {
const db = fixture(tempFile("queue.sqlite"));
@@ -176,14 +211,90 @@ describe("the projector's execution queue", () => {
seed(memory); seed(file);
expect(cooperativeReadFile(memory)).toBeNull();
expect(cooperativeReadFile(file)).not.toBeNull();
// The free-disk reading is taken live at read time (fs.statfsSync); every other field must match.
const withoutLiveDisk = (doc: unknown) => {
const copy = structuredClone(doc) as { q6_parallelism?: { df_margin?: { available_kib?: unknown } } };
if (copy.q6_parallelism?.df_margin) delete copy.q6_parallelism.df_margin.available_kib;
return copy;
};
const legacy = await documentOf(memory);
expect(withoutLiveDisk(await documentOf(file))).toEqual(withoutLiveDisk(legacy));
expect((legacy as { q1_lanes: unknown[] }).q1_lanes.length).toBeGreaterThan(0);
});
it("binds the same rows through the windowed read when the mission filter matches few of them, edge cases included", async () => {
const missionsRoot = path.dirname(tempFile("missions"));
fs.mkdirSync(path.join(missionsRoot, "release-9"));
fs.writeFileSync(path.join(missionsRoot, "release-9", "SPEC.md"), "---\nid: OPR_9\n---\n\n# Fixture mission\n");
const edges: Array<[id: string, state: string, tags: string[] | null, body: string]> = [
["qitem-tagged", "in-progress", ["mission:release-9", "project:p1", "slice:S1"], "Tagged."],
["qitem-alias-tag", "in-progress", ["mission:OPR_9", "project:p2", "slice:S2"], "Tagged with the mission's SPEC id."],
["qitem-case", "in-progress", ["mission:RELEASE-9", "slice:S3"], "Tagged in another ASCII case."],
["qitem-longer-tag", "in-progress", ["mission:release-90", "slice:S4"], "Another mission whose name contains this one."],
["qitem-other-tag", "in-progress", ["mission:other", "slice:S5"], "Tagged elsewhere; mentions release-9."],
["qitem-body", "in-progress", ["slice:S6", "project:p1"], "Untagged work for release-9."],
["qitem-wildcard", "in-progress", ["slice:S7"], "Untagged; mentions OPRx9, which LIKE's _ matches."],
["qitem-null-tags", "in-progress", null, "Slice: S8\nNo tags; mentions release-9."],
["qitem-empty-body", "in-progress", ["mission:release-9", "slice:S9"], ""],
["qitem-null-tags-empty-body", "in-progress", null, ""],
["qitem-moved", "in-progress", ["mission:release-9", "slice:S10"], "Claimed, then moved three times."],
];
// 700 unrelated rows around the edge rows, so matches are sparse and fall in different windows.
const seed = (db: Database.Database) => db.transaction(() => {
const fill = (from: number, to: number) => {
for (let i = from; i < to; i++) insertRow(db, `qitem-filler-${String(i).padStart(4, "0")}`, "done", ["slice:S1"], `Unrelated work ${i}.`);
};
fill(0, 300);
for (const [id, state, tags, body] of edges.slice(0, 4)) insertRow(db, id, state, tags, body);
fill(300, 600);
for (const [id, state, tags, body] of edges.slice(4)) insertRow(db, id, state, tags, body);
fill(600, 700);
for (let n = 0; n < 3; n++) {
db.prepare("INSERT INTO queue_transitions (qitem_id, ts, state, transition_note, actor_session) VALUES ('qitem-moved', ?, 'in-progress', 'moved', 'builder@r')")
.run(`2026-10-25T11:3${n}:00.000Z`);
}
})();
const memory = fixture(), file = fixture(tempFile("sparse.sqlite"));
seed(memory); seed(file);
expect(cooperativeReadFile(file)).not.toBeNull();
const deps = (db: Database.Database) => ({ db, now: () => NOW, slicesRoot: () => missionsRoot, rigsRoot: () => "/nonexistent-rigs-root",
exec: async (): Promise<string> => { throw new Error("not a repository"); } });
for (const project of [undefined, "p1"]) {
const legacy = await buildExecutionView(deps(memory), { mission: "release-9", project });
expect(withoutLiveDisk(await buildExecutionView(deps(file), { mission: "release-9", project }))).toEqual(withoutLiveDisk(legacy));
expect(laneIds(legacy)).toEqual(project ? ["qitem-body", "qitem-tagged"] : [
"qitem-alias-tag", "qitem-body", "qitem-case", "qitem-empty-body", "qitem-moved", "qitem-null-tags", "qitem-tagged", "qitem-wildcard",
]);
}
});
});
describe("slow execution projections in the slow-operation log", () => {
afterEach(() => configureSyncSiteRecorder(undefined));
it("offers a diagnostic only at the slow threshold, and a throwing recorder changes nothing for the caller", () => {
const offered: unknown[] = [];
configureSyncSiteRecorder({ recordDiagnostic: (record) => { offered.push(record); return true; } });
recordSlowDiagnostic(249.9, { n: 1 });
recordSlowDiagnostic(250, { n: 2 });
recordSlowDiagnostic(Number.NaN, { n: 3 });
expect(offered).toEqual([{ n: 2 }]);
configureSyncSiteRecorder({ recordDiagnostic: () => { throw new Error("recorder broke"); } });
expect(() => recordSlowDiagnostic(300, { n: 4 })).not.toThrow();
});
it("records a slow projection's elapsed times and the candidate read's longest stretch, with no row content", async () => {
const offered: Record<string, unknown>[] = [];
configureSyncSiteRecorder({ recordDiagnostic: (record) => { offered.push(record); return true; } });
const db = track(createDb(tempFile("slow.sqlite")));
migrate(db, [coreSchema, bindingsSessionsSchema, rigArchiveSchema, eventsSchema, queueItemSummarySchema, queueItemsSchema, queueTransitionsSchema, queueTransitionWakesSchema, viewsCustomSchema]);
db.prepare(`INSERT INTO queue_items (qitem_id, ts_created, ts_updated, source_session, destination_session, state, priority, tier, tags, body)
VALUES ('qitem-slow', '2026-10-25T10:00:00.000Z', '2026-10-25T10:00:00.000Z', 'lead@r', 'builder@r', 'in-progress', 'normal', 'light', ?, ?)`)
.run(JSON.stringify(["slice:S1"]), "Private words.\nworktree_path=/nowhere/slow\n");
// Each Git probe of the row's worktree takes 260 ms, so the projection crosses the 250 ms threshold.
await buildExecutionView({ db, now: () => new Date("2026-10-25T12:00:00.000Z"), slicesRoot: () => null, rigsRoot: () => "/nonexistent-rigs-root",
exec: async (): Promise<string> => { await new Promise((resolve) => setTimeout(resolve, 260)); throw new Error("not a repository"); } });
expect(offered).toHaveLength(1);
const record = offered[0]!;
expect(record).toMatchObject({ schema: "openrig.execution-view/v1", candidateRead: "windowed", candidateRows: 1, candidateWindows: 1 });
expect(record.projectionMs).toBeGreaterThanOrEqual(250);
expect(record.candidateMs).toBeLessThanOrEqual(record.projectionMs as number);
expect(record.candidateLongestStretchMs).toBeLessThanOrEqual(record.candidateMs as number);
expect(Object.keys(record).sort()).toEqual(["candidateLongestStretchMs", "candidateMs", "candidateRead", "candidateRows", "candidateWindows", "projectionMs", "schema", "utc"]);
expect(JSON.stringify(record)).not.toMatch(/Private|nowhere|builder@r|S1/);
});
});