From c52e276a5c2a2f268a0d3d54a27f4b368bbe6546 Mon Sep 17 00:00:00 2001 From: Samuel Ortiz Date: Wed, 14 Aug 2019 15:25:32 +0200 Subject: [PATCH] vmm: Log debug ioport timestamps We timestamp the VM creation time, and log the elapsed time between that instant and the debug ioport events. Signed-off-by: Samuel Ortiz --- vmm/src/vm.rs | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/vmm/src/vm.rs b/vmm/src/vm.rs index 32ed4a0a2..3c88b2337 100755 --- a/vmm/src/vm.rs +++ b/vmm/src/vm.rs @@ -396,6 +396,7 @@ pub struct Vcpu { io_bus: devices::Bus, mmio_bus: devices::Bus, ioapic: Option>>, + vm_ts: std::time::Instant, } impl Vcpu { @@ -420,6 +421,7 @@ impl Vcpu { io_bus, mmio_bus, ioapic, + vm_ts: vm.creation_ts, }) } @@ -503,7 +505,15 @@ impl Vcpu { // Log debug io port codes. fn log_debug_ioport(&self, code: u8) { - debug!("{} (code 0x{:x})", DebugIoPortRange::from_u8(code), code); + let ts = self.vm_ts.elapsed(); + + debug!( + "[{} code 0x{:x}] {}.{:>06} seconds", + DebugIoPortRange::from_u8(code), + code, + ts.as_secs(), + ts.as_micros() + ); } } @@ -1314,6 +1324,7 @@ pub struct Vm<'a> { config: VmConfig<'a>, epoll: EpollContext, on_tty: bool, + creation_ts: std::time::Instant, } impl<'a> Vm<'a> { @@ -1321,6 +1332,7 @@ impl<'a> Vm<'a> { let kernel = File::open(&config.kernel.path).map_err(Error::KernelFile)?; let fd = kvm.create_vm().map_err(Error::VmCreate)?; let fd = Arc::new(fd); + let creation_ts = std::time::Instant::now(); // Init guest memory let arch_mem_regions = arch::arch_memory_regions(config.memory.size); @@ -1513,6 +1525,7 @@ impl<'a> Vm<'a> { config, epoll, on_tty, + creation_ts, }) }