perf(runner): write preparation span rows to the run log in the background (#20426)

## 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 <noreply@anthropic.com>

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

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<void>((resolve) => { release = resolve; });
+    const write = vi.fn(async (event: AdapterRuntimeEvent) => {
+      await gate;
+      written.push((event.payload as Record<string, unknown>)?.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<void>((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"); });

server/src/services/native-runtime/native-run-trace.ts

@@ -531,6 +531,8 @@ export function createNativeRunTrace(input: {
       endedAtMs?: number;
       outcome?: NativeRunSpanOutcome;
       attributes?: Record<string, string | number | boolean>;
+      /** Write the run-log row after the caller continues; `finish` settles it. */
+      deferRunLog?: boolean;
     } = {},
   ): Promise<void> => {
     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<void> => {
+  const record = async (span: NativeRunHistoricalSpan, options: { persistRunLog?: boolean; deferRunLog?: boolean } = {}): Promise<void> => {
     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<void> = 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<void> => {
     if (ended) return;
     try { input.onFinish?.(); } catch { /* Diagnostics cannot change runner control flow. */ }

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;
         }

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;