devices: bus: Add debug logs for devices and bus.
Change bus logs from info to debug.
Add debug logs for each device on sleep, snapshot, wake, restore.
Add info log at top level snapshot and restore.
BUG=N/A
TEST=boot crosvm, snapshot. Shut down, boot with restore.
TEST=boot crosvm with --log-level=debug, snapshot. Shut down, boot with restore.
Change-Id: I67263a5745dac6647dbe689aa3b97c8f43555593
Reviewed-on: https://chromium-review.googlesource.com/c/crosvm/crosvm/+/4954726
Auto-Submit: Elie Kheirallah <khei@google.com>
Reviewed-by: Frederick Mayle <fmayle@google.com>
Commit-Queue: Elie Kheirallah <khei@google.com>
Reviewed-by: Daniel Verkamp <dverkamp@chromium.org>
diff --git a/devices/src/bus.rs b/devices/src/bus.rs
index 0cd3016..f43659a 100644
--- a/devices/src/bus.rs
+++ b/devices/src/bus.rs
@@ -18,6 +18,7 @@
use anyhow::anyhow;
use anyhow::Context;
+use base::debug;
use base::error;
use remain::sorted;
use serde::Deserialize;
@@ -408,10 +409,12 @@
match device_entry {
BusDeviceEntry::OuterSync(dev) => {
let mut dev = (*dev).lock();
+ debug!("Sleep on device: {}", dev.debug_label());
dev.sleep()
.with_context(|| format!("failed to sleep {}", dev.debug_label()))?;
}
BusDeviceEntry::InnerSync(dev) => {
+ debug!("Sleep on device: {}", dev.debug_label());
dev.sleep_sync()
.with_context(|| format!("failed to sleep {}", dev.debug_label()))?;
}
@@ -425,10 +428,12 @@
match device_entry {
BusDeviceEntry::OuterSync(dev) => {
let mut dev = dev.lock();
+ debug!("Wake on device: {}", dev.debug_label());
dev.wake()
.with_context(|| format!("failed to wake {}", dev.debug_label()))?;
}
BusDeviceEntry::InnerSync(dev) => {
+ debug!("Wake on device: {}", dev.debug_label());
dev.wake_sync()
.with_context(|| format!("failed to wake {}", dev.debug_label()))?;
}
@@ -445,17 +450,21 @@
match device_entry {
BusDeviceEntry::OuterSync(dev) => {
let dev = dev.lock();
+ debug!("Snapshot on device: {}", dev.debug_label());
add_snapshot(
u32::from(dev.device_id()),
dev.snapshot()
.with_context(|| format!("failed to snapshot {}", dev.debug_label()))?,
)
}
- BusDeviceEntry::InnerSync(dev) => add_snapshot(
- u32::from(dev.device_id()),
- dev.snapshot_sync()
- .with_context(|| format!("failed to snapshot {}", dev.debug_label()))?,
- ),
+ BusDeviceEntry::InnerSync(dev) => {
+ debug!("Snapshot on device: {}", dev.debug_label());
+ add_snapshot(
+ u32::from(dev.device_id()),
+ dev.snapshot_sync()
+ .with_context(|| format!("failed to snapshot {}", dev.debug_label()))?,
+ )
+ }
}
}
Ok(())
@@ -474,19 +483,21 @@
match device_entry {
BusDeviceEntry::OuterSync(dev) => {
let mut dev = dev.lock();
+ debug!("Restore on device: {}", dev.debug_label());
let snapshot = pop_snapshot(dev.device_id()).ok_or_else(|| {
- anyhow!("missing snapshot for device {:?}", dev.debug_label())
+ anyhow!("missing snapshot for device {}", dev.debug_label())
})?;
dev.restore(snapshot).with_context(|| {
- format!("restore failed for device {:?}", dev.debug_label())
+ format!("restore failed for device {}", dev.debug_label())
})?;
}
BusDeviceEntry::InnerSync(dev) => {
+ debug!("Restore on device: {}", dev.debug_label());
let snapshot = pop_snapshot(dev.device_id()).ok_or_else(|| {
- anyhow!("missing snapshot for device {:?}", dev.debug_label())
+ anyhow!("missing snapshot for device {}", dev.debug_label())
})?;
dev.restore_sync(snapshot).with_context(|| {
- format!("restore failed for device {:?}", dev.debug_label())
+ format!("restore failed for device {}", dev.debug_label())
})?;
}
}
diff --git a/devices/src/lib.rs b/devices/src/lib.rs
index 34565c0..1da1cc4 100644
--- a/devices/src/lib.rs
+++ b/devices/src/lib.rs
@@ -47,6 +47,7 @@
use anyhow::anyhow;
use anyhow::Context;
+use base::debug;
use base::error;
use base::info;
use base::Tube;
@@ -228,7 +229,7 @@
fn sleep_devices(bus: &Bus) -> anyhow::Result<()> {
match bus.sleep_devices() {
Ok(_) => {
- info!("Devices slept successfully on {:?} Bus", bus.get_bus_type());
+ debug!("Devices slept successfully on {:?} Bus", bus.get_bus_type());
Ok(())
}
Err(e) => Err(anyhow!(
@@ -242,7 +243,7 @@
fn wake_devices(bus: &Bus) {
match bus.wake_devices() {
Ok(_) => {
- info!(
+ debug!(
"Devices awoken successfully on {:?} Bus",
bus.get_bus_type()
);
@@ -301,7 +302,7 @@
) -> anyhow::Result<()> {
match bus.snapshot_devices(add_snapshot) {
Ok(_) => {
- info!(
+ debug!(
"Devices snapshot successfully for {:?} Bus",
bus.get_bus_type()
);
@@ -325,7 +326,7 @@
) -> anyhow::Result<()> {
match bus.restore_devices(devices_map) {
Ok(_) => {
- info!(
+ debug!(
"Devices restore successfully for {:?} Bus",
bus.get_bus_type()
);
diff --git a/vm_control/src/lib.rs b/vm_control/src/lib.rs
index 816204e..6efe7eb 100644
--- a/vm_control/src/lib.rs
+++ b/vm_control/src/lib.rs
@@ -1726,6 +1726,7 @@
VmResponse::Err(SysError::new(ENOTSUP))
}
VmRequest::SuspendVm => {
+ info!("Starting crosvm suspend");
kick_vcpus(VcpuControl::RunState(VmRunMode::Suspending));
let current_mode = match get_vcpu_state(kick_vcpus, vcpu_size) {
Ok(state) => state,
@@ -1749,7 +1750,10 @@
.recv()
.context("receive from devices control socket")
{
- Ok(VmResponse::Ok) => VmResponse::Ok,
+ Ok(VmResponse::Ok) => {
+ info!("Finished crosvm suspend successfully");
+ VmResponse::Ok
+ }
Ok(resp) => {
error!("device sleep failed: {}", resp);
VmResponse::Err(SysError::new(EIO))
@@ -1761,6 +1765,7 @@
}
}
VmRequest::ResumeVm => {
+ info!("Starting crosvm resume");
if let Err(e) = device_control_tube
.send(&DeviceControlCommand::WakeDevices)
.context("send command to devices control socket")
@@ -1772,7 +1777,9 @@
.recv()
.context("receive from devices control socket")
{
- Ok(VmResponse::Ok) => (),
+ Ok(VmResponse::Ok) => {
+ info!("Finished crosvm resume successfully");
+ }
Ok(resp) => {
error!("device wake failed: {}", resp);
return VmResponse::Err(SysError::new(EIO));
@@ -1889,6 +1896,7 @@
VmResponse::ErrString("hot plug not supported".to_owned())
}
VmRequest::Snapshot(SnapshotCommand::Take { ref snapshot_path }) => {
+ info!("Starting crosvm snapshot");
match do_snapshot(
snapshot_path.to_path_buf(),
kick_vcpus,
@@ -1897,7 +1905,10 @@
vcpu_size,
snapshot_irqchip,
) {
- Ok(()) => VmResponse::Ok,
+ Ok(()) => {
+ info!("Finished crosvm snapshot successfully");
+ VmResponse::Ok
+ }
Err(e) => {
error!("failed to handle snapshot: {:?}", e);
VmResponse::Err(SysError::new(EIO))
@@ -1905,6 +1916,7 @@
}
}
VmRequest::Restore(RestoreCommand::Apply { ref restore_path }) => {
+ info!("Starting crosvm restore");
match do_restore(
restore_path.clone(),
kick_vcpus,
@@ -1914,7 +1926,10 @@
vcpu_size,
restore_irqchip,
) {
- Ok(()) => VmResponse::Ok,
+ Ok(()) => {
+ info!("Finished crosvm restore successfully");
+ VmResponse::Ok
+ }
Err(e) => {
error!("failed to handle restore: {:?}", e);
VmResponse::Err(SysError::new(EIO))
