[Bug]: nixl connector PD disagg stuck at INFO logging level

[herotai214]

Your current environment

/

🐛 Describe the bug

cc EPD authors @fake0fan @knlnguyen1802 @herotai214 @khuonglmhw
cc @NickLucche

Following #29248 having issue with the EPD disagg feature, I found that simply running PD disagg with nixl connector with export VLLM_LOGGING_LEVEL=INFO would also stuck at the decode instance when streaming for the 1st request.

export VLLM_LOGGING_LEVEL=DEBUG avoids the issue and works fine, but I think there are still some defects that worth paying attention...

My starting script for PD disagg with nixl connector using /tests/v1/kv_connector/nixl_integration/toy_proxy_server.py:

#!/bin/bash
set -xe

echo "🚧🚧 Running NIXL CONNECTOR!!!!!!!! 🚧🚧"

MODEL_NAME=<YOUR_MODEL_NAME_HERE>
LOG_PATH=<YOUR_LOG_PATH_HERE>
mkdir -p $LOG_PATH

# Cleanup function
cleanup() {
    echo "Stopping everything…"
    trap - INT TERM USR1   # prevent re-entrancy
    
    # Kill all tracked PIDs
    for pid in "${PIDS[@]}"; do
        if kill -0 "$pid" 2>/dev/null; then
            echo "Killing process $pid"
            kill "$pid" 2>/dev/null
        fi
    done
    
    # Wait a moment for graceful shutdown
    sleep 2
    
    # Force kill any remaining processes
    for pid in "${PIDS[@]}"; do
        if kill -0 "$pid" 2>/dev/null; then
            echo "Force killing process $pid"
            kill -9 "$pid" 2>/dev/null
        fi
    done
    
    # Kill the entire process group as backup
    kill -- -$$ 2>/dev/null
    
    echo "All processes stopped."
    exit 0
}

trap cleanup INT
trap cleanup USR1
trap cleanup TERM

export VLLM_HOST_IP=$(hostname -I | awk '{print $1}')

# a function that waits vLLM server to start
wait_for_server() {
  local port=$1
  timeout 12000 bash -c "
    until curl -s localhost:${port}/v1/chat/completions > /dev/null; do
      sleep 1
    done" && return 0 || return 1
}

### NIXL
A=2
B=3
C=6661
D=6662
PORT=9775

CUDA_VISIBLE_DEVICES=$A VLLM_NIXL_SIDE_CHANNEL_PORT=5559 vllm serve $MODEL_NAME \
    --port $C \
    --enforce-eager \
    --gpu-memory-utilization 0.8 \
    --trust-remote-code \
    --max-num-batched-tokens 4096 \
    --kv-transfer-config \
    '{"kv_connector":"NixlConnector","kv_role":"kv_producer","kv_rank":0,"kv_parallel_size":2}' \
    > $LOG_PATH/prefiller_$(date +"%Y%m%d_%H%M%S").log 2>&1 &

# decoding instance, which is the KV consumer
CUDA_VISIBLE_DEVICES=$B VLLM_NIXL_SIDE_CHANNEL_PORT=6000 vllm serve $MODEL_NAME \
    --port $D \
    --enforce-eager \
    --gpu-memory-utilization 0.8 \
    --trust-remote-code \
    --max-num-batched-tokens 4096 \
    --kv-transfer-config \
    '{"kv_connector":"NixlConnector","kv_role":"kv_consumer","kv_rank":1,"kv_parallel_size":2}' \
    > $LOG_PATH/decoder_$(date +"%Y%m%d_%H%M%S").log 2>&1 &

# wait until prefill and decode instances are ready
wait_for_server $C
wait_for_server $D

# toy server
python3 /workspace/hero/hero_EPD_1017/vllm/tests/v1/kv_connector/nixl_integration/toy_proxy_server.py  \
    --prefiller-ports $C   \
    --decoder-ports $D   \
    --port $PORT \
    > $LOG_PATH/proxy_$(date +"%Y%m%d_%H%M%S").log 2>&1 &

sleep 1

## Vision benchmark
wait_for_server $PORT

vllm bench serve \
  --backend openai-chat \
  --model $MODEL_NAME \
  --endpoint /v1/chat/completions \
  --dataset-name hf \
  --dataset-path lmarena-ai/VisionArena-Chat \
  --hf-split train \
  --num-prompts 100 \
  --seed 40 \
  --save-result \
  --save-detailed \
  --result-dir $LOG_PATH \
  --result-filename pddisaggnixl_$(date +"%Y%m%d_%H%M%S").json \
  --port $PORT


# cleanup
echo "cleanup..."
cleanup

Related logs:

Details

At INFO level:

prefill instance

INFO 11-25 02:39:04 [scheduler.py:207] Chunked prefill is enabled with max_num_batched_tokens=2048.
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:04 [api_server.py:2056] vLLM API server version 0.11.2.dev157+ge9af6ba62
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:04 [utils.py:253] non-default args: {'model_tag': '/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', 'port': 6661, 'model': '/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', 'trust_remote_code': True, 'enforce_eager': True, 'gpu_memory_utilization': 0.8, 'max_num_batched_tokens': 4096, 'kv_transfer_config': KVTransferConfig(kv_connector='NixlConnector', engine_id='966415c7-c559-48e7-a664-c287e16856be', kv_buffer_device='cuda', kv_buffer_size=1000000000.0, kv_role='kv_producer', kv_rank=0, kv_parallel_size=2, kv_ip='127.0.0.1', kv_port=14579, kv_connector_extra_config={}, kv_connector_module_path=None, enable_permute_local_kv=False)}
�[0;36m(APIServer pid=248)�[0;0m The argument `trust_remote_code` is to be used with Auto classes. It has no effect here and is ignored.
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:04 [model.py:630] Resolved architecture: Qwen2_5_VLForConditionalGeneration
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:04 [model.py:1745] Using max model len 128000
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:06 [scheduler.py:207] Chunked prefill is enabled with max_num_batched_tokens=4096.
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:06 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(APIServer pid=248)�[0;0m WARNING 11-25 02:39:06 [vllm.py:729] Turning off hybrid kv cache manager because `--kv-transfer-config` is set. This will reduce the performance of vLLM on LLMs with sliding window attention or Mamba attention. If you are a developer of kv connector, please consider supporting hybrid kv cache manager for your connector by making sure your connector is a subclass of `SupportsHMA` defined in kv_connector/v1/base.py.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:16 [core.py:93] Initializing a V1 LLM engine (v0.11.2.dev157+ge9af6ba62) with config: model='/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', speculative_config=None, tokenizer='/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.bfloat16, max_seq_len=128000, download_dir=None, load_format=auto, tensor_parallel_size=1, pipeline_parallel_size=1, data_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto, device_config=cuda, structured_outputs_config=StructuredOutputsConfig(backend='auto', disable_fallback=False, disable_any_whitespace=False, disable_additional_properties=False, reasoning_parser='', reasoning_parser_plugin='', enable_in_reasoning=False), observability_config=ObservabilityConfig(show_hidden_metrics_for_version=None, otlp_traces_endpoint=None, collect_detailed_traces=None), seed=0, served_model_name=/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct, enable_prefix_caching=True, enable_chunked_prefill=True, pooler_config=None, compilation_config={'level': None, 'mode': <CompilationMode.NONE: 0>, 'debug_dump_path': None, 'cache_dir': '', 'compile_cache_save_format': 'binary', 'backend': 'inductor', 'custom_ops': ['all'], 'splitting_ops': None, 'compile_mm_encoder': False, 'use_inductor': None, 'compile_sizes': [], 'inductor_compile_config': {'enable_auto_functionalized_v2': False, 'combo_kernels': True, 'benchmark_combo_kernel': True}, 'inductor_passes': {}, 'cudagraph_mode': <CUDAGraphMode.NONE: 0>, 'cudagraph_num_of_warmups': 0, 'cudagraph_capture_sizes': [], 'cudagraph_copy_inputs': False, 'cudagraph_specialize_lora': True, 'use_inductor_graph_partition': False, 'pass_config': {}, 'max_cudagraph_capture_size': 0, 'local_cache_dir': None}
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:20 [parallel_state.py:1217] world_size=1 rank=0 local_rank=0 distributed_init_method=tcp://10.90.67.85:54579 backend=nccl
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:20 [parallel_state.py:1425] rank 0 in world size 1 is assigned as DP rank 0, PP rank 0, PCP rank 0, TP rank 0, EP rank 0
�[0;36m(EngineCore_DP0 pid=594)�[0;0m The image processor of type `Qwen2VLImageProcessor` is now loaded as a fast processor by default, even if the model checkpoint was saved with a slow processor. This is a breaking change and may produce slightly different outputs. To continue using the slow processor, instantiate this class with `use_fast=False`. Note that this behavior will be extended to all models in a future release.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:25 [gpu_model_runner.py:3249] Starting to load model /mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct...
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:25 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:25 [cuda.py:415] Valid backends: ['FLASH_ATTN', 'FLASHINFER', 'TRITON_ATTN', 'FLEX_ATTENTION']
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:25 [cuda.py:424] Using FLASH_ATTN backend.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 
Loading safetensors checkpoint shards:   0% Completed | 0/2 [00:00<?, ?it/s]
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 
Loading safetensors checkpoint shards:  50% Completed | 1/2 [00:00<00:00,  1.51it/s]
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 
Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:01<00:00,  1.55it/s]
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 
Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:01<00:00,  1.55it/s]
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:27 [default_loader.py:308] Loading weights took 1.33 seconds
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:27 [gpu_model_runner.py:3331] Model loading took 7.1556 GiB memory and 1.685600 seconds
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:28 [gpu_model_runner.py:4083] Encoder cache will be initialized with a budget of 114688 tokens, and profiled with 1 video items of the maximum feature size.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [gpu_worker.py:348] Available KV cache memory: 42.95 GiB
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [kv_cache_utils.py:1234] GPU KV cache size: 1,251,120 tokens
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [kv_cache_utils.py:1239] Maximum concurrency for 128,000 tokens per request: 9.77x
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [nixl_connector.py:73] NIXL is available
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [factory.py:64] Creating v1 connector with name: NixlConnector and engine_id: 966415c7-c559-48e7-a664-c287e16856be
�[0;36m(EngineCore_DP0 pid=594)�[0;0m WARNING 11-25 02:39:44 [base.py:163] Initializing KVConnectorBase_V1. This API is experimental and subject to change in the future as we iterate the design.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [nixl_connector.py:799] Initializing NIXL wrapper
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:44 [nixl_connector.py:800] Initializing NIXL worker 966415c7-c559-48e7-a664-c287e16856be
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 2025-11-25 02:39:46 NIXL INFO    _api.py:361 Backend UCX was instantiated
�[0;36m(EngineCore_DP0 pid=594)�[0;0m 2025-11-25 02:39:46 NIXL INFO    _api.py:251 Initialized NIXL agent: 72fca207-f8c6-4554-9663-6b9c3f44660b
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:46 [cuda.py:415] Valid backends: ['FLASH_ATTN', 'FLASHINFER', 'TRITON_ATTN', 'FLEX_ATTENTION']
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:46 [cuda.py:424] Using FLASH_ATTN backend.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:46 [nixl_connector.py:199] NixlConnector setting KV cache layout to HND for better xfer performance.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:47 [nixl_connector.py:1154] Registering KV_Caches. use_mla: False, kv_buffer_device: cuda, use_host_buffer: False
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:49 [core.py:253] init engine (profile, create kv cache, warmup model) took 21.55 seconds
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:49 [factory.py:64] Creating v1 connector with name: NixlConnector and engine_id: 966415c7-c559-48e7-a664-c287e16856be
�[0;36m(EngineCore_DP0 pid=594)�[0;0m WARNING 11-25 02:39:49 [base.py:163] Initializing KVConnectorBase_V1. This API is experimental and subject to change in the future as we iterate the design.
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:49 [nixl_connector.py:364] Initializing NIXL Scheduler 966415c7-c559-48e7-a664-c287e16856be
�[0;36m(EngineCore_DP0 pid=594)�[0;0m INFO 11-25 02:39:50 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [nixl_connector.py:73] NIXL is available
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [api_server.py:1804] Supported tasks: ['generate']
�[0;36m(APIServer pid=248)�[0;0m WARNING 11-25 02:39:50 [model.py:1568] Default sampling parameters have been overridden by the model's Hugging Face generation config recommended from the model creator. If this is not intended, please relaunch vLLM instance with `--generation-config vllm`.
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [serving_responses.py:154] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [serving_chat.py:131] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [serving_completion.py:73] Using default completion sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [serving_chat.py:131] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [api_server.py:2134] Starting vLLM API server 0 on http://0.0.0.0:6661
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:38] Available routes are:
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /openapi.json, Methods: HEAD, GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /docs, Methods: HEAD, GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /docs/oauth2-redirect, Methods: HEAD, GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /redoc, Methods: HEAD, GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /health, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /load, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /pause, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /resume, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /is_paused, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /tokenize, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /detokenize, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/models, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /version, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/responses, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/responses/{response_id}, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/responses/{response_id}/cancel, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/messages, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/chat/completions, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/completions, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/embeddings, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /pooling, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /classify, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /score, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/score, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/audio/transcriptions, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/audio/translations, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /rerank, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/rerank, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v2/rerank, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /scale_elastic_ep, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /is_scaling_elastic_ep, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /inference/v1/generate, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /ping, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /ping, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /invocations, Methods: POST
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /metrics, Methods: GET
�[0;36m(APIServer pid=248)�[0;0m INFO:     Started server process [248]
�[0;36m(APIServer pid=248)�[0;0m INFO:     Waiting for application startup.
�[0;36m(APIServer pid=248)�[0;0m INFO:     Application startup complete.
�[0;36m(APIServer pid=248)�[0;0m INFO:     127.0.0.1:40172 - "GET /v1/chat/completions HTTP/1.1" 405 Method Not Allowed
�[0;36m(APIServer pid=248)�[0;0m The image processor of type `Qwen2VLImageProcessor` is now loaded as a fast processor by default, even if the model checkpoint was saved with a slow processor. This is a breaking change and may produce slightly different outputs. To continue using the slow processor, instantiate this class with `use_fast=False`. Note that this behavior will be extended to all models in a future release.
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:40:45 [chat_utils.py:574] Detected the chat template content format to be 'openai'. You can set `--chat-template-content-format` to override this.
�[0;36m(APIServer pid=248)�[0;0m INFO:     127.0.0.1:45690 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:40:50 [loggers.py:236] Engine 000: Avg prompt throughput: 26.2 tokens/s, Avg generation throughput: 0.1 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%, External prefix cache hit rate: 0.0%, MM cache hit rate: 0.0%
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:41:00 [loggers.py:236] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%, External prefix cache hit rate: 0.0%, MM cache hit rate: 0.0%
�[0;36m(APIServer pid=248)�[0;0m INFO 11-25 02:46:09 [launcher.py:110] Shutting down FastAPI HTTP server.

decode instance

INFO 11-25 02:39:04 [scheduler.py:207] Chunked prefill is enabled with max_num_batched_tokens=2048.
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:04 [api_server.py:2056] vLLM API server version 0.11.2.dev157+ge9af6ba62
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:04 [utils.py:253] non-default args: {'model_tag': '/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', 'port': 6662, 'model': '/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', 'trust_remote_code': True, 'enforce_eager': True, 'gpu_memory_utilization': 0.8, 'max_num_batched_tokens': 4096, 'kv_transfer_config': KVTransferConfig(kv_connector='NixlConnector', engine_id='027a18cd-ad69-4b86-92cb-2fd78674bced', kv_buffer_device='cuda', kv_buffer_size=1000000000.0, kv_role='kv_consumer', kv_rank=1, kv_parallel_size=2, kv_ip='127.0.0.1', kv_port=14579, kv_connector_extra_config={}, kv_connector_module_path=None, enable_permute_local_kv=False)}
�[0;36m(APIServer pid=249)�[0;0m The argument `trust_remote_code` is to be used with Auto classes. It has no effect here and is ignored.
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:04 [model.py:630] Resolved architecture: Qwen2_5_VLForConditionalGeneration
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:04 [model.py:1745] Using max model len 128000
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:06 [scheduler.py:207] Chunked prefill is enabled with max_num_batched_tokens=4096.
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:06 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(APIServer pid=249)�[0;0m WARNING 11-25 02:39:06 [vllm.py:729] Turning off hybrid kv cache manager because `--kv-transfer-config` is set. This will reduce the performance of vLLM on LLMs with sliding window attention or Mamba attention. If you are a developer of kv connector, please consider supporting hybrid kv cache manager for your connector by making sure your connector is a subclass of `SupportsHMA` defined in kv_connector/v1/base.py.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:16 [core.py:93] Initializing a V1 LLM engine (v0.11.2.dev157+ge9af6ba62) with config: model='/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', speculative_config=None, tokenizer='/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.bfloat16, max_seq_len=128000, download_dir=None, load_format=auto, tensor_parallel_size=1, pipeline_parallel_size=1, data_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto, device_config=cuda, structured_outputs_config=StructuredOutputsConfig(backend='auto', disable_fallback=False, disable_any_whitespace=False, disable_additional_properties=False, reasoning_parser='', reasoning_parser_plugin='', enable_in_reasoning=False), observability_config=ObservabilityConfig(show_hidden_metrics_for_version=None, otlp_traces_endpoint=None, collect_detailed_traces=None), seed=0, served_model_name=/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct, enable_prefix_caching=True, enable_chunked_prefill=True, pooler_config=None, compilation_config={'level': None, 'mode': <CompilationMode.NONE: 0>, 'debug_dump_path': None, 'cache_dir': '', 'compile_cache_save_format': 'binary', 'backend': 'inductor', 'custom_ops': ['all'], 'splitting_ops': None, 'compile_mm_encoder': False, 'use_inductor': None, 'compile_sizes': [], 'inductor_compile_config': {'enable_auto_functionalized_v2': False, 'combo_kernels': True, 'benchmark_combo_kernel': True}, 'inductor_passes': {}, 'cudagraph_mode': <CUDAGraphMode.NONE: 0>, 'cudagraph_num_of_warmups': 0, 'cudagraph_capture_sizes': [], 'cudagraph_copy_inputs': False, 'cudagraph_specialize_lora': True, 'use_inductor_graph_partition': False, 'pass_config': {}, 'max_cudagraph_capture_size': 0, 'local_cache_dir': None}
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:20 [parallel_state.py:1217] world_size=1 rank=0 local_rank=0 distributed_init_method=tcp://10.90.67.85:33843 backend=nccl
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:20 [parallel_state.py:1425] rank 0 in world size 1 is assigned as DP rank 0, PP rank 0, PCP rank 0, TP rank 0, EP rank 0
�[0;36m(EngineCore_DP0 pid=590)�[0;0m The image processor of type `Qwen2VLImageProcessor` is now loaded as a fast processor by default, even if the model checkpoint was saved with a slow processor. This is a breaking change and may produce slightly different outputs. To continue using the slow processor, instantiate this class with `use_fast=False`. Note that this behavior will be extended to all models in a future release.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:25 [gpu_model_runner.py:3249] Starting to load model /mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct...
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:25 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:25 [cuda.py:415] Valid backends: ['FLASH_ATTN', 'FLASHINFER', 'TRITON_ATTN', 'FLEX_ATTENTION']
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:25 [cuda.py:424] Using FLASH_ATTN backend.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 
Loading safetensors checkpoint shards:   0% Completed | 0/2 [00:00<?, ?it/s]
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 
Loading safetensors checkpoint shards:  50% Completed | 1/2 [00:00<00:00,  1.53it/s]
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 
Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:01<00:00,  1.59it/s]
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 
Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:01<00:00,  1.58it/s]
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:27 [default_loader.py:308] Loading weights took 1.30 seconds
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:27 [gpu_model_runner.py:3331] Model loading took 7.1556 GiB memory and 1.701283 seconds
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:28 [gpu_model_runner.py:4083] Encoder cache will be initialized with a budget of 114688 tokens, and profiled with 1 video items of the maximum feature size.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [gpu_worker.py:348] Available KV cache memory: 42.95 GiB
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [kv_cache_utils.py:1234] GPU KV cache size: 1,251,120 tokens
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [kv_cache_utils.py:1239] Maximum concurrency for 128,000 tokens per request: 9.77x
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [nixl_connector.py:73] NIXL is available
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [factory.py:64] Creating v1 connector with name: NixlConnector and engine_id: 027a18cd-ad69-4b86-92cb-2fd78674bced
�[0;36m(EngineCore_DP0 pid=590)�[0;0m WARNING 11-25 02:39:44 [base.py:163] Initializing KVConnectorBase_V1. This API is experimental and subject to change in the future as we iterate the design.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [nixl_connector.py:799] Initializing NIXL wrapper
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:44 [nixl_connector.py:800] Initializing NIXL worker 027a18cd-ad69-4b86-92cb-2fd78674bced
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 2025-11-25 02:39:46 NIXL INFO    _api.py:361 Backend UCX was instantiated
�[0;36m(EngineCore_DP0 pid=590)�[0;0m 2025-11-25 02:39:46 NIXL INFO    _api.py:251 Initialized NIXL agent: e04da5c5-8fb1-476f-a589-d9e9fa2231d8
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:46 [cuda.py:415] Valid backends: ['FLASH_ATTN', 'FLASHINFER', 'TRITON_ATTN', 'FLEX_ATTENTION']
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:46 [cuda.py:424] Using FLASH_ATTN backend.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:46 [nixl_connector.py:199] NixlConnector setting KV cache layout to HND for better xfer performance.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:47 [nixl_connector.py:1154] Registering KV_Caches. use_mla: False, kv_buffer_device: cuda, use_host_buffer: False
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:49 [core.py:253] init engine (profile, create kv cache, warmup model) took 21.62 seconds
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:49 [factory.py:64] Creating v1 connector with name: NixlConnector and engine_id: 027a18cd-ad69-4b86-92cb-2fd78674bced
�[0;36m(EngineCore_DP0 pid=590)�[0;0m WARNING 11-25 02:39:49 [base.py:163] Initializing KVConnectorBase_V1. This API is experimental and subject to change in the future as we iterate the design.
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:49 [nixl_connector.py:364] Initializing NIXL Scheduler 027a18cd-ad69-4b86-92cb-2fd78674bced
�[0;36m(EngineCore_DP0 pid=590)�[0;0m INFO 11-25 02:39:50 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [nixl_connector.py:73] NIXL is available
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [api_server.py:1804] Supported tasks: ['generate']
�[0;36m(APIServer pid=249)�[0;0m WARNING 11-25 02:39:50 [model.py:1568] Default sampling parameters have been overridden by the model's Hugging Face generation config recommended from the model creator. If this is not intended, please relaunch vLLM instance with `--generation-config vllm`.
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [serving_responses.py:154] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [serving_chat.py:131] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [serving_completion.py:73] Using default completion sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [serving_chat.py:131] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [api_server.py:2134] Starting vLLM API server 0 on http://0.0.0.0:6662
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:38] Available routes are:
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /openapi.json, Methods: HEAD, GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /docs, Methods: HEAD, GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /docs/oauth2-redirect, Methods: HEAD, GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /redoc, Methods: HEAD, GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /health, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /load, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /pause, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /resume, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /is_paused, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /tokenize, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /detokenize, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/models, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /version, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/responses, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/responses/{response_id}, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/responses/{response_id}/cancel, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/messages, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/chat/completions, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/completions, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/embeddings, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /pooling, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /classify, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /score, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/score, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/audio/transcriptions, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/audio/translations, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /rerank, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v1/rerank, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /v2/rerank, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /scale_elastic_ep, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /is_scaling_elastic_ep, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /inference/v1/generate, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /ping, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /ping, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /invocations, Methods: POST
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:39:50 [launcher.py:46] Route: /metrics, Methods: GET
�[0;36m(APIServer pid=249)�[0;0m INFO:     Started server process [249]
�[0;36m(APIServer pid=249)�[0;0m INFO:     Waiting for application startup.
�[0;36m(APIServer pid=249)�[0;0m INFO:     Application startup complete.
�[0;36m(APIServer pid=249)�[0;0m INFO:     127.0.0.1:43240 - "GET /v1/chat/completions HTTP/1.1" 405 Method Not Allowed
�[0;36m(APIServer pid=249)�[0;0m The image processor of type `Qwen2VLImageProcessor` is now loaded as a fast processor by default, even if the model checkpoint was saved with a slow processor. This is a breaking change and may produce slightly different outputs. To continue using the slow processor, instantiate this class with `use_fast=False`. Note that this behavior will be extended to all models in a future release.
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:40:48 [chat_utils.py:574] Detected the chat template content format to be 'openai'. You can set `--chat-template-content-format` to override this.
�[0;36m(APIServer pid=249)�[0;0m INFO:     127.0.0.1:49674 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=249)�[0;0m INFO 11-25 02:46:09 [launcher.py:110] Shutting down FastAPI HTTP server.

proxy

INFO:     Started server process [2512]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
INFO:     Uvicorn running on http://127.0.0.1:9775 (Press CTRL+C to quit)
Initialized 1 prefill clients and 1 decode clients.
INFO:     127.0.0.1:51120 - "GET /v1/chat/completions HTTP/1.1" 405 Method Not Allowed
INFO:     127.0.0.1:54482 - "POST /v1/chat/completions HTTP/1.1" 200 OK
INFO:     Shutting down
INFO:     Waiting for application shutdown.
INFO:     Application shutdown complete.
INFO:     Finished server process [2512]

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.

[herotai214]

My latest findings are:

• After haning 5-10 minutes (usually ~10 minutes), the streaming part will finally start and finish gracefully; Can show all 100 successful results and 0 failure.
• Pulled the latest commit, and this nixl PD issue still exist
• Double checked that a single instance (without PD disagg) running benchmark at INFO level doesn't have this issue;

My pure guess is, after 5-10 minutes, it aborts something (related to VLLM_NIXL_ABORT_REQUEST_TIMEOUT?) , making the streaming can finally work

Hope above information helps locate the root issues :)

The decode instance log showing successful KV Transfer metrics:

Details

INFO 11-25 06:41:21 [scheduler.py:207] Chunked prefill is enabled with max_num_batched_tokens=2048.
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:41:21 [api_server.py:2056] vLLM API server version 0.11.2.dev157+ge9af6ba62
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:41:21 [utils.py:253] non-default args: {'model_tag': '/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', 'port': 6662, 'model': '/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', 'trust_remote_code': True, 'enforce_eager': True, 'gpu_memory_utilization': 0.8, 'max_num_batched_tokens': 4096, 'kv_transfer_config': KVTransferConfig(kv_connector='NixlConnector', engine_id='ccf4f896-b8cc-4cdc-95ea-a70c7f5e1c19', kv_buffer_device='cuda', kv_buffer_size=1000000000.0, kv_role='kv_consumer', kv_rank=1, kv_parallel_size=2, kv_ip='127.0.0.1', kv_port=14579, kv_connector_extra_config={}, kv_connector_module_path=None, enable_permute_local_kv=False)}
�[0;36m(APIServer pid=3500)�[0;0m The argument `trust_remote_code` is to be used with Auto classes. It has no effect here and is ignored.
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:41:21 [model.py:640] Resolved architecture: Qwen2_5_VLForConditionalGeneration
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:41:21 [model.py:1755] Using max model len 128000
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:41:22 [scheduler.py:207] Chunked prefill is enabled with max_num_batched_tokens=4096.
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:41:22 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(APIServer pid=3500)�[0;0m WARNING 11-25 06:41:22 [vllm.py:729] Turning off hybrid kv cache manager because `--kv-transfer-config` is set. This will reduce the performance of vLLM on LLMs with sliding window attention or Mamba attention. If you are a developer of kv connector, please consider supporting hybrid kv cache manager for your connector by making sure your connector is a subclass of `SupportsHMA` defined in kv_connector/v1/base.py.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:32 [core.py:93] Initializing a V1 LLM engine (v0.11.2.dev157+ge9af6ba62) with config: model='/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', speculative_config=None, tokenizer='/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.bfloat16, max_seq_len=128000, download_dir=None, load_format=auto, tensor_parallel_size=1, pipeline_parallel_size=1, data_parallel_size=1, disable_custom_all_reduce=False, quantization=None, enforce_eager=True, kv_cache_dtype=auto, device_config=cuda, structured_outputs_config=StructuredOutputsConfig(backend='auto', disable_fallback=False, disable_any_whitespace=False, disable_additional_properties=False, reasoning_parser='', reasoning_parser_plugin='', enable_in_reasoning=False), observability_config=ObservabilityConfig(show_hidden_metrics_for_version=None, otlp_traces_endpoint=None, collect_detailed_traces=None), seed=0, served_model_name=/mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct, enable_prefix_caching=True, enable_chunked_prefill=True, pooler_config=None, compilation_config={'level': None, 'mode': <CompilationMode.NONE: 0>, 'debug_dump_path': None, 'cache_dir': '', 'compile_cache_save_format': 'binary', 'backend': 'inductor', 'custom_ops': ['all'], 'splitting_ops': None, 'compile_mm_encoder': False, 'use_inductor': None, 'compile_sizes': [], 'inductor_compile_config': {'enable_auto_functionalized_v2': False, 'combo_kernels': True, 'benchmark_combo_kernel': True}, 'inductor_passes': {}, 'cudagraph_mode': <CUDAGraphMode.NONE: 0>, 'cudagraph_num_of_warmups': 0, 'cudagraph_capture_sizes': [], 'cudagraph_copy_inputs': False, 'cudagraph_specialize_lora': True, 'use_inductor_graph_partition': False, 'pass_config': {}, 'max_cudagraph_capture_size': 0, 'dynamic_shapes_config': {'type': <DynamicShapesType.BACKED: 'backed'>}, 'local_cache_dir': None}
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:36 [parallel_state.py:1217] world_size=1 rank=0 local_rank=0 distributed_init_method=tcp://10.90.67.85:36365 backend=nccl
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
[Gloo] Rank 0 is connected to 0 peer ranks. Expected number of connected peer ranks is : 0
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:36 [parallel_state.py:1425] rank 0 in world size 1 is assigned as DP rank 0, PP rank 0, PCP rank 0, TP rank 0, EP rank 0
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m The image processor of type `Qwen2VLImageProcessor` is now loaded as a fast processor by default, even if the model checkpoint was saved with a slow processor. This is a breaking change and may produce slightly different outputs. To continue using the slow processor, instantiate this class with `use_fast=False`. Note that this behavior will be extended to all models in a future release.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:41 [gpu_model_runner.py:3261] Starting to load model /mnt/nvme3n1/models/Qwen2.5-VL-3B-Instruct...
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:43 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:43 [cuda.py:410] Valid backends: ['FLASH_ATTN', 'FLASHINFER', 'TRITON_ATTN', 'FLEX_ATTENTION']
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:43 [cuda.py:419] Using FLASH_ATTN backend.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 
Loading safetensors checkpoint shards:   0% Completed | 0/2 [00:00<?, ?it/s]
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 
Loading safetensors checkpoint shards:  50% Completed | 1/2 [00:00<00:00,  1.54it/s]
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 
Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:01<00:00,  1.60it/s]
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 
Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:01<00:00,  1.59it/s]
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:44 [default_loader.py:308] Loading weights took 1.30 seconds
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:45 [gpu_model_runner.py:3343] Model loading took 7.1556 GiB memory and 3.416922 seconds
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:45 [gpu_model_runner.py:4100] Encoder cache will be initialized with a budget of 114688 tokens, and profiled with 1 video items of the maximum feature size.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:58 [gpu_worker.py:348] Available KV cache memory: 42.95 GiB
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:59 [kv_cache_utils.py:1243] GPU KV cache size: 1,251,136 tokens
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:59 [kv_cache_utils.py:1248] Maximum concurrency for 128,000 tokens per request: 9.77x
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:59 [nixl_connector.py:72] NIXL is available
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:59 [factory.py:64] Creating v1 connector with name: NixlConnector and engine_id: ccf4f896-b8cc-4cdc-95ea-a70c7f5e1c19
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m WARNING 11-25 06:41:59 [base.py:163] Initializing KVConnectorBase_V1. This API is experimental and subject to change in the future as we iterate the design.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:59 [nixl_connector.py:798] Initializing NIXL wrapper
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:41:59 [nixl_connector.py:799] Initializing NIXL worker ccf4f896-b8cc-4cdc-95ea-a70c7f5e1c19
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 2025-11-25 06:42:01 NIXL INFO    _api.py:361 Backend UCX was instantiated
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m 2025-11-25 06:42:01 NIXL INFO    _api.py:251 Initialized NIXL agent: a6db1a60-5fb1-490b-805a-4c62db0d483c
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:01 [cuda.py:410] Valid backends: ['FLASH_ATTN', 'FLASHINFER', 'TRITON_ATTN', 'FLEX_ATTENTION']
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:01 [cuda.py:419] Using FLASH_ATTN backend.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:01 [nixl_connector.py:198] NixlConnector setting KV cache layout to HND for better xfer performance.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:01 [nixl_connector.py:1151] Registering KV_Caches. use_mla: False, kv_buffer_device: cuda, use_host_buffer: False
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:04 [core.py:253] init engine (profile, create kv cache, warmup model) took 18.74 seconds
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:04 [factory.py:64] Creating v1 connector with name: NixlConnector and engine_id: ccf4f896-b8cc-4cdc-95ea-a70c7f5e1c19
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m WARNING 11-25 06:42:04 [base.py:163] Initializing KVConnectorBase_V1. This API is experimental and subject to change in the future as we iterate the design.
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:04 [nixl_connector.py:363] Initializing NIXL Scheduler ccf4f896-b8cc-4cdc-95ea-a70c7f5e1c19
�[0;36m(EngineCore_DP0 pid=3838)�[0;0m INFO 11-25 06:42:04 [vllm.py:508] Cudagraph is disabled under eager mode
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:04 [nixl_connector.py:72] NIXL is available
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [api_server.py:1804] Supported tasks: ['generate']
�[0;36m(APIServer pid=3500)�[0;0m WARNING 11-25 06:42:05 [model.py:1578] Default sampling parameters have been overridden by the model's Hugging Face generation config recommended from the model creator. If this is not intended, please relaunch vLLM instance with `--generation-config vllm`.
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [serving_responses.py:154] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [serving_chat.py:131] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [serving_completion.py:73] Using default completion sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [serving_chat.py:131] Using default chat sampling params from model: {'repetition_penalty': 1.05, 'temperature': 1e-06}
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [api_server.py:2134] Starting vLLM API server 0 on http://0.0.0.0:6662
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:38] Available routes are:
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /openapi.json, Methods: HEAD, GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /docs, Methods: HEAD, GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /docs/oauth2-redirect, Methods: HEAD, GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /redoc, Methods: HEAD, GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /health, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /load, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /pause, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /resume, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /is_paused, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /tokenize, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /detokenize, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/models, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /version, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/responses, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/responses/{response_id}, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/responses/{response_id}/cancel, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/messages, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/chat/completions, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/completions, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/embeddings, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /pooling, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /classify, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /score, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/score, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/audio/transcriptions, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/audio/translations, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /rerank, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v1/rerank, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /v2/rerank, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /scale_elastic_ep, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /is_scaling_elastic_ep, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /inference/v1/generate, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /ping, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /ping, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /invocations, Methods: POST
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:05 [launcher.py:46] Route: /metrics, Methods: GET
�[0;36m(APIServer pid=3500)�[0;0m INFO:     Started server process [3500]
�[0;36m(APIServer pid=3500)�[0;0m INFO:     Waiting for application startup.
�[0;36m(APIServer pid=3500)�[0;0m INFO:     Application startup complete.
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:41872 - "GET /v1/chat/completions HTTP/1.1" 405 Method Not Allowed
�[0;36m(APIServer pid=3500)�[0;0m The image processor of type `Qwen2VLImageProcessor` is now loaded as a fast processor by default, even if the model checkpoint was saved with a slow processor. This is a breaking change and may produce slightly different outputs. To continue using the slow processor, instantiate this class with `use_fast=False`. Note that this behavior will be extended to all models in a future release.
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:42:27 [chat_utils.py:574] Detected the chat template content format to be 'openai'. You can set `--chat-template-content-format` to override this.
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:54120 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:51:58 [loggers.py:236] Engine 000: Avg prompt throughput: 1.6 tokens/s, Avg generation throughput: 0.7 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%, External prefix cache hit rate: 100.0%, MM cache hit rate: 0.0%
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:51:58 [metrics.py:106] KV Transfer metrics: Num successful transfers=1, Avg xfer time (ms)=377.718, P90 xfer time (ms)=377.718, Avg post time (ms)=366.188, P90 post time (ms)=366.188, Avg MB per transfer=9.562, Throughput (MB/s)=25.317, Avg number of descriptors=72.0
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:54120 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43224 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43228 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43244 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43248 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:54120 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43228 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43262 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43264 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43276 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43282 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43312 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43296 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43306 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43330 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43320 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43368 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43344 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43370 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43394 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43378 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43408 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43346 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43362 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43424 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43450 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43420 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43434 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43466 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43470 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43458 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43478 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43488 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43490 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43496 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43500 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43502 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43518 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43524 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43534 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43548 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43564 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43568 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43566 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43582 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43598 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43612 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43614 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43646 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43624 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43638 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43654 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43660 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43668 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43684 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43678 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43690 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43706 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43730 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43726 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43736 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43714 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43752 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43744 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43770 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43768 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43778 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43794 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43798 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43806 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43808 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43848 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43824 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43838 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43832 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43858 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43872 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43886 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43890 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43624 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43638 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43646 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43668 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:52:08 [loggers.py:236] Engine 000: Avg prompt throughput: 7817.5 tokens/s, Avg generation throughput: 805.0 tokens/s, Running: 16 reqs, Waiting: 0 reqs, GPU KV cache usage: 2.6%, Prefix cache hit rate: 0.4%, External prefix cache hit rate: 99.6%, MM cache hit rate: 1.2%
�[0;36m(APIServer pid=3500)�[0;0m INFO 11-25 06:52:08 [metrics.py:106] KV Transfer metrics: Num successful transfers=83, Avg xfer time (ms)=25.367, P90 xfer time (ms)=35.118, Avg post time (ms)=0.988, P90 post time (ms)=1.495, Avg MB per transfer=33.262, Throughput (MB/s)=1311.225, Avg number of descriptors=72.0
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43690 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43768 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59378 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43736 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43678 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59382 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59390 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43770 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59404 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59410 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43778 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:43872 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59416 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59424 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59428 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59440 - "POST /v1/chat/completions HTTP/1.1" 200 OK
�[0;36m(APIServer pid=3500)�[0;0m INFO:     127.0.0.1:59432 - "POST /v1/chat/completions HTTP/1.1" 200 OK

[NickLucche]

Thanks for reporting

[erezzarum]

I can confirm the same, using VLLM_LOGGING_LEVEL=DEBUG solve this.

[karen-sy]

Following. VLLM_LOGGING_LEVEL=DEBUG solves it, but even then the first request with the debug flag takes a few seconds longer than all subsequent requests

[alec-flowers]

I set this up and the root cause seems to be there is a hot loop that occurs that doesn't release the GIL to allow for NIXL to do
add_remote_agent. When setting VLLM_LOGGING_LEVEL=DEBUG there is some I/O activity that releases the GIL to allow things to be set up.

If I add a sleep to _process_engine_step

if not model_executed and self.scheduler.has_requests():
         time.sleep(0.001)

This will fix the issue. I also set up a git bisect and root caused the issue to this commit:
c9e6658 - [NIXL] heterogeneous block_size support (#26759)
cc: @xuechendi @NickLucche

[alec-flowers]

We noticed this issue in CI when trying to bump to v0.11.2 - ai-dynamo/dynamo#4476

[xuechendi]

@alec-flowers , can you elaborate more on what exact causing the not releasing issue ? Is that we are now adding additional nixl handler during hand_shake?

[alec-flowers]

Its hard to tell exactly what happened from before to now. I think there is now more python work that was added and this is increasing the effects of this hot loop starving the GIL.

If you want to reproduce you can run this small script that will reproduce the error. I ran this on a single GPU (A6000) but I've tested something like TP1 P/D Qwen/Qwen3-30B-fp8 on H100 and its even worse there where things will hang for minutes on that first request.

bisect_test.sh

[NickLucche]

Let's dig a bit deeper into this, thanks @alec-flowers for initial pointer at the issue. I would like to come up with a more elegant and long-term solution rather than tweaking core though.

[robertgshaw2-redhat]

Hey @alec-flowers - do you know which version of python you are using?

[robertgshaw2-redhat]

I have a feeling it could be related to how we do the sched_yeild for the shm broadcast:

• vllm/vllm/distributed/utils.py

  Lines 38 to 50 in 70d5953

  	# We prefer to use os.sched_yield as it results in tighter polling loops,
  	# measured to be around 3e-7 seconds. However on earlier versions of Python
  	# os.sched_yield() does not release the GIL, so we fall back to time.sleep(0)
  	USE_SCHED_YIELD = (sys.version_info[:3] >= (3, 11, 1)) or (
  	sys.version_info[:2] == (3, 10) and sys.version_info[2] >= 8
  	)
  	def sched_yield():
  	if USE_SCHED_YIELD:
  	os.sched_yield()
  	else:
  	time.sleep(0)

[karen-sy]

@alec-flowers and I are on Python 3.12.
Our full docker env setup is here: https://github.com/ai-dynamo/dynamo/blob/8acd4c10c521dedff2c15df96a904684867a3886/container/build.sh (./container/build.sh --VLLM, see Dockerfile and Dockerfile.vllm in same directory)(EDIT: fixed link to point to right PR branch)

[NickLucche]

Can't quite reproduce on 70d5953f8 with your script @alec-flowers , will check out your container env for differences.

This is my environment btw (nixl==0.7.1):

Details

Collecting environment information...
uv is set
==============================
        System Info
==============================
OS                           : CentOS Stream 9 (x86_64)
GCC version                  : (GCC) 11.5.0 20240719 (Red Hat 11.5.0-11)
Clang version                : Could not collect
CMake version                : version 3.26.5
Libc version                 : glibc-2.34

==============================
       PyTorch Info
==============================
PyTorch version              : 2.9.0+cu129
Is debug build               : False
CUDA used to build PyTorch   : 12.9
ROCM used to build PyTorch   : N/A

==============================
      Python Environment
==============================
Python version               : 3.12.11 (main, Aug 14 2025, 00:00:00) [GCC 11.5.0 20240719 (Red Hat 11.5.0-11)] (64-bit runtime)
Python platform              : Linux-5.14.0-620.el9.x86_64-x86_64-with-glibc2.34

==============================
       CUDA / GPU Info
==============================
Is CUDA available            : True
CUDA runtime version         : 12.9.86
CUDA_MODULE_LOADING set to   : 
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        : 580.95.05
cuDNN version                : Could not collect
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:                           46 bits physical, 57 bits virtual
Byte Order:                              Little Endian
CPU(s):                                  160
On-line CPU(s) list:                     0-159
Vendor ID:                               GenuineIntel
Model name:                              Intel Xeon Processor (SapphireRapids)
CPU family:                              6
Model:                                   143
Thread(s) per core:                      2
Core(s) per socket:                      40
Socket(s):                               2
Stepping:                                4
BogoMIPS:                                4200.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 cpuid tsc_known_freq pni pclmulqdq vmx 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 ssbd ibrs ibpb stibp ibrs_enhanced tpr_shadow flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves avx_vnni avx512_bf16 wbnoinvd arat vnmi avx512vbmi umip pku ospke waitpkg avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq la57 rdpid bus_lock_detect cldemote movdiri movdir64b fsrm md_clear serialize tsxldtrk amx_bf16 avx512_fp16 amx_tile amx_int8 arch_capabilities
Virtualization:                          VT-x
Hypervisor vendor:                       KVM
Virtualization type:                     full
L1d cache:                               5 MiB (160 instances)
L1i cache:                               5 MiB (160 instances)
L2 cache:                                320 MiB (80 instances)
L3 cache:                                32 MiB (2 instances)
NUMA node(s):                            2
NUMA node0 CPU(s):                       0-79
NUMA node1 CPU(s):                       80-159
Vulnerability Gather data sampling:      Not affected
Vulnerability Indirect target selection: Mitigation; Aligned branch/return thunks
Vulnerability Itlb multihit:             Not affected
Vulnerability L1tf:                      Not affected
Vulnerability Mds:                       Not affected
Vulnerability Meltdown:                  Not affected
Vulnerability Mmio stale data:           Unknown: No mitigations
Vulnerability Reg file data sampling:    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; PBRSB-eIBRS SW sequence; BHI SW loop, KVM SW loop
Vulnerability Srbds:                     Not affected
Vulnerability Tsa:                       Not affected
Vulnerability Tsx async abort:           Not affected

==============================
Versions of relevant libraries
==============================
[pip3] flashinfer-python==0.5.2
[pip3] numpy==2.2.0
[pip3] nvidia-cublas-cu12==12.9.1.4
[pip3] nvidia-cuda-cupti-cu12==12.9.79
[pip3] nvidia-cuda-nvrtc-cu12==12.9.86
[pip3] nvidia-cuda-runtime-cu12==12.9.79
[pip3] nvidia-cudnn-cu12==9.10.2.21
[pip3] nvidia-cudnn-frontend==1.14.1
[pip3] nvidia-cufft-cu12==11.4.1.4
[pip3] nvidia-cufile-cu12==1.14.1.1
[pip3] nvidia-curand-cu12==10.3.10.19
[pip3] nvidia-cusolver-cu12==11.7.5.82
[pip3] nvidia-cusparse-cu12==12.5.10.65
[pip3] nvidia-cusparselt-cu12==0.7.1
[pip3] nvidia-cutlass-dsl==4.3.0.dev0
[pip3] nvidia-ml-py==13.580.82
[pip3] nvidia-nccl-cu12==2.27.5
[pip3] nvidia-nvjitlink-cu12==12.9.86
[pip3] nvidia-nvshmem-cu12==3.3.20
[pip3] nvidia-nvtx-cu12==12.9.79
[pip3] pynvml==13.0.1
[pip3] pyzmq==27.1.0
[pip3] torch==2.9.0+cu129
[pip3] torchaudio==2.9.0+cu129
[pip3] torchvision==0.24.0+cu129
[pip3] transformers==4.56.1
[pip3] triton==3.5.0
[conda] Could not collect

==============================
         vLLM Info
==============================
ROCM Version                 : Could not collect
vLLM Version                 : 0.11.2.dev301+g70d5953f8 (git sha: 70d5953f8)
vLLM Build Flags:
  CUDA Archs: Not Set; ROCm: Disabled
GPU Topology:
  	�[4mGPU0	GPU1	GPU2	GPU3	GPU4	GPU5	GPU6	GPU7	CPU Affinity	NUMA Affinity	GPU NUMA ID�[0m
GPU0	 X 	NV18	NV18	NV18	NV18	NV18	NV18	NV18	0-79	0		N/A
GPU1	NV18	 X 	NV18	NV18	NV18	NV18	NV18	NV18	0-79	0		N/A
GPU2	NV18	NV18	 X 	NV18	NV18	NV18	NV18	NV18	0-79	0		N/A
GPU3	NV18	NV18	NV18	 X 	NV18	NV18	NV18	NV18	0-79	0		N/A
GPU4	NV18	NV18	NV18	NV18	 X 	NV18	NV18	NV18	80-159	1		N/A
GPU5	NV18	NV18	NV18	NV18	NV18	 X 	NV18	NV18	80-159	1		N/A
GPU6	NV18	NV18	NV18	NV18	NV18	NV18	 X 	NV18	80-159	1		N/A
GPU7	NV18	NV18	NV18	NV18	NV18	NV18	NV18	 X 	80-159	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

==============================
     Environment Variables
==============================
PYTORCH_NVML_BASED_CUDA_CHECK=1
TORCHINDUCTOR_COMPILE_THREADS=1