vmm: Add some tracing of boot sequence

Add tracing of the VM boot sequence from the point at which the request
to create a VM is received to the hand-off to the vCPU threads running.

Signed-off-by: Rob Bradford <robert.bradford@intel.com>

vmm/src/acpi.rs

@@ -19,6 +19,7 @@ use bitflags::bitflags;
 use pci::PciBdf;
 use std::sync::{Arc, Mutex};
 use std::time::Instant;
+use tracer::trace_scoped;
 use vm_memory::{Address, ByteValued, Bytes, GuestAddress, GuestMemoryRegion};
 
 /* Values for Type in APIC sub-headers */
@@ -172,6 +173,7 @@ pub fn create_dsdt_table(
     cpu_manager: &Arc<Mutex<CpuManager>>,
     memory_manager: &Arc<Mutex<MemoryManager>>,
 ) -> Sdt {
+    trace_scoped!("create_dsdt_table");
     // DSDT
     let mut dsdt = Sdt::new(*b"DSDT", 36, 6, *b"CLOUDH", *b"CHDSDT  ", 1);
 
@@ -186,6 +188,8 @@ pub fn create_dsdt_table(
 }
 
 fn create_facp_table(dsdt_offset: GuestAddress, device_manager: &Arc<Mutex<DeviceManager>>) -> Sdt {
+    trace_scoped!("create_facp_table");
+
     // Revision 6 of the ACPI FADT table is 276 bytes long
     let mut facp = Sdt::new(*b"FACP", 276, 6, *b"CLOUDH", *b"CHFACP  ", 1);
 
@@ -606,6 +610,8 @@ pub fn create_acpi_tables(
     memory_manager: &Arc<Mutex<MemoryManager>>,
     numa_nodes: &NumaNodes,
 ) -> GuestAddress {
+    trace_scoped!("create_acpi_tables");
+
     let start_time = Instant::now();
     let rsdp_offset = arch::layout::RSDP_POINTER;
     let mut tables: Vec<u64> = Vec::new();

vmm/src/cpu.rs

@@ -69,6 +69,7 @@ use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::{Arc, Barrier, Mutex};
 use std::{cmp, io, result, thread};
 use thiserror::Error;
+use tracer::trace_scoped;
 use vm_device::BusDevice;
 #[cfg(feature = "guest_debug")]
 use vm_memory::ByteValued;
@@ -1127,6 +1128,8 @@ impl CpuManager {
     }
 
     pub fn create_boot_vcpus(&mut self, entry_point: Option<EntryPoint>) -> Result<()> {
+        trace_scoped!("create_boot_vcpus");
+
         self.create_vcpus(self.boot_vcpus(), entry_point)
     }
 

vmm/src/device_manager.rs

@@ -74,6 +74,7 @@ use std::path::PathBuf;
 use std::result;
 use std::sync::{Arc, Mutex};
 use std::time::Instant;
+use tracer::trace_scoped;
 use vfio_ioctls::{VfioContainer, VfioDevice, VfioDeviceFd};
 use virtio_devices::transport::VirtioTransport;
 use virtio_devices::transport::{VirtioPciDevice, VirtioPciDeviceActivator};
@@ -958,6 +959,8 @@ impl DeviceManager {
         boot_id_list: BTreeSet<String>,
         timestamp: Instant,
     ) -> DeviceManagerResult<Arc<Mutex<Self>>> {
+        trace_scoped!("DeviceManager::new");
+
         let device_tree = Arc::new(Mutex::new(DeviceTree::new()));
 
         let num_pci_segments =
@@ -1120,6 +1123,8 @@ impl DeviceManager {
         console_pty: Option<PtyPair>,
         console_resize_pipe: Option<File>,
     ) -> DeviceManagerResult<()> {
+        trace_scoped!("create_devices");
+
         let mut virtio_devices: Vec<MetaVirtioDevice> = Vec::new();
 
         let interrupt_controller = self.add_interrupt_controller()?;

vmm/src/lib.rs

@@ -46,6 +46,7 @@ use std::sync::mpsc::{Receiver, RecvError, SendError, Sender};
 use std::sync::{Arc, Mutex};
 use std::{result, thread};
 use thiserror::Error;
+use tracer::trace_scoped;
 use vm_memory::bitmap::AtomicBitmap;
 use vm_migration::{protocol::*, Migratable};
 use vm_migration::{MigratableError, Pausable, Snapshot, Snapshottable, Transportable};
@@ -524,50 +525,56 @@ impl Vmm {
     }
 
     fn vm_boot(&mut self) -> result::Result<(), VmError> {
-        // If we don't have a config, we can not boot a VM.
-        if self.vm_config.is_none() {
-            return Err(VmError::VmMissingConfig);
-        };
+        tracer::start();
+        let r = {
+            trace_scoped!("vm_boot");
+            // If we don't have a config, we can not boot a VM.
+            if self.vm_config.is_none() {
+                return Err(VmError::VmMissingConfig);
+            };
 
-        // Create a new VM if we don't have one yet.
-        if self.vm.is_none() {
-            let exit_evt = self.exit_evt.try_clone().map_err(VmError::EventFdClone)?;
-            let reset_evt = self.reset_evt.try_clone().map_err(VmError::EventFdClone)?;
-            #[cfg(feature = "gdb")]
-            let vm_debug_evt = self
-                .vm_debug_evt
-                .try_clone()
-                .map_err(VmError::EventFdClone)?;
-            let activate_evt = self
-                .activate_evt
-                .try_clone()
-                .map_err(VmError::EventFdClone)?;
+            // Create a new VM if we don't have one yet.
+            if self.vm.is_none() {
+                let exit_evt = self.exit_evt.try_clone().map_err(VmError::EventFdClone)?;
+                let reset_evt = self.reset_evt.try_clone().map_err(VmError::EventFdClone)?;
+                #[cfg(feature = "gdb")]
+                let vm_debug_evt = self
+                    .vm_debug_evt
+                    .try_clone()
+                    .map_err(VmError::EventFdClone)?;
+                let activate_evt = self
+                    .activate_evt
+                    .try_clone()
+                    .map_err(VmError::EventFdClone)?;
 
-            if let Some(ref vm_config) = self.vm_config {
-                let vm = Vm::new(
-                    Arc::clone(vm_config),
-                    exit_evt,
-                    reset_evt,
-                    #[cfg(feature = "gdb")]
-                    vm_debug_evt,
-                    &self.seccomp_action,
-                    self.hypervisor.clone(),
-                    activate_evt,
-                    None,
-                    None,
-                    None,
-                )?;
+                if let Some(ref vm_config) = self.vm_config {
+                    let vm = Vm::new(
+                        Arc::clone(vm_config),
+                        exit_evt,
+                        reset_evt,
+                        #[cfg(feature = "gdb")]
+                        vm_debug_evt,
+                        &self.seccomp_action,
+                        self.hypervisor.clone(),
+                        activate_evt,
+                        None,
+                        None,
+                        None,
+                    )?;
 
-                self.vm = Some(vm);
+                    self.vm = Some(vm);
+                }
             }
-        }
 
-        // Now we can boot the VM.
-        if let Some(ref mut vm) = self.vm {
-            vm.boot()
-        } else {
-            Err(VmError::VmNotCreated)
-        }
+            // Now we can boot the VM.
+            if let Some(ref mut vm) = self.vm {
+                vm.boot()
+            } else {
+                Err(VmError::VmNotCreated)
+            }
+        };
+        tracer::end();
+        r
     }
 
     fn vm_pause(&mut self) -> result::Result<(), VmError> {

vmm/src/memory_manager.rs

@@ -36,6 +36,7 @@ use std::os::unix::io::{AsRawFd, FromRawFd, RawFd};
 use std::path::PathBuf;
 use std::result;
 use std::sync::{Arc, Barrier, Mutex};
+use tracer::trace_scoped;
 use versionize::{VersionMap, Versionize, VersionizeResult};
 use versionize_derive::Versionize;
 use virtio_devices::BlocksState;
@@ -876,6 +877,8 @@ impl MemoryManager {
         existing_memory_files: Option<HashMap<u32, File>>,
         #[cfg(target_arch = "x86_64")] sgx_epc_config: Option<Vec<SgxEpcConfig>>,
     ) -> Result<Arc<Mutex<MemoryManager>>, Error> {
+        trace_scoped!("MemoryManager::new");
+
         let user_provided_zones = config.size == 0;
 
         let mmio_address_space_size = mmio_address_space_size(phys_bits);

vmm/src/vm.rs

@@ -86,6 +86,7 @@ use std::sync::{Arc, Mutex, RwLock};
 use std::time::Instant;
 use std::{result, str, thread};
 use thiserror::Error;
+use tracer::trace_scoped;
 use vm_device::Bus;
 #[cfg(target_arch = "x86_64")]
 use vm_device::BusDevice;
@@ -500,6 +501,8 @@ impl Vm {
         restoring: bool,
         timestamp: Instant,
     ) -> Result<Self> {
+        trace_scoped!("Vm::new_from_memory_manager");
+
         let boot_id_list = config
             .lock()
             .unwrap()
@@ -724,6 +727,8 @@ impl Vm {
         console_pty: Option<PtyPair>,
         console_resize_pipe: Option<File>,
     ) -> Result<Self> {
+        trace_scoped!("Vm::new");
+
         let timestamp = Instant::now();
 
         #[cfg(feature = "tdx")]
@@ -1097,6 +1102,7 @@ impl Vm {
         payload: &PayloadConfig,
         memory_manager: Arc<Mutex<MemoryManager>>,
     ) -> Result<EntryPoint> {
+        trace_scoped!("load_payload");
         match (
             &payload.firmware,
             &payload.kernel,
@@ -1163,6 +1169,7 @@ impl Vm {
 
     #[cfg(target_arch = "x86_64")]
     fn configure_system(&mut self, rsdp_addr: GuestAddress) -> Result<()> {
+        trace_scoped!("configure_system");
         info!("Configuring system");
         let mem = self.memory_manager.lock().unwrap().boot_guest_memory();
 
@@ -2155,6 +2162,8 @@ impl Vm {
     }
 
     fn entry_point(&mut self) -> Result<Option<EntryPoint>> {
+        trace_scoped!("entry_point");
+
         self.load_payload_handle
             .take()
             .map(|handle| handle.join().map_err(Error::KernelLoadThreadJoin)?)
@@ -2162,6 +2171,7 @@ impl Vm {
     }
 
     pub fn boot(&mut self) -> Result<()> {
+        trace_scoped!("Vm::boot");
         info!("Booting VM");
         event!("vm", "booting");
         let current_state = self.get_state()?;