[Performance]: Low GPU Utilization (70%) for ViT+Qwen2 VLM Model.

[Oldpan]

Proposal to improve performance

x

Report of performance regression

I am benchmarking a custom model with a VLM structure consisting of ViT + Qwen2. During stress testing, I found that the GPU utilization reaches only 70%. Using the PyTorch profiler, I noticed that each iteration has a 2ms period at the start of Qwen2-forward that doesn't call CUDA. What is this period doing, and can it be optimized?

My Qwen2 model is relatively small at 0.5B.

My scripts:

 vllm serve /custom_model --gpu-memory-utilization 0.8 --port 8523  --max_model_len 4096 --max_num_seqs 256 --limit-mm-per-prompt image=1  --disable-log-requests 

benchmark scripts with --request-rate=20

trace here: https://drive.google.com/file/d/1pGWAH5j2VXviumqH9LRw7jm182_nAlBK/view?usp=drive_link

What are the possible reasons or parameters that could improve performance? Thanks！

Misc discussion on performance

x

Your current environment (if you think it is necessary)

The output of `python collect_env.py`
INFO 05-20 07:17:33 [__init__.py:248] Automatically detected platform cuda.
Collecting environment information...
==============================
        System Info
==============================
OS                           : Ubuntu 24.04.1 LTS (x86_64)
GCC version                  : (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0
Clang version                : 18.1.3 (1ubuntu1)
CMake version                : version 4.0.0
Libc version                 : glibc-2.39

==============================
       PyTorch Info
==============================
PyTorch version              : 2.7.0+cu126
Is debug build               : False
CUDA used to build PyTorch   : 12.6
ROCM used to build PyTorch   : N/A

==============================
      Python Environment
==============================
Python version               : 3.12.9 | packaged by Anaconda, Inc. | (main, Feb  6 2025, 18:56:27) [GCC 11.2.0] (64-bit runtime)
Python platform              : Linux-5.4.119-19-0013_plus-x86_64-with-glibc2.39

==============================
       CUDA / GPU Info
==============================
Is CUDA available            : True
CUDA runtime version         : 12.8.61
CUDA_MODULE_LOADING set to   : LAZY
GPU models and configuration : 
GPU 0: NVIDIA GeForce RTX 4090
GPU 1: NVIDIA GeForce RTX 4090
GPU 2: NVIDIA GeForce RTX 4090
GPU 3: NVIDIA GeForce RTX 4090
GPU 4: NVIDIA GeForce RTX 4090
GPU 5: NVIDIA GeForce RTX 4090
GPU 6: NVIDIA GeForce RTX 4090
GPU 7: NVIDIA GeForce RTX 4090

Nvidia driver version        : 535.171.04
cuDNN version                : Probably one of the following:
/usr/lib/x86_64-linux-gnu/libcudnn.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_adv.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_cnn.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_engines_precompiled.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_engines_runtime_compiled.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_graph.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_heuristic.so.9.7.1
/usr/lib/x86_64-linux-gnu/libcudnn_ops.so.9.7.1
HIP runtime version          : N/A
MIOpen runtime version       : N/A
Is XNNPACK available         : True

==============================
          CPU Info
==============================
Architecture:                    x86_64
CPU op-mode(s):                  32-bit, 64-bit
Address sizes:                   52 bits physical, 48 bits virtual
Byte Order:                      Little Endian
CPU(s):                          112
On-line CPU(s) list:             0-111
Vendor ID:                       GenuineIntel
BIOS Vendor ID:                  Red Hat
Model name:                      Intel(R) Xeon(R) Platinum 8476C
BIOS Model name:                 3.0  CPU @ 2.0GHz
BIOS CPU family:                 1
CPU family:                      6
Model:                           143
Thread(s) per core:              2
Core(s) per socket:              28
Socket(s):                       2
Stepping:                        6
BogoMIPS:                        5200.00
Flags:                           fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl xtopology nonstop_tsc cpuid tsc_known_freq pni pclmulqdq monitor ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch cpuid_fault invpcid_single ssbd ibrs ibpb ibrs_enhanced fsgsbase bmi1 hle avx2 smep bmi2 erms invpcid rtm avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves avx512_bf16 wbnoinvd arat avx512vbmi umip avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq movdiri movdir64b fsrm arch_capabilities
Hypervisor vendor:               KVM
Virtualization type:             full
L1d cache:                       2.6 MiB (56 instances)
L1i cache:                       1.8 MiB (56 instances)
L2 cache:                        112 MiB (56 instances)
L3 cache:                        195 MiB (2 instances)
NUMA node(s):                    1
NUMA node0 CPU(s):               0-111
Vulnerability Itlb multihit:     Not affected
Vulnerability L1tf:              Not affected
Vulnerability Mds:               Not affected
Vulnerability Meltdown:          Not affected
Vulnerability Spec store bypass: Vulnerable
Vulnerability Spectre v1:        Vulnerable: __user pointer sanitization and usercopy barriers only; no swapgs barriers
Vulnerability Spectre v2:        Vulnerable, IBPB: disabled, STIBP: disabled
Vulnerability Srbds:             Not affected
Vulnerability Tsx async abort:   Not affected

==============================
Versions of relevant libraries
==============================
[pip3] numpy==1.26.4
[pip3] nvidia-cublas-cu12==12.6.4.1
[pip3] nvidia-cuda-cupti-cu12==12.6.80
[pip3] nvidia-cuda-nvrtc-cu12==12.6.77
[pip3] nvidia-cuda-runtime-cu12==12.6.77
[pip3] nvidia-cudnn-cu12==9.5.1.17
[pip3] nvidia-cufft-cu12==11.3.0.4
[pip3] nvidia-cufile-cu12==1.11.1.6
[pip3] nvidia-curand-cu12==10.3.7.77
[pip3] nvidia-cusolver-cu12==11.7.1.2
[pip3] nvidia-cusparse-cu12==12.5.4.2
[pip3] nvidia-cusparselt-cu12==0.6.3
[pip3] nvidia-ml-py==12.570.86
[pip3] nvidia-nccl-cu12==2.26.2
[pip3] nvidia-nvjitlink-cu12==12.6.85
[pip3] nvidia-nvtx-cu12==12.6.77
[pip3] onnx==1.18.0
[pip3] onnxruntime-gpu==1.22.0
[pip3] pynvml==12.0.0
[pip3] pyzmq==26.3.0
[pip3] torch==2.7.0
[pip3] torchaudio==2.7.0
[pip3] torchvision==0.22.0
[pip3] transformers==4.51.3
[pip3] triton==3.3.0
[conda] numpy                     1.26.4                   pypi_0    pypi
[conda] nvidia-cublas-cu12        12.6.4.1                 pypi_0    pypi
[conda] nvidia-cuda-cupti-cu12    12.6.80                  pypi_0    pypi
[conda] nvidia-cuda-nvrtc-cu12    12.6.77                  pypi_0    pypi
[conda] nvidia-cuda-runtime-cu12  12.6.77                  pypi_0    pypi
[conda] nvidia-cudnn-cu12         9.5.1.17                 pypi_0    pypi
[conda] nvidia-cufft-cu12         11.3.0.4                 pypi_0    pypi
[conda] nvidia-cufile-cu12        1.11.1.6                 pypi_0    pypi
[conda] nvidia-curand-cu12        10.3.7.77                pypi_0    pypi
[conda] nvidia-cusolver-cu12      11.7.1.2                 pypi_0    pypi
[conda] nvidia-cusparse-cu12      12.5.4.2                 pypi_0    pypi
[conda] nvidia-cusparselt-cu12    0.6.3                    pypi_0    pypi
[conda] nvidia-ml-py              12.570.86                pypi_0    pypi
[conda] nvidia-nccl-cu12          2.26.2                   pypi_0    pypi
[conda] nvidia-nvjitlink-cu12     12.6.85                  pypi_0    pypi
[conda] nvidia-nvtx-cu12          12.6.77                  pypi_0    pypi
[conda] pynvml                    12.0.0                   pypi_0    pypi
[conda] pyzmq                     26.3.0                   pypi_0    pypi
[conda] torch                     2.7.0                    pypi_0    pypi
[conda] torchaudio                2.7.0                    pypi_0    pypi
[conda] torchvision               0.22.0                   pypi_0    pypi
[conda] transformers              4.51.3                   pypi_0    pypi
[conda] triton                    3.3.0                    pypi_0    pypi

==============================
         vLLM Info
==============================
ROCM Version                 : Could not collect
Neuron SDK Version           : N/A
vLLM Version                 : 0.9.1.dev66+gd637b9609 (git sha: d637b9609)
vLLM Build Flags:
  CUDA Archs: 8.9; ROCm: Disabled; Neuron: Disabled
GPU Topology:
        GPU0    GPU1    GPU2    GPU3    GPU4    GPU5    GPU6    GPU7    CPU Affinity    NUMA Affinity   GPU NUMA ID
GPU0     X      PIX     PIX     PIX     SYS     SYS     SYS     SYS     0-111   0               N/A
GPU1    PIX      X      PIX     PIX     SYS     SYS     SYS     SYS     0-111   0               N/A
GPU2    PIX     PIX      X      PIX     SYS     SYS     SYS     SYS     0-111   0               N/A
GPU3    PIX     PIX     PIX      X      SYS     SYS     SYS     SYS     0-111   0               N/A
GPU4    SYS     SYS     SYS     SYS      X      PIX     PIX     PIX     0-111   0               N/A
GPU5    SYS     SYS     SYS     SYS     PIX      X      PIX     PIX     0-111   0               N/A
GPU6    SYS     SYS     SYS     SYS     PIX     PIX      X      PIX     0-111   0               N/A
GPU7    SYS     SYS     SYS     SYS     PIX     PIX     PIX      X      0-111   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

==============================
     Environment Variables
==============================
NVIDIA_VISIBLE_DEVICES=all
CUBLAS_VERSION=12.8.3.14
NVIDIA_REQUIRE_CUDA=cuda>=9.0
CUDA_CACHE_DISABLE=1
TORCH_CUDA_ARCH_LIST=8.9
NCCL_VERSION=2.25.1
NVIDIA_DRIVER_CAPABILITIES=compute,utility,video
VLLM_TORCH_PROFILER_DIR=../vllm_profile
NVIDIA_PRODUCT_NAME=Triton Server
CUDA_VERSION=12.8.0.038
CUDA_VER=12.8.0.038
VLLM_ATTENTION_BACKEND=FLASHINFER
CUDA_VISIBLE_DEVICES=2
CUDA_VISIBLE_DEVICES=2
CUDNN_FRONTEND_VERSION=1.10.0
CUDNN_VERSION=9.7.1.26
NVIDIA_TRITON_SERVER_VERSION=25.02
LD_LIBRARY_PATH=/usr/lib/x86_64-linux-gnu/:/usr/local/tensorrt/lib/:/opt/tritonserver/backends/tensorrtllm:/usr/local/tensorrt/lib:/usr/local/cuda/compat/lib:/usr/local/nvidia/lib:/usr/local/nvidia/lib64
NVIDIA_BUILD_ID=144783146
CUDA_DRIVER_VERSION=570.86.10
NVIDIA_REQUIRE_JETPACK_HOST_MOUNTS=
NCCL_CUMEM_ENABLE=0
PYTORCH_NVML_BASED_CUDA_CHECK=1
TORCHINDUCTOR_COMPILE_THREADS=1
CUDA_MODULE_LOADING=LAZY

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]

cc @youkaichao this looks related to torch.compile?

[youkaichao]

pytorch folks looked into this, and they find that the profiler adds some overhead here. cc @zou3519

for the piecewise cudagraph, you can use full-graph mode right now, with an option from #16072 .

for the call_size functions you mentioned, it is technically possible to bypass that part and replay cudagraphs directly. I'm not sure if it is worthwhile though. QWen 0.5B is a really small model.

[Oldpan]

@youkaichao
Since I have a 4090 card with compute capability 8.9, I cannot use VLLM_FLASH_ATTN_VERSION=3, so I also cannot use full cuda graph. The call_size function was accidentally opened when I took the screenshot, it's meaningless(sorry~).

I'm not sure if it's due to the profiler overhead, but even when the profiler is not enabled, the GPU utilization is around 70%

This is a detailed screenshot showing that the function calls during this 2ms period are all built-in method getitem of dict object at 0x7f4db867b8c0

[youkaichao]

To measure the cost from Dynamo bytecode, you can measure the time elapsed from

vllm/vllm/compilation/decorators.py

Line 245 in cd8dfc6

model_output = self.forward(*args, **kwargs)

to

vllm/vllm/compilation/backends.py

Line 518 in cd8dfc6

return self.split_gm

NOTE: you need to change return self.split_gm to

def func(*args, **kwargs):
    # measure the time here!
    return self.split_gm(*args, **kwargs)

return func

it is known that pytorch 2.7 results in many getitem calls, but previously we think the time is negligible.

[Oldpan]

To measure the cost from Dynamo bytecode, you can measure the time elapsed from

vllm/vllm/compilation/decorators.py

Line 245 in cd8dfc6

model_output = self.forward(*args, **kwargs)
to

vllm/vllm/compilation/backends.py

Line 518 in cd8dfc6

return self.split_gm
NOTE: you need to change return self.split_gm to

def func(*args, **kwargs):
# measure the time here!
return self.split_gm(*args, **kwargs)

return func
it is known that pytorch 2.7 results in many getitem calls, but previously we think the time is negligible.

Thanks for the explanation.
Here is my modification of the code you mentioned:

if not self.compilation_config.use_cudagraph or \
    not self.compilation_config.cudagraph_copy_inputs:
    def func(*args, **kwargs):
        time_tag = time.time()
        print(f" self.split_gm(*args, **kwargs) : {time_tag} ")
        return self.split_gm(*args, **kwargs)

    return func
    
...
with self.dispatch_to_code(0):
    start_time = time.time()
    model_output = self.forward(*args, **kwargs)
    end_time = time.time()
    print(f"self.forward: {end_time - start_time:.5f} s")
    print(f" dispatch_to_code - self.forward : {end_time}")
    return model_output

Here are the benchmark logs:

...
self.forward: 0.00214 s
dispatch_to_code - self.forward : 1748059309.0563402
self.split_gm(*args, **kwargs) : 1748059309.0576348
self.forward: 0.00217 s
dispatch_to_code - self.forward : 1748059309.0597036
self.split_gm(*args, **kwargs) : 1748059309.061023
self.forward: 0.00219 s
dispatch_to_code - self.forward : 1748059309.0631084
self.split_gm(*args, **kwargs) : 1748059309.0644667
self.forward: 0.00218 s
dispatch_to_code - self.forward : 1748059309.06654
self.split_gm(*args, **kwargs) : 1748059309.0678449
self.forward: 0.00222 s
dispatch_to_code - self.forward : 1748059309.0699596
self.split_gm(*args, **kwargs) : 1748059309.0712934
self.forward: 0.00216 s
dispatch_to_code - self.forward : 1748059309.0733473
self.split_gm(*args, **kwargs) : 1748059309.0746834
self.forward: 0.00216 s
dispatch_to_code - self.forward : 1748059309.07674
self.split_gm(*args, **kwargs) : 1748059309.0780935
self.forward: 0.00217 s
dispatch_to_code - self.forward : 1748059309.0801616
self.split_gm(*args, **kwargs) : 1748059309.081491
self.forward: 0.00217 s
dispatch_to_code - self.forward : 1748059309.0835583
self.split_gm(*args, **kwargs) : 1748059309.0848727
self.forward: 0.00215 s
dispatch_to_code - self.forward : 1748059309.0869222
self.split_gm(*args, **kwargs) : 1748059309.0882735
self.forward: 0.00215 s
dispatch_to_code - self.forward : 1748059309.0903192
self.split_gm(*args, **kwargs) : 1748059309.0916495
...

[youkaichao]

print(f"self.forward: {end_time - start_time:.5f} s")

this is inaccurate. cuda kernels are async, and you just recorded the cpu kernel launch time.

time_tag - start_time would be the cost by Dynamo bytecode.

[Oldpan]

print(f"self.forward: {end_time - start_time:.5f} s")

this is inaccurate. cuda kernels are async, and you just recorded the cpu kernel launch time.

time_tag - start_time would be the cost by Dynamo bytecode.

I forgot to add CUDA synchronization...

Currently, time_tag - start_time measures the Dynamo bytecode execution time.

The 2ms timing—is this considered overhead?

While this overhead is negligible for large LLMs, it might be significant for this 0.5B model.

[youkaichao]

Currently, time_tag - start_time measures the Dynamo bytecode execution time.

The 2ms timing—is this considered overhead?

Profiling needs to be very careful here, print can also take micro-second level time.

[Oldpan]

Currently, time_tag - start_time measures the Dynamo bytecode execution time.
The 2ms timing—is this considered overhead?

Profiling needs to be very careful here, print can also take micro-second level time.

That makes sense. Are there any effective ways to measure overhead, such as NVTX? And would NSys be useful for analysis?

Using Python print statements in vllm isn't accurate enough.

[youkaichao]

maybe torch.cuda.nvtx.range_push and torch.cuda.nvtx.range_pop can help.

or you can skip the print in start_time, just store the time in a global variable, and read it when you calculate time_tag .

[anijain2305]

Is it possible to run the profiler without with_stack=True? The reason we are seeing dict getitem boxes in the traces is because with_stack is turned to True. Without with_stack, we should hopefully have more accurate latency number.

To answer the question whats going on in that time period - it is called the pre-graph bytecode, i.e. the python code before we call the compiled graph. In this pre-graph bytecode, we collect all the inputs of the compiled graph. This collection requires us to walk through the nn modules to collect the parameters and buffers. We already have optimizations to speedup this collection of inputs (like complex subexpression elimination etc). But it is still possible that for small models, this walking of nn modules is expensive compared to the total runtime.