A high-throughput and memory-efficient inference and serving engine for LLMs
Mirrored from https://github.com/tduncan-lum/Nvidia-Optimization-Stack---VLLM.git
Synced Nov 15, 21:00 UTC
[V1] Simplify stats logging (#14082)
Signed-off-by: Nick Hill <nhill@redhat.com>
Nick Hill committed
Mar 3, 2025 at 10:34 UTC
872db2be0e8499960cedbbc2fbcbcb2837b53be2
3 files changed
+30
-37
vllm/v1/engine/async_llm.py
+11
-10
@@ -1,6 +1,7 @@
1
# SPDX-License-Identifier: Apache-2.0
2
3
import asyncio
4
+import logging
5
import os
6
from collections.abc import AsyncGenerator, Mapping
7
from typing import Optional, Union
@@ -57,10 +58,9 @@ class AsyncLLM(EngineClient):
58
self.log_stats = log_stats
59
self.stat_loggers: list[StatLoggerBase] = []
60
if self.log_stats:
60
- self.stat_loggers.extend([
61
- LoggingStatLogger(),
62
- PrometheusStatLogger(vllm_config),
63
- ])
61
+ if logger.isEnabledFor(logging.INFO):
62
+ self.stat_loggers.append(LoggingStatLogger())
63
+ self.stat_loggers.append(PrometheusStatLogger(vllm_config))
64
65
# Tokenizer (+ ensure liveness if running in another process).
66
self.tokenizer = init_tokenizer_from_configs(
@@ -287,7 +287,7 @@ class AsyncLLM(EngineClient):
287
# 4) Logging.
288
# TODO(rob): make into a coroutine and launch it in
289
# background thread once Prometheus overhead is non-trivial.
290
- self._log_stats(
290
+ self._record_stats(
291
scheduler_stats=outputs.scheduler_stats,
292
iteration_stats=iteration_stats,
293
)
@@ -306,7 +306,7 @@ class AsyncLLM(EngineClient):
306
if self.log_requests:
307
logger.info("Aborted request %s.", request_id)
308
309
- def _log_stats(
309
+ def _record_stats(
310
self,
311
scheduler_stats: Optional[SchedulerStats],
312
iteration_stats: Optional[IterationStats],
@@ -316,9 +316,9 @@ class AsyncLLM(EngineClient):
316
317
assert scheduler_stats is not None
318
assert iteration_stats is not None
319
- for logger in self.stat_loggers:
320
- logger.log(scheduler_stats=scheduler_stats,
321
- iteration_stats=iteration_stats)
319
+ for stat_logger in self.stat_loggers:
320
+ stat_logger.record(scheduler_stats=scheduler_stats,
321
+ iteration_stats=iteration_stats)
322
323
def encode(
324
self,
@@ -354,7 +354,8 @@ class AsyncLLM(EngineClient):
354
scheduler_outputs=None,
355
model_output=None,
356
) -> None:
357
- logger.debug("Called do_log_stats.")
357
+ for stat_logger in self.stat_loggers:
358
+ stat_logger.log()
359
360
async def check_health(self) -> None:
361
logger.debug("Called check_health.")
vllm/v1/engine/core.py
+4
-13
@@ -316,19 +316,10 @@ class EngineCoreProc(EngineCore):
316
# Loop until process is sent a SIGINT or SIGTERM
317
while True:
318
# 1) Poll the input queue until there is work to do.
319
- if not self.scheduler.has_unfinished_requests():
320
- while True:
321
- try:
322
- req = self.input_queue.get(timeout=POLLING_TIMEOUT_S)
323
- self._handle_client_request(*req)
324
- break
325
- except queue.Empty:
326
- logger.debug("EngineCore busy loop waiting.")
327
- # Break out the loop so we can log_stats in step().
328
- if self.log_stats:
329
- break
330
- except BaseException:
331
- raise
319
+ while not self.scheduler.has_unfinished_requests():
320
+ logger.debug("EngineCore busy loop waiting.")
321
+ req = self.input_queue.get()
322
+ self._handle_client_request(*req)
323
324
# 2) Handle any new client requests.
325
while not self.input_queue.empty():
vllm/v1/metrics/loggers.py
+15
-14
@@ -21,15 +21,19 @@ _LOCAL_LOGGING_INTERVAL_SEC = 5.0
21
class StatLoggerBase(ABC):
22
23
@abstractmethod
24
- def log(self, scheduler_stats: SchedulerStats,
25
- iteration_stats: IterationStats):
24
+ def record(self, scheduler_stats: SchedulerStats,
25
+ iteration_stats: IterationStats):
26
...
27
28
+ def log(self): # noqa
29
+ pass
30
+
31
32
class LoggingStatLogger(StatLoggerBase):
33
34
def __init__(self):
35
self._reset(time.monotonic())
36
+ self.last_scheduler_stats = SchedulerStats()
37
38
def _reset(self, now):
39
self.last_log_time = now
@@ -41,11 +45,6 @@ class LoggingStatLogger(StatLoggerBase):
45
# Prefix cache metrics. TODO: Make the interval configurable.
46
self.prefix_caching_metrics = PrefixCachingMetrics()
47
44
- def _local_interval_elapsed(self, now: float) -> bool:
45
- # Log every _LOCAL_LOGGING_INTERVAL_SEC.
46
- elapsed_time = now - self.last_log_time
47
- return elapsed_time > _LOCAL_LOGGING_INTERVAL_SEC
48
-
48
def _track_iteration_stats(self, iteration_stats: IterationStats):
49
# Save tracked stats for token counters.
50
self.num_prompt_tokens.append(iteration_stats.num_prompt_tokens)
@@ -56,24 +55,26 @@ class LoggingStatLogger(StatLoggerBase):
55
# Compute summary metrics for tracked stats
56
return float(np.sum(tracked_stats) / (now - self.last_log_time))
57
59
- def log(self, scheduler_stats: SchedulerStats,
60
- iteration_stats: IterationStats):
58
+ def record(self, scheduler_stats: SchedulerStats,
59
+ iteration_stats: IterationStats):
60
"""Log Stats to standard output."""
61
62
self._track_iteration_stats(iteration_stats)
63
64
self.prefix_caching_metrics.observe(scheduler_stats.prefix_cache_stats)
65
67
- now = time.monotonic()
68
- if not self._local_interval_elapsed(now):
69
- return
66
+ self.last_scheduler_stats = scheduler_stats
67
68
+ def log(self):
69
+ now = time.monotonic()
70
prompt_throughput = self._get_throughput(self.num_prompt_tokens, now)
71
generation_throughput = self._get_throughput(
72
self.num_generation_tokens, now)
73
74
self._reset(now)
75
76
+ scheduler_stats = self.last_scheduler_stats
77
+
78
# Format and print output.
79
logger.info(
80
"Avg prompt throughput: %.1f tokens/s, "
@@ -274,8 +275,8 @@ class PrometheusStatLogger(StatLoggerBase):
275
labelnames=metrics_info.keys()).labels(**metrics_info)
276
info_gauge.set(1)
277
277
- def log(self, scheduler_stats: SchedulerStats,
278
- iteration_stats: IterationStats):
278
+ def record(self, scheduler_stats: SchedulerStats,
279
+ iteration_stats: IterationStats):
280
"""Log to prometheus."""
281
self.gauge_scheduler_running.set(scheduler_stats.num_running_reqs)
282
self.gauge_scheduler_waiting.set(scheduler_stats.num_waiting_reqs)