diff --git a/lmdeploy/messages.py b/lmdeploy/messages.py index 9486cc62b0..080feedcb9 100644 --- a/lmdeploy/messages.py +++ b/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 diff --git a/lmdeploy/metrics/loggers.py b/lmdeploy/metrics/loggers.py index 258fa30318..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 # @@ -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.""" diff --git a/lmdeploy/metrics/stats.py b/lmdeploy/metrics/stats.py index 90b19d924f..62b4fe1006 100644 --- a/lmdeploy/metrics/stats.py +++ b/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: diff --git a/lmdeploy/pytorch/paging/scheduler.py b/lmdeploy/pytorch/paging/scheduler.py index 690a547e90..f4be82731f 100644 --- a/lmdeploy/pytorch/paging/scheduler.py +++ b/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, ) diff --git a/tests/test_lmdeploy/test_metrics_loggers.py b/tests/test_lmdeploy/test_metrics_loggers.py index 69ba4db4e5..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 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