Measure first deliverable text in native run traces (#17434)

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

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`,

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.

maps/feature-map/runs-adapters.md

@@ -38,6 +38,9 @@ without restricting the root span name. Compare workspace preparation with its
 `controller.startup.<phase>`. 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.<phase>` 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.

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<string, unknown>, 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();
+  });
+});

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<string, unknown> {
+  return value && typeof value === "object" && !Array.isArray(value)
+    ? value as Record<string, unknown>
+    : {};
+}
+
+function text(value: unknown): string | null {
+  return typeof value === "string" && value.length > 0 ? value : null;
+}
+
+export function createNativeDeliverableTextObservation() {
+  const itemKinds = new Map<string, string>();
+  const observeItem = (payload: Record<string, unknown>, 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<PrpEvent, "eventType" | "payload" | "itemId">): 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;
+  };
+}

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<string, unknown>) => ({
+        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<typeof issueServiceModule.issueService>);
+    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[] = [];

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,