Skip to content

Commit 7ac046f

Browse files
authored
Add WebSocket round-trip metrics (Time To Last Round Trip and Avg RTT) (#850)
## Summary Adds two round-trip metrics to the realtime WebSocket backend (`openai_websocket`): **Time To Last Round Trip** and an approximate **Avg RTT**. In streaming transcription, input packets and output tokens flow as separate streams, so the existing token metrics (TTFT, ITL, TPOT) do not capture the send-to-receive lag a user actually experiences. These two estimate that lag from the send and receive timestamps and are reported automatically whenever the WebSocket backend is used. Per the issue discussion, Time To First Round Trip is omitted because it overlaps the existing TTFT, and the names avoid `TTFT`/`TTLT` to prevent collision with the token metrics. ## Details - `schemas/info.py`: add scalar timing fields to `RequestTimings` (`last_request_sent`, `request_sent_sum`/`request_sent_count`, `token_received_sum`/`token_received_count`). Scalars rather than lists, so they stay correct under `RequestInfo.model_copy` (which shallow-copies timings). - `backends/openai/websocket.py`: record a timestamp after each outbound frame (`session.update`, audio appends, both commits) via a small `_record_request_sent` helper, and accumulate received content-token timestamps in `_record_content_tokens`. - `schemas/request_stats.py`: add computed properties `time_to_last_round_trip_ms` (last received token minus last sent packet) and `avg_round_trip_time_ms` (mean received minus mean sent). Both return `None` when no sends were recorded, so non-WebSocket backends are unaffected. - `benchmark/schemas/metrics.py` and `accumulator.py`: add the two `StatusDistributionSummary` fields, compile them in `GenerativeMetrics.compile()`, and accumulate them for live progress. - `benchmark/outputs/console.py` and `csv.py`: show both in the request-latency table and the CSV export. JSON/YAML already include them via the schema. The HTML report is left for a follow-up. - `docs/guides/metrics.md`: document both metrics, noting they are WebSocket-only and that Avg RTT is approximate (it assumes sent packets and received tokens line up evenly in time). ## Test Plan - `tox -e test-unit` passes, including new tests: - `tests/unit/backends/openai/test_realtime_ws.py`: the backend records send/receive timestamps (counts, sums, last-sent) over an in-process WebSocket stub. - `tests/unit/schemas/test_request_stats.py`: the two properties compute correctly and return `None` without send timings. - `tests/unit/benchmark/schemas/test_metrics.py`: the metrics expose schema fields and compile into distributions. - `tox -e lint-check` and `tox -e type-check` pass. - Manual check on CPU (no GPU): drove `OpenAIWebSocketBackend.resolve()` against a fake realtime server with ~100 ms simulated per-token lag. Time To Last Round Trip came out around 300 ms and Avg RTT around 200 ms (matching the lag), and both were `None` for a non-WebSocket request. For a live run, point a benchmark at a vLLM realtime server (e.g. Voxtral) and confirm both metrics appear in the console latency table and `benchmarks.json`. ## Related Issues - Resolves #832 --- - [x] "I certify that all code in this PR is my own, except as noted below." ## Use of AI - [x] Includes code generated or substantially modified by an AI agent - [x] Includes tests generated or substantially modified by an AI agent > NOTE: the `Generated-by` or `Assisted-by` trailers should be used in git commit messages when code or tests were generated or substantially modified by an AI agent, as described in the project's [`DEVELOPING.md`](https://github.com/vllm-project/guidellm/blob/main/DEVELOPING.md) file. --- # git log commit 457d56e Author: Suraj Singh <[email protected]> Date: Wed Jun 24 15:00:52 2026 -0700 test(openai): add failing websocket round-trip metric tests (#832) Add RED unit tests for Time To Last Round Trip and Avg RTT on the openai_websocket backend (send/receive timestamp recording, computed properties, None-gating, and metric compile). They fail until the implementation lands. Assisted-by: Claude Code Signed-off-by: Suraj Singh <[email protected]> commit 81a0aee Author: Suraj Singh <[email protected]> Date: Wed Jun 24 15:00:52 2026 -0700 feat(openai): record websocket send/receive timestamps (#832) Add scalar round-trip timing fields to RequestTimings and record per-frame sent timestamps and received content-token timestamps in the openai_websocket backend. These feed the Time To Last Round Trip and Avg RTT metrics; HTTP backends leave them unset. Assisted-by: Claude Code Signed-off-by: Suraj Singh <[email protected]> commit 94f941c Author: Suraj Singh <[email protected]> Date: Wed Jun 24 15:00:52 2026 -0700 feat(benchmark): compute and aggregate websocket round-trip metrics (#832) Add time_to_last_round_trip_ms and avg_round_trip_time_ms as computed request stats (None unless send timings exist), aggregate them in GenerativeMetrics.compile(), and accumulate them for live progress. Avg RTT is an approximation of the mean send-to-receive lag. Assisted-by: Claude Code Signed-off-by: Suraj Singh <[email protected]> commit c5efcaf Author: Suraj Singh <[email protected]> Date: Wed Jun 24 15:00:52 2026 -0700 feat(benchmark): show websocket round-trip metrics in console and CSV (#832) Surface Time To Last Round Trip and Avg RTT in the request latency console table and the CSV export. JSON/YAML already include them via the schema; the HTML report is left for a follow-up. Assisted-by: Claude Code Signed-off-by: Suraj Singh <[email protected]> commit da70077 Author: Suraj Singh <[email protected]> Date: Wed Jun 24 15:00:53 2026 -0700 docs(metrics): document websocket round-trip metrics (#832) Describe Time To Last Round Trip and Avg RTT in the metrics guide, noting they are websocket-only and that Avg RTT is an approximation. Assisted-by: Claude Code Signed-off-by: Suraj Singh <[email protected]> commit ee76dd2 Author: Suraj Singh <[email protected]> Date: Tue Aug 11 09:59:50 2026 -0700 fix(outputs): hide realtime-only metrics from console Signed-off-by: Suraj Singh <[email protected]> --------- Assisted-by: Claude Code Signed-off-by: Suraj Singh <[email protected]>
1 parent d3a6da9 commit 7ac046f

11 files changed

Lines changed: 400 additions & 3 deletions

File tree

docs/guides/metrics.md

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -71,6 +71,16 @@ These metrics provide a breakdown of the overall request statuses, helping users
7171
- **Definition**: The average time taken to generate each output token, including the first token.
7272
- **Use Case**: Provides a detailed view of the model's token generation efficiency.
7373

74+
### Time To Last Round Trip
75+
76+
- **Definition**: For the realtime WebSocket backend (`openai_websocket`), the time from the last sent packet to the last received token.
77+
- **Use Case**: Measures tail latency of a streaming exchange (how long the final output lags the final input).
78+
79+
### Average Round-Trip Time (Avg RTT)
80+
81+
- **Definition**: For the WebSocket backend, the mean of received-token timestamps minus the mean of sent-packet timestamps.
82+
- **Use Case**: Estimates the average send-to-receive lag across a request. It is approximate, since it assumes sent packets and received tokens line up evenly in time.
83+
7484
## Statistical Summaries
7585

7686
GuideLLM provides detailed statistical summaries for each of the above metrics using the `StatusDistributionSummary` and `DistributionSummary` models. These summaries include the following statistics:

src/guidellm/backends/openai/websocket.py

Lines changed: 22 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -80,6 +80,9 @@ def _record_content_tokens(
8080
if content_tokens <= 0:
8181
return False
8282

83+
request_info.timings.token_received_sum += iter_time
84+
request_info.timings.token_received_count += 1
85+
8386
if request_info.timings.first_token_iteration is None:
8487
request_info.timings.first_token_iteration = iter_time
8588
request_info.timings.token_iterations = 0
@@ -92,6 +95,18 @@ def _record_content_tokens(
9295
return False
9396

9497

98+
def _record_request_sent(request_info: RequestInfo) -> None:
99+
"""
100+
Record the timestamp of one outbound WebSocket frame for round-trip metrics.
101+
102+
:param request_info: Mutable timing state for the in-flight request.
103+
"""
104+
sent_time = time.time()
105+
request_info.timings.last_request_sent = sent_time
106+
request_info.timings.request_sent_sum += sent_time
107+
request_info.timings.request_sent_count += 1
108+
109+
95110
def _load_ws_event(raw: str) -> dict[str, Any]:
96111
"""Parse a JSON WebSocket text frame; raise RuntimeError on invalid JSON."""
97112
try:
@@ -377,8 +392,9 @@ async def resolve( # type: ignore[override, misc] # noqa: C901, PLR0912, PLR09
377392
self,
378393
request: GenerationRequest,
379394
request_info: RequestInfo,
380-
history: list[tuple[GenerationRequest, GenerationResponse | None]]
381-
| None = None,
395+
history: (
396+
list[tuple[GenerationRequest, GenerationResponse | None]] | None
397+
) = None,
382398
) -> AsyncIterator[tuple[GenerationResponse | None, RequestInfo]]:
383399
"""
384400
Stream one realtime transcription over WebSocket for a single audio column.
@@ -454,18 +470,22 @@ async def resolve( # type: ignore[override, misc] # noqa: C901, PLR0912, PLR09
454470
f"Expected session.created, got {first_event.get('type')!r}"
455471
)
456472
await ws.send(_json_text(session_update))
473+
_record_request_sent(request_info)
457474
for b64_chunk in chunks:
458475
await ws.send(
459476
_json_text(
460477
{"type": "input_audio_buffer.append", "audio": b64_chunk}
461478
)
462479
)
480+
_record_request_sent(request_info)
463481
await ws.send(
464482
_json_text({"type": "input_audio_buffer.commit", "final": False})
465483
)
484+
_record_request_sent(request_info)
466485
await ws.send(
467486
_json_text({"type": "input_audio_buffer.commit", "final": True})
468487
)
488+
_record_request_sent(request_info)
469489

470490
ignored_events = 0
471491
while True:

src/guidellm/benchmark/outputs/console.py

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -480,7 +480,6 @@ def print_request_latency_table(self, report: GenerativeBenchmarksReport):
480480
group="TPOT",
481481
name="ms",
482482
)
483-
484483
headers, values = columns.get_table_data()
485484
self.console.print("\n")
486485
self.console.print_table(

src/guidellm/benchmark/outputs/csv.py

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -455,6 +455,20 @@ def _add_request_latency_metrics(
455455
"Inter Token Latency",
456456
"ms",
457457
)
458+
self._add_stats_for_metric(
459+
headers,
460+
values,
461+
benchmark.metrics.time_to_last_round_trip_ms,
462+
"Time To Last Round Trip",
463+
"ms",
464+
)
465+
self._add_stats_for_metric(
466+
headers,
467+
values,
468+
benchmark.metrics.avg_round_trip_time_ms,
469+
"Avg Round Trip Time",
470+
"ms",
471+
)
458472

459473
def _add_server_throughput_metrics(
460474
self,

src/guidellm/benchmark/schemas/accumulator.py

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -495,6 +495,14 @@ class GenerativeMetricsAccumulator(StandardBaseModel):
495495
default_factory=RunningMetricStats,
496496
description="Accumulated time to first token statistics in milliseconds",
497497
)
498+
time_to_last_round_trip_ms: RunningMetricStats = Field(
499+
default_factory=RunningMetricStats,
500+
description="Accumulated websocket last round-trip latency in milliseconds",
501+
)
502+
avg_round_trip_time_ms: RunningMetricStats = Field(
503+
default_factory=RunningMetricStats,
504+
description="Accumulated websocket average round-trip time in milliseconds",
505+
)
498506
time_to_first_output_token_ms: RunningMetricStats = Field(
499507
default_factory=RunningMetricStats,
500508
description="Accumulated time to first content token stats in ms",
@@ -539,6 +547,12 @@ def update_estimate(self, stats: GenerativeRequestStats, duration: float):
539547
self.time_to_first_token_ms.update_estimate(
540548
stats.time_to_first_token_ms, duration=duration
541549
)
550+
self.time_to_last_round_trip_ms.update_estimate(
551+
stats.time_to_last_round_trip_ms, duration=duration
552+
)
553+
self.avg_round_trip_time_ms.update_estimate(
554+
stats.avg_round_trip_time_ms, duration=duration
555+
)
542556
self.time_to_first_output_token_ms.update_estimate(
543557
stats.time_to_first_output_token_ms, duration=duration
544558
)

src/guidellm/benchmark/schemas/metrics.py

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -813,6 +813,18 @@ class GenerativeMetrics(StandardBaseDict):
813813
inter_token_latency_ms: StatusDistributionSummary = Field(
814814
description="Distribution of inter-token latencies in milliseconds"
815815
)
816+
time_to_last_round_trip_ms: StatusDistributionSummary = Field(
817+
description=(
818+
"Distribution of websocket last-round-trip latencies in milliseconds "
819+
"(last received token minus last sent packet)"
820+
)
821+
)
822+
avg_round_trip_time_ms: StatusDistributionSummary = Field(
823+
description=(
824+
"Distribution of approximate websocket average round-trip times in "
825+
"milliseconds (mean received minus mean sent)"
826+
)
827+
)
816828
prompt_tokens_per_second: StatusDistributionSummary = Field(
817829
description="Distribution of prompt token processing rates"
818830
)
@@ -939,6 +951,18 @@ def compile(cls, accumulator: GenerativeBenchmarkAccumulator) -> GenerativeMetri
939951
incomplete=incomplete,
940952
errored=errored,
941953
),
954+
time_to_last_round_trip_ms=StatusDistributionSummary.from_values_function(
955+
function=lambda req: req.time_to_last_round_trip_ms or 0.0,
956+
successful=successful,
957+
incomplete=incomplete,
958+
errored=errored,
959+
),
960+
avg_round_trip_time_ms=StatusDistributionSummary.from_values_function(
961+
function=lambda req: req.avg_round_trip_time_ms or 0.0,
962+
successful=successful,
963+
incomplete=incomplete,
964+
errored=errored,
965+
),
942966
time_to_first_output_token_ms=StatusDistributionSummary.from_values_function(
943967
function=lambda req: req.time_to_first_output_token_ms or 0.0,
944968
successful=successful,

src/guidellm/schemas/info.py

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -78,6 +78,35 @@ class RequestTimings(StandardBaseDict):
7878
token_iterations: int = Field(
7979
default=0,
8080
)
81+
last_request_sent: float | None = Field(
82+
default=None,
83+
description=(
84+
"Unix timestamp of the last packet sent to the server, used for "
85+
"round-trip metrics (openai_websocket backend)"
86+
),
87+
)
88+
request_sent_sum: float = Field(
89+
default=0.0,
90+
description=(
91+
"Sum of sent-packet timestamps for mean round-trip estimation "
92+
"(openai_websocket backend)"
93+
),
94+
)
95+
request_sent_count: int = Field(
96+
default=0,
97+
description="Number of packets sent to the server (openai_websocket backend)",
98+
)
99+
token_received_sum: float = Field(
100+
default=0.0,
101+
description=(
102+
"Sum of received content-token timestamps for mean round-trip "
103+
"estimation (openai_websocket backend)"
104+
),
105+
)
106+
token_received_count: int = Field(
107+
default=0,
108+
description="Number of content tokens received (openai_websocket backend)",
109+
)
81110
request_end: float | None = Field(
82111
default=None,
83112
description="Unix timestamp when the backend completed processing the request",

src/guidellm/schemas/request_stats.py

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -170,6 +170,45 @@ def time_to_first_token_ms(self) -> float | None:
170170

171171
return 1000 * (first_token - start)
172172

173+
@computed_field # type: ignore[misc]
174+
@property
175+
def time_to_last_round_trip_ms(self) -> float | None:
176+
"""
177+
Time from the last sent packet to the last received token in milliseconds.
178+
179+
Only populated by the websocket backend, which records send timestamps;
180+
None for backends that do not record sends.
181+
182+
:return: Last round-trip latency in milliseconds, or None if unavailable
183+
"""
184+
last_received = self.info.timings.last_token_iteration
185+
last_sent = self.info.timings.last_request_sent
186+
if last_received is None or last_sent is None:
187+
return None
188+
189+
return 1000 * (last_received - last_sent)
190+
191+
@computed_field # type: ignore[misc]
192+
@property
193+
def avg_round_trip_time_ms(self) -> float | None:
194+
"""
195+
Approximate average round-trip time in milliseconds.
196+
197+
Computed as the mean of received content-token timestamps minus the mean
198+
of sent-packet timestamps. This is an approximation that assumes sent
199+
packets and received tokens align uniformly in time. Only populated by
200+
the websocket backend; None otherwise.
201+
202+
:return: Average round-trip time in milliseconds, or None if unavailable
203+
"""
204+
timings = self.info.timings
205+
if timings.request_sent_count <= 0 or timings.token_received_count <= 0:
206+
return None
207+
208+
mean_sent = timings.request_sent_sum / timings.request_sent_count
209+
mean_received = timings.token_received_sum / timings.token_received_count
210+
return 1000 * (mean_received - mean_sent)
211+
173212
@computed_field # type: ignore[misc]
174213
@property
175214
def time_per_output_token_ms(self) -> float | None:

tests/unit/backends/openai/test_realtime_ws.py

Lines changed: 123 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -656,3 +656,126 @@ def test_openai_websocket_backend_args_invalid_request_format_rejected() -> None
656656
target="http://localhost:8000",
657657
request_format="nope",
658658
)
659+
660+
661+
@pytest.mark.asyncio
662+
async def test_resolve_records_round_trip_timings() -> None:
663+
"""Round-trip send/receive timestamps are recorded during resolve.
664+
665+
## WRITTEN BY AI ##
666+
"""
667+
668+
async def handler(ws: object) -> None:
669+
await ws.send(
670+
json.dumps({"type": "session.created", "id": "sess-rtt", "created": 0})
671+
)
672+
while True:
673+
msg = await ws.recv()
674+
data = json.loads(msg if isinstance(msg, str) else msg.decode())
675+
if data.get("type") == "input_audio_buffer.commit" and data.get("final"):
676+
break
677+
await ws.send(json.dumps({"type": "transcription.delta", "delta": "hi"}))
678+
await ws.send(
679+
json.dumps(
680+
{
681+
"type": "transcription.done",
682+
"text": "hi",
683+
"usage": {
684+
"prompt_tokens": 5,
685+
"completion_tokens": 1,
686+
"total_tokens": 6,
687+
},
688+
}
689+
)
690+
)
691+
692+
async with serve(handler, "127.0.0.1", 0) as server:
693+
port = server.sockets[0].getsockname()[1]
694+
be = _make_ws_backend(
695+
target=f"http://127.0.0.1:{port}",
696+
model="m",
697+
validate_backend=False,
698+
)
699+
await be.process_startup()
700+
req = GenerationRequest(
701+
request_id="rtt",
702+
columns={
703+
"audio_column": [
704+
{"audio": b"fake", "format": "mp3", "file_name": "f.mp3"}
705+
]
706+
},
707+
)
708+
info = RequestInfo(timings=RequestTimings())
709+
async for _ in be.resolve(req, info):
710+
pass
711+
await be.process_shutdown()
712+
713+
t = info.timings
714+
# one patched chunk -> session.update + 1 append + 2 commits = 4 sends
715+
assert t.request_sent_count == 4
716+
assert t.last_request_sent is not None
717+
assert t.request_sent_sum > 0
718+
# one non-empty delta received
719+
assert t.token_received_count == 1
720+
assert t.token_received_sum > 0
721+
# tokens arrive after the last packet is sent -> last round trip >= 0
722+
assert t.last_token_iteration is not None
723+
assert t.last_token_iteration >= t.last_request_sent
724+
725+
726+
@pytest.mark.asyncio
727+
async def test_resolve_records_round_trip_timings_done_only() -> None:
728+
"""Send/receive timings are recorded when text arrives only on done.
729+
730+
## WRITTEN BY AI ##
731+
"""
732+
733+
async def handler(ws: object) -> None:
734+
await ws.send(
735+
json.dumps({"type": "session.created", "id": "sess-done", "created": 0})
736+
)
737+
while True:
738+
msg = await ws.recv()
739+
data = json.loads(msg if isinstance(msg, str) else msg.decode())
740+
if data.get("type") == "input_audio_buffer.commit" and data.get("final"):
741+
break
742+
await ws.send(
743+
json.dumps(
744+
{
745+
"type": "transcription.done",
746+
"text": "hello",
747+
"usage": {
748+
"prompt_tokens": 5,
749+
"completion_tokens": 1,
750+
"total_tokens": 6,
751+
},
752+
}
753+
)
754+
)
755+
756+
async with serve(handler, "127.0.0.1", 0) as server:
757+
port = server.sockets[0].getsockname()[1]
758+
be = _make_ws_backend(
759+
target=f"http://127.0.0.1:{port}",
760+
model="m",
761+
validate_backend=False,
762+
)
763+
await be.process_startup()
764+
req = GenerationRequest(
765+
request_id="rtt-done",
766+
columns={
767+
"audio_column": [
768+
{"audio": b"fake", "format": "mp3", "file_name": "f.mp3"}
769+
]
770+
},
771+
)
772+
info = RequestInfo(timings=RequestTimings())
773+
async for _ in be.resolve(req, info):
774+
pass
775+
await be.process_shutdown()
776+
777+
t = info.timings
778+
assert t.request_sent_count == 4
779+
assert t.last_request_sent is not None
780+
assert t.token_received_count == 1
781+
assert t.token_received_sum > 0

0 commit comments

Comments
 (0)