Skip to content

Measure per-turn latency in scripted evals and record in stereo - #5714

Draft
aconchillo wants to merge 2 commits into
mainfrom
aleix/evals-turn-timing
Draft

Measure per-turn latency in scripted evals and record in stereo#5714
aconchillo wants to merge 2 commits into
mainfrom
aleix/evals-turn-timing

Conversation

@aconchillo

Copy link
Copy Markdown
Contributor

Summary

  • Branch 1 of the evals latency proposal. A latency benchmark ported onto pipecat eval could only bound a turn's latency with within_ms, not measure it, while the harness already has every timestamp such a benchmark wants. Scripted turns now carry a timing (EvalTurnTiming) on EvalScriptTurnResult, written to results.jsonl under turns[].timing: milliseconds from the turn's input anchor to llm_started, the first LLM token, the end of the LLM response, the first function call, the bot's started/stopped-speaking reports, and the harness VAD's onset of the bot's speech, plus the derived voice_to_voice_ms and speech_padding_ms. A text turn is anchored at the send, a spoken turn at the end of the played utterance (input_duration_ms is its length); within_ms keeps its send anchor.
  • The bot's RTVI metrics (TTFB, processing time, token usage) deserialize into MetricsFrames in the harness pipeline and are kept per turn as timing.bot_metrics, so the service-measured TTFB sits next to the harness-measured one.
  • The measuring is an observer, EvalTimingObserver (pipecat.evals.timing), attached to the eval client's PipelineWorker. It tells the bot's frames from the user's by the processor that first pushed them (input transport, output transport, user TTS, bot-audio aggregator), and the script driver calls begin_turn() once a turn's input is out; the record keeps filling in until the next turn.
  • EvalClientOutputTransport.write_audio_frame() waits until the send task has sent the chunk, the way a write to a sound device would, so the base transport's BotStoppedSpeakingFrame marks the true end of the user's utterance; that frame is the spoken turn's anchor.
  • pipecat eval run -v prints ttfb, and v2v for a spoken turn, under each turn.
  • Recordings (--record-dir) are stereo, the user on the left channel and the bot on the right, for offline turn-taking analysis.

Testing

  • uv run pytest tests/test_evals_*.py tests/cli/test_eval_display.py tests/cli/test_eval_env.py -q
  • tests/test_evals_timing.py drives the observer with an injected clock; the session integration tests cover a text turn's timing and metrics and a played audio file's re-anchoring; the recorder tests cover the stereo layout.

https://claude.ai/code/session_01NgWzoMcT5TQ85tnmFT1BdR

A latency benchmark on `pipecat.evals` needs the timestamps behind a
turn, not only the pass/fail budget `within_ms` puts on them. The harness
sees every one it wants, and reports them per turn.

- `EvalTurnTiming` on `EvalScriptTurnResult.timing`, written to
  `results.jsonl` under `turns[].timing` and rebuilt by `_result_from_dict`:
  milliseconds from the turn's input anchor to `llm_started`, the first LLM
  token, the end of the LLM response, the first function call, the bot's
  started/stopped-speaking reports and the harness VAD's onset of its
  speech, plus the derived `voice_to_voice_ms` and `speech_padding_ms`. The
  anchor is the send for a text turn and the end of the utterance for a
  spoken one (`input_duration_ms` is its length); `within_ms` keeps running
  from the send, and script.py says so.

- `EvalTimingObserver` (pipecat.evals.timing), a `BaseObserver` on the eval
  client's `PipelineWorker`, takes the measures from the harness pipeline's
  frames, telling the bot's from the user's by the processor that first
  pushed them: the input transport for the bot's `LLMFullResponseStart/End`,
  `LLMTextFrame`, `FunctionCallInProgress`, `Bot*Speaking` and
  `MetricsFrame`; the output transport for the user utterance's
  `Bot*Speaking` bracket; the user TTS for its `TTSAudioRawFrame`s; the
  bot-audio aggregator for the `UserStartedSpeakingFrame` that is
  `bot_speech_onset`. The script driver calls `begin_turn()` once a turn's
  input is out; the returned record keeps filling in until the next turn.

- `EvalClientOutputTransport.write_audio_frame()` returns once the send task
  has sent the chunk, the way a write to a sound device would, so the base
  transport's `BotStoppedSpeakingFrame` for the utterance lands when its
  last chunk went out: that frame is the spoken turn's anchor. A write waits
  only while a send task exists, so the media sender draining its queue at
  stop does not hit the write timeout.

- The client serializer turns the bot's RTVI `metrics` messages into
  `MetricsFrame`s (TTFB, processing, LLM usage); the observer keeps them per
  turn as `timing.bot_metrics`, and the sink stops them like the bot's
  other frames.

- `pipecat eval run -v` prints `ttfb`, and `v2v` for a spoken turn, as one
  dim line under each turn (a `timing` progress record).

- `EvalClientRecorder.write()` writes stereo: the user on the left channel,
  the bot on the right, each on its own aligned timeline.

Claude-Session: https://claude.ai/code/session_01NgWzoMcT5TQ85tnmFT1BdR
@codecov

codecov Bot commented Sep 12, 2026

Copy link
Copy Markdown

Codecov Report

❌ Patch coverage is 98.17352% with 4 lines in your changes missing coverage. Please review.

Files with missing lines Patch % Lines
src/pipecat/evals/script_driver.py 90.47% 2 Missing ⚠️
src/pipecat/evals/results.py 95.45% 1 Missing ⚠️
src/pipecat/evals/timing.py 99.17% 1 Missing ⚠️
Files with missing lines Coverage Δ
src/pipecat/cli/commands/eval.py 62.54% <100.00%> (+3.69%) ⬆️
src/pipecat/evals/client.py 87.84% <100.00%> (+0.08%) ⬆️
src/pipecat/evals/client_transport.py 87.38% <100.00%> (+9.21%) ⬆️
src/pipecat/evals/script.py 95.41% <ø> (ø)
src/pipecat/evals/script_session.py 88.00% <100.00%> (+0.50%) ⬆️
src/pipecat/evals/serializer.py 96.57% <100.00%> (+0.45%) ⬆️
src/pipecat/evals/session.py 97.19% <ø> (ø)
src/pipecat/evals/suite.py 77.94% <100.00%> (+2.55%) ⬆️
src/pipecat/evals/results.py 98.49% <95.45%> (-0.61%) ⬇️
src/pipecat/evals/timing.py 99.17% <99.17%> (ø)
... and 1 more

... and 2 files with indirect coverage changes

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

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.

1 participant