From e087d0a25a188ccf1b238c087784e84989503a08 Mon Sep 17 00:00:00 2001 From: DavinciEvans Date: Tue, 23 Jun 2026 01:52:40 +0800 Subject: [PATCH 1/2] Add Prometheus counters for prefix cache queries and hits --- lmdeploy/messages.py | 2 ++ lmdeploy/metrics/loggers.py | 25 +++++++++++++++++++++ lmdeploy/metrics/stats.py | 8 +++++++ lmdeploy/pytorch/paging/scheduler.py | 3 +++ tests/test_lmdeploy/test_metrics_loggers.py | 16 ++++++++++++- 5 files changed, 53 insertions(+), 1 deletion(-) diff --git a/lmdeploy/messages.py b/lmdeploy/messages.py index 9486cc62b0..6580c150dd 100644 --- a/lmdeploy/messages.py +++ b/lmdeploy/messages.py @@ -663,6 +663,8 @@ class ScheduleMetrics: cached_blocks: int = 0 free_blocks: int = 0 prefix_cache_hit_rate: float = 0 + num_prefix_cache_query_tokens: int = 0 + num_prefix_cache_hit_tokens: int = 0 scheduler_tick: int = 0 diff --git a/lmdeploy/metrics/loggers.py b/lmdeploy/metrics/loggers.py index 258fa30318..86760e02f1 100644 --- a/lmdeploy/metrics/loggers.py +++ b/lmdeploy/metrics/loggers.py @@ -208,6 +208,22 @@ def __init__(self, model_name: str, max_model_len: int, dp_rank: int = 0): documentation='Number of generation tokens processed.', labelnames=labelnames).labels(*labelvalues) + # Prefix cache hit rate is derived in PromQL from these raw counters: + # rate(prefix_cache_hits_total) / rate(prefix_cache_queries_total) + self.counter_prefix_cache_queries = prometheus_client.Counter( + name='lmdeploy:prefix_cache_queries_total', + documentation='Number of tokens queried against the prefix cache.', + labelnames=labelnames).labels(*labelvalues) + + self.counter_prefix_cache_hits = prometheus_client.Counter( + name='lmdeploy:prefix_cache_hits_total', + documentation='Number of tokens served from the prefix cache.', + labelnames=labelnames).labels(*labelvalues) + + # engine-side stats are cumulative; track last seen values to emit deltas + self._last_prefix_cache_query_tokens = 0 + self._last_prefix_cache_hit_tokens = 0 + # Speculative decoding counters. Acceptance rate and mean acceptance # length are derived in PromQL from these raw counters. # rate(accepted_tokens) / rate(draft_tokens) @@ -386,6 +402,15 @@ def record_schedule(self, stats: SchedulerStats) -> None: self.gauge_gpu_cache_usage.set(stats.gpu_cache_usage) self.gauge_prefix_cache_hit_rate.set(stats.prefix_cache_hit_rate) + query_delta = stats.num_prefix_cache_query_tokens - self._last_prefix_cache_query_tokens + hit_delta = stats.num_prefix_cache_hit_tokens - self._last_prefix_cache_hit_tokens + if query_delta > 0: + self.counter_prefix_cache_queries.inc(query_delta) + if hit_delta > 0: + self.counter_prefix_cache_hits.inc(hit_delta) + self._last_prefix_cache_query_tokens = stats.num_prefix_cache_query_tokens + self._last_prefix_cache_hit_tokens = stats.num_prefix_cache_hit_tokens + def record_iteration(self, stats: IterationStats) -> None: """Report token-related metrics to prometheus.""" diff --git a/lmdeploy/metrics/stats.py b/lmdeploy/metrics/stats.py index 90b19d924f..378db8faac 100644 --- a/lmdeploy/metrics/stats.py +++ b/lmdeploy/metrics/stats.py @@ -39,6 +39,8 @@ class SchedulerStats: num_waiting_reqs: Engine core, requests queued waiting for execution. gpu_cache_usage: Fraction of GPU KV blocks utilized (0.0 to 1.0). prefix_cache_hit_rate: Prefix caching hit rate. + num_prefix_cache_query_tokens: Cumulative number of tokens queried against the prefix cache. + num_prefix_cache_hit_tokens: Cumulative number of tokens served from the prefix cache. """ # api server @@ -54,6 +56,8 @@ class SchedulerStats: num_waiting_reqs: int = 0 gpu_cache_usage: float = 0.0 prefix_cache_hit_rate: float = 0.0 + num_prefix_cache_query_tokens: int = 0 + num_prefix_cache_hit_tokens: int = 0 @property def num_failed_reqs(self) -> int: @@ -85,6 +89,8 @@ def __repr__(self): f' num_waiting_reqs={self.num_waiting_reqs},\n' f' gpu_cache_usage={self.gpu_cache_usage:.6f},\n' f' prefix_cache_hit_rate={self.prefix_cache_hit_rate:.6f},\n' + f' num_prefix_cache_query_tokens={self.num_prefix_cache_query_tokens},\n' + f' num_prefix_cache_hit_tokens={self.num_prefix_cache_hit_tokens},\n' ')') def update_from_schedule_metrics(self, scheduled_metrics: ScheduleMetrics): @@ -92,6 +98,8 @@ def update_from_schedule_metrics(self, scheduled_metrics: ScheduleMetrics): self.num_waiting_reqs = scheduled_metrics.waiting_seqs self.gpu_cache_usage = 1.0 - (scheduled_metrics.free_blocks / scheduled_metrics.total_blocks) self.prefix_cache_hit_rate = scheduled_metrics.prefix_cache_hit_rate + self.num_prefix_cache_query_tokens = scheduled_metrics.num_prefix_cache_query_tokens + self.num_prefix_cache_hit_tokens = scheduled_metrics.num_prefix_cache_hit_tokens class RequestStats: diff --git a/lmdeploy/pytorch/paging/scheduler.py b/lmdeploy/pytorch/paging/scheduler.py index 690a547e90..9ea1f04019 100644 --- a/lmdeploy/pytorch/paging/scheduler.py +++ b/lmdeploy/pytorch/paging/scheduler.py @@ -561,11 +561,14 @@ def collect_migration_done(self): @property def schedule_metrics(self): + prefix_cache_stats = self.block_trie.stats return ScheduleMetrics( active_seqs=self.num_running(), waiting_seqs=self.num_waiting() + self.num_ready(), total_blocks=self.block_manager.num_gpu_blocks, free_blocks=self.block_manager.get_num_free_gpu_blocks(), prefix_cache_hit_rate=self.block_trie.hit_rate(), + num_prefix_cache_query_tokens=prefix_cache_stats.num_query_tokens, + num_prefix_cache_hit_tokens=prefix_cache_stats.num_hit_tokens, scheduler_tick=self.scheduler_tick, ) diff --git a/tests/test_lmdeploy/test_metrics_loggers.py b/tests/test_lmdeploy/test_metrics_loggers.py index 69ba4db4e5..974e2b18f4 100644 --- a/tests/test_lmdeploy/test_metrics_loggers.py +++ b/tests/test_lmdeploy/test_metrics_loggers.py @@ -3,7 +3,7 @@ import pytest from lmdeploy.metrics.loggers import PrometheusStatLogger -from lmdeploy.metrics.stats import SpeculativeDecodingStats +from lmdeploy.metrics.stats import SchedulerStats, SpeculativeDecodingStats prometheus_client = pytest.importorskip('prometheus_client') @@ -42,3 +42,17 @@ def test_prometheus_stat_logger_records_specdecode_metrics(): position_labels = labels | {'position': '2'} assert _get_sample_value('lmdeploy:spec_decode_num_accepted_tokens_per_pos_total', position_labels) == 0 assert _get_sample_value('lmdeploy:spec_decode_per_position_accept_rate', position_labels) == 0 + + +def test_prometheus_stat_logger_records_prefix_cache_counters(): + logger = PrometheusStatLogger('test-prefix-model', max_model_len=16, dp_rank=0) + labels = {'model_name': 'test-prefix-model', 'engine': '0'} + + # engine-side stats are cumulative, so the logger must emit per-interval deltas + logger.record_schedule(SchedulerStats(num_prefix_cache_query_tokens=100, num_prefix_cache_hit_tokens=30)) + assert _get_sample_value('lmdeploy:prefix_cache_queries_total', labels) == 100 + assert _get_sample_value('lmdeploy:prefix_cache_hits_total', labels) == 30 + + logger.record_schedule(SchedulerStats(num_prefix_cache_query_tokens=250, num_prefix_cache_hit_tokens=80)) + assert _get_sample_value('lmdeploy:prefix_cache_queries_total', labels) == 250 + assert _get_sample_value('lmdeploy:prefix_cache_hits_total', labels) == 80 From 2c22d4431e28099eee4b813360e31d64a62e1603 Mon Sep 17 00:00:00 2001 From: DavinciEvans Date: Wed, 24 Jun 2026 02:35:31 +0800 Subject: [PATCH 2/2] Fix stale prefix cache hit rate metric --- lmdeploy/messages.py | 1 - lmdeploy/metrics/loggers.py | 42 ++++----------------- lmdeploy/metrics/stats.py | 4 -- lmdeploy/pytorch/paging/scheduler.py | 1 - tests/test_lmdeploy/test_metrics_loggers.py | 35 ++++++++++++----- 5 files changed, 33 insertions(+), 50 deletions(-) diff --git a/lmdeploy/messages.py b/lmdeploy/messages.py index 6580c150dd..080feedcb9 100644 --- a/lmdeploy/messages.py +++ b/lmdeploy/messages.py @@ -662,7 +662,6 @@ class ScheduleMetrics: active_blocks: int = 0 cached_blocks: int = 0 free_blocks: int = 0 - prefix_cache_hit_rate: float = 0 num_prefix_cache_query_tokens: int = 0 num_prefix_cache_hit_tokens: int = 0 scheduler_tick: int = 0 diff --git a/lmdeploy/metrics/loggers.py b/lmdeploy/metrics/loggers.py index 86760e02f1..9855a47dbc 100644 --- a/lmdeploy/metrics/loggers.py +++ b/lmdeploy/metrics/loggers.py @@ -35,13 +35,16 @@ class LoggingStatLogger(StatLoggerBase): def __init__(self, dp_rank: int = 0): self.dp_rank = dp_rank - self._reset(time.perf_counter()) self.last_scheduler_stats = SchedulerStats() + self._reset(time.perf_counter()) def _reset(self, now): self.last_log_time = now self.total_prompt_tokens = 0 self.total_generation_tokens = 0 + # prefix cache token counts at the start of this interval + self.last_prefix_cache_query_tokens = self.last_scheduler_stats.num_prefix_cache_query_tokens + self.last_prefix_cache_hit_tokens = self.last_scheduler_stats.num_prefix_cache_hit_tokens # spec decode self.num_drafts: int = 0 self.num_draft_tokens: int = 0 @@ -118,8 +121,10 @@ def log(self): f'{scheduler_stats.num_running_reqs} / {scheduler_stats.num_waiting_reqs}, ' f'KV cache: {scheduler_stats.gpu_cache_usage * 100 :.1f}%, ') - if scheduler_stats.prefix_cache_hit_rate != 0: - log_msg += f'Prefix cache hit rate: {scheduler_stats.prefix_cache_hit_rate * 100 :.1f}%, ' + if scheduler_stats.num_prefix_cache_query_tokens > self.last_prefix_cache_query_tokens: + query_delta = scheduler_stats.num_prefix_cache_query_tokens - self.last_prefix_cache_query_tokens + hit_delta = scheduler_stats.num_prefix_cache_hit_tokens - self.last_prefix_cache_hit_tokens + log_msg += f'Prefix cache hit rate: {hit_delta / query_delta * 100 :.1f}%, ' if spec_msg is not None: log_msg += spec_msg @@ -191,11 +196,6 @@ def __init__(self, model_name: str, max_model_len: int, dp_rank: int = 0): documentation='GPU KV-cache usage. 1 means 100 percent usage.', labelnames=labelnames).labels(*labelvalues) - self.gauge_prefix_cache_hit_rate = prometheus_client.Gauge( - name='lmdeploy:prefix_cache_hit_rate', - documentation='Prefix-cache hit rate. 1 means 100 percent of queried prefix tokens hit.', - labelnames=labelnames).labels(*labelvalues) - # # Counters # @@ -208,22 +208,6 @@ def __init__(self, model_name: str, max_model_len: int, dp_rank: int = 0): documentation='Number of generation tokens processed.', labelnames=labelnames).labels(*labelvalues) - # Prefix cache hit rate is derived in PromQL from these raw counters: - # rate(prefix_cache_hits_total) / rate(prefix_cache_queries_total) - self.counter_prefix_cache_queries = prometheus_client.Counter( - name='lmdeploy:prefix_cache_queries_total', - documentation='Number of tokens queried against the prefix cache.', - labelnames=labelnames).labels(*labelvalues) - - self.counter_prefix_cache_hits = prometheus_client.Counter( - name='lmdeploy:prefix_cache_hits_total', - documentation='Number of tokens served from the prefix cache.', - labelnames=labelnames).labels(*labelvalues) - - # engine-side stats are cumulative; track last seen values to emit deltas - self._last_prefix_cache_query_tokens = 0 - self._last_prefix_cache_hit_tokens = 0 - # Speculative decoding counters. Acceptance rate and mean acceptance # length are derived in PromQL from these raw counters. # rate(accepted_tokens) / rate(draft_tokens) @@ -400,16 +384,6 @@ def record_schedule(self, stats: SchedulerStats) -> None: self.gauge_scheduler_running.set(stats.num_running_reqs) self.gauge_scheduler_waiting.set(stats.num_waiting_reqs) self.gauge_gpu_cache_usage.set(stats.gpu_cache_usage) - self.gauge_prefix_cache_hit_rate.set(stats.prefix_cache_hit_rate) - - query_delta = stats.num_prefix_cache_query_tokens - self._last_prefix_cache_query_tokens - hit_delta = stats.num_prefix_cache_hit_tokens - self._last_prefix_cache_hit_tokens - if query_delta > 0: - self.counter_prefix_cache_queries.inc(query_delta) - if hit_delta > 0: - self.counter_prefix_cache_hits.inc(hit_delta) - self._last_prefix_cache_query_tokens = stats.num_prefix_cache_query_tokens - self._last_prefix_cache_hit_tokens = stats.num_prefix_cache_hit_tokens def record_iteration(self, stats: IterationStats) -> None: """Report token-related metrics to prometheus.""" diff --git a/lmdeploy/metrics/stats.py b/lmdeploy/metrics/stats.py index 378db8faac..62b4fe1006 100644 --- a/lmdeploy/metrics/stats.py +++ b/lmdeploy/metrics/stats.py @@ -38,7 +38,6 @@ class SchedulerStats: num_running_reqs: Engine core, currently executing requests. num_waiting_reqs: Engine core, requests queued waiting for execution. gpu_cache_usage: Fraction of GPU KV blocks utilized (0.0 to 1.0). - prefix_cache_hit_rate: Prefix caching hit rate. num_prefix_cache_query_tokens: Cumulative number of tokens queried against the prefix cache. num_prefix_cache_hit_tokens: Cumulative number of tokens served from the prefix cache. """ @@ -55,7 +54,6 @@ class SchedulerStats: num_running_reqs: int = 0 num_waiting_reqs: int = 0 gpu_cache_usage: float = 0.0 - prefix_cache_hit_rate: float = 0.0 num_prefix_cache_query_tokens: int = 0 num_prefix_cache_hit_tokens: int = 0 @@ -88,7 +86,6 @@ def __repr__(self): f' num_running_reqs={self.num_running_reqs},\n' f' num_waiting_reqs={self.num_waiting_reqs},\n' f' gpu_cache_usage={self.gpu_cache_usage:.6f},\n' - f' prefix_cache_hit_rate={self.prefix_cache_hit_rate:.6f},\n' f' num_prefix_cache_query_tokens={self.num_prefix_cache_query_tokens},\n' f' num_prefix_cache_hit_tokens={self.num_prefix_cache_hit_tokens},\n' ')') @@ -97,7 +94,6 @@ def update_from_schedule_metrics(self, scheduled_metrics: ScheduleMetrics): self.num_running_reqs = scheduled_metrics.active_seqs self.num_waiting_reqs = scheduled_metrics.waiting_seqs self.gpu_cache_usage = 1.0 - (scheduled_metrics.free_blocks / scheduled_metrics.total_blocks) - self.prefix_cache_hit_rate = scheduled_metrics.prefix_cache_hit_rate self.num_prefix_cache_query_tokens = scheduled_metrics.num_prefix_cache_query_tokens self.num_prefix_cache_hit_tokens = scheduled_metrics.num_prefix_cache_hit_tokens diff --git a/lmdeploy/pytorch/paging/scheduler.py b/lmdeploy/pytorch/paging/scheduler.py index 9ea1f04019..f4be82731f 100644 --- a/lmdeploy/pytorch/paging/scheduler.py +++ b/lmdeploy/pytorch/paging/scheduler.py @@ -567,7 +567,6 @@ def schedule_metrics(self): waiting_seqs=self.num_waiting() + self.num_ready(), total_blocks=self.block_manager.num_gpu_blocks, free_blocks=self.block_manager.get_num_free_gpu_blocks(), - prefix_cache_hit_rate=self.block_trie.hit_rate(), num_prefix_cache_query_tokens=prefix_cache_stats.num_query_tokens, num_prefix_cache_hit_tokens=prefix_cache_stats.num_hit_tokens, scheduler_tick=self.scheduler_tick, diff --git a/tests/test_lmdeploy/test_metrics_loggers.py b/tests/test_lmdeploy/test_metrics_loggers.py index 974e2b18f4..fa39c438c7 100644 --- a/tests/test_lmdeploy/test_metrics_loggers.py +++ b/tests/test_lmdeploy/test_metrics_loggers.py @@ -2,8 +2,8 @@ import pytest -from lmdeploy.metrics.loggers import PrometheusStatLogger -from lmdeploy.metrics.stats import SchedulerStats, SpeculativeDecodingStats +from lmdeploy.metrics.loggers import LoggingStatLogger, PrometheusStatLogger +from lmdeploy.metrics.stats import IterationStats, SchedulerStats, SpeculativeDecodingStats prometheus_client = pytest.importorskip('prometheus_client') @@ -44,15 +44,30 @@ def test_prometheus_stat_logger_records_specdecode_metrics(): assert _get_sample_value('lmdeploy:spec_decode_per_position_accept_rate', position_labels) == 0 -def test_prometheus_stat_logger_records_prefix_cache_counters(): - logger = PrometheusStatLogger('test-prefix-model', max_model_len=16, dp_rank=0) - labels = {'model_name': 'test-prefix-model', 'engine': '0'} +def _iteration_stats(prompt_tokens: int) -> IterationStats: + stats = IterationStats() + stats.prompt_tokens = prompt_tokens + return stats - # engine-side stats are cumulative, so the logger must emit per-interval deltas + +def test_logging_stat_logger_reports_interval_prefix_cache_hit_rate(capsys): + logger = LoggingStatLogger(dp_rank=0) + + # cumulative engine-side counts; the log line must report the interval hit + # rate over the last logging window, not the lifetime average. + logger.record_iteration(_iteration_stats(100)) logger.record_schedule(SchedulerStats(num_prefix_cache_query_tokens=100, num_prefix_cache_hit_tokens=30)) - assert _get_sample_value('lmdeploy:prefix_cache_queries_total', labels) == 100 - assert _get_sample_value('lmdeploy:prefix_cache_hits_total', labels) == 30 + logger.log() + assert 'Prefix cache hit rate: 30.0%' in capsys.readouterr().out + + # interval (80-30)/(250-100) = 50/150 = 33.3%, not the lifetime 80/250 = 32% + logger.record_iteration(_iteration_stats(150)) + logger.record_schedule(SchedulerStats(num_prefix_cache_query_tokens=250, num_prefix_cache_hit_tokens=80)) + logger.log() + assert 'Prefix cache hit rate: 33.3%' in capsys.readouterr().out + # no new queries in the interval -> the line is omitted, no div-by-zero + logger.record_iteration(_iteration_stats(10)) logger.record_schedule(SchedulerStats(num_prefix_cache_query_tokens=250, num_prefix_cache_hit_tokens=80)) - assert _get_sample_value('lmdeploy:prefix_cache_queries_total', labels) == 250 - assert _get_sample_value('lmdeploy:prefix_cache_hits_total', labels) == 80 + logger.log() + assert 'Prefix cache hit rate' not in capsys.readouterr().out