fix overhead for /messages

This commit is contained in:
shivam 2026-03-27 14:48:27 -07:00
parent 2ea9e207bd
commit ded4373cc1
6 changed files with 417 additions and 13 deletions

View file

@ -144,6 +144,32 @@ MCP_HEALTH_CHECK_TIMEOUT = float(os.getenv("LITELLM_MCP_HEALTH_CHECK_TIMEOUT", "
LITELLM_UI_ALLOW_HEADERS = [
"x-litellm-semantic-filter",
"x-litellm-semantic-filter-tools",
# Expose LiteLLM proxy response headers to browser clients (fetch / dashboard).
# Without these, Access-Control-Expose-Headers hides them from JavaScript.
"x-litellm-call-id",
"x-litellm-model-id",
"x-litellm-cache-key",
"x-litellm-model-api-base",
"x-litellm-version",
"x-litellm-model-region",
"x-litellm-response-cost",
"x-litellm-response-cost-original",
"x-litellm-response-cost-discount-amount",
"x-litellm-response-cost-margin-amount",
"x-litellm-response-cost-margin-percent",
"x-litellm-key-tpm-limit",
"x-litellm-key-rpm-limit",
"x-litellm-key-max-budget",
"x-litellm-key-spend",
"x-litellm-response-duration-ms",
"x-litellm-overhead-duration-ms",
"x-litellm-callback-duration-ms",
"x-litellm-timing-pre-processing-ms",
"x-litellm-timing-llm-api-ms",
"x-litellm-timing-post-processing-ms",
"x-litellm-timing-message-copy-ms",
"x-litellm-fastest_response_batch_completion",
"x-litellm-timeout",
]
# Gemini model-specific minimal thinking budget constants

View file

@ -60,6 +60,9 @@ from litellm.integrations.deepeval.deepeval import DeepEvalLogger
from litellm.integrations.mlflow import MlflowLogger
from litellm.integrations.sqs import SQSLogger
from litellm.litellm_core_utils.core_helpers import reconstruct_model_name
from litellm.litellm_core_utils.llm_response_utils.response_metadata import (
get_response_hidden_params,
)
from litellm.litellm_core_utils.get_litellm_params import get_litellm_params
from litellm.litellm_core_utils.llm_cost_calc.tool_call_cost_tracking import (
StandardBuiltInToolCostTracking,
@ -1693,20 +1696,31 @@ class Logging(LiteLLMLoggingBaseClass):
Non-streaming success uses _process_hidden_params_and_response_cost (skipped when
stream=True). Streaming assembles the full response later; without this merge,
OTEL/callbacks that read metadata.hidden_params miss cost-related fields.
Merge with any existing metadata.hidden_params (e.g. proxy-injected timing for
/v1/messages SSE) instead of replacing, so litellm_overhead_time_ms is not dropped
when the assembled response omits it.
"""
if logging_result is None:
return
hidden_params = getattr(logging_result, "_hidden_params", None)
if not hidden_params:
incoming = get_response_hidden_params(logging_result)
if not incoming:
return
if self.model_call_details.get("litellm_params") is None:
return
self.model_call_details["litellm_params"].setdefault("metadata", {})
if self.model_call_details["litellm_params"]["metadata"] is None:
self.model_call_details["litellm_params"]["metadata"] = {}
self.model_call_details["litellm_params"]["metadata"]["hidden_params"] = getattr(
logging_result, "_hidden_params", {}
)
md = self.model_call_details["litellm_params"]["metadata"]
if not isinstance(md, dict):
return
existing = md.get("hidden_params")
if not isinstance(existing, dict):
existing = {}
if not isinstance(incoming, dict):
md["hidden_params"] = existing or incoming
return
md["hidden_params"] = {**existing, **incoming}
def _process_hidden_params_and_response_cost(
self,
@ -1714,13 +1728,13 @@ class Logging(LiteLLMLoggingBaseClass):
start_time,
end_time,
):
hidden_params = getattr(logging_result, "_hidden_params", {})
hidden_params = get_response_hidden_params(logging_result)
if hidden_params:
if self.model_call_details.get("litellm_params") is not None:
self.model_call_details["litellm_params"].setdefault("metadata", {})
if self.model_call_details["litellm_params"]["metadata"] is None:
self.model_call_details["litellm_params"]["metadata"] = {}
self.model_call_details["litellm_params"]["metadata"]["hidden_params"] = getattr(logging_result, "_hidden_params", {}) # type: ignore
self.model_call_details["litellm_params"]["metadata"]["hidden_params"] = get_response_hidden_params(logging_result) # type: ignore
if self.model_call_details.get("cache_hit") is True:
self.model_call_details["response_cost"] = 0.0
@ -5299,6 +5313,13 @@ def _extract_response_obj_and_hidden_params(
hidden_params = getattr(init_response_obj, "_hidden_params", None)
elif isinstance(init_response_obj, dict):
response_obj = init_response_obj
hp = get_response_hidden_params(init_response_obj)
if hp:
hidden_params = (
hp if isinstance(hp, dict) else hp.model_dump(exclude_none=True)
)
else:
hidden_params = None
else:
response_obj = {}
@ -5346,6 +5367,15 @@ def get_standard_logging_object_payload(
litellm_params = kwargs.get("litellm_params", {}) or {}
proxy_server_request = litellm_params.get("proxy_server_request") or {}
# Proxy injects timing into litellm_params.metadata.hidden_params (e.g. /v1/messages SSE) while
# _extract_response_obj_and_hidden_params only reads from the response object. Merge so
# StandardLoggingPayload.hidden_params (and spend log metadata) include litellm_overhead_time_ms.
md = litellm_params.get("metadata")
if isinstance(md, dict):
meta_hp = md.get("hidden_params")
if isinstance(meta_hp, dict) and meta_hp:
hidden_params = {**(hidden_params or {}), **meta_hp}
# Merge both litellm_metadata and metadata to get complete metadata
metadata: dict = StandardLoggingPayloadSetup.merge_litellm_metadata(
litellm_params

View file

@ -13,6 +13,111 @@ from litellm.types.utils import (
)
def get_response_hidden_params(response: Any) -> Union[HiddenParams, dict]:
"""
Read LiteLLM internal fields from ModelResponse/Streaming responses or from
dict-shaped provider responses (e.g. Anthropic ``/v1/messages`` JSON bodies).
Dict responses store timing/cost under the ``_hidden_params`` key; the proxy
strips that key before returning JSON to clients.
"""
if response is None:
return {}
hp = getattr(response, "_hidden_params", None)
if hp is not None:
return hp
if isinstance(response, dict):
inner = response.get("_hidden_params")
if isinstance(inner, dict):
return inner
return {}
def strip_litellm_internal_keys_from_dict_response(response: Any) -> None:
"""Remove internal keys from dict API responses before JSON serialization."""
if isinstance(response, dict):
response.pop("_hidden_params", None)
def merge_hidden_params_with_logging_timings(
response: Any,
logging_obj: Any,
*,
end_time: Optional[datetime.datetime] = None,
) -> dict:
"""
Merge response hidden params with timing derived from the LiteLLM logging object.
Used by the proxy when ``response`` does not expose ``_hidden_params`` (e.g. Anthropic
``/v1/messages`` streaming async generators) or when timing keys are missing, so
``x-litellm-overhead-duration-ms`` and spend metadata can still be populated.
Mirrors :meth:`ResponseMetadata.set_timing_metrics` for overhead/cache/callback fields.
"""
hp_raw = get_response_hidden_params(response)
if isinstance(hp_raw, dict):
out: dict = dict(hp_raw)
elif hp_raw is not None and hasattr(hp_raw, "model_dump"):
out = hp_raw.model_dump(exclude_none=True)
else:
out = {}
if out.get("litellm_overhead_time_ms") is not None:
return out
if logging_obj is None or not hasattr(logging_obj, "model_call_details"):
return out
mcd = logging_obj.model_call_details
start_time = getattr(logging_obj, "start_time", None)
_end = end_time or datetime.datetime.now()
if start_time is None:
return out
total_ms = (_end - start_time).total_seconds() * 1000
out.setdefault("_response_ms", total_ms)
llm_api_duration_ms = mcd.get("llm_api_duration_ms")
if llm_api_duration_ms is not None:
overhead_ms = round(total_ms - float(llm_api_duration_ms), 4)
out["litellm_overhead_time_ms"] = max(overhead_ms, 0.0)
else:
caching_details = getattr(logging_obj, "caching_details", None)
if (
caching_details is not None
and caching_details.get("cache_hit") is True
and (cache_duration_ms := caching_details.get("cache_duration_ms"))
is not None
):
out["litellm_overhead_time_ms"] = max(
total_ms - float(cache_duration_ms), 0.0
)
callback_duration_ms = getattr(logging_obj, "callback_duration_ms", None)
if callback_duration_ms is not None:
out.setdefault(
"callback_duration_ms", round(float(callback_duration_ms), 4)
)
if LITELLM_DETAILED_TIMING and llm_api_duration_ms is not None:
detailed: dict = {
"timing_llm_api_ms": round(float(llm_api_duration_ms), 4),
}
msg_copy_ms = getattr(logging_obj, "message_copy_duration_ms", None)
if msg_copy_ms is not None:
detailed["timing_message_copy_ms"] = round(float(msg_copy_ms), 4)
api_call_start = mcd.get("api_call_start_time")
if api_call_start is not None and start_time is not None:
pre_ms = (api_call_start - start_time).total_seconds() * 1000
detailed["timing_pre_processing_ms"] = round(pre_ms, 4)
post_ms = total_ms - pre_ms - float(llm_api_duration_ms)
detailed["timing_post_processing_ms"] = round(max(post_ms, 0), 4)
out.update(detailed)
return out
class ResponseMetadata:
"""
Handles setting and managing `_hidden_params`, `response_time_ms`, and `litellm_overhead_time_ms` for LiteLLM responses
@ -20,8 +125,8 @@ class ResponseMetadata:
def __init__(self, result: Any):
self.result = result
self._hidden_params: Union[HiddenParams, dict] = (
getattr(result, "_hidden_params", {}) or {}
self._hidden_params: Union[HiddenParams, dict] = get_response_hidden_params(
result
)
@property
@ -169,6 +274,15 @@ class ResponseMetadata:
"""Apply metadata to the response object"""
if hasattr(self.result, "_hidden_params"):
self.result._hidden_params = self._hidden_params
elif isinstance(self.result, dict):
# Dict-shaped responses (e.g. Anthropic Messages API) have no
# attribute slot; use a private key stripped before HTTP response.
if isinstance(self._hidden_params, dict):
self.result["_hidden_params"] = self._hidden_params
elif isinstance(self._hidden_params, HiddenParams):
self.result["_hidden_params"] = self._hidden_params.model_dump(
exclude_none=True
)
def update_response_metadata(

View file

@ -35,6 +35,10 @@ from litellm.litellm_core_utils.litellm_logging import Logging as LiteLLMLogging
from litellm.litellm_core_utils.llm_response_utils.get_headers import (
get_response_headers,
)
from litellm.litellm_core_utils.llm_response_utils.response_metadata import (
merge_hidden_params_with_logging_timings,
strip_litellm_internal_keys_from_dict_response,
)
from litellm.litellm_core_utils.safe_json_dumps import safe_dumps
from litellm.proxy._types import ProxyException, UserAPIKeyAuth
from litellm.proxy.auth.auth_utils import check_response_size_is_safe
@ -417,6 +421,49 @@ class ProxyBaseLLMRequestProcessing:
def __init__(self, data: dict):
self.data = data
@staticmethod
def _inject_proxy_timing_into_logging_metadata(
logging_obj: Optional[LiteLLMLoggingObj],
hidden_params: dict,
) -> None:
"""
When the response object has no _hidden_params (e.g. messages SSE), spend logs and
callbacks still read timing from litellm_params.metadata.hidden_params.
"""
if logging_obj is None or not hasattr(logging_obj, "model_call_details"):
return
timing_keys = (
"litellm_overhead_time_ms",
"_response_ms",
"callback_duration_ms",
"timing_llm_api_ms",
"timing_pre_processing_ms",
"timing_post_processing_ms",
"timing_message_copy_ms",
)
to_merge = {
k: hidden_params[k]
for k in timing_keys
if k in hidden_params and hidden_params[k] is not None
}
if not to_merge:
return
mcd = logging_obj.model_call_details
lp = mcd.get("litellm_params")
if not isinstance(lp, dict):
return
md = lp.get("metadata")
if md is None:
md = {}
lp["metadata"] = md
elif not isinstance(md, dict):
return
existing = md.get("hidden_params")
if existing is None:
md["hidden_params"] = to_merge
elif isinstance(existing, dict):
existing.update(to_merge)
@staticmethod
def get_custom_headers(
*,
@ -986,7 +1033,16 @@ class ProxyBaseLLMRequestProcessing:
_exception_raised = False
try:
hidden_params = getattr(response, "_hidden_params", {}) or {}
# Async generators (e.g. Anthropic /v1/messages SSE) have no _hidden_params;
# merge timing from logging_obj.model_call_details (llm_api_duration_ms, etc.).
hidden_params = merge_hidden_params_with_logging_timings(
response,
logging_obj,
end_time=datetime.now(),
)
ProxyBaseLLMRequestProcessing._inject_proxy_timing_into_logging_metadata(
logging_obj, hidden_params
)
model_id = self._get_model_id_from_response(hidden_params, self.data)
cache_key, api_base, response_cost = (
@ -1217,9 +1273,22 @@ class ProxyBaseLLMRequestProcessing:
log_context=f"litellm_call_id={logging_obj.litellm_call_id}",
)
hidden_params = (
getattr(response, "_hidden_params", {}) or {}
) # get any updated response headers
# Re-merge after post_call_success_hook so dict / CSW hidden_params + logging timings align.
hidden_params = merge_hidden_params_with_logging_timings(
response,
logging_obj,
end_time=datetime.now(),
)
ProxyBaseLLMRequestProcessing._inject_proxy_timing_into_logging_metadata(
logging_obj, hidden_params
)
model_id = self._get_model_id_from_response(hidden_params, self.data)
cache_key = hidden_params.get("cache_key", None) or ""
api_base = hidden_params.get("api_base", None) or ""
response_cost = hidden_params.get("response_cost", None) or ""
fastest_response_batch_completion = hidden_params.get(
"fastest_response_batch_completion", None
)
additional_headers = hidden_params.get("additional_headers", {}) or {}
fastapi_response.headers.update(
@ -1252,6 +1321,8 @@ class ProxyBaseLLMRequestProcessing:
await check_response_size_is_safe(response=response)
strip_litellm_internal_keys_from_dict_response(response)
return response
async def base_passthrough_process_llm_request(

View file

@ -6,6 +6,7 @@ through _hidden_params to the x-litellm-callback-duration-ms response header.
"""
import datetime
import types
from unittest.mock import MagicMock
import litellm.litellm_core_utils.llm_response_utils.response_metadata as response_metadata_mod
@ -13,6 +14,9 @@ import litellm.proxy.common_request_processing as common_request_processing_mod
from litellm.litellm_core_utils.litellm_logging import Logging
from litellm.litellm_core_utils.llm_response_utils.response_metadata import (
ResponseMetadata,
get_response_hidden_params,
merge_hidden_params_with_logging_timings,
strip_litellm_internal_keys_from_dict_response,
update_response_metadata,
)
from litellm.proxy._types import UserAPIKeyAuth
@ -20,6 +24,77 @@ from litellm.proxy.common_request_processing import ProxyBaseLLMRequestProcessin
from litellm.types.utils import ModelResponse
class TestMergeHiddenParamsWithLoggingTimings:
"""Proxy merge for async generators / responses without _hidden_params."""
def test_fills_overhead_from_logging_obj(self):
"""Simulates /v1/messages SSE: no response._hidden_params, timing on logging_obj."""
class _FakeStream:
pass
logging_obj = types.SimpleNamespace(
start_time=datetime.datetime(2025, 1, 1, 0, 0, 0),
model_call_details={"llm_api_duration_ms": 40.0},
caching_details=None,
)
end = datetime.datetime(2025, 1, 1, 0, 0, 1)
merged = merge_hidden_params_with_logging_timings(
_FakeStream(),
logging_obj,
end_time=end,
)
assert merged["litellm_overhead_time_ms"] == 960.0
assert merged["_response_ms"] == 1000.0
def test_preserves_existing_overhead_on_response(self):
logging_obj = types.SimpleNamespace(
start_time=datetime.datetime(2025, 1, 1, 0, 0, 0),
model_call_details={"llm_api_duration_ms": 1.0},
)
class R:
_hidden_params = {"litellm_overhead_time_ms": 42.0, "_response_ms": 100.0}
merged = merge_hidden_params_with_logging_timings(
R(),
logging_obj,
end_time=datetime.datetime(2025, 1, 1, 0, 0, 1),
)
assert merged["litellm_overhead_time_ms"] == 42.0
class TestDictResponseHiddenParams:
"""Dict-shaped API responses (e.g. Anthropic /v1/messages) must carry timing metadata."""
def test_update_response_metadata_stores_overhead_on_dict(self):
result: dict = {"id": "msg_1", "type": "message", "role": "assistant", "content": []}
logging_obj = MagicMock()
logging_obj.model_call_details = {"llm_api_duration_ms": 50.0}
logging_obj.caching_details = None
logging_obj._response_cost_calculator = MagicMock(return_value=0.0)
logging_obj.litellm_call_id = "call-1"
start = datetime.datetime(2025, 1, 1, 0, 0, 0)
end = datetime.datetime(2025, 1, 1, 0, 0, 1)
update_response_metadata(
result=result,
logging_obj=logging_obj,
model="claude-3-5-sonnet",
kwargs={},
start_time=start,
end_time=end,
)
hidden = get_response_hidden_params(result)
assert hidden.get("litellm_overhead_time_ms") is not None
assert hidden.get("_response_ms") == 1000.0
strip_litellm_internal_keys_from_dict_response(result)
assert "_hidden_params" not in result
class TestCallbackDurationMs:
"""Tests for the callback_duration_ms metric in ResponseMetadata."""

View file

@ -2299,3 +2299,91 @@ def test_merge_hidden_params_from_response_into_metadata_no_op_when_empty():
assert "hidden_params" not in logging_obj.model_call_details["litellm_params"][
"metadata"
]
def test_merge_hidden_params_from_response_preserves_proxy_injected_timing():
"""Proxy may inject timing before stream end; assembled response merge must not drop it."""
from litellm.litellm_core_utils.litellm_logging import Logging as LiteLLMLoggingObj
logging_obj = LiteLLMLoggingObj(
model="claude-3-5-sonnet",
messages=[{"role": "user", "content": "hi"}],
stream=True,
call_type="anthropic_messages",
start_time=time.time(),
litellm_call_id="merge-hp-timing",
function_id="merge-hp-timing-fn",
)
logging_obj.model_call_details = {
"litellm_params": {
"metadata": {
"hidden_params": {"litellm_overhead_time_ms": 273.329, "_response_ms": 1590.0}
}
},
}
class _Assembled:
_hidden_params = {"response_cost": 0.001, "model_id": "mid-2"}
logging_obj._merge_hidden_params_from_response_into_metadata(_Assembled())
hp = logging_obj.model_call_details["litellm_params"]["metadata"]["hidden_params"]
assert hp["litellm_overhead_time_ms"] == 273.329
assert hp["_response_ms"] == 1590.0
assert hp["response_cost"] == 0.001
assert hp["model_id"] == "mid-2"
def test_get_standard_logging_payload_includes_metadata_hidden_params_overhead():
"""Spend logs read overhead from standard_logging_object.hidden_params; merge metadata.hidden_params."""
from datetime import datetime
from litellm.litellm_core_utils.litellm_logging import (
get_standard_logging_object_payload,
Logging as LiteLLMLoggingObj,
)
logging_obj = LiteLLMLoggingObj(
model="claude-3-5-sonnet-20240620",
messages=[{"role": "user", "content": "hi"}],
stream=True,
call_type="anthropic_messages",
start_time=datetime.now(),
litellm_call_id="sl-overhead-meta",
function_id="sl-overhead-meta-fn",
)
kwargs = {
"model": "claude-3-5-sonnet-20240620",
"stream": True,
"litellm_params": {
"metadata": {
"hidden_params": {
"litellm_overhead_time_ms": 88.5,
"_response_ms": 1200.0,
"model_id": "router-model-id",
}
}
},
"response_cost": 0.0,
"custom_llm_provider": "anthropic",
}
# Dict body without _hidden_params (timing only on metadata.hidden_params)
init_response_obj = {
"id": "msg_01",
"type": "message",
"role": "assistant",
"content": [{"type": "text", "text": "ok"}],
"model": "claude-3-5-sonnet-20240620",
"usage": {"input_tokens": 1, "output_tokens": 2},
}
now = datetime.now()
payload = get_standard_logging_object_payload(
kwargs=kwargs,
init_response_obj=init_response_obj,
start_time=now,
end_time=now,
logging_obj=logging_obj,
status="success",
)
assert payload is not None
assert payload["hidden_params"]["litellm_overhead_time_ms"] == 88.5
assert payload["hidden_params"]["model_id"] == "router-model-id"