[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

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

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,

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

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

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

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