mirror of
https://github.com/BerriAI/litellm.git
synced 2026-08-28 05:25:59 +00:00
feat(otel): add latency metrics (TTFT, TPOT, Total Generation Time) to OTEL logging (#17888)
- Add time_to_first_token_histogram using api_call_start_time for accurate measurement - Add time_per_output_token_histogram for average time per output token - Add response_duration_histogram for total LLM API generation time - Extract latency metric recording into dedicated helper methods - Fix parent span double-ending bug when reused as primary span - Use api_call_start_time for TTFT to exclude LiteLLM overhead (matches Prometheus) - Support both streaming and non-streaming requests - Handle both datetime and float timestamp formats
This commit is contained in:
Alexsander Hamir
GitHub
parent
d38f241032
commit
f4db4b6f0e
1 changed files with 168 additions and 3 deletions
|
|
@ -248,6 +248,9 @@ class OpenTelemetry(CustomLogger):
|
|||
self._operation_duration_histogram = None
|
||||
self._token_usage_histogram = None
|
||||
self._cost_histogram = None
|
||||
self._time_to_first_token_histogram = None
|
||||
self._time_per_output_token_histogram = None
|
||||
self._response_duration_histogram = None
|
||||
return
|
||||
|
||||
from opentelemetry import metrics
|
||||
|
|
@ -300,6 +303,21 @@ class OpenTelemetry(CustomLogger):
|
|||
description="GenAI request cost",
|
||||
unit="USD",
|
||||
)
|
||||
self._time_to_first_token_histogram = meter.create_histogram(
|
||||
name="gen_ai.client.response.time_to_first_token",
|
||||
description="Time to first token for streaming requests",
|
||||
unit="s",
|
||||
)
|
||||
self._time_per_output_token_histogram = meter.create_histogram(
|
||||
name="gen_ai.client.response.time_per_output_token",
|
||||
description="Average time per output token (generation time / completion tokens)",
|
||||
unit="s",
|
||||
)
|
||||
self._response_duration_histogram = meter.create_histogram(
|
||||
name="gen_ai.client.response.duration",
|
||||
description="Total LLM API generation time (excludes LiteLLM overhead)",
|
||||
unit="s",
|
||||
)
|
||||
|
||||
def _init_logs(self, logger_provider):
|
||||
# nothing to do if events disabled
|
||||
|
|
@ -612,8 +630,9 @@ class OpenTelemetry(CustomLogger):
|
|||
if self.config.enable_events:
|
||||
self._emit_semantic_logs(kwargs, response_obj, span)
|
||||
|
||||
# 6. End parent span
|
||||
if parent_span is not None:
|
||||
# 6. End parent span (only if it wasn't reused as the primary span)
|
||||
# If parent_span was reused as the primary span, it was already ended in _start_primary_span
|
||||
if parent_span is not None and parent_span is not span:
|
||||
parent_span.end(end_time=self._to_ns(datetime.now()))
|
||||
|
||||
def _start_primary_span(
|
||||
|
|
@ -727,6 +746,152 @@ class OpenTelemetry(CustomLogger):
|
|||
if self._cost_histogram and cost:
|
||||
self._cost_histogram.record(cost, attributes=common_attrs)
|
||||
|
||||
# Record latency metrics (TTFT, TPOT, and Total Generation Time)
|
||||
self._record_time_to_first_token_metric(kwargs, common_attrs)
|
||||
self._record_time_per_output_token_metric(
|
||||
kwargs, response_obj, end_time, duration_s, common_attrs
|
||||
)
|
||||
self._record_response_duration_metric(kwargs, end_time, common_attrs)
|
||||
|
||||
def _record_time_to_first_token_metric(self, kwargs: dict, common_attrs: dict):
|
||||
"""Record Time to First Token (TTFT) metric for streaming requests."""
|
||||
optional_params = kwargs.get("optional_params", {})
|
||||
is_streaming = optional_params.get("stream", False)
|
||||
|
||||
if not (self._time_to_first_token_histogram and is_streaming):
|
||||
return
|
||||
|
||||
# Use api_call_start_time for precision (matches Prometheus implementation)
|
||||
# This excludes LiteLLM overhead and measures pure LLM API latency
|
||||
api_call_start_time = kwargs.get("api_call_start_time", None)
|
||||
completion_start_time = kwargs.get("completion_start_time", None)
|
||||
|
||||
if api_call_start_time is not None and completion_start_time is not None:
|
||||
# Convert to timestamps if needed (handles both datetime and float)
|
||||
if isinstance(api_call_start_time, datetime):
|
||||
api_call_start_ts = api_call_start_time.timestamp()
|
||||
else:
|
||||
api_call_start_ts = api_call_start_time
|
||||
|
||||
if isinstance(completion_start_time, datetime):
|
||||
completion_start_ts = completion_start_time.timestamp()
|
||||
else:
|
||||
completion_start_ts = completion_start_time
|
||||
|
||||
time_to_first_token_seconds = completion_start_ts - api_call_start_ts
|
||||
self._time_to_first_token_histogram.record(
|
||||
time_to_first_token_seconds, attributes=common_attrs
|
||||
)
|
||||
|
||||
def _record_time_per_output_token_metric(
|
||||
self,
|
||||
kwargs: dict,
|
||||
response_obj: Optional[Any],
|
||||
end_time: datetime,
|
||||
duration_s: float,
|
||||
common_attrs: dict,
|
||||
):
|
||||
"""Record Time Per Output Token (TPOT) metric.
|
||||
|
||||
Calculated as: generation_time / completion_tokens
|
||||
- For streaming: uses end_time - completion_start_time (time to generate all tokens after first)
|
||||
- For non-streaming: uses end_time - api_call_start_time (total generation time)
|
||||
"""
|
||||
if not self._time_per_output_token_histogram:
|
||||
return
|
||||
|
||||
# Get completion tokens from response_obj
|
||||
completion_tokens = None
|
||||
if response_obj and (usage := response_obj.get("usage")):
|
||||
completion_tokens = usage.get("completion_tokens")
|
||||
|
||||
if completion_tokens is None or completion_tokens <= 0:
|
||||
return
|
||||
|
||||
# Calculate generation time
|
||||
completion_start_time = kwargs.get("completion_start_time", None)
|
||||
api_call_start_time = kwargs.get("api_call_start_time", None)
|
||||
|
||||
# Convert end_time to timestamp
|
||||
if isinstance(end_time, datetime):
|
||||
end_time_ts = end_time.timestamp()
|
||||
else:
|
||||
end_time_ts = end_time
|
||||
|
||||
if completion_start_time is not None:
|
||||
# Streaming: use completion_start_time (when first token arrived)
|
||||
# This measures time to generate all tokens after the first one
|
||||
if isinstance(completion_start_time, datetime):
|
||||
completion_start_ts = completion_start_time.timestamp()
|
||||
else:
|
||||
completion_start_ts = completion_start_time
|
||||
|
||||
generation_time_seconds = end_time_ts - completion_start_ts
|
||||
elif api_call_start_time is not None:
|
||||
# Non-streaming: use api_call_start_time (total generation time)
|
||||
if isinstance(api_call_start_time, datetime):
|
||||
api_call_start_ts = api_call_start_time.timestamp()
|
||||
else:
|
||||
api_call_start_ts = api_call_start_time
|
||||
|
||||
generation_time_seconds = end_time_ts - api_call_start_ts
|
||||
else:
|
||||
# Fallback: use duration_s (already calculated as (end_time - start_time).total_seconds())
|
||||
generation_time_seconds = duration_s
|
||||
|
||||
if generation_time_seconds > 0:
|
||||
time_per_output_token_seconds = generation_time_seconds / completion_tokens
|
||||
self._time_per_output_token_histogram.record(
|
||||
time_per_output_token_seconds, attributes=common_attrs
|
||||
)
|
||||
|
||||
def _record_response_duration_metric(
|
||||
self,
|
||||
kwargs: dict,
|
||||
end_time: Union[datetime, float],
|
||||
common_attrs: dict,
|
||||
):
|
||||
"""Record Total Generation Time (response duration) metric.
|
||||
|
||||
Measures pure LLM API generation time: end_time - api_call_start_time
|
||||
This excludes LiteLLM overhead and measures only the LLM provider's response time.
|
||||
Works for both streaming and non-streaming requests.
|
||||
|
||||
Mirrors Prometheus's litellm_llm_api_latency_metric.
|
||||
Uses kwargs.get("end_time") with fallback to parameter for consistency with Prometheus.
|
||||
"""
|
||||
if not self._response_duration_histogram:
|
||||
return
|
||||
|
||||
api_call_start_time = kwargs.get("api_call_start_time", None)
|
||||
if api_call_start_time is None:
|
||||
return
|
||||
|
||||
# Use end_time from kwargs if available (matches Prometheus), otherwise use parameter
|
||||
# For streaming: end_time is when the stream completes (final chunk received)
|
||||
# For non-streaming: end_time is when the response is received
|
||||
_end_time = kwargs.get("end_time") or end_time
|
||||
if _end_time is None:
|
||||
_end_time = datetime.now()
|
||||
|
||||
# Convert to timestamps if needed (handles both datetime and float)
|
||||
if isinstance(api_call_start_time, datetime):
|
||||
api_call_start_ts = api_call_start_time.timestamp()
|
||||
else:
|
||||
api_call_start_ts = api_call_start_time
|
||||
|
||||
if isinstance(_end_time, datetime):
|
||||
end_time_ts = _end_time.timestamp()
|
||||
else:
|
||||
end_time_ts = _end_time
|
||||
|
||||
response_duration_seconds = end_time_ts - api_call_start_ts
|
||||
|
||||
if response_duration_seconds > 0:
|
||||
self._response_duration_histogram.record(
|
||||
response_duration_seconds, attributes=common_attrs
|
||||
)
|
||||
|
||||
def _emit_semantic_logs(self, kwargs, response_obj, span: Span):
|
||||
if not self.config.enable_events:
|
||||
return
|
||||
|
|
@ -1226,7 +1391,7 @@ class OpenTelemetry(CustomLogger):
|
|||
value=usage.get("prompt_tokens"),
|
||||
)
|
||||
|
||||
########################################################################
|
||||
########################################################################
|
||||
########## LLM Request Medssages / tools / content Attributes ###########
|
||||
#########################################################################
|
||||
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue