|
| 1 | +""" |
| 2 | +Unit tests for verifying that latency is correctly recorded in pl_client.run |
| 3 | +Tests the fix for the issue where request_start_time and request_end_time were being set to the same value. |
| 4 | +""" |
| 5 | + |
| 6 | +import asyncio |
| 7 | +import time |
| 8 | +from unittest.mock import MagicMock, patch |
| 9 | + |
| 10 | +import pytest |
| 11 | + |
| 12 | +from promptlayer import AsyncPromptLayer, PromptLayer |
| 13 | +from promptlayer.promptlayer_mixins import PromptLayerMixin |
| 14 | + |
| 15 | + |
| 16 | +class TestLatencyRecording: |
| 17 | + """Test suite for latency recording functionality""" |
| 18 | + |
| 19 | + def test_prepare_track_request_kwargs_with_timestamps(self): |
| 20 | + """Test that _prepare_track_request_kwargs correctly uses provided timestamps""" |
| 21 | + |
| 22 | + # Arrange |
| 23 | + api_key = "test_api_key" |
| 24 | + request_params = { |
| 25 | + "function_name": "test_function", |
| 26 | + "provider": "openai", |
| 27 | + "function_kwargs": {"model": "gpt-4"}, |
| 28 | + "prompt_blueprint": {"id": 123, "version": 1}, |
| 29 | + } |
| 30 | + tags = ["test"] |
| 31 | + input_variables = {"query": "test"} |
| 32 | + group_id = None |
| 33 | + |
| 34 | + # Create distinct timestamps with 2 second difference |
| 35 | + start_time = 1000.0 |
| 36 | + end_time = 1002.0 |
| 37 | + |
| 38 | + # Act |
| 39 | + result = PromptLayerMixin._prepare_track_request_kwargs( |
| 40 | + api_key=api_key, |
| 41 | + request_params=request_params, |
| 42 | + tags=tags, |
| 43 | + input_variables=input_variables, |
| 44 | + group_id=group_id, |
| 45 | + request_start_time=start_time, |
| 46 | + request_end_time=end_time, |
| 47 | + ) |
| 48 | + |
| 49 | + # Assert |
| 50 | + assert result["request_start_time"] == start_time, "Start time should match provided value" |
| 51 | + assert result["request_end_time"] == end_time, "End time should match provided value" |
| 52 | + |
| 53 | + # Calculate latency |
| 54 | + latency = result["request_end_time"] - result["request_start_time"] |
| 55 | + assert latency == 2.0, f"Latency should be 2.0 seconds, but got {latency}" |
| 56 | + |
| 57 | + def test_prepare_track_request_kwargs_without_timestamps(self): |
| 58 | + """Test backward compatibility when timestamps are not provided""" |
| 59 | + |
| 60 | + # Arrange |
| 61 | + api_key = "test_api_key" |
| 62 | + request_params = { |
| 63 | + "function_name": "test_function", |
| 64 | + "provider": "openai", |
| 65 | + "function_kwargs": {"model": "gpt-4"}, |
| 66 | + "prompt_blueprint": {"id": 123, "version": 1}, |
| 67 | + } |
| 68 | + |
| 69 | + # Act |
| 70 | + result = PromptLayerMixin._prepare_track_request_kwargs( |
| 71 | + api_key=api_key, |
| 72 | + request_params=request_params, |
| 73 | + tags=["test"], |
| 74 | + input_variables={"query": "test"}, |
| 75 | + group_id=None, |
| 76 | + ) |
| 77 | + |
| 78 | + # Assert - timestamps should be auto-generated and nearly identical (old buggy behavior) |
| 79 | + latency = result["request_end_time"] - result["request_start_time"] |
| 80 | + assert latency < 0.01, "Without provided timestamps, latency should be near-zero (backward compatibility)" |
| 81 | + |
| 82 | + @patch("promptlayer.promptlayer.track_request") |
| 83 | + @patch("promptlayer.templates.TemplateManager.get") |
| 84 | + def test_run_internal_captures_timing_correctly(self, mock_template_get, mock_track_request): |
| 85 | + """Test that _run_internal correctly captures timing before and after LLM call""" |
| 86 | + |
| 87 | + # Arrange |
| 88 | + mock_template_get.return_value = { |
| 89 | + "id": 1, |
| 90 | + "prompt_template": {"type": "chat", "messages": []}, |
| 91 | + "metadata": {"model": {"provider": "openai", "name": "gpt-4"}}, |
| 92 | + "llm_kwargs": {"model": "gpt-4"}, |
| 93 | + } |
| 94 | + |
| 95 | + # Create a mock LLM response |
| 96 | + mock_response = MagicMock() |
| 97 | + mock_response.model_dump = MagicMock(return_value={"choices": []}) |
| 98 | + |
| 99 | + # Create a mock request function that simulates delay |
| 100 | + def mock_request_function(**kwargs): |
| 101 | + time.sleep(0.5) # Simulate 500ms API call |
| 102 | + return mock_response |
| 103 | + |
| 104 | + # Mock the track request to capture the timing |
| 105 | + tracked_times = {} |
| 106 | + |
| 107 | + def capture_track_request(**kwargs): |
| 108 | + tracked_times["start"] = kwargs.get("request_start_time") |
| 109 | + tracked_times["end"] = kwargs.get("request_end_time") |
| 110 | + return {"request_id": "test_id", "prompt_blueprint": {}} |
| 111 | + |
| 112 | + mock_track_request.side_effect = capture_track_request |
| 113 | + |
| 114 | + client = PromptLayer(api_key="test_key") |
| 115 | + |
| 116 | + # Patch _prepare_llm_data to use our mock request function |
| 117 | + with patch.object(client, "_prepare_llm_data") as mock_prepare: |
| 118 | + mock_prepare.return_value = { |
| 119 | + "request_function": mock_request_function, |
| 120 | + "provider": "openai", |
| 121 | + "function_name": "test", |
| 122 | + "stream_function": None, |
| 123 | + "client_kwargs": {}, |
| 124 | + "function_kwargs": {}, |
| 125 | + "prompt_blueprint": {"id": 1, "version": 1, "metadata": {}}, |
| 126 | + } |
| 127 | + |
| 128 | + # Act |
| 129 | + client._run_internal(prompt_name="test_prompt", input_variables={}) |
| 130 | + |
| 131 | + # Assert |
| 132 | + assert "start" in tracked_times, "Start time should be tracked" |
| 133 | + assert "end" in tracked_times, "End time should be tracked" |
| 134 | + |
| 135 | + if tracked_times["start"] and tracked_times["end"]: |
| 136 | + latency = tracked_times["end"] - tracked_times["start"] |
| 137 | + # Should be at least 0.5 seconds (our simulated delay) |
| 138 | + assert latency >= 0.5, f"Latency should be at least 0.5 seconds, but got {latency}" |
| 139 | + # But shouldn't be more than 1 second |
| 140 | + assert latency < 1.0, f"Latency should be less than 1 second, but got {latency}" |
| 141 | + |
| 142 | + @pytest.mark.asyncio |
| 143 | + @patch("promptlayer.promptlayer.atrack_request") |
| 144 | + @patch("promptlayer.templates.AsyncTemplateManager.get") |
| 145 | + async def test_async_run_internal_captures_timing_correctly(self, mock_template_get, mock_atrack_request): |
| 146 | + """Test that async _run_internal correctly captures timing""" |
| 147 | + |
| 148 | + # Arrange |
| 149 | + mock_template_get.return_value = { |
| 150 | + "id": 1, |
| 151 | + "prompt_template": {"type": "chat", "messages": []}, |
| 152 | + "metadata": {"model": {"provider": "openai", "name": "gpt-4"}}, |
| 153 | + "llm_kwargs": {"model": "gpt-4"}, |
| 154 | + } |
| 155 | + |
| 156 | + # Create a mock LLM response |
| 157 | + mock_response = MagicMock() |
| 158 | + mock_response.model_dump = MagicMock(return_value={"choices": []}) |
| 159 | + |
| 160 | + # Create an async mock request function that simulates delay |
| 161 | + async def mock_request_function(**kwargs): |
| 162 | + await asyncio.sleep(0.5) # Simulate 500ms API call |
| 163 | + return mock_response |
| 164 | + |
| 165 | + # Mock the track request to capture the timing |
| 166 | + tracked_times = {} |
| 167 | + |
| 168 | + async def capture_track_request(**kwargs): |
| 169 | + tracked_times["start"] = kwargs.get("request_start_time") |
| 170 | + tracked_times["end"] = kwargs.get("request_end_time") |
| 171 | + return {"request_id": "test_id", "prompt_blueprint": {}} |
| 172 | + |
| 173 | + mock_atrack_request.side_effect = capture_track_request |
| 174 | + |
| 175 | + client = AsyncPromptLayer(api_key="test_key") |
| 176 | + |
| 177 | + # Patch _prepare_llm_data to use our mock request function |
| 178 | + with patch.object(client, "_prepare_llm_data") as mock_prepare: |
| 179 | + mock_prepare.return_value = { |
| 180 | + "request_function": mock_request_function, |
| 181 | + "provider": "openai", |
| 182 | + "function_name": "test", |
| 183 | + "stream_function": None, |
| 184 | + "client_kwargs": {}, |
| 185 | + "function_kwargs": {}, |
| 186 | + "prompt_blueprint": {"id": 1, "version": 1, "metadata": {}}, |
| 187 | + } |
| 188 | + |
| 189 | + # Act |
| 190 | + await client._run_internal(prompt_name="test_prompt", input_variables={}) |
| 191 | + |
| 192 | + # Assert |
| 193 | + assert "start" in tracked_times, "Start time should be tracked" |
| 194 | + assert "end" in tracked_times, "End time should be tracked" |
| 195 | + |
| 196 | + if tracked_times["start"] and tracked_times["end"]: |
| 197 | + latency = tracked_times["end"] - tracked_times["start"] |
| 198 | + # Should be at least 0.5 seconds (our simulated delay) |
| 199 | + assert latency >= 0.5, f"Latency should be at least 0.5 seconds, but got {latency}" |
| 200 | + # But shouldn't be more than 1 second |
| 201 | + assert latency < 1.0, f"Latency should be less than 1 second, but got {latency}" |
| 202 | + |
| 203 | + def test_streaming_captures_start_time(self): |
| 204 | + """Test that streaming mode correctly passes start_time to the stream handler""" |
| 205 | + |
| 206 | + # This test verifies that when stream=True, the start_time is captured |
| 207 | + # and passed to the stream_response function |
| 208 | + |
| 209 | + client = PromptLayer(api_key="test_key") |
| 210 | + |
| 211 | + # Mock the dependencies |
| 212 | + with patch("promptlayer.templates.TemplateManager.get") as mock_get, patch( |
| 213 | + "promptlayer.promptlayer.stream_response" |
| 214 | + ) as mock_stream: |
| 215 | + mock_get.return_value = { |
| 216 | + "id": 1, |
| 217 | + "prompt_template": {"type": "chat"}, |
| 218 | + "metadata": {"model": {"provider": "openai", "name": "gpt-4"}}, |
| 219 | + "llm_kwargs": {}, |
| 220 | + } |
| 221 | + |
| 222 | + # Mock the LLM request to return a generator (streaming response) |
| 223 | + def mock_generator(): |
| 224 | + yield {"chunk": 1} |
| 225 | + yield {"chunk": 2} |
| 226 | + |
| 227 | + with patch.object(client, "_prepare_llm_data") as mock_prepare: |
| 228 | + mock_prepare.return_value = { |
| 229 | + "request_function": lambda **k: mock_generator(), |
| 230 | + "provider": "openai", |
| 231 | + "function_name": "test", |
| 232 | + "stream_function": lambda x: x, |
| 233 | + "client_kwargs": {}, |
| 234 | + "function_kwargs": {}, |
| 235 | + "prompt_blueprint": {"id": 1, "version": 1, "metadata": {}}, |
| 236 | + } |
| 237 | + |
| 238 | + # Act |
| 239 | + client._run_internal(prompt_name="test", stream=True) |
| 240 | + |
| 241 | + # Assert that stream_response was called |
| 242 | + mock_stream.assert_called_once() |
| 243 | + |
| 244 | + # Get the after_stream callable that was passed |
| 245 | + call_args = mock_stream.call_args |
| 246 | + after_stream_callable = call_args[1]["after_stream"] |
| 247 | + |
| 248 | + # The callable should have access to request_start_time |
| 249 | + # This is verified by the structure of _create_track_request_callable |
| 250 | + assert callable(after_stream_callable) |
| 251 | + |
| 252 | + def test_latency_calculation_accuracy(self): |
| 253 | + """Test that latency calculation is accurate for various time differences""" |
| 254 | + |
| 255 | + test_cases = [ |
| 256 | + (1000.0, 1000.1, 0.1), # 100ms |
| 257 | + (1000.0, 1001.0, 1.0), # 1 second |
| 258 | + (1000.0, 1005.5, 5.5), # 5.5 seconds |
| 259 | + (1000.0, 1000.001, 0.001), # 1ms |
| 260 | + ] |
| 261 | + |
| 262 | + for start, end, expected_latency in test_cases: |
| 263 | + result = PromptLayerMixin._prepare_track_request_kwargs( |
| 264 | + api_key="test", |
| 265 | + request_params={ |
| 266 | + "function_name": "test", |
| 267 | + "provider": "openai", |
| 268 | + "function_kwargs": {}, |
| 269 | + "prompt_blueprint": {"id": 1, "version": 1}, |
| 270 | + }, |
| 271 | + tags=[], |
| 272 | + input_variables={}, |
| 273 | + group_id=None, |
| 274 | + request_start_time=start, |
| 275 | + request_end_time=end, |
| 276 | + ) |
| 277 | + |
| 278 | + actual_latency = result["request_end_time"] - result["request_start_time"] |
| 279 | + assert abs(actual_latency - expected_latency) < 0.0001, ( |
| 280 | + f"Expected latency {expected_latency}, got {actual_latency}" |
| 281 | + ) |
| 282 | + |
| 283 | + |
| 284 | +if __name__ == "__main__": |
| 285 | + # Run the tests |
| 286 | + pytest.main([__file__, "-v"]) |
0 commit comments