| 1 | # SPDX-License-Identifier: Apache-2.0 |
| 2 | # SPDX-FileCopyrightText: Copyright contributors to the vLLM project |
| 3 | |
| 4 | import logging |
| 5 | import time |
| 6 | from abc import ABC, abstractmethod |
| 7 | from collections.abc import Callable |
| 8 | |
| 9 | from prometheus_client import Counter, Gauge, Histogram |
| 10 | |
| 11 | import vllm.envs as envs |
| 12 | from vllm.compilation.cuda_graph import CUDAGraphLogging |
| 13 | from vllm.config import SupportsMetricsInfo, VllmConfig |
| 14 | from vllm.distributed.ec_transfer.ec_connector.metrics import ( |
| 15 | ECConnectorLogging, |
| 16 | ECConnectorProm, |
| 17 | ) |
| 18 | from vllm.distributed.kv_transfer.kv_connector.v1.metrics import ( |
| 19 | KVConnectorLogging, |
| 20 | KVConnectorProm, |
| 21 | ) |
| 22 | from vllm.logger import init_logger |
| 23 | from vllm.plugins import STAT_LOGGER_PLUGINS_GROUP, load_plugins_by_group |
| 24 | from vllm.v1.engine import FinishReason |
| 25 | from vllm.v1.metrics.buckets import histogram_buckets |
| 26 | from vllm.v1.metrics.perf import PerfMetricsLogging, PerfMetricsProm |
| 27 | from vllm.v1.metrics.prometheus import unregister_vllm_metrics |
| 28 | from vllm.v1.metrics.stats import ( |
| 29 | KV_FETCH_STAGES, |
| 30 | CachingMetrics, |
| 31 | IterationStats, |
| 32 | MultiModalCacheStats, |
| 33 | PromptTokenStats, |
| 34 | SchedulerStats, |
| 35 | ) |
| 36 | from vllm.v1.metrics.utils import create_metric_per_engine |
| 37 | from vllm.v1.spec_decode.metrics import SpecDecodingLogging, SpecDecodingProm |
| 38 | |
| 39 | logger = init_logger(__name__) |
| 40 | |
| 41 | # User-facing reason labels for waiting request breakdown |
| 42 | WAITING_REASON_CAPACITY = "capacity" |
| 43 | WAITING_REASON_DEFERRED = "deferred" |
| 44 | |
| 45 | PerEngineStatLoggerFactory = Callable[[VllmConfig, int], "StatLoggerBase"] |
| 46 | AggregateStatLoggerFactory = type["AggregateStatLoggerBase"] |
| 47 | StatLoggerFactory = AggregateStatLoggerFactory | PerEngineStatLoggerFactory |
| 48 | |
| 49 | |
| 50 | class StatLoggerBase(ABC): |
| 51 | """Interface for logging metrics. |
| 52 | |
| 53 | API users may define custom loggers that implement this interface. |
| 54 | However, note that the `SchedulerStats` and `IterationStats` classes |
| 55 | are not considered stable interfaces and may change in future versions. |
| 56 | """ |
| 57 | |
| 58 | @abstractmethod |
| 59 | def __init__(self, vllm_config: VllmConfig, engine_index: int = 0): ... |
| 60 | |
| 61 | @abstractmethod |
| 62 | def record( |
| 63 | self, |
| 64 | scheduler_stats: SchedulerStats | None, |
| 65 | iteration_stats: IterationStats | None, |
| 66 | mm_cache_stats: MultiModalCacheStats | None = None, |
| 67 | engine_idx: int = 0, |
| 68 | ): ... |
| 69 | |
| 70 | @abstractmethod |
| 71 | def log_engine_initialized(self): ... |
| 72 | |
| 73 | def log(self): # noqa |
| 74 | pass |
| 75 | |
| 76 | def record_sleep_state(self, is_awake: int, level: int): # noqa |
| 77 | pass |
| 78 | |
| 79 | |
| 80 | def load_stat_logger_plugin_factories() -> list[StatLoggerFactory]: |
| 81 | factories: list[StatLoggerFactory] = [] |
| 82 | |
| 83 | for name, plugin_class in load_plugins_by_group(STAT_LOGGER_PLUGINS_GROUP).items(): |
| 84 | if not isinstance(plugin_class, type) or not issubclass( |
| 85 | plugin_class, StatLoggerBase |
| 86 | ): |
| 87 | raise TypeError( |
| 88 | f"Stat logger plugin {name!r} must be a subclass of " |
| 89 | f"StatLoggerBase (got {plugin_class!r})." |
| 90 | ) |
| 91 | |
| 92 | factories.append(plugin_class) |
| 93 | |
| 94 | return factories |
| 95 | |
| 96 | |
| 97 | class AggregateStatLoggerBase(StatLoggerBase): |
| 98 | """Abstract base class for loggers that |
| 99 | aggregate across multiple DP engines.""" |
| 100 | |
| 101 | @abstractmethod |
| 102 | def __init__(self, vllm_config: VllmConfig, engine_indexes: list[int]): ... |
| 103 | |
| 104 | |
| 105 | class LoggingStatLogger(StatLoggerBase): |
| 106 | def __init__(self, vllm_config: VllmConfig, engine_index: int = 0): |
| 107 | self.engine_index = engine_index |
| 108 | self.vllm_config = vllm_config |
| 109 | device_type = vllm_config.device_config.device_type |
| 110 | self.kv_cache_device = "GPU" if device_type == "cuda" else device_type.upper() |
| 111 | self._reset(time.monotonic()) |
| 112 | |
| 113 | self.last_scheduler_stats = SchedulerStats() |
| 114 | |
| 115 | # Caching metrics. This cannot be reset. |
| 116 | # TODO: Make the interval configurable. |
| 117 | self.prefix_caching_metrics = CachingMetrics() |
| 118 | self.connector_prefix_caching_metrics = CachingMetrics() |
| 119 | self.mm_caching_metrics = CachingMetrics() |
| 120 | |
| 121 | model_config = self.vllm_config.model_config |
| 122 | is_diffusion = model_config is not None and model_config.is_diffusion |
| 123 | self.spec_decoding_logging = SpecDecodingLogging(is_diffusion=is_diffusion) |
| 124 | kv_transfer_config = self.vllm_config.kv_transfer_config |
| 125 | self.kv_connector_logging = KVConnectorLogging(kv_transfer_config) |
| 126 | ec_transfer_config = self.vllm_config.ec_transfer_config |
| 127 | self.ec_connector_logging = ECConnectorLogging(ec_transfer_config) |
| 128 | self.cudagraph_logging = None |
| 129 | if self.vllm_config.observability_config.cudagraph_metrics: |
| 130 | self.cudagraph_logging = CUDAGraphLogging( |
| 131 | self.vllm_config.compilation_config.cudagraph_mode, |
| 132 | self.vllm_config.compilation_config.cudagraph_capture_sizes, |
| 133 | ) |
| 134 | self.last_prompt_throughput: float = 0.0 |
| 135 | self.last_generation_throughput: float = 0.0 |
| 136 | self.engine_is_idle = False |
| 137 | self.aggregated = False |
| 138 | |
| 139 | if self._enable_perf_stats(): |
| 140 | self.perf_metrics_logging = PerfMetricsLogging(vllm_config) |
| 141 | |
| 142 | def _reset(self, now): |
| 143 | self.last_log_time = now |
| 144 | |
| 145 | # Tracked stats over current local logging interval. |
| 146 | self.num_prompt_tokens: int = 0 |
| 147 | self.num_generation_tokens: int = 0 |
| 148 | self.num_corrupted_reqs: int = 0 |
| 149 | self.num_preemptions: int = 0 |
| 150 | |
| 151 | def _enable_perf_stats(self) -> bool: |
| 152 | return self.vllm_config.observability_config.enable_mfu_metrics |
| 153 | |
| 154 | def _track_iteration_stats(self, iteration_stats: IterationStats): |
| 155 | # Save tracked stats for token counters. |
| 156 | # Use computed tokens for prompt throughput (excludes cached/transferred) |
| 157 | self.num_prompt_tokens += iteration_stats.prompt_token_stats.computed |
| 158 | self.num_generation_tokens += iteration_stats.num_generation_tokens |
| 159 | self.num_corrupted_reqs += iteration_stats.num_corrupted_reqs |
| 160 | self.num_preemptions += iteration_stats.num_preempted_reqs |
| 161 | |
| 162 | def _get_throughput(self, tracked_stats: int, now: float) -> float: |
| 163 | # Compute summary metrics for tracked stats |
| 164 | delta_time = now - self.last_log_time |
| 165 | if delta_time <= 0.0: |
| 166 | return 0.0 |
| 167 | return float(tracked_stats / delta_time) |
| 168 | |
| 169 | @property |
| 170 | def log_prefix(self): |
| 171 | return "Engine {:03d}: ".format(self.engine_index) |
| 172 | |
| 173 | def _log_prefix_for_engine(self, engine_idx: int) -> str: |
| 174 | if self.engine_index == engine_idx: |
| 175 | return self.log_prefix |
| 176 | return "Engine {:03d}: ".format(engine_idx) |
| 177 | |
| 178 | def _log_iteration_details( |
| 179 | self, scheduler_stats: SchedulerStats, engine_idx: int |
| 180 | ) -> None: |
| 181 | details = scheduler_stats.iteration_details |
| 182 | if details is None: |
| 183 | return |
| 184 | |
| 185 | encoder_msg = "" |
| 186 | if details.num_encoder_inputs: |
| 187 | encoder_msg = ( |
| 188 | f", encoder inputs: {details.num_encoder_inputs}, " |
| 189 | f"encoder output embeddings: {details.num_encoder_output_tokens}" |
| 190 | ) |
| 191 | |
| 192 | logger.info( |
| 193 | "%sIteration(%d): %d context requests, %d context tokens, " |
| 194 | "%d generation requests, %d generation tokens, " |
| 195 | "iteration elapsed time: %.2f ms%s, " |
| 196 | "%s KV cache usage: %.1f%%%s", |
| 197 | self._log_prefix_for_engine(engine_idx), |
| 198 | details.iteration_index, |
| 199 | details.num_ctx_requests, |
| 200 | details.num_ctx_tokens, |
| 201 | details.num_generation_requests, |
| 202 | details.num_generation_tokens, |
| 203 | details.elapsed_ms, |
| 204 | " (dummy)" if details.is_dummy else "", |
| 205 | self.kv_cache_device, |
| 206 | scheduler_stats.kv_cache_usage * 100, |
| 207 | encoder_msg, |
| 208 | ) |
| 209 | |
| 210 | def record( |
| 211 | self, |
| 212 | scheduler_stats: SchedulerStats | None, |
| 213 | iteration_stats: IterationStats | None, |
| 214 | mm_cache_stats: MultiModalCacheStats | None = None, |
| 215 | engine_idx: int = 0, |
| 216 | ): |
| 217 | """Log Stats to standard output.""" |
| 218 | if iteration_stats: |
| 219 | self._track_iteration_stats(iteration_stats) |
| 220 | |
| 221 | if scheduler_stats is not None: |
| 222 | self._log_iteration_details(scheduler_stats, engine_idx) |
| 223 | self.prefix_caching_metrics.observe(scheduler_stats.prefix_cache_stats) |
| 224 | |
| 225 | if scheduler_stats.connector_prefix_cache_stats is not None: |
| 226 | self.connector_prefix_caching_metrics.observe( |
| 227 | scheduler_stats.connector_prefix_cache_stats |
| 228 | ) |
| 229 | |
| 230 | if scheduler_stats.spec_decoding_stats is not None: |
| 231 | self.spec_decoding_logging.observe(scheduler_stats.spec_decoding_stats) |
| 232 | if kv_connector_stats := scheduler_stats.kv_connector_stats: |
| 233 | self.kv_connector_logging.observe(kv_connector_stats) |
| 234 | if ec_connector_stats := scheduler_stats.ec_connector_stats: |
| 235 | self.ec_connector_logging.observe(ec_connector_stats) |
| 236 | if ( |
| 237 | self.cudagraph_logging is not None |
| 238 | and scheduler_stats.cudagraph_stats is not None |
| 239 | ): |
| 240 | self.cudagraph_logging.observe(scheduler_stats.cudagraph_stats) |
| 241 | if not self.aggregated: |
| 242 | self.last_scheduler_stats = scheduler_stats |
| 243 | if (perf_stats := scheduler_stats.perf_stats) and self._enable_perf_stats(): |
| 244 | self.perf_metrics_logging.observe(perf_stats) |
| 245 | if mm_cache_stats: |
| 246 | self.mm_caching_metrics.observe(mm_cache_stats) |
| 247 | |
| 248 | def _update_stats(self): |
| 249 | now = time.monotonic() |
| 250 | prompt_throughput = self._get_throughput(self.num_prompt_tokens, now) |
| 251 | generation_throughput = self._get_throughput(self.num_generation_tokens, now) |
| 252 | |
| 253 | self._reset(now) |
| 254 | self.engine_is_idle = not any( |
| 255 | ( |
| 256 | prompt_throughput, |
| 257 | generation_throughput, |
| 258 | self.last_prompt_throughput, |
| 259 | self.last_generation_throughput, |
| 260 | ) |
| 261 | ) |
| 262 | self.last_generation_throughput = generation_throughput |
| 263 | self.last_prompt_throughput = prompt_throughput |
| 264 | |
| 265 | def aggregate_scheduler_stats(self): |
| 266 | # noop for per engine loggers |
| 267 | return |
| 268 | |
| 269 | def log(self): |
| 270 | self._update_stats() |
| 271 | self.aggregate_scheduler_stats() |
| 272 | # Avoid log noise on an idle production system |
| 273 | log_fn = logger.debug if self.engine_is_idle else logger.info |
| 274 | # Format and print output. |
| 275 | log_parts = [ |
| 276 | "Avg prompt throughput: %.1f tokens/s", |
| 277 | "Avg generation throughput: %.1f tokens/s", |
| 278 | "Running: %d reqs", |
| 279 | "Waiting: %d reqs", |
| 280 | ] |
| 281 | total_waiting = ( |
| 282 | self.last_scheduler_stats.num_waiting_reqs |
| 283 | + self.last_scheduler_stats.num_skipped_waiting_reqs |
| 284 | ) |
| 285 | log_args: list[int | float | str] = [ |
| 286 | self.last_prompt_throughput, |
| 287 | self.last_generation_throughput, |
| 288 | self.last_scheduler_stats.num_running_reqs, |
| 289 | total_waiting, |
| 290 | ] |
| 291 | |
| 292 | if self.last_scheduler_stats.num_skipped_waiting_reqs > 0: |
| 293 | log_parts.append("Deferred: %d reqs") |
| 294 | log_args.append(self.last_scheduler_stats.num_skipped_waiting_reqs) |
| 295 | |
| 296 | kv_fetch = self.last_scheduler_stats.num_kv_fetch_reqs_by_stage |
| 297 | if any(kv_fetch.values()): |
| 298 | log_parts.append( |
| 299 | "KV fetch: %d waiting to start, %d in progress, %d completed waiting" |
| 300 | ) |
| 301 | log_args.extend(kv_fetch.get(stage, 0) for stage in KV_FETCH_STAGES) |
| 302 | |
| 303 | if self.num_preemptions > 0: |
| 304 | log_parts.append("Preemptions: %d") |
| 305 | log_args.append(self.num_preemptions) |
| 306 | |
| 307 | log_parts.append("%s KV cache usage: %.1f%%") |
| 308 | log_args.extend( |
| 309 | [ |
| 310 | self.kv_cache_device, |
| 311 | self.last_scheduler_stats.kv_cache_usage * 100, |
| 312 | ] |
| 313 | ) |
| 314 | if not self.prefix_caching_metrics.empty: |
| 315 | log_parts.append("Prefix cache hit rate: %.1f%%") |
| 316 | log_args.append(self.prefix_caching_metrics.hit_rate * 100) |
| 317 | |
| 318 | if envs.VLLM_COMPUTE_NANS_IN_LOGITS: |
| 319 | log_parts.append("Corrupted: %d reqs") |
| 320 | log_args.append(self.num_corrupted_reqs) |
| 321 | if not self.connector_prefix_caching_metrics.empty: |
| 322 | log_parts.append("External prefix cache hit rate: %.1f%%") |
| 323 | log_args.append(self.connector_prefix_caching_metrics.hit_rate * 100) |
| 324 | if not self.mm_caching_metrics.empty: |
| 325 | log_parts.append("MM cache hit rate: %.1f%%") |
| 326 | log_args.append(self.mm_caching_metrics.hit_rate * 100) |
| 327 | |
| 328 | log_fn( |
| 329 | self.log_prefix + ", ".join(log_parts), |
| 330 | *log_args, |
| 331 | ) |
| 332 | |
| 333 | self.spec_decoding_logging.log(log_fn=log_fn) |
| 334 | self.kv_connector_logging.log(log_fn=log_fn) |
| 335 | self.ec_connector_logging.log(log_fn=log_fn) |
| 336 | if self.cudagraph_logging is not None: |
| 337 | self.cudagraph_logging.log(log_fn=log_fn) |
| 338 | if self._enable_perf_stats(): |
| 339 | self.perf_metrics_logging.log(log_fn=log_fn, log_prefix=self.log_prefix) |
| 340 | |
| 341 | def log_engine_initialized(self): |
| 342 | if self.vllm_config.cache_config.num_gpu_blocks: |
| 343 | logger.debug( |
| 344 | "Engine %03d: vllm cache_config_info with initialization " |
| 345 | "after num_gpu_blocks is: %d", |
| 346 | self.engine_index, |
| 347 | self.vllm_config.cache_config.num_gpu_blocks, |
| 348 | ) |
| 349 | |
| 350 | |
| 351 | class AggregatedLoggingStatLogger(LoggingStatLogger, AggregateStatLoggerBase): |
| 352 | def __init__( |
| 353 | self, |
| 354 | vllm_config: VllmConfig, |
| 355 | engine_indexes: list[int], |
| 356 | ): |
| 357 | self.engine_indexes = engine_indexes |
| 358 | self.last_scheduler_stats_dict: dict[int, SchedulerStats] = { |
| 359 | idx: SchedulerStats() for idx in self.engine_indexes |
| 360 | } |
| 361 | LoggingStatLogger.__init__(self, vllm_config, engine_index=-1) |
| 362 | self.aggregated = True |
| 363 | |
| 364 | @property |
| 365 | def log_prefix(self): |
| 366 | return "{} Engines Aggregated: ".format(len(self.engine_indexes)) |
| 367 | |
| 368 | def _enable_perf_stats(self) -> bool: |
| 369 | # Adding per_gpu perf stats across engines can lead to misleading numbers. |
| 370 | return False |
| 371 | |
| 372 | def record( |
| 373 | self, |
| 374 | scheduler_stats: SchedulerStats | None, |
| 375 | iteration_stats: IterationStats | None, |
| 376 | mm_cache_stats: MultiModalCacheStats | None = None, |
| 377 | engine_idx: int = 0, |
| 378 | ): |
| 379 | if engine_idx not in self.engine_indexes: |
| 380 | logger.warning("Unexpected engine_idx: %d", engine_idx) |
| 381 | return |
| 382 | LoggingStatLogger.record( |
| 383 | self, |
| 384 | scheduler_stats, |
| 385 | iteration_stats, |
| 386 | mm_cache_stats=mm_cache_stats, |
| 387 | engine_idx=engine_idx, |
| 388 | ) |
| 389 | if scheduler_stats is not None: |
| 390 | self.last_scheduler_stats_dict[engine_idx] = scheduler_stats |
| 391 | |
| 392 | def aggregate_scheduler_stats(self): |
| 393 | self.last_scheduler_stats = SchedulerStats() |
| 394 | for last_scheduler_stats in self.last_scheduler_stats_dict.values(): |
| 395 | self.last_scheduler_stats.num_waiting_reqs += ( |
| 396 | last_scheduler_stats.num_waiting_reqs |
| 397 | ) |
| 398 | self.last_scheduler_stats.num_running_reqs += ( |
| 399 | last_scheduler_stats.num_running_reqs |
| 400 | ) |
| 401 | self.last_scheduler_stats.num_skipped_waiting_reqs += ( |
| 402 | last_scheduler_stats.num_skipped_waiting_reqs |
| 403 | ) |
| 404 | engine_kv_fetch = last_scheduler_stats.num_kv_fetch_reqs_by_stage |
| 405 | total_kv_fetch = self.last_scheduler_stats.num_kv_fetch_reqs_by_stage |
| 406 | for stage, num_reqs in engine_kv_fetch.items(): |
| 407 | total_kv_fetch[stage] = total_kv_fetch.get(stage, 0) + num_reqs |
| 408 | self.last_scheduler_stats.kv_cache_usage += ( |
| 409 | last_scheduler_stats.kv_cache_usage |
| 410 | ) |
| 411 | self.last_scheduler_stats.kv_cache_usage /= len(self.last_scheduler_stats_dict) |
| 412 | |
| 413 | def log(self): |
| 414 | LoggingStatLogger.log(self) |
| 415 | |
| 416 | def log_engine_initialized(self): |
| 417 | if self.vllm_config.cache_config.num_gpu_blocks: |
| 418 | logger.info( |
| 419 | "%d Engines: vllm cache_config_info with initialization " |
| 420 | "after num_gpu_blocks is: %d", |
| 421 | len(self.engine_indexes), |
| 422 | self.vllm_config.cache_config.num_gpu_blocks, |
| 423 | ) |
| 424 | |
| 425 | |
| 426 | class PerEngineStatLoggerAdapter(AggregateStatLoggerBase): |
| 427 | def __init__( |
| 428 | self, |
| 429 | vllm_config: VllmConfig, |
| 430 | engine_indexes: list[int], |
| 431 | per_engine_stat_logger_factory: PerEngineStatLoggerFactory, |
| 432 | ) -> None: |
| 433 | self.per_engine_stat_loggers = {} |
| 434 | self.engine_indexes = engine_indexes |
| 435 | for engine_index in engine_indexes: |
| 436 | self.per_engine_stat_loggers[engine_index] = per_engine_stat_logger_factory( |
| 437 | vllm_config, engine_index |
| 438 | ) |
| 439 | |
| 440 | def record( |
| 441 | self, |
| 442 | scheduler_stats: SchedulerStats | None, |
| 443 | iteration_stats: IterationStats | None, |
| 444 | mm_cache_stats: MultiModalCacheStats | None = None, |
| 445 | engine_idx: int = 0, |
| 446 | ): |
| 447 | if engine_idx not in self.per_engine_stat_loggers: |
| 448 | logger.warning("Unexpected engine_idx: %d", engine_idx) |
| 449 | return |
| 450 | self.per_engine_stat_loggers[engine_idx].record( |
| 451 | scheduler_stats, |
| 452 | iteration_stats, |
| 453 | mm_cache_stats=mm_cache_stats, |
| 454 | engine_idx=engine_idx, |
| 455 | ) |
| 456 | |
| 457 | def log(self): |
| 458 | for per_engine_stat_logger in self.per_engine_stat_loggers.values(): |
| 459 | per_engine_stat_logger.log() |
| 460 | |
| 461 | def log_engine_initialized(self): |
| 462 | for per_engine_stat_logger in self.per_engine_stat_loggers.values(): |
| 463 | per_engine_stat_logger.log_engine_initialized() |
| 464 | |
| 465 | |
| 466 | class PrometheusStatLogger(AggregateStatLoggerBase): |
| 467 | _gauge_cls = Gauge |
| 468 | _counter_cls = Counter |
| 469 | _histogram_cls = Histogram |
| 470 | _spec_decoding_cls = SpecDecodingProm |
| 471 | _kv_connector_cls = KVConnectorProm |
| 472 | _ec_connector_cls = ECConnectorProm |
| 473 | _perf_metrics_cls = PerfMetricsProm |
| 474 | |
| 475 | def __init__( |
| 476 | self, vllm_config: VllmConfig, engine_indexes: list[int] | None = None |
| 477 | ): |
| 478 | if engine_indexes is None: |
| 479 | engine_indexes = [0] |
| 480 | |
| 481 | self.engine_indexes = engine_indexes |
| 482 | |
| 483 | unregister_vllm_metrics() |
| 484 | self.vllm_config = vllm_config |
| 485 | # Use this flag to hide metrics that were deprecated in |
| 486 | # a previous release and which will be removed future |
| 487 | self.show_hidden_metrics = vllm_config.observability_config.show_hidden_metrics |
| 488 | self.kv_cache_metrics_enabled = ( |
| 489 | vllm_config.observability_config.kv_cache_metrics |
| 490 | ) |
| 491 | |
| 492 | labelnames = ["model_name", "engine"] |
| 493 | model_name = vllm_config.model_config.served_model_name |
| 494 | max_model_len = vllm_config.model_config.max_model_len |
| 495 | |
| 496 | self.per_engine_labelvalues: dict[int, list[object]] = { |
| 497 | idx: [model_name, str(idx)] for idx in engine_indexes |
| 498 | } |
| 499 | per_engine_labelvalues = self.per_engine_labelvalues |
| 500 | |
| 501 | self.spec_decoding_prom = self._spec_decoding_cls( |
| 502 | vllm_config.speculative_config, |
| 503 | labelnames, |
| 504 | per_engine_labelvalues, |
| 505 | is_diffusion=vllm_config.model_config.is_diffusion, |
| 506 | ) |
| 507 | self.kv_connector_prom = self._kv_connector_cls( |
| 508 | vllm_config, labelnames, per_engine_labelvalues |
| 509 | ) |
| 510 | self.ec_connector_prom = self._ec_connector_cls( |
| 511 | vllm_config, labelnames, per_engine_labelvalues |
| 512 | ) |
| 513 | self.perf_metrics_prom = self._perf_metrics_cls( |
| 514 | vllm_config, labelnames, per_engine_labelvalues |
| 515 | ) |
| 516 | |
| 517 | # |
| 518 | # Scheduler state |
| 519 | # |
| 520 | gauge_scheduler_running = self._gauge_cls( |
| 521 | name="vllm:num_requests_running", |
| 522 | documentation="Number of requests in model execution batches.", |
| 523 | multiprocess_mode="mostrecent", |
| 524 | labelnames=labelnames, |
| 525 | ) |
| 526 | self.gauge_scheduler_running = create_metric_per_engine( |
| 527 | gauge_scheduler_running, per_engine_labelvalues |
| 528 | ) |
| 529 | |
| 530 | gauge_scheduler_waiting = self._gauge_cls( |
| 531 | name="vllm:num_requests_waiting", |
| 532 | documentation="Number of requests waiting to be processed.", |
| 533 | multiprocess_mode="mostrecent", |
| 534 | labelnames=labelnames, |
| 535 | ) |
| 536 | self.gauge_scheduler_waiting = create_metric_per_engine( |
| 537 | gauge_scheduler_waiting, per_engine_labelvalues |
| 538 | ) |
| 539 | |
| 540 | gauge_waiting_by_reason = self._gauge_cls( |
| 541 | name="vllm:num_requests_waiting_by_reason", |
| 542 | documentation=( |
| 543 | "Number of waiting requests by reason. " |
| 544 | "Reason labels: 'capacity' = waiting for scheduling capacity; " |
| 545 | "'deferred' = deferred by transient constraints " |
| 546 | "(LoRA budget, KV transfer, blocked status). " |
| 547 | "Sum of all reasons equals vllm:num_requests_waiting." |
| 548 | ), |
| 549 | multiprocess_mode="mostrecent", |
| 550 | labelnames=labelnames + ["reason"], |
| 551 | ) |
| 552 | self.gauge_waiting_by_reason: dict[str, dict[int, Gauge]] = {} |
| 553 | for waiting_reason in [WAITING_REASON_CAPACITY, WAITING_REASON_DEFERRED]: |
| 554 | per_engine_labelvalues_with_reason = { |
| 555 | idx: labelvalues + [waiting_reason] |
| 556 | for idx, labelvalues in per_engine_labelvalues.items() |
| 557 | } |
| 558 | self.gauge_waiting_by_reason[waiting_reason] = create_metric_per_engine( |
| 559 | gauge_waiting_by_reason, per_engine_labelvalues_with_reason |
| 560 | ) |
| 561 | |
| 562 | self.gauge_kv_fetch_by_stage: dict[str, dict[int, Gauge]] = {} |
| 563 | kv_transfer_config = vllm_config.kv_transfer_config |
| 564 | if kv_transfer_config is not None and kv_transfer_config.is_kv_consumer: |
| 565 | gauge_kv_fetch_by_stage = self._gauge_cls( |
| 566 | name="vllm:num_requests_kv_fetch_by_stage", |
| 567 | documentation=( |
| 568 | "Number of waiting requests by async KV load stage. " |
| 569 | "Stage labels: 'waiting_to_start' = needs an async KV load " |
| 570 | "that has not started; 'in_progress' = load started and not " |
| 571 | "yet reported finished; 'completed_waiting' = load finished, " |
| 572 | "request not running yet." |
| 573 | ), |
| 574 | multiprocess_mode="mostrecent", |
| 575 | labelnames=labelnames + ["stage"], |
| 576 | ) |
| 577 | for stage in KV_FETCH_STAGES: |
| 578 | per_engine_labelvalues_with_stage = { |
| 579 | idx: labelvalues + [stage] |
| 580 | for idx, labelvalues in per_engine_labelvalues.items() |
| 581 | } |
| 582 | self.gauge_kv_fetch_by_stage[stage] = create_metric_per_engine( |
| 583 | gauge_kv_fetch_by_stage, per_engine_labelvalues_with_stage |
| 584 | ) |
| 585 | |
| 586 | gauge_engine_sleep_state = self._gauge_cls( |
| 587 | name="vllm:engine_sleep_state", |
| 588 | documentation=( |
| 589 | "Engine sleep state; awake = 0 means engine is sleeping; " |
| 590 | "awake = 1 means engine is awake; " |
| 591 | "weights_offloaded = 1 means sleep level 1; " |
| 592 | "discard_all = 1 means sleep level 2." |
| 593 | ), |
| 594 | labelnames=labelnames + ["sleep_state"], |
| 595 | multiprocess_mode="mostrecent", |
| 596 | ) |
| 597 | |
| 598 | self.gauge_engine_sleep_state = {} |
| 599 | sleep_state = ["awake", "weights_offloaded", "discard_all"] |
| 600 | |
| 601 | for s in sleep_state: |
| 602 | self.gauge_engine_sleep_state[s] = { |
| 603 | idx: gauge_engine_sleep_state.labels( |
| 604 | engine=idx, model_name=model_name, sleep_state=s |
| 605 | ) |
| 606 | for idx in engine_indexes |
| 607 | } |
| 608 | |
| 609 | # Setting default values |
| 610 | self.record_sleep_state() |
| 611 | |
| 612 | gauge_kv_cache_usage = self._gauge_cls( |
| 613 | name="vllm:kv_cache_usage_perc", |
| 614 | documentation="KV-cache usage. 1 means 100 percent usage.", |
| 615 | multiprocess_mode="mostrecent", |
| 616 | labelnames=labelnames, |
| 617 | ) |
| 618 | self.gauge_kv_cache_usage = create_metric_per_engine( |
| 619 | gauge_kv_cache_usage, per_engine_labelvalues |
| 620 | ) |
| 621 | |
| 622 | if envs.VLLM_COMPUTE_NANS_IN_LOGITS: |
| 623 | counter_corrupted_requests = self._counter_cls( |
| 624 | name="vllm:corrupted_requests", |
| 625 | documentation=( |
| 626 | "Corrupted requests, in terms of total number of requests " |
| 627 | "with NaNs in logits." |
| 628 | ), |
| 629 | labelnames=labelnames, |
| 630 | ) |
| 631 | self.counter_corrupted_requests = create_metric_per_engine( |
| 632 | counter_corrupted_requests, per_engine_labelvalues |
| 633 | ) |
| 634 | |
| 635 | counter_prefix_cache_queries = self._counter_cls( |
| 636 | name="vllm:prefix_cache_queries", |
| 637 | documentation=( |
| 638 | "Prefix cache queries, in terms of number of queried tokens." |
| 639 | ), |
| 640 | labelnames=labelnames, |
| 641 | ) |
| 642 | self.counter_prefix_cache_queries = create_metric_per_engine( |
| 643 | counter_prefix_cache_queries, per_engine_labelvalues |
| 644 | ) |
| 645 | |
| 646 | counter_prefix_cache_hits = self._counter_cls( |
| 647 | name="vllm:prefix_cache_hits", |
| 648 | documentation=("Prefix cache hits, in terms of number of cached tokens."), |
| 649 | labelnames=labelnames, |
| 650 | ) |
| 651 | self.counter_prefix_cache_hits = create_metric_per_engine( |
| 652 | counter_prefix_cache_hits, per_engine_labelvalues |
| 653 | ) |
| 654 | |
| 655 | # |
| 656 | # External - KV connector prefix cache |
| 657 | # |
| 658 | |
| 659 | counter_connector_prefix_cache_queries = self._counter_cls( |
| 660 | name="vllm:external_prefix_cache_queries", |
| 661 | documentation=( |
| 662 | "External prefix cache queries from KV connector " |
| 663 | "cross-instance cache sharing, in terms of number of queried tokens." |
| 664 | ), |
| 665 | labelnames=labelnames, |
| 666 | ) |
| 667 | self.counter_connector_prefix_cache_queries = create_metric_per_engine( |
| 668 | counter_connector_prefix_cache_queries, per_engine_labelvalues |
| 669 | ) |
| 670 | |
| 671 | counter_connector_prefix_cache_hits = self._counter_cls( |
| 672 | name="vllm:external_prefix_cache_hits", |
| 673 | documentation=( |
| 674 | "External prefix cache hits from KV connector " |
| 675 | "cross-instance cache sharing, in terms of number of cached tokens." |
| 676 | ), |
| 677 | labelnames=labelnames, |
| 678 | ) |
| 679 | self.counter_connector_prefix_cache_hits = create_metric_per_engine( |
| 680 | counter_connector_prefix_cache_hits, per_engine_labelvalues |
| 681 | ) |
| 682 | |
| 683 | # |
| 684 | # Multi-modal cache |
| 685 | # |
| 686 | |
| 687 | counter_mm_cache_queries = self._counter_cls( |
| 688 | name="vllm:mm_cache_queries", |
| 689 | documentation=( |
| 690 | "Multi-modal cache queries, in terms of number of queried items." |
| 691 | ), |
| 692 | labelnames=labelnames, |
| 693 | ) |
| 694 | self.counter_mm_cache_queries = create_metric_per_engine( |
| 695 | counter_mm_cache_queries, per_engine_labelvalues |
| 696 | ) |
| 697 | |
| 698 | counter_mm_cache_hits = self._counter_cls( |
| 699 | name="vllm:mm_cache_hits", |
| 700 | documentation=( |
| 701 | "Multi-modal cache hits, in terms of number of cached items." |
| 702 | ), |
| 703 | labelnames=labelnames, |
| 704 | ) |
| 705 | self.counter_mm_cache_hits = create_metric_per_engine( |
| 706 | counter_mm_cache_hits, per_engine_labelvalues |
| 707 | ) |
| 708 | |
| 709 | # |
| 710 | # Counters |
| 711 | # |
| 712 | counter_num_preempted_reqs = self._counter_cls( |
| 713 | name="vllm:num_preemptions", |
| 714 | documentation="Cumulative number of preemption from the engine.", |
| 715 | labelnames=labelnames, |
| 716 | ) |
| 717 | self.counter_num_preempted_reqs = create_metric_per_engine( |
| 718 | counter_num_preempted_reqs, per_engine_labelvalues |
| 719 | ) |
| 720 | |
| 721 | counter_prompt_tokens = self._counter_cls( |
| 722 | name="vllm:prompt_tokens", |
| 723 | documentation="Number of prefill tokens processed.", |
| 724 | labelnames=labelnames, |
| 725 | ) |
| 726 | self.counter_prompt_tokens = create_metric_per_engine( |
| 727 | counter_prompt_tokens, per_engine_labelvalues |
| 728 | ) |
| 729 | |
| 730 | # Labeled prompt token counters by source |
| 731 | counter_prompt_tokens_by_source = self._counter_cls( |
| 732 | name="vllm:prompt_tokens_by_source", |
| 733 | documentation="Number of prompt tokens by source.", |
| 734 | labelnames=labelnames + ["source"], |
| 735 | ) |
| 736 | self.counter_prompt_tokens_by_source: dict[str, dict[int, Counter]] = {} |
| 737 | for source in PromptTokenStats.ALL_SOURCES: |
| 738 | self.counter_prompt_tokens_by_source[source] = { |
| 739 | idx: counter_prompt_tokens_by_source.labels( |
| 740 | model_name, str(idx), source |
| 741 | ) |
| 742 | for idx in engine_indexes |
| 743 | } |
| 744 | |
| 745 | # Cached prompt tokens counter |
| 746 | counter_prompt_tokens_cached = self._counter_cls( |
| 747 | name="vllm:prompt_tokens_cached", |
| 748 | documentation="Number of cached prompt tokens (local + external).", |
| 749 | labelnames=labelnames, |
| 750 | ) |
| 751 | self.counter_prompt_tokens_cached = create_metric_per_engine( |
| 752 | counter_prompt_tokens_cached, per_engine_labelvalues |
| 753 | ) |
| 754 | |
| 755 | counter_generation_tokens = self._counter_cls( |
| 756 | name="vllm:generation_tokens", |
| 757 | documentation="Number of generation tokens processed.", |
| 758 | labelnames=labelnames, |
| 759 | ) |
| 760 | self.counter_generation_tokens = create_metric_per_engine( |
| 761 | counter_generation_tokens, per_engine_labelvalues |
| 762 | ) |
| 763 | |
| 764 | self.counter_request_success: dict[FinishReason, dict[int, Counter]] = {} |
| 765 | counter_request_success_base = self._counter_cls( |
| 766 | name="vllm:request_success", |
| 767 | documentation="Count of successfully processed requests.", |
| 768 | labelnames=labelnames + ["finished_reason"], |
| 769 | ) |
| 770 | for reason in FinishReason: |
| 771 | self.counter_request_success[reason] = { |
| 772 | idx: counter_request_success_base.labels( |
| 773 | model_name, str(idx), str(reason) |
| 774 | ) |
| 775 | for idx in engine_indexes |
| 776 | } |
| 777 | |
| 778 | custom_buckets = vllm_config.observability_config.custom_histogram_buckets |
| 779 | request_tokens_buckets = histogram_buckets( |
| 780 | "request_tokens", max_model_len=max_model_len, overrides=custom_buckets |
| 781 | ) |
| 782 | iteration_tokens_buckets = histogram_buckets( |
| 783 | "iteration_tokens", overrides=custom_buckets |
| 784 | ) |
| 785 | request_params_n_buckets = histogram_buckets( |
| 786 | "request_params_n", overrides=custom_buckets |
| 787 | ) |
| 788 | time_to_first_token_buckets = histogram_buckets( |
| 789 | "time_to_first_token", overrides=custom_buckets |
| 790 | ) |
| 791 | inter_token_latency_buckets = histogram_buckets( |
| 792 | "inter_token_latency", overrides=custom_buckets |
| 793 | ) |
| 794 | request_latency_buckets = histogram_buckets( |
| 795 | "request_latency", overrides=custom_buckets |
| 796 | ) |
| 797 | request_num_preemptions_buckets = histogram_buckets( |
| 798 | "request_num_preemptions", overrides=custom_buckets |
| 799 | ) |
| 800 | |
| 801 | # |
| 802 | # Histograms of counts |
| 803 | # |
| 804 | histogram_num_prompt_tokens_request = self._histogram_cls( |
| 805 | name="vllm:request_prompt_tokens", |
| 806 | documentation="Number of prefill tokens processed.", |
| 807 | buckets=request_tokens_buckets, |
| 808 | labelnames=labelnames, |
| 809 | ) |
| 810 | self.histogram_num_prompt_tokens_request = create_metric_per_engine( |
| 811 | histogram_num_prompt_tokens_request, per_engine_labelvalues |
| 812 | ) |
| 813 | |
| 814 | histogram_num_generation_tokens_request = self._histogram_cls( |
| 815 | name="vllm:request_generation_tokens", |
| 816 | documentation="Number of generation tokens processed.", |
| 817 | buckets=request_tokens_buckets, |
| 818 | labelnames=labelnames, |
| 819 | ) |
| 820 | self.histogram_num_generation_tokens_request = create_metric_per_engine( |
| 821 | histogram_num_generation_tokens_request, per_engine_labelvalues |
| 822 | ) |
| 823 | |
| 824 | # TODO: This metric might be incorrect in case of using multiple |
| 825 | # api_server counts which uses prometheus mp. |
| 826 | # See: https://github.com/vllm-project/vllm/pull/18053 |
| 827 | histogram_iteration_tokens = self._histogram_cls( |
| 828 | name="vllm:iteration_tokens_total", |
| 829 | documentation="Histogram of number of tokens per engine_step.", |
| 830 | buckets=iteration_tokens_buckets, |
| 831 | labelnames=labelnames, |
| 832 | ) |
| 833 | self.histogram_iteration_tokens = create_metric_per_engine( |
| 834 | histogram_iteration_tokens, per_engine_labelvalues |
| 835 | ) |
| 836 | |
| 837 | histogram_max_num_generation_tokens_request = self._histogram_cls( |
| 838 | name="vllm:request_max_num_generation_tokens", |
| 839 | documentation="Histogram of maximum number of requested generation tokens.", |
| 840 | buckets=request_tokens_buckets, |
| 841 | labelnames=labelnames, |
| 842 | ) |
| 843 | self.histogram_max_num_generation_tokens_request = create_metric_per_engine( |
| 844 | histogram_max_num_generation_tokens_request, per_engine_labelvalues |
| 845 | ) |
| 846 | |
| 847 | histogram_n_request = self._histogram_cls( |
| 848 | name="vllm:request_params_n", |
| 849 | documentation="Histogram of the n request parameter.", |
| 850 | buckets=request_params_n_buckets, |
| 851 | labelnames=labelnames, |
| 852 | ) |
| 853 | self.histogram_n_request = create_metric_per_engine( |
| 854 | histogram_n_request, per_engine_labelvalues |
| 855 | ) |
| 856 | |
| 857 | histogram_max_tokens_request = self._histogram_cls( |
| 858 | name="vllm:request_params_max_tokens", |
| 859 | documentation="Histogram of the max_tokens request parameter.", |
| 860 | buckets=request_tokens_buckets, |
| 861 | labelnames=labelnames, |
| 862 | ) |
| 863 | self.histogram_max_tokens_request = create_metric_per_engine( |
| 864 | histogram_max_tokens_request, per_engine_labelvalues |
| 865 | ) |
| 866 | |
| 867 | # |
| 868 | # Histogram of timing intervals |
| 869 | # |
| 870 | histogram_time_to_first_token = self._histogram_cls( |
| 871 | name="vllm:time_to_first_token_seconds", |
| 872 | documentation="Histogram of time to first token in seconds.", |
| 873 | buckets=time_to_first_token_buckets, |
| 874 | labelnames=labelnames, |
| 875 | ) |
| 876 | self.histogram_time_to_first_token = create_metric_per_engine( |
| 877 | histogram_time_to_first_token, per_engine_labelvalues |
| 878 | ) |
| 879 | |
| 880 | histogram_inter_token_latency = self._histogram_cls( |
| 881 | name="vllm:inter_token_latency_seconds", |
| 882 | documentation="Histogram of inter-token latency in seconds.", |
| 883 | buckets=inter_token_latency_buckets, |
| 884 | labelnames=labelnames, |
| 885 | ) |
| 886 | self.histogram_inter_token_latency = create_metric_per_engine( |
| 887 | histogram_inter_token_latency, per_engine_labelvalues |
| 888 | ) |
| 889 | |
| 890 | histogram_request_time_per_output_token = self._histogram_cls( |
| 891 | name="vllm:request_time_per_output_token_seconds", |
| 892 | documentation="Histogram of time_per_output_token_seconds per request.", |
| 893 | buckets=inter_token_latency_buckets, |
| 894 | labelnames=labelnames, |
| 895 | ) |
| 896 | self.histogram_request_time_per_output_token = create_metric_per_engine( |
| 897 | histogram_request_time_per_output_token, per_engine_labelvalues |
| 898 | ) |
| 899 | |
| 900 | histogram_e2e_time_request = self._histogram_cls( |
| 901 | name="vllm:e2e_request_latency_seconds", |
| 902 | documentation="Histogram of e2e request latency in seconds.", |
| 903 | buckets=request_latency_buckets, |
| 904 | labelnames=labelnames, |
| 905 | ) |
| 906 | self.histogram_e2e_time_request = create_metric_per_engine( |
| 907 | histogram_e2e_time_request, per_engine_labelvalues |
| 908 | ) |
| 909 | |
| 910 | histogram_queue_time_request = self._histogram_cls( |
| 911 | name="vllm:request_queue_time_seconds", |
| 912 | documentation="Histogram of time spent in WAITING phase for request.", |
| 913 | buckets=request_latency_buckets, |
| 914 | labelnames=labelnames, |
| 915 | ) |
| 916 | self.histogram_queue_time_request = create_metric_per_engine( |
| 917 | histogram_queue_time_request, per_engine_labelvalues |
| 918 | ) |
| 919 | |
| 920 | histogram_inference_time_request = self._histogram_cls( |
| 921 | name="vllm:request_inference_time_seconds", |
| 922 | documentation="Histogram of time spent in RUNNING phase for request.", |
| 923 | buckets=request_latency_buckets, |
| 924 | labelnames=labelnames, |
| 925 | ) |
| 926 | self.histogram_inference_time_request = create_metric_per_engine( |
| 927 | histogram_inference_time_request, per_engine_labelvalues |
| 928 | ) |
| 929 | |
| 930 | histogram_prefill_time_request = self._histogram_cls( |
| 931 | name="vllm:request_prefill_time_seconds", |
| 932 | documentation="Histogram of time spent in PREFILL phase for request.", |
| 933 | buckets=request_latency_buckets, |
| 934 | labelnames=labelnames, |
| 935 | ) |
| 936 | self.histogram_prefill_time_request = create_metric_per_engine( |
| 937 | histogram_prefill_time_request, per_engine_labelvalues |
| 938 | ) |
| 939 | |
| 940 | histogram_decode_time_request = self._histogram_cls( |
| 941 | name="vllm:request_decode_time_seconds", |
| 942 | documentation="Histogram of time spent in DECODE phase for request.", |
| 943 | buckets=request_latency_buckets, |
| 944 | labelnames=labelnames, |
| 945 | ) |
| 946 | self.histogram_decode_time_request = create_metric_per_engine( |
| 947 | histogram_decode_time_request, per_engine_labelvalues |
| 948 | ) |
| 949 | |
| 950 | histogram_request_num_preemptions = self._histogram_cls( |
| 951 | name="vllm:request_num_preemptions", |
| 952 | documentation="Histogram of the number of times a request was preempted.", |
| 953 | buckets=request_num_preemptions_buckets, |
| 954 | labelnames=labelnames, |
| 955 | ) |
| 956 | self.histogram_request_num_preemptions = create_metric_per_engine( |
| 957 | histogram_request_num_preemptions, per_engine_labelvalues |
| 958 | ) |
| 959 | |
| 960 | histogram_prefill_kv_computed_request = self._histogram_cls( |
| 961 | name="vllm:request_prefill_kv_computed_tokens", |
| 962 | documentation=( |
| 963 | "Histogram of new KV tokens computed during prefill " |
| 964 | "(excluding cached tokens)." |
| 965 | ), |
| 966 | buckets=request_tokens_buckets, |
| 967 | labelnames=labelnames, |
| 968 | ) |
| 969 | self.histogram_prefill_kv_computed_request = create_metric_per_engine( |
| 970 | histogram_prefill_kv_computed_request, per_engine_labelvalues |
| 971 | ) |
| 972 | |
| 973 | # |
| 974 | # KV Cache residency metrics |
| 975 | # |
| 976 | if self.kv_cache_metrics_enabled: |
| 977 | kv_cache_residency_buckets = histogram_buckets( |
| 978 | "kv_cache_residency", overrides=custom_buckets |
| 979 | ) |
| 980 | |
| 981 | histogram_kv_block_lifetime = self._histogram_cls( |
| 982 | name="vllm:kv_block_lifetime_seconds", |
| 983 | documentation=( |
| 984 | "Histogram of KV cache block lifetime from allocation to eviction. " |
| 985 | "Sampled metrics (controlled by --kv-cache-metrics-sample)." |
| 986 | ), |
| 987 | buckets=kv_cache_residency_buckets, |
| 988 | labelnames=labelnames, |
| 989 | ) |
| 990 | self.histogram_kv_block_lifetime = create_metric_per_engine( |
| 991 | histogram_kv_block_lifetime, per_engine_labelvalues |
| 992 | ) |
| 993 | |
| 994 | histogram_kv_block_idle_before_evict = self._histogram_cls( |
| 995 | name="vllm:kv_block_idle_before_evict_seconds", |
| 996 | documentation=( |
| 997 | "Histogram of idle time before KV cache block eviction. " |
| 998 | "Sampled metrics (controlled by --kv-cache-metrics-sample)." |
| 999 | ), |
| 1000 | buckets=kv_cache_residency_buckets, |
| 1001 | labelnames=labelnames, |
| 1002 | ) |
| 1003 | self.histogram_kv_block_idle_before_evict = create_metric_per_engine( |
| 1004 | histogram_kv_block_idle_before_evict, per_engine_labelvalues |
| 1005 | ) |
| 1006 | |
| 1007 | histogram_kv_block_reuse_gap = self._histogram_cls( |
| 1008 | name="vllm:kv_block_reuse_gap_seconds", |
| 1009 | documentation=( |
| 1010 | "Histogram of time gaps between consecutive KV cache block " |
| 1011 | "accesses. Only the most recent accesses are recorded " |
| 1012 | "(ring buffer). Sampled metrics (controlled by " |
| 1013 | "--kv-cache-metrics-sample)." |
| 1014 | ), |
| 1015 | buckets=kv_cache_residency_buckets, |
| 1016 | labelnames=labelnames, |
| 1017 | ) |
| 1018 | self.histogram_kv_block_reuse_gap = create_metric_per_engine( |
| 1019 | histogram_kv_block_reuse_gap, per_engine_labelvalues |
| 1020 | ) |
| 1021 | else: |
| 1022 | self.histogram_kv_block_lifetime = {} |
| 1023 | self.histogram_kv_block_idle_before_evict = {} |
| 1024 | self.histogram_kv_block_reuse_gap = {} |
| 1025 | |
| 1026 | # |
| 1027 | # LoRA metrics |
| 1028 | # |
| 1029 | |
| 1030 | # TODO: This metric might be incorrect in case of using multiple |
| 1031 | # api_server counts which uses prometheus mp. |
| 1032 | self.gauge_lora_info: Gauge | None = None |
| 1033 | if vllm_config.lora_config is not None: |
| 1034 | if len(self.engine_indexes) > 1: |
| 1035 | logger.warning( |
| 1036 | "vllm:lora_requests_info prometheus metrics may be " |
| 1037 | "incorrect/misleading with data parallel deployments." |
| 1038 | ) |
| 1039 | self.labelname_max_lora = "max_lora" |
| 1040 | self.labelname_waiting_lora_adapters = "waiting_lora_adapters" |
| 1041 | self.labelname_running_lora_adapters = "running_lora_adapters" |
| 1042 | self.max_lora = vllm_config.lora_config.max_loras |
| 1043 | self.gauge_lora_info = self._gauge_cls( |
| 1044 | name="vllm:lora_requests_info", |
| 1045 | documentation="Running stats on lora requests.", |
| 1046 | multiprocess_mode="sum", |
| 1047 | labelnames=[ |
| 1048 | self.labelname_max_lora, |
| 1049 | self.labelname_waiting_lora_adapters, |
| 1050 | self.labelname_running_lora_adapters, |
| 1051 | ], |
| 1052 | ) |
| 1053 | |
| 1054 | def log_metrics_info(self, type: str, config_obj: SupportsMetricsInfo): |
| 1055 | metrics_info = config_obj.metrics_info() |
| 1056 | metrics_info["engine"] = "" |
| 1057 | |
| 1058 | name, documentation = None, None |
| 1059 | if type == "cache_config": |
| 1060 | name = "vllm:cache_config_info" |
| 1061 | documentation = "Information of the LLMEngine CacheConfig" |
| 1062 | assert name is not None, f"Unknown metrics info type {type}" |
| 1063 | |
| 1064 | # Info type metrics are syntactic sugar for a gauge permanently set to 1 |
| 1065 | # Since prometheus multiprocessing mode does not support Info, emulate |
| 1066 | # info here with a gauge. |
| 1067 | info_gauge = self._gauge_cls( |
| 1068 | name=name, |
| 1069 | documentation=documentation, |
| 1070 | multiprocess_mode="mostrecent", |
| 1071 | labelnames=metrics_info.keys(), |
| 1072 | ) |
| 1073 | for engine_index in self.engine_indexes: |
| 1074 | metrics_info = config_obj.metrics_info() |
| 1075 | metrics_info["engine"] = str(engine_index) |
| 1076 | info_gauge.labels(**metrics_info).set(1) |
| 1077 | |
| 1078 | def record( |
| 1079 | self, |
| 1080 | scheduler_stats: SchedulerStats | None, |
| 1081 | iteration_stats: IterationStats | None, |
| 1082 | mm_cache_stats: MultiModalCacheStats | None = None, |
| 1083 | engine_idx: int = 0, |
| 1084 | ): |
| 1085 | """Log to prometheus.""" |
| 1086 | if scheduler_stats is not None: |
| 1087 | self.gauge_scheduler_running[engine_idx].set( |
| 1088 | scheduler_stats.num_running_reqs |
| 1089 | ) |
| 1090 | total_waiting = ( |
| 1091 | scheduler_stats.num_waiting_reqs |
| 1092 | + scheduler_stats.num_skipped_waiting_reqs |
| 1093 | ) |
| 1094 | self.gauge_scheduler_waiting[engine_idx].set(total_waiting) |
| 1095 | self.gauge_waiting_by_reason[WAITING_REASON_CAPACITY][engine_idx].set( |
| 1096 | scheduler_stats.num_waiting_reqs |
| 1097 | ) |
| 1098 | self.gauge_waiting_by_reason[WAITING_REASON_DEFERRED][engine_idx].set( |
| 1099 | scheduler_stats.num_skipped_waiting_reqs |
| 1100 | ) |
| 1101 | for stage, gauges in self.gauge_kv_fetch_by_stage.items(): |
| 1102 | gauges[engine_idx].set( |
| 1103 | scheduler_stats.num_kv_fetch_reqs_by_stage.get(stage, 0) |
| 1104 | ) |
| 1105 | self.gauge_kv_cache_usage[engine_idx].set(scheduler_stats.kv_cache_usage) |
| 1106 | |
| 1107 | self.counter_prefix_cache_queries[engine_idx].inc( |
| 1108 | scheduler_stats.prefix_cache_stats.queries |
| 1109 | ) |
| 1110 | self.counter_prefix_cache_hits[engine_idx].inc( |
| 1111 | scheduler_stats.prefix_cache_stats.hits |
| 1112 | ) |
| 1113 | |
| 1114 | if scheduler_stats.connector_prefix_cache_stats is not None: |
| 1115 | self.counter_connector_prefix_cache_queries[engine_idx].inc( |
| 1116 | scheduler_stats.connector_prefix_cache_stats.queries |
| 1117 | ) |
| 1118 | self.counter_connector_prefix_cache_hits[engine_idx].inc( |
| 1119 | scheduler_stats.connector_prefix_cache_stats.hits |
| 1120 | ) |
| 1121 | |
| 1122 | if scheduler_stats.spec_decoding_stats is not None: |
| 1123 | self.spec_decoding_prom.observe( |
| 1124 | scheduler_stats.spec_decoding_stats, engine_idx |
| 1125 | ) |
| 1126 | |
| 1127 | if scheduler_stats.kv_connector_stats is not None: |
| 1128 | self.kv_connector_prom.observe( |
| 1129 | scheduler_stats.kv_connector_stats, engine_idx |
| 1130 | ) |
| 1131 | |
| 1132 | if scheduler_stats.ec_connector_stats is not None: |
| 1133 | self.ec_connector_prom.observe( |
| 1134 | scheduler_stats.ec_connector_stats, engine_idx |
| 1135 | ) |
| 1136 | |
| 1137 | if scheduler_stats.perf_stats is not None: |
| 1138 | self.perf_metrics_prom.observe(scheduler_stats.perf_stats, engine_idx) |
| 1139 | |
| 1140 | if ( |
| 1141 | self.kv_cache_metrics_enabled |
| 1142 | and scheduler_stats.kv_cache_eviction_events |
| 1143 | ): |
| 1144 | lifetime_hist = self.histogram_kv_block_lifetime[engine_idx] |
| 1145 | idle_hist = self.histogram_kv_block_idle_before_evict[engine_idx] |
| 1146 | reuse_hist = self.histogram_kv_block_reuse_gap[engine_idx] |
| 1147 | |
| 1148 | for event in scheduler_stats.kv_cache_eviction_events: |
| 1149 | lifetime_hist.observe(event.lifetime_seconds) |
| 1150 | idle_hist.observe(event.idle_seconds) |
| 1151 | for gap in event.reuse_gaps_seconds: |
| 1152 | reuse_hist.observe(gap) |
| 1153 | |
| 1154 | if self.gauge_lora_info is not None: |
| 1155 | running_lora_adapters = ",".join( |
| 1156 | scheduler_stats.running_lora_adapters.keys() |
| 1157 | ) |
| 1158 | waiting_lora_adapters = ",".join( |
| 1159 | scheduler_stats.waiting_lora_adapters.keys() |
| 1160 | ) |
| 1161 | lora_info_labels = { |
| 1162 | self.labelname_running_lora_adapters: running_lora_adapters, |
| 1163 | self.labelname_waiting_lora_adapters: waiting_lora_adapters, |
| 1164 | self.labelname_max_lora: self.max_lora, |
| 1165 | } |
| 1166 | self.gauge_lora_info.labels(**lora_info_labels).set_to_current_time() |
| 1167 | |
| 1168 | if mm_cache_stats is not None: |
| 1169 | self.counter_mm_cache_queries[engine_idx].inc(mm_cache_stats.queries) |
| 1170 | self.counter_mm_cache_hits[engine_idx].inc(mm_cache_stats.hits) |
| 1171 | |
| 1172 | if iteration_stats is None: |
| 1173 | return |
| 1174 | if envs.VLLM_COMPUTE_NANS_IN_LOGITS: |
| 1175 | self.counter_corrupted_requests[engine_idx].inc( |
| 1176 | iteration_stats.num_corrupted_reqs |
| 1177 | ) |
| 1178 | self.counter_num_preempted_reqs[engine_idx].inc( |
| 1179 | iteration_stats.num_preempted_reqs |
| 1180 | ) |
| 1181 | self.counter_prompt_tokens[engine_idx].inc(iteration_stats.num_prompt_tokens) |
| 1182 | # Labeled prompt token counters by source |
| 1183 | pts = iteration_stats.prompt_token_stats |
| 1184 | for source in PromptTokenStats.ALL_SOURCES: |
| 1185 | self.counter_prompt_tokens_by_source[source][engine_idx].inc( |
| 1186 | pts.get_by_source(source) |
| 1187 | ) |
| 1188 | self.counter_prompt_tokens_cached[engine_idx].inc(pts.cached_tokens) |
| 1189 | self.counter_generation_tokens[engine_idx].inc( |
| 1190 | iteration_stats.num_generation_tokens |
| 1191 | ) |
| 1192 | self.histogram_iteration_tokens[engine_idx].observe( |
| 1193 | iteration_stats.prompt_token_stats.computed |
| 1194 | + iteration_stats.num_generation_tokens |
| 1195 | ) |
| 1196 | |
| 1197 | for max_gen_tokens in iteration_stats.max_num_generation_tokens_iter: |
| 1198 | self.histogram_max_num_generation_tokens_request[engine_idx].observe( |
| 1199 | max_gen_tokens |
| 1200 | ) |
| 1201 | for n_param in iteration_stats.n_params_iter: |
| 1202 | self.histogram_n_request[engine_idx].observe(n_param) |
| 1203 | for ttft in iteration_stats.time_to_first_tokens_iter: |
| 1204 | self.histogram_time_to_first_token[engine_idx].observe(ttft) |
| 1205 | for itl in iteration_stats.inter_token_latencies_iter: |
| 1206 | self.histogram_inter_token_latency[engine_idx].observe(itl) |
| 1207 | |
| 1208 | for finished_request in iteration_stats.finished_requests: |
| 1209 | self.counter_request_success[finished_request.finish_reason][ |
| 1210 | engine_idx |
| 1211 | ].inc() |
| 1212 | self.histogram_e2e_time_request[engine_idx].observe( |
| 1213 | finished_request.e2e_latency |
| 1214 | ) |
| 1215 | self.histogram_queue_time_request[engine_idx].observe( |
| 1216 | finished_request.queued_time |
| 1217 | ) |
| 1218 | self.histogram_prefill_time_request[engine_idx].observe( |
| 1219 | finished_request.prefill_time |
| 1220 | ) |
| 1221 | self.histogram_inference_time_request[engine_idx].observe( |
| 1222 | finished_request.inference_time |
| 1223 | ) |
| 1224 | self.histogram_decode_time_request[engine_idx].observe( |
| 1225 | finished_request.decode_time |
| 1226 | ) |
| 1227 | self.histogram_request_num_preemptions[engine_idx].observe( |
| 1228 | finished_request.num_preemptions |
| 1229 | ) |
| 1230 | # Calculate prefill KV compute (excludes cached tokens) |
| 1231 | prefill_kv_computed = finished_request.num_prompt_tokens - max( |
| 1232 | finished_request.num_cached_tokens, 0 |
| 1233 | ) |
| 1234 | self.histogram_prefill_kv_computed_request[engine_idx].observe( |
| 1235 | prefill_kv_computed |
| 1236 | ) |
| 1237 | self.histogram_num_prompt_tokens_request[engine_idx].observe( |
| 1238 | finished_request.num_prompt_tokens |
| 1239 | ) |
| 1240 | self.histogram_num_generation_tokens_request[engine_idx].observe( |
| 1241 | finished_request.num_generation_tokens |
| 1242 | ) |
| 1243 | self.histogram_request_time_per_output_token[engine_idx].observe( |
| 1244 | finished_request.mean_time_per_output_token |
| 1245 | ) |
| 1246 | if finished_request.max_tokens_param: |
| 1247 | self.histogram_max_tokens_request[engine_idx].observe( |
| 1248 | finished_request.max_tokens_param |
| 1249 | ) |
| 1250 | |
| 1251 | def record_sleep_state(self, sleep: int = 0, level: int = 0): |
| 1252 | awake = 1 |
| 1253 | discard_all = 0 |
| 1254 | weights_offloaded = 0 |
| 1255 | |
| 1256 | if sleep == 1: |
| 1257 | awake = 0 |
| 1258 | if level == 1: |
| 1259 | weights_offloaded = 1 |
| 1260 | elif level == 2: |
| 1261 | discard_all = 1 |
| 1262 | |
| 1263 | for engine_idx in self.engine_indexes: |
| 1264 | self.gauge_engine_sleep_state["discard_all"][engine_idx].set(discard_all) |
| 1265 | self.gauge_engine_sleep_state["weights_offloaded"][engine_idx].set( |
| 1266 | weights_offloaded |
| 1267 | ) |
| 1268 | self.gauge_engine_sleep_state["awake"][engine_idx].set(awake) |
| 1269 | |
| 1270 | def log_engine_initialized(self): |
| 1271 | self.log_metrics_info("cache_config", self.vllm_config.cache_config) |
| 1272 | |
| 1273 | |
| 1274 | class StatLoggerManager: |
| 1275 | """StatLoggerManager: |
| 1276 | Logging happens at the level of the EngineCore (per scheduler). |
| 1277 | * DP: >1 EngineCore per AsyncLLM - loggers for each EngineCore. |
| 1278 | * With Local Logger, just make N copies for N EngineCores. |
| 1279 | * With Prometheus, we need a single logger with N "labels" |
| 1280 | |
| 1281 | This class abstracts away this implementation detail from |
| 1282 | the AsyncLLM, allowing the AsyncLLM to just call .record() |
| 1283 | and .log() to a simple interface. |
| 1284 | """ |
| 1285 | |
| 1286 | def __init__( |
| 1287 | self, |
| 1288 | vllm_config: VllmConfig, |
| 1289 | engine_idxs: list[int] | None = None, |
| 1290 | custom_stat_loggers: list[StatLoggerFactory] | None = None, |
| 1291 | enable_default_loggers: bool = True, |
| 1292 | aggregate_engine_logging: bool = False, |
| 1293 | client_count: int = 1, |
| 1294 | ): |
| 1295 | self.engine_indexes = engine_idxs if engine_idxs else [0] |
| 1296 | self.stat_loggers: list[AggregateStatLoggerBase] = [] |
| 1297 | stat_logger_factories: list[StatLoggerFactory] = [] |
| 1298 | if custom_stat_loggers is not None: |
| 1299 | stat_logger_factories.extend(custom_stat_loggers) |
| 1300 | if enable_default_loggers and logger.isEnabledFor(logging.INFO): |
| 1301 | if client_count > 1: |
| 1302 | logger.warning( |
| 1303 | "AsyncLLM created with api_server_count more than 1; " |
| 1304 | "disabling stats logging to avoid incomplete stats." |
| 1305 | ) |
| 1306 | else: |
| 1307 | default_logger_factory = ( |
| 1308 | AggregatedLoggingStatLogger |
| 1309 | if aggregate_engine_logging |
| 1310 | else LoggingStatLogger |
| 1311 | ) |
| 1312 | stat_logger_factories.append(default_logger_factory) |
| 1313 | custom_prometheus_logger: bool = False |
| 1314 | for stat_logger_factory in stat_logger_factories: |
| 1315 | if isinstance(stat_logger_factory, type) and issubclass( |
| 1316 | stat_logger_factory, AggregateStatLoggerBase |
| 1317 | ): |
| 1318 | global_stat_logger = stat_logger_factory( |
| 1319 | vllm_config=vllm_config, |
| 1320 | engine_indexes=self.engine_indexes, |
| 1321 | ) |
| 1322 | if isinstance(global_stat_logger, PrometheusStatLogger): |
| 1323 | custom_prometheus_logger = True |
| 1324 | else: |
| 1325 | # per engine logger |
| 1326 | global_stat_logger = PerEngineStatLoggerAdapter( |
| 1327 | vllm_config=vllm_config, |
| 1328 | engine_indexes=self.engine_indexes, |
| 1329 | per_engine_stat_logger_factory=stat_logger_factory, # type: ignore[arg-type] |
| 1330 | ) |
| 1331 | self.stat_loggers.append(global_stat_logger) |
| 1332 | if not custom_prometheus_logger: |
| 1333 | self.stat_loggers.append( |
| 1334 | PrometheusStatLogger(vllm_config, self.engine_indexes) |
| 1335 | ) |
| 1336 | |
| 1337 | def record( |
| 1338 | self, |
| 1339 | scheduler_stats: SchedulerStats | None, |
| 1340 | iteration_stats: IterationStats | None, |
| 1341 | mm_cache_stats: MultiModalCacheStats | None = None, |
| 1342 | engine_idx: int | None = None, |
| 1343 | ): |
| 1344 | if engine_idx is None: |
| 1345 | engine_idx = 0 |
| 1346 | for stat_logger in self.stat_loggers: |
| 1347 | stat_logger.record( |
| 1348 | scheduler_stats, |
| 1349 | iteration_stats, |
| 1350 | mm_cache_stats=mm_cache_stats, |
| 1351 | engine_idx=engine_idx, |
| 1352 | ) |
| 1353 | |
| 1354 | def record_sleep_state(self, sleep: int = 0, level: int = 0): |
| 1355 | for logger in self.stat_loggers: |
| 1356 | logger.record_sleep_state(sleep, level) |
| 1357 | |
| 1358 | def log(self): |
| 1359 | for logger in self.stat_loggers: |
| 1360 | logger.log() |
| 1361 | |
| 1362 | def log_engine_initialized(self): |
| 1363 | for agg_logger in self.stat_loggers: |
| 1364 | agg_logger.log_engine_initialized() |