From f6d768326166ea08cfdf124729ec0ce3edb8af54 Mon Sep 17 00:00:00 2001 From: Ishaan Jaff Date: Mon, 29 Sep 2025 17:33:27 -0700 Subject: [PATCH] [Feat] LiteLLM Overhead metric tracking - Add support for tracking litellm overhead on cache hits (#15045) * test_litellm_overhead * vertex track overhead * fix config.yaml used for testing * test_litellm_overhead_stream * add update_response_metadata for caching handler * add CachingDetails * fix update_response_metadata import * add CachingDetails metrics * add CachingDetails * test_litellm_overhead_cache_hit * test_litellm_overhead_cache_hit * test_litellm_overhead_cache_hit --- litellm/caching/caching_handler.py | 33 +++++++++++++++++ litellm/litellm_core_utils/litellm_logging.py | 4 +++ .../llm_response_utils/response_metadata.py | 30 ++++++++++++++-- litellm/types/utils.py | 12 +++++++ litellm/utils.py | 29 +++------------ .../test_litellm_overhead.py | 36 +++++++++++++++++++ 6 files changed, 117 insertions(+), 27 deletions(-) diff --git a/litellm/caching/caching_handler.py b/litellm/caching/caching_handler.py index 9526c4a2f3..b151ebd651 100644 --- a/litellm/caching/caching_handler.py +++ b/litellm/caching/caching_handler.py @@ -36,12 +36,16 @@ import litellm from litellm._logging import print_verbose, verbose_logger from litellm.caching import InMemoryCache from litellm.caching.caching import S3Cache +from litellm.litellm_core_utils.llm_response_utils.response_metadata import ( + update_response_metadata, +) from litellm.litellm_core_utils.logging_utils import ( _assemble_complete_response_from_streaming_chunks, ) from litellm.types.caching import CachedEmbedding from litellm.types.rerank import RerankResponse from litellm.types.utils import ( + CachingDetails, CallTypes, Embedding, EmbeddingResponse, @@ -136,6 +140,13 @@ class LLMCachingHandler: kwargs = kwargs.copy() args = args or () + ######################################################### + # Init cache timing metrics + ######################################################### + cache_check_start_time = datetime.datetime.now() + cache_check_end_time = None + ######################################################### + parent_otel_span = _get_parent_otel_span_from_kwargs(kwargs) kwargs["parent_otel_span"] = parent_otel_span @@ -157,6 +168,7 @@ class LLMCachingHandler: kwargs=kwargs, args=args, ) + cache_check_end_time = datetime.datetime.now() if cached_result is not None and not isinstance(cached_result, list): verbose_logger.debug("Cache Hit!") @@ -168,6 +180,7 @@ class LLMCachingHandler: api_base=kwargs.get("api_base", None), api_key=kwargs.get("api_key", None), ) + cache_duration_ms = (cache_check_end_time - cache_check_start_time).total_seconds() * 1000 self._update_litellm_logging_obj_environment( logging_obj=logging_obj, model=model, @@ -175,10 +188,12 @@ class LLMCachingHandler: cached_result=cached_result, is_async=True, custom_llm_provider=custom_llm_provider, + cache_duration_ms=cache_duration_ms, ) call_type = original_function.__name__ + cached_result = self._convert_cached_result_to_model_response( cached_result=cached_result, call_type=call_type, @@ -716,6 +731,18 @@ class LLMCachingHandler: and isinstance(cached_result._hidden_params, dict) ): cached_result._hidden_params["cache_hit"] = True + + ######################################################### + # Add final timing metrics to the cached result + ######################################################### + update_response_metadata( + result=cached_result, + logging_obj=logging_obj, + model=model, + kwargs=kwargs, + start_time=self.start_time, + end_time=datetime.datetime.now(), + ) return cached_result def _convert_cached_stream_response( @@ -944,6 +971,7 @@ class LLMCachingHandler: is_async: bool, is_embedding: bool = False, custom_llm_provider: Optional[str] = None, + cache_duration_ms: Optional[float] = None, ): """ Helper function to update the LiteLLMLoggingObj environment variables. @@ -995,6 +1023,11 @@ class LLMCachingHandler: custom_llm_provider=custom_llm_provider, ) + logging_obj.caching_details = CachingDetails( + cache_hit=True, + cache_duration_ms=cache_duration_ms, + ) + def convert_args_to_kwargs( original_function: Callable, diff --git a/litellm/litellm_core_utils/litellm_logging.py b/litellm/litellm_core_utils/litellm_logging.py index bbadc9c818..24449e1bd0 100644 --- a/litellm/litellm_core_utils/litellm_logging.py +++ b/litellm/litellm_core_utils/litellm_logging.py @@ -83,6 +83,7 @@ from litellm.types.mcp import MCPPostCallResponseObject from litellm.types.rerank import RerankResponse from litellm.types.router import CustomPricingLiteLLMParams from litellm.types.utils import ( + CachingDetails, CallTypes, CostBreakdown, CostResponseTypes, @@ -348,6 +349,9 @@ class Logging(LiteLLMLoggingBaseClass): # Initialize cost breakdown field self.cost_breakdown: Optional[CostBreakdown] = None + # Init Caching related details + self.caching_details: Optional[CachingDetails] = None + self.model_call_details: Dict[str, Any] = { "litellm_trace_id": litellm_trace_id, "litellm_call_id": litellm_call_id, 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 b1085c684f..c5ef723762 100644 --- a/litellm/litellm_core_utils/llm_response_utils/response_metadata.py +++ b/litellm/litellm_core_utils/llm_response_utils/response_metadata.py @@ -85,15 +85,37 @@ class ResponseMetadata: # Set total response time if supported if self.supports_response_time: self.result._response_ms = total_response_time_ms + + ######################################################### + # 1. Add _response_ms total duration + ######################################################### + self._update_hidden_params( + { + "_response_ms": total_response_time_ms, + } + ) - # Calculate LiteLLM overhead + ######################################################### + # 2. Add LiteLLM overhead duration + ######################################################### llm_api_duration_ms = logging_obj.model_call_details.get("llm_api_duration_ms") if llm_api_duration_ms is not None: overhead_ms = round(total_response_time_ms - llm_api_duration_ms, 4) self._update_hidden_params( { "litellm_overhead_time_ms": overhead_ms, - "_response_ms": total_response_time_ms, + } + ) + + ######################################################### + # 3. Add duration for reading from cache + # In this case overhead from litellm is the difference between the cache read duration and the total response time + ######################################################### + if logging_obj.caching_details is not None and logging_obj.caching_details.get("cache_hit") is True and (cache_duration_ms := logging_obj.caching_details.get("cache_duration_ms")) is not None: + overhead_ms = total_response_time_ms - cache_duration_ms + self._update_hidden_params( + { + "litellm_overhead_time_ms": overhead_ms, } ) @@ -113,6 +135,10 @@ def update_response_metadata( ) -> None: """ Updates response metadata including hidden params and timing metrics + Updates response metadata, adds the following: + - response._hidden_params + - response._hidden_params["litellm_overhead_time_ms"] + - response.response_time_ms """ if result is None: return diff --git a/litellm/types/utils.py b/litellm/types/utils.py index 16a69d049c..b0183249ba 100644 --- a/litellm/types/utils.py +++ b/litellm/types/utils.py @@ -2059,6 +2059,18 @@ class StandardLoggingGuardrailInformation(TypedDict, total=False): StandardLoggingPayloadStatus = Literal["success", "failure"] +class CachingDetails(TypedDict): + """ + Track all caching related metrics, fields for a given request + """ + cache_hit: Optional[bool] + """ + Whether the request hit the cache + """ + cache_duration_ms: Optional[float] + """ + Duration for reading from cache + """ class CostBreakdown(TypedDict): """ diff --git a/litellm/utils.py b/litellm/utils.py index cb340735b4..9fdde626ae 100644 --- a/litellm/utils.py +++ b/litellm/utils.py @@ -7,7 +7,6 @@ # # Thank you users! We ❤️ you! - Krrish & Ishaan -from io import StringIO import ast import asyncio import base64 @@ -37,6 +36,7 @@ from dataclasses import dataclass, field from functools import lru_cache, wraps from importlib import resources from inspect import iscoroutine +from io import StringIO from os.path import abspath, dirname, join import aiohttp @@ -232,6 +232,9 @@ from typing import ( from openai import OpenAIError as OriginalError +from litellm.litellm_core_utils.llm_response_utils.response_metadata import ( + update_response_metadata, +) from litellm.litellm_core_utils.thread_pool_executor import executor from litellm.litellm_core_utils.token_counter import token_counter as token_counter_new from litellm.llms.base_llm.anthropic_messages.transformation import ( @@ -1677,30 +1680,6 @@ def _is_streaming_request( return False -def update_response_metadata( - result: Any, - logging_obj: LiteLLMLoggingObject, - model: Optional[str], - kwargs: dict, - start_time: datetime.datetime, - end_time: datetime.datetime, -) -> None: - """ - Updates response metadata, adds the following: - - response._hidden_params - - response._hidden_params["litellm_overhead_time_ms"] - - response.response_time_ms - """ - if result is None: - return - - metadata = ResponseMetadata(result) - metadata.set_hidden_params(logging_obj=logging_obj, model=model, kwargs=kwargs) - metadata.set_timing_metrics( - start_time=start_time, end_time=end_time, logging_obj=logging_obj - ) - metadata.apply() - def _select_tokenizer( model: str, custom_tokenizer: Optional[CustomHuggingfaceTokenizer] = None diff --git a/tests/litellm_utils_tests/test_litellm_overhead.py b/tests/litellm_utils_tests/test_litellm_overhead.py index 8b83257f9b..e3472de184 100644 --- a/tests/litellm_utils_tests/test_litellm_overhead.py +++ b/tests/litellm_utils_tests/test_litellm_overhead.py @@ -5,6 +5,7 @@ import time from datetime import datetime from unittest.mock import AsyncMock, patch, MagicMock import pytest +import asyncio sys.path.insert( 0, os.path.abspath("../..") @@ -75,6 +76,7 @@ async def test_litellm_overhead_non_streaming(model): pass + @pytest.mark.asyncio @pytest.mark.parametrize( "model", @@ -131,3 +133,37 @@ async def test_litellm_overhead_stream(model): assert overhead_percent < 40 pass + + +@pytest.mark.asyncio +async def test_litellm_overhead_cache_hit(): + """ + Test that litellm overhead is tracked on cache hits. + Makes two identical requests and checks that the second one (cache hit) has overhead in hidden params. + """ + from litellm.caching.caching import Cache + + litellm._turn_on_debug() + litellm.cache = Cache() + print("test2 for caching") + litellm.set_verbose = True + messages = [{"role": "user", "content": "Hello, world! Cache test"}] + response1 = await litellm.acompletion(model="gpt-4.1-nano", messages=messages, caching=True) + await asyncio.sleep(2) + # Wait for any pending background tasks to complete + pending_tasks = [task for task in asyncio.all_tasks() if not task.done()] + print("all pending tasks", pending_tasks) + if pending_tasks: + await asyncio.wait(pending_tasks, timeout=1.0) + + response2 = await litellm.acompletion(model="gpt-4.1-nano", messages=messages, caching=True) + print("RESPONSE 1", response1) + print("RESPONSE 2", response2) + assert response1.id == response2.id + + print("response 2 hidden params", response2._hidden_params) + + + assert "_response_ms" in response2._hidden_params + total_time_ms = response2._hidden_params["_response_ms"] + assert response2._hidden_params["litellm_overhead_time_ms"] > 0 and response2._hidden_params["litellm_overhead_time_ms"] < total_time_ms \ No newline at end of file