nvme_driver: add admin pending command tracing#3070
nvme_driver: add admin pending command tracing#3070gurasinghMS merged 10 commits intomicrosoft:mainfrom
Conversation
There was a problem hiding this comment.
Pull request overview
Adds diagnostic tracing to the NVMe driver to help understand when admin-queue commands are still pending at save time (and for how long), plus a small test failure-message cleanup.
Changes:
- Track an
issued_attimestamp for pending admin-queue commands. - Emit tracing events for pending admin commands during
QueueHandler::save(). - Update a vmm_test assertion message to avoid hard-coding a specific timeout value.
Reviewed changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated 1 comment.
| File | Description |
|---|---|
vmm_tests/vmm_tests/tests/tests/multiarch/openhcl_servicing.rs |
Updates an assertion message to reference the configured timeout rather than a specific duration. |
vm/devices/storage/disk_nvme/nvme_driver/src/queue_pair.rs |
Adds per-command timing for admin-queue pending commands and attempts to log pending durations at save time. |
alandau
left a comment
There was a problem hiding this comment.
A few small comments, the main one being about the eager evaluation.
| #[inspect(with = "|x| x.map(|elapsed| elapsed.elapsed().as_secs_f64())")] | ||
| elapsed: Option<Instant>, |
There was a problem hiding this comment.
The elapsed field actually stores a submission timestamp (Instant), not an elapsed duration. This is confusing (especially with the inspect formatter computing elapsed() on it). Consider renaming the field to something like submitted_at/submitted_instant (or similar) and update the logging/inspect label accordingly so the name matches the stored value.
| #[inspect(with = "|x| x.map(|elapsed| elapsed.elapsed().as_secs_f64())")] | |
| elapsed: Option<Instant>, | |
| #[inspect(with = "|x| x.map(|instant| instant.elapsed().as_secs_f64())")] | |
| submitted_at: Option<Instant>, |
There was a problem hiding this comment.
@alandau on the topic of naming here: naming it "submitted_at" but having inspect log the elapsed time doesn't make much sense. What do you think?
There was a problem hiding this comment.
We can call the field submitted_at, and rename the field only for inspect: #inspect[with = "....", rename = "elapsed"]. Good idea on printing elapsed rather than the instant.
BTW, I'm wary of using floats for time sensitive things (which might not be the case here, since we're doing this only for admin commands, but still). We can do e.g. .as_millis() as u64. A u64 millis should last for a bazillion years. Up to you.
Adds some tracing only for pending commands on the admin queue and how long we have waited for them at the time of save.
Adds some tracing only for pending commands on the admin queue and how long we have waited for them at the time of save.
Adds some tracing only for pending commands on the admin queue and how long we have waited for them at the time of save.