mirror of
https://github.com/BerriAI/litellm.git
synced 2026-09-21 00:21:49 +00:00
fix(timing): subtract every provider attempt from receive-anchored overhead
Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>
This commit is contained in:
kerry
parent
7dede188f8
commit
1961cbcb6c
5 changed files with 168 additions and 22 deletions
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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:
|
||||
|
|
|
|||
|
|
@ -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 = {
|
||||
|
|
|
|||
|
|
@ -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}"
|
||||
|
||||
|
||||
# ---------------------------------------------------------------------------
|
||||
|
|
|
|||
|
|
@ -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"]
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue