[Bug]: Metrics time_to_first_token_seconds, time_per_output_token_seconds not working correctly

[thies1006]

Your current environment

vllm==0.5.1

🐛 Describe the bug

python -m vllm.entrypoints.openai.api_server --model /secondary/thies/Hermes-2-Theta-Llama-3-70B/ --tensor-parallel-size 8 --max-num-batched-tokens 8192

The entries of the histograms

• time_to_first_token_seconds
• time_per_output_token_seconds

are identical for all buckets, so the time values are apparently always 0 seconds.

# HELP vllm:time_to_first_token_seconds Histogram of time to first token in seconds.
# TYPE vllm:time_to_first_token_seconds histogram
vllm:time_to_first_token_seconds_bucket{le="0.001",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.005",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.01",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.02",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.04",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.06",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.08",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.1",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.25",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.5",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="0.75",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="1.0",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="2.5",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="5.0",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="7.5",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="10.0",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_bucket{le="+Inf",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_count{model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 208.0
vllm:time_to_first_token_seconds_sum{model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 0.011674165725708008
# HELP vllm:time_per_output_token_seconds Histogram of time per output token in seconds.
# TYPE vllm:time_per_output_token_seconds histogram
vllm:time_per_output_token_seconds_bucket{le="0.01",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.025",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.05",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.075",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.1",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.15",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.2",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.3",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.4",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.5",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="0.75",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="1.0",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="2.5",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_bucket{le="+Inf",model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0
vllm:time_per_output_token_seconds_count{model_name="/secondary/thies/Hermes-2-Theta-Llama-3-70B/"} 2493.0

[AllenDou]

@thies1006 Consider increasing the prompt length. You may see a difference in the results

[ashgold]

@AllenDou
same on me.

Since v0.5.x, this same symptom occurs.
The average number of input tokens per request is 1.5K and the average number of response tokens is 0.2K.

[AllenDou]

@AllenDou same on me.

Since v0.5.x, this same symptom occurs. The average number of input tokens per request is 1.5K and the average number of response tokens is 0.2K.

Could you show your model(public model is better) & test data & method(chat or completion)?

[AllenDou]

#6686 @ashgold @thies1006

[yejingfu]

duplicated #6507

[AllenDou]

duplicated #6507

fixed by #6686

[thies1006]

just checked, metrics are now fine for me in v0.5.4 (unrelated: need to use --disable-frontend-multiprocessing in this version)