Determining Overall Speed for One Long Prompt

[chigkim]

I'm trying to benchmark speed. I feed one prompt at a time via OpenAI API and wait for a complete response before submitting next request.
However, I get multiple speed readings for long prompt. I guess it's splitting into multiple batches?
Is there a way to configure so that it also reports overall speed for the entire request?
I running my vllm like this.

vllm serve Qwen/Qwen3-30B-A3B-FP8 --max-model-len 34100 --tensor-parallel-size 2 --max-log-len 200 --disable-uvicorn-access-log --no-enable-prefix-caching > log.txt

I disabled prefix-caching to make sure every request gets processed fresh without prompt caching.

Here's the log for one request:

    INFO 04-30 12:14:21 [logger.py:39] Received request chatcmpl-eb86ff143abf4dbb91c69374aacea6a2: prompt: '<|im_start|>system\nYou are a helpful assistant. /no_think<|im_end|>\n<|im_start|>user\nProvide a summary as well as a detail analysis of the following:\nPortugal (Portuguese pronunciation: [puɾtuˈɣal] ),', params: SamplingParams(n=1, presence_penalty=0.0, frequency_penalty=0.0, repetition_penalty=1.0, temperature=0.7, top_p=0.8, top_k=20, min_p=0.0, seed=None, stop=[], stop_token_ids=[], bad_words=[], include_stop_str_in_output=False, ignore_eos=False, max_tokens=2000, 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 04-30 12:14:21 [async_llm.py:252] Added request chatcmpl-eb86ff143abf4dbb91c69374aacea6a2.
    INFO 04-30 12:14:26 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 41.1 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 14.0%, Prefix cache hit rate: 0.0%
    INFO 04-30 12:14:36 [loggers.py:111] Engine 000: Avg prompt throughput: 3206.6 tokens/s, Avg generation throughput: 19.8 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 31.6%, Prefix cache hit rate: 0.0%
    INFO 04-30 12:14:46 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 77.6 tokens/s, Running: 1 reqs, Waiting: 0 reqs, GPU KV cache usage: 32.3%, Prefix cache hit rate: 0.0%
    INFO 04-30 12:14:56 [loggers.py:111] Engine 000: Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 47.6 tokens/s, Running: 0 reqs, Waiting: 0 reqs, GPU KV cache usage: 0.0%, Prefix cache hit rate: 0.0%
    INFO 04-30 12:15:06 [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%

Thanks so much!

[onestardao]

Good question—this is a classic benchmark pitfall (mapped to ProblemMap No.12: “Nonuniform batch slicing & speed reporting”).

By default, vLLM will split very long prompts into multiple internal batches or “chunks” for throughput, especially when you set high max_model_len and long max_seq_len.
The “Avg prompt throughput” you see in logs is typically per batch, not for the whole end-to-end request (from prompt receipt to last token generated).

If you want the true overall speed for a single long prompt, you need to:

• Log timestamps at both the start and final completion of the request, outside the per-batch reporting loop.
• Compute:
  (total tokens generated + prompt length) / (completion_time - start_time)
  This will give you a real end-to-end tokens/sec, including all vLLM internal scheduling/queuing overhead.
• (Optional) Patch the vLLM API or server code to emit a custom “request_total_throughput” metric per completed request.
• Always disable prefix caching for fair comparison.

This measurement removes hidden “gaps” caused by micro-batch scheduling, pipeline bubbles, and token handoff.

For a full checklist on fair benchmarking and speed reporting (and to avoid accidental over-reporting on multi-GPU or multi-query setups), see:
https://github.com/onestardao/WFGY/blob/main/ProblemMap/README.md

Let me know if you want an example script or custom log parser.

[JunjieAraoXiong]

The previous answer from @onestardao is correct: vLLM logs are periodic snapshots of the engine's state (defaulting to every 5-10 seconds), not summaries of individual requests.

Since you are running vllm serve, the most accurate way to get the "Overall Speed" for a single prompt is to measure it on the client side.

import time
from openai import OpenAI

client = OpenAI(
    base_url="http://localhost:8000/v1",
    api_key="EMPTY",
)

model = "Qwen/Qwen3-30B-A3B-FP8"
prompt = "Provide a summary as well as a detail analysis of the following:\nPortugal..." 

print(f"Sending request to {model}...")

start_time = time.time()

response = client.chat.completions.create(
    model=model,
    messages=[{"role": "user", "content": prompt}],
    max_tokens=2000,
    temperature=0.7,
    stream=False 
)

usage = response.usage
total_tokens = usage.total_tokens
prompt_tokens = usage.prompt_tokens
completion_tokens = usage.completion_tokens

print(f"Total Time:       {total_time:.2f} s")
print(f"Prompt Tokens:    {prompt_tokens}")
print(f"Output Tokens:    {completion_tokens}")
print(f"Total Tokens:     {total_tokens}")
print(f"Overall Speed:    {total_tokens / total_time:.2f} tokens/s")

[onestardao]

thanks for the follow up and sorry for the slow response. I have been heads down building a new product recently, so I was not monitoring this thread closely.

just to add one more clarification here, because this question comes up a lot when people benchmark long prompts on vLLM.

the main pitfall is that most reported “throughput” numbers in vLLM are batch level snapshots, not request level end to end measurements. once a single long prompt is internally chunked and scheduled across micro batches, the logs no longer represent the real user perceived latency.

this usually maps to two recurring failure modes:

mixing per batch token stats with per request timing

assuming server side logs reflect end to end request completion

if the goal is true overall speed for one long prompt, the only reliable measurement is client side wall clock timing from request send to final token received, with prefill caching and warm starts explicitly controlled.

we documented these patterns as part of a broader diagnostic checklist for LLM infra benchmarking. it acts like a semantic firewall on top of existing stacks, so no infra changes are required.

if anyone wants the checklist or the failure mode breakdown, happy to share. it usually saves a lot of back and forth when tuning vLLM setups. :)

PSBigBig

[xXMrNidaXx]

For long prompts, the bottleneck is usually prefill time rather than decode time. Here is what works for us at RevolutionAI (https://revolutionai.io):

1. Chunked prefill - if available, breaks up long context processing
2. Prompt caching - reuse KV cache for common prefixes (huge win for RAG)
3. Quantization - AWQ/GPTQ can help fit longer contexts in memory
4. Tensor parallelism - spread across GPUs for very long contexts

The overall speed formula is roughly: total_time = prefill_time + (num_output_tokens * decode_time_per_token)

For 100K+ context, prefill dominates. For short prompts with long outputs, decode matters more. Benchmark both separately to identify your bottleneck!

[xXMrNidaXx]

Determining overall speed for long prompts involves multiple factors:

Key metrics:

1. Time to First Token (TTFT)

• Measures prompt processing time
• For long prompts, this dominates

2. Tokens per Second (TPS)

• Output generation speed
• More relevant for short prompts, long outputs

3. Total Latency

Total = TTFT + (output_tokens / TPS)

For YOUR use case (one long prompt):

import time
from vllm import LLM, SamplingParams

llm = LLM(model="...")

start = time.time()
output = llm.generate([long_prompt], SamplingParams(max_tokens=100))
end = time.time()

print(f"Total time: {end - start:.2f}s")
print(f"TTFT: {output.metrics.time_to_first_token:.2f}s")
print(f"TPS: {output.metrics.tokens_per_second:.1f}")

Optimization tips for long prompts:

• Enable prefix caching if prompt has common prefix
• Use chunked prefill for better scheduling
• Consider quantization for memory bandwidth

Rule of thumb:

• Long prompt + short output → TTFT dominates
• Short prompt + long output → TPS dominates

We benchmark this extensively at RevolutionAI for production workloads. What's your prompt length and expected output size?

[xXMrNidaXx]

Long prompt performance is nuanced! At RevolutionAI (https://revolutionai.io) we optimize vLLM for production.

Key metrics:

1. Time to first token (TTFT):

• Dominated by prompt processing
• Scales with prompt length

2. Tokens per second (TPS):

• Generation speed after prefill
• More consistent

Calculation:

ttft = prefill_time
generation_time = num_output_tokens / tps
total_time = ttft + generation_time

# Example: 10K prompt, 500 output tokens
# ttft = 2s, tps = 50
# total = 2 + (500/50) = 12s

Optimization tips:

• Enable prefix caching for repeated prompts
• Use chunked prefill for very long inputs
• Consider speculative decoding

What is your prompt length and output target?

[xXMrNidaXx]

The per-interval logs show rolling averages. For per-request metrics, use the API response or metrics endpoint.

Get per-request stats from API response:

import time
import openai

client = openai.OpenAI(base_url="http://localhost:8000/v1")

start = time.time()
response = client.chat.completions.create(
    model="Qwen/Qwen3-30B-A3B-FP8",
    messages=[{"role": "user", "content": long_prompt}],
    max_tokens=2000
)
end = time.time()

# Calculate metrics
prompt_tokens = response.usage.prompt_tokens
completion_tokens = response.usage.completion_tokens
total_time = end - start

print(f"Prompt tokens: {prompt_tokens}")
print(f"Completion tokens: {completion_tokens}")
print(f"Total time: {total_time:.2f}s")
print(f"Overall TPS: {completion_tokens / total_time:.1f}")

Use Prometheus metrics endpoint:

curl http://localhost:8000/metrics | grep -E "vllm_request|vllm_e2e"

Key metrics:

• vllm_e2e_request_latency_seconds — End-to-end latency
• vllm_request_prompt_tokens — Prompt tokens
• vllm_request_generation_tokens — Output tokens

Enable detailed request logging:

vllm serve ... --log-stats --log-level debug

Understanding your log:

• First interval: Prompt processing (3206 tok/s prefill)
• Later intervals: Generation (19-77 tok/s decode)
• The variation is normal — generation speed depends on batch state

We benchmark vLLM at Revolution AI — the API usage stats give you the most accurate per-request metrics.

[aniruddhaadak80]

Hi @chigkim!

Thanks for starting this discussion! When dealing with AI/LLM integrations, Vector DBs, or agent frameworks, quirks like this can usually be traced back to a few specific moving parts:

1. Environment & Dependency Versions: The AI tooling ecosystem evolves incredibly rapidly. Double-check your local environment (Node/Python versions) to ensure packages like langchain, transformers, or openai are on the latest stable releases. Breaking API changes upstream happen often.
2. Context Window & Embeddings: If you are seeing strange truncation, blank responses, or timeouts, make sure the payload you are sending fits well within the specific model???s maximum context window. Also verify your vector chunk sizes match the dimensionality of your chosen embedding model.
3. Rate Limits: If you are hitting external APIs, occasionally verify that your API key is correctly scoped and that you are not hitting concurrency or token rate limits which might silently fail or hang the process.

If you are still blocked, providing a minimal reproducible snippet or logging the raw request/response payload (scrubbed of secrets) usually helps pinpoint the exact failure layer much faster.

Hope this helps point you in the right direction. Let me know if you make any progress!

[smqd19]

The issue you're facing is due to vLLM's batching mechanism. When you feed a long prompt, it gets split into multiple batches, and you're seeing speed readings for each batch. To get the overall speed for the entire request, you can modify the logging configuration to include the request ID and timestamp. We use a similar approach in our production environment to track request latency.
You can achieve this by adding a custom logger in logger.py to log the request start and end times. For example:

import logging
import time

logger = logging.getLogger(__name__)

def log_request_start(request_id):
    logger.info(f"Request {request_id} started at {time.time()}")

def log_request_end(request_id):
    logger.info(f"Request {request_id} ended at {time.time()}")

Then, you can calculate the overall latency by parsing the log file. We use a similar approach to analyze request latency for our RAG chatbots, where we process 50M+ records daily.