add debug messages

Author: dobrac

src/vmm/src/devices/virtio/block/virtio/device.rs

@@ -35,7 +35,7 @@ use crate::devices::virtio::generated::virtio_ring::VIRTIO_RING_F_EVENT_IDX;
 use crate::devices::virtio::queue::{InvalidAvailIdx, Queue};
 use crate::devices::virtio::transport::{VirtioInterrupt, VirtioInterruptType};
 use crate::impl_device_type;
-use crate::logger::{IncMetric, error, warn};
+use crate::logger::{IncMetric, debug, error, warn};
 use crate::rate_limiter::{BucketUpdate, RateLimiter};
 use crate::utils::u64_to_usize;
 use crate::vmm_config::RateLimiterConfig;
@@ -474,6 +474,7 @@ impl VirtioBlock {
         // This is safe since we checked in the event handler that the device is activated.
         let active_state = self.device_state.active_state().unwrap();
         let queue = &mut self.queues[0];
+        let mut processed = 0_u32;
 
         loop {
             match engine.pop(&active_state.mem) {
@@ -504,6 +505,7 @@ impl VirtioBlock {
                                 finished.desc_idx, err
                             )
                         });
+                    processed = processed.saturating_add(1);
                 }
             }
         }
@@ -517,6 +519,10 @@ impl VirtioBlock {
                     self.metrics.event_fails.inc();
                 });
         }
+        debug!(
+            "virtio-block '{}' processed {} io_uring completions",
+            self.id, processed
+        );
     }
 
     pub fn process_async_completion_event(&mut self) {
@@ -573,21 +579,37 @@ impl VirtioBlock {
     /// Prepare device for being snapshotted.
     pub fn prepare_save(&mut self) -> Result<(), VirtioBlockError> {
         if !self.is_activated() {
+            debug!(
+                "virtio-block '{}' prepare_save skipped (device inactive)",
+                self.id
+            );
             return Ok(());
         }
 
+        debug!(
+            "virtio-block '{}' draining outstanding IO before snapshot",
+            self.id
+        );
         self.drain_and_flush(false)?;
         let is_async = matches!(self.disk.file_engine, FileEngine::Async(_));
         if is_async {
             self.process_async_completion_queue();
             if let FileEngine::Async(ref engine) = self.disk.file_engine {
                 let pending = engine.pending_ops();
+                debug!(
+                    "virtio-block '{}' prepare_save async pending_ops after drain: {}",
+                    self.id, pending
+                );
                 if pending != 0 {
                     return Err(VirtioBlockError::PendingAsyncOperations(pending));
                 }
             }
         }
 
+        debug!(
+            "virtio-block '{}' prepare_save finished; async backend drained",
+            self.id
+        );
         Ok(())
     }
 }

src/vmm/src/devices/virtio/block/virtio/io/async_io.rs

@@ -14,7 +14,7 @@ use crate::devices::virtio::block::virtio::{IO_URING_NUM_ENTRIES, PendingRequest
 use crate::io_uring::operation::{Cqe, OpCode, Operation};
 use crate::io_uring::restriction::Restriction;
 use crate::io_uring::{IoUring, IoUringError};
-use crate::logger::log_dev_preview_warning;
+use crate::logger::{debug, log_dev_preview_warning};
 use crate::vstate::memory::{GuestAddress, GuestMemory, GuestMemoryExtension, GuestMemoryMmap};
 
 #[derive(Debug, thiserror::Error, displaydoc::Display)]
@@ -224,12 +224,26 @@ impl AsyncFileEngine {
     }
 
     pub fn drain_and_flush(&mut self, discard_cqes: bool) -> Result<(), AsyncIoError> {
+        let pending_before = self.pending_ops();
+        debug!(
+            "AsyncFileEngine draining: pending_ops={} discard_cqes={}",
+            pending_before, discard_cqes
+        );
         self.drain(discard_cqes)?;
+        debug!(
+            "AsyncFileEngine drain complete: pending_ops={} (discard_cqes={})",
+            self.pending_ops(),
+            discard_cqes
+        );
 
         // Sync data out to physical media on host.
         // We don't need to call flush first since all the ops are performed through io_uring
         // and Rust shouldn't manage any data in its internal buffers.
         self.file.sync_all().map_err(AsyncIoError::SyncAll)?;
+        debug!(
+            "AsyncFileEngine sync complete: pending_ops={}",
+            self.pending_ops()
+        );
 
         Ok(())
     }