vmm: guest boot time in CPU us and wall clock us

Signed-off-by: Alexandra Iordache <[email protected]>

Author: Alexandra Iordache

vmm/Cargo.toml

@@ -4,6 +4,7 @@ version = "0.1.0"
 authors = ["Amazon firecracker team <[email protected]>"]
 
 [dependencies]
+chrono = ">=0.4"
 libc = ">=0.2.39"
 epoll = "=2.1.0"
 futures = ">=0.1.18"
@@ -15,6 +16,7 @@ timerfd = ">=1.0"
 
 data_model = { path = "../data_model" }
 devices = { path = "../devices" }
+fc_util = { path = "../fc_util" }
 kernel = { path = "../kernel" }
 kvm = { path = "../kvm" }
 logger = { path = "../logger" }

vmm/src/lib.rs

@@ -1,3 +1,4 @@
+extern crate chrono;
 extern crate epoll;
 extern crate futures;
 extern crate libc;
@@ -9,6 +10,7 @@ extern crate timerfd;
 
 extern crate data_model;
 extern crate devices;
+extern crate fc_util;
 extern crate kernel;
 extern crate kvm;
 #[macro_use]
@@ -50,6 +52,7 @@ use device_manager::legacy::LegacyDeviceManager;
 use device_manager::mmio::MMIODeviceManager;
 use devices::virtio;
 use devices::{DeviceEventT, EpollHandler, EpollHandlerPayload};
+use fc_util::now_cputime_us;
 use kernel::cmdline as kernel_cmdline;
 use kernel::loader as kernel_loader;
 use kvm::*;
@@ -71,6 +74,7 @@ const DEFAULT_KERNEL_CMDLINE: &str = "reboot=k panic=1 pci=off nomodules 8250.nr
 const VCPU_RTSIG_OFFSET: i32 = 0;
 const WRITE_METRICS_PERIOD_SECONDS: u64 = 60;
 static START_INSTANCE_REQUEST_TS: AtomicUsize = ATOMIC_USIZE_INIT;
+static START_INSTANCE_REQUEST_CPU_TS: AtomicUsize = ATOMIC_USIZE_INIT;
 
 /// Errors associated with the VMM internal logic. These errors cannot be generated by direct user
 /// input, but can result from bad configuration of the host (for example if Firecracker doesn't
@@ -807,12 +811,22 @@ impl Vmm {
                                         if addr == MAGIC_IOPORT_SIGNAL_GUEST_BOOT_COMPLETE
                                             && data[0] == MAGIC_VALUE_SIGNAL_GUEST_BOOT_COMPLETE
                                         {
-                                            let boot_time_ns = time::precise_time_ns() as usize
+                                            let now_cpu_us = now_cputime_us();
+                                            let now_us =
+                                                chrono::Utc::now().timestamp_nanos() / 1000;
+
+                                            let boot_time_us = now_us as usize
                                                 - START_INSTANCE_REQUEST_TS.load(Ordering::Acquire);
+                                            let boot_time_cpu_us = now_cpu_us as usize
+                                                - START_INSTANCE_REQUEST_CPU_TS
+                                                    .load(Ordering::Acquire);
                                             warn!(
-                                                "Guest-boot-time = {:>6} us {} ms",
-                                                boot_time_ns / 1000,
-                                                boot_time_ns / 1000000
+                                                "Guest-boot-time = {:>6} us {} ms, \
+                                                 {:>6} CPU us {} CPU ms",
+                                                boot_time_us,
+                                                boot_time_us / 1000,
+                                                boot_time_cpu_us,
+                                                boot_time_cpu_us / 1000
                                             );
                                         }
                                         io_bus.write(addr as u64, data);
@@ -955,7 +969,11 @@ impl Vmm {
     }
 
     fn start_microvm(&mut self) -> std::result::Result<VmmData, VmmActionError> {
-        START_INSTANCE_REQUEST_TS.store(time::precise_time_ns() as usize, Ordering::Release);
+        START_INSTANCE_REQUEST_CPU_TS.store(now_cputime_us() as usize, Ordering::Release);
+        START_INSTANCE_REQUEST_TS.store(
+            (chrono::Utc::now().timestamp_nanos() / 1000) as usize,
+            Ordering::Release,
+        );
         info!("VMM received instance start command");
         if self.is_instance_initialized() {
             return Err(VmmActionError::StartMicrovm(