From 232480d18fe5756d3c49acd2600f6b434cc217e5 Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Mon, 9 Nov 2026 17:50:15 -0800 Subject: [PATCH] perf(runner): write preparation span rows to the run log in the background (#20426) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - Before a native run starts its provider, the executor copies the preparation spans (queue, prepare phases, environment) into the run trace and the run log > - It records about 25 spans and waits for one run-log insert per span, one after another > - On a hosted test deployment, that step (`native.controller.span_persistence`, added in #20396) took a median of 0.28 s, and every task waited for it before the Runner started > - The run trace already has a way to write diagnostics without blocking the caller: `defer`, which `finish` drains before the root span closes > - This pull request writes those run-log rows through that path, in order, while the spans themselves are still recorded at once > - The benefit is about 0.25 s less before the provider starts, on every native run, cold or warm ## Linked Issues or Issue Description **What existing behavior does this improve?** The time between the end of heartbeat preparation and `native.session.execute` for native Runner tasks. **Subsystem affected** Server: native runtime tracing (`server/src/services/native-runtime/native-run-trace.ts`) and the native session executor. **Current behavior** `executeNativeSession` calls `trace.record` for each preparation span and awaits it. `trace.end` awaits `emitCompletedSpanEvent`, which inserts one `run.performance.span` row through `onEvent`. On a hosted test deployment, measured with the #20396 spans across 10 runs, `native.controller.span_persistence` took a median of 0.28 s: - 0.30 to 0.36 s for runs right after a computer wake - 0.17 to 0.25 s for runs on an awake computer It is the second largest step between preparation and the provider start (the median of that whole gap is 1.0 s). **Proposed behavior** The spans are still started and ended at once, with the same parents. The speed-budget bookkeeping still runs at once too. Only the run-log row is written later: one row at a time, in the order the spans ended, before the trace finishes. **Reason and benefit** The rows are diagnostics, and they already carry their own start time (`wallStartedAtMs`, `startOffsetMs`). Readers do not depend on the row order: the only reader in the repository, `summarizeStartupReuse`, looks for `runner.process.launch`, which this change does not defer. The provider can start without waiting for these inserts. **Breaking changes** None. ## What Changed - `native-run-trace.ts`: `end` and `record` take an optional `deferRunLog`. With it, `end` queues the run-log row on a per-trace chain registered with `defer`, so rows are written one at a time in order and `finish` waits for them. A row requested after the trace finished is dropped, as for other deferred diagnostics. - `native-session-executor.ts`: the preparation spans and the `environment.startup` scope use `deferRunLog: true`. - `doc/run-log-events.md`: note that native preparation span rows are written late, in order. - `native-run-trace.test.ts`: two tests. - Spans are recorded under their parent while every row write is blocked, and the rows are written in order before `task.provider_session.measured`. - A deferred row requested after `finish` is not written. ## Verification - `npx vitest run src/services/native-runtime/native-run-trace.test.ts src/services/native-runtime/native-run-trace-context.test.ts` (34 passed). Both new tests fail without the source change: the first times out waiting on the blocked write, and the second sees the row written. - `npx vitest run src/__tests__/heartbeat-preparation-gap-spans.test.ts src/services/native-runtime/native-session-executor.test.ts` (1321 passed) - `pnpm --filter @paperclipai/server typecheck` ## Risks - Low risk. The change is diagnostic only: OpenTelemetry spans and the speed-budget checks are unchanged. - The preparation rows can now land in the run log after the first Runner events. Readers already use the payload times, not the row order. - If the server process dies between the provider start and `finish`, the preparation rows of that run can be missing from the run log. The OpenTelemetry spans are not affected. - The deferred rows are written while the run continues, as budget-breach rows already are, so the sink sees concurrent writes from one run. This was already the case for deferred diagnostics. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, used through Claude Code with tool use (shell, file edits, test runs, Honeycomb queries) and extended thinking. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 --- doc/run-log-events.md | 4 ++ .../native-runtime/native-run-trace.test.ts | 38 +++++++++++++++++++ .../native-runtime/native-run-trace.ts | 35 ++++++++++++----- ...unner-restart-recovery.integration.test.ts | 4 +- .../native-runtime/native-session-executor.ts | 6 ++- 5 files changed, 75 insertions(+), 12 deletions(-) diff --git a/doc/run-log-events.md b/doc/run-log-events.md index 161edb0bae5..217e785025a 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -68,6 +68,10 @@ Every `run.performance.span` payload also carries `wallStartedAtMs`, the span's start time in epoch milliseconds (since 2026-11-09). Span rows can be written late through deferred diagnostics, so readers take a span's start from this field (or from the trace start plus `startOffsetMs`), never from the row's write time. +The preparation spans of a native run (`heartbeat.queue`, `heartbeat.prepare_*`, +`environment.*`) are always written this way: in the order they ended, while the +provider starts, and before the run's trace finishes. They can appear after the +first Runner events of the run. `run.performance.span` also records `task.time_to_first_token` once per native dispatch at the first newly committed deliverable text: assistant or reasoning diff --git a/server/src/services/native-runtime/native-run-trace.test.ts b/server/src/services/native-runtime/native-run-trace.test.ts index 1cfb22cddcd..bd448269e37 100644 --- a/server/src/services/native-runtime/native-run-trace.test.ts +++ b/server/src/services/native-runtime/native-run-trace.test.ts @@ -595,6 +595,44 @@ describe("deferred diagnostics", () => { expect(names.indexOf("task.time_to_first_token")).toBeLessThan(names.indexOf("task.provider_session.measured")); }); + it("records spans without waiting on deferred run-log rows, then writes them in order before finish", async () => { + const { traceContext, spans } = createRecordingTraceContext(); + const written: unknown[] = []; + let release!: () => void; + const gate = new Promise((resolve) => { release = resolve; }); + const write = vi.fn(async (event: AdapterRuntimeEvent) => { + await gate; + written.push((event.payload as Record)?.span); + }); + const trace = createNativeRunTrace({ runId: "deferred-rows", startedAtMs: 1_000, traceContext, onEvent: write }); + trace.start("task.prepare", { parentName: "task.provider_session", startedAtMs: 1_000 }); + const names = ["heartbeat.queue", "heartbeat.prepare_before_environment", "heartbeat.prepare_after_environment"]; + for (const [index, name] of names.entries()) { + await trace.record({ name, parentName: "task.prepare", startedAtMs: 1_000 + index, endedAtMs: 1_100 + index }, { deferRunLog: true }); + } + // The spans exist under their parent while every row write is still blocked. + expect(spans.filter((span) => span.parentName === "task.prepare").map((span) => span.name)).toEqual(names); + expect(spans.filter((span) => names.includes(span.name)).every((span) => span.endedAtMs !== null)).toBe(true); + expect(written).toEqual([]); + expect(write.mock.calls.length).toBeLessThanOrEqual(1); + const finished = trace.finish("ok"); + release(); + await finished; + // Rows keep the order their spans ended in and land before the root span closes. + expect(written.slice(0, 3)).toEqual(names); + expect(written.indexOf("task.provider_session.measured")).toBeGreaterThan(2); + }); + + it("drops deferred run-log rows requested after the trace finished", async () => { + const write = vi.fn(async () => {}); + const trace = createNativeRunTrace({ runId: "deferred-rows-late", traceContext: createRecordingTraceContext().traceContext, onEvent: write }); + await trace.finish("ok"); + write.mockClear(); + await trace.record({ name: "heartbeat.queue", startedAtMs: 1_000, endedAtMs: 1_100 }, { deferRunLog: true }); + await new Promise((resolve) => setImmediate(resolve)); + expect(write).not.toHaveBeenCalled(); + }); + it("ignores a failed deferred diagnostic and work deferred after finish", async () => { const trace = createNativeRunTrace({ runId: "deferred-fail", traceContext: createRecordingTraceContext().traceContext }); trace.defer(async () => { throw new Error("diagnostic failed"); }); diff --git a/server/src/services/native-runtime/native-run-trace.ts b/server/src/services/native-runtime/native-run-trace.ts index 9224fd9dfee..6267e985f32 100644 --- a/server/src/services/native-runtime/native-run-trace.ts +++ b/server/src/services/native-runtime/native-run-trace.ts @@ -531,6 +531,8 @@ export function createNativeRunTrace(input: { endedAtMs?: number; outcome?: NativeRunSpanOutcome; attributes?: Record; + /** Write the run-log row after the caller continues; `finish` settles it. */ + deferRunLog?: boolean; } = {}, ): Promise => { const state = scopeState(scope); @@ -550,14 +552,18 @@ export function createNativeRunTrace(input: { }); if (outcome === "failed") { try { state.span.setStatus({ code: 2 }); } catch {} } try { state.span.end(endedAtMs); } catch {} - if (state.persistRunLog) await emitCompletedSpanEvent({ - name: state.name, - parentName: state.parentName, - startedAtMs: state.startedAtMs, - endedAtMs, - outcome, - attributes: state.attributes, - }); + if (state.persistRunLog) { + const completed: NativeRunHistoricalSpan = { + name: state.name, + parentName: state.parentName, + startedAtMs: state.startedAtMs, + endedAtMs, + outcome, + attributes: state.attributes, + }; + if (options.deferRunLog) deferRunLogRow(completed); + else await emitCompletedSpanEvent(completed); + } checkSpanBudget(state.name, state.startedAtMs, endedAtMs); }; @@ -596,7 +602,7 @@ export function createNativeRunTrace(input: { ); }; - const record = async (span: NativeRunHistoricalSpan, options: { persistRunLog?: boolean } = {}): Promise => { + const record = async (span: NativeRunHistoricalSpan, options: { persistRunLog?: boolean; deferRunLog?: boolean } = {}): Promise => { const scope = start(span.name, { parentName: span.parentName, startedAtMs: span.startedAtMs, @@ -606,6 +612,7 @@ export function createNativeRunTrace(input: { await end(scope, { endedAtMs: span.endedAtMs, outcome: span.outcome, + deferRunLog: options.deferRunLog, }); }; @@ -648,6 +655,16 @@ export function createNativeRunTrace(input: { pendingDiagnostics.add(pending); }; + // Deferred run-log rows are written one at a time, in the order their spans + // ended, so the sink sees the same sequence as the awaited path. + let runLogRows: Promise = Promise.resolve(); + const deferRunLogRow = (span: NativeRunHistoricalSpan): void => { + if (ended) return; + const written = runLogRows.then(() => emitCompletedSpanEvent(span)); + runLogRows = written; + defer(() => written); + }; + const finish = async (outcome: NativeRunSpanOutcome): Promise => { if (ended) return; try { input.onFinish?.(); } catch { /* Diagnostics cannot change runner control flow. */ } diff --git a/server/src/services/native-runtime/native-runner-restart-recovery.integration.test.ts b/server/src/services/native-runtime/native-runner-restart-recovery.integration.test.ts index 729845d8a14..b6af62a30fc 100644 --- a/server/src/services/native-runtime/native-runner-restart-recovery.integration.test.ts +++ b/server/src/services/native-runtime/native-runner-restart-recovery.integration.test.ts @@ -2510,7 +2510,9 @@ process.on("SIGTERM", () => child.kill("SIGTERM")); backend: { descriptor, openSession }, preparationSpans: [{ name: "heartbeat.prepare_after_environment", startedAtMs: Date.now(), endedAtMs: Date.now() }], onEvent: async event => { - if (event.payload?.span === "heartbeat.prepare_after_environment") { + // Preparation span rows are written in the background, so hold the + // controller on the awaited environment receipt that precedes them. + if (event.eventType === "run.startup.reuse" && event.payload?.layer === "environment") { prepared(); await continuePreparation; } diff --git a/server/src/services/native-runtime/native-session-executor.ts b/server/src/services/native-runtime/native-session-executor.ts index f0e9a0e335f..25eba55d801 100644 --- a/server/src/services/native-runtime/native-session-executor.ts +++ b/server/src/services/native-runtime/native-session-executor.ts @@ -9773,6 +9773,8 @@ async function executePaperclipNativeSessionAttempt( startedAtMs: environmentStartedAtMs, }) : null; + // The spans are recorded now; their run-log rows are written in the + // background so the provider start does not wait for one insert per span. await timeController("span_persistence", async () => { for (const span of preparationSpans) { const rootMilestone = isNativeRunRootHistoricalSpan(span.name); @@ -9783,10 +9785,10 @@ async function executePaperclipNativeSessionAttempt( : environmentSpans.includes(span) ? "environment.startup" : "task.prepare", - }); + }, { deferRunLog: true }); } if (environmentScope) { - await trace.end(environmentScope, { endedAtMs: environmentEndedAtMs }); + await trace.end(environmentScope, { endedAtMs: environmentEndedAtMs, deferRunLog: true }); } }); let retainedTransition: VerifiedWarmTransitionBinding | undefined;