devices: virtio: Add trace points to virtio-blk and virtio-scsi

This commit adds tracing points in virtio-blk and virtio-scsi, so that
developpers can easily measure the performance of each commands.

BUG=300042376
TEST=tools/presubmit

Change-Id: Iaae2912505c6e224fa1fe587fb51c97838ecb66b
Reviewed-on: https://chromium-review.googlesource.com/c/crosvm/crosvm/+/5035879
Reviewed-by: Keiichi Watanabe <keiichiw@chromium.org>
Reviewed-by: Takaya Saeki <takayas@chromium.org>
Commit-Queue: Joe Hattori <hattorij@google.com>

cros_tracing/src/trace_marker.rs

@@ -237,7 +237,9 @@ setup_trace_marker!(
     (VirtioFs, true),
     (VirtioNet, true),
     (USB, true),
-    (gpu_display, true)
+    (gpu_display, true),
+    (VirtioBlk, true),
+    (VirtioScsi, true)
 );
 
 /// Platform-specific implementation of the `trace_simple_print!` macro. If tracing

devices/src/virtio/block/asynchronous.rs

@@ -306,6 +306,7 @@ pub async fn process_one_chain(
     flush_timer: &RefCell<TimerAsync<Timer>>,
     flush_timer_armed: &RefCell<bool>,
 ) {
+    let _trace = cros_tracing::trace_event!(VirtioBlk, "process_one_chain");
     let len = match process_one_request(&mut avail_desc, disk_state, flush_timer, flush_timer_armed)
         .await
     {
@@ -815,6 +816,7 @@ impl BlockAsync {
                 let offset = sector
                     .checked_shl(u32::from(SECTOR_SHIFT))
                     .ok_or(ExecuteError::OutOfRange)?;
+                let _trace = cros_tracing::trace_event!(VirtioBlk, "in", offset, data_len);
                 check_range(offset, data_len as u64, disk_size)?;
                 let disk_image = &disk_state.disk_image;
                 writer
@@ -834,6 +836,7 @@ impl BlockAsync {
                 let offset = sector
                     .checked_shl(u32::from(SECTOR_SHIFT))
                     .ok_or(ExecuteError::OutOfRange)?;
+                let _trace = cros_tracing::trace_event!(VirtioBlk, "out", offset, data_len);
                 check_range(offset, data_len as u64, disk_size)?;
                 let disk_image = &disk_state.disk_image;
                 reader
@@ -856,6 +859,14 @@ impl BlockAsync {
                 }
             }
             VIRTIO_BLK_T_DISCARD | VIRTIO_BLK_T_WRITE_ZEROES => {
+                let _trace = cros_tracing::trace_event!(
+                    VirtioBlk,
+                    if req_type == VIRTIO_BLK_T_DISCARD {
+                        "discard"
+                    } else {
+                        "write_zeroes"
+                    }
+                );
                 if req_type == VIRTIO_BLK_T_DISCARD && !disk_state.sparse {
                     // Discard is a hint; if this is a non-sparse disk, just ignore it.
                     return Ok(());
@@ -911,6 +922,7 @@ impl BlockAsync {
                 }
             }
             VIRTIO_BLK_T_FLUSH => {
+                let _trace = cros_tracing::trace_event!(VirtioBlk, "flush");
                 disk_state
                     .disk_image
                     .fdatasync()
@@ -926,6 +938,7 @@ impl BlockAsync {
                 }
             }
             VIRTIO_BLK_T_GET_ID => {
+                let _trace = cros_tracing::trace_event!(VirtioBlk, "get_id");
                 if let Some(id) = disk_state.id {
                     writer.write_all(&id).map_err(ExecuteError::CopyId)?;
                 } else {

devices/src/virtio/scsi/commands.rs

@@ -231,7 +231,10 @@ impl Read6 {
         writer: &mut Writer,
         dev: &AsyncLogicalUnit,
     ) -> Result<(), ExecuteError> {
-        read_from_disk(writer, dev, self.xfer_len(), self.lba() as u64).await
+        let xfer_len = self.xfer_len();
+        let lba = self.lba() as u64;
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "READ(6)", xfer_len, lba);
+        read_from_disk(writer, dev, xfer_len, lba).await
     }
 }
 
@@ -259,6 +262,7 @@ impl Inquiry {
     }
 
     fn emulate(&self, writer: &mut Writer, dev: &AsyncLogicalUnit) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "INQUIRY");
         if self.vital_product_data_enabled() {
             return self.emulate_vital_product_data_page(writer, dev);
         }
@@ -410,6 +414,7 @@ pub struct ModeSelect6 {
 
 impl ModeSelect6 {
     fn emulate(&self) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "MODE_SELECT(6)");
         // TODO(b/303338922): Implement this command properly.
         Err(ExecuteError::InvalidField)
     }
@@ -449,6 +454,7 @@ impl ModeSense6 {
     }
 
     fn emulate(&self, writer: &mut Writer, dev: &AsyncLogicalUnit) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "MODE_SENSE(6)");
         let alloc_len = self.alloc_len();
         let mut outbuf = vec![0u8; cmp::max(4096, alloc_len)];
         // outbuf[0]: Represents data length. Will be filled later.
@@ -635,6 +641,7 @@ pub struct ReadCapacity16 {
 
 impl ReadCapacity16 {
     fn emulate(&self, writer: &mut Writer, dev: &AsyncLogicalUnit) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "READ_CAPACITY(16)");
         let mut outbuf = [0u8; 32];
         // Last logical block address
         outbuf[..8].copy_from_slice(&dev.max_lba.saturating_sub(1).to_be_bytes());
@@ -671,7 +678,10 @@ impl Read10 {
         writer: &mut Writer,
         dev: &AsyncLogicalUnit,
     ) -> Result<(), ExecuteError> {
-        read_from_disk(writer, dev, self.xfer_len(), self.lba()).await
+        let xfer_len = self.xfer_len();
+        let lba = self.lba();
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "READ(10)", lba, xfer_len);
+        read_from_disk(writer, dev, xfer_len, lba).await
     }
 }
 
@@ -700,7 +710,10 @@ impl Write10 {
         reader: &mut Reader,
         dev: &AsyncLogicalUnit,
     ) -> Result<(), ExecuteError> {
-        write_to_disk(reader, dev, self.xfer_len(), self.lba()).await
+        let xfer_len = self.xfer_len();
+        let lba = self.lba();
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "WRITE(10)", lba, xfer_len);
+        write_to_disk(reader, dev, xfer_len, lba).await
     }
 }
 
@@ -740,6 +753,7 @@ pub struct SynchronizeCache10 {
 
 impl SynchronizeCache10 {
     async fn emulate(&self, dev: &AsyncLogicalUnit) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "SYNCHRONIZE_CACHE(10)");
         dev.disk_image.fdatasync().await.map_err(|e| {
             warn!("failed to sync: {e}");
             ExecuteError::SynchronizationError
@@ -811,6 +825,7 @@ impl WriteSame10 {
     ) -> Result<(), ExecuteError> {
         let lba = self.lba() as u64;
         let nblocks = self.nblocks() as u64;
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "WRITE_SAME(10)", lba, nblocks);
         if nblocks == 0 {
             // crosvm does not allow the number of blocks to be zero.
             return Err(ExecuteError::InvalidField);
@@ -852,6 +867,7 @@ impl Unmap {
         reader: &mut Reader,
         dev: &AsyncLogicalUnit,
     ) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "UNMAP");
         // Reject anchor == 1
         if self.anchor() {
             return Err(ExecuteError::InvalidField);
@@ -927,6 +943,7 @@ impl WriteSame16 {
     ) -> Result<(), ExecuteError> {
         let lba = self.lba();
         let nblocks = self.nblocks() as u64;
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "WRITE_SAME(16)", lba, nblocks);
         if nblocks == 0 {
             // crosvm does not allow the number of blocks to be zero.
             return Err(ExecuteError::InvalidField);
@@ -961,6 +978,7 @@ impl ReportLuns {
     }
 
     fn emulate(&self, writer: &mut Writer) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "REPORT_LUNS");
         // We need at least 16 bytes.
         if self.alloc_len() < 16 {
             return Err(ExecuteError::InvalidField);
@@ -996,6 +1014,7 @@ impl ReportSupportedTMFs {
     }
 
     fn emulate(&self, writer: &mut Writer) -> Result<(), ExecuteError> {
+        let _trace = cros_tracing::trace_event!(VirtioScsi, "REPORT_SUPPORTED_TMFs");
         // The allocation length should be at least four.
         if self.alloc_len() < 4 {
             return Err(ExecuteError::InvalidField);

devices/src/virtio/scsi/device.rs

@@ -751,6 +751,7 @@ async fn process_one_chain(
     interrupt: &Interrupt,
     queue_type: &QueueType,
 ) {
+    let _trace = cros_tracing::trace_event!(VirtioScsi, "process_one_chain");
     let len = process_one_request(&mut avail_desc, queue_type).await;
     let mut queue = queue.borrow_mut();
     queue.add_used(avail_desc, len as u32);

docs/book/src/tracing.md

@@ -46,6 +46,9 @@ The categories that are currently supported by cros_tracing are:
 - VirtioFs
 - VirtioNet
 - USB
+- gpu_display
+- VirtioBlk
+- VirtioScsi
 
 ### The trace_marker Backend
 
@@ -184,7 +187,15 @@ In this last example we used the `VirtioFs` category tag. If you want to add a n
 
 ```rust
 // List of categories that can be enabled.
-setup_trace_marker!((VirtioFs, true), (NewCategory, true));
+setup_trace_marker!(
+    (VirtioFs, true),
+    (VirtioNet, true),
+    (USB, true),
+    (gpu_display, true),
+    (VirtioBlk, true),
+    (VirtioScsi, true),
+    (NewCategory, true)
+);
 ```
 
 If the value is `false` then the events will not be traced. This can be useful when you just want to