From 2a81c65671daf2bea890a365ffb96a2ef65c90e8 Mon Sep 17 00:00:00 2001 From: Alexsander Hamir Date: Tue, 3 Feb 2026 14:22:28 -0800 Subject: [PATCH] feat: Add request translation time tracking with comprehensive tests - Implement request_translation_time_ms tracking in BaseLLMHTTPHandler - Use time.perf_counter() for accurate timing measurements - Add comprehensive test suite covering: * Normal timing tracking with measurable delay * Fast transform operations (near-zero time) * Error handling (timing not set on transform errors) - Tests follow professional patterns with proper structure and edge cases --- litellm/llms/custom_httpx/llm_http_handler.py | 6 + .../test_request_translation_timing.py | 200 ++++++++++++++++++ 2 files changed, 206 insertions(+) create mode 100644 tests/test_litellm/llms/custom_httpx/test_request_translation_timing.py diff --git a/litellm/llms/custom_httpx/llm_http_handler.py b/litellm/llms/custom_httpx/llm_http_handler.py index d2ea7e872a2..46ed72115cb 100644 --- a/litellm/llms/custom_httpx/llm_http_handler.py +++ b/litellm/llms/custom_httpx/llm_http_handler.py @@ -1,4 +1,5 @@ import json +import time from typing import ( TYPE_CHECKING, Any, @@ -379,6 +380,8 @@ class BaseLLMHTTPHandler: litellm_params=litellm_params, ) + # Time request translation + request_translation_start = time.perf_counter() data = provider_config.transform_request( model=model, messages=messages, @@ -386,6 +389,9 @@ class BaseLLMHTTPHandler: litellm_params=litellm_params, headers=headers, ) + request_translation_end = time.perf_counter() + request_translation_time_ms = (request_translation_end - request_translation_start) * 1000 + logging_obj.model_call_details["request_translation_time_ms"] = request_translation_time_ms if extra_body is not None: data = {**data, **extra_body} diff --git a/tests/test_litellm/llms/custom_httpx/test_request_translation_timing.py b/tests/test_litellm/llms/custom_httpx/test_request_translation_timing.py new file mode 100644 index 00000000000..948c7aa331f --- /dev/null +++ b/tests/test_litellm/llms/custom_httpx/test_request_translation_timing.py @@ -0,0 +1,200 @@ +""" +Tests for request translation timing tracking. + +Verifies that request_translation_time_ms is correctly stored in model_call_details +when transform_request 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 TestRequestTranslationTiming: + """Test suite for request translation timing tracking.""" + + def test_request_translation_time_is_tracked(self): + """ + Test that request_translation_time_ms is stored in model_call_details + when transform_request completes successfully. + """ + handler = BaseLLMHTTPHandler() + + # Create a mock config that simulates work during transform_request + mock_config = Mock(spec=BaseConfig) + + # Simulate a transform_request that takes measurable time + def transform_with_delay(*args, **kwargs): + time.sleep(0.005) # 5ms delay to ensure measurable time + return {"model": "gpt-4", "messages": []} + + mock_config.transform_request = transform_with_delay + 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_config.transform_response = Mock(return_value=ModelResponse()) + + # 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 "request_translation_time_ms" in mock_logging_obj.model_call_details + translation_time = mock_logging_obj.model_call_details["request_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_request_translation_time_is_zero_for_instant_transform(self): + """ + Test that request_translation_time_ms is still tracked even when + transform_request is very fast (near-zero time). + """ + handler = BaseLLMHTTPHandler() + + mock_config = Mock(spec=BaseConfig) + # Very fast transform_request (no 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_config.transform_response = Mock(return_value=ModelResponse()) + + 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 "request_translation_time_ms" in mock_logging_obj.model_call_details + translation_time = mock_logging_obj.model_call_details["request_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_request_translation_time_not_set_on_transform_error(self): + """ + Test that request_translation_time_ms is not set if transform_request + raises an exception before completion. + """ + handler = BaseLLMHTTPHandler() + + mock_config = Mock(spec=BaseConfig) + # transform_request that raises an error + mock_config.transform_request = Mock(side_effect=ValueError("Transform error")) + mock_config.get_complete_url = Mock(return_value="https://api.openai.com/v1/chat/completions") + mock_config.validate_environment = Mock(return_value={}) + + mock_logging_obj = Mock() + mock_logging_obj.model_call_details = {} + + # 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(), + provider_config=mock_config, + ) + + # Verify timing was not set due to error + assert "request_translation_time_ms" not in mock_logging_obj.model_call_details