[Bug]: last_token_time is equal to arrival_time

[wolfgangsmdt]

Your current environment

The bug is not related to the envirement

Model Input Dumps

The bug does not related to the model

🐛 Describe the bug

QUESTION 1:

How do you calculate the RequestMetrics in RequestOutput please look at screen-shot below (in YELLOW):

I have found here in L. 696 that last_token_time is equal to arrival_time !!! IS IT A BUG?

Could you please tell me what unit is the time is it second? nanosecond? I believe it is something like this example below (correct me if I am wrong):

import time
arrival_time = time.perf_counter()

QUESTION 2:

How can I calculate the tokens/second (for output), TTFT, TBT, throughput and total time

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.

[DarkLight1337]

cc @comaniac

[comaniac]

The line you pointed out isn't a bug and isn't the root cause of the issue you're reporting. After all, we don't know the last token time when creating this object upon receiving the request. It will be updated when seq_group.get_last_latency() is called, so we should try to understand why it's not being called for the request.

[wolfgangsmdt]

The line you pointed out isn't a bug and isn't the root cause of the issue you're reporting. After all, we don't know the last token time when creating this object upon receiving the request. It will be updated when seq_group.get_last_latency() is called, so we should try to understand why it's not being called for the request.

Thanks for the reply @comaniac .
What do you need from me like informations to help you fix the issue.

My goal is to have TTFT, TBT and Tokens/second

Thanks

[comaniac]

I don't have bandwidth to look into it now but it shouldn't be hard to fix. Please feel free to submit a PR if you are able to fix it and I'll help review, or I may try to fix that in my spare time (but cannot guarantee any timeline).

[sri-fiddler]

@wolfgangsmdt, the last_token_time is updated in the following line.

vllm/vllm/sequence.py

Line 801 in ccb5376

self.metrics.last_token_time = now

But I am curious as to how the time to first token can be calculated. Would it be first_token_time - arrival_time?

[wolfgangsmdt]

@sri-fiddler
I do not know why I have them the same.

For me to have the time to first token (TTFT) it will be as you said but in reverse first_token_time - arrival_time

So for me:

# TTFT (second)
ttft_s = first_token_time - arrival_time

# Total time (second) 
total_time_s = finished_time - arrival_time

# Tokens/second
tps = len(outputs[0].token_ids) / abs(last_token_time - first_token_time)

# Total throughput (for me I believe)
total_throughput = len(outputs[0].token_ids) / total_time_s

However, what is weird to me is that first_token_time is higher than last_token_time this is why I put abs (absolute value) to get the tokens/second.

Any idea on how to get the time between tokens (TBT)

[sri-fiddler]

Yes, @wolfgangsmdt, you're right. I've made the changes on my end too.

I figured that last_token_time - first_token_time would be the time between tokens, however, I get a negative value here, which is surprising.