feat: add a debug log for vm build time

Add a couple of events to the debug logs. With this information we can
extract information of how long did those events take.

Added as debug messages to make it clear to customers that these are
unstable and may change format or disappear at any moment, at should not
be depended upon.

Signed-off-by: Pablo Barbáchano <[email protected]>

Author: pb8o

src/vmm/src/builder.rs

@@ -52,7 +52,7 @@ use crate::devices::virtio::vsock::{Vsock, VsockUnixBackend};
 use crate::devices::BusDevice;
 #[cfg(target_arch = "aarch64")]
 use crate::logger;
-use crate::logger::error;
+use crate::logger::{debug, error};
 use crate::persist::{MicrovmState, MicrovmStateError};
 use crate::resources::VmResources;
 use crate::vmm_config::boot_source::BootConfig;
@@ -380,14 +380,16 @@ pub fn build_and_boot_microvm(
     event_manager: &mut EventManager,
     seccomp_filters: &BpfThreadMap,
 ) -> Result<Arc<Mutex<Vmm>>, StartMicrovmError> {
+    debug!("event_start: build microvm for boot");
     let vmm = build_microvm_for_boot(instance_info, vm_resources, event_manager, seccomp_filters)?;
-
+    debug!("event_end: build microvm for boot");
     // The vcpus start off in the `Paused` state, let them run.
+    debug!("event_start: boot microvm");
     vmm.lock()
         .unwrap()
         .resume_vm()
         .map_err(StartMicrovmError::Internal)?;
-
+    debug!("event_end: boot microvm");
     Ok(vmm)
 }
 
@@ -448,6 +450,7 @@ pub fn build_microvm_from_snapshot(
     })?;
 
     // Build Vmm.
+    debug!("event_start: build microvm from snapshot");
     let (mut vmm, mut vcpus) = create_vmm_and_vcpus(
         instance_info,
         event_manager,
@@ -545,6 +548,7 @@ pub fn build_microvm_from_snapshot(
             .get("vmm")
             .ok_or(BuildMicrovmFromSnapshotError::MissingVmmSeccompFilters)?,
     )?;
+    debug!("event_end: build microvm from snapshot");
 
     Ok(vmm)
 }

tests/integration_tests/performance/test_boottime.py

@@ -2,6 +2,7 @@
 # SPDX-License-Identifier: Apache-2.0
 """Tests that ensure the boot time to init process is within spec."""
 
+import datetime
 import re
 import time
 
@@ -153,6 +154,25 @@ def _configure_and_run_vm(microvm, network=False, initrd=False):
     microvm.start()
 
 
+def find_events(log_data):
+    """
+    Parse events in the Firecracker logs
+
+    Events have this format:
+
+        TIMESTAMP [LOGLEVEL] event_(start|end): EVENT
+    """
+    ts_fmt = "%Y-%m-%dT%H:%M:%S.%f"
+    matches = re.findall(r"(.+) \[.+\] event_(start|end): (.*)", log_data)
+    timestamps = {}
+    for ts, when, what in matches:
+        evt1 = timestamps.setdefault(what, {})
+        evt1[when] = datetime.datetime.strptime(ts[:-3], ts_fmt)
+    for _, val in timestamps.items():
+        val["duration"] = val["end"] - val["start"]
+    return timestamps
+
+
 @pytest.mark.parametrize(
     "vcpu_count,mem_size_mib",
     [(1, 128), (1, 1024), (2, 2048), (4, 4096)],
@@ -184,3 +204,11 @@ def test_boottime(
         vm.start()
         boottime_us = _get_microvm_boottime(vm)
         metrics.put_metric("boot_time", boottime_us, unit="Microseconds")
+        timestamps = find_events(vm.log_data)
+        build_time = timestamps["build microvm for boot"]["duration"]
+        metrics.put_metric("build_time", build_time.microseconds, unit="Microseconds")
+        metrics.put_metric(
+            "guest_boot_time",
+            boottime_us - build_time.microseconds,
+            unit="Microseconds",
+        )