fix(observability): judge the TTFT budget from run creation; report the wait behind a live turn (#19941)

## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work.
> - Invariant 8 of the durable-ownership plan says turns must start
fast. #19863 added per-run speed budgets that write
`run.performance.budget_exceeded` to the run log.
> - The Phase 2 chaos data (#19927) showed follow-up TTFT about 3x over
the claude budget.
> - The cause is measurement scope. A follow-up comment posted during a
live turn waits for that turn to end, and TTFT is anchored at the
comment. The budgets came from idle follow-ups.
> - This pull request judges the TTFT budget from run creation and
reports the wait separately.
> - The benefit is that budget breaches point at real start-up slowness,
not at time spent behind a turn the user is already watching.

## Linked Issues or Issue Description

Refs #19863 (speed budgets), #19927 (Phase 2 data), #19852 (startup
sub-spans), #19888 (warm default).

**What happened?**
In two local storm waves, C1 follow-up runs breached the claude warm
TTFT budget (p50 27.6–29.9 s against 9.5 s). Their spans show
`comment.to_run_created` at 6–62 s (waiting for the live turn), then
session resume at 1.4–3.8 s and submit-to-first-event at 2–5 s. Codex
without the wait was about 4.8 s, the same as the warm-follow-up
baseline.

**What did you expect?**
The budget should judge start-up latency, which is what its baseline
measured. The wait behind a live turn should be visible but not judged.

**Steps to reproduce**
1. Run a local chaos storm with C1 tasks.
2. Read `run.performance.budget_exceeded` rows with metric `ttft` for
`issue_commented` runs, and compare them with each run's
`comment.to_run_created` span.

## What Changed

- `native-run-trace.ts`: the TTFT budget check measures from run
creation (start of `heartbeat.queue`, or end of the ingress span). The
TTFT span itself does not change.
- `native-speed-budgets.ts`: breaches can carry `inputWaitMs` (TTFT
only).
- `tests/restart-chaos/ttft-baseline-stats.ts` and `ttft-baseline.ts`:
the wait behind a live turn is its own measured step (`inputWait`), next
to the full TTFT and the TTFT from run creation. The TTFT table gains a
"Wait behind live turn" column. The full comment-to-first-token time
stays the user-visible metric.
- `doc/run-log-events.md` and the plan's speed-budget section describe
the rule.

## Verification

- `cd server && npx vitest run
src/services/native-runtime/native-speed-budgets.test.ts
src/services/native-runtime/native-run-trace.test.ts`: 43 pass, 2 new.
`pnpm exec vitest run --config tests/restart-chaos/vitest.config.ts
tests/restart-chaos/ttft-baseline-stats.test.ts`: 12 pass, 1 new. They
cover a follow-up under budget after a 60 s wait (no breach), a
follow-up over budget (breach with `inputWaitMs`), and queueing after
run creation still judged.
- Server typecheck passes.

## Risks

- Low. This is a run-log-only change (AGENTS.md §5.7): no Telemetry and
no span attributes change.
- A slow wait before run creation is no longer a TTFT budget breach. The
TTFT span still records it, and the breach payload names it. Admission
holds after run creation are still judged.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, in Claude Code with
tool use (shell, file edits).

## 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
- [ ] All Paperclip CI gates are green
- [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups
- [ ] 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/plans/2026-11-07-durable-ownership-and-reconciliation.md

@@ -73,7 +73,7 @@ Each metric is reported by adapter (Codex, Claude/ACPX, OpenCode) and environmen
 
 Phase 1 sets these budgets from the local baseline in `2026-11-07-ttft-baseline.md`. Each budget is the baseline value times 1.2, rounded up to 0.5 s. The 20% headroom covers the small samples and the shared host of the baseline. Daytona and other remote environments get budgets after their own baseline.
 
-A single run is checked against its p95 budget. When a run exceeds it, the run log gets one `run.performance.budget_exceeded` row (`doc/run-log-events.md`). The p50 budgets apply to aggregates: chaos waves, the baseline driver, and staging. Every later phase's exit criteria include "no regression against these budgets". The table lives in code at `server/src/services/native-runtime/native-speed-budgets.ts`.
+A single run is checked against its p95 budget. When a run exceeds it, the run log gets one `run.performance.budget_exceeded` row (`doc/run-log-events.md`). The TTFT span keeps the full user-visible latency, but the TTFT budget judges it from run creation: time an input waited for its run to exist (for example a comment posted while the previous turn was still running) is not judged, because the baseline measured idle follow-ups. That wait is real user-visible latency, so it is its own measured step: the `comment.to_run_created` span in the run log, `inputWaitMs` in a breach, and its own column ("Wait behind live turn") in the TTFT tables of the baseline driver and chaos reports, next to the full comment-to-first-token TTFT. The p50 budgets apply to aggregates: chaos waves, the baseline driver, and staging. Every later phase's exit criteria include "no regression against these budgets". The table lives in code at `server/src/services/native-runtime/native-speed-budgets.ts`.
 
 Time to first token (s, p50 / p95):
 

doc/run-log-events.md

@@ -100,6 +100,9 @@ provider event). The payload names `adapter` (`codex`, `claude` or `opencode`),
 `environment` (`local`), `startKind` (`cold`, `warm` or `unknown`; an unknown
 start uses the looser budget), `measuredMs`, `budgetP50Ms`, `budgetP95Ms`,
 `percentile` (`p95`), `baseline`, and, for restart recovery, `disposition`.
+For `ttft`, `measuredMs` counts from run creation: when the input waited for its
+run to exist (for example a comment posted while the previous turn was still
+running), that wait is excluded from the judgment and reported as `inputWaitMs`.
 Each metric is checked at most once per dispatch. A restart-recovery dispatch is
 judged only on `restart_recovery`, because its TTFT and boot span the outage. Remote runs and other adapters have
 no budget yet. The event is written in detached diagnostic work after the

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

@@ -359,6 +359,10 @@ export function createNativeRunTrace(input: {
   // measurement, so the check never adds a wait to the turn path.
   let budgetStart: SpeedBudgetStart | null = null;
   let queueEndedAtMs: number | null = null;
+  // When the run row was created (start of heartbeat.queue, end of the
+  // ingress span). Input accepted before it waited for a run to exist, for
+  // example a comment posted while the previous turn was still running.
+  let runCreatedAtMs: number | null = null;
   let attemptStartedAtMs: number | null = null;
   let bootChecked = false;
   const reportBudgetBreach = (breach: SpeedBudgetBreach | null): void => {
@@ -376,13 +380,18 @@ export function createNativeRunTrace(input: {
   const checkSpanBudget = (name: string, startedAtMs: number, endedAtMs: number): void => {
     if (!input.budget || input.budget.restartRecovery) return;
     const subject = { adapter: input.budget.adapter, environment: input.budget.environment };
-    if (name === "heartbeat.queue") queueEndedAtMs = endedAtMs;
+    if (name === "heartbeat.queue") { queueEndedAtMs = endedAtMs; runCreatedAtMs ??= startedAtMs; }
+    if (name === "comment.to_run_created" || name === "question_response.to_run_created") runCreatedAtMs ??= endedAtMs;
     // A resumed attempt keeps the run's original queue span; its own claim is
     // the start of this attempt's preparation.
     if (name === "heartbeat.prepare_before_environment") attemptStartedAtMs = startedAtMs;
     if (name === "task.time_to_first_token") {
+      // The span keeps the full user-visible latency. The budget (baseline:
+      // idle follow-ups) judges it from run creation: time the input spent
+      // waiting for a run to exist (behind a live turn) is reported, not judged.
+      const inputWaitMs = runCreatedAtMs !== null && runCreatedAtMs > startedAtMs ? runCreatedAtMs - startedAtMs : 0;
       reportBudgetBreach(evaluateSpeedBudget({ ...subject, metric: "ttft", start: budgetStart,
-        measuredMs: endedAtMs - startedAtMs }));
+        measuredMs: endedAtMs - startedAtMs - inputWaitMs, ...(inputWaitMs > 0 ? { inputWaitMs } : {}) }));
     }
     // Agent boot: run claimed (end of heartbeat.queue) to the provider session
     // accepting turn.start (end of runner.turn.submit or runner.session.resume).

server/src/services/native-runtime/native-speed-budgets.test.ts

@@ -87,6 +87,39 @@ describe("speed budget checks in the native run trace", () => {
     expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", adapter: "claude", startKind: "warm", measuredMs: ttft })]);
   });
 
+  it("judges a follow-up's TTFT from run creation and reports the wait behind the live turn", async () => {
+    // A comment posted while the previous turn runs waits for a run to exist;
+    // the budget (idle follow-up baseline) judges the time after that.
+    const budget = LOCAL_SPEED_BUDGETS.claude.ttft.warm.p95Ms;
+    const wait = 60_000;
+    const quiet = traced({ adapter: "claude", environment: "local" });
+    quiet.trace.setBudgetStart("warm");
+    await quiet.trace.record({ name: "comment.to_run_created", startedAtMs: 0, endedAtMs: wait });
+    await quiet.trace.record({ name: "heartbeat.queue", startedAtMs: wait, endedAtMs: wait + 100 });
+    await quiet.trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: wait + budget - 1 });
+    await quiet.trace.finish("ok");
+    expect(quiet.breaches()).toEqual([]);
+
+    const slow = traced({ adapter: "claude", environment: "local" });
+    slow.trace.setBudgetStart("warm");
+    await slow.trace.record({ name: "comment.to_run_created", startedAtMs: 0, endedAtMs: wait });
+    await slow.trace.record({ name: "heartbeat.queue", startedAtMs: wait, endedAtMs: wait + 100 });
+    await slow.trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: wait + budget + 1 });
+    await slow.trace.finish("ok");
+    expect(slow.breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1, inputWaitMs: wait })]);
+  });
+
+  it("still judges queueing after run creation (admission, dispatch) inside the TTFT budget", async () => {
+    const { trace, breaches } = traced({ adapter: "codex", environment: "local" });
+    trace.setBudgetStart("cold");
+    const budget = LOCAL_SPEED_BUDGETS.codex.ttft.cold.p95Ms;
+    await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: budget });
+    await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: budget + 1 });
+    await trace.finish("ok");
+    expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1 })]);
+    expect(breaches()[0]).not.toHaveProperty("inputWaitMs");
+  });
+
   it("checks restart recovery latency once, from ready to the first provider event", async () => {
     const { trace, breaches } = traced({ adapter: "opencode", environment: "local" });
     const late = LOCAL_SPEED_BUDGETS.opencode.restart_recovery.p95Ms + 1_000;

server/src/services/native-runtime/native-speed-budgets.ts

@@ -87,6 +87,9 @@ export type SpeedBudgetBreach = {
   percentile: "p95";
   baseline: string;
   disposition?: string;
+  /** TTFT only: time the input waited for its run to exist (for example a
+   * comment posted while the previous turn was running). Not judged. */
+  inputWaitMs?: number;
 };
 
 /** A breach when one measured run exceeds its p95 budget, else null. */
@@ -97,6 +100,7 @@ export function evaluateSpeedBudget(input: {
   start: SpeedBudgetStart | null;
   measuredMs: number;
   disposition?: string;
+  inputWaitMs?: number;
 }): SpeedBudgetBreach | null {
   if (!input.adapter || input.environment !== "local" || !Number.isFinite(input.measuredMs) || input.measuredMs < 0) return null;
   const budget = speedBudgetFor(input.adapter, input.metric, input.start);
@@ -106,6 +110,7 @@ export function evaluateSpeedBudget(input: {
     startKind: input.start ?? "unknown", measuredMs: Math.round(input.measuredMs), budgetP50Ms: budget.p50Ms,
     budgetP95Ms: budget.p95Ms, percentile: "p95", baseline: SPEED_BUDGET_BASELINE,
     ...(input.disposition ? { disposition: input.disposition } : {}),
+    ...(input.inputWaitMs ? { inputWaitMs: Math.round(input.inputWaitMs) } : {}),
   };
 }
 

tests/restart-chaos/ttft-baseline-stats.test.ts

@@ -43,6 +43,21 @@ describe("ttft baseline statistics", () => {
     ]);
   });
 
+  it("reports the wait behind a live turn as its own step and the TTFT the budget judges", () => {
+    // A follow-up comment posted during the previous turn waits 40 s for its run.
+    const followUp = run("f", "warm", [
+      reuse("reused"),
+      span("comment.to_run_created", 0, 40_000),
+      span("heartbeat.queue", 40_000, 100),
+      span("runner.session.resume", 40_100, 2_000),
+      span("task.time_to_first_token", 0, 45_000, { anchor: "comment" }),
+    ]);
+    expect(runMetrics(followUp)).toMatchObject({ ttftMs: 45_000, inputWaitMs: 40_000, ttftAfterRunCreatedMs: 5_000 });
+    expect(runMetrics(coldRun("c"))).toMatchObject({ inputWaitMs: null, ttftAfterRunCreatedMs: 6_000 });
+    const [row] = baselineRows([followUp]);
+    expect(row).toMatchObject({ ttft: { p50: 45_000 }, inputWait: { n: 1, p50: 40_000 }, ttftAfterRunCreated: { p50: 5_000 } });
+  });
+
   it("uses runner.session.resume as the turn boundary for a resumed session", () => {
     const resumed = run("r", "warm", [reuse("reused"), span("heartbeat.queue", 0, 50), span("runner.session.resume", 60, 940)]);
     expect(runWarmth(resumed)).toBe("warm");

tests/restart-chaos/ttft-baseline-stats.ts

@@ -70,10 +70,16 @@ export interface RunMetrics {
   bootMs: number | null;
   /** Durations of every span that starts before the first turn submission. */
   preTurnSteps: Record<string, number>;
+  /** Input accepted to run created (`comment.to_run_created` or
+   * `question_response.to_run_created`): the wait behind a live turn. Part of
+   * the user-visible TTFT; reported as its own step, not judged by the budget. */
+  inputWaitMs: number | null;
+  /** TTFT from run creation: what the speed budget judges. */
+  ttftAfterRunCreatedMs: number | null;
 }
 
 /** Spans that wrap others (or the whole run); ranking them would double count. */
-const CUMULATIVE_SPANS = new Set(["task.time_to_first_token", "task.provider_session.measured", "task.prepare",
+const CUMULATIVE_SPANS = new Set(["task.time_to_first_token", "comment.to_run_created", "question_response.to_run_created", "task.provider_session.measured", "task.prepare",
   "native.session.execute", "runner.session.startup", "agent.turn", "environment.startup"]);
 
 const FIRST_SPAN = (spans: RunSpan[], name: string) => spans.find(span => span.name === name) ?? null;
@@ -95,7 +101,12 @@ export function runMetrics(run: BaselineRun): RunMetrics {
       if (span.startOffsetMs < turnStartAt && !(span.name in preTurnSteps)) preTurnSteps[span.name] = span.durationMs;
     }
   }
+  const ingress = FIRST_SPAN(spans, "comment.to_run_created") ?? FIRST_SPAN(spans, "question_response.to_run_created");
+  // Only an ingress that starts the TTFT span waited for its run to exist.
+  const inputWaitMs = ingress && ttft && ingress.startOffsetMs <= ttft.startOffsetMs ? ingress.durationMs : null;
   return {
+    inputWaitMs,
+    ttftAfterRunCreatedMs: ttft ? Math.max(0, ttft.durationMs - (inputWaitMs ?? 0)) : null,
     ttftMs: ttft ? ttft.durationMs : null,
     ttftAnchor: ttft && typeof ttft.attributes.anchor === "string" ? ttft.attributes.anchor : null,
     bootMs: claimedAt !== null && turnStartAt !== null ? Math.max(0, turnStartAt - claimedAt) : null,
@@ -128,7 +139,12 @@ export function recoverySamples(runs: readonly BaselineRun[], faults: readonly B
   return samples;
 }
 
-export interface BaselineRow { adapter: string; environment: string; warmth: "cold" | "warm"; ttft: Distribution; boot: Distribution; anchors: Record<string, number> }
+export interface BaselineRow { adapter: string; environment: string; warmth: "cold" | "warm"; ttft: Distribution; boot: Distribution;
+  /** The wait behind a live turn (input accepted to run created), its own measured step. */
+  inputWait: Distribution;
+  /** TTFT from run creation: the value the speed budget judges. */
+  ttftAfterRunCreated: Distribution;
+  anchors: Record<string, number> }
 
 export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] {
   const groups = new Map<string, { adapter: string; environment: string; warmth: "cold" | "warm"; metrics: RunMetrics[] }>();
@@ -145,7 +161,9 @@ export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] {
     for (const metric of group.metrics) if (metric.ttftAnchor) anchors[metric.ttftAnchor] = (anchors[metric.ttftAnchor] ?? 0) + 1;
     return { adapter: group.adapter, environment: group.environment, warmth: group.warmth, anchors,
       ttft: distribution(group.metrics.flatMap(metric => metric.ttftMs === null ? [] : [metric.ttftMs])),
-      boot: distribution(group.metrics.flatMap(metric => metric.bootMs === null ? [] : [metric.bootMs])) };
+      boot: distribution(group.metrics.flatMap(metric => metric.bootMs === null ? [] : [metric.bootMs])),
+      inputWait: distribution(group.metrics.flatMap(metric => metric.inputWaitMs === null ? [] : [metric.inputWaitMs])),
+      ttftAfterRunCreated: distribution(group.metrics.flatMap(metric => metric.ttftAfterRunCreatedMs === null ? [] : [metric.ttftAfterRunCreatedMs])) };
   });
 }
 

tests/restart-chaos/ttft-baseline.ts

@@ -152,9 +152,9 @@ async function readyAdapters(api: ChaosApi, lab: ChaosLab, adapters: AdapterId[]
 
 function report(runs: BaselineRun[], faults: BaselineFault[]): string {
   const ms = (value: number | null) => value === null ? "—" : `${(value / 1000).toFixed(2)} s`;
-  const lines = ["| Adapter | Env | Start | n | TTFT p50 | TTFT p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|"];
+  const lines = ["| Adapter | Env | Start | n | TTFT p50 | TTFT p95 | Wait behind live turn p50 / p95 (n) | TTFT from run created p50 / p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|---|---|"];
   for (const row of baselineRows(runs)) {
-    lines.push(`| ${row.adapter} | ${row.environment} | ${row.warmth} | ${row.ttft.n}/${row.boot.n} | ${ms(row.ttft.p50)} | ${ms(row.ttft.p95)} | ${ms(row.boot.p50)} | ${ms(row.boot.p95)} | ${Object.entries(row.anchors).map(([k, v]) => `${k}×${v}`).join(", ") || "—"} |`);
+    lines.push(`| ${row.adapter} | ${row.environment} | ${row.warmth} | ${row.ttft.n}/${row.boot.n} | ${ms(row.ttft.p50)} | ${ms(row.ttft.p95)} | ${ms(row.inputWait.p50)} / ${ms(row.inputWait.p95)} (${row.inputWait.n}) | ${ms(row.ttftAfterRunCreated.p50)} / ${ms(row.ttftAfterRunCreated.p95)} | ${ms(row.boot.p50)} | ${ms(row.boot.p95)} | ${Object.entries(row.anchors).map(([k, v]) => `${k}×${v}`).join(", ") || "—"} |`);
   }
   lines.push("", "| Pre-turn step | n | p50 | p95 | Adapters |", "|---|---|---|---|---|");
   for (const step of rankPreTurnSteps(runs).slice(0, 25)) lines.push(`| \`${step.step}\` | ${step.n} | ${ms(step.p50)} | ${ms(step.p95)} | ${step.adapters.join(", ")} |`);