[Misc] Accurately capture the time of loading weights

[waltforme]

This PR tries to better capture the time of loading weights.

As we know, there are two major phases when loading a model: (A) downloading model if not in cache, and (B) loading weights.

Due to the lazy nature of generators that yield tensors one by one, the downloading phase is not executed until a load_weights method of the corresponding model begins to iterate over the generator.

So, in order to accurately capture the time of loading weights, we need to start our stopwatch after downloading is finished and before the first tensor is yielded. That's the general idea of this PR.

[github-actions]

👋 Hi! Thank you for contributing to the vLLM project.

💬 Join our developer Slack at https://slack.vllm.ai to discuss your PR in #pr-reviews, coordinate on features in #feat- channels, or join special interest groups in #sig- channels.

Just a reminder: PRs would not trigger full CI run by default. Instead, it would only run fastcheck CI which starts running only a small and essential subset of CI tests to quickly catch errors. You can run other CI tests on top of those by going to your fastcheck build on Buildkite UI (linked in the PR checks section) and unblock them. If you do not have permission to unblock, ping simon-mo or khluu to add you in our Buildkite org.

Once the PR is approved and ready to go, your PR reviewer(s) can run CI to test the changes comprehensively before merging.

To run CI, PR reviewers can either: Add ready label to the PR or enable auto-merge.

🚀

[ywang96]

Thanks for the PR!

I gave this PR a try with meta-llama/Llama-3.2-1B and this is what it looks like on V0.

INFO 03-01 07:56:47 [weight_utils.py:273] Time spent downloading weights for meta-llama/Llama-3.2-1B: 14.584169 seconds
INFO 03-01 07:56:47 [weight_utils.py:307] No model.safetensors.index.json found in remote.
Loading safetensors checkpoint shards:   0% Completed | 0/1 [00:00<?, ?it/s]
Loading safetensors checkpoint shards: 100% Completed | 1/1 [00:05<00:00,  5.31s/it]
Loading safetensors checkpoint shards: 100% Completed | 1/1 [00:05<00:00,  5.31s/it]

INFO 03-01 07:56:52 [loader.py:423] Loading weights took 5.38 seconds
INFO 03-01 07:56:53 [model_runner.py:1117] Loading model weights took 2.3185 GB and 20.256478 seconds

I left a minor comment - please take a look!

[ywang96]

Let's update this on V0 as well?

I also think logger.info("Model loading took %.4f GB and %.6f seconds", sounds more natural and less confusing!

[waltforme]

Good point, thanks!
Latest push tweaks the wording as suggested, and contains the same change for V0.

[ywang96]

LGTM! Thanks for this QoL change!