diff --git a/litellm/llms/custom_httpx/llm_http_handler.py b/litellm/llms/custom_httpx/llm_http_handler.py index 46ed72115cb..814bc20ce7e 100644 --- a/litellm/llms/custom_httpx/llm_http_handler.py +++ b/litellm/llms/custom_httpx/llm_http_handler.py @@ -303,7 +303,9 @@ class BaseLLMHTTPHandler: logging_obj=logging_obj, signed_json_body=signed_json_body, ) - return provider_config.transform_response( + # Time response translation + response_translation_start = time.perf_counter() + result = provider_config.transform_response( model=model, raw_response=response, model_response=model_response, @@ -316,6 +318,10 @@ class BaseLLMHTTPHandler: encoding=encoding, json_mode=json_mode, ) + response_translation_end = time.perf_counter() + response_translation_time_ms = (response_translation_end - response_translation_start) * 1000 + logging_obj.model_call_details["response_translation_time_ms"] = response_translation_time_ms + return result def completion( self, @@ -538,7 +544,9 @@ class BaseLLMHTTPHandler: litellm_params=litellm_params, logging_obj=logging_obj, ) - return provider_config.transform_response( + # Time response translation + response_translation_start = time.perf_counter() + result = provider_config.transform_response( model=model, raw_response=response, model_response=model_response, @@ -551,6 +559,10 @@ class BaseLLMHTTPHandler: encoding=encoding, json_mode=json_mode, ) + response_translation_end = time.perf_counter() + response_translation_time_ms = (response_translation_end - response_translation_start) * 1000 + logging_obj.model_call_details["response_translation_time_ms"] = response_translation_time_ms + return result def make_sync_call( self, @@ -596,6 +608,8 @@ class BaseLLMHTTPHandler: ) if fake_stream is True: + # Time response translation + response_translation_start = time.perf_counter() model_response: ModelResponse = provider_config.transform_response( model=model, raw_response=response, @@ -608,6 +622,9 @@ class BaseLLMHTTPHandler: encoding=None, json_mode=json_mode, ) + response_translation_end = time.perf_counter() + response_translation_time_ms = (response_translation_end - response_translation_start) * 1000 + logging_obj.model_call_details["response_translation_time_ms"] = response_translation_time_ms completion_stream: Any = MockResponseIterator( model_response=model_response, json_mode=json_mode @@ -734,6 +751,8 @@ class BaseLLMHTTPHandler: ) if fake_stream is True: + # Time response translation + response_translation_start = time.perf_counter() model_response: ModelResponse = provider_config.transform_response( model=model, raw_response=response, @@ -746,6 +765,9 @@ class BaseLLMHTTPHandler: encoding=None, json_mode=json_mode, ) + response_translation_end = time.perf_counter() + response_translation_time_ms = (response_translation_end - response_translation_start) * 1000 + logging_obj.model_call_details["response_translation_time_ms"] = response_translation_time_ms completion_stream: Any = MockResponseIterator( model_response=model_response, json_mode=json_mode diff --git a/tests/test_litellm/llms/custom_httpx/test_response_translation_timing.py b/tests/test_litellm/llms/custom_httpx/test_response_translation_timing.py new file mode 100644 index 00000000000..11c8e74289c --- /dev/null +++ b/tests/test_litellm/llms/custom_httpx/test_response_translation_timing.py @@ -0,0 +1,220 @@ +""" +Tests for response translation timing tracking. + +Verifies that response_translation_time_ms is correctly stored in model_call_details +when transform_response is called during completion. +""" + +import os +import sys +import time +from unittest.mock import Mock, patch + +import pytest + +sys.path.insert(0, os.path.abspath("../../../../..")) + +from litellm.llms.custom_httpx.llm_http_handler import BaseLLMHTTPHandler +from litellm.llms.base_llm.chat.transformation import BaseConfig +from litellm.types.utils import ModelResponse + + +class TestResponseTranslationTiming: + """Test suite for response translation timing tracking.""" + + def test_response_translation_time_is_tracked(self): + """ + Test that response_translation_time_ms is stored in model_call_details + when transform_response completes successfully. + """ + handler = BaseLLMHTTPHandler() + + # Create a mock config that simulates work during transform_response + mock_config = Mock(spec=BaseConfig) + + # Simulate a transform_response that takes measurable time + def transform_response_with_delay(*args, **kwargs): + time.sleep(0.005) # 5ms delay to ensure measurable time + return ModelResponse() + + mock_config.transform_response = transform_response_with_delay + mock_config.transform_request = Mock(return_value={"model": "gpt-4", "messages": []}) + mock_config.get_complete_url = Mock(return_value="https://api.openai.com/v1/chat/completions") + mock_config.sign_request = Mock(return_value=({}, None)) + mock_config.validate_environment = Mock(return_value={}) + mock_config.should_fake_stream = Mock(return_value=False) + mock_config.max_retry_on_unprocessable_entity_error = 1 + mock_config.should_retry_llm_api_inside_llm_translation_on_http_error = Mock(return_value=False) + mock_config.get_error_class = Mock(side_effect=Exception("No error class")) + + # Mock HTTP client and response + from litellm.llms.custom_httpx.http_handler import HTTPHandler + mock_client = Mock(spec=HTTPHandler) + mock_response = Mock() + mock_response.status_code = 200 + mock_response.json.return_value = { + "id": "chatcmpl-123", + "choices": [{"message": {"role": "assistant", "content": "Hello"}}], + "usage": {"prompt_tokens": 10, "completion_tokens": 5, "total_tokens": 15}, + } + mock_client.post = Mock(return_value=mock_response) + + # Create logging object to capture timing + mock_logging_obj = Mock() + mock_logging_obj.model_call_details = {} + mock_logging_obj.update_environment_variables = Mock() + mock_logging_obj.pre_call = Mock() + mock_logging_obj.stream = False + + # Execute completion + handler.completion( + model="gpt-4", + messages=[], + api_base="https://api.openai.com/v1/chat/completions", + custom_llm_provider="openai", + model_response=ModelResponse(), + encoding=None, + logging_obj=mock_logging_obj, + optional_params={}, + timeout=30.0, + litellm_params={}, + acompletion=False, + stream=False, + fake_stream=False, + headers={}, + client=mock_client, + provider_config=mock_config, + ) + + # Verify timing was tracked + assert "response_translation_time_ms" in mock_logging_obj.model_call_details + translation_time = mock_logging_obj.model_call_details["response_translation_time_ms"] + + # Verify it's a numeric value + assert isinstance(translation_time, (int, float)) + + # Verify it's positive (should be at least 5ms due to our delay) + assert translation_time > 0 + assert translation_time >= 4.0 # Allow some margin for timing variance + + def test_response_translation_time_is_zero_for_instant_transform(self): + """ + Test that response_translation_time_ms is still tracked even when + transform_response is very fast (near-zero time). + """ + handler = BaseLLMHTTPHandler() + + mock_config = Mock(spec=BaseConfig) + # Very fast transform_response (no delay) + mock_config.transform_response = Mock(return_value=ModelResponse()) + mock_config.transform_request = Mock(return_value={"model": "gpt-4", "messages": []}) + mock_config.get_complete_url = Mock(return_value="https://api.openai.com/v1/chat/completions") + mock_config.sign_request = Mock(return_value=({}, None)) + mock_config.validate_environment = Mock(return_value={}) + mock_config.should_fake_stream = Mock(return_value=False) + mock_config.max_retry_on_unprocessable_entity_error = 1 + mock_config.should_retry_llm_api_inside_llm_translation_on_http_error = Mock(return_value=False) + mock_config.get_error_class = Mock(side_effect=Exception("No error class")) + + from litellm.llms.custom_httpx.http_handler import HTTPHandler + mock_client = Mock(spec=HTTPHandler) + mock_response = Mock() + mock_response.status_code = 200 + mock_response.json.return_value = { + "id": "chatcmpl-123", + "choices": [{"message": {"role": "assistant", "content": "Hello"}}], + "usage": {"prompt_tokens": 10, "completion_tokens": 5, "total_tokens": 15}, + } + mock_client.post = Mock(return_value=mock_response) + + mock_logging_obj = Mock() + mock_logging_obj.model_call_details = {} + mock_logging_obj.update_environment_variables = Mock() + mock_logging_obj.pre_call = Mock() + mock_logging_obj.stream = False + + handler.completion( + model="gpt-4", + messages=[], + api_base="https://api.openai.com/v1/chat/completions", + custom_llm_provider="openai", + model_response=ModelResponse(), + encoding=None, + logging_obj=mock_logging_obj, + optional_params={}, + timeout=30.0, + litellm_params={}, + acompletion=False, + stream=False, + fake_stream=False, + headers={}, + client=mock_client, + provider_config=mock_config, + ) + + # Verify timing is still tracked even for fast operations + assert "response_translation_time_ms" in mock_logging_obj.model_call_details + translation_time = mock_logging_obj.model_call_details["response_translation_time_ms"] + assert isinstance(translation_time, (int, float)) + # Should be >= 0 (can be very small but should be tracked) + assert translation_time >= 0 + + def test_response_translation_time_not_set_on_transform_error(self): + """ + Test that response_translation_time_ms is not set if transform_response + raises an exception before completion. + """ + handler = BaseLLMHTTPHandler() + + mock_config = Mock(spec=BaseConfig) + # transform_response that raises an error + mock_config.transform_response = Mock(side_effect=ValueError("Transform error")) + mock_config.transform_request = Mock(return_value={"model": "gpt-4", "messages": []}) + mock_config.get_complete_url = Mock(return_value="https://api.openai.com/v1/chat/completions") + mock_config.sign_request = Mock(return_value=({}, None)) + mock_config.validate_environment = Mock(return_value={}) + mock_config.should_fake_stream = Mock(return_value=False) + mock_config.max_retry_on_unprocessable_entity_error = 1 + mock_config.should_retry_llm_api_inside_llm_translation_on_http_error = Mock(return_value=False) + mock_config.get_error_class = Mock(side_effect=Exception("No error class")) + + from litellm.llms.custom_httpx.http_handler import HTTPHandler + mock_client = Mock(spec=HTTPHandler) + mock_response = Mock() + mock_response.status_code = 200 + mock_response.json.return_value = { + "id": "chatcmpl-123", + "choices": [{"message": {"role": "assistant", "content": "Hello"}}], + "usage": {"prompt_tokens": 10, "completion_tokens": 5, "total_tokens": 15}, + } + mock_client.post = Mock(return_value=mock_response) + + mock_logging_obj = Mock() + mock_logging_obj.model_call_details = {} + mock_logging_obj.update_environment_variables = Mock() + mock_logging_obj.pre_call = Mock() + mock_logging_obj.stream = False + + # Call should raise error + with pytest.raises(ValueError, match="Transform error"): + handler.completion( + model="gpt-4", + messages=[], + api_base="https://api.openai.com/v1/chat/completions", + custom_llm_provider="openai", + model_response=ModelResponse(), + encoding=None, + logging_obj=mock_logging_obj, + optional_params={}, + timeout=30.0, + litellm_params={}, + acompletion=False, + stream=False, + fake_stream=False, + headers={}, + client=mock_client, + provider_config=mock_config, + ) + + # Verify timing was not set due to error + assert "response_translation_time_ms" not in mock_logging_obj.model_call_details diff --git a/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py b/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py index 7a56d662fee..5504aee3cac 100644 --- a/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py +++ b/tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py @@ -830,6 +830,89 @@ def test_get_logging_payload_extracts_request_translation_time_from_model_call_d ), f"Expected 15.5, got {overhead_breakdown.get('request_translation_time_ms')}" +@patch("litellm.proxy.proxy_server.master_key", None) +@patch("litellm.proxy.proxy_server.general_settings", {}) +def test_get_logging_payload_extracts_response_translation_time_from_model_call_details(): + """ + Integration test: Verify that response_translation_time_ms stored in + logging_obj.model_call_details gets extracted and included in overhead_breakdown. + + This tests the full flow: + 1. response_translation_time_ms is stored in model_call_details (by llm_http_handler) + 2. get_logging_payload extracts it from model_call_details + 3. It's included in overhead_breakdown in the metadata + """ + from litellm.litellm_core_utils.litellm_logging import ( + Logging as LiteLLMLoggingObj, + ) + + # Create a logging_obj with response_translation_time_ms in model_call_details + # (simulating what llm_http_handler does) + logging_obj = LiteLLMLoggingObj( + model="gpt-3.5-turbo", + messages=[{"role": "user", "content": "test"}], + stream=False, + call_type="completion", + start_time=None, + litellm_call_id="test-call-id", + function_id="test-function-id", + ) + + # Simulate the timing being stored (as done in llm_http_handler.py) + logging_obj.model_call_details["response_translation_time_ms"] = 12.7 + + # Create kwargs with the logging_obj + kwargs = { + "model": "gpt-3.5-turbo", + "logging_obj": logging_obj, + "litellm_params": { + "metadata": { + "user_api_key": "sk-test-key", + } + }, + "call_type": "completion", + } + + response_obj = { + "id": "test-response-456", + "choices": [{"message": {"content": "Hello!"}}], + "usage": { + "total_tokens": 100, + "prompt_tokens": 50, + "completion_tokens": 50, + }, + } + + start_time = datetime.datetime.now(timezone.utc) + end_time = datetime.datetime.now(timezone.utc) + + payload = get_logging_payload( + kwargs=kwargs, + response_obj=response_obj, + start_time=start_time, + end_time=end_time, + ) + + # Parse the metadata JSON string + metadata_json = payload.get("metadata") + assert metadata_json is not None, "metadata should not be None" + + metadata = json.loads(metadata_json) + + # Verify overhead_breakdown exists and contains response_translation_time_ms + overhead_breakdown = metadata.get("overhead_breakdown") + assert overhead_breakdown is not None, "overhead_breakdown should be present" + assert isinstance(overhead_breakdown, dict), "overhead_breakdown should be a dict" + + assert ( + "response_translation_time_ms" in overhead_breakdown + ), "response_translation_time_ms should be in overhead_breakdown" + + assert ( + overhead_breakdown["response_translation_time_ms"] == 12.7 + ), f"Expected 12.7, got {overhead_breakdown.get('response_translation_time_ms')}" + + @patch("litellm.proxy.proxy_server.master_key", None) @patch("litellm.proxy.proxy_server.general_settings", {}) def test_get_logging_payload_extracts_overhead_breakdown_from_multiple_sources():