Skip to content

[Bug]: vLLM server hangs and timeouts after initial requests #17972

Description

@samuellimabraz

Your current environment

The output of python collect_env.py
- Collecting environment information...
- PyTorch version: 2.6.0+cu124
- Is debug build: False
- CUDA used to build PyTorch: 12.4
- ROCM used to build PyTorch: N/A
- 
- OS: Ubuntu 22.04.4 LTS (x86_64)
- GCC version: (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0
- Clang version: Could not collect
- CMake version: version 4.0.0
- Libc version: glibc-2.35
- 
- Python version: 3.12.10 (main, Apr  9 2025, 08:55:05) [GCC 11.4.0] (64-bit runtime)
- Python platform: Linux-5.10.236-227.928.amzn2.x86_64-x86_64-with-glibc2.35
- Is CUDA available: True
- CUDA runtime version: 12.4.131
- CUDA_MODULE_LOADING set to: LAZY
- GPU models and configuration: GPU 0: NVIDIA L4
- Nvidia driver version: 550.163.01
- cuDNN version: Could not collect
- HIP runtime version: N/A
- MIOpen runtime version: N/A
- Is XNNPACK available: True
- 
- CPU:
- Architecture:                         x86_64
- CPU op-mode(s):                       32-bit, 64-bit
- Address sizes:                        48 bits physical, 48 bits virtual
- Byte Order:                           Little Endian
- CPU(s):                               8
- On-line CPU(s) list:                  0-7
- Vendor ID:                            AuthenticAMD
- Model name:                           AMD EPYC 7R13 Processor
- CPU family:                           25
- Model:                                1
- Thread(s) per core:                   2
- Core(s) per socket:                   4
- Socket(s):                            1
- Stepping:                             1
- BogoMIPS:                             5299.99
- 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 nopl nonstop_tsc cpuid extd_apicid aperfmperf tsc_known_freq pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm cmp_legacy cr8_legacy abm sse4a misalignsse 3dnowprefetch topoext invpcid_single ssbd ibrs ibpb stibp vmmcall fsgsbase bmi1 avx2 smep bmi2 invpcid rdseed adx smap clflushopt clwb sha_ni xsaveopt xsavec xgetbv1 clzero xsaveerptr rdpru wbnoinvd arat npt nrip_save vaes vpclmulqdq rdpid
- Hypervisor vendor:                    KVM
- Virtualization type:                  full
- L1d cache:                            128 KiB (4 instances)
- L1i cache:                            128 KiB (4 instances)
- L2 cache:                             2 MiB (4 instances)
- L3 cache:                             16 MiB (1 instance)
- NUMA node(s):                         1
- NUMA node0 CPU(s):                    0-7
- 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, no microcode
- Vulnerability Spec store bypass:      Mitigation; Speculative Store Bypass disabled via prctl and seccomp
- Vulnerability Spectre v1:             Mitigation; usercopy/swapgs barriers and __user pointer sanitization
- Vulnerability Spectre v2:             Mitigation; Retpolines, IBPB conditional, IBRS_FW, STIBP always-on, RSB filling, PBRSB-eIBRS Not affected
- Vulnerability Srbds:                  Not affected
- Vulnerability Tsx async abort:        Not affected
- 
- Versions of relevant libraries:
- [pip3] flashinfer-python==0.2.1.post2+cu124torch2.6
- [pip3] numpy==2.2.5
- [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-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-cusparselt-cu12==0.6.2
- [pip3] nvidia-nccl-cu12==2.21.5
- [pip3] nvidia-nvjitlink-cu12==12.4.127
- [pip3] nvidia-nvtx-cu12==12.4.127
- [pip3] pyzmq==26.4.0
- [pip3] torch==2.6.0
- [pip3] torchaudio==2.6.0
- [pip3] torchvision==0.21.0
- [pip3] transformers==4.52.0.dev0
- [pip3] triton==3.2.0
- [conda] Could not collect
- ROCM Version: Could not collect
- Neuron SDK Version: N/A
- vLLM Version: 0.8.5.post1
- vLLM Build Flags:
- CUDA Archs: Not Set; ROCm: Disabled; Neuron: Disabled
- GPU Topology:
- 	�[4mGPU0	CPU Affinity	NUMA Affinity	GPU NUMA ID�[0m
- GPU0	 X 	0-7	0		N/A
- 
- Legend:
- 
-   X    = Self
-   SYS  = Connection traversing PCIe as well as the SMP interconnect between NUMA nodes (e.g., QPI/UPI)
-   NODE = Connection traversing PCIe as well as the interconnect between PCIe Host Bridges within a NUMA node
-   PHB  = Connection traversing PCIe as well as a PCIe Host Bridge (typically the CPU)
-   PXB  = Connection traversing multiple PCIe bridges (without traversing the PCIe Host Bridge)
-   PIX  = Connection traversing at most a single PCIe bridge
-   NV#  = Connection traversing a bonded set of # NVLinks
- 
- NVIDIA_VISIBLE_DEVICES=GPU-894ea203-35ac-c5cb-dcfa-9bcb23231d8e
- NVIDIA_REQUIRE_CUDA=cuda>=12.4 brand=tesla,driver>=470,driver<471 brand=unknown,driver>=470,driver<471 brand=nvidia,driver>=470,driver<471 brand=nvidiartx,driver>=470,driver<471 brand=geforce,driver>=470,driver<471 brand=geforcertx,driver>=470,driver<471 brand=quadro,driver>=470,driver<471 brand=quadrortx,driver>=470,driver<471 brand=titan,driver>=470,driver<471 brand=titanrtx,driver>=470,driver<471 brand=tesla,driver>=525,driver<526 brand=unknown,driver>=525,driver<526 brand=nvidia,driver>=525,driver<526 brand=nvidiartx,driver>=525,driver<526 brand=geforce,driver>=525,driver<526 brand=geforcertx,driver>=525,driver<526 brand=quadro,driver>=525,driver<526 brand=quadrortx,driver>=525,driver<526 brand=titan,driver>=525,driver<526 brand=titanrtx,driver>=525,driver<526 brand=tesla,driver>=535,driver<536 brand=unknown,driver>=535,driver<536 brand=nvidia,driver>=535,driver<536 brand=nvidiartx,driver>=535,driver<536 brand=geforce,driver>=535,driver<536 brand=geforcertx,driver>=535,driver<536 brand=quadro,driver>=535,driver<536 brand=quadrortx,driver>=535,driver<536 brand=titan,driver>=535,driver<536 brand=titanrtx,driver>=535,driver<536
- NCCL_VERSION=2.20.5-1
- NVIDIA_DRIVER_CAPABILITIES=compute,utility
- NVIDIA_PRODUCT_NAME=CUDA
- VLLM_USAGE_SOURCE=production-docker-image
- CUDA_VERSION=12.4.0
- VLLM_TRACE_FUNCTION=1
- VLLM_ALLOW_RUNTIME_LORA_UPDATING=false
- LD_LIBRARY_PATH=/usr/local/nvidia/lib:/usr/local/nvidia/lib64
- VLLM_LOGGING_LEVEL=DEBUG
- NCCL_CUMEM_ENABLE=0
- PYTORCH_NVML_BASED_CUDA_CHECK=1
- TORCHINDUCTOR_COMPILE_THREADS=1
- CUDA_MODULE_LOADING=LAZY

🐛 Describe the bug

I am experiencing an issue deploying vLLM OpenAI Server with docker, deployed on HuggingFace Inference Endpoints with an NVIDIA L4 GPU, hangs and becomes unresponsive after one or two initial successful requests. Subsequent requests result in timeouts.

Symptoms:

  • After 1-2 successful requests, all further requests to the /v1/chat/completions endpoint timeout.
  • GPU utilization drops significantly.
  • Server logs repeatedly show: 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%
  • This occurs even with VLLM_LOGGING_LEVEL=DEBUG and VLLM_TRACE_FUNCTION=1 enabled.
  • Setting environment variables --disable-custom-all-reduce and --enforce-eager (as seen in the attached entrypoint.sh and logs) does not resolve the issue.
  • Model: tech4humans/InternVL2_5-1B-MPO-swift-r4-rslora-bf16-merged-tuned

Steps to Reproduce

  1. Deploy vLLM using the provided Dockerfile and entrypoint.sh. I have this same image on Docker Hub: samuellimabraz/t4ai-doc-extraction:latest
  2. Send an initial request to the /v1/chat/completions endpoint using a client similar to the provided inference/client.py. This request should succeed.
  3. Send further requests. These requests will start to timeout.
  4. Observe the server logs, which will show the "0.0 tokens/s" messages and low GPU utilization.

Dockerfile:

    FROM vllm/vllm-openai:latest
    ENV VLLM_LOGGING_LEVEL=DEBUG
    ENV VLLM_TRACE_FUNCTION=1

    RUN wget https://github.com/vllm-project/vllm/blob/main/vllm/collect_env.py

    RUN apt-get update && apt-get install -y \
        python3 \
        git \
        && ln -sf /usr/bin/python3 /usr/bin/python \
        && apt-get clean \
        && rm -rf /var/lib/apt/lists/* \
        && pip install --no-cache-dir git+https://github.com/huggingface/transformers.git \
        && pip install --no-cache-dir --no-deps --upgrade "flash-attn>=2.6.3" \
        && rm -rf ~/.cache/pip

    COPY entrypoint.sh /entrypoint.sh
    RUN chmod +x /entrypoint.sh

    ENTRYPOINT ["/entrypoint.sh"]

entrypoint.sh:

#!/bin/bash
set -e

# Default values
export VLLM_LOGGING_LEVEL=${VLLM_LOGGING_LEVEL:-DEBUG}
export VLLM_ALLOW_RUNTIME_LORA_UPDATING=${VLLM_ALLOW_RUNTIME_LORA_UPDATING:-True}

# Required parameters
PORT=${PORT:-8080}
HUGGINGFACE_MODEL=${HUGGINGFACE_MODEL:?"HUGGINGFACE_MODEL must be set"}

# Optional parameters with default values
QUANTIZATION=${QUANTIZATION:-None}
KV_CACHE_DTYPE=${KV_CACHE_DTYPE:-auto}
CHAT_TEMPLATE_CONTENT_FORMAT=${CHAT_TEMPLATE_CONTENT_FORMAT:-openai}
CPU_OFFLOAD_GB=${CPU_OFFLOAD_GB:-0}
GPU_MEMORY_UTILIZATION=${GPU_MEMORY_UTILIZATION:-0.9}
DTYPE=${DTYPE:-auto}
MAX_MODEL_LEN=${MAX_MODEL_LEN:-4096}
API_KEY=${API_KEY:-}
TRUST_REMOTE_CODE=${TRUST_REMOTE_CODE:-true}
LIMIT_MM_PER_PROMPT=${LIMIT_MM_PER_PROMPT:-"image=1"}
DISABLE_CUSTOM_ALL_REDUCE=${DISABLE_CUSTOM_ALL_REDUCE:-true}
ENFORCE_EAGER=${ENFORCE_EAGER:-false}

# Check if python3 is available
if ! command -v python3 > /dev/null 2>&1; then
    echo "Error: python3 not found in the container"
    exit 1
fi

# Collect environment variables
python3 collect_env.py

# Configure Hugging Face token as environment variable for authentication
if [ -n "$HUGGINGFACE_TOKEN" ]; then
    export HF_TOKEN="$HUGGINGFACE_TOKEN"
else
    echo "Warning: HUGGINGFACE_TOKEN not provided. Private models may not be accessible."
fi

echo "Starting vLLM server with model: ${HUGGINGFACE_MODEL}"
echo "Port: ${PORT}"

# Build the command dynamically based on environment variables
CMD="python3 -m vllm.entrypoints.openai.api_server --model ${HUGGINGFACE_MODEL} --port ${PORT} --host 0.0.0.0"

# Add value-based parameters only if they're set
if [[ -n "${QUANTIZATION}" && "${QUANTIZATION}" != "None" ]]; then CMD="${CMD} --quantization ${QUANTIZATION}"; fi
if [[ -n "${DTYPE}" && "${DTYPE}" != "auto" ]]; then CMD="${CMD} --dtype ${DTYPE}"; fi
if [[ -n "${GPU_MEMORY_UTILIZATION}" ]]; then CMD="${CMD} --gpu-memory-utilization ${GPU_MEMORY_UTILIZATION}"; fi
if [[ -n "${CPU_OFFLOAD_GB}" && "${CPU_OFFLOAD_GB}" != "0" ]]; then CMD="${CMD} --cpu-offload-gb ${CPU_OFFLOAD_GB}"; fi
if [[ -n "${KV_CACHE_DTYPE}" && "${KV_CACHE_DTYPE}" != "auto" ]]; then CMD="${CMD} --kv-cache-dtype ${KV_CACHE_DTYPE}"; fi
if [[ -n "${MAX_MODEL_LEN}" ]]; then CMD="${CMD} --max-model-len ${MAX_MODEL_LEN}"; fi
if [[ -n "${CHAT_TEMPLATE_CONTENT_FORMAT}" ]]; then CMD="${CMD} --chat-template-content-format ${CHAT_TEMPLATE_CONTENT_FORMAT}"; fi
if [[ -n "${API_KEY}" ]]; then CMD="${CMD} --api-key ${API_KEY}"; fi
if [[ -n "${LIMIT_MM_PER_PROMPT}" ]]; then CMD="${CMD} --limit-mm-per-prompt ${LIMIT_MM_PER_PROMPT}"; fi

# Add flag-based parameters (enable/disable features)
if [[ "${TRUST_REMOTE_CODE}" == "true" ]]; then CMD="${CMD} --trust-remote-code"; fi
if [[ "${ENABLE_CHUNKED_PREFILL}" == "true" ]]; then CMD="${CMD} --enable-chunked-prefill"; fi
if [[ "${ENABLE_LORA}" == "true" ]]; then CMD="${CMD} --enable-lora"; fi
if [[ "${ENABLE_LORA_BIAS}" == "true" ]]; then CMD="${CMD} --enable-lora-bias"; fi
if [[ "${ENABLE_PROMPT_ADAPTER}" == "true" ]]; then CMD="${CMD} --enable-prompt-adapter"; fi
if [[ "${DISABLE_LOG_STATS}" == "true" ]]; then CMD="${CMD} --disable-log-stats"; fi
if [[ "${DISABLE_LOG_REQUESTS}" == "true" ]]; then CMD="${CMD} --disable-log-requests"; fi
if [[ "${DISABLE_FASTAPI_DOCS}" == "true" ]]; then CMD="${CMD} --disable-fastapi-docs"; fi
if [[ "${ENABLE_PROMPT_TOKENS_DETAILS}" == "true" ]]; then CMD="${CMD} --enable-prompt-tokens-details"; fi
if [[ "${ENABLE_SLEEP_MODE}" == "true" ]]; then CMD="${CMD} --enable-sleep-mode"; fi
if [[ "${CALCULATE_KV_SCALES}" == "true" ]]; then CMD="${CMD} --calculate-kv-scales"; fi
if [[ "${DISABLE_ASYNC_OUTPUT_PROC}" == "true" ]]; then CMD="${CMD} --disable-async-output-proc"; fi
if [[ "${DISABLE_MM_PREPROCESSOR_CACHE}" == "true" ]]; then CMD="${CMD} --disable-mm-preprocessor-cache"; fi

# Conditionally add --disable-custom-all-reduce and --enforce-eager flags
if [[ "${DISABLE_CUSTOM_ALL_REDUCE}" == "true" ]]; then CMD="${CMD} --disable-custom-all-reduce"; fi
if [[ "${ENFORCE_EAGER}" == "true" ]]; then CMD="${CMD} --enforce-eager"; fi

# Add tensor/pipeline parallel sizes if specified
if [[ -n "${TENSOR_PARALLEL_SIZE}" ]]; then CMD="${CMD} --tensor-parallel-size ${TENSOR_PARALLEL_SIZE}"; fi
if [[ -n "${PIPELINE_PARALLEL_SIZE}" ]]; then CMD="${CMD} --pipeline-parallel-size ${PIPELINE_PARALLEL_SIZE}"; fi

# Add batching parameters if specified
if [[ -n "${MAX_NUM_BATCHED_TOKENS}" ]]; then CMD="${CMD} --max-num-batched-tokens ${MAX_NUM_BATCHED_TOKENS}"; fi
if [[ -n "${MAX_NUM_SEQS}" ]]; then CMD="${CMD} --max-num-seqs ${MAX_NUM_SEQS}"; fi


# Log the final command
echo "Executing command: ${CMD}"

# Execute the command
exec ${CMD}

Client (Python - relevant parts for making a request):

      import json
      import time
      import base64
      import requests
      from typing import Dict, Any, Union, Optional

      class DocumentExtractionClient:
          def __init__(
              self,
              api_url: str = "YOUR_HF_ENDPOINT_URL/v1/chat/completions", 
              api_key: str = "YOUR_HF_TOKEN", 
              model_name: str = "tech4humans/InternVL2_5-1B-MPO-swift-r4-rslora-bf16-merged-tuned",
          ):
              self.api_url = api_url
              self.api_key = api_key
              self.model_name = model_name # This is passed in the payload
              self.headers = {
                  "Content-Type": "application/json",
                  "Authorization": f"Bearer {self.api_key}",
              }
          # ... (encode_base64 methods are omitted for brevity but are used)

          def extract_data(
              self,
              schema_json: Union[str, Dict],
              image_base64: str, # Assuming image is pre-encoded for simplicity here
              actual_mime_type: str = "image/jpeg",
              temperature: float = 0.1,
              top_p: float = 0.01,
              top_k: int = 1,
              repetition_penalty: float = 1.01,
              max_tokens: int = 512,
          ) -> Dict[str, Any]:
              if isinstance(schema_json, dict):
                  schema_json = json.dumps(schema_json)

              payload = {
                  "model": self.model_name, # Correctly using the instance's model_name
                  "messages": [
                      {
                          "role": "system",
                          "content": '''Parse the provided image of a document and extract the relevant information in a well-structured JSON format that the user will provide.''',
                      },
                      {
                          "role": "user",
                          "content": [
                              {"type": "text", "text": f"### Esquema JSON: {schema_json}"},
                              {
                                  "type": "image_url",
                                  "image_url": {
                                      "url": f"data:{actual_mime_type};base64,{image_base64}"
                                  },
                              },
                          ],
                      },
                  ],
                  "temperature": temperature,
                  "top_p": top_p,
                  "top_k": top_k,
                  "repetition_penalty": repetition_penalty,
                  "max_tokens": max_tokens,
              }

              start_time = time.time()
              response = requests.post(
                  self.api_url, headers=self.headers, data=json.dumps(payload), timeout=300
              )
              elapsed_time = time.time() - start_time
              response.raise_for_status() # Will raise an exception for bad status codes
              # ... (response processing)
              return response.json()

      # Example usage:
      # client = DocumentExtractionClient()
      # schema = {"field_name": {"description": "description", "type": "string"}}
      # # image_b64 = client.encode_base64_from_file("path/to/your/image.jpg")
      # # client.extract_data(schema_json=schema, image_base64=image_b64)
Server Log
Starting vLLM server with model: /repository
Port: 8080
Executing command: python3 -m vllm.entrypoints.openai.api_server --model /repository --port 8080 --host 0.0.0.0 --quantization fp8 --gpu-memory-utilization 0.9 --max-model-len 4096 --chat-template-content-format string --limit-mm-per-prompt image=1 --trust-remote-code --disable-custom-all-reduce --enforce-eager --max-num-batched-tokens 1024 --max-num-seqs 1
DEBUG 05-11 17:58:33 [__init__.py:28] No plugins for group vllm.platform_plugins found.
DEBUG 05-11 17:58:33 [__init__.py:34] Checking if TPU platform is available.
DEBUG 05-11 17:58:33 [__init__.py:44] TPU platform is not available because: No module named 'libtpu'
DEBUG 05-11 17:58:33 [__init__.py:52] Checking if CUDA platform is available.
DEBUG 05-11 17:58:33 [__init__.py:72] Confirmed CUDA platform is available.
DEBUG 05-11 17:58:33 [__init__.py:100] Checking if ROCm platform is available.
DEBUG 05-11 17:58:33 [__init__.py:114] ROCm platform is not available because: No module named 'amdsmi'
DEBUG 05-11 17:58:33 [__init__.py:122] Checking if HPU platform is available.
DEBUG 05-11 17:58:33 [__init__.py:129] HPU platform is not available because habana_frameworks is not found.
DEBUG 05-11 17:58:33 [__init__.py:140] Checking if XPU platform is available.
DEBUG 05-11 17:58:33 [__init__.py:150] XPU platform is not available because: No module named 'intel_extension_for_pytorch'
DEBUG 05-11 17:58:33 [__init__.py:158] Checking if CPU platform is available.
DEBUG 05-11 17:58:33 [__init__.py:180] Checking if Neuron platform is available.
DEBUG 05-11 17:58:33 [__init__.py:187] Neuron platform is not available because: No module named 'transformers_neuronx'
DEBUG 05-11 17:58:33 [__init__.py:52] Checking if CUDA platform is available.
DEBUG 05-11 17:58:33 [__init__.py:72] Confirmed CUDA platform is available.
INFO 05-11 17:58:33 [__init__.py:239] Automatically detected platform cuda.
DEBUG 05-11 17:58:34 [utils.py:135] Setting VLLM_WORKER_MULTIPROC_METHOD to 'spawn'
DEBUG 05-11 17:58:34 [__init__.py:28] No plugins for group vllm.general_plugins found.
INFO 05-11 17:58:35 [api_server.py:1043] vLLM API server version 0.8.5.post1
INFO 05-11 17:58:35 [api_server.py:1044] args: Namespace(host='0.0.0.0', port=8080, uvicorn_log_level='info', disable_uvicorn_access_log=False, allow_credentials=False, allowed_origins=['*'], allowed_methods=['*'], allowed_headers=['*'], api_key=None, lora_modules=None, prompt_adapters=None, chat_template=None, chat_template_content_format='string', response_role='assistant', ssl_keyfile=None, ssl_certfile=None, ssl_ca_certs=None, enable_ssl_refresh=False, ssl_cert_reqs=0, root_path=None, middleware=[], return_tokens_as_token_ids=False, disable_frontend_multiprocessing=False, enable_request_id_headers=False, enable_auto_tool_choice=False, tool_call_parser=None, tool_parser_plugin='', model='/repository', task='auto', tokenizer=None, hf_config_path=None, skip_tokenizer_init=False, revision=None, code_revision=None, tokenizer_revision=None, tokenizer_mode='auto', trust_remote_code=True, allowed_local_media_path=None, load_format='auto', download_dir=None, model_loader_extra_config={}, use_tqdm_on_load=True, config_format=<ConfigFormat.AUTO: 'auto'>, dtype='auto', max_model_len=4096, guided_decoding_backend='auto', reasoning_parser=None, logits_processor_pattern=None, model_impl='auto', distributed_executor_backend=None, pipeline_parallel_size=1, tensor_parallel_size=1, data_parallel_size=1, enable_expert_parallel=False, max_parallel_loading_workers=None, ray_workers_use_nsight=False, disable_custom_all_reduce=True, block_size=None, gpu_memory_utilization=0.9, swap_space=4, kv_cache_dtype='auto', num_gpu_blocks_override=None, enable_prefix_caching=None, prefix_caching_hash_algo='builtin', cpu_offload_gb=0, calculate_kv_scales=False, disable_sliding_window=False, use_v2_block_manager=True, seed=None, max_logprobs=20, disable_log_stats=False, quantization='fp8', rope_scaling=None, rope_theta=None, hf_token=None, hf_overrides=None, enforce_eager=True, max_seq_len_to_capture=8192, tokenizer_pool_size=0, tokenizer_pool_type='ray', tokenizer_pool_extra_config={}, limit_mm_per_prompt={'image': 1}, mm_processor_kwargs=None, disable_mm_preprocessor_cache=False, enable_lora=None, enable_lora_bias=False, max_loras=1, max_lora_rank=16, lora_extra_vocab_size=256, lora_dtype='auto', long_lora_scaling_factors=None, max_cpu_loras=None, fully_sharded_loras=False, enable_prompt_adapter=None, max_prompt_adapters=1, max_prompt_adapter_token=0, device='auto', speculative_config=None, ignore_patterns=[], served_model_name=None, qlora_adapter_name_or_path=None, show_hidden_metrics_for_version=None, otlp_traces_endpoint=None, collect_detailed_traces=None, disable_async_output_proc=False, max_num_batched_tokens=1024, max_num_seqs=1, max_num_partial_prefills=1, max_long_partial_prefills=1, long_prefill_token_threshold=0, num_lookahead_slots=0, scheduler_delay_factor=0.0, preemption_mode=None, num_scheduler_steps=1, multi_step_stream_outputs=True, scheduling_policy='fcfs', enable_chunked_prefill=None, disable_chunked_mm_input=False, scheduler_cls='vllm.core.scheduler.Scheduler', override_neuron_config=None, override_pooler_config=None, compilation_config=None, kv_transfer_config=None, worker_cls='auto', worker_extension_cls='', generation_config='auto', override_generation_config=None, enable_sleep_mode=False, additional_config=None, enable_reasoning=False, disable_cascade_attn=False, disable_log_requests=False, max_log_len=None, disable_fastapi_docs=False, enable_prompt_tokens_details=False, enable_server_load_tracking=False)
INFO 05-11 17:58:41 [config.py:717] This model supports multiple tasks: {'classify', 'embed', 'score', 'reward', 'generate'}. Defaulting to 'generate'.
INFO 05-11 17:58:41 [config.py:2003] Chunked prefill is enabled with max_num_batched_tokens=1024.
WARNING 05-11 17:58:41 [cuda.py:93] To see benefits of async output processing, enable CUDA graph. Since, enforce-eager is enabled, async output processor cannot be used
DEBUG 05-11 17:58:46 [__init__.py:28] No plugins for group vllm.platform_plugins found.
DEBUG 05-11 17:58:46 [__init__.py:34] Checking if TPU platform is available.
DEBUG 05-11 17:58:46 [__init__.py:44] TPU platform is not available because: No module named 'libtpu'
DEBUG 05-11 17:58:46 [__init__.py:52] Checking if CUDA platform is available.
DEBUG 05-11 17:58:46 [__init__.py:72] Confirmed CUDA platform is available.
DEBUG 05-11 17:58:46 [__init__.py:100] Checking if ROCm platform is available.
DEBUG 05-11 17:58:46 [__init__.py:114] ROCm platform is not available because: No module named 'amdsmi'
DEBUG 05-11 17:58:46 [__init__.py:122] Checking if HPU platform is available.
DEBUG 05-11 17:58:46 [__init__.py:129] HPU platform is not available because habana_frameworks is not found.
DEBUG 05-11 17:58:46 [__init__.py:140] Checking if XPU platform is available.
DEBUG 05-11 17:58:46 [__init__.py:150] XPU platform is not available because: No module named 'intel_extension_for_pytorch'
DEBUG 05-11 17:58:46 [__init__.py:158] Checking if CPU platform is available.
DEBUG 05-11 17:58:46 [__init__.py:180] Checking if Neuron platform is available.
DEBUG 05-11 17:58:46 [__init__.py:187] Neuron platform is not available because: No module named 'transformers_neuronx'
DEBUG 05-11 17:58:46 [__init__.py:52] Checking if CUDA platform is available.
DEBUG 05-11 17:58:46 [__init__.py:72] Confirmed CUDA platform is available.
INFO 05-11 17:58:46 [__init__.py:239] Automatically detected platform cuda.
INFO 05-11 17:58:48 [core.py:58] Initializing a V1 LLM engine (v0.8.5.post1) with config: model='/repository', speculative_config=None, tokenizer='/repository', skip_tokenizer_init=False, tokenizer_mode=auto, revision=None, override_neuron_config=None, tokenizer_revision=None, trust_remote_code=True, dtype=torch.bfloat16, max_seq_len=4096, download_dir=None, load_format=LoadFormat.AUTO, tensor_parallel_size=1, pipeline_parallel_size=1, disable_custom_all_reduce=True, quantization=fp8, enforce_eager=True, kv_cache_dtype=auto,  device_config=cuda, decoding_config=DecodingConfig(guided_decoding_backend='auto', reasoning_backend=None), observability_config=ObservabilityConfig(show_hidden_metrics=False, otlp_traces_endpoint=None, collect_model_forward_time=False, collect_model_execute_time=False), seed=None, served_model_name=/repository, num_scheduler_steps=1, multi_step_stream_outputs=True, enable_prefix_caching=True, chunked_prefill_enabled=True, use_async_output_proc=False, disable_mm_preprocessor_cache=False, mm_processor_kwargs=None, pooler_config=None, compilation_config={"splitting_ops":[],"compile_sizes":[],"cudagraph_capture_sizes":[],"max_capture_size":0}
WARNING 05-11 17:58:48 [logger.py:202] VLLM_TRACE_FUNCTION is enabled. It will record every function executed by Python. This will slow down the code. It is suggested to be used for debugging hang or crashes only.
INFO 05-11 17:58:48 [logger.py:206] Trace frame log is saved to /tmp/root/vllm/vllm-instance-7e6e1/VLLM_TRACE_FUNCTION_for_process_91_thread_140117216034816_at_2025-05-11_17:58:48.615797.log
DEBUG 05-11 17:58:48 [__init__.py:28] No plugins for group vllm.general_plugins found.
DEBUG 05-11 17:58:49 [decorators.py:109] Inferred dynamic dimensions for forward method of <class 'vllm.model_executor.models.llama.LlamaModel'>: ['input_ids', 'positions', 'intermediate_tensors', 'inputs_embeds']
DEBUG 05-11 17:58:53 [core_client.py:425] Waiting for 1 core engine proc(s) to start: {0}
WARNING 05-11 17:58:53 [utils.py:2522] Methods determine_num_available_blocks,device_config,get_cache_block_size_bytes,initialize_cache not implemented in <vllm.v1.worker.gpu_worker.Worker object at 0x7f6e8f8650a0>
DEBUG 05-11 17:58:53 [config.py:4110] enabled custom ops: Counter()
DEBUG 05-11 17:58:53 [config.py:4112] disabled custom ops: Counter()
DEBUG 05-11 17:58:54 [parallel_state.py:867] world_size=1 rank=0 local_rank=0 distributed_init_method=tcp://10.101.34.153:39843 backend=nccl
INFO 05-11 17:58:54 [parallel_state.py:1004] rank 0 in world size 1 is assigned as DP rank 0, PP rank 0, TP rank 0
INFO 05-11 17:58:54 [cuda.py:221] Using Flash Attention backend on V1 engine.
INFO 05-11 17:58:55 [topk_topp_sampler.py:59] Using FlashInfer for top-p & top-k sampling.
DEBUG 05-11 17:58:55 [config.py:4110] enabled custom ops: Counter()
DEBUG 05-11 17:58:55 [config.py:4112] disabled custom ops: Counter()
INFO 05-11 17:58:55 [gpu_model_runner.py:1329] Starting to load model /repository...
WARNING 05-11 17:58:55 [utils.py:168] The model class InternVLChatModel has not defined `packed_modules_mapping`, this may lead to incorrect mapping of quantized or ignored modules
INFO 05-11 17:58:56 [config.py:3614] cudagraph sizes specified by model runner [] is overridden by config []
DEBUG 05-11 17:58:59 [config.py:4110] enabled custom ops: Counter({'rms_norm': 73, 'silu_and_mul': 36, 'rotary_embedding': 1})
DEBUG 05-11 17:58:59 [config.py:4112] disabled custom ops: Counter()
DEBUG 05-11 17:58:59 [config.py:4110] enabled custom ops: Counter({'rms_norm': 73, 'silu_and_mul': 36, 'rotary_embedding': 1})
DEBUG 05-11 17:58:59 [config.py:4112] disabled custom ops: Counter()

Loading safetensors checkpoint shards:   0% Completed | 0/2 [00:00<?, ?it/s]
DEBUG 05-11 17:59:03 [core_client.py:425] Waiting for 1 core engine proc(s) to start: {0}

Loading safetensors checkpoint shards:  50% Completed | 1/2 [00:06<00:06,  6.12s/it]
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight lm_head.weight with shape torch.Size([151680, 2048])
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight mlp1.0.bias with shape torch.Size([4096])
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight mlp1.0.weight with shape torch.Size([4096])
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight mlp1.1.bias with shape torch.Size([2048])
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight mlp1.1.weight with shape torch.Size([2048, 4096])
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight mlp1.3.bias with shape torch.Size([2048])
DEBUG 05-11 17:59:06 [utils.py:156] Loaded weight mlp1.3.weight with shape torch.Size([2048, 2048])

Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:07<00:00,  3.07s/it]

Loading safetensors checkpoint shards: 100% Completed | 2/2 [00:07<00:00,  3.53s/it]

INFO 05-11 17:59:06 [loader.py:458] Loading weights took 7.14 seconds
WARNING 05-11 17:59:07 [kv_cache.py:128] Using Q scale 1.0 and prob scale 1.0 with fp8 attention. This may cause accuracy issues. Please make sure Q/prob scaling factors are available in the fp8 checkpoint.
INFO 05-11 17:59:08 [gpu_model_runner.py:1347] Model loading took 4.1030 GiB and 13.411079 seconds
INFO 05-11 17:59:09 [gpu_model_runner.py:1620] Encoder cache will be initialized with a budget of 3328 tokens, and profiled with 1 image items of the maximum feature size.
DEBUG 05-11 17:59:13 [core_client.py:425] Waiting for 1 core engine proc(s) to start: {0}
INFO 05-11 17:59:13 [kv_cache_utils.py:634] GPU KV cache size: 428,192 tokens
INFO 05-11 17:59:13 [kv_cache_utils.py:637] Maximum concurrency for 4,096 tokens per request: 104.54x
INFO 05-11 17:59:14 [core.py:159] init engine (profile, create kv cache, warmup model) took 5.53 seconds
INFO 05-11 17:59:14 [core_client.py:439] Core engine process 0 ready.
DEBUG 05-11 17:59:14 [core.py:421] EngineCore waiting for work.
INFO 05-11 17:59:14 [api_server.py:1090] Starting vLLM API server on http://0.0.0.0:8080
INFO 05-11 17:59:14 [launcher.py:28] Available routes are:
INFO 05-11 17:59:14 [launcher.py:36] Route: /openapi.json, Methods: HEAD, GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /docs, Methods: HEAD, GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /docs/oauth2-redirect, Methods: HEAD, GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /redoc, Methods: HEAD, GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /health, Methods: GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /load, Methods: GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /ping, Methods: GET, POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /tokenize, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /detokenize, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/models, Methods: GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /version, Methods: GET
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/chat/completions, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/completions, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/embeddings, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /pooling, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /score, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/score, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/audio/transcriptions, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /rerank, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v1/rerank, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /v2/rerank, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /invocations, Methods: POST
INFO 05-11 17:59:14 [launcher.py:36] Route: /metrics, Methods: GET
INFO:     Started server process [1]
INFO:     Waiting for application startup.
INFO:     Application startup complete.
DEBUG 05-11 17:59:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:53580 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:53586 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:24 [loggers.py:111] 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%
DEBUG 05-11 17:59:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:39184 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:39194 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:34 [loggers.py:111] 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%
DEBUG 05-11 17:59:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:42902 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:42906 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:44 [loggers.py:111] 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%
DEBUG 05-11 17:59:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:35332 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:35334 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:54 [loggers.py:111] 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%
DEBUG 05-11 17:59:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36530 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 17:59:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36514 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:04 [loggers.py:111] 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%
DEBUG 05-11 18:00:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:40206 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:40220 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:14 [loggers.py:111] 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%
DEBUG 05-11 18:00:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:59394 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:59392 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:24 [loggers.py:111] 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%
DEBUG 05-11 18:00:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37016 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37018 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:34 [loggers.py:111] 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%
DEBUG 05-11 18:00:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:49620 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:49632 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:44 [loggers.py:111] 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%
DEBUG 05-11 18:00:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37668 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37670 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:54 [loggers.py:111] 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%
DEBUG 05-11 18:00:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:41662 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:00:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:41664 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:04 [loggers.py:111] 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%
DEBUG 05-11 18:01:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37644 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37642 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:14 [loggers.py:111] 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%
DEBUG 05-11 18:01:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:53160 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:53162 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:24 [loggers.py:111] 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%
DEBUG 05-11 18:01:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:55914 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:55912 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:34 [loggers.py:111] 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%
DEBUG 05-11 18:01:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:55682 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:55684 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:44 [loggers.py:111] 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%
DEBUG 05-11 18:01:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:60926 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:60932 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:54 [loggers.py:111] 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%
DEBUG 05-11 18:01:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:60776 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:01:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:60778 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:04 [loggers.py:111] 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%
DEBUG 05-11 18:02:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:43872 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:43870 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:14 [loggers.py:111] 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%
DEBUG 05-11 18:02:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:52788 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:52790 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:24 [loggers.py:111] 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%
DEBUG 05-11 18:02:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36570 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36582 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:34 [loggers.py:111] 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%
DEBUG 05-11 18:02:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:59730 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:59744 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:44 [loggers.py:111] 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%
DEBUG 05-11 18:02:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:33360 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:33368 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:54 [loggers.py:111] 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%
DEBUG 05-11 18:02:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36724 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:02:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36726 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:04 [loggers.py:111] 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%
DEBUG 05-11 18:03:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36218 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36234 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:14 [loggers.py:111] 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%
DEBUG 05-11 18:03:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:59488 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:59490 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:24 [loggers.py:111] 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%
DEBUG 05-11 18:03:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36260 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:26 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36272 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:34 [loggers.py:111] 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%
DEBUG 05-11 18:03:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36048 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:36 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:36046 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:44 [loggers.py:111] 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%
DEBUG 05-11 18:03:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:55262 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:46 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:55264 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:54 [loggers.py:111] 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%
DEBUG 05-11 18:03:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:54988 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:03:56 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:54982 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:04:04 [loggers.py:111] 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%
DEBUG 05-11 18:04:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37492 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:04:06 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:37496 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:04:14 [loggers.py:111] 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%
DEBUG 05-11 18:04:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:38000 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:04:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:38016 - "GET /health HTTP/1.1" 200 OK
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:67: vision_select_layer: -1
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:68: ps_version: v2
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:69: min_dynamic_patch: 1
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:70: max_dynamic_patch: 12
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:42: vision_config is None. Initializing the InternVisionConfig with default values.
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:46: llm_config is None. Initializing the LlamaConfig config with default values (`LlamaConfig`).
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:67: vision_select_layer: -1
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:68: ps_version: v1
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:69: min_dynamic_patch: 1
[2025-05-11 18:04:21] INFO configuration_internvl_chat.py:70: max_dynamic_patch: 6
INFO 05-11 18:04:21 [chat_utils.py:397] Detected the chat template content format to be 'string'. You can set `--chat-template-content-format` to override this.
INFO 05-11 18:04:22 [logger.py:39] Received request chatcmpl-ICnXlz: prompt: '<|im_start|>system\nParse the provided image of a document and extract the relevant information in a well-structured JSON format that the user will provide.<|im_end|>\n<|im_start|>user\n<image>\n### Esquema JSON: {"nome_completo": {"description": "Nome completo conforme consta na CNH", "type": "string"}, "cpf": {"description": "Cadastro de Pessoa F\\u00edsica (CPF) do titular", "type": "string"}, "data_nascimento": {"description": "Data de nascimento do titular", "type": "date"}, "filiacao_pai": {"description": "Nome completo do genitor paterno", "type": "string"}, "filiacao_mae": {"description": "Nome completo do genitor materno", "type": "string"}, "categoria_habilitacao": {"description": "Categoria de habilita\\u00e7\\u00e3o para ve\\u00edculos automotores", "type": "enum", "values": ["ACC", "A", "B", "AB", "C", "D", "E"]}, "num_registro": {"description": "C\\u00f3digo \\u00fanico de identifica\\u00e7\\u00e3o da CNH", "type": "string"}, "data_1a_habilitacao": {"description": "Data em que a CNH foi obtida pela primeira vez", "type": "date"}, "data_emissao": {"description": "Data em que o documento foi emitido", "type": "date"}}<|im_end|>\n<|im_start|>assistant\n', params: SamplingParams(n=1, presence_penalty=0.0, frequency_penalty=0.0, repetition_penalty=1.01, temperature=0.1, top_p=0.01, top_k=1, min_p=0.0, seed=None, stop=[], stop_token_ids=[], bad_words=[], include_stop_str_in_output=False, ignore_eos=False, max_tokens=512, min_tokens=0, logprobs=None, prompt_logprobs=None, skip_special_tokens=True, spaces_between_special_tokens=True, truncate_prompt_tokens=None, guided_decoding=None, extra_args=None), prompt_token_ids: None, lora_request: None, prompt_adapter_request: None.
INFO 05-11 18:04:22 [async_llm.py:252] Added request chatcmpl-ICnXlz.
DEBUG 05-11 18:04:22 [core.py:427] EngineCore loop active.
DEBUG 05-11 18:04:24 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:04:34 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:04:44 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:04:54 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:05:04 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:05:14 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:05:24 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:05:34 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:05:44 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:05:54 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:06:04 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:06:14 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:06:24 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:06:34 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:06:44 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:06:54 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:07:04 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:07:14 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:07:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:35104 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:07:16 [async_llm.py:467] Called check_health.
INFO:     10.101.56.92:35102 - "GET /health HTTP/1.1" 200 OK
DEBUG 05-11 18:07:24 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:07:34 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:07:44 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:07:54 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:08:04 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:08:14 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:08:24 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:08:34 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:08:44 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:08:54 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:09:04 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:09:14 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:09:24 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
DEBUG 05-11 18:09:34 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 0.0 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%

The full log shows the server starts, handles one request (chatcmpl-ICnXlz), and then enters a state where it logs "Running: 1 reqs" but doesn't process it, and subsequent requests would timeout.

Expected Behavior:
The vLLM server should continue to process requests normally after the initial ones, without hanging or requiring a restart.

It seems like a request might be getting stuck in the engine, or some internal state is corrupted after the first few requests, preventing further processing. The VLLM_TRACE_FUNCTION=1 log is being generated at /tmp/root/vllm/vllm-instance-7e6e1/VLLM_TRACE_FUNCTION_for_process_91_thread_140117216034816_at_2025-05-11_17:58:48.615797.log as per the startup logs, but access to this file within the HF Inference Endpoint environment is not straightforward for direct user inspection.

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.

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingstaleOver 90 days of inactivity

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions