From 62f60bf158746c5807763778326b1eba4f2ed18a Mon Sep 17 00:00:00 2001 From: Nicky Leach Date: Sat, 24 Oct 2026 09:40:08 -0700 Subject: [PATCH] Measure first deliverable text in native run traces (#17434) --- doc/observability.md | 35 +++++++ doc/run-log-events.md | 14 +++ maps/agent-access-map/runs-adapters.md | 3 + maps/feature-map/runs-adapters.md | 3 + .../native-deliverable-text.test.ts | 56 +++++++++++ .../native-runtime/native-deliverable-text.ts | 57 ++++++++++++ .../native-session-executor.test.ts | 92 +++++++++++++++++++ .../native-runtime/native-session-executor.ts | 15 +++ 8 files changed, 275 insertions(+) create mode 100644 server/src/services/native-runtime/native-deliverable-text.test.ts create mode 100644 server/src/services/native-runtime/native-deliverable-text.ts diff --git a/doc/observability.md b/doc/observability.md index ae4deb44c38..55328507d0c 100644 --- a/doc/observability.md +++ b/doc/observability.md @@ -627,6 +627,41 @@ execution identity, or an existing assistant/reasoning/tool item start or completion. Usage updates and empty deltas do not count. This is a first activity metric, not time to a finished answer. +`task.time_to_first_token` measures the wait until text is deliverable to the +task transcript for each native dispatch. The first qualifying event is a +nonempty assistant or reasoning text delta, a completed assistant or reasoning +item with text, or an accepted run result with a nonempty summary. Text released +by redaction at item/turn/session completion also qualifies. Item identities and +text fields follow the task transcript projection; item starts, tools, usage, +empty text, result proposals, and duplicate PRP replay do not end the wait. + +The first-text milestone occurs after `task.prepare` and Runner startup. The +timing span is a cumulative interval, not a separate preparation step: + +```text +accepted ingress → queue → task.prepare → Runner startup → provider work → first text +└────────────────────── task.time_to_first_token ──────────────────────────────────┘ +``` + +The span starts at the native run trace's historical start: +the accepted comment or attested question response when present, otherwise run +creation from the queue span. Callers without preparation history start at native +dispatch. The interval includes queueing, Core preparation, workspace preparation, +Runner startup, provider latency, transport, and durable event ingestion. It ends +in Core's commit callback, when the text is readable through the run-events API, +using the Core clock rather than the provider event timestamp. Browser delivery +and rendering are excluded. The name is retained for existing trace queries; +this measures the first deliverable text, not an exact model token boundary. +Only the first qualifying event in a dispatch emits a span. Its `eventKind` is +`reasoning` for thinking text and `agentMessage` for assistant text or a result. +A dispatch without deliverable text emits no sample, including an early failure. +Same-run recovery retains the original historical start and can emit a new sample +only for newly committed output; it does not reconstruct prior first-token timing. +`task.time_to_first_token` is a child of `task.provider_session` that overlaps +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`. + `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/run-log-events.md b/doc/run-log-events.md index d9cbb905cb0..b449def19f6 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -64,6 +64,20 @@ instance run log and add no first-party Telemetry or OpenTelemetry export. ## Provider-pack preparation timing +`run.performance.span` also records `task.time_to_first_token` once per native +dispatch at the first newly committed deliverable text: assistant or reasoning +`item.delta`/`item.completed`, a redaction tail released at completion, or an +accepted run-result summary. Its +`durationMs` starts at the native run trace's historical start (accepted ingress, +otherwise queued run creation, or dispatch when history is absent) and ends at Core +commit callback. `startOffsetMs` is zero, and `eventKind` is `agentMessage` or +`reasoning`. It includes preparation and startup, but excludes browser +delivery/rendering. This measures text availability, not an exact model token. +Empty text, item starts, tools, usage, result proposals, and duplicate replay do +not qualify. No deliverable text means no timing sample. A recovered dispatch can +record newly committed output from the original start; it does not reproduce +earlier output timing. The event contains no text or provider identifiers. + The existing `run.performance.span` event also records `provider_pack.select`, `provider_pack.discover`, `provider_pack.verify`, `provider_pack.verify_preinstalled`, `provider_pack.link_preinstalled`, `provider_pack.clear_stale`, `provider_pack.upload`, diff --git a/maps/agent-access-map/runs-adapters.md b/maps/agent-access-map/runs-adapters.md index be3a21b69a8..7f5552f9919 100644 --- a/maps/agent-access-map/runs-adapters.md +++ b/maps/agent-access-map/runs-adapters.md @@ -199,6 +199,9 @@ existing hashed run ID. Controller startup phase spans carry no custom attribute Native controller setup and settlement phases use that same run hash, including assigned MCP discovery; neither tool definitions nor credentials are recorded. Both retain operator-controlled tracing; unconfigured clients stay silent. +The native first-text span ends after text is committed for the existing run-events +reader, including reasoning and completed responses. It exports only the bounded +text kind and timing, with no text content or new agent access. This adds no agent API, credential access, run-log write, or recovery authority. See [the tracing contract](../../doc/observability.md#controller-preparation-phases). Live latency verification remains separate from the existing access baseline. diff --git a/maps/feature-map/runs-adapters.md b/maps/feature-map/runs-adapters.md index cdbd1510f11..c44576823c7 100644 --- a/maps/feature-map/runs-adapters.md +++ b/maps/feature-map/runs-adapters.md @@ -38,6 +38,9 @@ without restricting the root span name. Compare workspace preparation with its `controller.startup.`. A recovery pause or deployment drain is not model execution time. See the [tracing contract](../../doc/observability.md#controller-preparation-phases). These source-level diagnostics do not establish a live response-time budget. +`task.time_to_first_token` measures accepted ingress through the first committed +text that the task transcript can show, including thinking and completed +responses. It includes preparation and startup, and excludes browser latency. Inspect `native.controller.` for backend construction, assigned-tool discovery and post-turn cleanup. Compare those intervals with the actual model turn; do not count a nested discovery interval twice. diff --git a/server/src/services/native-runtime/native-deliverable-text.test.ts b/server/src/services/native-runtime/native-deliverable-text.test.ts new file mode 100644 index 00000000000..49b55e08f77 --- /dev/null +++ b/server/src/services/native-runtime/native-deliverable-text.test.ts @@ -0,0 +1,56 @@ +import { describe, expect, it } from "vitest"; +import type { PrpEvent } from "../../vendor/paperclip-runner/index.js"; +import { createNativeDeliverableTextObservation } from "./native-deliverable-text.js"; + +function event(eventType: string, payload: Record, itemId?: string) { + return { eventType, payload, ...(itemId ? { itemId } : {}) } as PrpEvent; +} + +describe("native deliverable text", () => { + it.each(["agentMessage", "assistant_message", "reasoning"])("accepts streamed and completed %s text", (kind) => { + const observe = createNativeDeliverableTextObservation(); + const expected = kind === "reasoning" ? "reasoning" : "agentMessage"; + expect(observe(event("item.delta", { kind, text: "text" }, "message"))).toBe(expected); + expect(observe(event("item.completed", { kind, text: "text" }))).toBe(expected); + }); + + it("matches nested and inherited transcript item identities without counting starts", () => { + const observe = createNativeDeliverableTextObservation(); + expect(observe(event("item.started", { item: { id: "message", type: "agentMessage", text: "hidden" } }))).toBeNull(); + expect(observe(event("item.delta", { item: { id: "message", text: "visible" } }))).toBe("agentMessage"); + expect(observe(event("item.started", { kind: "reasoning" }, "thought"))).toBeNull(); + expect(observe(event("item.delta", { text: "thinking" }, "thought"))).toBe("reasoning"); + }); + + it("accepts text released by redaction at terminal boundaries", () => { + const observe = createNativeDeliverableTextObservation(); + expect(observe(event("item.delta", { kind: "reasoning", text: "" }, "thought"))).toBeNull(); + expect(observe(event("turn.completed", { outputTails: [ + { itemId: "thought", payload: { text: "settled thought" } }, + ] }))).toBe("reasoning"); + }); + + it("accepts an accepted result summary without any streamed text", () => { + const observe = createNativeDeliverableTextObservation(); + const result = { schema: "paperclip.run_result.v1", summary: "Done" }; + expect(observe(event("run.result.proposed", result))).toBeNull(); + expect(observe(event("run.result.accepted", { result }))).toBe("agentMessage"); + }); + + it.each([ + event("item.delta", { kind: "agentMessage", delta: "not projected" }, "message"), + event("item.delta", { kind: "agentMessage", content: "not projected" }, "message"), + event("item.delta", { kind: "agentMessage", text: "missing identity" }), + event("item.delta", { kind: "agentMessage", text: " " }, "message"), + event("item.completed", { kind: "reasoning", text: 42 }), + event("item.completed", { kind: "usage", text: "tokens" }), + event("item.completed", { kind: "toolCall", text: "arguments" }), + event("tool.execution.started", { executionId: "tool", text: "tool" }), + event("turn.started", { kind: "agentMessage", text: "metadata" }), + event("run.result.accepted", { result: { schema: "other", summary: "wrong schema" } }), + event("run.result.accepted", { result: { schema: "paperclip.run_result.v1", summary: " " } }), + event("turn.completed", { outputTails: [{ payload: { kind: "agentMessage", text: "no identity" } }] }), + ])("ignores text that the task transcript cannot show: %j", (candidate) => { + expect(createNativeDeliverableTextObservation()(candidate)).toBeNull(); + }); +}); diff --git a/server/src/services/native-runtime/native-deliverable-text.ts b/server/src/services/native-runtime/native-deliverable-text.ts new file mode 100644 index 00000000000..e228303ea0e --- /dev/null +++ b/server/src/services/native-runtime/native-deliverable-text.ts @@ -0,0 +1,57 @@ +import type { PrpEvent } from "../../vendor/paperclip-runner/index.js"; + +type TextKind = "agentMessage" | "reasoning"; + +function record(value: unknown): Record { + return value && typeof value === "object" && !Array.isArray(value) + ? value as Record + : {}; +} + +function text(value: unknown): string | null { + return typeof value === "string" && value.length > 0 ? value : null; +} + +export function createNativeDeliverableTextObservation() { + const itemKinds = new Map(); + const observeItem = (payload: Record, envelopeItemId?: string): TextKind | null => { + const item = record(payload.item); + const itemId = text(envelopeItemId) ?? text(payload.itemId) ?? text(item.id); + const kind = (text(payload.kind) ?? text(item.kind) ?? text(item.type) ?? "") + .replaceAll("_", "").toLowerCase() || (itemId ? itemKinds.get(itemId) : ""); + if (itemId && kind) itemKinds.set(itemId, kind); + if (!(text(payload.text) ?? text(item.text))?.trim()) return null; + if (kind === "reasoning") return "reasoning"; + return kind === "agentmessage" || kind === "assistantmessage" ? "agentMessage" : null; + }; + + return (event: Pick): TextKind | null => { + const payload = record(event.payload); + if (/^(item|turn|session)\.(completed|failed|cancelled|interrupted|closed)$/.test(event.eventType) + && Array.isArray(payload.outputTails)) { + for (const value of payload.outputTails) { + const tail = record(value); + const tailPayload = record(tail.payload); + const itemId = text(tail.itemId) ?? text(tailPayload.itemId) ?? text(record(tailPayload.item).id); + if (!itemId || typeof tailPayload.text !== "string") continue; + const kind = observeItem(tailPayload, itemId); + if (kind) return kind; + } + } + if (event.eventType === "item.started") { + observeItem(payload, event.itemId); + return null; + } + if (event.eventType === "item.delta" || event.eventType === "item.completed") { + const item = record(payload.item); + if (event.eventType === "item.delta" && + !(text(event.itemId) ?? text(payload.itemId) ?? text(item.id))) return null; + return observeItem(payload, event.itemId); + } + if (event.eventType === "run.result.accepted") { + const result = record(payload.result); + if (result.schema === "paperclip.run_result.v1" && text(result.summary)?.trim()) return "agentMessage"; + } + return null; + }; +} 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 6c48569a2d6..66a235cc2ba 100644 --- a/server/src/services/native-runtime/native-session-executor.test.ts +++ b/server/src/services/native-runtime/native-session-executor.test.ts @@ -6324,6 +6324,98 @@ describe("native terminal-turn accounting", () => { }); describe("native resumed preparation timing", () => { + it.each(["comment.to_run_created", "question_response.to_run_created", "heartbeat.queue", "native_dispatch"])( + "records first assistant text once from %s through Core preparation and event receipt", + async (ingress) => { + const startedAtMs = Date.now() - 5_000; + const events: AdapterRuntimeEvent[] = []; + const clock = vi.spyOn(Date, "now").mockReturnValue(startedAtMs + 4_000); + const event = (eventType: string, payload: Record) => ({ + eventType, payload, itemId: "message", emittedAt: new Date(startedAtMs + 2_000).toISOString(), + }) as PrpEvent; + state.execute.mockReset().mockImplementationOnce(async () => { + for (const candidate of [ + event("turn.submitted", {}), + event("turn.started", {}), + event("item.started", { kind: "agentMessage" }), + event("item.completed", { kind: "agentMessage", text: " " }), + event("item.delta", { kind: "agentMessage", text: " " }), + event("item.delta", { kind: "agentMessage", text: 42 }), + event("item.delta", { kind: "reasoning", text: "" }), + event("item.delta", { kind: "toolCall", text: "arguments" }), + event("item.delta", { kind: "usage", text: "tokens" }), + event("tool.execution.started", { executionId: "tool-1" }), + ]) await accountingEvents.committed!(candidate); + await accountingEvents.duplicate!(event("item.delta", { kind: "agentMessage", text: "replayed text" })); + expect(events.some((candidate) => candidate.payload?.span === "task.time_to_first_token")).toBe(false); + clock.mockReturnValue(startedAtMs + 4_500); + await accountingEvents.committed!(event("item.delta", { kind: "agentMessage", text: "first text" })); + clock.mockReturnValue(startedAtMs + 4_750); + await accountingEvents.committed!(event("item.delta", { kind: "agentMessage", text: "later 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: ingress === "native_dispatch" ? [] : [{ name: ingress, startedAtMs, endedAtMs: startedAtMs + 100 }], + onEvent: async (event) => { events.push(event); }, + }); + } finally { clock.mockRestore(); } + const ttft = events.filter((event) => event.payload?.span === "task.time_to_first_token"); + expect(ttft).toHaveLength(1); + expect(ttft[0]?.payload).toMatchObject({ parentSpan: "task.provider_session", startOffsetMs: 0, + durationMs: ingress === "native_dispatch" ? 500 : 4_500, eventKind: "agentMessage", outcome: "ok" }); + expect(events.find((event) => event.payload?.span === "provider.time_to_first_agent_event")?.payload) + .toMatchObject({ parentSpan: "agent.turn", eventKind: "agentMessage" }); + expect(JSON.stringify(ttft)).not.toContain("first text"); + expect(JSON.stringify(ttft)).not.toContain("later text"); + }, + ); + + it.each([ + ["item.delta", { kind: "reasoning", text: "thinking" }, "reasoning"], + ["item.completed", { kind: "reasoning", text: "thought" }, "reasoning"], + ["item.completed", { kind: "agentMessage", text: "answer" }, "agentMessage"], + ["run.result.accepted", { result: { schema: "paperclip.run_result.v1", summary: "done" } }, "agentMessage"], + ["turn.completed", { outputTails: [{ itemId: "message", payload: { kind: "agentMessage", text: "settled text" } }] }, "agentMessage"], + ] as const)("records first deliverable %s %j once", async (eventType, payload, eventKind) => { + const events: AdapterRuntimeEvent[] = []; + state.execute.mockReset().mockImplementationOnce(async () => { + const first = { eventType, payload, itemId: "message" } as unknown as PrpEvent; + await accountingEvents.duplicate!(first); + expect(events.some((event) => event.payload?.span === "task.time_to_first_token")).toBe(false); + await accountingEvents.committed!(first); + await accountingEvents.committed!({ eventType: "item.delta", itemId: "message", + payload: { kind: "agentMessage", text: "later text" } } as unknown as PrpEvent); + return { result: { summary: "cancelled" }, terminal: { runTerminalState: "cancelled" }, + turnId: "turn", normalizedSessionId: "session", providerSessionId: null, + driverKind: "test", driverVersion: "1", nativeEventCount: 1, highestContiguousSourceSeq: 1 }; + }); + await executePaperclipNativeSession({ db: leaseDb(), execution, runnerInstanceId: "runner", + onEvent: async (event) => { events.push(event); } }); + const ttft = events.filter((event) => event.payload?.span === "task.time_to_first_token"); + expect(ttft).toHaveLength(1); + expect(ttft[0]?.payload).toMatchObject({ parentSpan: "task.provider_session", eventKind, outcome: "ok" }); + expect(JSON.stringify(ttft)).not.toContain("later text"); + }); + + it("omits first-token timing when execution fails before assistant output", async () => { + const events: AdapterRuntimeEvent[] = []; + const failure = new Error("provider failed before output"); + const issueProjection = vi.spyOn(issueServiceModule, "issueService").mockReturnValue({ + update: vi.fn(async () => ({ status: "blocked", statusVersion: 1 })), + } as unknown as ReturnType); + state.execute.mockReset().mockRejectedValueOnce(failure); + try { + await expect(executePaperclipNativeSession({ db: leaseDb(), execution, runnerInstanceId: "runner", + onEvent: async (event) => { events.push(event); }, + })).rejects.toBe(failure); + } finally { issueProjection.mockRestore(); } + expect(events.some((event) => event.payload?.span === "task.time_to_first_token")).toBe(false); + }); + it("keeps answered-question ingress at the run root rather than charging it to preparation", async () => { const answeredAtMs = Date.now(); 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 69ffd01db7d..61092b3ce54 100644 --- a/server/src/services/native-runtime/native-session-executor.ts +++ b/server/src/services/native-runtime/native-session-executor.ts @@ -37,6 +37,7 @@ import { createAgentIdentityRedactor } from "../agent-identity-redaction.js"; import { parseCodexCliVersion } from "./codex-runtime-compatibility.js"; import { createNativeToolTrace, type NativeToolTrace } from "./native-tool-trace.js"; import { createNativeProviderFailureObservation } from "./native-provider-failure.js"; +import { createNativeDeliverableTextObservation } from "./native-deliverable-text.js"; import { createNativeGitHubAccess, type NativeGitHubAccess } from "./native-github-access.js"; import { resolveGitHubOperationCredentials } from "../github-operation-credentials.js"; import { bindManagedNativeCredentialTurn, completeManagedNativeCredentialTurn } from "./managed-native-credentials.js"; @@ -8248,6 +8249,8 @@ async function executePaperclipNativeSessionWithinScope( let turnSubmittedAtMs: number | null = null; let turnStartedAtMs: number | null = null; let firstAgentEventRecorded = false; + let firstTokenRecorded = false; + const observeDeliverableText = createNativeDeliverableTextObservation(); let providerUsageLimitObserved = false; const providerFailureObservation = createNativeProviderFailureObservation(input.execution.provider); let turnCompletedAtMs: number | null = null; @@ -8374,6 +8377,17 @@ async function executePaperclipNativeSessionWithinScope( privateKeyPem: input.runnerEnvironment?.PAPERCLIP_AGENT_PRIVATE_KEY, assertControllerActive, onCommittedEvent: async (event) => { + const textKind = !firstTokenRecorded ? observeDeliverableText(event) : null; + if (textKind) { + firstTokenRecorded = true; + await trace.record({ + name: "task.time_to_first_token", + parentName: "task.provider_session", + startedAtMs: trace.traceStartedAtMs, + endedAtMs: Date.now(), + attributes: { eventKind: textKind }, + }); + } await observeAccountingEvent(event); await toolTrace.observe(event); if (event.eventType === "item.completed" && @@ -8586,6 +8600,7 @@ async function executePaperclipNativeSessionWithinScope( ); }, onDuplicateEvent: async (event) => { + if (!firstTokenRecorded) observeDeliverableText(event); await observeAccountingEvent(event); // A crash can happen after the event commit but before its callback // finishes. Recover only idempotent durable projections here; activity,