perf: guard debug log f-strings and remove redundant dict copy in hot path (#19961)

Guard verbose_logger.debug() f-strings with isEnabledFor(logging.DEBUG)
checks in the router and cost calculation hot paths. Python evaluates
f-string arguments before the logging framework checks the log level,
causing expensive formatting on every request even with debug logging
disabled.

Changes:
- Remove redundant litellm_params.copy() in _completion/_acompletion
- Guard 5 debug logs in router.py (+ remove 1 duplicate log)
- Guard 6 debug logs in cost_calculator.py and utils.py
  - get_model_info(): formatted 50+ field dict every call
  - _apply_cost_margin(): called list(dict.keys()) every request

Profiled improvement: completion_cost 769µs → 637µs/call (-17.2%)
This commit is contained in:
ryan-crabbe
2026-02-07 10:40:29 -08:00
committed by GitHub
parent 616350f058
commit 606b9be0f7
3 changed files with 56 additions and 44 deletions
+29 -20
View File
@@ -1,5 +1,6 @@
# What is this?
## File for 'response_cost' calculation in Logging
import logging
import time
from functools import lru_cache
from typing import TYPE_CHECKING, Any, List, Literal, Optional, Tuple, Union, cast
@@ -774,10 +775,11 @@ def _apply_cost_discount(
discount_amount = original_cost * discount_percent
final_cost = original_cost - discount_amount
verbose_logger.debug(
f"Applied {discount_percent*100}% discount to {custom_llm_provider}: "
f"${original_cost:.6f} -> ${final_cost:.6f} (saved ${discount_amount:.6f})"
)
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(
f"Applied {discount_percent*100}% discount to {custom_llm_provider}: "
f"${original_cost:.6f} -> ${final_cost:.6f} (saved ${discount_amount:.6f})"
)
return final_cost, discount_percent, discount_amount
@@ -807,17 +809,20 @@ def _apply_cost_margin(
margin_config = None
if custom_llm_provider and custom_llm_provider in litellm.cost_margin_config:
margin_config = litellm.cost_margin_config[custom_llm_provider]
verbose_logger.debug(
f"Found provider-specific margin config for {custom_llm_provider}: {margin_config}"
)
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(
f"Found provider-specific margin config for {custom_llm_provider}: {margin_config}"
)
elif "global" in litellm.cost_margin_config:
margin_config = litellm.cost_margin_config["global"]
verbose_logger.debug(f"Using global margin config: {margin_config}")
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(f"Using global margin config: {margin_config}")
else:
verbose_logger.debug(
f"No margin config found. Provider: {custom_llm_provider}, "
f"Available configs: {list(litellm.cost_margin_config.keys())}"
)
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(
f"No margin config found. Provider: {custom_llm_provider}, "
f"Available configs: {list(litellm.cost_margin_config.keys())}"
)
if margin_config is not None:
# Handle different margin config formats
@@ -836,11 +841,12 @@ def _apply_cost_margin(
final_cost = original_cost + margin_total_amount
verbose_logger.debug(
f"Applied margin to {custom_llm_provider or 'global'}: "
f"${original_cost:.6f} -> ${final_cost:.6f} "
f"(margin: {margin_percent*100 if margin_percent > 0 else 0}% + ${margin_fixed_amount:.6f} = ${margin_total_amount:.6f})"
)
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(
f"Applied margin to {custom_llm_provider or 'global'}: "
f"${original_cost:.6f} -> ${final_cost:.6f} "
f"(margin: {margin_percent*100 if margin_percent > 0 else 0}% + ${margin_fixed_amount:.6f} = ${margin_total_amount:.6f})"
)
return final_cost, margin_percent, margin_fixed_amount, margin_total_amount
@@ -1021,9 +1027,10 @@ def completion_cost( # noqa: PLR0915
for idx, model in enumerate(potential_model_names):
try:
verbose_logger.debug(
f"selected model name for cost calculation: {model}"
)
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(
f"selected model name for cost calculation: {model}"
)
if completion_response is not None and (
isinstance(completion_response, BaseModel)
@@ -2126,3 +2133,5 @@ def handle_realtime_stream_cost_calculation(
total_cost = input_cost_per_token + output_cost_per_token
return total_cost
+25 -23
View File
@@ -1279,9 +1279,7 @@ class Router:
self._update_kwargs_with_deployment(deployment=deployment, kwargs=kwargs)
kwargs.pop("silent_model", None) # Ensure it's not in kwargs either
# No copy needed - data is only read and spread into new dict below
data = litellm_params.copy() # Use the local copy of litellm_params
model_name = data["model"]
model_name = litellm_params["model"]
potential_model_client = self._get_client(
deployment=deployment, kwargs=kwargs
)
@@ -1302,7 +1300,7 @@ class Router:
self.routing_strategy_pre_call_checks(deployment=deployment)
input_kwargs = {
**data,
**litellm_params,
"messages": messages,
"caching": self.cache_responses,
"client": model_client,
@@ -1690,10 +1688,8 @@ class Router:
self._update_kwargs_with_deployment(deployment=deployment, kwargs=kwargs)
kwargs.pop("silent_model", None) # Ensure it's not in kwargs either
# No copy needed - data is only read and spread into new dict below
data = litellm_params.copy() # Use the local copy of litellm_params
model_name = data["model"]
model_name = litellm_params["model"]
model_client = self._get_async_openai_model_client(
deployment=deployment,
@@ -1702,7 +1698,7 @@ class Router:
self.total_calls[model_name] += 1
input_kwargs = {
**data,
**litellm_params,
"messages": messages,
"caching": self.cache_responses,
"client": model_client,
@@ -4816,7 +4812,8 @@ class Router:
)
else:
response = await self.async_function_with_retries(*args, **kwargs)
verbose_router_logger.debug(f"Async Response: {response}")
if verbose_router_logger.isEnabledFor(logging.DEBUG):
verbose_router_logger.debug(f"Async Response: {response}")
response = add_fallback_headers_to_response(
response=response,
attempted_fallbacks=0,
@@ -8013,9 +8010,10 @@ class Router:
# check if the user sent in a deployment name instead
healthy_deployments = self._get_deployment_by_litellm_model(model=model)
verbose_router_logger.debug(
f"initial list of deployments: {healthy_deployments}"
)
if verbose_router_logger.isEnabledFor(logging.DEBUG):
verbose_router_logger.debug(
f"initial list of deployments: {healthy_deployments}"
)
if len(healthy_deployments) == 0:
# Check for default fallbacks if no deployments are found for the requested model
@@ -8086,18 +8084,20 @@ class Router:
request_kwargs=request_kwargs,
)
verbose_router_logger.debug(
f"healthy_deployments after team filter: {healthy_deployments}"
)
if verbose_router_logger.isEnabledFor(logging.DEBUG):
verbose_router_logger.debug(
f"healthy_deployments after team filter: {healthy_deployments}"
)
healthy_deployments = filter_web_search_deployments(
healthy_deployments=healthy_deployments,
request_kwargs=request_kwargs,
)
verbose_router_logger.debug(
f"healthy_deployments after web search filter: {healthy_deployments}"
)
if verbose_router_logger.isEnabledFor(logging.DEBUG):
verbose_router_logger.debug(
f"healthy_deployments after web search filter: {healthy_deployments}"
)
if isinstance(healthy_deployments, dict):
return healthy_deployments
@@ -8105,10 +8105,10 @@ class Router:
cooldown_deployments = await _async_get_cooldown_deployments(
litellm_router_instance=self, parent_otel_span=parent_otel_span
)
verbose_router_logger.debug(
f"async cooldown deployments: {cooldown_deployments}"
)
verbose_router_logger.debug(f"cooldown_deployments: {cooldown_deployments}")
if verbose_router_logger.isEnabledFor(logging.DEBUG):
verbose_router_logger.debug(
f"cooldown deployments: {cooldown_deployments}"
)
healthy_deployments = self._filter_cooldown_deployments(
healthy_deployments=healthy_deployments,
cooldown_deployments=cooldown_deployments,
@@ -8784,7 +8784,8 @@ class Router:
Returns:
List of healthy deployments
"""
verbose_router_logger.debug(f"cooldown deployments: {cooldown_deployments}")
if verbose_router_logger.isEnabledFor(logging.DEBUG):
verbose_router_logger.debug(f"cooldown deployments: {cooldown_deployments}")
# Convert to set for O(1) lookup and use list comprehension for O(n) filtering
cooldown_set = set(cooldown_deployments)
return [
@@ -8947,3 +8948,4 @@ class Router:
litellm._async_failure_callback = []
self.retry_policy = None
self.flush_cache()
+2 -1
View File
@@ -5809,7 +5809,8 @@ def get_model_info(model: str, custom_llm_provider: Optional[str] = None) -> Mod
if value is not None:
_model_info[key] = value # type: ignore
verbose_logger.debug(f"model_info: {_model_info}")
if verbose_logger.isEnabledFor(logging.DEBUG):
verbose_logger.debug(f"model_info: {_model_info}")
returned_model_info = ModelInfo(
**_model_info, supported_openai_params=supported_openai_params