Skip to content

[Bug]: Profiling on vLLM server hangs when --num-scheduler-steps > 1 #12032

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Open
1 task done
Jacob0226 opened this issue Jan 14, 2025 · 10 comments
Open
1 task done

[Bug]: Profiling on vLLM server hangs when --num-scheduler-steps > 1 #12032

Jacob0226 opened this issue Jan 14, 2025 · 10 comments
Labels
bug Something isn't working

Comments

@Jacob0226
Copy link

Your current environment

The output of `python collect_env.py` 
PyTorch version: 2.5.1+cu124
Is debug build: False
CUDA used to build PyTorch: 12.4
ROCM used to build PyTorch: N/A

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

Python version: 3.10.12 (main, Sep 11 2024, 15:47:36) [GCC 11.4.0] (64-bit runtime)
Python platform: Linux-6.8.0-51-generic-x86_64-with-glibc2.35
Is CUDA available: True
CUDA runtime version: 12.6.77
CUDA_MODULE_LOADING set to: LAZY
GPU models and configuration:
GPU 0: NVIDIA H100 80GB HBM3
GPU 1: NVIDIA H100 80GB HBM3
GPU 2: NVIDIA H100 80GB HBM3
GPU 3: NVIDIA H100 80GB HBM3
GPU 4: NVIDIA H100 80GB HBM3
GPU 5: NVIDIA H100 80GB HBM3
GPU 6: NVIDIA H100 80GB HBM3
GPU 7: NVIDIA H100 80GB HBM3

Nvidia driver version: 560.35.03
cuDNN version: Probably one of the following:
/usr/lib/x86_64-linux-gnu/libcudnn.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_adv.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_cnn.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_engines_precompiled.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_engines_runtime_compiled.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_graph.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_heuristic.so.9.5.0
/usr/lib/x86_64-linux-gnu/libcudnn_ops.so.9.5.0
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:                        52 bits physical, 57 bits virtual
Byte Order:                           Little Endian
CPU(s):                               384
On-line CPU(s) list:                  0-383
Vendor ID:                            AuthenticAMD
Model name:                           AMD EPYC 9654 96-Core Processor
CPU family:                           25
Model:                                17
Thread(s) per core:                   2
Core(s) per socket:                   96
Socket(s):                            2
Stepping:                             1
Frequency boost:                      enabled
CPU max MHz:                          3707.8120
CPU min MHz:                          1500.0000
BogoMIPS:                             4800.32
Flags:                                fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ht syscall nx mmxext fxsr_opt pdpe1gb rdtscp lm constant_tsc rep_good amd_lbr_v2 nopl nonstop_tsc cpuid extd_apicid aperfmperf rapl pni pclmulqdq monitor ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand lahf_lm cmp_legacy svm extapic cr8_legacy abm sse4a misalignsse 3dnowprefetch osvw ibs skinit wdt tce topoext perfctr_core perfctr_nb bpext perfctr_llc mwaitx cpb cat_l3 cdp_l3 hw_pstate ssbd mba perfmon_v2 ibrs ibpb stibp ibrs_enhanced vmmcall fsgsbase bmi1 avx2 smep bmi2 erms invpcid cqm rdt_a avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local user_shstk avx512_bf16 clzero irperf xsaveerptr rdpru wbnoinvd amd_ppin cppc arat npt lbrv svm_lock nrip_save tsc_scale vmcb_clean flushbyasid decodeassists pausefilter pfthreshold avic v_vmsave_vmload vgif x2avic v_spec_ctrl vnmi avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq la57 rdpid overflow_recov succor smca fsrm flush_l1d debug_swap
Virtualization:                       AMD-V
L1d cache:                            6 MiB (192 instances)
L1i cache:                            6 MiB (192 instances)
L2 cache:                             192 MiB (192 instances)
L3 cache:                             768 MiB (24 instances)
NUMA node(s):                         2
NUMA node0 CPU(s):                    0-95,192-287
NUMA node1 CPU(s):                    96-191,288-383
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 Reg file data sampling: Not affected
Vulnerability Retbleed:               Not affected
Vulnerability Spec rstack overflow:   Mitigation; Safe RET
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; STIBP always-on; RSB filling; PBRSB-eIBRS Not affected; BHI Not affected
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-cublas-cu12==12.4.5.8
[pip3] nvidia-cuda-cupti-cu12==12.4.127
[pip3] nvidia-cuda-nvrtc-cu12==12.4.127
[pip3] nvidia-cuda-runtime-cu12==12.4.127
[pip3] nvidia-cudnn-cu12==9.1.0.70
[pip3] nvidia-cudnn-frontend==1.7.0
[pip3] nvidia-cufft-cu12==11.2.1.3
[pip3] nvidia-curand-cu12==10.3.5.147
[pip3] nvidia-cusolver-cu12==11.6.1.9
[pip3] nvidia-cusparse-cu12==12.3.1.170
[pip3] nvidia-dali-cuda120==1.42.0
[pip3] nvidia-ml-py==12.560.30
[pip3] nvidia-modelopt==0.17.0
[pip3] nvidia-nccl-cu12==2.21.5
[pip3] nvidia-nvimgcodec-cu12==0.3.0.5
[pip3] nvidia-nvjitlink-cu12==12.4.127
[pip3] nvidia-nvtx-cu12==12.4.127
[pip3] nvidia-pyindex==1.0.9
[pip3] onnx==1.16.2
[pip3] optree==0.13.0
[pip3] pynvml==11.4.1
[pip3] pytorch-triton==3.0.0+dedb7bdf3
[pip3] pyzmq==26.2.0
[pip3] torch==2.5.1
[pip3] torch_tensorrt==2.5.0a0
[pip3] torchprofile==0.0.4
[pip3] torchvision==0.20.1
[pip3] transformers==4.48.0
[pip3] triton==3.1.0
[conda] Could not collect
ROCM Version: Could not collect
Neuron SDK Version: N/A
vLLM Version: 0.6.5
vLLM Build Flags:
CUDA Archs: 5.2 6.0 6.1 7.0 7.2 7.5 8.0 8.6 8.7 9.0+PTX; ROCm: Disabled; Neuron: Disabled
GPU Topology:
GPU0    GPU1    GPU2    GPU3    GPU4    GPU5    GPU6    GPU7    CPU Affinity    NUMA Affinity   GPU NUMA ID
GPU0     X      NV18    NV18    NV18    NV18    NV18    NV18    NV18    0-95,192-287    0               N/A
GPU1    NV18     X      NV18    NV18    NV18    NV18    NV18    NV18    0-95,192-287    0               N/A
GPU2    NV18    NV18     X      NV18    NV18    NV18    NV18    NV18    0-95,192-287    0               N/A
GPU3    NV18    NV18    NV18     X      NV18    NV18    NV18    NV18    0-95,192-287    0               N/A
GPU4    NV18    NV18    NV18    NV18     X      NV18    NV18    NV18    96-191,288-383  1               N/A
GPU5    NV18    NV18    NV18    NV18    NV18     X      NV18    NV18    96-191,288-383  1               N/A
GPU6    NV18    NV18    NV18    NV18    NV18    NV18     X      NV18    96-191,288-383  1               N/A
GPU7    NV18    NV18    NV18    NV18    NV18    NV18    NV18     X      96-191,288-383  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

NVIDIA_VISIBLE_DEVICES=all
CUBLAS_VERSION=12.6.3.3
NVIDIA_REQUIRE_CUDA=cuda>=9.0
CUDA_CACHE_DISABLE=1
TORCH_CUDA_ARCH_LIST=5.2 6.0 6.1 7.0 7.2 7.5 8.0 8.6 8.7 9.0+PTX
NCCL_VERSION=2.22.3
NVIDIA_DRIVER_CAPABILITIES=compute,utility,video
VLLM_TORCH_PROFILER_DIR=/home/jacchang/POC_RFP/vllm/DigitalOcean/prof/
NVIDIA_PRODUCT_NAME=PyTorch
CUDA_VERSION=12.6.2.004
PYTORCH_VERSION=2.5.0a0+e000cf0
PYTORCH_BUILD_NUMBER=0
CUDNN_FRONTEND_VERSION=1.7.0
CUDNN_VERSION=9.5.0.50
PYTORCH_HOME=/opt/pytorch/pytorch
LD_LIBRARY_PATH=/usr/local/lib/python3.10/dist-packages/cv2/../../lib64:/usr/local/cuda/compat/lib.real:/usr/local/lib/python3.10/dist-packages/torch/lib:/usr/local/lib/python3.10/dist-packages/torch_tensorrt/lib:/usr/local/cuda/compat/lib:/usr/local/nvidia/lib:/usr/local/nvidia/lib64
NVIDIA_BUILD_ID=114410972
CUDA_DRIVER_VERSION=560.35.03
PYTORCH_BUILD_VERSION=2.5.0a0+e000cf0
CUDA_HOME=/usr/local/cuda
CUDA_HOME=/usr/local/cuda
CUDA_MODULE_LOADING=LAZY
NVIDIA_REQUIRE_JETPACK_HOST_MOUNTS=
NVIDIA_PYTORCH_VERSION=24.10
TORCH_ALLOW_TF32_CUBLAS_OVERRIDE=1

Model Input Dumps

No response

🐛 Describe the bug

My vLLM version 0.6.5.
The vLLM server works well with any number of --num-scheduler-steps when running the script benchmark_serving.py. However, the script seems to hang when I use the --profile argument.

Testing with Different Values of --num-scheduler-steps:

  • --num-scheduler-steps=1: Works. It seems also work for other models.
  • --num-scheduler-steps=10: Causes the script to hang indefinitely.
  • --num-scheduler-steps=16: Works.

I am unsure why certain values of --num-scheduler-steps work in Llama-3.1-8B-Instruct model , while others cause the process to hang.

How to reproduce:

export VLLM_TORCH_PROFILER_DIR=/app
vllm serve /Path/to/meta-llama/Llama-3.1-8B-Instruct \
	--dtype float16 --swap-space 16 \
	--disable-log-requests --tensor-parallel-size 2 --distributed-executor-backend mp \
	--num-scheduler-steps 10 --gpu-memory-utilization 0.8 --max-model-len 8192 \
	--max-num-batched-tokens 65536 --enable-chunked-prefill=False 

python3 /vllm/benchmarks/benchmark_serving.py --host localhost --backend openai --port 8000 \
	--model /data/huggingface/hub/meta-llama/Llama-3.1-8B-Instruct --dataset-name random \
	--num-prompts 100 	--random-input-len 128 --random-output-len 128 --max-concurrency 64 \
	--percentile-metrics ttft,tpot,itl,e2el --profile

Logs from benchmark_serving.py:

python3 /app/vllm/benchmarks/benchmark_serving.py --host localhost --backend openai --port 8000 \
        --model /data/huggingface/hub/meta-llama/Llama-3.1-8B-Instruct --dataset-name random \
        --num-prompts 100       --random-input-len 2048 --random-output-len 128 --max-concurrency 64 \
        --percentile-metrics ttft,tpot,itl,e2el --profile
WARNING 01-14 09:29:47 rocm.py:34] `fork` method is not supported by ROCm. VLLM_WORKER_MULTIPROC_METHOD is overridden to `spawn` instead.
Namespace(backend='openai', base_url=None, host='localhost', port=8000, endpoint='/v1/completions', dataset=None, dataset_name='random', dataset_path=None, max_concurrency=64, model='/data/huggingface/hub/meta-llama/Llama-3.1-8B-Instruct', tokenizer=None, best_of=1, use_beam_search=False, num_prompts=100, logprobs=None, request_rate=inf, burstiness=1.0, seed=0, trust_remote_code=False, disable_tqdm=False, profile=True, save_result=False, metadata=None, result_dir=None, result_filename=None, ignore_eos=False, percentile_metrics='ttft,tpot,itl,e2el', metric_percentiles='99', goodput=None, sonnet_input_len=550, sonnet_output_len=150, sonnet_prefix_len=200, sharegpt_output_len=None, random_input_len=2048, random_output_len=128, random_range_ratio=1.0, random_prefix_len=0, hf_subset=None, hf_split=None, hf_output_len=None, tokenizer_mode='auto')
Starting initial single prompt test run...
Initial test run completed. Starting main benchmark run...
Starting profiler...
Traffic request rate: inf
Burstiness factor: 1.0 (Poisson process)
Maximum request concurrency: 64
  0%|                                                                                                                                                                                 | 0/100 [00:00<?, ?it/s]

Logs from server:

INFO 01-14 10:37:44 api_server.py:580] Using supplied chat template:
INFO 01-14 10:37:44 api_server.py:580] None
INFO 01-14 10:37:44 launcher.py:19] Available routes are:
INFO 01-14 10:37:44 launcher.py:27] Route: /openapi.json, Methods: HEAD, GET
INFO 01-14 10:37:44 launcher.py:27] Route: /docs, Methods: HEAD, GET
INFO 01-14 10:37:44 launcher.py:27] Route: /docs/oauth2-redirect, Methods: HEAD, GET
INFO 01-14 10:37:44 launcher.py:27] Route: /redoc, Methods: HEAD, GET
INFO 01-14 10:37:44 launcher.py:27] Route: /health, Methods: GET
INFO 01-14 10:37:44 launcher.py:27] Route: /tokenize, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /detokenize, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /v1/models, Methods: GET
INFO 01-14 10:37:44 launcher.py:27] Route: /version, Methods: GET
INFO 01-14 10:37:44 launcher.py:27] Route: /v1/chat/completions, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /v1/completions, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /v1/embeddings, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /score, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /v1/score, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /start_profile, Methods: POST
INFO 01-14 10:37:44 launcher.py:27] Route: /stop_profile, Methods: POST
INFO:     Started server process [180296]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
INFO:     127.0.0.1:40994 - "POST /v1/completions HTTP/1.1" 200 OK
INFO 01-14 10:38:04 metrics.py:467] Avg prompt throughput: 227.0 tokens/s, Avg generation throughput: 0.1 tokens/s, Running: 1 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 0.1%, CPU KV cache usage: 0.0%.
INFO 01-14 10:38:04 api_server.py:444] Starting profiler...
INFO 01-14 10:38:04 api_server.py:446] Profiler started.
INFO:     127.0.0.1:40996 - "POST /start_profile HTTP/1.1" 200 OK
INFO:     127.0.0.1:40998 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41008 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41014 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41016 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41032 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41034 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41048 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41056 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41058 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41068 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41084 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41090 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41102 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41118 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41134 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41136 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41150 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41162 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41174 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41180 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41184 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41194 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41206 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41210 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41216 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41230 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41238 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41250 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41266 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41272 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41286 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41292 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41296 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41298 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41304 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41306 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41318 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41330 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41332 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41346 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41352 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41354 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41356 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41368 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41376 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41378 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41382 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41384 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41392 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41406 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41416 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41428 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41438 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41454 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41468 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41482 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41496 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41502 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41514 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41516 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41530 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41544 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41556 - "POST /v1/completions HTTP/1.1" 200 OK
INFO:     127.0.0.1:41570 - "POST /v1/completions HTTP/1.1" 200 OK

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.
@Jacob0226 Jacob0226 added the bug Something isn't working label Jan 14, 2025
@Jacob0226
Copy link
Author

Hello, I would like to know if it is a well-known issue. It's okay if this cannot be fixed soon. I just want to know if I run with wrong settings, thanks.

@Jacob0226 Jacob0226 changed the title [Bug]: Profiling on vLLM server hangs when --num-scheduler-steps > 1 [Bug]: Profiling on vLLM server hangs when --num-scheduler-steps > 1 and tensor parallel > 1 Jan 22, 2025
@Jacob0226 Jacob0226 changed the title [Bug]: Profiling on vLLM server hangs when --num-scheduler-steps > 1 and tensor parallel > 1 [Bug]: Profiling on vLLM server hangs when --num-scheduler-steps > 1 Jan 22, 2025
@ren2504413601
Copy link

ren2504413601 commented Mar 22, 2025 •
edited
Loading

I had the same problem in the ray backend and multi-sep > 1 condition, and the service log printed No available block found in 60 second in shm.

I tried to open the ray dashboard to observe and found that the existing ray execute_model work is stuck in TP broadcast_tensordata. So if you post start_profile or stop_profile it will be hanged.

The details log is similar to this comment
[Bug]: No available block found in 60 second in shm

In my opinion, Before we post start_profile and stop_profile, we should stop the stuck ray execute_model work using the method
stop_remote_worker_execution_loop.

The same work had been used in llm_engine (details can be found in llm_engine.py#L1508 but I think it did not work in post start_profile or stop_profile method.

A possible solution might be like this:

def start_profile(self, level=None) -> None:

        if type(self.engine.model_executor) == GPUExecutor:
            self.engine.model_executor.start_profile()
        else:
            self.engine.model_executor.stop_remote_worker_execution_loop() # added line
            self.engine.model_executor._run_workers("start_profile")


    def stop_profile(self) -> None:
        if type(self.engine.model_executor) == GPUExecutor:
            self.engine.model_executor.stop_profile()
        else:
            self.engine.model_executor.stop_remote_worker_execution_loop() # added line
            self.engine.model_executor._run_workers("stop_profile")

I tried to modify the implementation in the llm_engine file, and found it works.

@Jacob0226 @andrew @tmm1 @markmc @HKUST

@ren2504413601
Copy link

I had the same problem in the ray backend and multi-sep > 1 condition, and the service log printed No available block found in 60 second in shm.

I tried to open the ray dashboard to observe and found that the existing ray execute_model work is stuck in TP broadcast_tensordata. So if you post start_profile or stop_profile it will be hanged.

The details log is similar to this comment [Bug]: No available block found in 60 second in shm

In my opinion, Before we post start_profile and stop_profile, we should stop the stuck ray execute_model work using the method stop_remote_worker_execution_loop.

The same work had been used in llm_engine (details can be found in llm_engine.py#L1508 but I think it did not work in post start_profile or stop_profile method.

A possible solution might be like this:

def start_profile(self, level=None) -> None:

        if type(self.engine.model_executor) == GPUExecutor:
            self.engine.model_executor.start_profile()
        else:
            self.engine.model_executor.stop_remote_worker_execution_loop() # added line
            self.engine.model_executor._run_workers("start_profile")


    def stop_profile(self) -> None:
        if type(self.engine.model_executor) == GPUExecutor:
            self.engine.model_executor.stop_profile()
        else:
            self.engine.model_executor.stop_remote_worker_execution_loop() # added line
            self.engine.model_executor._run_workers("stop_profile")

I tried to modify the implementation in the llm_engine file, and found it works.

@Jacob0226 @andrew @tmm1 @markmc @HKUST

@ren2504413601 ren2504413601 mentioned this issue Mar 22, 2025
Open
@ren2504413601
Copy link

ren2504413601 commented Mar 22, 2025 •
edited
Loading

I had the same problem in the ray backend and multi-sep > 1 condition, and the service log printed No available block found in 60 second in shm.
I tried to open the ray dashboard to observe and found that the existing ray execute_model work is stuck in TP broadcast_tensordata. So if you post start_profile or stop_profile it will be hanged.
The details log is similar to this comment [Bug]: No available block found in 60 second in shm
In my opinion, Before we post start_profile and stop_profile, we should stop the stuck ray execute_model work using the method stop_remote_worker_execution_loop.
The same work had been used in llm_engine (details can be found in llm_engine.py#L1508 but I think it did not work in post start_profile or stop_profile method.
A possible solution might be like this:

def start_profile(self, level=None) -> None:

        if type(self.engine.model_executor) == GPUExecutor:
            self.engine.model_executor.start_profile()
        else:
            self.engine.model_executor.stop_remote_worker_execution_loop() # added line
            self.engine.model_executor._run_workers("start_profile")


    def stop_profile(self) -> None:
        if type(self.engine.model_executor) == GPUExecutor:
            self.engine.model_executor.stop_profile()
        else:
            self.engine.model_executor.stop_remote_worker_execution_loop() # added line
            self.engine.model_executor._run_workers("stop_profile")

I tried to modify the implementation in the llm_engine file, and found it works.
@Jacob0226 @andrew @tmm1 @markmc @HKUST

@youkaichao @woosuk Kwon @DarkLight1337 @mgoin

@ren2504413601 ren2504413601 mentioned this issue Mar 22, 2025
Open
18 tasks
@youkaichao
Copy link
Member

@njhill knows more about this. the control plane in v0 is quite complicated.

btw we are moving towards v1 code, and this part of code can be less maintained. can you try the latest code?

@ren2504413601
Copy link

ren2504413601 commented Mar 22, 2025 •
edited
Loading

@njhill knows more about this. the control plane in v0 is quite complicated.

btw we are moving towards v1 code, and this part of code can be less maintained. can you try the latest code?

@youkaichao Do we have a solution for v0, a lot of our work is adapted to v0. Our version is v0.6.3.post1

@youkaichao @njhill Can you help me figure it out.

@njhill
Copy link
Member

njhill commented Mar 26, 2025

@ren2504413601 I think the solution you found is the right one. It looks like in the latest code, stop/start_profile use collective_rpc and it would make most sense to add the stop_remote_worker_execution_loop() to that method instead.

But it sounds like you're hacking an older fork here.

As @youkaichao says, all of this is on the v0 path anyhow and isn't applicable when in v1 mode.

@ren2504413601
Copy link

@ren2504413601 I think the solution you found is the right one. It looks like in the latest code, stop/start_profile use collective_rpc and it would make most sense to add the stop_remote_worker_execution_loop() to that method instead.

But it sounds like you're hacking an older fork here.

As @youkaichao says, all of this is on the v0 path anyhow and isn't applicable when in v1 mode.

Thanks for your reply. I test more case and found more interesting results, you can see this issue: #15543 @njhill @youkaichao
Do you think it is a better solution in muilt-step condition.

@njhill
Copy link
Member

njhill commented Mar 27, 2025

@ren2504413601 the v0 code is so convoluted, it's really hard to follow. It sounds like the other bug you're describing is unrelated to calling utility methods like start profile, and it's more that the worker loop is not getting paused in the multi-step case even when there are no requests in progress, is that correct?

I also realized that the solution suggested above will break v0 in some specific cases, in particular when frontend multiprocessing is disabled and/or pipeline parallel is used. This is because of how the sync collective_rpc method is also used in the async implementations of the util methods like start_profile. So it would still need a bit more work to work with those cases too.

@njhill njhill mentioned this issue Mar 27, 2025
Merged
@ren2504413601
Copy link

@ren2504413601 the v0 code is so convoluted, it's really hard to follow. It sounds like the other bug you're describing is unrelated to calling utility methods like start profile, and it's more that the worker loop is not getting paused in the multi-step case even when there are no requests in progress, is that correct?

I also realized that the solution suggested above will break v0 in some specific cases, in particular when frontend multiprocessing is disabled and/or pipeline parallel is used. This is because of how the sync collective_rpc method is also used in the async implementations of the util methods like start_profile. So it would still need a bit more work to work with those cases too.

Yes, it depends on the max-tokens value of request. If max-tokens % num-schedule-step !=0 it happens. So maybe there exists an another bug. stop_remote_worker_loop is just avoid this error.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@njhill @youkaichao @ren2504413601 @Jacob0226