scriptoriumadmin/litellm
1
0
Fork 0
mirror of https://github.com/BerriAI/litellm.git synced 2026-09-10 22:41:41 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 83

feat: implement response translation time tracking

Browse source 
- Add response_translation_time_ms tracking in BaseLLMHTTPHandler
- Instrument all 4 transform_response() call sites:
  * async_completion() path
  * completion() path
  * make_sync_call() fake_stream path
  * make_async_call() fake_stream path
- Follow exact same pattern as request_translation_time_ms
- Store timing in logging_obj.model_call_details
- Add comprehensive unit tests (3 test cases)
- Add integration test for full data flow
- All tests pass, no functionality changes

Covers providers using BaseLLMHTTPHandler (HTTP-based with transformation classes).
Extraction already handled by _extract_overhead_breakdown() helper function.
This commit is contained in:
Alexsander Hamir 2026-02-03 14:54:37 -08:00
parent bc3d55d876
commit 37d79d6e4c
3 changed files with 327 additions and 2 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

26
litellm/llms/custom_httpx/llm_http_handler.py
View file

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

220
tests/test_litellm/llms/custom_httpx/test_response_translation_timing.py Normal file
View file

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

83
tests/test_litellm/proxy/spend_tracking/test_spend_tracking_utils.py
View file

@ -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():