diff --git a/litellm-proxy-extras/litellm_proxy_extras/migrations/20260224201417_spend_logs_request_duration/migration.sql b/litellm-proxy-extras/litellm_proxy_extras/migrations/20260224201417_spend_logs_request_duration/migration.sql new file mode 100644 index 00000000000..604c1b16ff5 --- /dev/null +++ b/litellm-proxy-extras/litellm_proxy_extras/migrations/20260224201417_spend_logs_request_duration/migration.sql @@ -0,0 +1,2 @@ +-- AlterTable +ALTER TABLE "LiteLLM_SpendLogs" ADD COLUMN "request_duration_ms" INTEGER; \ No newline at end of file diff --git a/litellm-proxy-extras/litellm_proxy_extras/schema.prisma b/litellm-proxy-extras/litellm_proxy_extras/schema.prisma index 4af7484148c..5fa805e444e 100644 --- a/litellm-proxy-extras/litellm_proxy_extras/schema.prisma +++ b/litellm-proxy-extras/litellm_proxy_extras/schema.prisma @@ -477,6 +477,7 @@ model LiteLLM_SpendLogs { completion_tokens Int @default(0) startTime DateTime // Assuming start_time is a DateTime field endTime DateTime // Assuming end_time is a DateTime field + request_duration_ms Int? completionStartTime DateTime? // Assuming completionStartTime is a DateTime field model String @default("") model_id String? @default("") // the model id stored in proxy model db diff --git a/litellm/proxy/_types.py b/litellm/proxy/_types.py index 4053d9d077b..96c5265c0e6 100644 --- a/litellm/proxy/_types.py +++ b/litellm/proxy/_types.py @@ -3105,6 +3105,7 @@ class SpendLogsPayload(TypedDict): response: Optional[Union[str, list, dict]] proxy_server_request: Optional[str] session_id: Optional[str] + request_duration_ms: Optional[int] status: Literal["success", "failure"] diff --git a/litellm/proxy/schema.prisma b/litellm/proxy/schema.prisma index 8f746b1f9c0..8498b131df8 100644 --- a/litellm/proxy/schema.prisma +++ b/litellm/proxy/schema.prisma @@ -477,6 +477,7 @@ model LiteLLM_SpendLogs { completion_tokens Int @default(0) startTime DateTime // Assuming start_time is a DateTime field endTime DateTime // Assuming end_time is a DateTime field + request_duration_ms Int? completionStartTime DateTime? // Assuming completionStartTime is a DateTime field model String @default("") model_id String? @default("") // the model id stored in proxy model db diff --git a/litellm/proxy/spend_tracking/spend_management_endpoints.py b/litellm/proxy/spend_tracking/spend_management_endpoints.py index b4aeda62004..5b58fbe70a0 100644 --- a/litellm/proxy/spend_tracking/spend_management_endpoints.py +++ b/litellm/proxy/spend_tracking/spend_management_endpoints.py @@ -1726,7 +1726,7 @@ async def ui_view_spend_logs( # noqa: PLR0915 ) # Validate sort_by and sort_order - valid_sort_fields = {"spend", "total_tokens", "startTime", "endTime"} + valid_sort_fields = {"spend", "total_tokens", "startTime", "endTime", "request_duration_ms"} if sort_by not in valid_sort_fields: raise ProxyException( message=f"Invalid sort_by: {sort_by}. Must be one of: {', '.join(sorted(valid_sort_fields))}", @@ -1939,7 +1939,8 @@ async def ui_view_spend_logs( # noqa: PLR0915 custom_llm_provider, api_base, "user", metadata, cache_hit, cache_key, request_tags, team_id, organization_id, end_user, requester_ip_address, - session_id, status, mcp_namespaced_tool_name, agent_id + session_id, status, mcp_namespaced_tool_name, agent_id, + COALESCE(request_duration_ms, (EXTRACT(EPOCH FROM ("endTime" - "startTime")) * 1000)::INTEGER) AS request_duration_ms FROM "LiteLLM_SpendLogs" WHERE {" AND ".join(sql_conditions)} ORDER BY {_sql_col} {_sql_dir} diff --git a/litellm/proxy/spend_tracking/spend_tracking_utils.py b/litellm/proxy/spend_tracking/spend_tracking_utils.py index d517c76a08c..05dbb8ed71e 100644 --- a/litellm/proxy/spend_tracking/spend_tracking_utils.py +++ b/litellm/proxy/spend_tracking/spend_tracking_utils.py @@ -447,6 +447,7 @@ def get_logging_payload( # noqa: PLR0915 kwargs=kwargs, standard_logging_payload=standard_logging_payload, ), + request_duration_ms=_get_request_duration_ms(start_time, end_time), status=_get_status_for_spend_log( metadata=metadata, ), @@ -496,6 +497,16 @@ def _get_session_id_for_spend_log( return str(uuid.uuid4()) +def _get_request_duration_ms( + start_time: datetime, end_time: datetime +) -> Optional[int]: + """Compute request duration in milliseconds from start and end times.""" + try: + return int((end_time - start_time).total_seconds() * 1000) + except Exception: + return None + + def _ensure_datetime_utc(timestamp: datetime) -> datetime: """Helper to ensure datetime is in UTC""" timestamp = timestamp.astimezone(timezone.utc) diff --git a/schema.prisma b/schema.prisma index 4af7484148c..5fa805e444e 100644 --- a/schema.prisma +++ b/schema.prisma @@ -477,6 +477,7 @@ model LiteLLM_SpendLogs { completion_tokens Int @default(0) startTime DateTime // Assuming start_time is a DateTime field endTime DateTime // Assuming end_time is a DateTime field + request_duration_ms Int? completionStartTime DateTime? // Assuming completionStartTime is a DateTime field model String @default("") model_id String? @default("") // the model id stored in proxy model db diff --git a/tests/test_litellm/proxy/spend_tracking/test_spend_management_endpoints.py b/tests/test_litellm/proxy/spend_tracking/test_spend_management_endpoints.py index c3639e88f6e..e439dfd693c 100644 --- a/tests/test_litellm/proxy/spend_tracking/test_spend_management_endpoints.py +++ b/tests/test_litellm/proxy/spend_tracking/test_spend_management_endpoints.py @@ -274,6 +274,7 @@ ignored_keys = [ "endTime", "completionStartTime", "endTime", + "request_duration_ms", "organization_id", "metadata.model_map_information", "metadata.usage_object", @@ -606,6 +607,82 @@ async def test_ui_view_spend_logs_sort_validation_errors( app.dependency_overrides.pop(ps.user_api_key_auth, None) +@pytest.mark.asyncio +async def test_ui_view_spend_logs_sort_by_request_duration_ms(client, monkeypatch): + """Test that request_duration_ms is accepted as a valid sort_by field.""" + base_logs = [ + { + "request_id": "req_fast", + "api_key": "sk-test-key", + "user": "user1", + "spend": 0.10, + "total_tokens": 100, + "request_duration_ms": 100, + "startTime": "2025-01-01T00:00:00+00:00", + "endTime": "2025-01-01T00:00:00.100000+00:00", + "model": "gpt-4", + }, + { + "request_id": "req_slow", + "api_key": "sk-test-key", + "user": "user1", + "spend": 0.05, + "total_tokens": 50, + "request_duration_ms": 5000, + "startTime": "2025-01-01T00:00:01+00:00", + "endTime": "2025-01-01T00:00:06+00:00", + "model": "gpt-4", + }, + ] + + async def mock_count(*args, **kwargs): + return len(base_logs) + + async def mock_query_raw(sql_query, *params): + reverse = "DESC" in sql_query + sorted_logs = sorted( + base_logs, key=lambda x: x.get("request_duration_ms", 0), reverse=reverse + ) + page_size = params[-2] if len(params) >= 2 else 50 + skip = params[-1] if len(params) >= 1 else 0 + return sorted_logs[skip : skip + page_size] + + class MockPrismaClient: + def __init__(self): + self.db = MagicMock() + self.db.litellm_spendlogs = MagicMock() + self.db.litellm_spendlogs.count = AsyncMock(side_effect=mock_count) + self.db.query_raw = AsyncMock(side_effect=mock_query_raw) + + monkeypatch.setattr("litellm.proxy.proxy_server.prisma_client", MockPrismaClient()) + monkeypatch.setattr( + "litellm.proxy.spend_tracking.spend_management_endpoints._is_admin_view_safe", + lambda user_api_key_dict: True, + ) + app.dependency_overrides[ps.user_api_key_auth] = lambda: UserAPIKeyAuth( + user_role=LitellmUserRoles.PROXY_ADMIN, user_id="admin_user" + ) + + try: + response = client.get( + "/spend/logs/ui", + params={ + "start_date": "2024-12-25 00:00:00", + "end_date": "2025-01-02 23:59:59", + "sort_by": "request_duration_ms", + "sort_order": "asc", + }, + headers={"Authorization": "Bearer sk-test"}, + ) + + assert response.status_code == 200, response.text + data = response.json() + actual_ids = [log["request_id"] for log in data["data"]] + assert actual_ids == ["req_fast", "req_slow"] + finally: + app.dependency_overrides.pop(ps.user_api_key_auth, None) + + @pytest.mark.asyncio async def test_ui_view_spend_logs_with_team_id(client, monkeypatch): mock_spend_logs = [ 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 47a327f01f6..06a544e7f4d 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 @@ -20,6 +20,7 @@ from litellm.constants import LITELLM_TRUNCATED_PAYLOAD_FIELD, REDACTED_BY_LITEL from litellm.litellm_core_utils.safe_json_dumps import safe_dumps from litellm.proxy.spend_tracking.spend_tracking_utils import ( _get_proxy_server_request_for_spend_logs_payload, + _get_request_duration_ms, _get_response_for_spend_logs_payload, _get_spend_logs_metadata, _get_vector_store_request_for_spend_logs_payload, @@ -1232,3 +1233,50 @@ def test_get_logging_payload_handles_missing_retry_info_gracefully(): metadata.get("max_retries") is None ), "max_retries should be None when not provided" + +def test_get_request_duration_ms_normal(): + """Test that request duration is correctly computed in milliseconds.""" + start = datetime.datetime(2025, 1, 1, 0, 0, 0, tzinfo=timezone.utc) + end = datetime.datetime(2025, 1, 1, 0, 0, 2, 500000, tzinfo=timezone.utc) # 2.5s later + result = _get_request_duration_ms(start, end) + assert result == 2500 + + +def test_get_request_duration_ms_sub_millisecond(): + """Test that sub-millisecond durations are truncated to int.""" + start = datetime.datetime(2025, 1, 1, 0, 0, 0, 0, tzinfo=timezone.utc) + end = datetime.datetime(2025, 1, 1, 0, 0, 0, 500, tzinfo=timezone.utc) # 0.5ms + result = _get_request_duration_ms(start, end) + assert result == 0 + + +def test_get_request_duration_ms_zero(): + """Test that identical start and end times produce 0.""" + t = datetime.datetime(2025, 1, 1, 0, 0, 0, tzinfo=timezone.utc) + result = _get_request_duration_ms(t, t) + assert result == 0 + + +def test_get_logging_payload_includes_request_duration_ms(): + """Test that get_logging_payload populates request_duration_ms.""" + start_time = datetime.datetime(2025, 1, 1, 0, 0, 0, tzinfo=timezone.utc) + end_time = datetime.datetime(2025, 1, 1, 0, 0, 3, tzinfo=timezone.utc) # 3s later + + kwargs = { + "model": "gpt-4", + "litellm_params": {"api_base": "https://api.openai.com"}, + "standard_logging_object": None, + } + response_obj = {"usage": {"prompt_tokens": 10, "completion_tokens": 5, "total_tokens": 15}} + + with patch("litellm.proxy.proxy_server.master_key", None), \ + patch("litellm.proxy.proxy_server.general_settings", {}): + payload = get_logging_payload( + kwargs=kwargs, + response_obj=response_obj, + start_time=start_time, + end_time=end_time, + ) + + assert payload["request_duration_ms"] == 3000 +