Skip to content

Conversation

@phip1611
Copy link
Member

This is a small improvement to the timestamp in the logging format.

Example (old style)

cloud-hypervisor: 858.465660ms: <vcpu0> DEBUG:devices/src/ioapic.rs:154 -- IOAPIC_R @ offset 0x10
cloud-hypervisor: 858.507342ms: <vcpu0> DEBUG:devices/src/ioapic.rs:298 -- IOAPIC_R reg 0x1
cloud-hypervisor: 1.010001s: <vcpu0> DEBUG:devices/src/ioapic.rs:174 -- IOAPIC_W @ offset 0x0
cloud-hypervisor: 1.010067s: <vcpu0> DEBUG:devices/src/ioapic.rs:154 -- IOAPIC_R @ offset 0x10

Example (new style)

cloud-hypervisor:   0.731399s: <vcpu0> DEBUG:devices/src/ioapic.rs:174 -- IOAPIC_W @ offset 0x10
cloud-hypervisor:   0.731420s: <vcpu0> DEBUG:devices/src/ioapic.rs:252 -- IOAPIC_W reg 0x2a, val 0x10000
cloud-hypervisor:  17.026073s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo
cloud-hypervisor:  17.263210s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo
cloud-hypervisor:  17.547915s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo

Streamline the output format of the timestamp of a message.
The old format doesn't nicely align across multiple lines.

# Example (old style)
```
cloud-hypervisor: 858.465660ms: <vcpu0> DEBUG:devices/src/ioapic.rs:154 -- IOAPIC_R @ offset 0x10
cloud-hypervisor: 858.507342ms: <vcpu0> DEBUG:devices/src/ioapic.rs:298 -- IOAPIC_R reg 0x1
cloud-hypervisor: 1.010001s: <vcpu0> DEBUG:devices/src/ioapic.rs:174 -- IOAPIC_W @ offset 0x0
cloud-hypervisor: 1.010067s: <vcpu0> DEBUG:devices/src/ioapic.rs:154 -- IOAPIC_R @ offset 0x10
```

# Example (new style)
```
cloud-hypervisor:   0.731399s: <vcpu0> DEBUG:devices/src/ioapic.rs:174 -- IOAPIC_W @ offset 0x10
cloud-hypervisor:   0.731420s: <vcpu0> DEBUG:devices/src/ioapic.rs:252 -- IOAPIC_W reg 0x2a, val 0x10000
cloud-hypervisor:  17.026073s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo
cloud-hypervisor:  17.263210s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo
cloud-hypervisor:  17.547915s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo
```

Signed-off-by: Philipp Schuster <[email protected]>
On-behalf-of: SAP [email protected]
Signed-off-by: Philipp Schuster <[email protected]>
On-behalf-of: SAP [email protected]
@phip1611 phip1611 requested a review from a team as a code owner September 15, 2025 12:29
@russell-islam
Copy link
Contributor

Shouldn't we keep the smaller numbers as milliseconds?

@phip1611
Copy link
Member Author

Shouldn't we keep the smaller numbers as milliseconds?

Could you please elaborate a little about the value-add you see in this behavior? IMHO, having things aligned helps humans to parse the log much faster. And you have the milliseconds anyway, just in an aligned format.


let now = std::time::Instant::now();
let duration = now.duration_since(self.start);
let duration_s = duration.as_secs_f32();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks better:
let duration = self.start.elapsed().as_secs_f32();

@rbradford
Copy link
Member

Thanks @phip1611 - although this looks nice - I worry that this might break tooling that expects only a single space before the time - I see from the format string it right aligns it to 10 characters? How is that going to look when a VM is up for many months or even years?

@phip1611
Copy link
Member Author

phip1611 commented Sep 22, 2025

I see from the format string it right aligns it to 10 characters?

It would look somehow like this:

cloud-hypervisor: 171515151516.547915s: <vmm> INFO:vmm/src/api/mod.rs:898 -- API request event: VmInfo

I worry that this might break tooling that expects only a single space before the time

I see but do we make any promises for the log format?

From the README:

Currently the following items are not guaranteed across updates:

  • Snapshot/restore is not supported across different versions
  • Live migration is not supported across different versions
  • The following features are considered experimental and may change substantially between releases: TDX, vfio-user, vDPA.

So there are features for that we do not support "stability" across updates. Not sure is the log format is or should be one of them.

I don't have a very strong opinion here, it is just a quality of live improvement IMHO.

@rbradford rbradford added this pull request to the merge queue Sep 22, 2025
@github-merge-queue github-merge-queue bot removed this pull request from the merge queue due to failed status checks Sep 22, 2025
@rbradford rbradford added this pull request to the merge queue Sep 22, 2025
Merged via the queue into cloud-hypervisor:main with commit fae3241 Sep 22, 2025
42 of 44 checks passed
@likebreath likebreath moved this from 🆕 New to ✅ Done in Cloud Hypervisor Roadmap Nov 6, 2025
@phip1611 phip1611 deleted the upstream-logger-improvements branch November 25, 2025 13:07
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

Status: Done

Development

Successfully merging this pull request may close these issues.

4 participants