From 2d35ea5d07530dfca0518dd936d54688bffdb5a9 Mon Sep 17 00:00:00 2001 From: Yassin Kortam Date: Tue, 7 Jul 2026 19:15:49 +0300 Subject: [PATCH] feat(otel): stamp gen_ai.response.time_to_first_chunk on streaming LLM spans (#32236) (cherry picked from commit 3116ed211bf1a2720cfeed1d533154a83d26a39a) --- litellm/integrations/otel/logger.py | 6 ++- litellm/integrations/otel/mappers/genai.py | 1 + litellm/integrations/otel/model/metadata.py | 19 +++++++++- litellm/integrations/otel/model/payloads.py | 7 +++- litellm/integrations/otel/model/semconv.py | 1 + litellm/integrations/otel/plumbing/metrics.py | 10 ++--- .../integrations/otel/test_otel_v2_logger.py | 37 +++++++++++++++++++ 7 files changed, 72 insertions(+), 9 deletions(-) diff --git a/litellm/integrations/otel/logger.py b/litellm/integrations/otel/logger.py index 5e729e12be0..e258b239d93 100644 --- a/litellm/integrations/otel/logger.py +++ b/litellm/integrations/otel/logger.py @@ -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 diff --git a/litellm/integrations/otel/mappers/genai.py b/litellm/integrations/otel/mappers/genai.py index c5d8c35de7d..f568afa9e3e 100644 --- a/litellm/integrations/otel/mappers/genai.py +++ b/litellm/integrations/otel/mappers/genai.py @@ -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, diff --git a/litellm/integrations/otel/model/metadata.py b/litellm/integrations/otel/model/metadata.py index 37bb5464315..7ff4f540908 100644 --- a/litellm/integrations/otel/model/metadata.py +++ b/litellm/integrations/otel/model/metadata.py @@ -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: diff --git a/litellm/integrations/otel/model/payloads.py b/litellm/integrations/otel/model/payloads.py index b0dcf97b787..fcd710492f0 100644 --- a/litellm/integrations/otel/model/payloads.py +++ b/litellm/integrations/otel/model/payloads.py @@ -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, ) diff --git a/litellm/integrations/otel/model/semconv.py b/litellm/integrations/otel/model/semconv.py index 6315a5a4a89..4e725ae0a29 100644 --- a/litellm/integrations/otel/model/semconv.py +++ b/litellm/integrations/otel/model/semconv.py @@ -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" diff --git a/litellm/integrations/otel/plumbing/metrics.py b/litellm/integrations/otel/plumbing/metrics.py index cb1f9214876..50d0fb75962 100644 --- a/litellm/integrations/otel/plumbing/metrics.py +++ b/litellm/integrations/otel/plumbing/metrics.py @@ -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, diff --git a/tests/test_litellm/integrations/otel/test_otel_v2_logger.py b/tests/test_litellm/integrations/otel/test_otel_v2_logger.py index 674b2bec829..697b9293eea 100644 --- a/tests/test_litellm/integrations/otel/test_otel_v2_logger.py +++ b/tests/test_litellm/integrations/otel/test_otel_v2_logger.py @@ -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(