Fix stale prefix cache hit rate metric

lmdeploy/messages.py

@@ -662,7 +662,8 @@ 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
 
 

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
         #
@@ -384,7 +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)
 
     def record_iteration(self, stats: IterationStats) -> None:
         """Report token-related metrics to prometheus."""

lmdeploy/metrics/stats.py

@@ -38,7 +38,8 @@ 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.
     """
 
     # api server
@@ -53,7 +54,8 @@ 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
 
     @property
     def num_failed_reqs(self) -> int:
@@ -84,14 +86,16 @@ 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'
                 ')')
 
     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
 
 
 class RequestStats:

lmdeploy/pytorch/paging/scheduler.py

@@ -561,11 +561,13 @@ 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,
         )

tests/test_lmdeploy/test_metrics_loggers.py

@@ -2,8 +2,8 @@
 
 import pytest
 
-from lmdeploy.metrics.loggers import PrometheusStatLogger
-from lmdeploy.metrics.stats import SpeculativeDecodingStats
+from lmdeploy.metrics.loggers import LoggingStatLogger, PrometheusStatLogger
+from lmdeploy.metrics.stats import IterationStats, SchedulerStats, SpeculativeDecodingStats
 
 prometheus_client = pytest.importorskip('prometheus_client')
 
@@ -42,3 +42,32 @@ 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 _iteration_stats(prompt_tokens: int) -> IterationStats:
+    stats = IterationStats()
+    stats.prompt_tokens = prompt_tokens
+    return stats
+
+
+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))
+    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))
+    logger.log()
+    assert 'Prefix cache hit rate' not in capsys.readouterr().out