Skip to content

[Bugfix][Router] Use supplied timestamp for avg_latency and drop completed request maps - #1080

Open
nisaral wants to merge 2 commits into
vllm-project:mainfrom
nisaral:bugfix/request-stats-latency-timestamp
Open

[Bugfix][Router] Use supplied timestamp for avg_latency and drop completed request maps#1080
nisaral wants to merge 2 commits into
vllm-project:mainfrom
nisaral:bugfix/request-stats-latency-timestamp

Conversation

@nisaral

@nisaral nisaral commented Sep 7, 2026

Copy link
Copy Markdown

What

RequestStatsMonitor.on_request_complete recorded time.time() - start instead of timestamp - start, so avg_latency included monitor overhead and was untestable. Completed (engine_url, request_id) entries were also left in request_start_time and first_token_time.

Why

process_request() already captures end_time and passes it in. TTFT already uses the supplied timestamp; latency should too.

Test

src/tests/test_request_stats.py — latency equals the injected interval; maps are empty after complete; missing start is a no-op.

…t maps

Signed-off-by: Keyush nisar <nisarkeyush3@gmail.com>

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request addresses a memory leak in RequestStatsMonitor by popping completed requests from the tracking maps and corrects the latency calculation to use the provided timestamp instead of time.time(). It also introduces unit tests for these behaviors. The reviewer suggested updating decoding_length_monitors using the popped first_token_time so that avg_decoding_length is correctly calculated, along with adding corresponding assertions in the tests.

Comment on lines +219 to 224
request_start_time = self.request_start_time.pop(key, None)
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
)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

The decoding_length_monitors are never updated in the codebase, meaning avg_decoding_length will always return -1. Since first_token_time is popped here, we can use it to calculate the decoding length (timestamp - first_token_time) and update decoding_length_monitors accordingly.

        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, 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
                )
            self.decoding_length_monitors[engine_url].update(
                timestamp, timestamp - first_token_time
            )

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Taken. avg_decoding_length is documented as time from first token to completion, and popping first_token_time was discarding the only timestamp that can fill it. on_request_complete now updates decoding_length_monitors when a first-token time exists; requests that complete before the first token still leave the gauge at -1.

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)

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

Add an assertion to verify that avg_decoding_length is correctly calculated and updated.

Suggested change
assert stats[URL].avg_latency == pytest.approx(1.5)
assert stats[URL].avg_latency == pytest.approx(1.5)
assert stats[URL].avg_decoding_length == pytest.approx(1.3)

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added. The existing timestamps give decode duration 101.5 - 100.2 = 1.3, plus a case with no first token that stays at -1.

Signed-off-by: Keyush nisar <nisarkeyush3@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant