52efc34ebf · tduncan/Nvidia-Optimization-Stack-VLLM

vllm/compilation/backends.py

+25 -10

@@ -245,10 +245,14 @@ class CompilerManager:

245 if graph_index == 0:

246 # adds some info logging for the first graph

247 if runtime_shape is None:

248 - logger.info("Cache the graph for dynamic shape for later use")

248 + logger.info_once(

249 + "Cache the graph for dynamic shape for later use", scope="local"

250 + )

251 else:

250 - logger.info(

251 - "Cache the graph of shape %s for later use", str(runtime_shape)

252 + logger.info_once(

253 + "Cache the graph of shape %s for later use",

254 + str(runtime_shape),

255 + scope="local",

256 )

257 if runtime_shape is None:

258 logger.debug(

@@ -272,12 +276,17 @@ class CompilerManager:

276 elapsed = now - compilation_start_time

277 compilation_config.compilation_time += elapsed

278 if runtime_shape is None:

275 - logger.info("Compiling a graph for dynamic shape takes %.2f s", elapsed)

279 + logger.info_once(

280 + "Compiling a graph for dynamic shape takes %.2f s",

281 + elapsed,

282 + scope="local",

283 + )

284 else:

277 - logger.info(

285 + logger.info_once(

286 "Compiling a graph for shape %s takes %.2f s",

287 runtime_shape,

288 elapsed,

289 + scope="local",

290 )

291

292 return compiled_graph

@@ -604,10 +613,12 @@ class VllmBackend:

613 disable_cache = envs.VLLM_DISABLE_COMPILE_CACHE

614

615 if disable_cache:

607 - logger.info("vLLM's torch.compile cache is disabled.")

616 + logger.info_once("vLLM's torch.compile cache is disabled.", scope="local")

617 else:

609 - logger.info(

610 - "Using cache directory: %s for vLLM's torch.compile", local_cache_dir

618 + logger.info_once(

619 + "Using cache directory: %s for vLLM's torch.compile",

620 + local_cache_dir,

621 + scope="local",

622 )

623

624 self.compiler_manager.initialize_cache(

@@ -620,7 +631,9 @@ class VllmBackend:

631 from .monitor import torch_compile_start_time

632

633 dynamo_time = time.time() - torch_compile_start_time

623 - logger.info("Dynamo bytecode transform time: %.2f s", dynamo_time)

634 + logger.info_once(

635 + "Dynamo bytecode transform time: %.2f s", dynamo_time, scope="local"

636 + )

637 self.compilation_config.compilation_time += dynamo_time

638

639 # we control the compilation process, each instance can only be

@@ -672,7 +685,9 @@ class VllmBackend:

685 with open(graph_path, "w") as f:

686 f.write(src)

687

675 - logger.debug("Computation graph saved to %s", graph_path)

688 + logger.debug_once(

689 + "Computation graph saved to %s", graph_path, scope="local"

690 + )

691

692 self._called = True

693

vllm/compilation/monitor.py

+4 -2

@@ -31,8 +31,10 @@ def start_monitoring_torch_compile(vllm_config: VllmConfig):

31 def end_monitoring_torch_compile(vllm_config: VllmConfig):

32 compilation_config: CompilationConfig = vllm_config.compilation_config

33 if compilation_config.mode == CompilationMode.VLLM_COMPILE:

34 - logger.info(

35 - "torch.compile takes %.2f s in total", compilation_config.compilation_time

34 + logger.info_once(

35 + "torch.compile takes %.2f s in total",

36 + compilation_config.compilation_time,

37 + scope="local",

38 )

39 global context_manager

40 if context_manager is not None:

vllm/distributed/device_communicators/cuda_communicator.py

+5 -6

@@ -13,7 +13,6 @@ from vllm.distributed.device_communicators.pynccl import register_nccl_symmetric

13 from vllm.distributed.device_communicators.pynccl_allocator import (

14 is_symmetric_memory_enabled,

15 )

16 -from vllm.distributed.parallel_state import is_global_first_rank

16 from vllm.logger import init_logger

17 from vllm.platforms import current_platform

18

@@ -118,11 +117,11 @@ class CudaCommunicator(DeviceCommunicatorBase):

117 else:

118 raise ValueError(f"Unknown all2all backend: {self.all2all_backend}")

119

121 - if is_global_first_rank():

122 - logger.info(

123 - "Using %s all2all manager.",

124 - self.all2all_manager.__class__.__name__,

125 - )

120 + logger.info_once(

121 + "Using %s all2all manager.",

122 + self.all2all_manager.__class__.__name__,

123 + scope="global",

124 + )

125

126 def all_reduce(self, input_):

127 # since currently we perform copy input -> symm_input -> out-of-place AR

vllm/distributed/device_communicators/custom_all_reduce.py

+1 -1

@@ -34,7 +34,7 @@ def _can_p2p(rank: int, world_size: int) -> bool:

34 if i == rank:

35 continue

36 if envs.VLLM_SKIP_P2P_CHECK:

37 - logger.info("Skipping P2P check and trusting the driver's P2P report.")

37 + logger.debug("Skipping P2P check and trusting the driver's P2P report.")

38 return torch.cuda.can_device_access_peer(rank, i)

39 if not gpu_p2p_access_check(rank, i):

40 return False

vllm/distributed/device_communicators/pynccl.py

+3 -1

@@ -108,7 +108,9 @@ class PyNcclCommunicator:

108 if self.rank == 0:

109 # get the unique id from NCCL

110 self.unique_id = self.nccl.ncclGetUniqueId()

111 - logger.info("vLLM is using nccl==%s", self.nccl.ncclGetVersion())

111 + logger.info_once(

112 + "vLLM is using nccl==%s", self.nccl.ncclGetVersion(), scope="local"

113 + )

114 else:

115 # construct an empty unique id

116 self.unique_id = ncclUniqueId()

vllm/distributed/device_communicators/shm_broadcast.py

+1 -1

@@ -312,7 +312,7 @@ class MessageQueue:

312 remote_addr_ipv6=remote_addr_ipv6,

313 )

314

315 - logger.info("vLLM message queue communication handle: %s", self.handle)

315 + logger.debug("vLLM message queue communication handle: %s", self.handle)

316

317 def export_handle(self) -> Handle:

318 return self.handle

vllm/distributed/parallel_state.py

+25 -2

@@ -1157,7 +1157,7 @@ def init_distributed_environment(

1157 ip = parallel_config.data_parallel_master_ip

1158 port = parallel_config.get_next_dp_init_port()

1159 distributed_init_method = get_distributed_init_method(ip, port)

1160 - logger.info(

1160 + logger.debug(

1161 "Adjusting world_size=%d rank=%d distributed_init_method=%s for DP",

1162 world_size,

1163 rank,

@@ -1322,7 +1322,7 @@ def initialize_model_parallel(

1322 group_ranks, get_world_group().local_rank, backend, group_name="ep"

1323 )

1324

1325 - logger.info(

1325 + logger.info_once(

1326 "rank %s in world size %s is assigned as "

1327 "DP rank %s, PP rank %s, TP rank %s, EP rank %s",

1328 rank,

@@ -1625,6 +1625,29 @@ def is_global_first_rank() -> bool:

1625 return True

1626

1627

1628 +def is_local_first_rank() -> bool:

1629 + """

1630 + Check if the current process is the first local rank (rank 0 on its node).

1631 + """

1632 + try:

1633 + # prefer the initialized world group if available

1634 + global _WORLD

1635 + if _WORLD is not None:

1636 + return _WORLD.local_rank == 0

1637 +

1638 + if not torch.distributed.is_initialized():

1639 + return True

1640 +

1641 + # fallback to environment-provided local rank if available

1642 + # note: envs.LOCAL_RANK is set when using env:// launchers (e.g., torchrun)

1643 + try:

1644 + return int(envs.LOCAL_RANK) == 0 # type: ignore[arg-type]

1645 + except Exception:

1646 + return torch.distributed.get_rank() == 0

1647 + except Exception:

1648 + return True

1649 +

1650 +

1651 def _node_count(pg: ProcessGroup | StatelessProcessGroup) -> int:

1652 """

1653 Returns the total number of nodes in the process group.

vllm/logger.py

+40 -13

@@ -13,7 +13,7 @@ from logging import Logger

13 from logging.config import dictConfig

14 from os import path

15 from types import MethodType

16 -from typing import Any, cast

16 +from typing import Any, Literal, cast

17

18 import vllm.envs as envs

19

@@ -59,20 +59,37 @@ DEFAULT_LOGGING_CONFIG = {

59

60 @lru_cache

61 def _print_debug_once(logger: Logger, msg: str, *args: Hashable) -> None:

62 - # Set the stacklevel to 2 to print the original caller's line info

63 - logger.debug(msg, *args, stacklevel=2)

62 + # Set the stacklevel to 3 to print the original caller's line info

63 + logger.debug(msg, *args, stacklevel=3)

64

65

66 @lru_cache

67 def _print_info_once(logger: Logger, msg: str, *args: Hashable) -> None:

68 - # Set the stacklevel to 2 to print the original caller's line info

69 - logger.info(msg, *args, stacklevel=2)

68 + # Set the stacklevel to 3 to print the original caller's line info

69 + logger.info(msg, *args, stacklevel=3)

70

71

72 @lru_cache

73 def _print_warning_once(logger: Logger, msg: str, *args: Hashable) -> None:

74 - # Set the stacklevel to 2 to print the original caller's line info

75 - logger.warning(msg, *args, stacklevel=2)

74 + # Set the stacklevel to 3 to print the original caller's line info

75 + logger.warning(msg, *args, stacklevel=3)

76 +

77 +

78 +LogScope = Literal["process", "global", "local"]

79 +

80 +

81 +def _should_log_with_scope(scope: LogScope) -> bool:

82 + """Decide whether to log based on scope"""

83 + if scope == "global":

84 + from vllm.distributed.parallel_state import is_global_first_rank

85 +

86 + return is_global_first_rank()

87 + if scope == "local":

88 + from vllm.distributed.parallel_state import is_local_first_rank

89 +

90 + return is_local_first_rank()

91 + # default "process" scope: always log

92 + return True

93

94

95 class _VllmLogger(Logger):

@@ -84,33 +101,43 @@ class _VllmLogger(Logger):

101 `intel_extension_for_pytorch.utils._logger`.

102 """

103

87 - def debug_once(self, msg: str, *args: Hashable) -> None:

104 + def debug_once(

105 + self, msg: str, *args: Hashable, scope: LogScope = "process"

106 + ) -> None:

107 """

108 As [`debug`][logging.Logger.debug], but subsequent calls with

109 the same message are silently dropped.

110 """

111 + if not _should_log_with_scope(scope):

112 + return

113 _print_debug_once(self, msg, *args)

114

94 - def info_once(self, msg: str, *args: Hashable) -> None:

115 + def info_once(self, msg: str, *args: Hashable, scope: LogScope = "process") -> None:

116 """

117 As [`info`][logging.Logger.info], but subsequent calls with

118 the same message are silently dropped.

119 """

120 + if not _should_log_with_scope(scope):

121 + return

122 _print_info_once(self, msg, *args)

123

101 - def warning_once(self, msg: str, *args: Hashable) -> None:

124 + def warning_once(

125 + self, msg: str, *args: Hashable, scope: LogScope = "process"

126 + ) -> None:

127 """

128 As [`warning`][logging.Logger.warning], but subsequent calls with

129 the same message are silently dropped.

130 """

131 + if not _should_log_with_scope(scope):

132 + return

133 _print_warning_once(self, msg, *args)

134

135

136 # Pre-defined methods mapping to avoid repeated dictionary creation

137 _METHODS_TO_PATCH = {

111 - "debug_once": _print_debug_once,

112 - "info_once": _print_info_once,

113 - "warning_once": _print_warning_once,

138 + "debug_once": _VllmLogger.debug_once,

139 + "info_once": _VllmLogger.info_once,

140 + "warning_once": _VllmLogger.warning_once,

141 }

142

143

vllm/model_executor/layers/fused_moe/layer.py

+4 -2

@@ -368,11 +368,13 @@ class UnquantizedFusedMoEMethod(FusedMoEMethodBase, CustomOp):

368 logger.info_once(

369 "FlashInfer CUTLASS MoE is available for EP"

370 " but not enabled, consider setting"

371 - " VLLM_USE_FLASHINFER_MOE_FP16=1 to enable it."

371 + " VLLM_USE_FLASHINFER_MOE_FP16=1 to enable it.",

372 + scope="local",

373 )

374 elif self.moe.moe_parallel_config.dp_size > 1:

375 logger.info_once(

375 - "FlashInfer CUTLASS MoE is currently not available for DP."

376 + "FlashInfer CUTLASS MoE is currently not available for DP.",

377 + scope="local",

378 )

379 self.flashinfer_cutlass_moe = None # type: ignore

380

vllm/model_executor/model_loader/default_loader.py

+2 -1

@@ -311,9 +311,10 @@ class DefaultModelLoader(BaseModelLoader):

311 loaded_weights = load_weights_and_online_quantize(self, model, model_config)

312

313 self.counter_after_loading_weights = time.perf_counter()

314 - logger.info(

314 + logger.info_once(

315 "Loading weights took %.2f seconds",

316 self.counter_after_loading_weights - self.counter_before_loading_weights,

317 + scope="local",

318 )

319 # We only enable strict check for non-quantized models

320 # that have loaded weights tracking currently.

vllm/model_executor/model_loader/weight_utils.py

+1 -1

@@ -416,7 +416,7 @@ def download_weights_from_hf(

416 e,

417 )

418

419 - logger.info("Using model weights format %s", allow_patterns)

419 + logger.debug("Using model weights format %s", allow_patterns)

420 # Use file lock to prevent multiple processes from

421 # downloading the same model weights at the same time.

422 with get_lock(model_name_or_path, cache_dir):

vllm/platforms/__init__.py

+4 -2

@@ -222,10 +222,12 @@ def resolve_current_platform_cls_qualname() -> str:

222 )

223 elif len(activated_builtin_plugins) == 1:

224 platform_cls_qualname = builtin_platform_plugins[activated_builtin_plugins[0]]()

225 - logger.info("Automatically detected platform %s.", activated_builtin_plugins[0])

225 + logger.debug(

226 + "Automatically detected platform %s.", activated_builtin_plugins[0]

227 + )

228 else:

229 platform_cls_qualname = "vllm.platforms.interface.UnspecifiedPlatform"

228 - logger.info("No platform detected, vLLM is running on UnspecifiedPlatform")

230 + logger.debug("No platform detected, vLLM is running on UnspecifiedPlatform")

231 return platform_cls_qualname

232

233

vllm/platforms/cuda.py

+3 -1

@@ -298,7 +298,9 @@ class CudaPlatformBase(Platform):

298 )

299

300 if use_cutlassmla:

301 - logger.info_once("Using Cutlass MLA backend on V1 engine.")

301 + logger.info_once(

302 + "Using Cutlass MLA backend on V1 engine.", scope="local"

303 + )

304 return "vllm.v1.attention.backends.mla.cutlass_mla.CutlassMLABackend"

305 if use_flashinfermla:

306 from vllm.v1.attention.backends.utils import set_kv_cache_layout

vllm/utils/gc_utils.py

+1 -1

@@ -37,7 +37,7 @@ class GCDebugConfig:

37 except Exception:

38 self.enabled = False

39 logger.error("Failed to parse VLLM_GC_DEBUG(%s)", envs.VLLM_GC_DEBUG)

40 - logger.info("GC Debug Config. %s", str(self))

40 + logger.debug("GC Debug Config. %s", str(self))

41

42 def __repr__(self) -> str:

43 return f"enabled:{self.enabled},top_objects:{self.top_objects}"

vllm/v1/core/kv_cache_utils.py

+1 -1

@@ -1226,7 +1226,7 @@ def _report_kv_cache_config(

1226 vllm_config.parallel_config.decode_context_parallel_size,

1227 )

1228 num_tokens_str = f"{num_tokens:,}"

1229 - logger.info("GPU KV cache size: %s tokens", num_tokens_str)

1229 + logger.info_once("GPU KV cache size: %s tokens", num_tokens_str, scope="local")

1230 max_model_len_str = f"{vllm_config.model_config.max_model_len:,}"

1231 max_concurrency = get_max_concurrency_for_kv_cache_config(

1232 vllm_config, kv_cache_config

vllm/v1/engine/core.py

+4 -4

@@ -19,7 +19,6 @@ import zmq

19

20 from vllm.config import ParallelConfig, VllmConfig

21 from vllm.distributed import stateless_destroy_torch_distributed_process_group

22 -from vllm.distributed.parallel_state import is_global_first_rank

22 from vllm.envs import enable_envs_cache

23 from vllm.logger import init_logger

24 from vllm.logging_utils.dump_input import dump_engine_exception

@@ -90,7 +89,7 @@ class EngineCore:

89 load_general_plugins()

90

91 self.vllm_config = vllm_config

93 - if is_global_first_rank():

92 + if vllm_config.parallel_config.data_parallel_rank == 0:

93 logger.info(

94 "Initializing a V1 LLM engine (v%s) with config: %s",

95 VLLM_VERSION,

@@ -235,9 +234,10 @@ class EngineCore:

234 self.model_executor.initialize_from_config(kv_cache_configs)

235

236 elapsed = time.time() - start

238 - logger.info(

237 + logger.info_once(

238 ("init engine (profile, create kv cache, warmup model) took %.2f seconds"),

239 elapsed,

240 + scope="local",

241 )

242 return num_gpu_blocks, num_cpu_blocks, scheduler_kv_cache_config

243

@@ -713,7 +713,7 @@ class EngineCoreProc(EngineCore):

713 )

714

715 # Receive initialization message.

716 - logger.info("Waiting for init message from front-end.")

716 + logger.debug("Waiting for init message from front-end.")

717 if not handshake_socket.poll(timeout=HANDSHAKE_TIMEOUT_MINS * 60_000):

718 raise RuntimeError(

719 "Did not receive response from front-end "

vllm/v1/metrics/loggers.py

+1 -1

@@ -215,7 +215,7 @@ class LoggingStatLogger(StatLoggerBase):

215

216 def log_engine_initialized(self):

217 if self.vllm_config.cache_config.num_gpu_blocks:

218 - logger.info(

218 + logger.debug(

219 "Engine %03d: vllm cache_config_info with initialization "

220 "after num_gpu_blocks is: %d",

221 self.engine_index,

vllm/v1/sample/ops/topk_topp_sampler.py

+4 -1

@@ -33,7 +33,10 @@ class TopKTopPSampler(nn.Module):

33 ):

34 if envs.VLLM_USE_FLASHINFER_SAMPLER:

35 # Users must opt in explicitly via VLLM_USE_FLASHINFER_SAMPLER=1.

36 - logger.info_once("Using FlashInfer for top-p & top-k sampling.")

36 + logger.info_once(

37 + "Using FlashInfer for top-p & top-k sampling.",

38 + scope="global",

39 + )

40 self.forward = self.forward_cuda

41 else:

42 logger.debug_once(

vllm/v1/worker/dp_utils.py

+7 -7

@@ -6,7 +6,7 @@ import torch

6 import torch.distributed as dist

7

8 from vllm.config import ParallelConfig

9 -from vllm.distributed.parallel_state import get_dp_group, is_global_first_rank

9 +from vllm.distributed.parallel_state import get_dp_group

10 from vllm.logger import init_logger

11 from vllm.v1.worker.ubatch_utils import (

12 UBatchSlices,

@@ -132,12 +132,12 @@ def _synchronize_dp_ranks(

132 should_ubatch = _post_process_ubatch(tensor)

133

134 if should_ubatch and not should_dp_pad:

135 - if is_global_first_rank():

136 - logger.debug(

137 - "Microbatching has been triggered and requires DP padding. "

138 - "Enabling DP padding even though it has been explicitly "

139 - "disabled."

140 - )

135 + logger.debug_once(

136 + "Microbatching has been triggered and requires DP padding. "

137 + "Enabling DP padding even though it has been explicitly "

138 + "disabled.",

139 + scope="global",

140 + )

141 should_dp_pad = True

142

143 # Pad all DP ranks up to the maximum token count across ranks if

vllm/v1/worker/gpu_model_runner.py

+9 -3

@@ -2850,7 +2850,11 @@ class GPUModelRunner(LoRAModelRunnerMixin, KVConnectorModelRunnerMixin):

2850 Args:

2851 eep_scale_up: the model loading is for elastic EP scale up.

2852 """

2853 - logger.info("Starting to load model %s...", self.model_config.model)

2853 + logger.info_once(

2854 + "Starting to load model %s...",

2855 + self.model_config.model,

2856 + scope="global",

2857 + )

2858 if eep_scale_up:

2859 from vllm.distributed.parallel_state import get_ep_group

2860

@@ -2911,10 +2915,11 @@ class GPUModelRunner(LoRAModelRunnerMixin, KVConnectorModelRunnerMixin):

2915 self.model.set_aux_hidden_state_layers(aux_layers)

2916 time_after_load = time.perf_counter()

2917 self.model_memory_usage = m.consumed_memory

2914 - logger.info(

2918 + logger.info_once(

2919 "Model loading took %.4f GiB and %.6f seconds",

2920 self.model_memory_usage / GiB_bytes,

2921 time_after_load - time_before_load,

2922 + scope="local",

2923 )

2924 prepare_communication_buffer_for_model(self.model)

2925

@@ -3838,10 +3843,11 @@ class GPUModelRunner(LoRAModelRunnerMixin, KVConnectorModelRunnerMixin):

3843 elapsed_time = end_time - start_time

3844 cuda_graph_size = start_free_gpu_memory - end_free_gpu_memory

3845 # This usually takes 5~20 seconds.

3841 - logger.info(

3846 + logger.info_once(

3847 "Graph capturing finished in %.0f secs, took %.2f GiB",

3848 elapsed_time,

3849 cuda_graph_size / (1 << 30),

3850 + scope="local",

3851 )

3852 return cuda_graph_size

3853

vllm/v1/worker/gpu_worker.py

+6 -2

@@ -20,7 +20,10 @@ from vllm.distributed import (

20 set_custom_all_reduce,

21 )

22 from vllm.distributed.kv_transfer import ensure_kv_transfer_initialized

23 -from vllm.distributed.parallel_state import get_pp_group, get_tp_group

23 +from vllm.distributed.parallel_state import (

24 + get_pp_group,

25 + get_tp_group,

26 +)

27 from vllm.logger import init_logger

28 from vllm.lora.request import LoRARequest

29 from vllm.model_executor import set_random_seed

@@ -334,9 +337,10 @@ class Worker(WorkerBase):

337 GiB(free_gpu_memory - unrequested_memory),

338 )

339 logger.debug(profile_result)

337 - logger.info(

340 + logger.info_once(

341 "Available KV cache memory: %.2f GiB",

342 GiB(self.available_kv_cache_memory_bytes),

343 + scope="local",

344 )

345 gc.collect()

346

[Log] Optimize Startup Log (#26740)