This commit is contained in:
Shivam Rawat 2026-11-06 15:12:20 -08:00 • committed by GitHub
commit bf20226f4d
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
6 changed files with 51 additions and 25 deletions

View file

@ -188,9 +188,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(

View file

@ -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),
}

View file

@ -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
@ -2313,7 +2313,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": (

View file

@ -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 = {

View file

@ -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
):

View file

@ -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