loggers.py 20.8 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
from typing import Callable, Optional
8

9
import numpy as np
10
import prometheus_client
11

12
from vllm.config import SupportsMetricsInfo, VllmConfig
13
from vllm.logger import init_logger
14
from vllm.v1.core.kv_cache_utils import PrefixCachingMetrics
15
from vllm.v1.engine import FinishReason
16
from vllm.v1.metrics.prometheus import unregister_vllm_metrics
17
from vllm.v1.metrics.stats import IterationStats, SchedulerStats
18
from vllm.v1.spec_decode.metrics import SpecDecodingLogging, SpecDecodingProm
19
20
21

logger = init_logger(__name__)

22
23
StatLoggerFactory = Callable[[VllmConfig, int], "StatLoggerBase"]

24
25

class StatLoggerBase(ABC):
26
27
28
29
30
31
32
33
34
35
    """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
    def __init__(self, vllm_config: VllmConfig, engine_index: int = 0):
        ...
36
37

    @abstractmethod
38
    def record(self, scheduler_stats: Optional[SchedulerStats],
39
               iteration_stats: Optional[IterationStats]):
40
41
        ...

42
43
44
45
    @abstractmethod
    def log_engine_initialized(self):
        ...

46
47
48
    def log(self):  # noqa
        pass

49
50
51

class LoggingStatLogger(StatLoggerBase):

52
    def __init__(self, vllm_config: VllmConfig, engine_index: int = 0):
53
        self.engine_index = engine_index
54
        self.vllm_config = vllm_config
55
        self._reset(time.monotonic())
56
        self.last_scheduler_stats = SchedulerStats()
57
58
59
        # Prefix cache metrics. This cannot be reset.
        # TODO: Make the interval configurable.
        self.prefix_caching_metrics = PrefixCachingMetrics()
60
        self.spec_decoding_logging = SpecDecodingLogging()
61
62
        self.last_prompt_throughput: float = 0.0
        self.last_generation_throughput: float = 0.0
63

64
65
66
67
    def _reset(self, now):
        self.last_log_time = now

        # Tracked stats over current local logging interval.
68
69
        self.num_prompt_tokens: list[int] = []
        self.num_generation_tokens: list[int] = []
70

71
72
73
74
75
76
    def _track_iteration_stats(self, iteration_stats: IterationStats):
        # Save tracked stats for token counters.
        self.num_prompt_tokens.append(iteration_stats.num_prompt_tokens)
        self.num_generation_tokens.append(
            iteration_stats.num_generation_tokens)

77
    def _get_throughput(self, tracked_stats: list[int], now: float) -> float:
78
79
80
        # Compute summary metrics for tracked stats
        return float(np.sum(tracked_stats) / (now - self.last_log_time))

81
    def record(self, scheduler_stats: Optional[SchedulerStats],
82
               iteration_stats: Optional[IterationStats]):
83
84
        """Log Stats to standard output."""

85
86
        if iteration_stats:
            self._track_iteration_stats(iteration_stats)
87

88
89
90
        if scheduler_stats is not None:
            self.prefix_caching_metrics.observe(
                scheduler_stats.prefix_cache_stats)
91

92
93
94
            if scheduler_stats.spec_decoding_stats is not None:
                self.spec_decoding_logging.observe(
                    scheduler_stats.spec_decoding_stats)
95

96
            self.last_scheduler_stats = scheduler_stats
97

98
99
    def log(self):
        now = time.monotonic()
100
101
102
103
104
        prompt_throughput = self._get_throughput(self.num_prompt_tokens, now)
        generation_throughput = self._get_throughput(
            self.num_generation_tokens, now)

        self._reset(now)
105

106
107
        scheduler_stats = self.last_scheduler_stats

108
109
110
111
112
113
114
115
116
        log_fn = logger.info
        if not any(
            (prompt_throughput, generation_throughput,
             self.last_prompt_throughput, self.last_generation_throughput)):
            # Avoid log noise on an idle production system
            log_fn = logger.debug
        self.last_generation_throughput = generation_throughput
        self.last_prompt_throughput = prompt_throughput

117
        # Format and print output.
118
        log_fn(
119
            "Engine %03d: "
120
121
            "Avg prompt throughput: %.1f tokens/s, "
            "Avg generation throughput: %.1f tokens/s, "
122
123
124
            "Running: %d reqs, Waiting: %d reqs, "
            "GPU KV cache usage: %.1f%%, "
            "Prefix cache hit rate: %.1f%%",
125
            self.engine_index,
126
127
            prompt_throughput,
            generation_throughput,
128
129
            scheduler_stats.num_running_reqs,
            scheduler_stats.num_waiting_reqs,
130
            scheduler_stats.gpu_cache_usage * 100,
131
            self.prefix_caching_metrics.hit_rate * 100,
132
        )
133
        self.spec_decoding_logging.log(log_fn=log_fn)
134

135
    def log_engine_initialized(self):
136
137
138
139
140
        if self.vllm_config.cache_config.num_gpu_blocks:
            logger.info(
                "Engine %03d: vllm cache_config_info with initialization "
                "after num_gpu_blocks is: %d", self.engine_index,
                self.vllm_config.cache_config.num_gpu_blocks)
141

142
143

class PrometheusStatLogger(StatLoggerBase):
144
145
146
147
    _gauge_cls = prometheus_client.Gauge
    _counter_cls = prometheus_client.Counter
    _histogram_cls = prometheus_client.Histogram
    _spec_decoding_cls = SpecDecodingProm
148

149
    def __init__(self, vllm_config: VllmConfig, engine_index: int = 0):
150
151

        unregister_vllm_metrics()
152
153
        self.vllm_config = vllm_config
        self.engine_index = engine_index
154
155
156
157
158
        # Use this flag to hide metrics that were deprecated in
        # a previous release and which will be removed future
        self.show_hidden_metrics = \
            vllm_config.observability_config.show_hidden_metrics

159
160
161
162
163
        labelnames = ["model_name", "engine"]
        labelvalues = [
            vllm_config.model_config.served_model_name,
            str(engine_index)
        ]
164

165
        max_model_len = vllm_config.model_config.max_model_len
166

167
        self.spec_decoding_prom = self._spec_decoding_cls(
168
169
            vllm_config.speculative_config, labelnames, labelvalues)

170
171
172
        #
        # Scheduler state
        #
173
        self.gauge_scheduler_running = self._gauge_cls(
174
175
            name="vllm:num_requests_running",
            documentation="Number of requests in model execution batches.",
176
            multiprocess_mode="mostrecent",
177
178
            labelnames=labelnames).labels(*labelvalues)

179
        self.gauge_scheduler_waiting = self._gauge_cls(
180
181
            name="vllm:num_requests_waiting",
            documentation="Number of requests waiting to be processed.",
182
            multiprocess_mode="mostrecent",
183
184
            labelnames=labelnames).labels(*labelvalues)

185
186
187
        #
        # GPU cache
        #
188
        self.gauge_gpu_cache_usage = self._gauge_cls(
189
190
            name="vllm:gpu_cache_usage_perc",
            documentation="GPU KV-cache usage. 1 means 100 percent usage.",
191
            multiprocess_mode="mostrecent",
192
193
            labelnames=labelnames).labels(*labelvalues)

194
        self.counter_gpu_prefix_cache_queries = self._counter_cls(
195
196
            name="vllm:gpu_prefix_cache_queries",
            documentation=
197
            "GPU prefix cache queries, in terms of number of queried tokens.",
198
199
            labelnames=labelnames).labels(*labelvalues)

200
        self.counter_gpu_prefix_cache_hits = self._counter_cls(
201
202
            name="vllm:gpu_prefix_cache_hits",
            documentation=
203
            "GPU prefix cache hits, in terms of number of cached tokens.",
204
205
            labelnames=labelnames).labels(*labelvalues)

206
207
208
        #
        # Counters
        #
209
        self.counter_num_preempted_reqs = self._counter_cls(
210
            name="vllm:num_preemptions",
211
212
213
            documentation="Cumulative number of preemption from the engine.",
            labelnames=labelnames).labels(*labelvalues)

214
        self.counter_prompt_tokens = self._counter_cls(
215
            name="vllm:prompt_tokens",
216
217
218
            documentation="Number of prefill tokens processed.",
            labelnames=labelnames).labels(*labelvalues)

219
        self.counter_generation_tokens = self._counter_cls(
220
            name="vllm:generation_tokens",
221
222
223
            documentation="Number of generation tokens processed.",
            labelnames=labelnames).labels(*labelvalues)

224
        self.counter_request_success: dict[FinishReason,
225
                                           prometheus_client.Counter] = {}
226
        counter_request_success_base = self._counter_cls(
227
            name="vllm:request_success",
228
229
            documentation="Count of successfully processed requests.",
            labelnames=labelnames + ["finished_reason"])
230
        for reason in FinishReason:
231
232
233
234
            self.counter_request_success[
                reason] = counter_request_success_base.labels(*(labelvalues +
                                                                [str(reason)]))

235
236
237
        #
        # Histograms of counts
        #
238
        self.histogram_num_prompt_tokens_request = \
239
            self._histogram_cls(
240
241
242
243
244
245
                name="vllm:request_prompt_tokens",
                documentation="Number of prefill tokens processed.",
                buckets=build_1_2_5_buckets(max_model_len),
                labelnames=labelnames).labels(*labelvalues)

        self.histogram_num_generation_tokens_request = \
246
            self._histogram_cls(
247
248
249
250
251
                name="vllm:request_generation_tokens",
                documentation="Number of generation tokens processed.",
                buckets=build_1_2_5_buckets(max_model_len),
                labelnames=labelnames).labels(*labelvalues)

252
253
254
        # 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
255
        self.histogram_iteration_tokens = \
256
            self._histogram_cls(
257
258
                name="vllm:iteration_tokens_total",
                documentation="Histogram of number of tokens per engine_step.",
259
                buckets=[
260
261
                    1, 8, 16, 32, 64, 128, 256, 512, 1024, 2048, 4096, 8192,
                    16384
262
                ],
263
264
                labelnames=labelnames).labels(*labelvalues)

265
        self.histogram_max_num_generation_tokens_request = \
266
            self._histogram_cls(
267
268
269
270
271
272
273
                name="vllm:request_max_num_generation_tokens",
                documentation=
                "Histogram of maximum number of requested generation tokens.",
                buckets=build_1_2_5_buckets(max_model_len),
                labelnames=labelnames).labels(*labelvalues)

        self.histogram_n_request = \
274
            self._histogram_cls(
275
276
277
278
279
280
                name="vllm:request_params_n",
                documentation="Histogram of the n request parameter.",
                buckets=[1, 2, 5, 10, 20],
                labelnames=labelnames).labels(*labelvalues)

        self.histogram_max_tokens_request = \
281
            self._histogram_cls(
282
283
284
285
286
287
288
289
                name="vllm:request_params_max_tokens",
                documentation="Histogram of the max_tokens request parameter.",
                buckets=build_1_2_5_buckets(max_model_len),
                labelnames=labelnames).labels(*labelvalues)

        #
        # Histogram of timing intervals
        #
290
        self.histogram_time_to_first_token = \
291
            self._histogram_cls(
292
293
294
295
                name="vllm:time_to_first_token_seconds",
                documentation="Histogram of time to first token in seconds.",
                buckets=[
                    0.001, 0.005, 0.01, 0.02, 0.04, 0.06, 0.08, 0.1, 0.25, 0.5,
296
297
                    0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, 40.0, 80.0, 160.0,
                    640.0, 2560.0
298
299
300
301
                ],
                labelnames=labelnames).labels(*labelvalues)

        self.histogram_time_per_output_token = \
302
            self._histogram_cls(
303
304
305
306
                name="vllm:time_per_output_token_seconds",
                documentation="Histogram of time per output token in seconds.",
                buckets=[
                    0.01, 0.025, 0.05, 0.075, 0.1, 0.15, 0.2, 0.3, 0.4, 0.5,
307
                    0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, 40.0, 80.0
308
309
310
                ],
                labelnames=labelnames).labels(*labelvalues)

311
312
        request_latency_buckets = [
            0.3, 0.5, 0.8, 1.0, 1.5, 2.0, 2.5, 5.0, 10.0, 15.0, 20.0, 30.0,
313
            40.0, 50.0, 60.0, 120.0, 240.0, 480.0, 960.0, 1920.0, 7680.0
314
315
        ]
        self.histogram_e2e_time_request = \
316
            self._histogram_cls(
317
318
319
320
321
                name="vllm:e2e_request_latency_seconds",
                documentation="Histogram of e2e request latency in seconds.",
                buckets=request_latency_buckets,
                labelnames=labelnames).labels(*labelvalues)
        self.histogram_queue_time_request = \
322
            self._histogram_cls(
323
324
325
326
327
328
                name="vllm:request_queue_time_seconds",
                documentation=
                "Histogram of time spent in WAITING phase for request.",
                buckets=request_latency_buckets,
                labelnames=labelnames).labels(*labelvalues)
        self.histogram_inference_time_request = \
329
            self._histogram_cls(
330
331
332
333
334
335
                name="vllm:request_inference_time_seconds",
                documentation=
                "Histogram of time spent in RUNNING phase for request.",
                buckets=request_latency_buckets,
                labelnames=labelnames).labels(*labelvalues)
        self.histogram_prefill_time_request = \
336
            self._histogram_cls(
337
338
339
340
341
342
                name="vllm:request_prefill_time_seconds",
                documentation=
                "Histogram of time spent in PREFILL phase for request.",
                buckets=request_latency_buckets,
                labelnames=labelnames).labels(*labelvalues)
        self.histogram_decode_time_request = \
343
            self._histogram_cls(
344
345
346
347
348
349
                name="vllm:request_decode_time_seconds",
                documentation=
                "Histogram of time spent in DECODE phase for request.",
                buckets=request_latency_buckets,
                labelnames=labelnames).labels(*labelvalues)

350
351
352
        #
        # LoRA metrics
        #
353
354
355

        # TODO: This metric might be incorrect in case of using multiple
        # api_server counts which uses prometheus mp.
356
357
358
359
360
361
362
        self.gauge_lora_info: Optional[prometheus_client.Gauge] = None
        if vllm_config.lora_config is not None:
            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
            self.gauge_lora_info = \
363
                self._gauge_cls(
364
365
                    name="vllm:lora_requests_info",
                    documentation="Running stats on lora requests.",
366
                    multiprocess_mode="sum",
367
368
369
370
                    labelnames=[
                        self.labelname_max_lora,
                        self.labelname_waiting_lora_adapters,
                        self.labelname_running_lora_adapters,
371
372
                    ],
                )
373

374
    def log_metrics_info(self, type: str, config_obj: SupportsMetricsInfo):
375

376
        metrics_info = config_obj.metrics_info()
377
        metrics_info["engine"] = self.engine_index
378
379
380
381
382
383
384
385
386
387

        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.
388
        info_gauge = self._gauge_cls(
389
390
            name=name,
            documentation=documentation,
391
392
393
            multiprocess_mode="mostrecent",
            labelnames=metrics_info.keys(),
        ).labels(**metrics_info)
394
395
        info_gauge.set(1)

396
    def record(self, scheduler_stats: Optional[SchedulerStats],
397
               iteration_stats: Optional[IterationStats]):
398
        """Log to prometheus."""
399
400
401
        if scheduler_stats is not None:
            self.gauge_scheduler_running.set(scheduler_stats.num_running_reqs)
            self.gauge_scheduler_waiting.set(scheduler_stats.num_waiting_reqs)
402

403
            self.gauge_gpu_cache_usage.set(scheduler_stats.gpu_cache_usage)
404

405
406
407
408
            self.counter_gpu_prefix_cache_queries.inc(
                scheduler_stats.prefix_cache_stats.queries)
            self.counter_gpu_prefix_cache_hits.inc(
                scheduler_stats.prefix_cache_stats.hits)
409

410
411
412
            if scheduler_stats.spec_decoding_stats is not None:
                self.spec_decoding_prom.observe(
                    scheduler_stats.spec_decoding_stats)
413

414
415
416
        if iteration_stats is None:
            return

417
        self.counter_num_preempted_reqs.inc(iteration_stats.num_preempted_reqs)
418
419
420
        self.counter_prompt_tokens.inc(iteration_stats.num_prompt_tokens)
        self.counter_generation_tokens.inc(
            iteration_stats.num_generation_tokens)
421
422
423
        self.histogram_iteration_tokens.observe(
            iteration_stats.num_prompt_tokens + \
            iteration_stats.num_generation_tokens)
424

425
426
427
428
429
        for max_gen_tokens in iteration_stats.max_num_generation_tokens_iter:
            self.histogram_max_num_generation_tokens_request.observe(
                max_gen_tokens)
        for n_param in iteration_stats.n_params_iter:
            self.histogram_n_request.observe(n_param)
430
431
432
433
434
        for ttft in iteration_stats.time_to_first_tokens_iter:
            self.histogram_time_to_first_token.observe(ttft)
        for tpot in iteration_stats.time_per_output_tokens_iter:
            self.histogram_time_per_output_token.observe(tpot)

435
        for finished_request in iteration_stats.finished_requests:
436
            self.counter_request_success[finished_request.finish_reason].inc()
437
438
            self.histogram_e2e_time_request.observe(
                finished_request.e2e_latency)
439
440
441
442
            self.histogram_queue_time_request.observe(
                finished_request.queued_time)
            self.histogram_prefill_time_request.observe(
                finished_request.prefill_time)
443
444
445
446
            self.histogram_inference_time_request.observe(
                finished_request.inference_time)
            self.histogram_decode_time_request.observe(
                finished_request.decode_time)
447
448
449
450
            self.histogram_num_prompt_tokens_request.observe(
                finished_request.num_prompt_tokens)
            self.histogram_num_generation_tokens_request.observe(
                finished_request.num_generation_tokens)
451
452
            self.histogram_max_tokens_request.observe(
                finished_request.max_tokens_param)
453

454
455
456
457
458
459
460
461
462
463
464
465
466
        if self.gauge_lora_info is not None:
            running_lora_adapters = \
                ",".join(iteration_stats.running_lora_adapters.keys())
            waiting_lora_adapters = \
                ",".join(iteration_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()

467
468
469
    def log_engine_initialized(self):
        self.log_metrics_info("cache_config", self.vllm_config.cache_config)

470

471
def build_buckets(mantissa_lst: list[int], max_value: int) -> list[int]:
472
473
474
475
476
477
    """
    Builds a list of buckets with increasing powers of 10 multiplied by
    mantissa values until the value exceeds the specified maximum.

    """
    exponent = 0
478
    buckets: list[int] = []
479
480
481
482
483
484
485
486
487
488
    while True:
        for m in mantissa_lst:
            value = m * 10**exponent
            if value <= max_value:
                buckets.append(value)
            else:
                return buckets
        exponent += 1


489
def build_1_2_5_buckets(max_value: int) -> list[int]:
490
491
492
493
494
495
    """
    Example:
    >>> build_1_2_5_buckets(100)
    [1, 2, 5, 10, 20, 50, 100]
    """
    return build_buckets([1, 2, 5], max_value)
496
497


498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
def setup_default_loggers(
    vllm_config: VllmConfig,
    log_stats: bool,
    engine_num: int,
    custom_stat_loggers: Optional[list[StatLoggerFactory]] = None,
) -> list[list[StatLoggerBase]]:
    """Setup logging and prometheus metrics."""
    if not log_stats:
        return []

    factories: list[StatLoggerFactory]
    if custom_stat_loggers is not None:
        factories = custom_stat_loggers
    else:
        factories = [PrometheusStatLogger]
        if logger.isEnabledFor(logging.INFO):
            factories.append(LoggingStatLogger)

    stat_loggers: list[list[StatLoggerBase]] = []
    for i in range(engine_num):
        per_engine_stat_loggers: list[StatLoggerBase] = []
        for logger_factory in factories:
            per_engine_stat_loggers.append(logger_factory(vllm_config, i))
        stat_loggers.append(per_engine_stat_loggers)

    return stat_loggers