@tduncan / Nvidia-Optimization-Stack-VLLM Mirror · read-only / commits / 29d1ffc5b4

Fork 0

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, 01:00 UTC

[DP] Fix Prometheus Logging (#21257)

Signed-off-by: Robert Shaw <robshaw@redhat.com> Co-authored-by: Robert Shaw <robshaw@redhat.com>

Robert Shaw committed Jul 21, 2025 at 12:11 UTC 29d1ffc5b4c763ef76aff9e3f617fa60dd292418

6 files changed +378 -258

tests/v1/engine/test_async_llm.py

+4 -3

@@ -336,9 +336,10 @@ async def test_customize_loggers(monkeypatch):

336

337 await engine.do_log_stats()

338

339 - assert len(engine.stat_loggers) == 1

340 - assert len(engine.stat_loggers[0]) == 1

341 - engine.stat_loggers[0][0].log.assert_called_once()

339 + stat_loggers = engine.logger_manager.per_engine_logger_dict

340 + assert len(stat_loggers) == 1

341 + assert len(stat_loggers[0]) == 1

342 + stat_loggers[0][0].log.assert_called_once()

343

344

345 @pytest.mark.asyncio(scope="module")

tests/v1/test_async_llm_dp.py

+4 -2

@@ -90,8 +90,10 @@ async def test_load(output_kind: RequestOutputKind,

90 def __init__(self, vllm_config: VllmConfig, engine_index: int = 0):

91 stats_loggers[engine_index] = self

93 - def record(self, scheduler_stats: Optional[SchedulerStats],

94 - iteration_stats: Optional[IterationStats]):

93 + def record(self,

94 + scheduler_stats: Optional[SchedulerStats],

95 + iteration_stats: Optional[IterationStats],

96 + engine_idx: int = 0):

97 if iteration_stats:

98 self.finished_req_count += len(

99 iteration_stats.finished_requests)

vllm/v1/engine/async_llm.py

+26 -43

@@ -36,10 +36,9 @@ from vllm.v1.engine.output_processor import (OutputProcessor,

36 from vllm.v1.engine.parallel_sampling import ParentRequest

37 from vllm.v1.engine.processor import Processor

38 from vllm.v1.executor.abstract import Executor

39 -from vllm.v1.metrics.loggers import (StatLoggerBase, StatLoggerFactory,

40 - setup_default_loggers)

39 +from vllm.v1.metrics.loggers import StatLoggerFactory, StatLoggerManager

40 from vllm.v1.metrics.prometheus import shutdown_prometheus

42 -from vllm.v1.metrics.stats import IterationStats, SchedulerStats

41 +from vllm.v1.metrics.stats import IterationStats

43 logger = init_logger(__name__)

@@ -95,14 +94,6 @@ class AsyncLLM(EngineClient):

94 self.log_requests = log_requests

95 self.log_stats = log_stats

98 - # Set up stat loggers; independent set for each DP rank.

99 - self.stat_loggers: list[list[StatLoggerBase]] = setup_default_loggers(

100 - vllm_config=vllm_config,

101 - log_stats=self.log_stats,

102 - engine_num=vllm_config.parallel_config.data_parallel_size,

103 - custom_stat_loggers=stat_loggers,

104 - )

105 -

97 # Tokenizer (+ ensure liveness if running in another process).

98 self.tokenizer = init_tokenizer_from_configs(

99 model_config=vllm_config.model_config,

@@ -121,7 +112,6 @@ class AsyncLLM(EngineClient):

112 log_stats=self.log_stats)

113

114 # EngineCore (starts the engine in background process).

124 -

115 self.engine_core = EngineCoreClient.make_async_mp_client(

116 vllm_config=vllm_config,

117 executor_class=executor_class,

@@ -129,9 +119,17 @@ class AsyncLLM(EngineClient):

119 client_addresses=client_addresses,

120 client_index=client_index,

121 )

132 - if self.stat_loggers:

133 - for stat_logger in self.stat_loggers[0]:

134 - stat_logger.log_engine_initialized()

122 +

123 + # Loggers.

124 + self.logger_manager: Optional[StatLoggerManager] = None

125 + if self.log_stats:

126 + self.logger_manager = StatLoggerManager(

127 + vllm_config=vllm_config,

128 + engine_idxs=self.engine_core.engine_ranks,

129 + custom_stat_loggers=stat_loggers,

130 + )

131 + self.logger_manager.log_engine_initialized()

132 +

133 self.output_handler: Optional[asyncio.Task] = None

134 try:

135 # Start output handler eagerly if we are in the asyncio eventloop.

@@ -370,7 +368,7 @@ class AsyncLLM(EngineClient):

368 engine_core = self.engine_core

369 output_processor = self.output_processor

370 log_stats = self.log_stats

373 - stat_loggers = self.stat_loggers if log_stats else None

371 + logger_manager = self.logger_manager

372

373 async def output_handler():

374 try:

@@ -410,9 +408,9 @@ class AsyncLLM(EngineClient):

408 # 4) Logging.

409 # TODO(rob): make into a coroutine and launch it in

410 # background thread once Prometheus overhead is non-trivial.

413 - if stat_loggers:

414 - AsyncLLM._record_stats(

415 - stat_loggers[outputs.engine_index],

411 + if logger_manager:

412 + logger_manager.record(

413 + engine_idx=outputs.engine_index,

414 scheduler_stats=outputs.scheduler_stats,

415 iteration_stats=iteration_stats,

416 )

@@ -431,18 +429,6 @@ class AsyncLLM(EngineClient):

429 if self.log_requests:

430 logger.info("Aborted request %s.", request_id)

431

434 - @staticmethod

435 - def _record_stats(

436 - stat_loggers: list[StatLoggerBase],

437 - scheduler_stats: Optional[SchedulerStats],

438 - iteration_stats: Optional[IterationStats],

439 - ):

440 - """static so that it can be used from the output_handler task

441 - without a circular ref to AsyncLLM."""

442 - for stat_logger in stat_loggers:

443 - stat_logger.record(scheduler_stats=scheduler_stats,

444 - iteration_stats=iteration_stats)

445 -

432 async def encode(

433 self,

434 prompt: PromptType,

@@ -547,9 +533,8 @@ class AsyncLLM(EngineClient):

533 scheduler_outputs=None,

534 model_output=None,

535 ) -> None:

550 - for loggers in self.stat_loggers:

551 - for stat_logger in loggers:

552 - stat_logger.log()

536 + if self.logger_manager:

537 + self.logger_manager.log()

538

539 async def check_health(self) -> None:

540 logger.debug("Called check_health.")

@@ -653,18 +638,16 @@ class AsyncLLM(EngineClient):

638 new_data_parallel_size

639

640 # recreate stat loggers

656 - if new_data_parallel_size > old_data_parallel_size:

657 - stat_loggers: list[list[StatLoggerBase]] = setup_default_loggers(

641 + if new_data_parallel_size > old_data_parallel_size and self.log_stats:

642 + # TODO(rob): fix this after talking with Ray team.

643 + # This resets all the prometheus metrics since we

644 + # unregister during initialization. Need to understand

645 + # the intended behavior here better.

646 + self.logger_manager = StatLoggerManager(

647 vllm_config=self.vllm_config,

659 - log_stats=self.log_stats,

660 - engine_num=new_data_parallel_size,

648 + engine_idxs=list(range(new_data_parallel_size)),

649 custom_stat_loggers=None,

650 )

663 - num_new_engines = len(stat_loggers) - len(self.stat_loggers)

664 - self.stat_loggers.extend(stat_loggers[-num_new_engines:])

665 - else:

666 - for _ in range(old_data_parallel_size - new_data_parallel_size):

667 - self.stat_loggers.pop()

651

652 @property

653 def is_running(self) -> bool:

vllm/v1/engine/core_client.py

+5 -4

@@ -432,14 +432,15 @@ class MPClient(EngineCoreClient):

432 external_dp_lb = parallel_config.data_parallel_external_lb

433

434 offline_mode = parallel_config.data_parallel_rank_local is not None

435 - engine_ranks = [dp_rank] if (offline_mode

436 - or external_dp_lb) else range(dp_size)

435 + self.engine_ranks = ([dp_rank] if

436 + (offline_mode or external_dp_lb) else list(

437 + range(dp_size)))

438 assert parallel_config.data_parallel_size_local <= len(

438 - engine_ranks)

439 + self.engine_ranks)

440

441 # ZMQ identity of each engine that this client will talk to.

442 self.core_engines: list[EngineIdentity] = [

442 - index.to_bytes(2, "little") for index in engine_ranks

443 + index.to_bytes(2, "little") for index in self.engine_ranks

444 ]

445

446 # Wait for ready messages from each engine on the input socket.

vllm/v1/metrics/loggers.py

+339 -202

@@ -4,7 +4,7 @@

4 import logging

5 import time

6 from abc import ABC, abstractmethod

7 -from typing import Callable, Optional

7 +from typing import Callable, Optional, Union

9 import numpy as np

10 import prometheus_client

@@ -35,8 +35,10 @@ class StatLoggerBase(ABC):

35 ...

37 @abstractmethod

38 - def record(self, scheduler_stats: Optional[SchedulerStats],

39 - iteration_stats: Optional[IterationStats]):

38 + def record(self,

39 + scheduler_stats: Optional[SchedulerStats],

40 + iteration_stats: Optional[IterationStats],

41 + engine_idx: int = 0):

42 ...

44 @abstractmethod

@@ -78,8 +80,10 @@ class LoggingStatLogger(StatLoggerBase):

80 # Compute summary metrics for tracked stats

81 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 + def record(self,

84 + scheduler_stats: Optional[SchedulerStats],

85 + iteration_stats: Optional[IterationStats],

86 + engine_idx: int = 0):

87 """Log Stats to standard output."""

89 if iteration_stats:

@@ -146,233 +150,290 @@ class PrometheusStatLogger(StatLoggerBase):

150 _histogram_cls = prometheus_client.Histogram

151 _spec_decoding_cls = SpecDecodingProm

152

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

153 + def __init__(self,

154 + vllm_config: VllmConfig,

155 + engine_indexes: Optional[list[int]] = None):

156 + if engine_indexes is None:

157 + engine_indexes = [0]

158 + self.engine_indexes = engine_indexes

159

160 unregister_vllm_metrics()

161 self.vllm_config = vllm_config

153 - self.engine_index = engine_index

162 # Use this flag to hide metrics that were deprecated in

163 # a previous release and which will be removed future

164 self.show_hidden_metrics = \

165 vllm_config.observability_config.show_hidden_metrics

166

167 labelnames = ["model_name", "engine"]

160 - labelvalues = [

161 - vllm_config.model_config.served_model_name,

162 - str(engine_index)

163 - ]

164 -

168 + model_name = vllm_config.model_config.served_model_name

169 max_model_len = vllm_config.model_config.max_model_len

170

171 + if (len(self.engine_indexes) > 1

172 + and vllm_config.speculative_config is not None):

173 + raise NotImplementedError("Prometheus metrics with Spec Decoding "

174 + "with >1 EngineCore per AsyncLLM is not "

175 + "supported yet.")

176 + spec_decode_labelvalues = [

177 + vllm_config.model_config.served_model_name,

178 + str(self.engine_indexes[0])

179 + ]

180 self.spec_decoding_prom = self._spec_decoding_cls(

168 - vllm_config.speculative_config, labelnames, labelvalues)

181 + vllm_config.speculative_config, labelnames,

182 + spec_decode_labelvalues)

183

184 #

185 # Scheduler state

186 #

173 - self.gauge_scheduler_running = self._gauge_cls(

187 + gauge_scheduler_running = self._gauge_cls(

188 name="vllm:num_requests_running",

189 documentation="Number of requests in model execution batches.",

190 multiprocess_mode="mostrecent",

177 - labelnames=labelnames).labels(*labelvalues)

191 + labelnames=labelnames)

192 + self.gauge_scheduler_running = make_per_engine(gauge_scheduler_running,

193 + engine_indexes,

194 + model_name)

195

179 - self.gauge_scheduler_waiting = self._gauge_cls(

196 + gauge_scheduler_waiting = self._gauge_cls(

197 name="vllm:num_requests_waiting",

198 documentation="Number of requests waiting to be processed.",

199 multiprocess_mode="mostrecent",

183 - labelnames=labelnames).labels(*labelvalues)

200 + labelnames=labelnames)

201 + self.gauge_scheduler_waiting = make_per_engine(gauge_scheduler_waiting,

202 + engine_indexes,

203 + model_name)

204

205 #

206 # GPU cache

207 #

208 # Deprecated in 0.9 - Renamed as vllm:kv_cache_usage_perc

209 # TODO: in 0.10, only enable if show_hidden_metrics=True

190 - self.gauge_gpu_cache_usage = self._gauge_cls(

210 + gauge_gpu_cache_usage = self._gauge_cls(

211 name="vllm:gpu_cache_usage_perc",

212 documentation=(

213 "GPU KV-cache usage. 1 means 100 percent usage."

214 "DEPRECATED: Use vllm:kv_cache_usage_perc instead."),

215 multiprocess_mode="mostrecent",

196 - labelnames=labelnames).labels(*labelvalues)

216 + labelnames=labelnames)

217 + self.gauge_gpu_cache_usage = make_per_engine(gauge_gpu_cache_usage,

218 + engine_indexes,

219 + model_name)

220

221 # Deprecated in 0.9 - Renamed as vllm:prefix_cache_queries

222 # TODO: in 0.10, only enable if show_hidden_metrics=True

200 - self.counter_gpu_prefix_cache_queries = self._counter_cls(

223 + counter_gpu_prefix_cache_queries = self._counter_cls(

224 name="vllm:gpu_prefix_cache_queries",

202 - documentation=

203 - ("GPU prefix cache queries, in terms of number of queried tokens."

204 - "DEPRECATED: Use vllm:prefix_cache_queries instead."),

205 - labelnames=labelnames).labels(*labelvalues)

225 + documentation=(

226 + "GPU prefix cache queries, in terms of number of queried"

227 + "tokens. DEPRECATED: Use vllm:prefix_cache_queries instead."),

228 + labelnames=labelnames)

229 + self.counter_gpu_prefix_cache_queries = make_per_engine(

230 + counter_gpu_prefix_cache_queries, engine_indexes, model_name)

231

232 # Deprecated in 0.9 - Renamed as vllm:prefix_cache_hits

233 # TODO: in 0.10, only enable if show_hidden_metrics=True

209 - self.counter_gpu_prefix_cache_hits = self._counter_cls(

234 + counter_gpu_prefix_cache_hits = self._counter_cls(

235 name="vllm:gpu_prefix_cache_hits",

236 documentation=(

212 - "GPU prefix cache hits, in terms of number of cached tokens."

213 - "DEPRECATED: Use vllm:prefix_cache_hits instead."),

214 - labelnames=labelnames).labels(*labelvalues)

237 + "GPU prefix cache hits, in terms of number of cached "

238 + "tokens. DEPRECATED: Use vllm:prefix_cache_hits instead."),

239 + labelnames=labelnames)

240 + self.counter_gpu_prefix_cache_hits = make_per_engine(

241 + counter_gpu_prefix_cache_hits, engine_indexes, model_name)

242

216 - self.gauge_kv_cache_usage = self._gauge_cls(

243 + gauge_kv_cache_usage = self._gauge_cls(

244 name="vllm:kv_cache_usage_perc",

245 documentation="KV-cache usage. 1 means 100 percent usage.",

219 - labelnames=labelnames).labels(*labelvalues)

246 + labelnames=labelnames)

247 + self.gauge_kv_cache_usage = make_per_engine(gauge_kv_cache_usage,

248 + engine_indexes, model_name)

249

221 - self.counter_prefix_cache_queries = self._counter_cls(

250 + counter_prefix_cache_queries = self._counter_cls(

251 name="vllm:prefix_cache_queries",

252 documentation=(

253 "Prefix cache queries, in terms of number of queried tokens."),

225 - labelnames=labelnames).labels(*labelvalues)

254 + labelnames=labelnames)

255 + self.counter_prefix_cache_queries = make_per_engine(

256 + counter_prefix_cache_queries, engine_indexes, model_name)

257

227 - self.counter_prefix_cache_hits = self._counter_cls(

258 + counter_prefix_cache_hits = self._counter_cls(

259 name="vllm:prefix_cache_hits",

260 documentation=(

261 "Prefix cache hits, in terms of number of cached tokens."),

231 - labelnames=labelnames).labels(*labelvalues)

262 + labelnames=labelnames)

263 + self.counter_prefix_cache_hits = make_per_engine(

264 + counter_prefix_cache_hits, engine_indexes, model_name)

265

266 #

267 # Counters

268 #

236 - self.counter_num_preempted_reqs = self._counter_cls(

269 + counter_num_preempted_reqs = self._counter_cls(

270 name="vllm:num_preemptions",

271 documentation="Cumulative number of preemption from the engine.",

239 - labelnames=labelnames).labels(*labelvalues)

272 + labelnames=labelnames)

273 + self.counter_num_preempted_reqs = make_per_engine(

274 + counter_num_preempted_reqs, engine_indexes, model_name)

275

241 - self.counter_prompt_tokens = self._counter_cls(

276 + counter_prompt_tokens = self._counter_cls(

277 name="vllm:prompt_tokens",

278 documentation="Number of prefill tokens processed.",

244 - labelnames=labelnames).labels(*labelvalues)

279 + labelnames=labelnames)

280 + self.counter_prompt_tokens = make_per_engine(counter_prompt_tokens,

281 + engine_indexes,

282 + model_name)

283

246 - self.counter_generation_tokens = self._counter_cls(

284 + counter_generation_tokens = self._counter_cls(

285 name="vllm:generation_tokens",

286 documentation="Number of generation tokens processed.",

249 - labelnames=labelnames).labels(*labelvalues)

287 + labelnames=labelnames)

288 + self.counter_generation_tokens = make_per_engine(

289 + counter_generation_tokens, engine_indexes, model_name)

290

251 - self.counter_request_success: dict[FinishReason,

252 - prometheus_client.Counter] = {}

291 + self.counter_request_success: dict[FinishReason, dict[

292 + int, prometheus_client.Counter]] = {}

293 counter_request_success_base = self._counter_cls(

294 name="vllm:request_success",

295 documentation="Count of successfully processed requests.",

296 labelnames=labelnames + ["finished_reason"])

297 for reason in FinishReason:

258 - self.counter_request_success[

259 - reason] = counter_request_success_base.labels(*(labelvalues +

260 - [str(reason)]))

298 + self.counter_request_success[reason] = {

299 + idx:

300 + counter_request_success_base.labels(model_name, str(idx),

301 + str(reason))

302 + for idx in engine_indexes

303 + }

304

305 #

306 # Histograms of counts

307 #

265 - self.histogram_num_prompt_tokens_request = \

266 - self._histogram_cls(

267 - name="vllm:request_prompt_tokens",

268 - documentation="Number of prefill tokens processed.",

269 - buckets=build_1_2_5_buckets(max_model_len),

270 - labelnames=labelnames).labels(*labelvalues)

271 -

272 - self.histogram_num_generation_tokens_request = \

273 - self._histogram_cls(

274 - name="vllm:request_generation_tokens",

275 - documentation="Number of generation tokens processed.",

276 - buckets=build_1_2_5_buckets(max_model_len),

277 - labelnames=labelnames).labels(*labelvalues)

308 + histogram_num_prompt_tokens_request = self._histogram_cls(

309 + name="vllm:request_prompt_tokens",

310 + documentation="Number of prefill tokens processed.",

311 + buckets=build_1_2_5_buckets(max_model_len),

312 + labelnames=labelnames)

313 + self.histogram_num_prompt_tokens_request = make_per_engine(

314 + histogram_num_prompt_tokens_request, engine_indexes, model_name)

315 +

316 + histogram_num_generation_tokens_request = self._histogram_cls(

317 + name="vllm:request_generation_tokens",

318 + documentation="Number of generation tokens processed.",

319 + buckets=build_1_2_5_buckets(max_model_len),

320 + labelnames=labelnames)

321 + self.histogram_num_generation_tokens_request = make_per_engine(

322 + histogram_num_generation_tokens_request, engine_indexes,

323 + model_name)

324

325 # TODO: This metric might be incorrect in case of using multiple

326 # api_server counts which uses prometheus mp.

327 # See: https://github.com/vllm-project/vllm/pull/18053

282 - self.histogram_iteration_tokens = \

283 - self._histogram_cls(

284 - name="vllm:iteration_tokens_total",

285 - documentation="Histogram of number of tokens per engine_step.",

286 - buckets=[

287 - 1, 8, 16, 32, 64, 128, 256, 512, 1024, 2048, 4096, 8192,

288 - 16384

289 - ],

290 - labelnames=labelnames).labels(*labelvalues)

291 -

292 - self.histogram_max_num_generation_tokens_request = \

293 - self._histogram_cls(

294 - name="vllm:request_max_num_generation_tokens",

295 - documentation=

296 - "Histogram of maximum number of requested generation tokens.",

297 - buckets=build_1_2_5_buckets(max_model_len),

298 - labelnames=labelnames).labels(*labelvalues)

299 -

300 - self.histogram_n_request = \

301 - self._histogram_cls(

302 - name="vllm:request_params_n",

303 - documentation="Histogram of the n request parameter.",

304 - buckets=[1, 2, 5, 10, 20],

305 - labelnames=labelnames).labels(*labelvalues)

306 -

307 - self.histogram_max_tokens_request = \

308 - self._histogram_cls(

309 - name="vllm:request_params_max_tokens",

310 - documentation="Histogram of the max_tokens request parameter.",

311 - buckets=build_1_2_5_buckets(max_model_len),

312 - labelnames=labelnames).labels(*labelvalues)

328 + histogram_iteration_tokens = self._histogram_cls(

329 + name="vllm:iteration_tokens_total",

330 + documentation="Histogram of number of tokens per engine_step.",

331 + buckets=[

332 + 1, 8, 16, 32, 64, 128, 256, 512, 1024, 2048, 4096, 8192, 16384

333 + ],

334 + labelnames=labelnames)

335 + self.histogram_iteration_tokens = make_per_engine(

336 + histogram_iteration_tokens, engine_indexes, model_name)

337 +

338 + histogram_max_num_generation_tokens_request = self._histogram_cls(

339 + name="vllm:request_max_num_generation_tokens",

340 + documentation=

341 + "Histogram of maximum number of requested generation tokens.",

342 + buckets=build_1_2_5_buckets(max_model_len),

343 + labelnames=labelnames)

344 + self.histogram_max_num_generation_tokens_request = make_per_engine(

345 + histogram_max_num_generation_tokens_request, engine_indexes,

346 + model_name)

347 +

348 + histogram_n_request = self._histogram_cls(

349 + name="vllm:request_params_n",

350 + documentation="Histogram of the n request parameter.",

351 + buckets=[1, 2, 5, 10, 20],

352 + labelnames=labelnames)

353 + self.histogram_n_request = make_per_engine(histogram_n_request,

354 + engine_indexes, model_name)

355 +

356 + histogram_max_tokens_request = self._histogram_cls(

357 + name="vllm:request_params_max_tokens",

358 + documentation="Histogram of the max_tokens request parameter.",

359 + buckets=build_1_2_5_buckets(max_model_len),

360 + labelnames=labelnames)

361 + self.histogram_max_tokens_request = make_per_engine(

362 + histogram_max_tokens_request, engine_indexes, model_name)

363

364 #

365 # Histogram of timing intervals

366 #

317 - self.histogram_time_to_first_token = \

318 - self._histogram_cls(

319 - name="vllm:time_to_first_token_seconds",

320 - documentation="Histogram of time to first token in seconds.",

321 - buckets=[

322 - 0.001, 0.005, 0.01, 0.02, 0.04, 0.06, 0.08, 0.1, 0.25, 0.5,

323 - 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, 40.0, 80.0, 160.0,

324 - 640.0, 2560.0

325 - ],

326 - labelnames=labelnames).labels(*labelvalues)

327 -

328 - self.histogram_time_per_output_token = \

329 - self._histogram_cls(

330 - name="vllm:time_per_output_token_seconds",

331 - documentation="Histogram of time per output token in seconds.",

332 - buckets=[

333 - 0.01, 0.025, 0.05, 0.075, 0.1, 0.15, 0.2, 0.3, 0.4, 0.5,

334 - 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, 40.0, 80.0

335 - ],

336 - labelnames=labelnames).labels(*labelvalues)

367 + histogram_time_to_first_token = self._histogram_cls(

368 + name="vllm:time_to_first_token_seconds",

369 + documentation="Histogram of time to first token in seconds.",

370 + buckets=[

371 + 0.001, 0.005, 0.01, 0.02, 0.04, 0.06, 0.08, 0.1, 0.25, 0.5,

372 + 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, 40.0, 80.0, 160.0, 640.0,

373 + 2560.0

374 + ],

375 + labelnames=labelnames)

376 + self.histogram_time_to_first_token = make_per_engine(

377 + histogram_time_to_first_token, engine_indexes, model_name)

378 +

379 + histogram_time_per_output_token = self._histogram_cls(

380 + name="vllm:time_per_output_token_seconds",

381 + documentation="Histogram of time per output token in seconds.",

382 + buckets=[

383 + 0.01, 0.025, 0.05, 0.075, 0.1, 0.15, 0.2, 0.3, 0.4, 0.5, 0.75,

384 + 1.0, 2.5, 5.0, 7.5, 10.0, 20.0, 40.0, 80.0

385 + ],

386 + labelnames=labelnames)

387 + self.histogram_time_per_output_token = make_per_engine(

388 + histogram_time_per_output_token, engine_indexes, model_name)

389

390 request_latency_buckets = [

391 0.3, 0.5, 0.8, 1.0, 1.5, 2.0, 2.5, 5.0, 10.0, 15.0, 20.0, 30.0,

392 40.0, 50.0, 60.0, 120.0, 240.0, 480.0, 960.0, 1920.0, 7680.0

393 ]

342 - self.histogram_e2e_time_request = \

343 - self._histogram_cls(

344 - name="vllm:e2e_request_latency_seconds",

345 - documentation="Histogram of e2e request latency in seconds.",

346 - buckets=request_latency_buckets,

347 - labelnames=labelnames).labels(*labelvalues)

348 - self.histogram_queue_time_request = \

349 - self._histogram_cls(

350 - name="vllm:request_queue_time_seconds",

351 - documentation=

352 - "Histogram of time spent in WAITING phase for request.",

353 - buckets=request_latency_buckets,

354 - labelnames=labelnames).labels(*labelvalues)

355 - self.histogram_inference_time_request = \

356 - self._histogram_cls(

357 - name="vllm:request_inference_time_seconds",

358 - documentation=

359 - "Histogram of time spent in RUNNING phase for request.",

360 - buckets=request_latency_buckets,

361 - labelnames=labelnames).labels(*labelvalues)

362 - self.histogram_prefill_time_request = \

363 - self._histogram_cls(

364 - name="vllm:request_prefill_time_seconds",

365 - documentation=

366 - "Histogram of time spent in PREFILL phase for request.",

367 - buckets=request_latency_buckets,

368 - labelnames=labelnames).labels(*labelvalues)

369 - self.histogram_decode_time_request = \

370 - self._histogram_cls(

371 - name="vllm:request_decode_time_seconds",

372 - documentation=

373 - "Histogram of time spent in DECODE phase for request.",

374 - buckets=request_latency_buckets,

375 - labelnames=labelnames).labels(*labelvalues)

394 + histogram_e2e_time_request = self._histogram_cls(

395 + name="vllm:e2e_request_latency_seconds",

396 + documentation="Histogram of e2e request latency in seconds.",

397 + buckets=request_latency_buckets,

398 + labelnames=labelnames)

399 + self.histogram_e2e_time_request = make_per_engine(

400 + histogram_e2e_time_request, engine_indexes, model_name)

401 +

402 + histogram_queue_time_request = self._histogram_cls(

403 + name="vllm:request_queue_time_seconds",

404 + documentation=

405 + "Histogram of time spent in WAITING phase for request.",

406 + buckets=request_latency_buckets,

407 + labelnames=labelnames)

408 + self.histogram_queue_time_request = make_per_engine(

409 + histogram_queue_time_request, engine_indexes, model_name)

410 +

411 + histogram_inference_time_request = self._histogram_cls(

412 + name="vllm:request_inference_time_seconds",

413 + documentation=

414 + "Histogram of time spent in RUNNING phase for request.",

415 + buckets=request_latency_buckets,

416 + labelnames=labelnames)

417 + self.histogram_inference_time_request = make_per_engine(

418 + histogram_inference_time_request, engine_indexes, model_name)

419 +

420 + histogram_prefill_time_request = self._histogram_cls(

421 + name="vllm:request_prefill_time_seconds",

422 + documentation=

423 + "Histogram of time spent in PREFILL phase for request.",

424 + buckets=request_latency_buckets,

425 + labelnames=labelnames)

426 + self.histogram_prefill_time_request = make_per_engine(

427 + histogram_prefill_time_request, engine_indexes, model_name)

428 +

429 + histogram_decode_time_request = self._histogram_cls(

430 + name="vllm:request_decode_time_seconds",

431 + documentation=

432 + "Histogram of time spent in DECODE phase for request.",

433 + buckets=request_latency_buckets,

434 + labelnames=labelnames)

435 + self.histogram_decode_time_request = make_per_engine(

436 + histogram_decode_time_request, engine_indexes, model_name)

437

438 #

439 # LoRA metrics

@@ -382,6 +443,9 @@ class PrometheusStatLogger(StatLoggerBase):

443 # api_server counts which uses prometheus mp.

444 self.gauge_lora_info: Optional[prometheus_client.Gauge] = None

445 if vllm_config.lora_config is not None:

446 + if len(self.engine_indexes) > 1:

447 + raise NotImplementedError(

448 + "LoRA in DP mode is not supported yet.")

449 self.labelname_max_lora = "max_lora"

450 self.labelname_waiting_lora_adapters = "waiting_lora_adapters"

451 self.labelname_running_lora_adapters = "running_lora_adapters"

@@ -399,9 +463,8 @@ class PrometheusStatLogger(StatLoggerBase):

463 )

464

465 def log_metrics_info(self, type: str, config_obj: SupportsMetricsInfo):

402 -

466 metrics_info = config_obj.metrics_info()

404 - metrics_info["engine"] = self.engine_index

467 + metrics_info["engine"] = ""

468

469 name, documentation = None, None

470 if type == "cache_config":

@@ -417,27 +480,36 @@ class PrometheusStatLogger(StatLoggerBase):

480 documentation=documentation,

481 multiprocess_mode="mostrecent",

482 labelnames=metrics_info.keys(),

420 - ).labels(**metrics_info)

421 - info_gauge.set(1)

422 -

423 - def record(self, scheduler_stats: Optional[SchedulerStats],

424 - iteration_stats: Optional[IterationStats]):

483 + )

484 + for engine_index in self.engine_indexes:

485 + metrics_info = config_obj.metrics_info()

486 + metrics_info["engine"] = str(engine_index)

487 + info_gauge.labels(**metrics_info).set(1)

488 +

489 + def record(self,

490 + scheduler_stats: Optional[SchedulerStats],

491 + iteration_stats: Optional[IterationStats],

492 + engine_idx: int = 0):

493 """Log to prometheus."""

494 if scheduler_stats is not None:

427 - self.gauge_scheduler_running.set(scheduler_stats.num_running_reqs)

428 - self.gauge_scheduler_waiting.set(scheduler_stats.num_waiting_reqs)

495 + self.gauge_scheduler_running[engine_idx].set(

496 + scheduler_stats.num_running_reqs)

497 + self.gauge_scheduler_waiting[engine_idx].set(

498 + scheduler_stats.num_waiting_reqs)

499

430 - self.gauge_gpu_cache_usage.set(scheduler_stats.kv_cache_usage)

431 - self.gauge_kv_cache_usage.set(scheduler_stats.kv_cache_usage)

500 + self.gauge_gpu_cache_usage[engine_idx].set(

501 + scheduler_stats.kv_cache_usage)

502 + self.gauge_kv_cache_usage[engine_idx].set(

503 + scheduler_stats.kv_cache_usage)

504

433 - self.counter_gpu_prefix_cache_queries.inc(

505 + self.counter_gpu_prefix_cache_queries[engine_idx].inc(

506 scheduler_stats.prefix_cache_stats.queries)

435 - self.counter_gpu_prefix_cache_hits.inc(

507 + self.counter_gpu_prefix_cache_hits[engine_idx].inc(

508 scheduler_stats.prefix_cache_stats.hits)

509

438 - self.counter_prefix_cache_queries.inc(

510 + self.counter_prefix_cache_queries[engine_idx].inc(

511 scheduler_stats.prefix_cache_stats.queries)

440 - self.counter_prefix_cache_hits.inc(

512 + self.counter_prefix_cache_hits[engine_idx].inc(

513 scheduler_stats.prefix_cache_stats.hits)

514

515 if scheduler_stats.spec_decoding_stats is not None:

@@ -447,42 +519,45 @@ class PrometheusStatLogger(StatLoggerBase):

519 if iteration_stats is None:

520 return

521

450 - self.counter_num_preempted_reqs.inc(iteration_stats.num_preempted_reqs)

451 - self.counter_prompt_tokens.inc(iteration_stats.num_prompt_tokens)

452 - self.counter_generation_tokens.inc(

522 + self.counter_num_preempted_reqs[engine_idx].inc(

523 + iteration_stats.num_preempted_reqs)

524 + self.counter_prompt_tokens[engine_idx].inc(

525 + iteration_stats.num_prompt_tokens)

526 + self.counter_generation_tokens[engine_idx].inc(

527 iteration_stats.num_generation_tokens)

454 - self.histogram_iteration_tokens.observe(

528 + self.histogram_iteration_tokens[engine_idx].observe(

529 iteration_stats.num_prompt_tokens + \

530 iteration_stats.num_generation_tokens)

531

532 for max_gen_tokens in iteration_stats.max_num_generation_tokens_iter:

459 - self.histogram_max_num_generation_tokens_request.observe(

460 - max_gen_tokens)

533 + self.histogram_max_num_generation_tokens_request[

534 + engine_idx].observe(max_gen_tokens)

535 for n_param in iteration_stats.n_params_iter:

462 - self.histogram_n_request.observe(n_param)

536 + self.histogram_n_request[engine_idx].observe(n_param)

537 for ttft in iteration_stats.time_to_first_tokens_iter:

464 - self.histogram_time_to_first_token.observe(ttft)

538 + self.histogram_time_to_first_token[engine_idx].observe(ttft)

539 for tpot in iteration_stats.time_per_output_tokens_iter:

466 - self.histogram_time_per_output_token.observe(tpot)

540 + self.histogram_time_per_output_token[engine_idx].observe(tpot)

541

542 for finished_request in iteration_stats.finished_requests:

469 - self.counter_request_success[finished_request.finish_reason].inc()

470 - self.histogram_e2e_time_request.observe(

543 + self.counter_request_success[

544 + finished_request.finish_reason][engine_idx].inc()

545 + self.histogram_e2e_time_request[engine_idx].observe(

546 finished_request.e2e_latency)

472 - self.histogram_queue_time_request.observe(

547 + self.histogram_queue_time_request[engine_idx].observe(

548 finished_request.queued_time)

474 - self.histogram_prefill_time_request.observe(

549 + self.histogram_prefill_time_request[engine_idx].observe(

550 finished_request.prefill_time)

476 - self.histogram_inference_time_request.observe(

551 + self.histogram_inference_time_request[engine_idx].observe(

552 finished_request.inference_time)

478 - self.histogram_decode_time_request.observe(

553 + self.histogram_decode_time_request[engine_idx].observe(

554 finished_request.decode_time)

480 - self.histogram_num_prompt_tokens_request.observe(

555 + self.histogram_num_prompt_tokens_request[engine_idx].observe(

556 finished_request.num_prompt_tokens)

482 - self.histogram_num_generation_tokens_request.observe(

557 + self.histogram_num_generation_tokens_request[engine_idx].observe(

558 finished_request.num_generation_tokens)

559 if finished_request.max_tokens_param:

485 - self.histogram_max_tokens_request.observe(

560 + self.histogram_max_tokens_request[engine_idx].observe(

561 finished_request.max_tokens_param)

562

563 if self.gauge_lora_info is not None:

@@ -502,6 +577,18 @@ class PrometheusStatLogger(StatLoggerBase):

577 self.log_metrics_info("cache_config", self.vllm_config.cache_config)

578

579

580 +PromMetric = Union[

581 + prometheus_client.Gauge,

582 + prometheus_client.Counter,

583 + prometheus_client.Histogram,

584 +]

585 +

586 +

587 +def make_per_engine(metric: PromMetric, engine_idxs: list[int],

588 + model_name: str) -> dict[int, PromMetric]:

589 + return {idx: metric.labels(model_name, str(idx)) for idx in engine_idxs}

590 +

591 +

592 def build_buckets(mantissa_lst: list[int], max_value: int) -> list[int]:

593 """

594 Builds a list of buckets with increasing powers of 10 multiplied by

@@ -529,29 +616,79 @@ def build_1_2_5_buckets(max_value: int) -> list[int]:

616 return build_buckets([1, 2, 5], max_value)

617

618

532 -def setup_default_loggers(

533 - vllm_config: VllmConfig,

534 - log_stats: bool,

535 - engine_num: int,

536 - custom_stat_loggers: Optional[list[StatLoggerFactory]] = None,

537 -) -> list[list[StatLoggerBase]]:

538 - """Setup logging and prometheus metrics."""

539 - if not log_stats:

540 - return []

541 -

542 - factories: list[StatLoggerFactory]

543 - if custom_stat_loggers is not None:

544 - factories = custom_stat_loggers

545 - else:

546 - factories = [PrometheusStatLogger]

547 - if logger.isEnabledFor(logging.INFO):

548 - factories.append(LoggingStatLogger)

549 -

550 - stat_loggers: list[list[StatLoggerBase]] = []

551 - for i in range(engine_num):

552 - per_engine_stat_loggers: list[StatLoggerBase] = []

553 - for logger_factory in factories:

554 - per_engine_stat_loggers.append(logger_factory(vllm_config, i))

555 - stat_loggers.append(per_engine_stat_loggers)

556 -

557 - return stat_loggers

619 +class StatLoggerManager:

620 + """

621 + StatLoggerManager:

622 + Logging happens at the level of the EngineCore (per scheduler).

623 + * DP: >1 EngineCore per AsyncLLM - loggers for each EngineCore.

624 + * With Local Logger, just make N copies for N EngineCores.

625 + * With Prometheus, we need a single logger with N "labels"

626 +

627 + This class abstracts away this implementation detail from

628 + the AsyncLLM, allowing the AsyncLLM to just call .record()

629 + and .log() to a simple interface.

630 + """

631 +

632 + def __init__(

633 + self,

634 + vllm_config: VllmConfig,

635 + engine_idxs: Optional[list[int]] = None,

636 + custom_stat_loggers: Optional[list[StatLoggerFactory]] = None,

637 + ):

638 + self.engine_idxs = engine_idxs if engine_idxs else [0]

639 +

640 + factories: list[StatLoggerFactory]

641 + if custom_stat_loggers is not None:

642 + factories = custom_stat_loggers

643 + else:

644 + factories = []

645 + if logger.isEnabledFor(logging.INFO):

646 + factories.append(LoggingStatLogger)

647 +

648 + # engine_idx: StatLogger

649 + self.per_engine_logger_dict: dict[int, list[StatLoggerBase]] = {}

650 + prometheus_factory = PrometheusStatLogger

651 + for engine_idx in self.engine_idxs:

652 + loggers: list[StatLoggerBase] = []

653 + for logger_factory in factories:

654 + # If we get a custom prometheus logger, use that

655 + # instead. This is typically used for the ray case.

656 + if (isinstance(logger_factory, type)

657 + and issubclass(logger_factory, PrometheusStatLogger)):

658 + prometheus_factory = logger_factory

659 + continue

660 + loggers.append(logger_factory(vllm_config,

661 + engine_idx)) # type: ignore

662 + self.per_engine_logger_dict[engine_idx] = loggers

663 +

664 + # For Prometheus, need to share the metrics between EngineCores.

665 + # Each EngineCore's metrics are expressed as a unique label.

666 + self.prometheus_logger = prometheus_factory(vllm_config, engine_idxs)

667 +

668 + def record(

669 + self,

670 + scheduler_stats: Optional[SchedulerStats],

671 + iteration_stats: Optional[IterationStats],

672 + engine_idx: Optional[int] = None,

673 + ):

674 + if engine_idx is None:

675 + engine_idx = 0

676 +

677 + per_engine_loggers = self.per_engine_logger_dict[engine_idx]

678 + for logger in per_engine_loggers:

679 + logger.record(scheduler_stats, iteration_stats, engine_idx)

680 +

681 + self.prometheus_logger.record(scheduler_stats, iteration_stats,

682 + engine_idx)

683 +

684 + def log(self):

685 + for per_engine_loggers in self.per_engine_logger_dict.values():

686 + for logger in per_engine_loggers:

687 + logger.log()

688 +

689 + def log_engine_initialized(self):

690 + self.prometheus_logger.log_engine_initialized()

691 +

692 + for per_engine_loggers in self.per_engine_logger_dict.values():

693 + for logger in per_engine_loggers:

694 + logger.log_engine_initialized()

vllm/v1/metrics/ray_wrappers.py

-4

@@ -3,7 +3,6 @@

3 import time

4 from typing import Optional, Union

6 -from vllm.config import VllmConfig

6 from vllm.v1.metrics.loggers import PrometheusStatLogger

7 from vllm.v1.spec_decode.metrics import SpecDecodingProm

@@ -128,9 +127,6 @@ class RayPrometheusStatLogger(PrometheusStatLogger):

127 _histogram_cls = RayHistogramWrapper

128 _spec_decoding_cls = RaySpecDecodingProm

129

131 - def __init__(self, vllm_config: VllmConfig, engine_index: int = 0):

132 - super().__init__(vllm_config, engine_index)

133 -

130 @staticmethod

131 def _unregister_vllm_metrics():

132 # No-op on purpose