From 1202b9a07ad78f0ea97866256801386392c70534 Mon Sep 17 00:00:00 2001 From: Rob Bradford Date: Fri, 16 Sep 2022 16:56:36 +0100 Subject: [PATCH] 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 --- vmm/src/acpi.rs | 6 +++ vmm/src/cpu.rs | 3 ++ vmm/src/device_manager.rs | 5 +++ vmm/src/lib.rs | 85 +++++++++++++++++++++------------------ vmm/src/memory_manager.rs | 3 ++ vmm/src/vm.rs | 10 +++++ 6 files changed, 73 insertions(+), 39 deletions(-) diff --git a/vmm/src/acpi.rs b/vmm/src/acpi.rs index a439ccb77..fefcb90d1 100644 --- a/vmm/src/acpi.rs +++ b/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>, memory_manager: &Arc>, ) -> 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>) -> 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>, 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 = Vec::new(); diff --git a/vmm/src/cpu.rs b/vmm/src/cpu.rs index 5eadfc74e..02522e25d 100644 --- a/vmm/src/cpu.rs +++ b/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) -> Result<()> { + trace_scoped!("create_boot_vcpus"); + self.create_vcpus(self.boot_vcpus(), entry_point) } diff --git a/vmm/src/device_manager.rs b/vmm/src/device_manager.rs index edd065537..1703bcf93 100644 --- a/vmm/src/device_manager.rs +++ b/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, timestamp: Instant, ) -> DeviceManagerResult>> { + 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, console_resize_pipe: Option, ) -> DeviceManagerResult<()> { + trace_scoped!("create_devices"); + let mut virtio_devices: Vec = Vec::new(); let interrupt_controller = self.add_interrupt_controller()?; diff --git a/vmm/src/lib.rs b/vmm/src/lib.rs index 4da452d77..488bbfc6b 100644 --- a/vmm/src/lib.rs +++ b/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> { diff --git a/vmm/src/memory_manager.rs b/vmm/src/memory_manager.rs index f170d571e..65f2a37d6 100644 --- a/vmm/src/memory_manager.rs +++ b/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>, #[cfg(target_arch = "x86_64")] sgx_epc_config: Option>, ) -> Result>, Error> { + trace_scoped!("MemoryManager::new"); + let user_provided_zones = config.size == 0; let mmio_address_space_size = mmio_address_space_size(phys_bits); diff --git a/vmm/src/vm.rs b/vmm/src/vm.rs index 25c6acc96..a824449b9 100644 --- a/vmm/src/vm.rs +++ b/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 { + trace_scoped!("Vm::new_from_memory_manager"); + let boot_id_list = config .lock() .unwrap() @@ -724,6 +727,8 @@ impl Vm { console_pty: Option, console_resize_pipe: Option, ) -> Result { + trace_scoped!("Vm::new"); + let timestamp = Instant::now(); #[cfg(feature = "tdx")] @@ -1097,6 +1102,7 @@ impl Vm { payload: &PayloadConfig, memory_manager: Arc>, ) -> Result { + 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> { + 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()?;