diff --git a/src/tests/test_request_stats.py b/src/tests/test_request_stats.py new file mode 100644 index 000000000..55eff0f50 --- /dev/null +++ b/src/tests/test_request_stats.py @@ -0,0 +1,71 @@ +"""Unit tests for RequestStatsMonitor completion accounting. + +`on_request_complete` is the only place avg_latency is written. It must +use the caller-supplied timestamp (so a delayed monitor call does not +inflate the sample) and must drop per-request bookkeeping so the +(engine_url, request_id) maps cannot grow without bound. +""" + +import pytest + +from vllm_router.stats.request_stats import ( + RequestStatsMonitor, + SingletonMeta, + initialize_request_stats_monitor, +) + + +@pytest.fixture +def monitor(): + if RequestStatsMonitor in SingletonMeta._instances: + del SingletonMeta._instances[RequestStatsMonitor] + mon = initialize_request_stats_monitor(sliding_window_size=60.0) + yield mon + if RequestStatsMonitor in SingletonMeta._instances: + del SingletonMeta._instances[RequestStatsMonitor] + + +URL = "http://10.0.0.1:8000" + + +def test_avg_latency_uses_the_supplied_completion_timestamp(monitor): + """A later wall-clock read must not change the recorded latency. + + process_request() passes end_time into on_request_complete; using + time.time() inside the monitor would add whatever delay sits between + that capture and the method body. + """ + monitor.on_new_request(URL, "req-1", timestamp=100.0) + monitor.on_request_response(URL, "req-1", timestamp=100.2) + monitor.on_request_complete(URL, "req-1", timestamp=101.5) + + stats = monitor.get_request_stats(current_time=101.5) + assert stats[URL].avg_latency == pytest.approx(1.5) + assert stats[URL].avg_decoding_length == pytest.approx(1.3) + + +def test_completed_request_is_dropped_from_per_request_maps(monitor): + monitor.on_new_request(URL, "req-1", timestamp=10.0) + monitor.on_request_response(URL, "req-1", timestamp=10.1) + assert (URL, "req-1") in monitor.request_start_time + assert (URL, "req-1") in monitor.first_token_time + + monitor.on_request_complete(URL, "req-1", timestamp=11.0) + assert (URL, "req-1") not in monitor.request_start_time + assert (URL, "req-1") not in monitor.first_token_time + + +def test_complete_without_start_does_not_raise(monitor): + monitor.on_request_complete(URL, "never-seen", timestamp=1.0) + stats = monitor.get_request_stats(current_time=1.0) + assert stats[URL].finished_requests == 1 + assert stats[URL].avg_latency == -1 + assert stats[URL].avg_decoding_length == -1 + + +def test_complete_before_first_token_leaves_decoding_length_unset(monitor): + monitor.on_new_request(URL, "req-1", timestamp=10.0) + monitor.on_request_complete(URL, "req-1", timestamp=10.4) + stats = monitor.get_request_stats(current_time=10.4) + assert stats[URL].avg_latency == pytest.approx(0.4) + assert stats[URL].avg_decoding_length == -1 diff --git a/src/vllm_router/stats/request_stats.py b/src/vllm_router/stats/request_stats.py index f0409b912..ba2fb7a94 100644 --- a/src/vllm_router/stats/request_stats.py +++ b/src/vllm_router/stats/request_stats.py @@ -11,7 +11,6 @@ # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. -import time from collections import deque from dataclasses import dataclass from typing import Deque, Dict, Tuple @@ -216,9 +215,21 @@ def on_request_complete(self, engine_url: str, request_id: str, timestamp: float ) self.finished_requests[engine_url] += 1 - if request_start_time := self.request_start_time.get((engine_url, request_id)): + key = (engine_url, request_id) + request_start_time = self.request_start_time.pop(key, None) + first_token_time = self.first_token_time.pop(key, None) + if request_start_time is not None: self.latency_monitors[engine_url].update( - timestamp, time.time() - request_start_time + timestamp, timestamp - request_start_time + ) + if first_token_time is not None: + if engine_url not in self.decoding_length_monitors: + self.decoding_length_monitors[engine_url] = MovingAverageMonitor( + self.sliding_window_size + ) + # Field comment: time from first token to completion. + self.decoding_length_monitors[engine_url].update( + timestamp, timestamp - first_token_time ) def on_request_swapped(self, engine_url: str, request_id: str, timestamp: float):