[Bug]: Async engine hangs with 0.4.* releases

[glos-nv]

Your current environment

Collecting environment information...
PyTorch version: 2.3.0+cu121
Is debug build: False
CUDA used to build PyTorch: 12.1
ROCM used to build PyTorch: N/A

OS: Ubuntu 22.04.3 LTS (x86_64)
GCC version: (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0
Clang version: Could not collect
CMake version: version 3.29.3
Libc version: glibc-2.35

Python version: 3.10.12 (main, Nov 20 2023, 15:14:05) [GCC 11.4.0] (64-bit runtime)
Python platform: Linux-6.5.0-1020-oem-x86_64-with-glibc2.35
Is CUDA available: True
CUDA runtime version: 12.1.105
CUDA_MODULE_LOADING set to: LAZY
GPU models and configuration: GPU 0: NVIDIA RTX 6000 Ada Generation
Nvidia driver version: 545.29.06
cuDNN version: Could not collect
HIP runtime version: N/A
MIOpen runtime version: N/A
Is XNNPACK available: True

CPU:
Architecture:                       x86_64
CPU op-mode(s):                     32-bit, 64-bit
Address sizes:                      46 bits physical, 48 bits virtual
Byte Order:                         Little Endian
CPU(s):                             32
On-line CPU(s) list:                0-31
Vendor ID:                          GenuineIntel
Model name:                         13th Gen Intel(R) Core(TM) i9-13900K
CPU family:                         6
Model:                              183
Thread(s) per core:                 2
Core(s) per socket:                 24
Socket(s):                          1
Stepping:                           1
CPU max MHz:                        5800.0000
CPU min MHz:                        800.0000
BogoMIPS:                           5990.40
Flags:                              fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb ssbd ibrs ibpb stibp ibrs_enhanced tpr_shadow flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid rdseed adx smap clflushopt clwb intel_pt sha_ni xsaveopt xsavec xgetbv1 xsaves split_lock_detect avx_vnni dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp hwp_pkg_req hfi vnmi umip pku ospke waitpkg gfni vaes vpclmulqdq tme rdpid movdiri movdir64b fsrm md_clear serialize pconfig arch_lbr ibt flush_l1d arch_capabilities
Virtualization:                     VT-x
L1d cache:                          896 KiB (24 instances)
L1i cache:                          1.3 MiB (24 instances)
L2 cache:                           32 MiB (12 instances)
L3 cache:                           36 MiB (1 instance)
NUMA node(s):                       1
NUMA node0 CPU(s):                  0-31
Vulnerability Gather data sampling: Not affected
Vulnerability Itlb multihit:        Not affected
Vulnerability L1tf:                 Not affected
Vulnerability Mds:                  Not affected
Vulnerability Meltdown:             Not affected
Vulnerability Mmio stale data:      Not affected
Vulnerability Retbleed:             Not affected
Vulnerability Spec rstack overflow: Not affected
Vulnerability Spec store bypass:    Mitigation; Speculative Store Bypass disabled via prctl
Vulnerability Spectre v1:           Mitigation; usercopy/swapgs barriers and __user pointer sanitization
Vulnerability Spectre v2:           Mitigation; Enhanced / Automatic IBRS, IBPB conditional, RSB filling, PBRSB-eIBRS SW sequence
Vulnerability Srbds:                Not affected
Vulnerability Tsx async abort:      Not affected

Versions of relevant libraries:
[pip3] mypy-extensions==1.0.0
[pip3] numpy==1.26.4
[pip3] nvidia-nccl-cu12==2.20.5
[pip3] torch==2.3.0
[pip3] triton==2.3.0
[pip3] vllm-nccl-cu12==2.18.1.0.4.0
[conda] Could not collectROCM Version: Could not collect
Neuron SDK Version: N/A
vLLM Version: 0.4.2
vLLM Build Flags:
CUDA Archs: Not Set; ROCm: Disabled; Neuron: Disabled
GPU Topology:
�[4mGPU0	CPU Affinity	NUMA Affinity	GPU NUMA ID�[0m
GPU0	 X 	0-31	0		N/A

Legend:

  X    = Self
  SYS  = Connection traversing PCIe as well as the SMP interconnect between NUMA nodes (e.g., QPI/UPI)
  NODE = Connection traversing PCIe as well as the interconnect between PCIe Host Bridges within a NUMA node
  PHB  = Connection traversing PCIe as well as a PCIe Host Bridge (typically the CPU)
  PXB  = Connection traversing multiple PCIe bridges (without traversing the PCIe Host Bridge)
  PIX  = Connection traversing at most a single PCIe bridge
  NV#  = Connection traversing a bonded set of # NVLinks

🐛 Describe the bug

The code below worked fine with vllm==0.3.3 (I could see the generated output printed to the console).
However, when I try to use it with 0.4.0, 0.4.1 or 0.4.2 it hangs.

import argparse
import asyncio

from vllm.engine.arg_utils import AsyncEngineArgs
from vllm.engine.async_llm_engine import AsyncLLMEngine, AsyncStream
from vllm.sampling_params import SamplingParams


def parse_args():
    parser = argparse.ArgumentParser()
    parser = AsyncEngineArgs.add_cli_args(parser)
    return parser.parse_args()


async def iterate_over_output_for_one_prompt(output_iterator: AsyncStream) -> str:
    last_text = ""
    prompt = "???"

    async for output in output_iterator:
        prompt = output.prompt
        last_text = output.outputs[0].text

    return prompt + last_text


async def generate(engine: AsyncLLMEngine, prompts: list[str]) -> list[str]:
    sampling_params = SamplingParams(n=1, max_tokens=100, ignore_eos=True)
    output_iterators = [await engine.add_request(f"req_{i}", prompt, sampling_params)
                        for i, prompt in enumerate(prompts)]
    outputs = await asyncio.gather(*[iterate_over_output_for_one_prompt(output_iterator)
                                     for output_iterator in output_iterators])
    return list(outputs)


def main():
    args = parse_args()
    engine = AsyncLLMEngine.from_engine_args(AsyncEngineArgs.from_cli_args(args))
    prompts = ["I've never been to", "I would like to see"]
    outputs = asyncio.run(generate(engine, prompts))
    for output in outputs:
        print(output)
    print("FINISHED")


if __name__ == '__main__':
    main()

The last logs before iterrupting the execution are

INFO 05-13 14:28:39 async_llm_engine.py:120] Finished request req_0.
INFO 05-13 14:28:39 async_llm_engine.py:120] Finished request req_1.

And after finally pressing Ctrl+C I get

  File "/workdir/repo/llmvpr/vllm/minimal.py", line 46, in <module>
    main()
  File "/workdir/repo/llmvpr/vllm/minimal.py", line 39, in main
    outputs = asyncio.run(generate(engine, prompts))
  File "/usr/lib/python3.10/asyncio/runners.py", line 47, in run
    _cancel_all_tasks(loop)
  File "/usr/lib/python3.10/asyncio/runners.py", line 63, in _cancel_all_tasks
    loop.run_until_complete(tasks.gather(*to_cancel, return_exceptions=True))
  File "/usr/lib/python3.10/asyncio/base_events.py", line 636, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.10/asyncio/base_events.py", line 603, in run_forever
    self._run_once()
  File "/usr/lib/python3.10/asyncio/base_events.py", line 1871, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.10/selectors.py", line 469, in select
    fd_event_list = self._selector.poll(timeout, max_ev)
KeyboardInterrupt
Task was destroyed but it is pending!
task: <Task pending name='Task-2' coro=<AsyncLLMEngine.run_engine_loop() running at /usr/local/lib/python3.10/dist-packages/vllm/engine/async_llm_engine.py:490> wait_for=<Future pending cb=[Task.task_wakeup()]> cb=[_raise_exception_on_finish(error_callback=<bound method...7851eba052d0>>)() at /usr/local/lib/python3.10/dist-packages/vllm/engine/async_llm_engine.py:30, <1 more>, gather.<locals>._done_callback() at /usr/lib/python3.10/asyncio/tasks.py:720]>

Is there something wrong with my code or is it a bug in vllm?

[youkaichao]

If you experienced crashes or hangs, it would be helpful to run vllm with export VLLM_TRACE_FUNCTION=1 . All the function calls in vllm will be recorded. Inspect these log files, and tell which function crashes or hangs.

Quote from issue templates.

[glos-nv]

vllm_trace_function.log
The requested log file is too large to send in its entirety, but I am attaching the last 10MB.

[simon-mo]

When you initialize the async engine I think it expects to be in an running event loop, not sure why though.

If you change the code to

diff --git a/original.py b/repro.py
index 37ede83..8881b6f 100644
--- a/original.py
+++ b/repro.py
@@ -32,15 +32,15 @@ async def generate(engine: AsyncLLMEngine, prompts: list[str]) -> list[str]:
     return list(outputs)


-def main():
+async def main():
     args = parse_args()
     engine = AsyncLLMEngine.from_engine_args(AsyncEngineArgs.from_cli_args(args))
     prompts = ["I've never been to", "I would like to see"]
-    outputs = asyncio.run(generate(engine, prompts))
+    outputs = await generate(engine, prompts)
     for output in outputs:
         print(output)
     print("FINISHED")


 if __name__ == '__main__':
-    main()
+    asyncio.run(main())

The prints should succeed.

However, the script still will not exit. So there's still a bug.

[zifeitong]

Saw the same issue. I tested and the culprit commit should be #3015. It's not clear to me what's the root cause though.

[zifeitong]

So the problem is that

vllm/vllm/engine/async_llm_engine.py

Line 509 in 97b0300

has_requests_in_progress = await asyncio.wait_for(

triggered python/cpython#86296

The bug is fixed in Python 3.12 but will not be backported. It's very easy to workaround it in Python 3.11 with asyncio.timeout. However, the workaround for Python 3.8 - 3.10 is not straightforward.