[Bug]: Missing metrics in V1

[dtransposed]

Your current environment

The output of `python collect_env.py`

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: Debian GNU/Linux 11 (bullseye) (x86_64)
GCC version: (Debian 10.2.1-6) 10.2.1 20210110
Clang version: Could not collect
CMake version: version 3.18.4
Libc version: glibc-2.31

Python version: 3.10.16 | packaged by conda-forge | (main, Dec  5 2024, 14:16:10) [GCC 13.3.0] (64-bit runtime)
Python platform: Linux-5.10.0-34-cloud-amd64-x86_64-with-glibc2.31
Is CUDA available: True
CUDA runtime version: 12.4.131
CUDA_MODULE_LOADING set to: LAZY
GPU models and configuration: 
GPU 0: NVIDIA L4
GPU 1: NVIDIA L4

Nvidia driver version: 550.90.07
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
Byte Order:                           Little Endian
Address sizes:                        46 bits physical, 48 bits virtual
CPU(s):                               24
On-line CPU(s) list:                  0-23
Thread(s) per core:                   2
Core(s) per socket:                   12
Socket(s):                            1
NUMA node(s):                         1
Vendor ID:                            GenuineIntel
CPU family:                           6
Model:                                85
Model name:                           Intel(R) Xeon(R) CPU @ 2.20GHz
Stepping:                             7
CPU MHz:                              2200.194
BogoMIPS:                             4400.38
Hypervisor vendor:                    KVM
Virtualization type:                  full
L1d cache:                            384 KiB
L1i cache:                            384 KiB
L2 cache:                             12 MiB
L3 cache:                             38.5 MiB
NUMA node0 CPU(s):                    0-23
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:        Vulnerable: Clear CPU buffers attempted, no microcode; SMT Host state unknown
Vulnerability Reg file data sampling: Not affected
Vulnerability Retbleed:               Mitigation; Enhanced IBRS
Vulnerability Spec rstack overflow:   Not affected
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; Enhanced / Automatic IBRS, IBPB conditional, RSB filling, PBRSB-eIBRS SW sequence
Vulnerability Srbds:                  Not affected
Vulnerability Tsx async abort:        Vulnerable: Clear CPU buffers attempted, no microcode; SMT Host state unknown
Flags:                                fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl xtopology nonstop_tsc cpuid tsc_known_freq pni pclmulqdq ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch invpcid_single ssbd ibrs ibpb stibp ibrs_enhanced fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm mpx avx512f avx512dq rdseed adx smap clflushopt clwb avx512cd avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves arat avx512_vnni md_clear arch_capabilities

Versions of relevant libraries:
[pip3] mypy==1.15.0
[pip3] mypy-extensions==1.0.0
[pip3] numpy==1.26.4
[pip3] nvidia-cublas-cu12==12.4.5.8
[pip3] nvidia-cuda-cupti-cu12==12.4.127
[pip3] nvidia-cuda-nvrtc-cu12==12.4.127
[pip3] nvidia-cuda-runtime-cu12==12.4.127
[pip3] nvidia-cudnn-cu12==9.1.0.70
[pip3] nvidia-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.3.0
[pip3] sentence-transformers==3.4.1
[pip3] torch==2.6.0
[pip3] torchaudio==2.6.0
[pip3] torchvision==0.21.0
[pip3] transformers==4.51.1
[pip3] triton==3.2.0
[conda] numpy                     1.25.2                   pypi_0    pypi
[conda] nvidia-ml-py              11.495.46                pypi_0    pypi
[conda] pyzmq                     26.3.0                   pypi_0    pypi
ROCM Version: Could not collect
Neuron SDK Version: N/A
vLLM Version: 0.8.3
vLLM Build Flags:
CUDA Archs: Not Set; ROCm: Disabled; Neuron: Disabled
GPU Topology:
        GPU0    GPU1    CPU Affinity    NUMA Affinity   GPU NUMA ID
GPU0     X      PHB     0-23    0               N/A
GPU1    PHB      X      0-23    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

LD_LIBRARY_PATH=/usr/local/cuda/lib64:/usr/local/nccl2/lib:/usr/local/cuda/extras/CUPTI/lib64:/usr/local/cuda/lib64:/usr/local/nccl2/lib:/usr/local/cuda/extras/CUPTI/lib64
NCCL_CUMEM_ENABLE=0
PYTORCH_NVML_BASED_CUDA_CHECK=1
TORCHINDUCTOR_COMPILE_THREADS=1
CUDA_MODULE_LOADING=LAZY

🐛 Describe the bug

This is my sample script.py

from vllm import SamplingParams, AsyncEngineArgs, AsyncLLMEngine
import uuid
import asyncio
import time

async def main():
    """
    Simulates sending 100 concurrent requests to a vLLM inference engine.
    
    :returns: None
    """
    # Configure sampling parameters
    sampling_params = SamplingParams(
        max_tokens=100,
    )
    
    # Configure engine
    engine_args = AsyncEngineArgs(
        model="facebook/opt-125m",
        enforce_eager=True,
        gpu_memory_utilization=0.90,
        disable_log_requests=True,
        disable_log_stats=False
    )
    
    # Initialize engine
    engine = AsyncLLMEngine.from_engine_args(engine_args)
    
    # Define request processing coroutine
    async def process_request(request_id):
        """
        Process a single request using the vLLM engine.
        
        :param request_id: Unique identifier for the request
        :returns: Generated text output
        """
        prompt = f"Hello, how are you? This is request {request_id}"
        
        # Send request to the engine
        result_generator = engine.generate(
            prompt=prompt,
            sampling_params=sampling_params,
            request_id=str(request_id),
            
        )
        
        # Process the streaming results
        final_output = None
        async for request_output in result_generator:
            final_output = request_output
            
        return final_output
    
    # Create 10000 concurrent tasks
    print(f"Starting 10000 concurrent requests")
    
    tasks = []
    for i in range(10000):
        request_id = uuid.uuid4()
        tasks.append(process_request(request_id))
    
    # Wait for all tasks to complete
    await asyncio.gather(*tasks)
    
if __name__ == "__main__":
    asyncio.run(main())

When I run VLLM_USE_V1=0 python script.py

I do see the aggregate throughput metrics being regularly shown to me:

...
INFO 04-09 14:25:03 [worker.py:267] model weights take 0.24GiB; non_torch_memory takes 0.04GiB; PyTorch activation peak memory takes 0.47GiB; the rest of the memory reserved for KV Cache is 19.00GiB.
INFO 04-09 14:25:03 [executor_base.py:112] # cuda blocks: 34595, # CPU blocks: 7281
INFO 04-09 14:25:03 [executor_base.py:117] Maximum concurrency for 2048 tokens per request: 270.27x
INFO 04-09 14:25:06 [llm_engine.py:448] init engine (profile, create kv cache, warmup model) took 4.49 seconds
Starting 10000 concurrent requests
INFO 04-09 14:25:12 [metrics.py:488] Avg prompt throughput: 1899.6 tokens/s, Avg generation throughput: 975.1 tokens/s, Running: 256 reqs, Swapped: 0 reqs, Pending: 9725 reqs, GPU KV cache usage: 2.9%, CPU KV cache usage: 0.0%.
INFO 04-09 14:25:17 [metrics.py:488] Avg prompt throughput: 2006.7 tokens/s, Avg generation throughput: 5044.2 tokens/s, Running: 255 reqs, Swapped: 0 reqs, Pending: 9435 reqs, GPU KV cache usage: 3.4%, CPU KV cache usage: 0.0%.
INFO 04-09 14:25:22 [metrics.py:488] Avg prompt throughput: 1859.2 tokens/s, Avg generation throughput: 4441.8 tokens/s, Running: 255 reqs, Swapped: 0 reqs, Pending: 9166 reqs, GPU KV cache usage: 3.4%, CPU KV cache usage: 0.0%

however when VLLM_USE_V1=1python script.py

I only see:

INFO 04-09 14:27:52 [loader.py:447] Loading weights took 0.21 seconds
INFO 04-09 14:27:52 [gpu_model_runner.py:1273] Model loading took 0.2393 GiB and 0.666895 seconds
INFO 04-09 14:27:53 [kv_cache_utils.py:578] GPU KV cache size: 502,304 tokens
INFO 04-09 14:27:53 [kv_cache_utils.py:581] Maximum concurrency for 2,048 tokens per request: 245.27x
INFO 04-09 14:27:53 [core.py:162] init engine (profile, create kv cache, warmup model) took 0.97 seconds
Starting 10000 concurrent requests

and then nothing until completion.

I research the documentation together with vLLM chatbot and came across this option:

VLLM_USE_V1=1 VLLM_LOGGING_CONFIG_PATH="logging.json" script.py

which outputs:

{"message": "Loading weights took 0.21 seconds"}
{"message": "Model loading took 0.2393 GiB and 0.746670 seconds"}
{"message": "GPU KV cache size: 502,304 tokens"}
{"message": "Maximum concurrency for 2,048 tokens per request: 245.27x"}
{"message": "init engine (profile, create kv cache, warmup model) took 0.67 seconds"}
Starting 10000 concurrent requests

and then nothing.

I know that not too long ago the metrics for V1 were still in WiP state: #10582

But according to the changelog, 0.8.3 seems to be already feature-complete in that regard.

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.

[lengrongfu]

i will to look

[dtransposed]

Thank's @lengrongfu, keep me updated.

[lengrongfu]

@dtransposed I use main branch code to running, it have metrics. you can use latest version to try it or wait next version.

[dtransposed]

Got it.

[markmc]

..

When I run VLLM_USE_V1=0 python script.py

I do see the aggregate throughput metrics being regularly shown to me:

...

INFO 04-09 14:25:12 [metrics.py:488] Avg prompt throughput: 1899.6 tokens/s, Avg generation throughput: 975.1 tokens/s, Running: 256 reqs, Swapped: 0 reqs, Pending: 9725 reqs, GPU KV cache usage: 2.9%, CPU KV cache usage: 0.0%.

however when VLLM_USE_V1=1python script.py

I only see:

...

This metric logging is implemented in V1 with v0.8.3:

$ git checkout v0.8.3
....
$ git grep -n Avg vllm/v1/
vllm/v1/metrics/loggers.py:89:            "Avg prompt throughput: %.1f tokens/s, "
vllm/v1/metrics/loggers.py:90:            "Avg generation throughput: %.1f tokens/s, "

But I think #14082 made it not work in the case of using AsyncLLM API directly. See https://github.com/vllm-project/vllm/pull/14082/files#r1977750121

@njhill FYI

[njhill]

@markmc right, there was a follow-on TODO mentioned there which I should have tracked better, to move the async task triggering the log that runs every n seconds inside AsyncLLM. This should hopefully be straightforward but we'll want to take care to avoid the task holding a ref back to the AsyncLLM obj (this is getting addressed for other async tasks in #11737).

[SunYong0821]

@dtransposed I use main branch code to running, it have metrics. you can use latest version to try it or wait next version.我使用主分支代码来运行，它有指标。您可以使用最新版本来尝试它或等待下一个版本。

Is it possible to output metrics only when a request is received? The previous version accomplished this after I commented out the function 'lifespan'.

[lengrongfu]

@dtransposed I use main branch code to running, it have metrics. you can use latest version to try it or wait next version.我使用主分支代码来运行，它有指标。您可以使用最新版本来尝试它或等待下一个版本。

Is it possible to output metrics only when a request is received? The previous version accomplished this after I commented out the function 'lifespan'.

@markmc What do you think about this requirement? I think we can add an environment variable to control it.

[SunYong0821]

@dtransposed I use main branch code to running, it have metrics. you can use latest version to try it or wait next version.我使用主分支代码来运行，它有指标。您可以使用最新版本来尝试它或等待下一个版本。@dtranspose 我使用主分支代码来运行，它有指标。您可以使用最新版本来尝试或等待下一个版本。我使用主分支代码来运行，它有指标。您可以使用最新版本来尝试它或等待下一个版本。

Is it possible to output metrics only when a request is received? The previous version accomplished this after I commented out the function 'lifespan'.是否可以仅在收到请求时输出指标？之前的版本在我注释掉“lifespan”函数后实现了这一点。

@markmc What do you think about this requirement? I think we can add an environment variable to control it.你觉得这个要求怎么样？我觉得可以添加一个环境变量来控制。

That would be great if possible! Then the nohup command wouldn't grow so large.

[bbRLdev]

I am not clear from reading this thread, does this or does this not work with v1 engine, for version vllm 0.8.5.post1?
@lengrongfu @njhill
I do not see the logs when i use v1 engine and 0.8.5.post1 and use AsyncLLMEngine class directly

[FateForever0222]

Same question, does the current vllm support output metric when VLLM_USE_V1=1 ? @njhill @lengrongfu

[schoennenbeck]

@FateForever0222 @bbRLdev Not sure if this is still relevant for you. As of 0.9.1 it does not work.

A workaround can be found here: #20175