Skip to content

fix(swift): anchor realtime answer-generation span to response.created#577

Merged
cornelcroi merged 2 commits into
mainfrom
fix/anchor-generation-span-to-response-created
Jul 9, 2026
Merged

fix(swift): anchor realtime answer-generation span to response.created#577
cornelcroi merged 2 commits into
mainfrom
fix/anchor-generation-span-to-response-created

Conversation

@cornelcroi

@cornelcroi cornelcroi commented Jul 9, 2026

Copy link
Copy Markdown
Collaborator

Closes #578

Problem

In LangSmith, every realtime response / presenter LLM-call span shows Latency 0.00s, while the non-realtime llm.completion spans show real durations (e.g. 2.60s).

Root cause: the realtime answer generation is created and ended in the same synchronous block at response.done (OpenAIVoiceAssistant.swift:275, OpenAIGroundedVoiceAssistant.swift:265), so endedAt − startedAt ≈ 0. The non-realtime Agent.callModel (Agent.swift:157) opens its llm.completion span around the actual model.complete() call, which is why it measures correctly — this fix makes the realtime path do the same.

The OpenAI Realtime API provides no server-side timing (no timestamps on response.created/response.done, nothing in response.usage/status_details), so latency can only be measured client-side from the response.createdresponse.done receive-times.

Fix

Backdate the generation's start to the response's created receive-time:

  • Tracing — add a defaulted SpanHandle.generation(_:model:input:startedAt:) overload. The default ignores startedAt and stamps now, so every existing conformer (OSLogTracer, test doubles, any consumer custom SpanHandle) keeps compiling unchanged. ProcessedSpan overrides it and threads startedAt through child(...).
  • OpenAIVoiceAssistant — record responseStartedAt[id] at .responseCreated, pass it to the response generation, clear in resetTurn.
  • OpenAIGroundedVoiceAssistant — record presenterStartedAt when the presenter/direct response is created, pass it to the presenter generation, clear on finish/fail.

The generation now measures the true synthesis latency; tool time still shows as sibling tool.* spans, and the voice.turn root keeps its full duration.

Tests

  • RecordingTracer captures per-span start/end and implements the new overload.
  • ProcessingTracerTests.generationBackdatesStartedAtToTheGivenTime — the backdate survives finalize/export.
  • One test per assistant path (response, presenter, direct): a real gap between response.created and response.done is reflected in the generation's duration. Verified stable across repeated runs.

Full suite green (394 tests). No public breaking change (additive, defaulted).

🤖 Generated with Claude Code

The `response` (single) and `presenter`/direct (grounded) generation spans
were created AND ended in the same synchronous block at `response.done`, so
their exported latency was ~0 — in LangSmith the realtime LLM calls all
showed 0.00s, while the non-realtime `llm.completion` spans (opened around
the actual call) showed real durations. The OpenAI Realtime API sends no
server-side timing (no timestamps on events, nothing in response.done/usage/
status_details), so the duration can only be measured client-side from the
`response.created` → `response.done` receive-times.

Backdate the generation's start to the response's `created` receive-time:
- Tracing: add a defaulted `SpanHandle.generation(_:model:input:startedAt:)`
  overload (default ignores it and stamps now, so every existing conformer —
  OSLogTracer, test doubles, consumer custom tracers — keeps compiling);
  ProcessedSpan overrides it and threads `startedAt` through `child(...)`.
- OpenAIVoiceAssistant: record `responseStartedAt[id]` at `.responseCreated`,
  pass it to the `response` generation, clear it in `resetTurn`.
- OpenAIGroundedVoiceAssistant: record `presenterStartedAt` when the
  presenter/direct response is created, pass it to the `presenter` generation,
  clear on finish/fail.

The generation now measures the true synthesis latency; tool time still shows
as sibling `tool.*` spans and the `voice.turn` root keeps its full duration.

Tests: RecordingTracer captures per-span start/end and the new overload;
ProcessingTracerTests proves the backdate survives export; each assistant has
a test that a real gap between response.created and response.done is reflected
in the generation's duration (response, presenter, and direct paths).

Co-authored-by: Claude <claude@anthropic.com>

@chatgpt-codex-connector chatgpt-codex-connector Bot left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

💡 Codex Review

Here are some automated review suggestions for this pull request.

Reviewed commit: 9dd2b42193

ℹ️ About Codex in GitHub

Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you

  • Open a pull request for review
  • Mark a draft as ready
  • Comment "@codex review".

If Codex has suggestions, it will comment; otherwise it will react with 👍.

Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".

presenterId = nil
presenterActive = false
truncation.reset() // clean finish — nothing left to truncate
defer { presenterStartedAt = nil }

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

P2 Badge Clear presenter start before awaiting persistence

When a grounded voice session has a store and persist suspends, this defer does not run until after the await persist(...) below. Because Swift actors are reentrant at that await, a new turn can process its presenter/direct response.created and set presenterStartedAt; when the old persist returns, this defer then clears the new turn's timestamp, causing the next presenter generation to fall back to Date() and record ~0 latency again.

Useful? React with 👍 / 👎.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch — fixed in 0fce739. The defer ran at scope exit, i.e. after await persist(...); actor reentrancy at that await let the next turn's presenter response.created set presenterStartedAt during the suspension, and the deferred clear then wiped the new turn's timestamp (→ ~0 latency again). Now cleared synchronously before the await, matching the existing pendingUserText/replyText cleanup that already guards the same reentrancy window.

Codex review (PR #577): the `defer { presenterStartedAt = nil }` in the
grounded clean-finish block runs at scope exit — AFTER `await persist(...)`.
Actors are reentrant at that await, so a next turn can process its
presenter/direct response.created and set `presenterStartedAt` during the
suspension; the deferred clear then wipes the NEW turn's timestamp, and its
presenter generation falls back to Date() → ~0 latency again.

Clear it synchronously before the await instead, matching the existing
pendingUserText/replyText cleanup that guards the same reentrancy window.

Co-authored-by: Claude <claude@anthropic.com>
@cornelcroi cornelcroi merged commit ad3e337 into main Jul 9, 2026
7 checks passed
@cornelcroi cornelcroi deleted the fix/anchor-generation-span-to-response-created branch July 9, 2026 15:38
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Realtime answer-generation spans export with ~0 latency (LangSmith shows LLM calls at 0.00s)

1 participant