loggers.py 44.4 KB
Newer Older
1
# SPDX-License-Identifier: Apache-2.0
2
# SPDX-FileCopyrightText: Copyright contributors to the vLLM project
3

4
import logging
5
6
import time
from abc import ABC, abstractmethod
7
8
from collections.abc import Callable
from typing import TypeAlias
9

10
from prometheus_client import Counter, Gauge, Histogram
11

12
import vllm.envs as envs
13
from vllm.config import SupportsMetricsInfo, VllmConfig
14
15
16
17
from vllm.distributed.kv_transfer.kv_connector.v1.metrics import (
    KVConnectorLogging,
    KVConnectorPrometheus,
)
18
from vllm.logger import init_logger
19
from vllm.plugins import load_plugins_by_group
20
from vllm.v1.engine import FinishReason
21
from vllm.v1.metrics.prometheus import unregister_vllm_metrics
22
23
24
25
26
27
from vllm.v1.metrics.stats import (
    CachingMetrics,
    IterationStats,
    MultiModalCacheStats,
    SchedulerStats,
)
28
from vllm.v1.spec_decode.metrics import SpecDecodingLogging, SpecDecodingProm
29
30
31

logger = init_logger(__name__)

32
33
34
PerEngineStatLoggerFactory = Callable[[VllmConfig, int], "StatLoggerBase"]
AggregateStatLoggerFactory = type["AggregateStatLoggerBase"]
StatLoggerFactory = AggregateStatLoggerFactory | PerEngineStatLoggerFactory
35

36
37

class StatLoggerBase(ABC):
38
39
40
41
42
43
44
45
    """Interface for logging metrics.

    API users may define custom loggers that implement this interface.
    However, note that the `SchedulerStats` and `IterationStats` classes
    are not considered stable interfaces and may change in future versions.
    """

    @abstractmethod
46
    def __init__(self, vllm_config: VllmConfig, engine_index: int = 0): ...
47
48

    @abstractmethod
49
50
    def record(
        self,
51
52
53
        scheduler_stats: SchedulerStats | None,
        iteration_stats: IterationStats | None,
        mm_cache_stats: MultiModalCacheStats | None = None,
54
55
        engine_idx: int = 0,
    ): ...
56

57
    @abstractmethod
58
    def log_engine_initialized(self): ...
59

60
61
62
    def log(self):  # noqa
        pass

63
64
65
    def record_sleep_state(self, is_awake: int, level: int):  # noqa
        pass

66

67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
def load_stat_logger_plugin_factories() -> list[StatLoggerFactory]:
    factories: list[StatLoggerFactory] = []

    for name, plugin_class in load_plugins_by_group("vllm.stat_logger_plugins").items():
        if not isinstance(plugin_class, type) or not issubclass(
            plugin_class, StatLoggerBase
        ):
            raise TypeError(
                f"Stat logger plugin {name!r} must be a subclass of "
                f"StatLoggerBase (got {plugin_class!r})."
            )

        factories.append(plugin_class)

    return factories


84
85
86
87
88
89
90
91
class AggregateStatLoggerBase(StatLoggerBase):
    """Abstract base class for loggers that
    aggregate across multiple DP engines."""

    @abstractmethod
    def __init__(self, vllm_config: VllmConfig, engine_indexes: list[int]): ...


92
class LoggingStatLogger(StatLoggerBase):
93
    def __init__(self, vllm_config: VllmConfig, engine_index: int = 0):
94
        self.engine_index = engine_index
95
        self.vllm_config = vllm_config
96
        self._reset(time.monotonic())
97

98
        self.last_scheduler_stats = SchedulerStats()
99
100

        # Caching metrics. This cannot be reset.
101
        # TODO: Make the interval configurable.
102
        self.prefix_caching_metrics = CachingMetrics()
103
        self.connector_prefix_caching_metrics = CachingMetrics()
104
105
        self.mm_caching_metrics = CachingMetrics()

106
        self.spec_decoding_logging = SpecDecodingLogging()
107
        kv_tranfer_config = self.vllm_config.kv_transfer_config
108
        self.kv_connector_logging = KVConnectorLogging(kv_tranfer_config)
109
110
        self.last_prompt_throughput: float = 0.0
        self.last_generation_throughput: float = 0.0
111
112
        self.engine_is_idle = False
        self.aggregated = False
113

114
115
116
117
    def _reset(self, now):
        self.last_log_time = now

        # Tracked stats over current local logging interval.
118
119
        self.num_prompt_tokens: int = 0
        self.num_generation_tokens: int = 0
120
        self.num_corrupted_reqs: int = 0
121

122
123
    def _track_iteration_stats(self, iteration_stats: IterationStats):
        # Save tracked stats for token counters.
124
125
        self.num_prompt_tokens += iteration_stats.num_prompt_tokens
        self.num_generation_tokens += iteration_stats.num_generation_tokens
126
        self.num_corrupted_reqs += iteration_stats.num_corrupted_reqs
127

128
    def _get_throughput(self, tracked_stats: int, now: float) -> float:
129
        # Compute summary metrics for tracked stats
130
131
132
133
        delta_time = now - self.last_log_time
        if delta_time <= 0.0:
            return 0.0
        return float(tracked_stats / delta_time)
134

135
136
137
138
    @property
    def log_prefix(self):
        return "Engine {:03d}: ".format(self.engine_index)

139
140
    def record(
        self,
141
142
143
        scheduler_stats: SchedulerStats | None,
        iteration_stats: IterationStats | None,
        mm_cache_stats: MultiModalCacheStats | None = None,
144
145
        engine_idx: int = 0,
    ):
146
        """Log Stats to standard output."""
147
148
        if iteration_stats:
            self._track_iteration_stats(iteration_stats)
149

150
        if scheduler_stats is not None:
151
            self.prefix_caching_metrics.observe(scheduler_stats.prefix_cache_stats)
152

153
154
155
156
157
            if scheduler_stats.connector_prefix_cache_stats is not None:
                self.connector_prefix_caching_metrics.observe(
                    scheduler_stats.connector_prefix_cache_stats
                )

158
            if scheduler_stats.spec_decoding_stats is not None:
159
                self.spec_decoding_logging.observe(scheduler_stats.spec_decoding_stats)
160
            if kv_connector_stats := scheduler_stats.kv_connector_stats:
161
                self.kv_connector_logging.observe(kv_connector_stats)
162
163
            if not self.aggregated:
                self.last_scheduler_stats = scheduler_stats
164
165
166
        if mm_cache_stats:
            self.mm_caching_metrics.observe(mm_cache_stats)

167
    def _update_stats(self):
168
        now = time.monotonic()
169
        prompt_throughput = self._get_throughput(self.num_prompt_tokens, now)
170
        generation_throughput = self._get_throughput(self.num_generation_tokens, now)
171
172

        self._reset(now)
173
        self.engine_is_idle = not any(
174
175
176
177
178
179
            (
                prompt_throughput,
                generation_throughput,
                self.last_prompt_throughput,
                self.last_generation_throughput,
            )
180
        )
181
182
183
        self.last_generation_throughput = generation_throughput
        self.last_prompt_throughput = prompt_throughput

184
185
186
187
188
189
190
191
192
    def aggregate_scheduler_stats(self):
        # noop for per engine loggers
        return

    def log(self):
        self._update_stats()
        self.aggregate_scheduler_stats()
        # Avoid log noise on an idle production system
        log_fn = logger.debug if self.engine_is_idle else logger.info
193
        # Format and print output.
194
195
196
197
198
199
        log_parts = [
            "Avg prompt throughput: %.1f tokens/s",
            "Avg generation throughput: %.1f tokens/s",
            "Running: %d reqs",
            "Waiting: %d reqs",
            "GPU KV cache usage: %.1f%%",
200
            "Prefix cache hit rate: %.1f%%",
201
202
        ]
        log_args = [
203
204
205
206
207
            self.last_prompt_throughput,
            self.last_generation_throughput,
            self.last_scheduler_stats.num_running_reqs,
            self.last_scheduler_stats.num_waiting_reqs,
            self.last_scheduler_stats.kv_cache_usage * 100,
208
            self.prefix_caching_metrics.hit_rate * 100,
209
        ]
210
211
212
213

        if envs.VLLM_COMPUTE_NANS_IN_LOGITS:
            log_parts.append("Corrupted: %d reqs")
            log_args.append(self.num_corrupted_reqs)
214
215
216
        if not self.connector_prefix_caching_metrics.empty:
            log_parts.append("External prefix cache hit rate: %.1f%%")
            log_args.append(self.connector_prefix_caching_metrics.hit_rate * 100)
217
        if not self.mm_caching_metrics.empty:
218
219
220
221
            log_parts.append("MM cache hit rate: %.1f%%")
            log_args.append(self.mm_caching_metrics.hit_rate * 100)

        log_fn(
222
            self.log_prefix + ", ".join(log_parts),
223
            *log_args,
224
        )
225

226
        self.spec_decoding_logging.log(log_fn=log_fn)
227
        self.kv_connector_logging.log(log_fn=log_fn)
228

229
    def log_engine_initialized(self):
230
        if self.vllm_config.cache_config.num_gpu_blocks:
231
            logger.debug(
232
                "Engine %03d: vllm cache_config_info with initialization "
233
234
235
236
                "after num_gpu_blocks is: %d",
                self.engine_index,
                self.vllm_config.cache_config.num_gpu_blocks,
            )
237

238

239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
class AggregatedLoggingStatLogger(LoggingStatLogger, AggregateStatLoggerBase):
    def __init__(
        self,
        vllm_config: VllmConfig,
        engine_indexes: list[int],
    ):
        self.engine_indexes = engine_indexes
        self.last_scheduler_stats_dict: dict[int, SchedulerStats] = {
            idx: SchedulerStats() for idx in self.engine_indexes
        }
        LoggingStatLogger.__init__(self, vllm_config, engine_index=-1)
        self.aggregated = True

    @property
    def log_prefix(self):
        return "{} Engines Aggregated: ".format(len(self.engine_indexes))

    def record(
        self,
        scheduler_stats: SchedulerStats | None,
        iteration_stats: IterationStats | None,
        mm_cache_stats: MultiModalCacheStats | None = None,
        engine_idx: int = 0,
    ):
        if engine_idx not in self.engine_indexes:
            logger.warning("Unexpected engine_idx: %d", engine_idx)
            return
        LoggingStatLogger.record(
            self,
            scheduler_stats,
            iteration_stats,
            mm_cache_stats=mm_cache_stats,
            engine_idx=engine_idx,
        )
        if scheduler_stats is not None:
            self.last_scheduler_stats_dict[engine_idx] = scheduler_stats

    def aggregate_scheduler_stats(self):
        self.last_scheduler_stats = SchedulerStats()
        for last_scheduler_stats in self.last_scheduler_stats_dict.values():
            self.last_scheduler_stats.num_waiting_reqs += (
                last_scheduler_stats.num_waiting_reqs
            )
            self.last_scheduler_stats.num_running_reqs += (
                last_scheduler_stats.num_running_reqs
            )
            self.last_scheduler_stats.kv_cache_usage += (
                last_scheduler_stats.kv_cache_usage
            )
        self.last_scheduler_stats.kv_cache_usage /= len(self.last_scheduler_stats_dict)

    def log(self):
        LoggingStatLogger.log(self)

    def log_engine_initialized(self):
        if self.vllm_config.cache_config.num_gpu_blocks:
            logger.info(
                "%d Engines: vllm cache_config_info with initialization "
                "after num_gpu_blocks is: %d",
                len(self.engine_indexes),
                self.vllm_config.cache_config.num_gpu_blocks,
            )


class PerEngineStatLoggerAdapter(AggregateStatLoggerBase):
    def __init__(
        self,
        vllm_config: VllmConfig,
        engine_indexes: list[int],
        per_engine_stat_logger_factory: PerEngineStatLoggerFactory,
    ) -> None:
        self.per_engine_stat_loggers = {}
        self.engine_indexes = engine_indexes
        for engine_index in engine_indexes:
            self.per_engine_stat_loggers[engine_index] = per_engine_stat_logger_factory(
                vllm_config, engine_index
            )

    def record(
        self,
        scheduler_stats: SchedulerStats | None,
        iteration_stats: IterationStats | None,
        mm_cache_stats: MultiModalCacheStats | None = None,
        engine_idx: int = 0,
    ):
        if engine_idx not in self.per_engine_stat_loggers:
            logger.warning("Unexpected engine_idx: %d", engine_idx)
            return
        self.per_engine_stat_loggers[engine_idx].record(
            scheduler_stats,
            iteration_stats,
            mm_cache_stats=mm_cache_stats,
            engine_idx=engine_idx,
        )

    def log(self):
        for per_engine_stat_logger in self.per_engine_stat_loggers.values():
            per_engine_stat_logger.log()

    def log_engine_initialized(self):
        for per_engine_stat_logger in self.per_engine_stat_loggers.values():
            per_engine_stat_logger.log_engine_initialized()


class PrometheusStatLogger(AggregateStatLoggerBase):
344
345
346
    _gauge_cls = Gauge
    _counter_cls = Counter
    _histogram_cls = Histogram
347
    _spec_decoding_cls = SpecDecodingProm
348
    _kv_connector_cls = KVConnectorPrometheus
349

350
    def __init__(
351
        self, vllm_config: VllmConfig, engine_indexes: list[int] | None = None
352
    ):
353
354
        if engine_indexes is None:
            engine_indexes = [0]
355

356
        self.engine_indexes = engine_indexes
357
358

        unregister_vllm_metrics()
359
        self.vllm_config = vllm_config
360
361
        # Use this flag to hide metrics that were deprecated in
        # a previous release and which will be removed future
362
        self.show_hidden_metrics = vllm_config.observability_config.show_hidden_metrics
363

364
        labelnames = ["model_name", "engine"]
365
        model_name = vllm_config.model_config.served_model_name
366
        max_model_len = vllm_config.model_config.max_model_len
367

368
        per_engine_labelvalues: dict[int, list[str]] = {
369
            idx: [model_name, str(idx)] for idx in engine_indexes
370
371
        }

372
        self.spec_decoding_prom = self._spec_decoding_cls(
373
374
375
376
            vllm_config.speculative_config, labelnames, per_engine_labelvalues
        )
        self.kv_connector_prom = self._kv_connector_cls(
            vllm_config, labelnames, per_engine_labelvalues
377
        )
378

379
380
381
        #
        # Scheduler state
        #
382
        gauge_scheduler_running = self._gauge_cls(
383
384
            name="vllm:num_requests_running",
            documentation="Number of requests in model execution batches.",
385
            multiprocess_mode="mostrecent",
386
387
388
389
390
            labelnames=labelnames,
        )
        self.gauge_scheduler_running = make_per_engine(
            gauge_scheduler_running, engine_indexes, model_name
        )
391

392
        gauge_scheduler_waiting = self._gauge_cls(
393
394
            name="vllm:num_requests_waiting",
            documentation="Number of requests waiting to be processed.",
395
            multiprocess_mode="mostrecent",
396
397
398
399
400
            labelnames=labelnames,
        )
        self.gauge_scheduler_waiting = make_per_engine(
            gauge_scheduler_waiting, engine_indexes, model_name
        )
401

402
403
404
405
406
407
408
409
410
411
412
413
414
415
        gauge_engine_sleep_state = self._gauge_cls(
            name="vllm:engine_sleep_state",
            documentation=(
                "Engine sleep state; awake = 0 means engine is sleeping; "
                "awake = 1 means engine is awake; "
                "weights_offloaded = 1 means sleep level 1; "
                "discard_all = 1 means sleep level 2."
            ),
            labelnames=labelnames + ["sleep_state"],
            multiprocess_mode="mostrecent",
        )

        self.gauge_engine_sleep_state = {}
        sleep_state = ["awake", "weights_offloaded", "discard_all"]
416

417
418
419
420
421
422
423
        for s in sleep_state:
            self.gauge_engine_sleep_state[s] = {
                idx: gauge_engine_sleep_state.labels(
                    engine=idx, model_name=model_name, sleep_state=s
                )
                for idx in engine_indexes
            }
424

425
426
        # Setting default values
        self.record_sleep_state()
427

428
429
        # GPU cache
        #
430
431
432
433
434
435
436
437
        # Deprecated in 0.9.2 - Renamed as vllm:kv_cache_usage_perc
        # With 0.11.x you can enable with --show-hidden-metrics-for-version=0.10
        # TODO: remove in 0.12.0
        if self.show_hidden_metrics:
            gauge_gpu_cache_usage = self._gauge_cls(
                name="vllm:gpu_cache_usage_perc",
                documentation=(
                    "GPU KV-cache usage. 1 means 100 percent usage."
438
439
                    "DEPRECATED: Use vllm:kv_cache_usage_perc instead."
                ),
440
                multiprocess_mode="mostrecent",
441
442
                labelnames=labelnames,
            )
443
            self.gauge_gpu_cache_usage = make_per_engine(
444
445
                gauge_gpu_cache_usage, engine_indexes, model_name
            )
446
447
448
449
450
451
452
453
454
455
456

        # Deprecated in 0.9.2 - Renamed as vllm:prefix_cache_queries
        # With 0.11.x you can enable with --show-hidden-metrics-for-version=0.10
        # TODO: remove in 0.12.0
        if self.show_hidden_metrics:
            counter_gpu_prefix_cache_queries = self._counter_cls(
                name="vllm:gpu_prefix_cache_queries",
                documentation=(
                    "GPU prefix cache queries, in terms of number of queried"
                    "tokens. DEPRECATED: Use vllm:prefix_cache_queries instead."
                ),
457
458
                labelnames=labelnames,
            )
459
            self.counter_gpu_prefix_cache_queries = make_per_engine(
460
461
                counter_gpu_prefix_cache_queries, engine_indexes, model_name
            )
462
463
464
465
466
467
468
469
470

        # Deprecated in 0.9.2 - Renamed as vllm:prefix_cache_hits
        # With 0.11.x you can enable with --show-hidden-metrics-for-version=0.10
        # TODO: remove in 0.12.0
        if self.show_hidden_metrics:
            counter_gpu_prefix_cache_hits = self._counter_cls(
                name="vllm:gpu_prefix_cache_hits",
                documentation=(
                    "GPU prefix cache hits, in terms of number of cached "
471
472
473
474
                    "tokens. DEPRECATED: Use vllm:prefix_cache_hits instead."
                ),
                labelnames=labelnames,
            )
475
            self.counter_gpu_prefix_cache_hits = make_per_engine(
476
477
                counter_gpu_prefix_cache_hits, engine_indexes, model_name
            )
478

479
        gauge_kv_cache_usage = self._gauge_cls(
480
481
            name="vllm:kv_cache_usage_perc",
            documentation="KV-cache usage. 1 means 100 percent usage.",
482
483
484
485
486
            labelnames=labelnames,
        )
        self.gauge_kv_cache_usage = make_per_engine(
            gauge_kv_cache_usage, engine_indexes, model_name
        )
487

488
489
490
491
492
493
494
495
496
497
498
499
500
        if envs.VLLM_COMPUTE_NANS_IN_LOGITS:
            counter_corrupted_requests = self._counter_cls(
                name="vllm:corrupted_requests",
                documentation=(
                    "Corrupted requests, in terms of total number of requests "
                    "with NaNs in logits."
                ),
                labelnames=labelnames,
            )
            self.counter_corrupted_requests = make_per_engine(
                counter_corrupted_requests, engine_indexes, model_name
            )

501
        counter_prefix_cache_queries = self._counter_cls(
502
503
            name="vllm:prefix_cache_queries",
            documentation=(
504
505
506
507
                "Prefix cache queries, in terms of number of queried tokens."
            ),
            labelnames=labelnames,
        )
508
        self.counter_prefix_cache_queries = make_per_engine(
509
510
            counter_prefix_cache_queries, engine_indexes, model_name
        )
511

512
        counter_prefix_cache_hits = self._counter_cls(
513
            name="vllm:prefix_cache_hits",
514
515
516
            documentation=("Prefix cache hits, in terms of number of cached tokens."),
            labelnames=labelnames,
        )
517
        self.counter_prefix_cache_hits = make_per_engine(
518
519
            counter_prefix_cache_hits, engine_indexes, model_name
        )
520

521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
        #
        # External - KV connector prefix cache
        #

        counter_connector_prefix_cache_queries = self._counter_cls(
            name="vllm:external_prefix_cache_queries",
            documentation=(
                "External prefix cache queries from KV connector "
                "cross-instance cache sharing, in terms of number of queried tokens."
            ),
            labelnames=labelnames,
        )
        self.counter_connector_prefix_cache_queries = make_per_engine(
            counter_connector_prefix_cache_queries, engine_indexes, model_name
        )

        counter_connector_prefix_cache_hits = self._counter_cls(
            name="vllm:external_prefix_cache_hits",
            documentation=(
                "External prefix cache hits from KV connector "
                "cross-instance cache sharing, in terms of number of cached tokens."
            ),
            labelnames=labelnames,
        )
        self.counter_connector_prefix_cache_hits = make_per_engine(
            counter_connector_prefix_cache_hits, engine_indexes, model_name
        )

549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
        #
        # Multi-modal cache
        #

        counter_mm_cache_queries = self._counter_cls(
            name="vllm:mm_cache_queries",
            documentation=(
                "Multi-modal cache queries, in terms of number of queried items."
            ),
            labelnames=labelnames,
        )
        self.counter_mm_cache_queries = make_per_engine(
            counter_mm_cache_queries, engine_indexes, model_name
        )

        counter_mm_cache_hits = self._counter_cls(
            name="vllm:mm_cache_hits",
            documentation=(
                "Multi-modal cache hits, in terms of number of cached items."
            ),
            labelnames=labelnames,
        )
        self.counter_mm_cache_hits = make_per_engine(
            counter_mm_cache_hits, engine_indexes, model_name
        )

575
576
577
        #
        # Counters
        #
578
        counter_num_preempted_reqs = self._counter_cls(
579
            name="vllm:num_preemptions",
580
            documentation="Cumulative number of preemption from the engine.",
581
582
            labelnames=labelnames,
        )
583
        self.counter_num_preempted_reqs = make_per_engine(
584
585
            counter_num_preempted_reqs, engine_indexes, model_name
        )
586

587
        counter_prompt_tokens = self._counter_cls(
588
            name="vllm:prompt_tokens",
589
            documentation="Number of prefill tokens processed.",
590
591
592
593
594
            labelnames=labelnames,
        )
        self.counter_prompt_tokens = make_per_engine(
            counter_prompt_tokens, engine_indexes, model_name
        )
595

596
        counter_generation_tokens = self._counter_cls(
597
            name="vllm:generation_tokens",
598
            documentation="Number of generation tokens processed.",
599
600
            labelnames=labelnames,
        )
601
        self.counter_generation_tokens = make_per_engine(
602
603
            counter_generation_tokens, engine_indexes, model_name
        )
604

605
        self.counter_request_success: dict[FinishReason, dict[int, Counter]] = {}
606
        counter_request_success_base = self._counter_cls(
607
            name="vllm:request_success",
608
            documentation="Count of successfully processed requests.",
609
610
            labelnames=labelnames + ["finished_reason"],
        )
611
        for reason in FinishReason:
612
            self.counter_request_success[reason] = {
613
614
615
                idx: counter_request_success_base.labels(
                    model_name, str(idx), str(reason)
                )
616
617
                for idx in engine_indexes
            }
618

619
620
621
        #
        # Histograms of counts
        #
622
623
624
625
        histogram_num_prompt_tokens_request = self._histogram_cls(
            name="vllm:request_prompt_tokens",
            documentation="Number of prefill tokens processed.",
            buckets=build_1_2_5_buckets(max_model_len),
626
627
            labelnames=labelnames,
        )
628
        self.histogram_num_prompt_tokens_request = make_per_engine(
629
630
            histogram_num_prompt_tokens_request, engine_indexes, model_name
        )
631
632
633
634
635

        histogram_num_generation_tokens_request = self._histogram_cls(
            name="vllm:request_generation_tokens",
            documentation="Number of generation tokens processed.",
            buckets=build_1_2_5_buckets(max_model_len),
636
637
            labelnames=labelnames,
        )
638
        self.histogram_num_generation_tokens_request = make_per_engine(
639
640
            histogram_num_generation_tokens_request, engine_indexes, model_name
        )
641

642
643
644
        # TODO: This metric might be incorrect in case of using multiple
        # api_server counts which uses prometheus mp.
        # See: https://github.com/vllm-project/vllm/pull/18053
645
646
647
        histogram_iteration_tokens = self._histogram_cls(
            name="vllm:iteration_tokens_total",
            documentation="Histogram of number of tokens per engine_step.",
648
649
650
            buckets=[1, 8, 16, 32, 64, 128, 256, 512, 1024, 2048, 4096, 8192, 16384],
            labelnames=labelnames,
        )
651
        self.histogram_iteration_tokens = make_per_engine(
652
653
            histogram_iteration_tokens, engine_indexes, model_name
        )
654
655
656

        histogram_max_num_generation_tokens_request = self._histogram_cls(
            name="vllm:request_max_num_generation_tokens",
657
            documentation="Histogram of maximum number of requested generation tokens.",
658
            buckets=build_1_2_5_buckets(max_model_len),
659
660
            labelnames=labelnames,
        )
661
        self.histogram_max_num_generation_tokens_request = make_per_engine(
662
663
            histogram_max_num_generation_tokens_request, engine_indexes, model_name
        )
664
665
666
667
668

        histogram_n_request = self._histogram_cls(
            name="vllm:request_params_n",
            documentation="Histogram of the n request parameter.",
            buckets=[1, 2, 5, 10, 20],
669
670
671
672
673
            labelnames=labelnames,
        )
        self.histogram_n_request = make_per_engine(
            histogram_n_request, engine_indexes, model_name
        )
674
675
676
677
678

        histogram_max_tokens_request = self._histogram_cls(
            name="vllm:request_params_max_tokens",
            documentation="Histogram of the max_tokens request parameter.",
            buckets=build_1_2_5_buckets(max_model_len),
679
680
            labelnames=labelnames,
        )
681
        self.histogram_max_tokens_request = make_per_engine(
682
683
            histogram_max_tokens_request, engine_indexes, model_name
        )
684
685
686
687

        #
        # Histogram of timing intervals
        #
688
689
690
691
        histogram_time_to_first_token = self._histogram_cls(
            name="vllm:time_to_first_token_seconds",
            documentation="Histogram of time to first token in seconds.",
            buckets=[
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
                0.001,
                0.005,
                0.01,
                0.02,
                0.04,
                0.06,
                0.08,
                0.1,
                0.25,
                0.5,
                0.75,
                1.0,
                2.5,
                5.0,
                7.5,
                10.0,
                20.0,
                40.0,
                80.0,
                160.0,
                640.0,
                2560.0,
714
            ],
715
716
            labelnames=labelnames,
        )
717
        self.histogram_time_to_first_token = make_per_engine(
718
719
            histogram_time_to_first_token, engine_indexes, model_name
        )
720

721
722
        # Deprecated in 0.11 - Renamed as vllm:inter_token_latency_seconds
        # TODO: in 0.12, only enable if show_hidden_metrics=True
723
724
        histogram_time_per_output_token = self._histogram_cls(
            name="vllm:time_per_output_token_seconds",
725
726
            documentation=(
                "Histogram of time per output token in seconds."
727
728
                "DEPRECATED: Use vllm:inter_token_latency_seconds instead."
            ),
729
            buckets=[
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
                0.01,
                0.025,
                0.05,
                0.075,
                0.1,
                0.15,
                0.2,
                0.3,
                0.4,
                0.5,
                0.75,
                1.0,
                2.5,
                5.0,
                7.5,
                10.0,
                20.0,
                40.0,
                80.0,
749
            ],
750
751
            labelnames=labelnames,
        )
752
        self.histogram_time_per_output_token = make_per_engine(
753
754
            histogram_time_per_output_token, engine_indexes, model_name
        )
755

756
757
758
759
        histogram_inter_token_latency = self._histogram_cls(
            name="vllm:inter_token_latency_seconds",
            documentation="Histogram of inter-token latency in seconds.",
            buckets=[
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
                0.01,
                0.025,
                0.05,
                0.075,
                0.1,
                0.15,
                0.2,
                0.3,
                0.4,
                0.5,
                0.75,
                1.0,
                2.5,
                5.0,
                7.5,
                10.0,
                20.0,
                40.0,
                80.0,
779
            ],
780
781
            labelnames=labelnames,
        )
782
        self.histogram_inter_token_latency = make_per_engine(
783
784
            histogram_inter_token_latency, engine_indexes, model_name
        )
785

786
787
        histogram_request_time_per_output_token = self._histogram_cls(
            name="vllm:request_time_per_output_token_seconds",
788
            documentation="Histogram of time_per_output_token_seconds per request.",
789
            buckets=[
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
                0.01,
                0.025,
                0.05,
                0.075,
                0.1,
                0.15,
                0.2,
                0.3,
                0.4,
                0.5,
                0.75,
                1.0,
                2.5,
                5.0,
                7.5,
                10.0,
                20.0,
                40.0,
                80.0,
809
            ],
810
811
            labelnames=labelnames,
        )
812
        self.histogram_request_time_per_output_token = make_per_engine(
813
814
            histogram_request_time_per_output_token, engine_indexes, model_name
        )
815

816
        request_latency_buckets = [
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
            0.3,
            0.5,
            0.8,
            1.0,
            1.5,
            2.0,
            2.5,
            5.0,
            10.0,
            15.0,
            20.0,
            30.0,
            40.0,
            50.0,
            60.0,
            120.0,
            240.0,
            480.0,
            960.0,
            1920.0,
            7680.0,
838
        ]
839
840
841
842
        histogram_e2e_time_request = self._histogram_cls(
            name="vllm:e2e_request_latency_seconds",
            documentation="Histogram of e2e request latency in seconds.",
            buckets=request_latency_buckets,
843
844
            labelnames=labelnames,
        )
845
        self.histogram_e2e_time_request = make_per_engine(
846
847
            histogram_e2e_time_request, engine_indexes, model_name
        )
848
849
850

        histogram_queue_time_request = self._histogram_cls(
            name="vllm:request_queue_time_seconds",
851
            documentation="Histogram of time spent in WAITING phase for request.",
852
            buckets=request_latency_buckets,
853
854
            labelnames=labelnames,
        )
855
        self.histogram_queue_time_request = make_per_engine(
856
857
            histogram_queue_time_request, engine_indexes, model_name
        )
858
859
860

        histogram_inference_time_request = self._histogram_cls(
            name="vllm:request_inference_time_seconds",
861
            documentation="Histogram of time spent in RUNNING phase for request.",
862
            buckets=request_latency_buckets,
863
864
            labelnames=labelnames,
        )
865
        self.histogram_inference_time_request = make_per_engine(
866
867
            histogram_inference_time_request, engine_indexes, model_name
        )
868
869
870

        histogram_prefill_time_request = self._histogram_cls(
            name="vllm:request_prefill_time_seconds",
871
            documentation="Histogram of time spent in PREFILL phase for request.",
872
            buckets=request_latency_buckets,
873
874
            labelnames=labelnames,
        )
875
        self.histogram_prefill_time_request = make_per_engine(
876
877
            histogram_prefill_time_request, engine_indexes, model_name
        )
878
879
880

        histogram_decode_time_request = self._histogram_cls(
            name="vllm:request_decode_time_seconds",
881
            documentation="Histogram of time spent in DECODE phase for request.",
882
            buckets=request_latency_buckets,
883
884
            labelnames=labelnames,
        )
885
        self.histogram_decode_time_request = make_per_engine(
886
887
            histogram_decode_time_request, engine_indexes, model_name
        )
888

889
890
891
        #
        # LoRA metrics
        #
892
893
894

        # TODO: This metric might be incorrect in case of using multiple
        # api_server counts which uses prometheus mp.
895
        self.gauge_lora_info: Gauge | None = None
896
        if vllm_config.lora_config is not None:
897
            if len(self.engine_indexes) > 1:
898
                raise NotImplementedError("LoRA in DP mode is not supported yet.")
899
900
901
902
            self.labelname_max_lora = "max_lora"
            self.labelname_waiting_lora_adapters = "waiting_lora_adapters"
            self.labelname_running_lora_adapters = "running_lora_adapters"
            self.max_lora = vllm_config.lora_config.max_loras
903
904
905
906
907
908
909
910
911
912
            self.gauge_lora_info = self._gauge_cls(
                name="vllm:lora_requests_info",
                documentation="Running stats on lora requests.",
                multiprocess_mode="sum",
                labelnames=[
                    self.labelname_max_lora,
                    self.labelname_waiting_lora_adapters,
                    self.labelname_running_lora_adapters,
                ],
            )
913

914
915
    def log_metrics_info(self, type: str, config_obj: SupportsMetricsInfo):
        metrics_info = config_obj.metrics_info()
916
        metrics_info["engine"] = ""
917
918
919
920
921
922
923
924
925
926

        name, documentation = None, None
        if type == "cache_config":
            name = "vllm:cache_config_info"
            documentation = "Information of the LLMEngine CacheConfig"
        assert name is not None, f"Unknown metrics info type {type}"

        # Info type metrics are syntactic sugar for a gauge permanently set to 1
        # Since prometheus multiprocessing mode does not support Info, emulate
        # info here with a gauge.
927
        info_gauge = self._gauge_cls(
928
929
            name=name,
            documentation=documentation,
930
931
            multiprocess_mode="mostrecent",
            labelnames=metrics_info.keys(),
932
933
934
935
936
937
        )
        for engine_index in self.engine_indexes:
            metrics_info = config_obj.metrics_info()
            metrics_info["engine"] = str(engine_index)
            info_gauge.labels(**metrics_info).set(1)

938
939
    def record(
        self,
940
941
942
        scheduler_stats: SchedulerStats | None,
        iteration_stats: IterationStats | None,
        mm_cache_stats: MultiModalCacheStats | None = None,
943
944
        engine_idx: int = 0,
    ):
945
        """Log to prometheus."""
946
        if scheduler_stats is not None:
947
            self.gauge_scheduler_running[engine_idx].set(
948
949
                scheduler_stats.num_running_reqs
            )
950
            self.gauge_scheduler_waiting[engine_idx].set(
951
952
                scheduler_stats.num_waiting_reqs
            )
953
954
            if self.show_hidden_metrics:
                self.gauge_gpu_cache_usage[engine_idx].set(
955
956
957
                    scheduler_stats.kv_cache_usage
                )
            self.gauge_kv_cache_usage[engine_idx].set(scheduler_stats.kv_cache_usage)
958

959
960
            if self.show_hidden_metrics:
                self.counter_gpu_prefix_cache_queries[engine_idx].inc(
961
962
                    scheduler_stats.prefix_cache_stats.queries
                )
963
                self.counter_gpu_prefix_cache_hits[engine_idx].inc(
964
965
                    scheduler_stats.prefix_cache_stats.hits
                )
966

967
            self.counter_prefix_cache_queries[engine_idx].inc(
968
969
                scheduler_stats.prefix_cache_stats.queries
            )
970
            self.counter_prefix_cache_hits[engine_idx].inc(
971
972
                scheduler_stats.prefix_cache_stats.hits
            )
973

974
975
976
977
978
979
980
981
            if scheduler_stats.connector_prefix_cache_stats is not None:
                self.counter_connector_prefix_cache_queries[engine_idx].inc(
                    scheduler_stats.connector_prefix_cache_stats.queries
                )
                self.counter_connector_prefix_cache_hits[engine_idx].inc(
                    scheduler_stats.connector_prefix_cache_stats.hits
                )

982
983
            if scheduler_stats.spec_decoding_stats is not None:
                self.spec_decoding_prom.observe(
984
985
                    scheduler_stats.spec_decoding_stats, engine_idx
                )
986

987
988
989
990
991
            if scheduler_stats.kv_connector_stats is not None:
                self.kv_connector_prom.observe(
                    scheduler_stats.kv_connector_stats, engine_idx
                )

992
993
994
995
996
997
998
999
1000
1001
1002
1003
1004
1005
            if self.gauge_lora_info is not None:
                running_lora_adapters = ",".join(
                    scheduler_stats.running_lora_adapters.keys()
                )
                waiting_lora_adapters = ",".join(
                    scheduler_stats.waiting_lora_adapters.keys()
                )
                lora_info_labels = {
                    self.labelname_running_lora_adapters: running_lora_adapters,
                    self.labelname_waiting_lora_adapters: waiting_lora_adapters,
                    self.labelname_max_lora: self.max_lora,
                }
                self.gauge_lora_info.labels(**lora_info_labels).set_to_current_time()

1006
1007
1008
1009
        if mm_cache_stats is not None:
            self.counter_mm_cache_queries[engine_idx].inc(mm_cache_stats.queries)
            self.counter_mm_cache_hits[engine_idx].inc(mm_cache_stats.hits)

1010
1011
        if iteration_stats is None:
            return
1012
1013
1014
1015
        if envs.VLLM_COMPUTE_NANS_IN_LOGITS:
            self.counter_corrupted_requests[engine_idx].inc(
                iteration_stats.num_corrupted_reqs
            )
1016
        self.counter_num_preempted_reqs[engine_idx].inc(
1017
1018
1019
            iteration_stats.num_preempted_reqs
        )
        self.counter_prompt_tokens[engine_idx].inc(iteration_stats.num_prompt_tokens)
1020
        self.counter_generation_tokens[engine_idx].inc(
1021
1022
            iteration_stats.num_generation_tokens
        )
1023
        self.histogram_iteration_tokens[engine_idx].observe(
1024
1025
            iteration_stats.num_prompt_tokens + iteration_stats.num_generation_tokens
        )
1026

1027
        for max_gen_tokens in iteration_stats.max_num_generation_tokens_iter:
1028
1029
1030
            self.histogram_max_num_generation_tokens_request[engine_idx].observe(
                max_gen_tokens
            )
1031
        for n_param in iteration_stats.n_params_iter:
1032
            self.histogram_n_request[engine_idx].observe(n_param)
1033
        for ttft in iteration_stats.time_to_first_tokens_iter:
1034
            self.histogram_time_to_first_token[engine_idx].observe(ttft)
1035
1036
1037
        for itl in iteration_stats.inter_token_latencies_iter:
            self.histogram_inter_token_latency[engine_idx].observe(itl)
            self.histogram_time_per_output_token[engine_idx].observe(itl)
1038

1039
        for finished_request in iteration_stats.finished_requests:
1040
1041
1042
            self.counter_request_success[finished_request.finish_reason][
                engine_idx
            ].inc()
1043
            self.histogram_e2e_time_request[engine_idx].observe(
1044
1045
                finished_request.e2e_latency
            )
1046
            self.histogram_queue_time_request[engine_idx].observe(
1047
1048
                finished_request.queued_time
            )
1049
            self.histogram_prefill_time_request[engine_idx].observe(
1050
1051
                finished_request.prefill_time
            )
1052
            self.histogram_inference_time_request[engine_idx].observe(
1053
1054
                finished_request.inference_time
            )
1055
            self.histogram_decode_time_request[engine_idx].observe(
1056
1057
                finished_request.decode_time
            )
1058
            self.histogram_num_prompt_tokens_request[engine_idx].observe(
1059
1060
                finished_request.num_prompt_tokens
            )
1061
            self.histogram_num_generation_tokens_request[engine_idx].observe(
1062
1063
                finished_request.num_generation_tokens
            )
1064
            self.histogram_request_time_per_output_token[engine_idx].observe(
1065
1066
                finished_request.mean_time_per_output_token
            )
1067
            if finished_request.max_tokens_param:
1068
                self.histogram_max_tokens_request[engine_idx].observe(
1069
1070
                    finished_request.max_tokens_param
                )
1071

1072
1073
1074
1075
1076
1077
1078
1079
1080
1081
1082
1083
1084
1085
1086
1087
1088
1089
1090
    def record_sleep_state(self, sleep: int = 0, level: int = 0):
        awake = 1
        discard_all = 0
        weights_offloaded = 0

        if sleep == 1:
            awake = 0
            if level == 1:
                weights_offloaded = 1
            elif level == 2:
                discard_all = 1

        for engine_idx in self.engine_indexes:
            self.gauge_engine_sleep_state["discard_all"][engine_idx].set(discard_all)
            self.gauge_engine_sleep_state["weights_offloaded"][engine_idx].set(
                weights_offloaded
            )
            self.gauge_engine_sleep_state["awake"][engine_idx].set(awake)

1091
1092
1093
    def log_engine_initialized(self):
        self.log_metrics_info("cache_config", self.vllm_config.cache_config)

1094

1095
PromMetric: TypeAlias = Gauge | Counter | Histogram
1096
1097


1098
1099
1100
def make_per_engine(
    metric: PromMetric, engine_idxs: list[int], model_name: str
) -> dict[int, PromMetric]:
1101
1102
1103
    return {idx: metric.labels(model_name, str(idx)) for idx in engine_idxs}


1104
def build_buckets(mantissa_lst: list[int], max_value: int) -> list[int]:
1105
1106
1107
1108
1109
1110
    """
    Builds a list of buckets with increasing powers of 10 multiplied by
    mantissa values until the value exceeds the specified maximum.

    """
    exponent = 0
1111
    buckets: list[int] = []
1112
1113
1114
1115
1116
1117
1118
1119
1120
1121
    while True:
        for m in mantissa_lst:
            value = m * 10**exponent
            if value <= max_value:
                buckets.append(value)
            else:
                return buckets
        exponent += 1


1122
def build_1_2_5_buckets(max_value: int) -> list[int]:
1123
1124
1125
1126
1127
1128
    """
    Example:
    >>> build_1_2_5_buckets(100)
    [1, 2, 5, 10, 20, 50, 100]
    """
    return build_buckets([1, 2, 5], max_value)
1129
1130


1131
1132
1133
1134
1135
1136
1137
1138
1139
1140
1141
1142
1143
1144
1145
1146
class StatLoggerManager:
    """
    StatLoggerManager:
        Logging happens at the level of the EngineCore (per scheduler).
         * DP: >1 EngineCore per AsyncLLM - loggers for each EngineCore.
         * With Local Logger, just make N copies for N EngineCores.
         * With Prometheus, we need a single logger with N "labels"

        This class abstracts away this implementation detail from
        the AsyncLLM, allowing the AsyncLLM to just call .record()
        and .log() to a simple interface.
    """

    def __init__(
        self,
        vllm_config: VllmConfig,
1147
1148
        engine_idxs: list[int] | None = None,
        custom_stat_loggers: list[StatLoggerFactory] | None = None,
1149
        enable_default_loggers: bool = True,
1150
        aggregate_engine_logging: bool = False,
1151
        client_count: int = 1,
1152
    ):
1153
1154
1155
        self.engine_indexes = engine_idxs if engine_idxs else [0]
        self.stat_loggers: list[AggregateStatLoggerBase] = []
        stat_logger_factories: list[StatLoggerFactory] = []
1156
        if custom_stat_loggers is not None:
1157
            stat_logger_factories.extend(custom_stat_loggers)
1158
        if enable_default_loggers and logger.isEnabledFor(logging.INFO):
1159
1160
1161
            if client_count > 1:
                logger.warning(
                    "AsyncLLM created with api_server_count more than 1; "
1162
1163
                    "disabling stats logging to avoid incomplete stats."
                )
1164
            else:
1165
1166
1167
1168
1169
1170
1171
1172
1173
1174
1175
1176
1177
1178
1179
1180
1181
1182
1183
1184
1185
1186
1187
1188
1189
1190
1191
1192
1193
                default_logger_factory = (
                    AggregatedLoggingStatLogger
                    if aggregate_engine_logging
                    else LoggingStatLogger
                )
                stat_logger_factories.append(default_logger_factory)
        custom_prometheus_logger: bool = False
        for stat_logger_factory in stat_logger_factories:
            if isinstance(stat_logger_factory, type) and issubclass(
                stat_logger_factory, AggregateStatLoggerBase
            ):
                global_stat_logger = stat_logger_factory(
                    vllm_config=vllm_config,
                    engine_indexes=self.engine_indexes,
                )
                if isinstance(global_stat_logger, PrometheusStatLogger):
                    custom_prometheus_logger = True
            else:
                # per engine logger
                global_stat_logger = PerEngineStatLoggerAdapter(
                    vllm_config=vllm_config,
                    engine_indexes=self.engine_indexes,
                    per_engine_stat_logger_factory=stat_logger_factory,  # type: ignore[arg-type]
                )
            self.stat_loggers.append(global_stat_logger)
        if not custom_prometheus_logger:
            self.stat_loggers.append(
                PrometheusStatLogger(vllm_config, self.engine_indexes)
            )
1194
1195
1196

    def record(
        self,
1197
1198
1199
1200
        scheduler_stats: SchedulerStats | None,
        iteration_stats: IterationStats | None,
        mm_cache_stats: MultiModalCacheStats | None = None,
        engine_idx: int | None = None,
1201
1202
1203
    ):
        if engine_idx is None:
            engine_idx = 0
1204
        for logger in self.stat_loggers:
1205
1206
1207
1208
1209
1210
            logger.record(
                scheduler_stats,
                iteration_stats,
                mm_cache_stats=mm_cache_stats,
                engine_idx=engine_idx,
            )
1211

1212
1213
1214
1215
    def record_sleep_state(self, sleep: int = 0, level: int = 0):
        for logger in self.stat_loggers:
            logger.record_sleep_state(sleep, level)

1216
    def log(self):
1217
1218
        for logger in self.stat_loggers:
            logger.log()
1219
1220

    def log_engine_initialized(self):
1221
1222
        for agg_logger in self.stat_loggers:
            agg_logger.log_engine_initialized()