From 00ab2c1be316ffba51432efbc76d746d7f2580cc Mon Sep 17 00:00:00 2001 From: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com> Date: Fri, 18 Sep 2026 22:07:43 +0000 Subject: [PATCH] fix(timing): anchor response duration and overhead at proxy receive time Co-Authored-By: Ishaan Jaffer <155045088+ishaan-berri@users.noreply.github.com> --- .../llm_response_utils/response_metadata.py | 12 +++++-- .../test_response_metadata.py | 35 ++++++++++++++++++- 2 files changed, 43 insertions(+), 4 deletions(-) diff --git a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py index c83c266a17e..9a007489473 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -5,7 +5,7 @@ from typing import Any, Final import httpx from litellm.constants import LITELLM_DETAILED_TIMING -from litellm.litellm_core_utils.core_helpers import process_response_headers +from litellm.litellm_core_utils.core_helpers import get_litellm_metadata_from_kwargs, process_response_headers from litellm.litellm_core_utils.llm_response_utils.get_api_base import get_api_base from litellm.litellm_core_utils.logging_utils import LiteLLMLoggingObject from litellm.types.utils import ( @@ -16,19 +16,25 @@ from litellm.types.utils import ( ) +def _timing_window_start(start_time: datetime.datetime, logging_obj: LiteLLMLoggingObject) -> datetime.datetime: + received_at: Final = get_litellm_metadata_from_kwargs(logging_obj.model_call_details).get("litellm_received_at") + return received_at if isinstance(received_at, datetime.datetime) else start_time + + def response_timing_metrics( start_time: datetime.datetime, end_time: datetime.datetime, logging_obj: LiteLLMLoggingObject, include_overhead: bool = True, ) -> Mapping[str, float]: - """``_response_ms`` for the whole call, plus ``litellm_overhead_time_ms`` when it can be derived. + """``_response_ms`` for the window starting at proxy receive time when stamped, else ``start_time``. On a cache hit the overhead is the total minus the cache read; otherwise it is the total minus the provider call (``llm_api_duration_ms``). It is omitted when neither duration was recorded, and when ``include_overhead`` is False because the two durations cover different windows. """ - total_response_time_ms: Final = (end_time - start_time).total_seconds() * 1000 + window_start: Final = _timing_window_start(start_time, logging_obj) + total_response_time_ms: Final = (end_time.timestamp() - window_start.timestamp()) * 1000 if not include_overhead: return {"_response_ms": total_response_time_ms} # mutable-ok: read-only timing result caching_details: Final = logging_obj.caching_details diff --git a/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py b/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py index a06b6bbf3cc..40f964cd3fc 100644 --- a/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py +++ b/tests/test_litellm/litellm_core_utils/llm_response_utils/test_response_metadata.py @@ -9,6 +9,8 @@ import asyncio import datetime from unittest.mock import MagicMock +import pytest + import litellm.litellm_core_utils.llm_response_utils.response_metadata as response_metadata_mod import litellm.proxy.common_request_processing as common_request_processing_mod from litellm.litellm_core_utils.litellm_logging import Logging @@ -231,11 +233,13 @@ class TestResponseTimingMetrics: START = datetime.datetime(2025, 1, 1, 0, 0, 0) END = datetime.datetime(2025, 1, 1, 0, 0, 1) - def _make_logging_obj(self, llm_api_duration_ms=None, caching_details=None): + def _make_logging_obj(self, llm_api_duration_ms=None, caching_details=None, received_at=None): logging_obj = MagicMock() logging_obj.model_call_details = {} if llm_api_duration_ms is not None: logging_obj.model_call_details["llm_api_duration_ms"] = llm_api_duration_ms + if received_at is not None: + logging_obj.model_call_details["litellm_params"] = {"metadata": {"litellm_received_at": received_at}} logging_obj.caching_details = caching_details return logging_obj @@ -246,6 +250,35 @@ class TestResponseTimingMetrics: "litellm_overhead_time_ms": 100.0, } + def test_window_starts_at_proxy_receive_when_stamped(self): + received_at = self.START.astimezone(datetime.timezone.utc) - datetime.timedelta(seconds=3) + logging_obj = self._make_logging_obj(llm_api_duration_ms=900.0, received_at=received_at) + + result = response_timing_metrics(self.START, self.END, logging_obj) + + assert result["_response_ms"] == pytest.approx(4000.0) + assert result["litellm_overhead_time_ms"] == pytest.approx(3100.0) + + def test_cache_hit_window_starts_at_proxy_receive_when_stamped(self): + received_at = self.START.astimezone(datetime.timezone.utc) - datetime.timedelta(seconds=3) + logging_obj = self._make_logging_obj( + caching_details={"cache_hit": True, "cache_duration_ms": 250.0}, + received_at=received_at, + ) + + result = response_timing_metrics(self.START, self.END, logging_obj) + + assert result["_response_ms"] == pytest.approx(4000.0) + assert result["litellm_overhead_time_ms"] == pytest.approx(3750.0) + + def test_non_datetime_proxy_receive_falls_back_to_start_time(self): + logging_obj = self._make_logging_obj(llm_api_duration_ms=900.0, received_at="bad") + + result = response_timing_metrics(self.START, self.END, logging_obj) + + assert result["_response_ms"] == pytest.approx(1000.0) + assert result["litellm_overhead_time_ms"] == pytest.approx(100.0) + def test_overhead_omitted_when_no_provider_or_cache_duration_recorded(self): logging_obj = self._make_logging_obj() assert response_timing_metrics(self.START, self.END, logging_obj) == {"_response_ms": 1000.0}