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

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-01-28 15:12:47 -08:00 • committed by Alexsander Hamir
parent 33440858aa
commit eb264c802c
3 changed files with 73 additions and 53 deletions

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
@ -716,10 +717,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
@ -749,17 +751,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
@ -778,11 +783,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
@ -957,9 +963,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)
@ -2035,3 +2042,5 @@ def handle_realtime_stream_cost_calculation(
total_cost = input_cost_per_token + output_cost_per_token
return total_cost

View file

@ -1239,10 +1239,8 @@ class Router:
request_kwargs=kwargs,
)
self._update_kwargs_with_deployment(deployment=deployment, kwargs=kwargs)
# No copy needed - data is only read and spread into new dict below
data = deployment["litellm_params"]
model_name = data["model"]
kwargs.pop("silent_model", None) # Ensure it's not in kwargs either
model_name = litellm_params["model"]
potential_model_client = self._get_client(
deployment=deployment, kwargs=kwargs
)
@ -1262,15 +1260,14 @@ class Router:
if not self.has_model_id(model):
self.routing_strategy_pre_call_checks(deployment=deployment)
response = litellm.completion(
**{
**data,
"messages": messages,
"caching": self.cache_responses,
"client": model_client,
**kwargs,
}
)
input_kwargs = {
**litellm_params,
"messages": messages,
"caching": self.cache_responses,
"client": model_client,
**kwargs,
}
response = litellm.completion(**input_kwargs)
verbose_router_logger.info(
f"litellm.completion(model={model_name})\033[32m 200 OK\033[0m"
)
@ -1552,10 +1549,9 @@ class Router:
deployment=deployment, parent_otel_span=parent_otel_span
)
self._update_kwargs_with_deployment(deployment=deployment, kwargs=kwargs)
# No copy needed - data is only read and spread into new dict below
data = deployment["litellm_params"]
kwargs.pop("silent_model", None) # Ensure it's not in kwargs either
model_name = data["model"]
model_name = litellm_params["model"]
model_client = self._get_async_openai_model_client(
deployment=deployment,
@ -1564,7 +1560,7 @@ class Router:
self.total_calls[model_name] += 1
input_kwargs = {
**data,
**litellm_params,
"messages": messages,
"caching": self.cache_responses,
"client": model_client,
@ -4561,7 +4557,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,
@ -7728,9 +7725,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
@ -7801,18 +7799,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
@ -7820,10 +7820,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,
@ -8499,7 +8499,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 [
@ -8662,3 +8663,4 @@ class Router:
litellm._async_failure_callback = []
self.retry_policy = None
self.flush_cache()

View file

@ -5698,7 +5698,16 @@ def get_model_info(model: str, custom_llm_provider: Optional[str] = None) -> Mod
custom_llm_provider=custom_llm_provider,
)
verbose_logger.debug(f"model_info: {_model_info}")
provider_info = get_provider_info(
model=model, custom_llm_provider=custom_llm_provider
)
if provider_info:
for key, value in provider_info.items():
if value is not None:
_model_info[key] = value # type: ignore
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