diff --git a/doc/observability.md b/doc/observability.md index 46a39f5c749..c68ca2820e3 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -772,6 +772,18 @@ queueing, preparation and execution; do not add its duration to those phases. No text or provider event identifiers are exported. The existing duration attribute is `paperclip.native.span.duration_ms`. +`task.time_to_first_agent_activity` uses the same start and `anchor` as +`task.time_to_first_token`, and ends when Core commits the first event that +`provider.time_to_first_agent_event` counts: a text delta, a tool-call start, or +a reasoning item, whichever comes first. That is when the user sees the agent +respond, so the native speed budgets judge this span (metric +`time_to_first_activity`, measured from run creation). Its `eventKind` is +`agentMessage`, `reasoning`, `toolCall` or `dynamicToolCall`. Time to first text +stays a reported metric without a budget: tool-first adapters (for example +Claude) often call tools before they write any text, so first text includes +model tool work rather than control-plane latency. Like TTFT, it is a cumulative +child of `task.provider_session`; do not add it to the phases it overlaps. + `tool.request.input_stream` measures the observed request-input window: from an ACP tool announcement to its last input update before the provider reports the tool complete. It can include provider buffering and transport. It is not diff --git a/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md b/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md index c8038f06820..f20302066b8 100644 --- a/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md +++ b/doc/plans/2026-11-07-durable-ownership-and-reconciliation.md @@ -37,7 +37,7 @@ These become reconciler checks and crash-suite assertions. They should also be a 5. **Work-based budgets:** a restart consumes run budget only when the resumed attempt started provider work and made no progress. 6. **Generation fencing:** every runner and provider event carries its generation and turn. Events from an earlier generation are recorded as history and never fail the current turn. 7. **Visible next action:** every non-terminal task has a next action, either automatic or a working control. "Waiting" with no owner is a violation. -8. **Fast turns:** TTFT and agent boot stay within their measured budgets. Restart safety work never adds waiting or file transfer before `turn.start` (see "Performance constraint" below). +8. **Fast turns:** time to first visible agent activity and agent boot stay within their measured budgets (TTFT, time to first text, is reported; since 2026-11-08 the budget judges first activity, because tool-first adapters call tools before writing text). Restart safety work never adds waiting or file transfer before `turn.start` (see "Performance constraint" below). ## Performance constraint: a turn must start as fast as possible diff --git a/doc/plans/2026-11-07-ttft-baseline.md b/doc/plans/2026-11-07-ttft-baseline.md index 6cff9ed6142..055b976c464 100644 --- a/doc/plans/2026-11-07-ttft-baseline.md +++ b/doc/plans/2026-11-07-ttft-baseline.md @@ -45,6 +45,7 @@ Plan: [`2026-11-07-durable-ownership-and-reconciliation.md`](2026-11-07-durable- | Metric | Definition (run-log spans) | |---|---| | **TTFT** | `task.time_to_first_token`. It runs from the accepted input to the first deliverable text committed by Core. The accepted input is the wake comment, the answered question, or the durable wake request when that is earlier (#19838). Otherwise it is run creation. `anchor` names which one. | +| **First visible activity** | `task.time_to_first_agent_activity`: the same start as TTFT, to the first text delta, tool-call start or reasoning item committed by Core. Added 2026-11-08: the speed budgets judge this metric (from run creation) with the TTFT numbers below, and TTFT is reported without a budget, because tool-first adapters such as Claude call tools before they write text. | | **Agent boot** | Run claimed (end of `heartbeat.queue`) → provider session accepted `turn.start` (end of `runner.turn.submit`, or of `runner.session.resume` for a resumed session) | | **Pre-turn steps** | Every span that starts before the turn boundary above, without cumulative wrappers (`task.prepare`, `runner.session.startup`, `environment.startup`) | | **Restart recovery latency** | Fault `readyAt` (the harness saw `/api/ready` = `ready` and a healthy `/api/liveness`) → the recovered run's next provider event, grouped by `native.recovery.transition.runnerDisposition` | diff --git a/doc/run-log-events.md b/doc/run-log-events.md index 1119e5b8064..e6f63526d73 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -93,18 +93,20 @@ earlier output timing. The event contains no text or provider identifiers. level `warn`) records one native run that exceeded its p95 speed budget. The budgets come from the Phase 0 local baseline and are listed in `doc/plans/2026-11-07-durable-ownership-and-reconciliation.md` ("Speed budgets"). -`metric` is `ttft` (`task.time_to_first_token`), `agent_boot` (end of +`metric` is `time_to_first_activity` (`task.time_to_first_agent_activity`: +the first text delta, tool-call start or reasoning item; named `ttft` and +judged on `task.time_to_first_token` before 2026-11-08), `agent_boot` (end of `heartbeat.queue` to the end of `runner.turn.submit` or `runner.session.resume`) or `restart_recovery` (startup recovery `ready` to the recovered run's first 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 +For `time_to_first_activity`, `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 +judged only on `restart_recovery`, because its first activity and boot span the outage. Time to first text (`task.time_to_first_token`) is reported without a budget. Remote runs and other adapters have no budget yet. The event is written in detached diagnostic work after the measurement, so it adds no wait before `turn.start`. It is a run-log row only and never goes to Telemetry. diff --git a/server/src/services/native-runtime/native-run-trace.ts b/server/src/services/native-runtime/native-run-trace.ts index 7615ce13364..137ca901612 100644 --- a/server/src/services/native-runtime/native-run-trace.ts +++ b/server/src/services/native-runtime/native-run-trace.ts @@ -385,12 +385,13 @@ export function createNativeRunTrace(input: { // 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") { + if (name === "task.time_to_first_agent_activity") { // 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. + // Time to first text (task.time_to_first_token) is reported, not budgeted. const inputWaitMs = runCreatedAtMs !== null && runCreatedAtMs > startedAtMs ? runCreatedAtMs - startedAtMs : 0; - reportBudgetBreach(evaluateSpeedBudget({ ...subject, metric: "ttft", start: budgetStart, + reportBudgetBreach(evaluateSpeedBudget({ ...subject, metric: "time_to_first_activity", start: budgetStart, measuredMs: endedAtMs - startedAtMs - inputWaitMs, ...(inputWaitMs > 0 ? { inputWaitMs } : {}) })); } // Agent boot: run claimed (end of heartbeat.queue) to the provider session diff --git a/server/src/services/native-runtime/native-session-executor.test.ts b/server/src/services/native-runtime/native-session-executor.test.ts index aff0735736e..ce4ecb810bf 100644 --- a/server/src/services/native-runtime/native-session-executor.test.ts +++ b/server/src/services/native-runtime/native-session-executor.test.ts @@ -8842,6 +8842,41 @@ describe("native resumed preparation timing", () => { }, ); + it("records first visible activity at a tool call that precedes the first text", async () => { + const startedAtMs = Date.now() - 20_000; + const events: AdapterRuntimeEvent[] = []; + const clock = vi.spyOn(Date, "now").mockReturnValue(startedAtMs + 3_000); + const event = (eventType: string, payload: Record) => ({ + eventType, payload, itemId: "item", emittedAt: new Date(Date.now()).toISOString(), + }) as PrpEvent; + state.execute.mockReset().mockImplementationOnce(async () => { + for (const candidate of [event("turn.submitted", {}), event("turn.started", {})]) await accountingEvents.committed!(candidate); + clock.mockReturnValue(startedAtMs + 5_000); + // Tool-first: the agent starts a tool before it writes any text. + await accountingEvents.committed!(event("tool.execution.started", { executionId: "tool-1" })); + clock.mockReturnValue(startedAtMs + 16_000); + await accountingEvents.committed!(event("item.delta", { kind: "agentMessage", text: "first text" })); + return { result: { summary: "cancelled" }, terminal: { runTerminalState: "cancelled" }, + turnId: "turn", normalizedSessionId: "session", providerSessionId: null, + driverKind: "test", driverVersion: "1", nativeEventCount: 1, highestContiguousSourceSeq: 1 }; + }); + try { + await executePaperclipNativeSession({ db: leaseDb(), execution, runnerInstanceId: "runner", + preparationSpans: [{ name: "heartbeat.queue", startedAtMs, endedAtMs: startedAtMs + 100 }], + onEvent: async (event) => { + events.push(event); + // A slow run-log sink: writing the first-agent-event span takes 3 s. + // That write must not count as time until the agent responded. + if (event.payload?.span === "provider.time_to_first_agent_event") clock.mockReturnValue(startedAtMs + 8_000); + } }); + } finally { clock.mockRestore(); } + const span = (name: string) => events.filter((candidate) => candidate.payload?.span === name); + expect(span("task.time_to_first_agent_activity")).toHaveLength(1); + expect(span("task.time_to_first_agent_activity")[0]?.payload).toMatchObject({ parentSpan: "task.provider_session", + startOffsetMs: 0, durationMs: 5_000, eventKind: "toolCall", anchor: "run_created" }); + expect(span("task.time_to_first_token")[0]?.payload).toMatchObject({ durationMs: 16_000, eventKind: "agentMessage" }); + }); + it("anchors first-token timing at an earlier durable wake request without blocking later events", async () => { const startedAtMs = Date.now() - 5_000; const events: AdapterRuntimeEvent[] = []; diff --git a/server/src/services/native-runtime/native-session-executor.ts b/server/src/services/native-runtime/native-session-executor.ts index 5a3c30b02cd..bddd42e90e3 100644 --- a/server/src/services/native-runtime/native-session-executor.ts +++ b/server/src/services/native-runtime/native-session-executor.ts @@ -10363,6 +10363,9 @@ async function executePaperclipNativeSessionWithinScope( const kind = firstMeaningfulAgentEventKind(event); if (kind) { firstAgentEventRecorded = true; + // The commit observation, read before any diagnostic write so a slow + // run-log sink never counts as time until the agent responded. + const activityAt = Date.now(); await trace.record({ name: "provider.time_to_first_agent_event", parentName: "agent.turn", @@ -10370,6 +10373,23 @@ async function executePaperclipNativeSessionWithinScope( endedAtMs: milestoneAtMs, attributes: { eventKind: kind }, }); + // The user-visible response (the speed budget's metric): the same + // anchor as time to first text, to this first visible agent event. + // Detached like TTFT, so the anchor read never delays the turn. + trace.defer(async () => { + const activityStart = resolveNativeTimeToFirstTokenStart({ + traceStartedAtMs: trace.traceStartedAtMs, + preparationSpans, + wakeRequestedAtMs: await readNativeRunWakeRequestedAtMs(input.db, input.execution.binding.runId), + }); + await trace.record({ + name: "task.time_to_first_agent_activity", + parentName: "task.provider_session", + startedAtMs: activityStart.startedAtMs, + endedAtMs: activityAt, + attributes: { eventKind: kind, anchor: activityStart.anchor }, + }); + }); } } if ( diff --git a/server/src/services/native-runtime/native-speed-budgets.test.ts b/server/src/services/native-runtime/native-speed-budgets.test.ts index 72741b7c20b..1b54906f324 100644 --- a/server/src/services/native-runtime/native-speed-budgets.test.ts +++ b/server/src/services/native-runtime/native-speed-budgets.test.ts @@ -14,7 +14,7 @@ import { describe("speed budgets", () => { it("defines p50 below p95 for every adapter, metric and start", () => { for (const budgets of Object.values(LOCAL_SPEED_BUDGETS)) { - for (const budget of [budgets.ttft.cold, budgets.ttft.warm, budgets.agent_boot.cold, budgets.agent_boot.warm, + for (const budget of [budgets.time_to_first_activity.cold, budgets.time_to_first_activity.warm, budgets.agent_boot.cold, budgets.agent_boot.warm, budgets.restart_recovery]) { expect(budget.p50Ms).toBeGreaterThan(0); expect(budget.p50Ms).toBeLessThanOrEqual(budget.p95Ms); @@ -31,20 +31,20 @@ describe("speed budgets", () => { }); it("judges one run against p95 and uses the looser budget when the start kind is unknown", () => { - const codexCold = LOCAL_SPEED_BUDGETS.codex.ttft.cold.p95Ms; - expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "ttft", start: "cold", measuredMs: codexCold })) + const codexCold = LOCAL_SPEED_BUDGETS.codex.time_to_first_activity.cold.p95Ms; + expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "time_to_first_activity", start: "cold", measuredMs: codexCold })) .toBeNull(); - expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "ttft", start: "cold", measuredMs: codexCold + 1 })) - .toMatchObject({ metric: "ttft", adapter: "codex", startKind: "cold", budgetP95Ms: codexCold, percentile: "p95" }); - const loose = speedBudgetFor("codex", "ttft", null); - expect(loose.p95Ms).toBe(Math.max(codexCold, LOCAL_SPEED_BUDGETS.codex.ttft.warm.p95Ms)); - expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "ttft", start: null, measuredMs: codexCold + 1 })) + expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "time_to_first_activity", start: "cold", measuredMs: codexCold + 1 })) + .toMatchObject({ metric: "time_to_first_activity", adapter: "codex", startKind: "cold", budgetP95Ms: codexCold, percentile: "p95" }); + const loose = speedBudgetFor("codex", "time_to_first_activity", null); + expect(loose.p95Ms).toBe(Math.max(codexCold, LOCAL_SPEED_BUDGETS.codex.time_to_first_activity.warm.p95Ms)); + expect(evaluateSpeedBudget({ adapter: "codex", environment: "local", metric: "time_to_first_activity", start: null, measuredMs: codexCold + 1 })) .toBeNull(); }); it("does not judge remote runs or adapters without a baseline", () => { - expect(evaluateSpeedBudget({ adapter: "codex", environment: "remote", metric: "ttft", start: "cold", measuredMs: 1e9 })).toBeNull(); - expect(evaluateSpeedBudget({ adapter: null, environment: "local", metric: "ttft", start: "cold", measuredMs: 1e9 })).toBeNull(); + expect(evaluateSpeedBudget({ adapter: "codex", environment: "remote", metric: "time_to_first_activity", start: "cold", measuredMs: 1e9 })).toBeNull(); + expect(evaluateSpeedBudget({ adapter: null, environment: "local", metric: "time_to_first_activity", start: "cold", measuredMs: 1e9 })).toBeNull(); }); }); @@ -66,7 +66,7 @@ describe("speed budget checks in the native run trace", () => { await trace.record({ name: "runner.turn.submit", startedAtMs: 100, endedAtMs: 100 + boot }); // A second submit in the same run is not a second boot. await trace.record({ name: "runner.turn.submit", startedAtMs: 100, endedAtMs: 100 + boot * 2 }); - await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: 1_000 }); + await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 1_000 }); await trace.finish("ok"); expect(breaches()).toEqual([expect.objectContaining({ @@ -78,25 +78,25 @@ describe("speed budget checks in the native run trace", () => { it("writes a breach for a slow TTFT recorded by deferred diagnostics before the trace closes", async () => { const { trace, breaches } = traced({ adapter: "claude", environment: "local" }); trace.setBudgetStart("warm"); - const ttft = LOCAL_SPEED_BUDGETS.claude.ttft.warm.p95Ms + 1; + const ttft = LOCAL_SPEED_BUDGETS.claude.time_to_first_activity.warm.p95Ms + 1; trace.defer(async () => { - await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: ttft }); + await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: ttft }); }); await trace.finish("ok"); - expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", adapter: "claude", startKind: "warm", measuredMs: ttft })]); + expect(breaches()).toEqual([expect.objectContaining({ metric: "time_to_first_activity", 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 budget = LOCAL_SPEED_BUDGETS.claude.time_to_first_activity.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.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: wait + budget - 1 }); await quiet.trace.finish("ok"); expect(quiet.breaches()).toEqual([]); @@ -104,22 +104,34 @@ describe("speed budget checks in the native run trace", () => { 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.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: wait + budget + 1 }); await slow.trace.finish("ok"); - expect(slow.breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1, inputWaitMs: wait })]); + expect(slow.breaches()).toEqual([expect.objectContaining({ metric: "time_to_first_activity", 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; + const budget = LOCAL_SPEED_BUDGETS.codex.time_to_first_activity.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.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: budget + 1 }); await trace.finish("ok"); - expect(breaches()).toEqual([expect.objectContaining({ metric: "ttft", measuredMs: budget + 1 })]); + expect(breaches()).toEqual([expect.objectContaining({ metric: "time_to_first_activity", measuredMs: budget + 1 })]); expect(breaches()[0]).not.toHaveProperty("inputWaitMs"); }); + it("judges first visible activity, not first text, so a tool-first turn is within budget", async () => { + const { trace, breaches } = traced({ adapter: "claude", environment: "local" }); + trace.setBudgetStart("cold"); + const budget = LOCAL_SPEED_BUDGETS.claude.time_to_first_activity.cold.p95Ms; + await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: 50 }); + // The agent calls a tool at once and writes its first text much later. + await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 5_000 }); + await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: budget * 2 }); + await trace.finish("ok"); + expect(breaches()).toEqual([]); + }); + 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; @@ -135,7 +147,7 @@ describe("speed budget checks in the native run trace", () => { const { trace, breaches } = traced({ adapter: "codex", environment: "local", restartRecovery: true }); await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: 1 }); await trace.record({ name: "runner.session.resume", startedAtMs: 1, endedAtMs: 120_000 }); - await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: 120_000 }); + await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 120_000 }); const at = LOCAL_SPEED_BUDGETS.codex.restart_recovery.p95Ms + 1; trace.checkRestartRecovery({ readyAtMs: 0, emittedAtMs: at, committedAtMs: at, disposition: "resume_dead_runner" }); await trace.finish("ok"); @@ -189,7 +201,7 @@ describe("speed budget checks in the native run trace", () => { const { trace, breaches } = traced(budget); await trace.record({ name: "heartbeat.queue", startedAtMs: 0, endedAtMs: 1 }); await trace.record({ name: "runner.turn.submit", startedAtMs: 1, endedAtMs: 10_000_000 }); - await trace.record({ name: "task.time_to_first_token", startedAtMs: 0, endedAtMs: 10_000_000 }); + await trace.record({ name: "task.time_to_first_agent_activity", startedAtMs: 0, endedAtMs: 10_000_000 }); await trace.finish("ok"); expect(breaches()).toEqual([]); } diff --git a/server/src/services/native-runtime/native-speed-budgets.ts b/server/src/services/native-runtime/native-speed-budgets.ts index 3b49837caf2..cc6302b88bb 100644 --- a/server/src/services/native-runtime/native-speed-budgets.ts +++ b/server/src/services/native-runtime/native-speed-budgets.ts @@ -14,7 +14,15 @@ */ export type SpeedBudgetAdapter = "claude" | "codex" | "opencode"; -export type SpeedBudgetMetric = "ttft" | "agent_boot" | "restart_recovery"; +/** + * `time_to_first_activity`: run creation to the first agent activity the UI + * shows (a text delta, a tool-call start or a reasoning indicator, whichever + * comes first; span `task.time_to_first_agent_activity`). That is when the user + * sees the agent respond. Time to first text (`task.time_to_first_token`) stays + * a reported metric without a budget: tool-first adapters such as Claude often + * call tools before they write text. The budget numbers are the TTFT baseline's. + */ +export type SpeedBudgetMetric = "time_to_first_activity" | "agent_boot" | "restart_recovery"; export type SpeedBudgetStart = "cold" | "warm"; export type SpeedBudget = { p50Ms: number; p95Ms: number }; @@ -31,24 +39,24 @@ export const RESTART_RECOVERY_PROVIDER_EVENT_TYPES: ReadonlySet = new Se const s = (seconds: number) => Math.round(seconds * 1000); -/** TTFT and agent boot by adapter and start kind; restart recovery by adapter. */ +/** First activity and agent boot by adapter and start kind; restart recovery by adapter. */ export const LOCAL_SPEED_BUDGETS: Readonly; + time_to_first_activity: Record; agent_boot: Record; restart_recovery: SpeedBudget; }>> = { claude: { - ttft: { cold: { p50Ms: s(16.5), p95Ms: s(30) }, warm: { p50Ms: s(9.5), p95Ms: s(28.5) } }, + time_to_first_activity: { cold: { p50Ms: s(16.5), p95Ms: s(30) }, warm: { p50Ms: s(9.5), p95Ms: s(28.5) } }, agent_boot: { cold: { p50Ms: s(9), p95Ms: s(20.5) }, warm: { p50Ms: s(3.5), p95Ms: s(16.5) } }, restart_recovery: { p50Ms: s(15), p95Ms: s(22.5) }, }, codex: { - ttft: { cold: { p50Ms: s(6), p95Ms: s(17) }, warm: { p50Ms: s(10), p95Ms: s(28.5) } }, + time_to_first_activity: { cold: { p50Ms: s(6), p95Ms: s(17) }, warm: { p50Ms: s(10), p95Ms: s(28.5) } }, agent_boot: { cold: { p50Ms: s(2.5), p95Ms: s(7) }, warm: { p50Ms: s(5), p95Ms: s(16.5) } }, restart_recovery: { p50Ms: s(6.5), p95Ms: s(8) }, }, opencode: { - ttft: { cold: { p50Ms: s(17.5), p95Ms: s(49) }, warm: { p50Ms: s(26.5), p95Ms: s(88) } }, + time_to_first_activity: { cold: { p50Ms: s(17.5), p95Ms: s(49) }, warm: { p50Ms: s(26.5), p95Ms: s(88) } }, agent_boot: { cold: { p50Ms: s(12), p95Ms: s(37) }, warm: { p50Ms: s(22), p95Ms: s(65.5) } }, restart_recovery: { p50Ms: s(25.5), p95Ms: s(38.5) }, }, @@ -87,7 +95,7 @@ export type SpeedBudgetBreach = { percentile: "p95"; baseline: string; disposition?: string; - /** TTFT only: time the input waited for its run to exist (for example a + /** First activity 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; }; diff --git a/tests/restart-chaos/ttft-baseline-stats.test.ts b/tests/restart-chaos/ttft-baseline-stats.test.ts index f82fd5159b5..39a5490fc9b 100644 --- a/tests/restart-chaos/ttft-baseline-stats.test.ts +++ b/tests/restart-chaos/ttft-baseline-stats.test.ts @@ -77,6 +77,33 @@ describe("ttft baseline statistics", () => { ttft: { n: 2, p50: 6_000, p95: 12_000 } }); }); + it("reports first visible activity from run creation next to first text", () => { + const toolFirst = run("t", "warm", [ + reuse("reused"), + span("comment.to_run_created", 0, 30_000), + span("heartbeat.queue", 30_000, 100), + span("task.time_to_first_agent_activity", 0, 35_000, { anchor: "comment" }), + span("task.time_to_first_token", 0, 48_000, { anchor: "comment" }), + ], "claude"); + expect(runMetrics(toolFirst)).toMatchObject({ inputWaitMs: 30_000, firstActivityAfterRunCreatedMs: 5_000, + ttftAfterRunCreatedMs: 18_000 }); + expect(baselineRows([toolFirst])[0]).toMatchObject({ firstActivityAfterRunCreated: { p50: 5_000 }, + ttftAfterRunCreated: { p50: 18_000 } }); + }); + + it("measures first activity from run creation even when it is anchored at an earlier wake request", () => { + // A deferred wake accepted 30 s before the run existed; activity 5 s after run creation. + const deferred = run("d", "cold", [ + reuse("fresh"), + span("heartbeat.queue", 0, 100), + span("task.time_to_first_agent_activity", -30_000, 35_000, { anchor: "wake_request" }), + ], "claude"); + expect(runMetrics(deferred).firstActivityAfterRunCreatedMs).toBe(5_000); + const deferredText = run("e", "cold", [reuse("fresh"), span("heartbeat.queue", 0, 100), + span("task.time_to_first_token", -30_000, 35_000, { anchor: "wake_request" })], "claude"); + expect(runMetrics(deferredText).ttftAfterRunCreatedMs).toBe(5_000); + }); + it("ranks pre-turn steps by p95 without cumulative wrappers", () => { const ranked = rankPreTurnSteps([coldRun("a"), coldRun("b", 2)]); expect(ranked[0]).toMatchObject({ step: "runner.process.launch", n: 2, p95: 3_000 }); diff --git a/tests/restart-chaos/ttft-baseline-stats.ts b/tests/restart-chaos/ttft-baseline-stats.ts index 5043f886feb..3e5bda1f661 100644 --- a/tests/restart-chaos/ttft-baseline-stats.ts +++ b/tests/restart-chaos/ttft-baseline-stats.ts @@ -74,12 +74,16 @@ export interface RunMetrics { * `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. */ + /** TTFT (first text) from run creation: reported, no budget for tool-first adapters. */ ttftAfterRunCreatedMs: number | null; + /** First visible agent activity (text delta, tool-call start or reasoning) + * from run creation (`task.time_to_first_agent_activity`): what the speed + * budget judges. */ + firstActivityAfterRunCreatedMs: 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", "comment.to_run_created", "question_response.to_run_created", "task.provider_session.measured", "task.prepare", +const CUMULATIVE_SPANS = new Set(["task.time_to_first_token", "task.time_to_first_agent_activity", "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; @@ -87,6 +91,7 @@ const FIRST_SPAN = (spans: RunSpan[], name: string) => spans.find(span => span.n export function runMetrics(run: BaselineRun): RunMetrics { const spans = runSpans(run); const ttft = FIRST_SPAN(spans, "task.time_to_first_token"); + const activity = FIRST_SPAN(spans, "task.time_to_first_agent_activity"); const queue = FIRST_SPAN(spans, "heartbeat.queue"); // runner.turn.submit = session.started → turn.submitted; a resumed session has // runner.session.resume ending at turn.submitted instead. @@ -103,10 +108,19 @@ export function runMetrics(run: BaselineRun): RunMetrics { } 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; + const anchor = ttft ?? activity; + // From run creation, as the runtime budget judges it: the start of + // heartbeat.queue, else the end of the ingress span. Independent of the + // span's own anchor (an earlier wake request or comment is not counted). + const runCreatedAt = queue ? queue.startOffsetMs : ingress ? ingress.startOffsetMs + ingress.durationMs : null; + const afterRunCreated = (span: RunSpan) => runCreatedAt === null + ? Math.max(0, span.durationMs - (inputWaitMs ?? 0)) + : Math.max(0, span.startOffsetMs + span.durationMs - runCreatedAt); + const inputWaitMs = ingress && anchor && ingress.startOffsetMs <= anchor.startOffsetMs ? ingress.durationMs : null; return { inputWaitMs, - ttftAfterRunCreatedMs: ttft ? Math.max(0, ttft.durationMs - (inputWaitMs ?? 0)) : null, + firstActivityAfterRunCreatedMs: activity ? afterRunCreated(activity) : null, + ttftAfterRunCreatedMs: ttft ? afterRunCreated(ttft) : 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, @@ -142,8 +156,10 @@ export function recoverySamples(runs: readonly BaselineRun[], faults: readonly B 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. */ + /** TTFT (first text) from run creation: reported. */ ttftAfterRunCreated: Distribution; + /** First visible agent activity from run creation: the value the speed budget judges. */ + firstActivityAfterRunCreated: Distribution; anchors: Record } export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] { @@ -164,7 +180,8 @@ export function baselineRows(runs: readonly BaselineRun[]): BaselineRow[] { ttft: distribution(group.metrics.flatMap(metric => metric.ttftMs === null ? [] : [metric.ttftMs])), 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])) }; + ttftAfterRunCreated: distribution(group.metrics.flatMap(metric => metric.ttftAfterRunCreatedMs === null ? [] : [metric.ttftAfterRunCreatedMs])), + firstActivityAfterRunCreated: distribution(group.metrics.flatMap(metric => metric.firstActivityAfterRunCreatedMs === null ? [] : [metric.firstActivityAfterRunCreatedMs])) }; }); } diff --git a/tests/restart-chaos/ttft-baseline.ts b/tests/restart-chaos/ttft-baseline.ts index 291a12ffd19..2f1fe6d633d 100644 --- a/tests/restart-chaos/ttft-baseline.ts +++ b/tests/restart-chaos/ttft-baseline.ts @@ -190,8 +190,8 @@ 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 | Wait behind live turn p50 / p95 (n) | TTFT from run created p50 / p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|---|---|"]; - const rowLine = (row: ReturnType[number]) => `| ${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(", ") || "—"} |`; + const lines = ["| Adapter | Env | Start | n | TTFT p50 | TTFT p95 | Wait behind live turn p50 / p95 (n) | First activity from run created p50 / p95 (budget) | TTFT from run created p50 / p95 | Boot p50 | Boot p95 | TTFT anchors |", "|---|---|---|---|---|---|---|---|---|---|---|---|"]; + const rowLine = (row: ReturnType[number]) => `| ${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.firstActivityAfterRunCreated.p50)} / ${ms(row.firstActivityAfterRunCreated.p95)} | ${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(", ") || "—"} |`; for (const row of baselineRows(runs)) lines.push(rowLine(row)); // New agents wait for harness verification before their run is created: // their own rows, so that wait never blends into ordinary cold starts.