diff --git a/litellm/constants.py b/litellm/constants.py index 8d05115e76e..6c31a5f2bcd 100644 --- a/litellm/constants.py +++ b/litellm/constants.py @@ -187,9 +187,12 @@ REDACTED_TOOL_CALL_ARGUMENTS_PLACEHOLDER: Final = "{}" MAX_STRING_LENGTH_STDOUT_LOG: Final = get_env_int("MAX_STRING_LENGTH_STDOUT_LOG", 4096) MAX_BASE64_LENGTH_STDOUT_LOG: Final = get_env_int("MAX_BASE64_LENGTH_STDOUT_LOG", 4096) + # When true, adds detailed per-phase timing breakdown headers to responses. # Headers: x-litellm-timing-{pre-processing,llm-api,post-processing,message-copy}-ms -LITELLM_DETAILED_TIMING: Final = os.getenv("LITELLM_DETAILED_TIMING", "false").lower() == "true" +def is_detailed_timing_enabled() -> bool: + return os.getenv("LITELLM_DETAILED_TIMING", "false").lower() == "true" + # Model cost map validation constants MODEL_COST_MAP_MIN_MODEL_COUNT: Final = get_env_int( 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 051a8fdf256..70445557d52 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -6,7 +6,7 @@ from typing import Final import httpx from pydantic import TypeAdapter, ValidationError -from litellm.constants import LITELLM_DETAILED_TIMING +from litellm.constants import is_detailed_timing_enabled 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 @@ -243,7 +243,7 @@ class ResponseMetadata: # 3. Detailed per-phase timing (opt-in via env var) ######################################################### llm_api_duration_ms: Final[float | None] = logging_obj.model_call_details.get("llm_api_duration_ms") - if LITELLM_DETAILED_TIMING and llm_api_duration_ms is not None: + if is_detailed_timing_enabled() and llm_api_duration_ms is not None: detailed: Final[dict[str, float]] = { "timing_llm_api_ms": round(llm_api_duration_ms, 4), } diff --git a/litellm/proxy/common_request_processing.py b/litellm/proxy/common_request_processing.py index e812b03385d..66d61147bfa 100644 --- a/litellm/proxy/common_request_processing.py +++ b/litellm/proxy/common_request_processing.py @@ -42,7 +42,6 @@ from litellm.constants import ( DD_TRACER_STREAMING_CHUNK_YIELD_RESOURCE, DEFAULT_MAX_RECURSE_DEPTH, LITELLM_CLIENT_DISCONNECT_DETAIL, - LITELLM_DETAILED_TIMING, LITELLM_HTTP_STATUS_CLIENT_DISCONNECTED, MAX_LITELLM_CALL_ID_LENGTH, MAX_PAYLOAD_SIZE_FOR_DEBUG_LOG, @@ -51,6 +50,7 @@ from litellm.constants import ( STREAM_SSE_DATA_PREFIX, STREAM_SSE_KEEPALIVE_PING_BYTES, UNSAFE_PROXY_RESPONSE_HEADERS, + is_detailed_timing_enabled, ) from litellm.integrations.custom_guardrail import CustomGuardrail from litellm.integrations.otel.runtime import phase_event @@ -2302,7 +2302,7 @@ class ProxyBaseLLMRequestProcessing: "x-litellm-timing-post-processing-ms": str(hidden_params.get("timing_post_processing_ms", None)), "x-litellm-timing-message-copy-ms": str(hidden_params.get("timing_message_copy_ms", None)), } - if LITELLM_DETAILED_TIMING + if is_detailed_timing_enabled() else {} ), "x-litellm-fastest_response_batch_completion": ( diff --git a/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py b/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py index 6d9d8c7997a..501bf4b865e 100644 --- a/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py +++ b/tests/unit/litellm_core_utils/llm_response_utils/test_response_metadata.py @@ -15,8 +15,6 @@ from unittest.mock import MagicMock import pytest import litellm -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.cost_calculator import select_model_name_for_cost_calc from litellm.litellm_core_utils.litellm_logging import Logging from litellm.litellm_core_utils.llm_response_utils.response_metadata import ( @@ -459,9 +457,9 @@ class TestDetailedTiming: logging_obj.message_copy_duration_ms = message_copy_duration_ms return logging_obj - def test_detailed_timing_headers_present_when_enabled(self, monkeypatch): + def test_detailed_timing_headers_present_when_enabled(self, monkeypatch: pytest.MonkeyPatch) -> None: """When LITELLM_DETAILED_TIMING is true, detailed timing keys appear in hidden_params.""" - monkeypatch.setattr(response_metadata_mod, "LITELLM_DETAILED_TIMING", True) + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "true") result = ModelResponse() start = datetime.datetime(2025, 1, 1, 0, 0, 0) @@ -485,8 +483,10 @@ class TestDetailedTiming: assert hidden.get("timing_post_processing_ms") == 10.0 # 530 - 20 - 500 @pytest.mark.skipif(not hasattr(time, "tzset"), reason="switching the process timezone needs time.tzset()") - def test_detailed_timing_pre_processing_uses_receive_anchor(self, monkeypatch, process_timezone: str): - monkeypatch.setattr(response_metadata_mod, "LITELLM_DETAILED_TIMING", True) + def test_detailed_timing_pre_processing_uses_receive_anchor( + self, monkeypatch: pytest.MonkeyPatch, process_timezone: str + ) -> None: + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "true") result = ModelResponse() received_at = datetime.datetime(2025, 1, 1, tzinfo=datetime.timezone.utc) @@ -507,9 +507,9 @@ class TestDetailedTiming: assert hidden.get("timing_pre_processing_ms") == pytest.approx(200.0) assert hidden.get("timing_post_processing_ms") == pytest.approx(30.0) - def test_detailed_timing_absent_when_disabled(self, monkeypatch): + def test_detailed_timing_absent_when_disabled(self, monkeypatch: pytest.MonkeyPatch) -> None: """When LITELLM_DETAILED_TIMING is false, no detailed timing keys.""" - monkeypatch.setattr(response_metadata_mod, "LITELLM_DETAILED_TIMING", False) + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "false") result = ModelResponse() start = datetime.datetime(2025, 1, 1, 0, 0, 0) @@ -524,9 +524,9 @@ class TestDetailedTiming: assert hidden.get("timing_llm_api_ms") is None assert hidden.get("timing_pre_processing_ms") is None - def test_detailed_timing_headers_in_custom_headers(self, monkeypatch): + def test_detailed_timing_headers_in_custom_headers(self, monkeypatch: pytest.MonkeyPatch) -> None: """When LITELLM_DETAILED_TIMING is true, headers flow to get_custom_headers.""" - monkeypatch.setattr(common_request_processing_mod, "LITELLM_DETAILED_TIMING", True) + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "true") user_api_key_dict = UserAPIKeyAuth(api_key="sk-test") hidden_params = { @@ -547,9 +547,9 @@ class TestDetailedTiming: assert headers["x-litellm-timing-post-processing-ms"] == "10.0" assert headers["x-litellm-timing-message-copy-ms"] == "2.5" - def test_detailed_timing_headers_absent_when_disabled(self, monkeypatch): + def test_detailed_timing_headers_absent_when_disabled(self, monkeypatch: pytest.MonkeyPatch) -> None: """When LITELLM_DETAILED_TIMING is false, no timing headers emitted.""" - monkeypatch.setattr(common_request_processing_mod, "LITELLM_DETAILED_TIMING", False) + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "false") user_api_key_dict = UserAPIKeyAuth(api_key="sk-test") hidden_params = { diff --git a/tests/unit/proxy/proxy_server/test_proxy_config.py b/tests/unit/proxy/proxy_server/test_proxy_config.py index 712b4134c05..8e047ed6f9b 100644 --- a/tests/unit/proxy/proxy_server/test_proxy_config.py +++ b/tests/unit/proxy/proxy_server/test_proxy_config.py @@ -35,7 +35,8 @@ from pydantic import JsonValue, TypeAdapter, ValidationError import litellm from litellm._logging import turn_on_json from litellm.llms.custom_httpx.http_handler import HTTPHandler -from litellm.proxy._types import CommonProxyErrors, ConfigGeneralSettings +from litellm.proxy._types import CommonProxyErrors, ConfigGeneralSettings, UserAPIKeyAuth +from litellm.proxy.common_request_processing import ProxyBaseLLMRequestProcessing from litellm.proxy.common_utils.encrypt_decrypt_utils import encrypt_value_helper from litellm.proxy.config_resolvers.settings_store import SettingsStore from litellm.router_api import ApplyResult, RouterSettings @@ -2512,6 +2513,29 @@ def test_ProxyConfig__load_environment_variables_sets_env(monkeypatch): assert result == {"TEST_LOAD_ENV_X": "hello", "set": True, "len": 1} +def test_ProxyConfig__load_environment_variables_enables_detailed_timing( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "false") + ProxyConfig()._load_environment_variables({"environment_variables": {"LITELLM_DETAILED_TIMING": "true"}}) + + headers: Final = ProxyBaseLLMRequestProcessing.get_custom_headers( + user_api_key_dict=UserAPIKeyAuth(api_key="sk-test"), + hidden_params={ + "_response_ms": 530.0, + "timing_llm_api_ms": 500.0, + "timing_pre_processing_ms": 20.0, + "timing_post_processing_ms": 10.0, + "timing_message_copy_ms": 2.5, + }, + ) + + assert headers["x-litellm-timing-llm-api-ms"] == "500.0" + assert headers["x-litellm-timing-pre-processing-ms"] == "20.0" + assert headers["x-litellm-timing-post-processing-ms"] == "10.0" + assert headers["x-litellm-timing-message-copy-ms"] == "2.5" + + def test_ProxyConfig__load_environment_variables_warns_when_the_config_replaces_a_process_value( monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture ): diff --git a/tests/unit/proxy/rerank_endpoints/test_endpoints.py b/tests/unit/proxy/rerank_endpoints/test_endpoints.py index c1908a97d7e..c76db2f909e 100644 --- a/tests/unit/proxy/rerank_endpoints/test_endpoints.py +++ b/tests/unit/proxy/rerank_endpoints/test_endpoints.py @@ -13,7 +13,6 @@ import respx from fastapi import FastAPI, HTTPException, Request, Response from fastapi.testclient import TestClient -import litellm.proxy.common_request_processing as common_request_processing_mod import litellm.proxy.proxy_server as proxy_server_mod from litellm._logging import verbose_proxy_logger from litellm.proxy._types import ProxyException, UserAPIKeyAuth @@ -99,10 +98,10 @@ async def test_rerank_emits_latency_and_cost_headers(): @pytest.mark.asyncio -async def test_rerank_emits_detailed_timing_headers_when_enabled(): +async def test_rerank_emits_detailed_timing_headers_when_enabled(monkeypatch: pytest.MonkeyPatch) -> None: """LITELLM_DETAILED_TIMING must also work on /rerank, not just /chat/completions.""" - with patch.object(common_request_processing_mod, "LITELLM_DETAILED_TIMING", True): # test-quality-ok: LITELLM_DETAILED_TIMING is a module constant; toggling it is the behavior under test - fastapi_response = await _call_rerank() + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "true") + fastapi_response = await _call_rerank() assert fastapi_response.headers["x-litellm-timing-llm-api-ms"] == "1488.0" assert fastapi_response.headers["x-litellm-timing-pre-processing-ms"] == "10.0" @@ -119,9 +118,9 @@ async def test_rerank_emits_zero_response_cost_header(): @pytest.mark.asyncio -async def test_rerank_omits_detailed_timing_headers_when_disabled(): - with patch.object(common_request_processing_mod, "LITELLM_DETAILED_TIMING", False): # test-quality-ok: LITELLM_DETAILED_TIMING is a module constant; toggling it is the behavior under test - fastapi_response = await _call_rerank() +async def test_rerank_omits_detailed_timing_headers_when_disabled(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("LITELLM_DETAILED_TIMING", "false") + fastapi_response = await _call_rerank() assert "x-litellm-timing-llm-api-ms" not in fastapi_response.headers