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
This commit is contained in:
Alexsander Hamir 2026-02-03 14:22:28 -08:00
parent d86346c65b
commit 2a81c65671
2 changed files with 206 additions and 0 deletions

View file

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

View file

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