[Bug]: multiprocessing KeyError from cache[rtype].remove(name)

[RobertFischer]

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.4 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.5
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-5.15.0-107-generic-x86_64-with-glibc2.35
Is CUDA available: True
CUDA runtime version: Could not collect
CUDA_MODULE_LOADING set to: LAZY
GPU models and configuration:
GPU 0: Tesla T4
GPU 1: Tesla T4

Nvidia driver version: 535.183.01
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):                             104
On-line CPU(s) list:                0-103
Vendor ID:                          GenuineIntel
Model name:                         Intel(R) Xeon(R) Gold 6230R CPU @ 2.10GHz
CPU family:                         6
Model:                              85
Thread(s) per core:                 2
Core(s) per socket:                 26
Socket(s):                          2
Stepping:                           7
CPU max MHz:                        4000.0000
CPU min MHz:                        1000.0000
BogoMIPS:                           4200.00
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 pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb cat_l3 cdp_l3 invpcid_single intel_ppin ssbd mba ibrs ibpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid cqm mpx rdt_a avx512f avx512dq rdseed adx smap clflushopt clwb intel_pt avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local dtherm ida arat pln pts pku ospke avx512_vnni md_clear flush_l1d arch_capabilities
Virtualization:                     VT-x
L1d cache:                          1.6 MiB (52 instances)
L1i cache:                          1.6 MiB (52 instances)
L2 cache:                           52 MiB (52 instances)
L3 cache:                           71.5 MiB (2 instances)
NUMA node(s):                       2
NUMA node0 CPU(s):                  0,2,4,6,8,10,12,14,16,18,20,22,24,26,28,30,32,34,36,38,40,42,44,46,48,50,52,54,56,58,60,62,64,66,68,70,72,74,76,78,80,82,84,86,88,90,92,94,96,98,100,102
NUMA node1 CPU(s):                  1,3,5,7,9,11,13,15,17,19,21,23,25,27,29,31,33,35,37,39,41,43,45,47,49,51,53,55,57,59,61,63,65,67,69,71,73,75,77,79,81,83,85,87,89,91,93,95,97,99,101,103
Vulnerability Gather data sampling: Mitigation; Microcode
Vulnerability Itlb multihit:        KVM: Mitigation: VMX disabled
Vulnerability L1tf:                 Not affected
Vulnerability Mds:                  Not affected
Vulnerability Meltdown:             Not affected
Vulnerability Mmio stale data:      Mitigation; Clear CPU buffers; SMT vulnerable
Vulnerability Retbleed:             Mitigation; Enhanced IBRS
Vulnerability Spec rstack overflow: Not affected
Vulnerability Spec store bypass:    Mitigation; Speculative Store Bypass disabled via prctl and seccomp
Vulnerability Spectre v1:           Mitigation; usercopy/swapgs barriers and __user pointer sanitization
Vulnerability Spectre v2:           Mitigation; Enhanced IBRS; IBPB conditional; RSB filling; PBRSB-eIBRS SW sequence; BHI Syscall hardening, KVM SW loop
Vulnerability Srbds:                Not affected
Vulnerability Tsx async abort:      Mitigation; TSX disabled

Versions of relevant libraries:
[pip3] numpy==1.26.4
[pip3] nvidia-nccl-cu12==2.20.5
[pip3] torch==2.3.0
[pip3] transformers==4.41.2
[pip3] triton==2.3.0
[conda] Could not collect
ROCM Version: Could not collect
Neuron SDK Version: N/A
vLLM Version: 0.5.0.post1
vLLM Build Flags:
CUDA Archs: Not Set; ROCm: Disabled; Neuron: Disabled
GPU Topology:
GPU0	GPU1	CPU Affinity	NUMA Affinity	GPU NUMA ID
GPU0	 X 	SYS	0,2,4,6,8,10	0		N/A
GPU1	SYS	 X 	1,3,5,7,9,11	1		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

+ exec python3 -m vllm.entrypoints.openai.api_server --port 8000 --model /models/TheBloke/Llama-2-13B-chat-AWQ --tensor-parallel-size 2 --gpu-memory-utilization 0.6 --quantization awq
INFO 06-18 18:49:00 api_server.py:177] vLLM API server version 0.5.0.post1
INFO 06-18 18:49:00 api_server.py:178] args: Namespace(host=None, port=8000, uvicorn_log_level='info', allow_credentials=False, allowed_origins=['*'], allowed_methods=['*'], allowed_headers=['*'], api_key=None, lora_modules=None, chat_template=None, response_role='assistant', ssl_keyfile=None, ssl_certfile=None, ssl_ca_certs=None, ssl_cert_reqs=0, root_path=None, middleware=[], model='/models/TheBloke/Llama-2-13B-chat-AWQ', tokenizer=None, skip_tokenizer_init=False, revision=None, code_revision=None, tokenizer_revision=None, tokenizer_mode='auto', trust_remote_code=False, download_dir=None, load_format='auto', dtype='auto', kv_cache_dtype='auto', quantization_param_path=None, max_model_len=None, guided_decoding_backend='outlines', distributed_executor_backend=None, worker_use_ray=False, pipeline_parallel_size=1, tensor_parallel_size=2, max_parallel_loading_workers=None, ray_workers_use_nsight=False, block_size=16, enable_prefix_caching=False, disable_sliding_window=False, use_v2_block_manager=False, num_lookahead_slots=0, seed=0, swap_space=4, gpu_memory_utilization=0.6, num_gpu_blocks_override=None, max_num_batched_tokens=None, max_num_seqs=256, max_logprobs=20, disable_log_stats=False, quantization='awq', rope_scaling=None, rope_theta=None, enforce_eager=False, max_context_len_to_capture=None, max_seq_len_to_capture=8192, disable_custom_all_reduce=False, tokenizer_pool_size=0, tokenizer_pool_type='ray', tokenizer_pool_extra_config=None, enable_lora=False, max_loras=1, max_lora_rank=16, lora_extra_vocab_size=256, lora_dtype='auto', long_lora_scaling_factors=None, max_cpu_loras=None, fully_sharded_loras=False, device='auto', image_input_type=None, image_token_id=None, image_input_shape=None, image_feature_size=None, image_processor=None, image_processor_revision=None, disable_image_processor=False, scheduler_delay_factor=0.0, enable_chunked_prefill=False, speculative_model=None, num_speculative_tokens=None, speculative_max_model_len=None, speculative_disable_by_batch_size=None, ngram_prompt_lookup_max=None, ngram_prompt_lookup_min=None, model_loader_extra_config=None, preemption_mode=None, served_model_name=None, qlora_adapter_name_or_path=None, engine_use_ray=False, disable_log_requests=False, max_log_len=None)
WARNING 06-18 18:49:00 config.py:217] awq quantization is not fully optimized yet. The speed can be slower than non-quantized models.
2024-06-18 18:49:02,601	INFO worker.py:1753 -- Started a local Ray instance.
INFO 06-18 18:49:03 config.py:623] Defaulting to use mp for distributed inference
INFO 06-18 18:49:03 llm_engine.py:161] Initializing an LLM engine (v0.5.0.post1) with config: model='/models/TheBloke/Llama-2-13B-chat-AWQ', speculative_config=None, tokenizer='/models/TheBloke/Llama-2-13B-chat-AWQ', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, rope_scaling=None, rope_theta=None, tokenizer_revision=None, trust_remote_code=False, dtype=torch.float16, max_seq_len=4096, download_dir=None, load_format=LoadFormat.AUTO, tensor_parallel_size=2, disable_custom_all_reduce=False, quantization=awq, enforce_eager=False, kv_cache_dtype=auto, quantization_param_path=None, device_config=cuda, decoding_config=DecodingConfig(guided_decoding_backend='outlines'), seed=0, served_model_name=/models/TheBloke/Llama-2-13B-chat-AWQ)
WARNING 06-18 18:49:03 logger.py:146] VLLM_TRACE_FUNCTION is enabled. It will record every function executed by Python. This will slow down the code. It is suggested to be used for debugging hang or crashes only.
INFO 06-18 18:49:03 logger.py:150] Trace frame log is saved to /tmp/vllm/vllm-instance-55c4b1c07eb04b5cb88254a49e2e53f4/VLLM_TRACE_FUNCTION_for_process_1_thread_139769720075392_at_2024-06-18_18:49:03.498228.log
INFO 06-18 18:49:04 selector.py:131] Cannot use FlashAttention-2 backend for Volta and Turing GPUs.
INFO 06-18 18:49:04 selector.py:51] Using XFormers backend.
(VllmWorkerProcess pid=768) WARNING 06-18 18:49:10 logger.py:146] VLLM_TRACE_FUNCTION is enabled. It will record every function executed by Python. This will slow down the code. It is suggested to be used for debugging hang or crashes only.
(VllmWorkerProcess pid=768) INFO 06-18 18:49:10 logger.py:150] Trace frame log is saved to /tmp/vllm/vllm-instance-55c4b1c07eb04b5cb88254a49e2e53f4/VLLM_TRACE_FUNCTION_for_process_768_thread_140264482706560_at_2024-06-18_18:49:10.092174.log
(VllmWorkerProcess pid=768) INFO 06-18 18:49:10 selector.py:131] Cannot use FlashAttention-2 backend for Volta and Turing GPUs.
(VllmWorkerProcess pid=768) INFO 06-18 18:49:10 selector.py:51] Using XFormers backend.
DEBUG 06-18 18:49:13 parallel_state.py:526] world_size=2 rank=0 local_rank=0 distributed_init_method=tcp://10.42.0.97:53801 backend=nccl
(VllmWorkerProcess pid=768) INFO 06-18 18:49:19 multiproc_worker_utils.py:215] Worker ready; awaiting tasks
(VllmWorkerProcess pid=768) DEBUG 06-18 18:49:19 parallel_state.py:526] world_size=2 rank=1 local_rank=1 distributed_init_method=tcp://10.42.0.97:53801 backend=nccl
(VllmWorkerProcess pid=768) INFO 06-18 18:49:19 utils.py:637] Found nccl from library libnccl.so.2
(VllmWorkerProcess pid=768) INFO 06-18 18:49:19 pynccl.py:63] vLLM is using nccl==2.20.5
INFO 06-18 18:49:19 utils.py:637] Found nccl from library libnccl.so.2
INFO 06-18 18:49:19 pynccl.py:63] vLLM is using nccl==2.20.5
Traceback (most recent call last):
  File "/usr/lib/python3.10/multiprocessing/resource_tracker.py", line 209, in main
    cache[rtype].remove(name)
KeyError: '/psm_a1296931'
INFO 06-18 18:49:20 custom_all_reduce_utils.py:170] generating GPU P2P access cache in /root/.config/vllm/gpu_p2p_access_cache_for_0,1.json
(VllmWorkerProcess pid=768) INFO 06-18 18:49:59 custom_all_reduce_utils.py:179] reading GPU P2P access cache from /root/.config/vllm/gpu_p2p_access_cache_for_0,1.json
INFO 06-18 18:49:59 custom_all_reduce_utils.py:179] reading GPU P2P access cache from /root/.config/vllm/gpu_p2p_access_cache_for_0,1.json
(VllmWorkerProcess pid=768) INFO 06-18 18:49:59 selector.py:131] Cannot use FlashAttention-2 backend for Volta and Turing GPUs.
(VllmWorkerProcess pid=768) INFO 06-18 18:49:59 selector.py:51] Using XFormers backend.
INFO 06-18 18:49:59 selector.py:131] Cannot use FlashAttention-2 backend for Volta and Turing GPUs.
INFO 06-18 18:49:59 selector.py:51] Using XFormers backend.

...and then vLLM crashes.

[youkaichao]

I don't think your code crashes after this benign error. see #5468

[RobertFischer]

You are in fact correct: of course, immediately after posting this bug report, I found out that vLLM is taking a while to connect and it's being killed by its supervisor.

Sorry for the annoyance. Maybe it'll save someone else from the red herring in the future...?

[njhill]

Though benign, it's still a bit strange / not ideal that these errors appear in the log. So this might still be a legit issue to track.

FWIW it does not seem to happen when fork is used instead of spawn (VLLM_WORKER_MULTIPROC_METHOD=fork). Looks like we'll probably make this the default soon anyhow: #5669.

[youkaichao]

@njhill please check #5512 . That benign error comes from Python's incorrect resource tracking