[Bug]: 启动qwen2.5-vl系列的时候为啥老是卡着

[lijingcheng2021]

Your current environment

为啥老是卡着

🐛 Describe the bug

为啥启动服务的时候老是卡着

Before submitting a new issue...

• Make sure you already searched for relevant issues, and asked the chatbot living at the bottom right corner of the documentation page, which can answer lots of frequently asked questions.

[DarkLight1337]

Can you cancel the command and print out the stack trace? This should tell us where it's getting stuck at.

[YorkSu]

I manually add some debug log to do the stack trace. (I can't see anything with VLLM_TRACE_FUNCTION=1)

Stuck trace:

1. Stuck
   1. vllm.worker.model_runner.py, V0
      • GPUModelRunnerBase._dummy_run
      • dummy_data = self.input_registry.dummy_data_for_profiling(...)
   2. vllm.v1.worker.gpu_model_runner.py, V1
      • GPUModelRunner.profile_run
      • dummy_request_data = self.input_registry.dummy_data_for_profiling(...)
2. vllm.inputs.registry.py
   • InputRegistry.dummy_data_for_profiling
     • dummy_data = profiler.get_dummy_data(...)
3. vllm.multimodel.profiling.py
   • MultiModelProfiler.get_dummy_data
     • mm_inputs = self._get_dummy_mm_inputs(...)
   • MultiModelProfiler._get_dummy_mm_inputs
     • return self.processor.apply(...)
4. vllm.multimodel.processing.py
   • BaseMultiModelProcessing.apply
     1. (...) = self._cached_apply_hf_processor(...), stuck here for a while
     2. (...) = self._apply_prompt_replacements(...), stuck here for a loooooong time
   • BaseMultiModelProcessing._apply_prompt_replacements
     • text = decode_tokens(...), stuck here for a loooooong time

Some observations:

1. Arguments --limit-mm-per-prompt image=5 affects the stuck time
   • I can see the processor_inputs at MultiModelProfiler._get_dummy_mm_inputs
   • By printing its content, I found that this dummy data contains 5 pictures with a pixel size of 3584x3584 (Qwen2.5-VL max_pixels) and a video with a shape of (1, 3584, 3584, 3).
   • I set the --max-model-len 32768, so the token length of the dummy data far exceeds the maximum length of the model
2. When it gets stuck, the cpu usage is 100% and only one core is used

[DarkLight1337]

Thanks for the analysis, let me dig deeper regarding this.

[DarkLight1337]

When I profile this, the place where it gets stuck is actually in _cached_apply_hf_processor (taking around 90% of the total time of _get_dummy_mm_inputs), rather than decode_tokens. It takes 15s on average to get the dummy inputs, which is quite long but still not enough to consider it to be "hanging".

Here is my profiling code:

# Append this to tests/models/multimodal/processing/test_qwen2_vl.py
from tqdm import tqdm
from vllm.multimodal.profiling import MultiModalProfiler

@pytest.mark.parametrize("model_id", ["Qwen/Qwen2.5-VL-3B-Instruct"])
@pytest.mark.parametrize("max_model_len", [2048 * 2 ** i for i in range(5)])
def test_processor_perf(model_id: str, max_model_len: int):
    ctx = build_model_context(
        model_name=model_id,
        tokenizer_name=model_id,
        max_model_len=max_model_len,
        mm_processor_kwargs={},
        limit_mm_per_prompt={"image": 5},
    )
    tokenizer = cached_tokenizer_from_config(ctx.model_config)
    processor = MULTIMODAL_REGISTRY.create_processor(
        ctx.model_config,
        tokenizer=tokenizer,
    )
    profiler = MultiModalProfiler(processor)

    for _ in tqdm(range(10),
                  desc=f"Profiling {model_id} processor for {max_model_len=}"):
        profiler.get_dummy_data(max_model_len)

And the command to run the profiler (I use py-spy):

py-spy record -o profile.svg --rate 20 -- pytest tests/models/multimodal/processing/test_qwen2_vl.py -k test_processor_perf[32768-Qwen/Qwen2.5-VL-3B-Instruct] -svv

It shows that the cause of the problem is the slow image processing speed of HF's Qwen2VLImageProcessor.

[DarkLight1337]

cc @Isotr0py @ywang96

[YorkSu]

I made a similar profile. model_id=/models/Qwen2.5-VL-7B-Instruct-AWQ
NOTE: I replaced image_processor_type in preprocessor_config.json with Qwen2VLImageProcessorFast (original value: Qwen2VLImageProcessor)

py-spy record -o profile.svg --rate 20 -- pytest tests/models/multimodal/processing/test_qwen2_vl.py -k test_processor_perf[32768-/models/Qwen2.5-VL-7B-Instruct-AWQ] -svv

It shows that call_hf_proceessor (vllm/inputs/registry.py:167) taking around 85% of the total time of _get_dummy_mm_inputs. The major contributor to this time is the preprocess (transformers/models/qwen2_vl/image_processing_qwen2_vl_fast.py:355). The overall execution time is approximately 1~3 minutes.

If I set the number of cores for the Kubernetes pod to 1, the process becomes extremely slow, taking about 15 to 30 minutes. (The relatively faster experiment above runs with core=64.)

[Isotr0py]

@YorkSu Qwen2VLImageProcessorFast is using torchvision for processing. And I remember that native float16 support is just added to torch2.6, so it will be quite slow if you using float16 (the only available dtype for AWQ) and Qwen2VLImageProcessorFast together on CPU because we're still using torch2.5.

Can you check what happened if you switch to Qwen2VLImageProcessor? Oh, didn't notice there have been a profiling on Qwen2VLImageProcessor, let me investigate it tonight.

[YorkSu]

I switched to Qwen2VLImageProcessor and performed the performance test again. The situation is worse; call_hf_processor (vllm/inputs/registry.py:167) occupies more than 95% of the time (mainly due to preprocess (transformers/models/qwen2_vl/image_processing_qwen2_vl.py:375)), and the overall time consumption has also reached 5 minutes.

[denadai2]

same issue. cpu usage high, gpu usage 0 for minutes and minutes and minutes

[DarkLight1337]

In the meantime, you can try to alleviate this via the following settings:

• Cap the maximum number of pixels allowed in the HF processor (--mm-processor-kwargs '{"max_pixels": ...}')
• If you don't need to handle videos, you can disable profiling for video inputs (--limit-mm-per-prompt image=...,video=0)

[denadai2]

this is the video: https://recsys.westlake.edu.cn/MicroLens-50k-Dataset/MicroLens-50k_videos/17513.mp4, resized to 426x240, 10 fps

this is the code:

ORIGINAL_MODEL_PATH = "Qwen/Qwen2.5-VL-7B-Instruct"
min_pixels = 256*28*28
max_pixels = 1280*28*28

llm = LLM(
    model=ORIGINAL_MODEL_PATH,
    limit_mm_per_prompt={"image": 1, "video": 1},
    tensor_parallel_size=4,
    #max_num_seqs=1,
    #max_model_len=70000,
    mm_processor_kwargs={"use_fast": True,
                         "image_processor_type": "Qwen2VLImageProcessorFast"},  # not valid args it tells me Keyword argument `use_fast` is not a valid argument for this processor and will be ignored.
    disable_mm_preprocessor_cache=True,
    enforce_eager=True,
    enable_chunked_prefill=False,
)

processor = AutoProcessor.from_pretrained(ORIGINAL_MODEL_PATH, use_fast=True, min_pixels=min_pixels, max_pixels=max_pixels)
sampling_params = SamplingParams(
    temperature=0.1,
    top_p=0.001,
    repetition_penalty=1.05,
    max_tokens=1024,
    stop_token_ids=[],
)

import os
input_path = "/data/sampled_videos"
output_path = "/data/processed_data/video_captions"

for video_name in ["17513.mp4"]:

    prompt = """Describe the content of the video"""

    messages = [
        {"role": "system", "content": "You are a helpful assistant."},
        {"role": "user", "content": [
            {"type": "text", "text": prompt},
            {
                "type": "video",
                "video": f"{input_path}/{video_name}",
                "fps": 2,
            }
        ]
         },
    ]

    prompt = processor.apply_chat_template(
        messages,
        tokenize=False,
        add_generation_prompt=True,
    )
    image_inputs, video_inputs, video_kwargs = process_vision_info(messages, return_video_kwargs=True)

    mm_data = {}
    if video_inputs is not None:
        mm_data["video"] = video_inputs

    print(mm_data)
    llm_inputs = {
        "prompt": prompt,
        "multi_modal_data": mm_data,

        # FPS will be returned in video_kwargs
        "mm_processor_kwargs": video_kwargs,
    }

    outputs = llm.generate([llm_inputs], sampling_params=sampling_params,
    use_tqdm=False,)
    generated_text = outputs[0].outputs[0].text

logs

INFO 03-19 09:57:28 [__init__.py:32] name=register_dummy_model, value=vllm_plugin_meralion:register
INFO 03-19 09:57:28 [__init__.py:34] all available plugins for group vllm.general_plugins will be loaded.
INFO 03-19 09:57:28 [__init__.py:36] set environment variable VLLM_PLUGINS to control which plugins to load.
INFO 03-19 09:57:29 [__init__.py:44] plugin register_dummy_model loaded.
INFO 03-19 09:57:38 [config.py:583] This model supports multiple tasks: {'embed', 'score', 'generate', 'reward', 'classify'}. Defaulting to 'generate'.
INFO 03-19 09:57:39 [config.py:1515] Defaulting to use mp for distributed inference
INFO 03-19 09:57:39 [config.py:1693] Chunked prefill is enabled with max_num_batched_tokens=8192.
WARNING 03-19 09:57:39 [cuda.py:95] To see benefits of async output processing, enable CUDA graph. Since, enforce-eager is enabled, async output processor cannot be used
INFO 03-19 09:57:39 [core.py:53] Initializing a V1 LLM engine (v0.8.0) with config: model='Qwen/Qwen2.5-VL-7B-Instruct', speculative_config=None, tokenizer='Qwen/Qwen2.5-VL-7B-Instruct', skip_tokeni
zer_init=False, tokenizer_mode=auto, revision=None, override_neuron_config=None, tokenizer_revision=None, trust_remote_code=False, dtype=torch.bfloat16, max_seq_len=70000, download_dir=None, load_fo
rmat=auto, tensor_parallel_size=4, pipeline_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto,  device_config=cuda, decoding_config=Decodin
gConfig(guided_decoding_backend='xgrammar', reasoning_backend=None), observability_config=ObservabilityConfig(show_hidden_metrics=False, otlp_traces_endpoint=None, collect_model_forward_time=False,
collect_model_execute_time=False), seed=None, served_model_name=Qwen/Qwen2.5-VL-7B-Instruct, num_scheduler_steps=1, multi_step_stream_outputs=True, enable_prefix_caching=True, chunked_prefill_enable
d=True, use_async_output_proc=False, disable_mm_preprocessor_cache=True, mm_processor_kwargs={'use_fast': True, 'image_processor_type': 'Qwen2VLImageProcessorFast', 'min_pixels': 200704, 'max_pixels
': 1003520}, pooler_config=None, compilation_config={"splitting_ops":[],"compile_sizes":[],"cudagraph_capture_sizes":[],"max_capture_size":0}
WARNING 03-19 09:57:39 [multiproc_worker_utils.py:310] Reducing Torch parallelism from 24 threads to 1 to avoid unnecessary CPU contention. Set OMP_NUM_THREADS in the external environment to tune th
is value as needed.
INFO 03-19 09:57:39 [custom_cache_manager.py:19] Setting Triton cache manager to: vllm.triton_utils.custom_cache_manager:CustomCacheManager
INFO 03-19 09:57:39 [shm_broadcast.py:258] vLLM message queue communication handle: Handle(local_reader_ranks=[0, 1, 2, 3], buffer_handle=(4, 10485760, 10, 'psm_26b212bf'), local_subscribe_addr='ipc
:///var/tmp/d4b1c15b-fbc1-4aea-9a33-e02e5d366c58', remote_subscribe_addr=None, remote_addr_ipv6=False)
WARNING 03-19 09:57:40 [utils.py:2282] Methods determine_num_available_blocks,device_config,get_cache_block_size_bytes,initialize_cache not implemented in <vllm.v1.worker.gpu_worker.Worker object at
 0x7f39364e01f0>
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:40 [shm_broadcast.py:258] vLLM message queue communication handle: Handle(local_reader_ranks=[0], buffer_handle=(1, 10485760, 10, 'psm_bfdf48f5'), loca
l_subscribe_addr='ipc:///var/tmp/52aae627-f0eb-422f-8772-f0ec9231c6d9', remote_subscribe_addr=None, remote_addr_ipv6=False)
WARNING 03-19 09:57:41 [utils.py:2282] Methods determine_num_available_blocks,device_config,get_cache_block_size_bytes,initialize_cache not implemented in <vllm.v1.worker.gpu_worker.Worker object at
 0x7f39364e07f0>
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:41 [shm_broadcast.py:258] vLLM message queue communication handle: Handle(local_reader_ranks=[0], buffer_handle=(1, 10485760, 10, 'psm_0d780ac3'), loca
l_subscribe_addr='ipc:///var/tmp/660d1efa-a66a-451f-a2bd-f8d07119dd00', remote_subscribe_addr=None, remote_addr_ipv6=False)
WARNING 03-19 09:57:42 [utils.py:2282] Methods determine_num_available_blocks,device_config,get_cache_block_size_bytes,initialize_cache not implemented in <vllm.v1.worker.gpu_worker.Worker object at
 0x7f39364e0280>
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:42 [shm_broadcast.py:258] vLLM message queue communication handle: Handle(local_reader_ranks=[0], buffer_handle=(1, 10485760, 10, 'psm_66d25fa1'), loca
l_subscribe_addr='ipc:///var/tmp/f561ec64-1da7-4f0e-b95d-4c924192b592', remote_subscribe_addr=None, remote_addr_ipv6=False)
WARNING 03-19 09:57:43 [utils.py:2282] Methods determine_num_available_blocks,device_config,get_cache_block_size_bytes,initialize_cache not implemented in <vllm.v1.worker.gpu_worker.Worker object at
 0x7f39364e07c0>
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:43 [shm_broadcast.py:258] vLLM message queue communication handle: Handle(local_reader_ranks=[0], buffer_handle=(1, 10485760, 10, 'psm_bd41afd7'), loca
l_subscribe_addr='ipc:///var/tmp/9b140b29-7d9b-4da7-8d77-43c2e2639a0b', remote_subscribe_addr=None, remote_addr_ipv6=False)
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2`
$
l_subscribe_addr='ipc:///var/tmp/9b140b29-7d9b-4da7-8d77-43c2e2639a0b', remote_subscribe_addr=None, remote_addr_ipv6=False)
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:44 [utils.py:925] Found nccl from library libnccl.so.2
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:44 [pynccl.py:69] vLLM is using nccl==2.21.5
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:44 [pynccl.py:69] vLLM is using nccl==2.21.5
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:44 [pynccl.py:69] vLLM is using nccl==2.21.5
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:44 [pynccl.py:69] vLLM is using nccl==2.21.5
(VllmWorker rank=1 pid=29437) WARNING 03-19 09:57:44 [custom_all_reduce.py:137] Custom allreduce is disabled because it's not supported on more than two PCIe-only GPUs. To silence this warning, spec
ify disable_custom_all_reduce=True explicitly.
(VllmWorker rank=3 pid=29489) WARNING 03-19 09:57:44 [custom_all_reduce.py:137] Custom allreduce is disabled because it's not supported on more than two PCIe-only GPUs. To silence this warning, spec
ify disable_custom_all_reduce=True explicitly.
(VllmWorker rank=2 pid=29459) WARNING 03-19 09:57:44 [custom_all_reduce.py:137] Custom allreduce is disabled because it's not supported on more than two PCIe-only GPUs. To silence this warning, spec
ify disable_custom_all_reduce=True explicitly.
(VllmWorker rank=0 pid=29399) WARNING 03-19 09:57:44 [custom_all_reduce.py:137] Custom allreduce is disabled because it's not supported on more than two PCIe-only GPUs. To silence this warning, spec
ify disable_custom_all_reduce=True explicitly.
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:44 [shm_broadcast.py:258] vLLM message queue communication handle: Handle(local_reader_ranks=[1, 2, 3], buffer_handle=(3, 4194304, 6, 'psm_ac4b5bec'),
local_subscribe_addr='ipc:///var/tmp/4c56f1a0-030a-44a2-9b30-eb00ad163ec6', remote_subscribe_addr=None, remote_addr_ipv6=False)
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:44 [parallel_state.py:967] rank 3 in world size 4 is assigned as DP rank 0, PP rank 0, TP rank 3
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:44 [parallel_state.py:967] rank 2 in world size 4 is assigned as DP rank 0, PP rank 0, TP rank 2
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:44 [parallel_state.py:967] rank 1 in world size 4 is assigned as DP rank 0, PP rank 0, TP rank 1
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:44 [parallel_state.py:967] rank 0 in world size 4 is assigned as DP rank 0, PP rank 0, TP rank 0
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:44 [cuda.py:215] Using Flash Attention backend on V1 engine.
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:44 [cuda.py:215] Using Flash Attention backend on V1 engine.
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:44 [cuda.py:215] Using Flash Attention backend on V1 engine.
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:44 [cuda.py:215] Using Flash Attention backend on V1 engine.
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:45 [gpu_model_runner.py:1128] Starting to load model Qwen/Qwen2.5-VL-7B-Instruct...
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:45 [gpu_model_runner.py:1128] Starting to load model Qwen/Qwen2.5-VL-7B-Instruct...
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:45 [gpu_model_runner.py:1128] Starting to load model Qwen/Qwen2.5-VL-7B-Instruct...
(VllmWorker rank=3 pid=29489) WARNING 03-19 09:57:45 [vision.py:94] Current `vllm-flash-attn` has a bug inside vision module, so we use xformers backend instead. You can run `pip install flash-attn`
 to use flash-attention backend.
(VllmWorker rank=2 pid=29459) WARNING 03-19 09:57:45 [vision.py:94] Current `vllm-flash-attn` has a bug inside vision module, so we use xformers backend instead. You can run `pip install flash-attn`
 to use flash-attention backend.
(VllmWorker rank=0 pid=29399) WARNING 03-19 09:57:45 [vision.py:94] Current `vllm-flash-attn` has a bug inside vision module, so we use xformers backend instead. You can run `pip install flash-attn`
 to use flash-attention backend.
(VllmWorker rank=3 pid=29489) INFO 03-19 09:57:45 [config.py:3222] cudagraph sizes specified by model runner [] is overridden by config []
(VllmWorker rank=1 pid=29437) INFO 03-19 09:57:45 [gpu_model_runner.py:1128] Starting to load model Qwen/Qwen2.5-VL-7B-Instruct...
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:45 [config.py:3222] cudagraph sizes specified by model runner [] is overridden by config []
(VllmWorker rank=0 pid=29399) INFO 03-19 09:57:45 [config.py:3222] cudagraph sizes specified by model runner [] is overridden by config []
(VllmWorker rank=1 pid=29437) WARNING 03-19 09:57:45 [vision.py:94] Current `vllm-flash-attn` has a bug inside vision module, so we use xformers backend instead. You can run `pip install flash-attn

tested with 0.8.0

[denadai2]

@DarkLight1337 no changes with that. The video I am using is already resized to 10 fps 426x240 pixels

I also have a log telling me
(VllmWorker rank=2 pid=29459) INFO 03-19 09:57:49 [gpu_model_runner.py:1358] Encoder cache will be initialized with a budget of 9800 tokens, and profiled with 1 video items of the maximum feature size.

and

Keyword argument `use_fast` is not a valid argument for this processor and will be ignored.
Keyword argument `image_processor_type` is not a valid argument for this processor and will be ignored.
Keyword argument `min_pixels` is not a valid argument for this processor and will be ignored.
Keyword argument `max_pixels` is not a valid argument for this processor and will be ignored.

[DarkLight1337]

Does the slow response occur when starting vLLM, or during inference time?

[denadai2]

inference time, on the generate call

nvtop

htop