From 2515b06f1938a12a98f4926539a2d481f8fe09bf Mon Sep 17 00:00:00 2001 From: Philipp Schuster Date: Wed, 8 Apr 2026 16:04:30 +0200 Subject: [PATCH] vmm: incoming migration: log duration of state receive and VM resume Instrument the two main downtime-phase operations on the destination side - receiving state and resuming the VM - so their costs are visible in logs and can be iterated on. The new log messages may look like this: ```text cloud-hypervisor: 7.283424s: DEBUG:vmm/src/lib.rs:948 -- Migration (incoming): recv_snapshot:3ms restore:10ms cloud-hypervisor: 7.284824s: DEBUG:vmm/src/lib.rs:967 -- Migration (incoming): resume:1ms cloud-hypervisor: 7.284842s: DEBUG:vmm/src/lib.rs:977 -- Migration (incoming): Receiving final state and resuming the VM took 15ms ``` On-behalf-of: SAP philipp.schuster@sap.com Signed-off-by: Philipp Schuster --- vmm/src/lib.rs | 126 +++++++++++++++++++++++++++++++++---------------- 1 file changed, 85 insertions(+), 41 deletions(-) diff --git a/vmm/src/lib.rs b/vmm/src/lib.rs index 5cedeef65..df94b54e2 100644 --- a/vmm/src/lib.rs +++ b/vmm/src/lib.rs @@ -653,7 +653,10 @@ enum ReceiveMigrationState { Configured(ReceiveMigrationConfiguredData), /// Memory is populated and we received the state. The VM is ready to go. - StateReceived, + StateReceived { + /// The timestamp where the VMM started to receive the final state. + state_receive_begin: Instant, + }, /// The migration is successful. Completed, @@ -938,18 +941,43 @@ impl Vmm { Ok(Configured(config_data)) } Command::State => { + let state_receive_begin = Instant::now(); config_data.connections.cleanup()?; - self.vm_receive_state(req, socket, config_data.memory_manager)?; - Ok(StateReceived) + let (recv_state_dur, restore_vm_dur) = + self.vm_receive_state(req, socket, config_data.memory_manager)?; + debug!( + "Migration (incoming): recv_snapshot:{}ms restore:{}ms", + recv_state_dur.as_millis(), + restore_vm_dur.as_millis(), + ); + Ok(StateReceived { + state_receive_begin, + }) } _ => invalid_command(), }, - StateReceived => match req.command() { + StateReceived { + state_receive_begin, + } => match req.command() { Command::Complete => { // The unwrap is safe, because the state machine makes sure we called // vm_receive_state before, which creates the VM. let vm = self.vm.as_mut().unwrap(); - vm.resume()?; + let (_, resume_duration) = measure_ok(|| vm.resume())?; + debug!( + "Migration (incoming): resume:{}ms", + resume_duration.as_millis() + ); + // This logs the downtime without the final memory delta, so + // it does not reflect the actual downtime. While we could + // pass along the timestamp from when the VM was paused, + // that would rely on both VM hosts having synchronized + // clocks, which we cannot guarantee. For that reason, this + // is logged as debug! rather than info!. + debug!( + "Migration (incoming): Receiving final state and resuming the VM took {}ms", + state_receive_begin.elapsed().as_millis() + ); Ok(Completed) } _ => invalid_command(), @@ -1046,23 +1074,33 @@ impl Vmm { Ok(memory_manager) } + /// Receives the final VM state (devices, vCPUs) and restores the VM. + /// + /// Measures the time for each step. fn vm_receive_state( &mut self, req: &Request, socket: &mut T, mm: Arc>, - ) -> std::result::Result<(), MigratableError> + ) -> std::result::Result< + ( + Duration, /* state receive + deserialize */ + Duration, /* restoring */ + ), + MigratableError, + > where T: Read, { - // Read in state data - let mut data: Vec = Vec::new(); - data.resize_with(req.length() as usize, Default::default); - socket - .read_exact(&mut data) - .map_err(MigratableError::MigrateSocket)?; - let snapshot: Snapshot = serde_json::from_slice(&data).map_err(|e| { - MigratableError::MigrateReceive(anyhow!("Error deserialising snapshot: {e}")) + let (snapshot, receive_duration): (Snapshot, Duration) = measure_ok(|| { + let mut data: Vec = Vec::new(); + data.resize_with(req.length() as usize, Default::default); + socket + .read_exact(&mut data) + .map_err(MigratableError::MigrateSocket)?; + serde_json::from_slice(&data).map_err(|e| { + MigratableError::MigrateReceive(anyhow!("Error deserialising snapshot: {e}")) + }) })?; let exit_evt = self.exit_evt.try_clone().map_err(|e| { @@ -1079,38 +1117,44 @@ impl Vmm { MigratableError::MigrateReceive(anyhow!("Error cloning activate EventFd: {e}")) })?; - #[cfg(not(target_arch = "riscv64"))] - let timestamp = Instant::now(); - let hypervisor_vm = mm.lock().unwrap().vm.clone(); - let mut vm = Vm::new_from_memory_manager( - self.vm_config.clone().unwrap(), - mm, - hypervisor_vm, - exit_evt, - reset_evt, - #[cfg(feature = "guest_debug")] - debug_evt, - &self.seccomp_action, - self.hypervisor.clone(), - activate_evt, + let (vm, restore_duration) = measure_ok(|| { #[cfg(not(target_arch = "riscv64"))] - timestamp, - self.console_info.clone(), - self.console_resize_pipe.clone(), - Arc::clone(&self.original_termios_opt), - Some(&snapshot), - ) - .map_err(|e| { - MigratableError::MigrateReceive(anyhow!("Error creating VM from snapshot: {e:?}")) + let timestamp = Instant::now(); + let hypervisor_vm = mm.lock().unwrap().vm.clone(); + + let mut vm = Vm::new_from_memory_manager( + self.vm_config.clone().unwrap(), + mm, + hypervisor_vm, + exit_evt, + reset_evt, + #[cfg(feature = "guest_debug")] + debug_evt, + &self.seccomp_action, + self.hypervisor.clone(), + activate_evt, + #[cfg(not(target_arch = "riscv64"))] + timestamp, + self.console_info.clone(), + self.console_resize_pipe.clone(), + Arc::clone(&self.original_termios_opt), + Some(&snapshot), + ) + .map_err(|e| { + MigratableError::MigrateReceive(anyhow!("Error creating VM from snapshot: {e:?}")) + })?; + + // Create VM + vm.restore().map_err(|e| { + MigratableError::MigrateReceive(anyhow!("Failed restoring the Vm: {e}")) + })?; + + Ok(vm) })?; - // Create VM - vm.restore().map_err(|e| { - MigratableError::MigrateReceive(anyhow!("Failed restoring the Vm: {e}")) - })?; self.vm = Some(vm); - Ok(()) + Ok((receive_duration, restore_duration)) } /// Performs the initial memory transmission (iteration zero) plus a