@tduncan / Nvidia-Optimization-Stack-VLLM Mirror · read-only / commits / 41a4829f22

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 1, 22:30 UTC

[Logs Refactor] Optimize shutdown logs, easier to follow and consistent (#43707)

Signed-off-by: yewentao256 <zhyanwentao@126.com>

Wentao Ye committed Jun 4, 2026 at 14:36 UTC 41a4829f2202f726711349994526afd4b24be868

7 files changed +139 -23

vllm/distributed/parallel_state.py

@@ -2055,6 +2055,10 @@ def destroy_distributed_environment():

2055

2056

2057 def cleanup_dist_env_and_memory(shutdown_ray: bool = False):

2058 + logger.debug(

2059 + "[shutdown] Distributed: cleanup start shutdown_ray=%s",

2060 + shutdown_ray,

2061 + )

2062 # Reset environment variable cache

2063 envs.disable_envs_cache()

2064

@@ -2089,6 +2093,8 @@ def cleanup_dist_env_and_memory(shutdown_ray: bool = False):

2093 "torch._C._host_emptyCache() only available in Pytorch >=2.5"

2094 )

2095

2096 + logger.debug_once("[shutdown] Distributed: cleanup complete")

2097 +

2098

2099 def in_the_same_node_as(

2100 pg: ProcessGroup | StatelessProcessGroup, source_rank: int = 0

vllm/entrypoints/launcher.py

+13 -1

@@ -95,6 +95,9 @@ async def serve_http(

95 shutdown_event = asyncio.Event()

97 def signal_handler() -> None:

98 + if shutdown_event.is_set():

99 + return

100 + logger.info_once("[shutdown] API server: shutdown triggered")

101 shutdown_event.set()

102

103 async def dummy_shutdown() -> None:

@@ -108,12 +111,21 @@ async def serve_http(

111

112 engine_client = app.state.engine_client

113 timeout = engine_client.vllm_config.shutdown_timeout

114 + mode = "abort" if timeout == 0 else "drain"

115 +

116 + logger.info(

117 + "[shutdown] API server: stopping engine client mode=%s timeout=%ss",

118 + mode,

119 + timeout,

120 + )

121

122 await loop.run_in_executor(

123 None, partial(engine_client.shutdown, timeout=timeout)

124 )

125 + logger.info_once("[shutdown] API server: engine client stopped")

126

127 server.should_exit = True

128 + logger.info_once("[shutdown] API server: signalling HTTP server shutdown")

129 server_task.cancel()

130 watchdog_task.cancel()

131 if ssl_cert_refresher:

@@ -134,7 +146,7 @@ async def serve_http(

146 process,

147 " ".join(process.cmdline()),

148 )

137 - logger.info("Shutting down FastAPI HTTP server.")

149 + logger.info_once("[shutdown] API server: shutting down FastAPI HTTP server")

150 return server.shutdown()

151 finally:

152 shutdown_task.cancel()

vllm/v1/core/sched/scheduler.py

@@ -2056,13 +2056,17 @@ class Scheduler(SchedulerInterface):

2056 return spec_decoding_stats

2057

2058 def shutdown(self) -> None:

2059 + logger.debug_once("[shutdown] Scheduler: start")

2060 if self.kv_event_publisher:

2061 self.kv_event_publisher.shutdown()

2062 if self.connector is not None:

2063 self.connector.shutdown()

2064 +

2065 if self.ec_connector is not None:

2066 self.ec_connector.shutdown()

2067

2068 + logger.debug_once("[shutdown] Scheduler: complete")

2069 +

2070 ########################################################################

2071 # KV Connector Related Methods

2072 ########################################################################

vllm/v1/engine/core.py

+32 -7

@@ -608,6 +608,7 @@ class EngineCore:

608 self.abort_requests(request_ids)

609

610 def shutdown(self):

611 + logger.debug_once("[shutdown] EngineCore: tearing down local resources")

612 self.structured_output_manager.clear_backend()

613 if self.model_executor:

614 self.model_executor.shutdown()

@@ -622,6 +623,7 @@ class EngineCore:

623 # Tear down distributed state initialized in this EngineCore process

624 # before it exits and release cached memory.

625 cleanup_dist_env_and_memory()

626 + logger.debug_once("[shutdown] EngineCore: local resource teardown complete")

627

628 def profile(self, is_start: bool = True, profile_prefix: str | None = None):

629 self.model_executor.profile(is_start, profile_prefix)

@@ -1172,6 +1174,11 @@ class EngineCoreProc(EngineCore):

1174 signal_callback = SignalCallback(wakeup_engine)

1175

1176 def signal_handler(signum, frame):

1177 + signal_name = signal.Signals(signum).name

1178 + logger.info(

1179 + "[shutdown] EngineCore: trigger received signal=%s",

1180 + signal_name,

1181 + )

1182 engine_core.shutdown_state = EngineShutdownState.REQUESTED

1183 signal_callback.trigger()

1184

@@ -1181,7 +1188,7 @@ class EngineCoreProc(EngineCore):

1188 engine_core.run_busy_loop()

1189

1190 except SystemExit:

1184 - logger.debug("EngineCore exiting.")

1191 + logger.info_once("[shutdown] EngineCore: exiting busy loop")

1192 raise

1193 except Exception as e:

1194 if engine_core is None:

@@ -1285,13 +1292,21 @@ class EngineCoreProc(EngineCore):

1292

1293 if self.shutdown_state == EngineShutdownState.REQUESTED:

1294 shutdown_timeout = self.vllm_config.shutdown_timeout

1295 + mode = "abort" if shutdown_timeout == 0 else "drain"

1296

1289 - logger.info("Shutdown initiated (timeout=%d)", shutdown_timeout)

1297 + logger.info(

1298 + "[shutdown] EngineCore: start mode=%s timeout=%ds",

1299 + mode,

1300 + shutdown_timeout,

1301 + )

1302

1303 if shutdown_timeout == 0:

1304 num_requests = self.scheduler.get_num_unfinished_requests()

1305 if num_requests > 0:

1294 - logger.info("Aborting %d requests", num_requests)

1306 + logger.info(

1307 + "[shutdown] EngineCore: aborting in-flight requests count=%d",

1308 + num_requests,

1309 + )

1310 aborted_reqs = self.scheduler.finish_requests(

1311 None, RequestStatus.FINISHED_ABORTED

1312 )

@@ -1300,7 +1315,8 @@ class EngineCoreProc(EngineCore):

1315 num_requests = self.scheduler.get_num_unfinished_requests()

1316 if num_requests > 0:

1317 logger.info(

1303 - "Draining %d in-flight requests (timeout=%ds)",

1318 + "[shutdown] EngineCore: draining in-flight requests "

1319 + "count=%d timeout=%ds",

1320 num_requests,

1321 shutdown_timeout,

1322 )

@@ -1309,7 +1325,10 @@ class EngineCoreProc(EngineCore):

1325

1326 # Exit when no work remaining

1327 if not self.has_work():

1312 - logger.info("Shutdown complete")

1328 + logger.info(

1329 + "[shutdown] EngineCore: request processing complete; "

1330 + "starting resource teardown"

1331 + )

1332 return False

1333

1334 return True

@@ -1353,7 +1372,10 @@ class EngineCoreProc(EngineCore):

1372 if self.shutdown_state == EngineShutdownState.RUNNING:

1373 return False

1374

1356 - logger.info("Rejecting request %s (server shutting down)", request.request_id)

1375 + logger.debug(

1376 + "[shutdown] EngineCore: rejecting new request request_id=%s",

1377 + request.request_id,

1378 + )

1379 self._send_abort_outputs_to_client([request.request_id], request.client_index)

1380 return True

1381

@@ -1363,7 +1385,10 @@ class EngineCoreProc(EngineCore):

1385 if self.shutdown_state == EngineShutdownState.RUNNING:

1386 return False

1387

1366 - logger.warning("Rejecting utility call %s (server shutting down)", method_name)

1388 + logger.warning(

1389 + "[shutdown] EngineCore: rejecting utility call method=%s",

1390 + method_name,

1391 + )

1392 output = UtilityOutput(call_id, failure_message="Server shutting down")

1393 self.output_queue.put_nowait(

1394 (client_idx, EngineCoreOutputs(utility_output=output))

vllm/v1/engine/core_client.py

+12

@@ -391,6 +391,7 @@ class BackgroundResources:

391 def __call__(self):

392 """Clean up background resources."""

393

394 + logger.debug_once("[shutdown] MPClient: background resource cleanup start")

395 self.engine_dead = True

396 if self.engine_manager is not None:

397 self.engine_manager.shutdown()

@@ -445,6 +446,8 @@ class BackgroundResources:

446 # Send shutdown signal.

447 shutdown_sender.send(b"")

448

449 + logger.debug_once("[shutdown] MPClient: background resource cleanup complete")

450 +

451 def validate_alive(self, frames: Sequence[zmq.Frame]):

452 if len(frames) == 1 and (frames[0].buffer == EngineCoreProc.ENGINE_CORE_DEAD):

453 self.engine_dead = True

@@ -645,9 +648,15 @@ class MPClient(EngineCoreClient):

648 def shutdown(self, timeout: float | None = None) -> None:

649 """Shutdown engine manager under timeout and clean up resources."""

650 if self._finalizer.detach() is not None:

651 + timeout_str = "default" if timeout is None else f"{timeout}s"

652 + logger.info("[shutdown] MPClient: start timeout=%s", timeout_str)

653 if self.resources.engine_manager is not None:

654 + logger.info_once("[shutdown] MPClient: stopping engine manager")

655 self.resources.engine_manager.shutdown(timeout=timeout)

656 + logger.info_once("[shutdown] MPClient: engine manager stopped")

657 + logger.info_once("[shutdown] MPClient: cleaning up background resources")

658 self.resources()

659 + logger.info_once("[shutdown] MPClient: complete")

660

661 def _format_exception(self, e: Exception) -> Exception:

662 """If errored, use EngineDeadError so root cause is clear."""

@@ -687,6 +696,9 @@ class MPClient(EngineCoreClient):

696 if not _self or not _self._finalizer.alive or _self.resources.engine_dead:

697 return

698 _self.resources.engine_dead = True

699 + logger.warning_once(

700 + "[shutdown] MPClient: engine core exited unexpectedly; starting cleanup"

701 + )

702 _self.shutdown()

703 # Note: For MPClient, we don't have a failure callback mechanism

704 # like MultiprocExecutor, but we set engine_dead flag which will

vllm/v1/executor/multiproc_executor.py

+36 -9

@@ -422,27 +422,45 @@ class MultiprocExecutor(Executor):

422 return False

423

424 active_procs = lambda: [proc for proc in worker_procs if proc.is_alive()]

425 + initial_count = len(active_procs())

426 +

427 # Give processes time to clean themselves up properly first

426 - logger.debug("Worker Termination: allow workers to gracefully shutdown")

428 + logger.info(

429 + "[shutdown] Executor: waiting for worker exit count=%d",

430 + initial_count,

431 + )

432 if wait_for_termination(active_procs(), 4):

433 + logger.info_once("[shutdown] Executor: all workers exited gracefully")

434 return

435

436 # Send SIGTERM if still running

431 - logger.debug("Worker Termination: workers still running sending SIGTERM")

432 - for p in active_procs():

437 + remaining = active_procs()

438 + logger.warning(

439 + "[shutdown] Executor: workers still running after grace period; "

440 + "sending SIGTERM count=%d",

441 + len(remaining),

442 + )

443 + for p in remaining:

444 p.terminate()

445 if not wait_for_termination(active_procs(), 4):

446 # Send SIGKILL if still running

436 - logger.debug(

437 - "Worker Termination: resorting to SIGKILL to take down workers"

447 + remaining = active_procs()

448 + logger.warning(

449 + "[shutdown] Executor: workers still running after SIGTERM; "

450 + "sending SIGKILL count=%d",

451 + len(remaining),

452 )

439 - for p in active_procs():

453 + for p in remaining:

454 p.kill()

455

456 def shutdown(self):

457 """Properly shut down the executor and its workers"""

458 if not getattr(self, "shutting_down", False):

445 - logger.debug("Triggering shutdown of workers")

459 + worker_count = len(getattr(self, "workers", None) or [])

460 + logger.debug(

461 + "[shutdown] Executor: start worker_count=%d",

462 + worker_count,

463 + )

464 self.shutting_down = True

465

466 # Make sure all the worker processes are terminated first.

@@ -468,6 +486,8 @@ class MultiprocExecutor(Executor):

486 mq.shutdown()

487 self.response_mqs = []

488

489 + logger.debug_once("[shutdown] Executor: complete")

490 +

491 def check_health(self) -> None:

492 self.collective_rpc("check_health", timeout=10)

493 return

@@ -867,7 +887,9 @@ class WorkerProc:

887 if ready_writer is not None:

888 logger.exception("WorkerProc failed to start.")

889 elif shutdown_requested.is_set():

870 - logger.info("WorkerProc shutting down.")

890 + logger.debug_once(

891 + "[shutdown] WorkerProc: exiting after shutdown request"

892 + )

893 else:

894 logger.exception("WorkerProc failed.")

895

@@ -879,7 +901,12 @@ class WorkerProc:

901 except SystemExit as e:

902 # SystemExit is raised on SIGTERM or SIGKILL, which usually indicates that

903 # the graceful shutdown process did not succeed

882 - logger.warning("WorkerProc was terminated")

904 + if shutdown_requested.is_set():

905 + logger.debug_once(

906 + "[shutdown] WorkerProc: terminated by shutdown signal"

907 + )

908 + else:

909 + logger.warning("WorkerProc was terminated")

910 # SystemExit must never be ignored

911 raise e

912

vllm/v1/utils.py

+36 -6

@@ -444,6 +444,12 @@ def _shutdown_subprocesses(

444 timeout = 0.0

445 timeout = max(timeout, 5.0)

446

447 + logger.debug(

448 + "[shutdown] Subprocess manager: start process_count=%d timeout=%ss",

449 + len(procs),

450 + timeout,

451 + )

452 +

453 for proc in procs:

454 if proc.is_alive():

455 proc.terminate()

@@ -456,9 +462,18 @@ def _shutdown_subprocesses(

462 if proc.is_alive():

463 proc.join(remaining)

464

459 - for proc in procs:

460 - if proc.is_alive() and (pid := proc.pid) is not None:

461 - kill_process_tree(pid)

465 + remaining_pids = [

466 + proc.pid for proc in procs if proc.is_alive() and proc.pid is not None

467 + ]

468 + if remaining_pids:

469 + logger.warning(

470 + "[shutdown] Subprocess manager: force killing remaining processes count=%d",

471 + len(remaining_pids),

472 + )

473 + for pid in remaining_pids:

474 + kill_process_tree(pid)

475 +

476 + logger.debug_once("[shutdown] Subprocess manager: complete")

477

478

479 def run_api_server_worker_proc(

@@ -565,6 +580,12 @@ def shutdown(procs: list[BaseProcess], timeout: float | None = None) -> None:

580 # have a user-configured shutdown timeout.

581 timeout = 5.0

582

583 + logger.debug(

584 + "[shutdown] Process manager: start process_count=%d timeout=%ss",

585 + len(procs),

586 + timeout,

587 + )

588 +

589 # Shutdown the process.

590 for proc in procs:

591 if proc.is_alive():

@@ -579,9 +600,18 @@ def shutdown(procs: list[BaseProcess], timeout: float | None = None) -> None:

600 if proc.is_alive():

601 proc.join(remaining)

602

582 - for proc in procs:

583 - if proc.is_alive() and (pid := proc.pid) is not None:

584 - kill_process_tree(pid)

603 + remaining_pids = [

604 + proc.pid for proc in procs if proc.is_alive() and proc.pid is not None

605 + ]

606 + if remaining_pids:

607 + logger.warning(

608 + "[shutdown] Process manager: force killing remaining processes count=%d",

609 + len(remaining_pids),

610 + )

611 + for pid in remaining_pids:

612 + kill_process_tree(pid)

613 +

614 + logger.debug_once("[shutdown] Process manager: complete")

615

616

617 def copy_slice(