add more debug messages

Author: dobrac

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

@@ -475,6 +475,11 @@ impl VirtioBlock {
         let active_state = self.device_state.active_state().unwrap();
         let queue = &mut self.queues[0];
         let mut processed = 0_u32;
+        let pending_before = engine.pending_ops();
+        debug!(
+            "virtio-block '{}' starting async completion drain: pending_ops={}",
+            self.id, pending_before
+        );
 
         loop {
             match engine.pop(&active_state.mem) {
@@ -520,8 +525,10 @@ impl VirtioBlock {
                 });
         }
         debug!(
-            "virtio-block '{}' processed {} io_uring completions",
-            self.id, processed
+            "virtio-block '{}' processed {} io_uring completions; pending_ops={} after drain",
+            self.id,
+            processed,
+            engine.pending_ops()
         );
     }
 

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

@@ -131,6 +131,8 @@ impl AsyncFileEngine {
         count: u32,
         req: PendingRequest,
     ) -> Result<(), RequestError<AsyncIoError>> {
+        let req_type = req.request_type();
+        let desc_idx = req.desc_idx();
         let buf = match mem.get_slice(addr, count as usize) {
             Ok(slice) => slice.ptr_guard_mut().as_ptr(),
             Err(err) => {
@@ -154,7 +156,17 @@ impl AsyncFileEngine {
             .map_err(|(io_uring_error, data)| RequestError {
                 req: data.req,
                 error: AsyncIoError::IoUring(io_uring_error),
-            })
+            })?;
+
+        debug!(
+            "AsyncFileEngine queued {:?} request desc_idx={} offset={} len={} pending_ops={}",
+            req_type,
+            desc_idx,
+            offset,
+            count,
+            self.pending_ops()
+        );
+        Ok(())
     }
 
     pub fn push_write(
@@ -165,6 +177,8 @@ impl AsyncFileEngine {
         count: u32,
         req: PendingRequest,
     ) -> Result<(), RequestError<AsyncIoError>> {
+        let req_type = req.request_type();
+        let desc_idx = req.desc_idx();
         let buf = match mem.get_slice(addr, count as usize) {
             Ok(slice) => slice.ptr_guard_mut().as_ptr(),
             Err(err) => {
@@ -188,18 +202,38 @@ impl AsyncFileEngine {
             .map_err(|(io_uring_error, data)| RequestError {
                 req: data.req,
                 error: AsyncIoError::IoUring(io_uring_error),
-            })
+            })?;
+
+        debug!(
+            "AsyncFileEngine queued {:?} request desc_idx={} offset={} len={} pending_ops={}",
+            req_type,
+            desc_idx,
+            offset,
+            count,
+            self.pending_ops()
+        );
+        Ok(())
     }
 
     pub fn push_flush(&mut self, req: PendingRequest) -> Result<(), RequestError<AsyncIoError>> {
+        let req_type = req.request_type();
+        let desc_idx = req.desc_idx();
         let wrapped_user_data = WrappedRequest::new(req);
 
         self.ring
             .push(Operation::fsync(0, wrapped_user_data))
             .map_err(|(io_uring_error, data)| RequestError {
                 req: data.req,
                 error: AsyncIoError::IoUring(io_uring_error),
-            })
+            })?;
+
+        debug!(
+            "AsyncFileEngine queued {:?} request desc_idx={} pending_ops={}",
+            req_type,
+            desc_idx,
+            self.pending_ops()
+        );
+        Ok(())
     }
 
     pub fn kick_submission_queue(&mut self) -> Result<(), AsyncIoError> {

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

@@ -16,6 +16,7 @@ use crate::devices::virtio::device::{ActiveState, DeviceState};
 use crate::devices::virtio::generated::virtio_blk::VIRTIO_BLK_F_RO;
 use crate::devices::virtio::generated::virtio_ids::VIRTIO_ID_BLOCK;
 use crate::devices::virtio::persist::VirtioDeviceState;
+use crate::logger::debug;
 use crate::rate_limiter::RateLimiter;
 use crate::rate_limiter::persist::RateLimiterState;
 use crate::snapshot::Persist;
@@ -69,6 +70,11 @@ impl Persist<'_> for VirtioBlock {
     type Error = VirtioBlockError;
 
     fn save(&self) -> Self::State {
+        let pending_ops = self.disk.file_engine.pending_async_ops();
+        debug!(
+            "virtio-block '{}' save invoked with pending_async_ops={}",
+            self.id, pending_ops
+        );
         // Save device state.
         VirtioBlockState {
             id: self.id.clone(),

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

@@ -98,6 +98,18 @@ pub struct PendingRequest {
 }
 
 impl PendingRequest {
+    pub fn request_type(&self) -> RequestType {
+        self.r#type
+    }
+
+    pub fn desc_idx(&self) -> u16 {
+        self.desc_idx
+    }
+
+    pub fn data_len(&self) -> u32 {
+        self.data_len
+    }
+
     fn write_status_and_finish(
         self,
         status: &Status,