feat(otel): stamp gen_ai.response.time_to_first_chunk on streaming LLM spans (#32236)

(cherry picked from commit 3116ed211b)
This commit is contained in:
Yassin Kortam 2026-07-07 19:15:49 +03:00 committed by Yuneng Jiang
parent b5dee35fb3
commit 2d35ea5d07
No known key found for this signature in database
7 changed files with 72 additions and 9 deletions

View file

@ -368,7 +368,11 @@ class OpenTelemetryV2(CustomLogger):
# it (named provisionally) so it isn't leaked as an open span.
carrier.span.end(end_time=to_ns(end_time))
return None
data = LLMCallSpanData.from_standard_logging_payload(payload, capture_content=self.config.capture_span_content)
data = LLMCallSpanData.from_standard_logging_payload(
payload,
capture_content=self.config.capture_span_content,
time_to_first_chunk_seconds=call.time_to_first_chunk_seconds,
)
end_time_ns = to_ns(end_time)
if carrier.span is not None:
# Born at the boundary: stamp attributes from the typed payload, set

View file

@ -55,6 +55,7 @@ class GenAIMapper:
GenAI.RESPONSE_MODEL: lambda d: d.response_model,
GenAI.RESPONSE_ID: lambda d: d.response_id,
GenAI.RESPONSE_FINISH_REASONS: lambda d: list(d.finish_reasons) if d.finish_reasons else None,
GenAI.RESPONSE_TIME_TO_FIRST_CHUNK: lambda d: d.time_to_first_chunk_seconds,
GenAI.USAGE_INPUT_TOKENS: lambda d: d.usage.input_tokens,
GenAI.USAGE_OUTPUT_TOKENS: lambda d: d.usage.output_tokens,
Error.TYPE: lambda d: d.error.error_type if d.error else None,

View file

@ -41,7 +41,7 @@ from typing import TYPE_CHECKING, Any, Mapping, cast
from litellm.constants import LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL
from litellm.integrations.otel.model.semconv import resolve_operation
from litellm.integrations.otel.model.utils import as_str
from litellm.integrations.otel.model.utils import as_str, to_seconds
if TYPE_CHECKING:
from litellm.types.utils import StandardLoggingPayload
@ -201,6 +201,7 @@ class LLMCallEvent:
# span is renamed from the typed payload at close (``finish_span``); this only
# needs to be reasonable for a span that never gets closed (a leak).
provisional_span_name: str
time_to_first_chunk_seconds: float | None
@classmethod
def from_dict(cls, kwargs: Mapping[str, Any]) -> "LLMCallEvent":
@ -214,9 +215,25 @@ class LLMCallEvent:
dynamic_params=kwargs.get("standard_callback_dynamic_params"),
is_no_upstream_call=bool(kwargs.get(LITELLM_LOGGING_NO_UPSTREAM_LLM_CALL)),
provisional_span_name=f"{operation.value} {model}".strip(),
time_to_first_chunk_seconds=time_to_first_chunk_seconds(kwargs),
)
def time_to_first_chunk_seconds(kwargs: Mapping[str, Any]) -> float | None:
"""Seconds from the upstream request being issued (``api_call_start_time``)
to the first streamed chunk (``completion_start_time``); ``None`` for
non-streaming calls, where ``completion_start_time`` is backfilled with the
end time and would not measure first-chunk latency."""
optional_params = cast(Mapping[str, Any], kwargs.get("optional_params") or {})
if not optional_params.get("stream"):
return None
api_call_start = to_seconds(kwargs.get("api_call_start_time"))
completion_start = to_seconds(kwargs.get("completion_start_time"))
if api_call_start is None or completion_start is None:
return None
return completion_start - api_call_start
def _call_id(payload: "StandardLoggingPayload | None", kwargs: Mapping[str, Any]) -> str | None:
"""The call id from the payload (when closed) or the bare kwargs (at pre_call)."""
if payload is not None:

View file

@ -305,10 +305,14 @@ class LLMCallSpanData:
messages_in: tuple[Mapping[str, object], ...] = ()
choices_out: tuple[Mapping[str, object], ...] = ()
system_fingerprint: str | None = None
time_to_first_chunk_seconds: float | None = None
@classmethod
def from_standard_logging_payload(
cls, payload: "StandardLoggingPayload", capture_content: bool = False
cls,
payload: "StandardLoggingPayload",
capture_content: bool = False,
time_to_first_chunk_seconds: float | None = None,
) -> "LLMCallSpanData":
params = cast(Mapping[str, object], payload.get("model_parameters") or {})
# The single parse of the request's metadata — the request-vs-provider
@ -349,6 +353,7 @@ class LLMCallSpanData:
messages_in=_dicts(payload.get("messages")) if capture_content else (),
choices_out=choices_out if capture_content else (),
system_fingerprint=as_str(response.get("system_fingerprint")),
time_to_first_chunk_seconds=time_to_first_chunk_seconds,
)

View file

@ -69,6 +69,7 @@ class GenAI:
RESPONSE_ID: Final = "gen_ai.response.id"
RESPONSE_MODEL: Final = "gen_ai.response.model"
RESPONSE_FINISH_REASONS: Final = "gen_ai.response.finish_reasons"
RESPONSE_TIME_TO_FIRST_CHUNK: Final = "gen_ai.response.time_to_first_chunk"
# usage
USAGE_INPUT_TOKENS: Final = "gen_ai.usage.input_tokens"
USAGE_OUTPUT_TOKENS: Final = "gen_ai.usage.output_tokens"

View file

@ -21,6 +21,7 @@ from litellm.integrations.opentelemetry import (
_build_metric_attribute_filter,
_resolve_metric_attribute_filter,
)
from litellm.integrations.otel.model.metadata import time_to_first_chunk_seconds
from litellm.integrations.otel.model.semconv import Metric, resolve_operation
from litellm.integrations.otel.model.utils import to_seconds
from litellm.litellm_core_utils.safe_json_dumps import safe_dumps
@ -181,13 +182,10 @@ class GenAIMetricRecorder:
self._metrics.token_usage.record(usage.get("completion_tokens", 0), attributes=out_attrs)
def _record_time_to_first_token(self, kwargs: Mapping[str, Any], common_attrs: dict) -> None:
if not kwargs.get("optional_params", {}).get("stream", False):
time_to_first_chunk = time_to_first_chunk_seconds(kwargs)
if time_to_first_chunk is None:
return
api_call_start = to_seconds(kwargs.get("api_call_start_time"))
completion_start = to_seconds(kwargs.get("completion_start_time"))
if api_call_start is None or completion_start is None:
return
self._metrics.time_to_first_token.record(completion_start - api_call_start, attributes=common_attrs)
self._metrics.time_to_first_token.record(time_to_first_chunk, attributes=common_attrs)
def _record_time_per_output_token(
self,

View file

@ -168,6 +168,43 @@ def test_async_log_success_event_emits_llm_call_span():
assert span.status.status_code is StatusCode.UNSET
def test_streaming_span_carries_time_to_first_chunk():
logger, exporter = _logger()
kwargs = {
**_kwargs(payload=_payload(stream=True)),
"optional_params": {"stream": True},
"api_call_start_time": datetime(2026, 5, 26, 12, 0, 0, tzinfo=timezone.utc),
"completion_start_time": datetime(2026, 5, 26, 12, 0, 0, 750000, tzinfo=timezone.utc),
}
_emit_llm(logger, kwargs)
(span,) = exporter.get_finished_spans()
assert span.attributes[GenAI.RESPONSE_TIME_TO_FIRST_CHUNK] == pytest.approx(0.75)
def test_non_streaming_span_has_no_time_to_first_chunk():
logger, exporter = _logger()
kwargs = {
**_kwargs(),
"optional_params": {},
"api_call_start_time": datetime(2026, 5, 26, 12, 0, 0, tzinfo=timezone.utc),
"completion_start_time": datetime(2026, 5, 26, 12, 0, 5, tzinfo=timezone.utc),
}
_emit_llm(logger, kwargs)
(span,) = exporter.get_finished_spans()
assert GenAI.RESPONSE_TIME_TO_FIRST_CHUNK not in span.attributes
def test_streaming_span_without_timing_omits_time_to_first_chunk():
logger, exporter = _logger()
kwargs = {
**_kwargs(payload=_payload(stream=True)),
"optional_params": {"stream": True},
}
_emit_llm(logger, kwargs)
(span,) = exporter.get_finished_spans()
assert GenAI.RESPONSE_TIME_TO_FIRST_CHUNK not in span.attributes
def test_async_log_failure_event_marks_error_status():
logger, exporter = _logger()
payload = _payload(