From 1961cbcb6c9b2f82ac7379ca45274e3cce855923 Mon Sep 17 00:00:00 2001 From: kerry Date: Sat, 19 Sep 2026 00:18:13 +0000 Subject: [PATCH] fix(timing): subtract every provider attempt from receive-anchored overhead Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com> --- .../llm_response_utils/response_metadata.py | 31 +++++++-- litellm/litellm_core_utils/logging_utils.py | 10 ++- .../test_response_metadata.py | 56 ++++++++++++---- .../litellm_core_utils/test_logging_utils.py | 28 ++++++-- .../test_router_retry_non_retryable_errors.py | 65 +++++++++++++++++++ 5 files changed, 168 insertions(+), 22 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 9a007489473..3778ae1281f 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -1,6 +1,6 @@ import datetime from collections.abc import Mapping -from typing import Any, Final +from typing import Any, Final, cast import httpx @@ -16,9 +16,13 @@ from litellm.types.utils import ( ) -def _timing_window_start(start_time: datetime.datetime, logging_obj: LiteLLMLoggingObject) -> datetime.datetime: +def _timing_window_start( + start_time: datetime.datetime, logging_obj: LiteLLMLoggingObject +) -> tuple[datetime.datetime, bool]: 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 + if isinstance(received_at, datetime.datetime): + return received_at, True + return start_time, False def response_timing_metrics( @@ -33,7 +37,9 @@ def response_timing_metrics( 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. """ - window_start: Final = _timing_window_start(start_time, logging_obj) + timing_window: Final = _timing_window_start(start_time, logging_obj) + window_start: Final = timing_window[0] + receive_anchored: Final = timing_window[1] 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 @@ -43,11 +49,26 @@ def response_timing_metrics( if caching_details is not None and caching_details.get("cache_hit") is True else None ) + metadata_value: Final = get_litellm_metadata_from_kwargs(logging_obj.model_call_details) + metadata: Final = cast(dict[str, object], metadata_value) if isinstance(metadata_value, dict) else {} llm_api_duration_ms: Final = logging_obj.model_call_details.get("llm_api_duration_ms") if cache_duration_ms is not None: overhead_ms: float | None = total_response_time_ms - cache_duration_ms elif llm_api_duration_ms is not None: - overhead_ms = round(total_response_time_ms - llm_api_duration_ms, 4) + total_provider_duration_ms: Final = metadata.get("llm_api_duration_ms_total") + provider_duration_ms: Final = ( + total_provider_duration_ms + if receive_anchored + and isinstance(total_provider_duration_ms, float) + and isinstance(llm_api_duration_ms, (int, float)) + and total_provider_duration_ms >= llm_api_duration_ms + else llm_api_duration_ms + ) + overhead_ms = ( + round(total_response_time_ms - provider_duration_ms, 4) + if isinstance(provider_duration_ms, (int, float)) + else None + ) else: overhead_ms = None if overhead_ms is None: diff --git a/litellm/litellm_core_utils/logging_utils.py b/litellm/litellm_core_utils/logging_utils.py index 0f14b461d3d..82bfb0efdb1 100644 --- a/litellm/litellm_core_utils/logging_utils.py +++ b/litellm/litellm_core_utils/logging_utils.py @@ -5,13 +5,14 @@ import re import time from collections.abc import Iterator, Mapping, Sequence from datetime import datetime -from typing import TYPE_CHECKING, Any, Final +from typing import TYPE_CHECKING, Any, Final, cast from litellm._logging import format_base64_size, verbose_logger from litellm.constants import ( BASE64_TRUNCATION_OFFLOAD_THRESHOLD_CHARS, MAX_BASE64_LENGTH_FOR_LOGGING, ) +from litellm.litellm_core_utils.core_helpers import get_litellm_metadata_from_kwargs from litellm.types.utils import ( ModelResponse, ModelResponseStream, @@ -286,6 +287,13 @@ def _set_duration_in_model_call_details( duration_ms: Final = (end_time - start_time).total_seconds() * 1000 if logging_obj and hasattr(logging_obj, "model_call_details"): logging_obj.model_call_details["llm_api_duration_ms"] = duration_ms + metadata_value: Final = get_litellm_metadata_from_kwargs(logging_obj.model_call_details) + if isinstance(metadata_value, dict): + metadata: Final = cast(dict[str, object], metadata_value) + existing_total: Final = metadata.get("llm_api_duration_ms_total") + metadata["llm_api_duration_ms_total"] = ( + existing_total if isinstance(existing_total, float) else 0.0 + ) + duration_ms else: verbose_logger.debug("`logging_obj` not found - unable to track `llm_api_duration_ms") except Exception as e: 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 eeccbc719d3..832be1a12d9 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 @@ -72,9 +72,7 @@ class TestCallbackDurationMs: def test_update_response_metadata_includes_callback_duration(self): """End-to-end: update_response_metadata should propagate callback_duration_ms.""" result = ModelResponse() - logging_obj = self._make_logging_obj( - callback_duration_ms=5.5, llm_api_duration_ms=800.0 - ) + logging_obj = self._make_logging_obj(callback_duration_ms=5.5, llm_api_duration_ms=800.0) logging_obj._response_cost_calculator = MagicMock(return_value=0.001) logging_obj.litellm_call_id = "test-call-id" @@ -236,6 +234,7 @@ class TestResponseTimingMetrics: def _make_logging_obj( self, llm_api_duration_ms: float | None = None, + llm_api_duration_ms_total: float | None = None, caching_details: dict[str, object] | None = None, received_at: datetime.datetime | str | None = None, ) -> MagicMock: @@ -243,8 +242,13 @@ class TestResponseTimingMetrics: 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}} + if received_at is not None or llm_api_duration_ms_total is not None: + metadata = {} + if received_at is not None: + metadata["litellm_received_at"] = received_at + if llm_api_duration_ms_total is not None: + metadata["llm_api_duration_ms_total"] = llm_api_duration_ms_total + logging_obj.model_call_details["litellm_params"] = {"metadata": metadata} logging_obj.caching_details = caching_details return logging_obj @@ -264,6 +268,40 @@ class TestResponseTimingMetrics: assert result["_response_ms"] == pytest.approx(4000.0) assert result["litellm_overhead_time_ms"] == pytest.approx(3100.0) + def test_receive_anchored_window_subtracts_all_provider_attempts(self): + logging_obj = self._make_logging_obj( + llm_api_duration_ms=300.0, + llm_api_duration_ms_total=700.0, + received_at=self.START, + ) + + 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(300.0) + + def test_sdk_window_subtracts_current_provider_attempt(self): + logging_obj = self._make_logging_obj( + llm_api_duration_ms=300.0, + llm_api_duration_ms_total=700.0, + ) + + 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(700.0) + + def test_receive_anchored_window_falls_back_to_current_provider_attempt(self): + logging_obj = self._make_logging_obj( + llm_api_duration_ms=300.0, + received_at=self.START, + ) + + 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(700.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( @@ -415,9 +453,7 @@ class TestDetailedTiming: def test_detailed_timing_headers_in_custom_headers(self, monkeypatch): """When LITELLM_DETAILED_TIMING is true, headers flow to get_custom_headers.""" - monkeypatch.setattr( - common_request_processing_mod, "LITELLM_DETAILED_TIMING", True - ) + monkeypatch.setattr(common_request_processing_mod, "LITELLM_DETAILED_TIMING", True) user_api_key_dict = UserAPIKeyAuth(api_key="sk-test") hidden_params = { @@ -440,9 +476,7 @@ class TestDetailedTiming: def test_detailed_timing_headers_absent_when_disabled(self, monkeypatch): """When LITELLM_DETAILED_TIMING is false, no timing headers emitted.""" - monkeypatch.setattr( - common_request_processing_mod, "LITELLM_DETAILED_TIMING", False - ) + monkeypatch.setattr(common_request_processing_mod, "LITELLM_DETAILED_TIMING", False) user_api_key_dict = UserAPIKeyAuth(api_key="sk-test") hidden_params = { diff --git a/tests/test_litellm/litellm_core_utils/test_logging_utils.py b/tests/test_litellm/litellm_core_utils/test_logging_utils.py index b446021a7dc..f669ff86c13 100644 --- a/tests/test_litellm/litellm_core_utils/test_logging_utils.py +++ b/tests/test_litellm/litellm_core_utils/test_logging_utils.py @@ -2,18 +2,39 @@ Tests for litellm.litellm_core_utils.logging_utils — base64 truncation helpers. """ +import datetime import threading +from unittest.mock import MagicMock import pytest from litellm.litellm_core_utils import logging_utils from litellm.litellm_core_utils.logging_utils import ( - format_base64_size, + _set_duration_in_model_call_details, _truncate_base64_in_string, + format_base64_size, truncate_base64_in_messages, truncate_base64_in_messages_async, ) + +class TestSetDurationInModelCallDetails: + def test_accumulates_provider_attempts_in_shared_metadata(self): + metadata = {"request_id": "test"} + logging_obj = MagicMock() + logging_obj.model_call_details = {"litellm_params": {"metadata": metadata}} + first_start = datetime.datetime(2025, 1, 1, 0, 0, 0) + first_end = first_start + datetime.timedelta(milliseconds=300) + second_start = datetime.datetime(2025, 1, 1, 0, 0, 1) + second_end = second_start + datetime.timedelta(milliseconds=700) + + _set_duration_in_model_call_details(logging_obj, first_start, first_end) + _set_duration_in_model_call_details(logging_obj, second_start, second_end) + + assert metadata["llm_api_duration_ms_total"] == pytest.approx(1000.0) + assert logging_obj.model_call_details["llm_api_duration_ms"] == pytest.approx(700.0) + + # --------------------------------------------------------------------------- # format_base64_size # --------------------------------------------------------------------------- @@ -157,10 +178,7 @@ class TestTruncateBase64InMessages: } ] result = truncate_base64_in_messages(messages) - assert ( - result[0]["content"][0]["image_url"]["url"] - == f"data:image/png;base64,{short}" - ) + assert result[0]["content"][0]["image_url"]["url"] == f"data:image/png;base64,{short}" # --------------------------------------------------------------------------- diff --git a/tests/test_litellm/test_router_retry_non_retryable_errors.py b/tests/test_litellm/test_router_retry_non_retryable_errors.py index 0728947eafe..c797f0f96a6 100644 --- a/tests/test_litellm/test_router_retry_non_retryable_errors.py +++ b/tests/test_litellm/test_router_retry_non_retryable_errors.py @@ -10,12 +10,20 @@ Verifies that: Regression tests for https://github.com/BerriAI/litellm/issues/21343 """ +import asyncio +import datetime +from collections.abc import Awaitable, Callable +from typing import Final, cast from unittest.mock import AsyncMock, patch import pytest import litellm from litellm import Router +from litellm.litellm_core_utils.litellm_logging import Logging +from litellm.litellm_core_utils.logging_utils import track_llm_api_timing +from litellm.litellm_core_utils.rules import Rules +from litellm.utils import function_setup def _make_rate_limit_error(message="Rate limited"): @@ -274,3 +282,60 @@ async def test_not_found_error_in_retry_loop_raises_immediately(): # Only 2 calls: initial + first retry that hits non-retryable assert call_count == 2 + + +@pytest.mark.asyncio +async def test_retry_attempts_accumulate_timing_in_shared_request_metadata(): + metadata: dict[str, object] = {"model_group": "test-model"} + logging_obj_raw, _ = function_setup( + "acompletion", + Rules(), + datetime.datetime.now(), + model="test-model", + messages=[{"role": "user", "content": "test"}], + metadata=metadata, + litellm_call_id="retry-timing-test", + is_async_call=True, + ) + logging_obj: Final[Logging] = cast(Logging, logging_obj_raw) + attempt_numbers: list[int] = [] + metadata_ids: list[int] = [] + + @track_llm_api_timing() + async def timed_attempt(*, logging_obj: Logging, **kwargs: object) -> str: + del kwargs + attempt_numbers.append(len(attempt_numbers) + 1) + metadata_ids.append(id(logging_obj.model_call_details["litellm_params"]["metadata"])) + await asyncio.sleep(0.01) + if len(attempt_numbers) == 1: + raise _make_rate_limit_error() + return "success" + + async def invoke(original_function: Callable[..., Awaitable[str]], *args: object, **kwargs: object) -> str: + return await original_function(*args, **kwargs) + + router = _create_router(num_retries=1) + with ( + patch.object(router, "make_call", new=AsyncMock(side_effect=invoke)), + patch.object( + router, + "_async_get_healthy_deployments", + new=AsyncMock(return_value=(["d1"], ["d1"])), + ), + patch.object(router, "_time_to_sleep_before_retry", return_value=0), + ): + result = await router.async_function_with_retries( + original_function=timed_attempt, + model="test-model", + messages=[{"role": "user", "content": "test"}], + metadata=metadata, + logging_obj=logging_obj, + num_retries=1, + ) + + request_metadata: Final = logging_obj.model_call_details["litellm_params"]["metadata"] + assert result == "success" + assert attempt_numbers == [1, 2] + assert request_metadata is metadata + assert metadata_ids == [id(metadata), id(metadata)] + assert request_metadata["llm_api_duration_ms_total"] > logging_obj.model_call_details["llm_api_duration_ms"]