Add span metrics for model_forward, scheduler and sampler time

[sfc-gh-mkeralapura]

See an example trace log here
s3://ml-dev-sfc-or-dev-misc1-k8s/vllm_bench/spanlogs/mkeralapura_llama-3-70b-0ffc9601_vllm-engine_0.span_trace_log to maheshkm/mkeralapura_llama-3-70b-0ffc9601_vllm-engine_0.span_trace_log

An entry there will look like
Span #0
Trace ID : e3e70682c2094cac629f6fbed82c07cd
Parent ID :
ID : 0a5d2f346baa9455
Name : llm_request
Kind : Server
Start time : 2024-08-02 18:18:39.590171648 +0000 UTC
End time : 2024-08-02 18:18:43.366565895 +0000 UTC
Status code : Unset
Status message :
Attributes:
-> gen_ai.response.model: Str(/data-fast/s3/ml-dev-sfc-or-dev-misc1-k8s/yak/hf_models/meta-llama/Meta-Llama-3-70B)
-> gen_ai.request.id: Str(fcdae8c235f84b618c24b656f3ad4024)
-> gen_ai.request.temperature: Double(0)
-> gen_ai.request.top_p: Double(1)
-> gen_ai.request.max_tokens: Int(256)
-> gen_ai.request.best_of: Int(1)
-> gen_ai.request.n: Int(1)
-> gen_ai.usage.num_sequences: Int(1)
-> gen_ai.usage.prompt_tokens: Int(2106)
-> gen_ai.usage.completion_tokens: Int(256)
-> gen_ai.latency.time_in_queue: Double(0.012117147445678711)
-> gen_ai.latency.time_to_first_token: Double(0.2345738410949707)
-> gen_ai.latency.e2e: Double(3.775825023651123)
-> gen_ai.latency.time_in_scheduler: Double(0.017550230026245117)
-> gen_ai.latency.time_in_model_forward: Double(3.151565277099609)
-> gen_ai.latency.time_in_model_execute: Double(3.6468167304992676)
{"kind": "exporter", "data_type": "traces", "name": "debug"}

Had to put the model_forward time behind a flag since I could not get it working without the synchronize.
The synchronize does not seem to add a delay though. For example the llama3 example benchmark run 9 seconds faster (27s vs 267). Overall, our expectation is that there should be no operations pending by the time the sampler is finished. Maybe if there is no token or in some other corner case there is something pending and elapsed_time() crashes with Cuda runtime error: device is busy.

---

PR Checklist (Click to Expand)

Thank you for your contribution to vLLM! Before submitting the pull request, please ensure the PR meets the following criteria. This helps vLLM maintain the code quality and improve the efficiency of the review process.

PR Title and Classification

Only specific types of PRs will be reviewed. The PR title is prefixed appropriately to indicate the type of change. Please use one of the following:

• [Bugfix] for bug fixes.
• [CI/Build] for build or continuous integration improvements.
• [Doc] for documentation fixes and improvements.
• [Model] for adding a new model or improving an existing model. Model name should appear in the title.
• [Frontend] For changes on the vLLM frontend (e.g., OpenAI API server, LLM class, etc.)
• [Kernel] for changes affecting CUDA kernels or other compute kernels.
• [Core] for changes in the core vLLM logic (e.g., LLMEngine, AsyncLLMEngine, Scheduler, etc.)
• [Hardware][Vendor] for hardware-specific changes. Vendor name should appear in the prefix (e.g., [Hardware][AMD]).
• [Misc] for PRs that do not fit the above categories. Please use this sparingly.

Note: If the PR spans more than one category, please include all relevant prefixes.

Code Quality

The PR need to meet the following code quality standards:

• We adhere to Google Python style guide and Google C++ style guide.
• Pass all linter checks. Please use format.sh to format your code.
• The code need to be well-documented to ensure future contributors can easily understand the code.
• Include sufficient tests to ensure the project to stay correct and robust. This includes both unit tests and integration tests.
• Please add documentation to docs/source/ if the PR modifies the user-facing behaviors of vLLM. It helps vLLM user understand and utilize the new features or changes.

Notes for Large Changes

Please keep the changes as concise as possible. For major architectural changes (>500 LOC excluding kernel/data/config/test), we would expect a GitHub issue (RFC) discussing the technical design and justification. Otherwise, we will tag it with rfc-required and might not go through the PR.

What to Expect for the Reviews

The goal of the vLLM team is to be a transparent reviewing machine. We would like to make the review process transparent and efficient and make sure no contributor feel confused or frustrated. However, the vLLM team is small, so we need to prioritize some PRs over others. Here is what you can expect from the review process:

• After the PR is submitted, the PR will be assigned to a reviewer. Every reviewer will pick up the PRs based on their expertise and availability.
• After the PR is assigned, the reviewer will provide status update every 2-3 days. If the PR is not reviewed within 7 days, please feel free to ping the reviewer or the vLLM team.
• After the review, the reviewer will put an action-required label on the PR if there are changes required. The contributor should address the comments and ping the reviewer to re-review the PR.
• Please respond to all comments within a reasonable time frame. If a comment isn't clear or you disagree with a suggestion, feel free to ask for clarification or discuss the suggestion.

Thank You

Finally, thank you for taking the time to read these guidelines and for your interest in contributing to vLLM. Your contributions make vLLM a great tool for everyone!

[github-actions]

👋 Hi! Thank you for contributing to the vLLM project.
Just a reminder: PRs would not trigger full CI run by default. Instead, it would only run fastcheck CI which consists a small and essential subset of CI tests to quickly catch errors. You can run other CI tests on top of default ones by unblocking the steps in your fast-check build on Buildkite UI.

Once the PR is approved and ready to go, please make sure to run full CI as it is required to merge (or just use auto-merge).

To run full CI, you can do one of these:

• Comment /ready on the PR
• Add ready label to the PR
• Enable auto-merge.

🚀

[sfc-gh-aqiao]

is it possible to count time being swapped out separately? I think counting scheduler time for a non-running request is a bit hard to interpret, because we'd normally want to compare it with model forward time and execute time to understand the overhead, and those are only collected for running requests.

[sfc-gh-mkeralapura]

For now, counted scheduler time only over the running ones.

For a future change, we can track a different metric of swapped_out_time for each request.

[sfc-gh-aqiao]

it looks like there's a Event.synchronize() which seems a better fit than this global synchronize() https://pytorch.org/docs/stable/generated/torch.cuda.Event.html

[sfc-gh-mkeralapura]

Done. Thanks for the tip!

[sfc-gh-aqiao]

extraneous change

[sfc-gh-mkeralapura]

Done.