diff mbox series

[v2,10/10] usb/msd: Add more tracing

Message ID 20250411080431.207579-11-npiggin@gmail.com (mailing list archive)
State New
Headers show
Series usb/msd: Permit relaxed ordering of IN packets | expand

Commit Message

Nicholas Piggin April 11, 2025, 8:04 a.m. UTC
Add tracing for more received packet types, cbw_state changes, and
some more SCSI callbacks. These were useful in debugging relaxed
packet ordering support.

Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
---
 hw/usb/dev-storage.c | 23 +++++++++++++++++++++--
 hw/usb/trace-events  |  9 ++++++++-
 2 files changed, 29 insertions(+), 3 deletions(-)

Comments

Philippe Mathieu-Daudé April 11, 2025, 10:36 a.m. UTC | #1
On 11/4/25 10:04, Nicholas Piggin wrote:
> Add tracing for more received packet types, cbw_state changes, and
> some more SCSI callbacks. These were useful in debugging relaxed
> packet ordering support.
> 
> Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
> ---
>   hw/usb/dev-storage.c | 23 +++++++++++++++++++++--
>   hw/usb/trace-events  |  9 ++++++++-
>   2 files changed, 29 insertions(+), 3 deletions(-)


>   static void usb_msd_copy_data(MSDState *s, USBPacket *p)
>   {
>       uint32_t len;
> +
>       len = p->iov.size - p->actual_length;
> +
> +    trace_usb_msd_copy_data(s->req->tag, len);
> +
>       if (len > s->scsi_len)
>           len = s->scsi_len;
>       usb_packet_copy(p, scsi_req_get_buf(s->req) + s->scsi_off, len);
> @@ -264,6 +268,8 @@ void usb_msd_transfer_data(SCSIRequest *req, uint32_t len)
>       MSDState *s = DO_UPCAST(MSDState, dev.qdev, req->bus->qbus.parent);
>       USBPacket *p = s->data_packet;
>   
> +    trace_usb_msd_transfer_data(req->tag, len);
> +
>       if (s->cbw_state == USB_MSD_CBW_DATAIN) {
>           if (req->cmd.mode == SCSI_XFER_TO_DEV) {
>               usb_msd_fatal_error(s);
> @@ -324,11 +330,13 @@ void usb_msd_command_complete(SCSIRequest *req, size_t resid)
>           }
>           if (s->data_len == 0) {
>               s->cbw_state = USB_MSD_CBW_CSW;
> +            trace_usb_msd_cbw_state(s->cbw_state);
>           }
>           /* USB_RET_SUCCESS status clears previous ASYNC status */
>           usb_msd_data_packet_complete(s, USB_RET_SUCCESS);
>       } else if (s->data_len == 0) {
>           s->cbw_state = USB_MSD_CBW_CSW;
> +        trace_usb_msd_cbw_state(s->cbw_state);
>       }

Maybe helpful to log state transition?

   void usb_msd_cbw_change_state(MSDState *s,
                                 enum USBMSDCBWState cbw_state)
   {
       if (s->cbw_state != cbw_state) {
           trace_usb_msd_cbw_state(s->cbw_state, cbw_state);
           s->cbw_state = cbw_state;
       }
   }

Otherwise,
Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
Nicholas Piggin April 12, 2025, 5:33 a.m. UTC | #2
On Fri Apr 11, 2025 at 8:36 PM AEST, Philippe Mathieu-Daudé wrote:
> On 11/4/25 10:04, Nicholas Piggin wrote:
>> Add tracing for more received packet types, cbw_state changes, and
>> some more SCSI callbacks. These were useful in debugging relaxed
>> packet ordering support.
>> 
>> Signed-off-by: Nicholas Piggin <npiggin@gmail.com>
>> ---
>>   hw/usb/dev-storage.c | 23 +++++++++++++++++++++--
>>   hw/usb/trace-events  |  9 ++++++++-
>>   2 files changed, 29 insertions(+), 3 deletions(-)
>
>
>>   static void usb_msd_copy_data(MSDState *s, USBPacket *p)
>>   {
>>       uint32_t len;
>> +
>>       len = p->iov.size - p->actual_length;
>> +
>> +    trace_usb_msd_copy_data(s->req->tag, len);
>> +
>>       if (len > s->scsi_len)
>>           len = s->scsi_len;
>>       usb_packet_copy(p, scsi_req_get_buf(s->req) + s->scsi_off, len);
>> @@ -264,6 +268,8 @@ void usb_msd_transfer_data(SCSIRequest *req, uint32_t len)
>>       MSDState *s = DO_UPCAST(MSDState, dev.qdev, req->bus->qbus.parent);
>>       USBPacket *p = s->data_packet;
>>   
>> +    trace_usb_msd_transfer_data(req->tag, len);
>> +
>>       if (s->cbw_state == USB_MSD_CBW_DATAIN) {
>>           if (req->cmd.mode == SCSI_XFER_TO_DEV) {
>>               usb_msd_fatal_error(s);
>> @@ -324,11 +330,13 @@ void usb_msd_command_complete(SCSIRequest *req, size_t resid)
>>           }
>>           if (s->data_len == 0) {
>>               s->cbw_state = USB_MSD_CBW_CSW;
>> +            trace_usb_msd_cbw_state(s->cbw_state);
>>           }
>>           /* USB_RET_SUCCESS status clears previous ASYNC status */
>>           usb_msd_data_packet_complete(s, USB_RET_SUCCESS);
>>       } else if (s->data_len == 0) {
>>           s->cbw_state = USB_MSD_CBW_CSW;
>> +        trace_usb_msd_cbw_state(s->cbw_state);
>>       }
>
> Maybe helpful to log state transition?
>
>    void usb_msd_cbw_change_state(MSDState *s,
>                                  enum USBMSDCBWState cbw_state)
>    {
>        if (s->cbw_state != cbw_state) {
>            trace_usb_msd_cbw_state(s->cbw_state, cbw_state);
>            s->cbw_state = cbw_state;
>        }
>    }

Yeah that's not a bad idea. I added that. I made a few more tweaks
and added some more trace points too, but nothing major.

>
> Otherwise,
> Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>
diff mbox series

Patch

diff --git a/hw/usb/dev-storage.c b/hw/usb/dev-storage.c
index 654b9071d33..0ed39de189d 100644
--- a/hw/usb/dev-storage.c
+++ b/hw/usb/dev-storage.c
@@ -187,7 +187,7 @@  static void usb_msd_data_packet_complete(MSDState *s, int status)
      * because another request may be issued before usb_packet_complete
      * returns.
      */
-    trace_usb_msd_packet_complete();
+    trace_usb_msd_data_packet_complete();
     s->data_packet = NULL;
     p->status = status;
     usb_packet_complete(&s->dev, p);
@@ -202,7 +202,7 @@  static void usb_msd_csw_packet_complete(MSDState *s, int status)
      * because another request may be issued before usb_packet_complete
      * returns.
      */
-    trace_usb_msd_packet_complete();
+    trace_usb_msd_csw_packet_complete();
     s->csw_in_packet = NULL;
     p->status = status;
     usb_packet_complete(&s->dev, p);
@@ -231,7 +231,11 @@  static void usb_msd_fatal_error(MSDState *s)
 static void usb_msd_copy_data(MSDState *s, USBPacket *p)
 {
     uint32_t len;
+
     len = p->iov.size - p->actual_length;
+
+    trace_usb_msd_copy_data(s->req->tag, len);
+
     if (len > s->scsi_len)
         len = s->scsi_len;
     usb_packet_copy(p, scsi_req_get_buf(s->req) + s->scsi_off, len);
@@ -264,6 +268,8 @@  void usb_msd_transfer_data(SCSIRequest *req, uint32_t len)
     MSDState *s = DO_UPCAST(MSDState, dev.qdev, req->bus->qbus.parent);
     USBPacket *p = s->data_packet;
 
+    trace_usb_msd_transfer_data(req->tag, len);
+
     if (s->cbw_state == USB_MSD_CBW_DATAIN) {
         if (req->cmd.mode == SCSI_XFER_TO_DEV) {
             usb_msd_fatal_error(s);
@@ -324,11 +330,13 @@  void usb_msd_command_complete(SCSIRequest *req, size_t resid)
         }
         if (s->data_len == 0) {
             s->cbw_state = USB_MSD_CBW_CSW;
+            trace_usb_msd_cbw_state(s->cbw_state);
         }
         /* USB_RET_SUCCESS status clears previous ASYNC status */
         usb_msd_data_packet_complete(s, USB_RET_SUCCESS);
     } else if (s->data_len == 0) {
         s->cbw_state = USB_MSD_CBW_CSW;
+        trace_usb_msd_cbw_state(s->cbw_state);
     }
 
     if (s->cbw_state == USB_MSD_CBW_CSW) {
@@ -336,6 +344,7 @@  void usb_msd_command_complete(SCSIRequest *req, size_t resid)
         if (p) {
             usb_msd_send_status(s, p);
             s->cbw_state = USB_MSD_CBW_NONE;
+            trace_usb_msd_cbw_state(s->cbw_state);
             /* USB_RET_SUCCESS status clears previous ASYNC status */
             usb_msd_csw_packet_complete(s, USB_RET_SUCCESS);
         }
@@ -379,6 +388,7 @@  void usb_msd_handle_reset(USBDevice *dev)
 
     memset(&s->csw, 0, sizeof(s->csw));
     s->cbw_state = USB_MSD_CBW_NONE;
+    trace_usb_msd_cbw_state(s->cbw_state);
 
     s->needs_reset = false;
 }
@@ -429,6 +439,8 @@  static void usb_msd_cancel_io(USBDevice *dev, USBPacket *p)
 {
     MSDState *s = USB_STORAGE_DEV(dev);
 
+    trace_usb_msd_cancel_io();
+
     if (p == s->data_packet) {
         s->data_packet = NULL;
         if (s->req) {
@@ -516,6 +528,7 @@  static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p)
         }
         trace_usb_msd_cmd_submit(cbw.lun, tag, cbw.flags,
                                  cbw.cmd_len, s->data_len);
+        trace_usb_msd_cbw_state(s->cbw_state);
         assert(le32_to_cpu(s->csw.residue) == 0);
         assert(s->scsi_len == 0);
         s->req = scsi_req_new(scsi_dev, tag, cbw.lun,
@@ -553,6 +566,7 @@  static void usb_msd_handle_data_out(USBDevice *dev, USBPacket *p)
                 s->data_len -= len;
                 if (s->data_len == 0) {
                     s->cbw_state = USB_MSD_CBW_CSW;
+                    trace_usb_msd_cbw_state(s->cbw_state);
                 }
             }
         }
@@ -579,6 +593,7 @@  static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p)
 
     switch (s->cbw_state) {
     case USB_MSD_CBW_NONE:
+        trace_usb_msd_unknown_in(p->iov.size);
         if (s->unknown_in_packet) {
             qemu_log_mask(LOG_GUEST_ERROR, "usb-msd: second IN packet was"
                                            "received before CBW\n");
@@ -590,6 +605,7 @@  static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p)
         break;
 
     case USB_MSD_CBW_DATAOUT:
+        trace_usb_msd_csw_in();
         if (s->unknown_in_packet) {
             error_report("usb-msd: unknown_in_packet in DATAOUT state");
             goto fail;
@@ -610,6 +626,7 @@  static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p)
         break;
 
     case USB_MSD_CBW_CSW:
+        trace_usb_msd_csw_in();
         if (s->unknown_in_packet) {
             error_report("usb-msd: unknown_in_packet in DATAOUT state");
             goto fail;
@@ -626,6 +643,7 @@  static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p)
         } else {
             usb_msd_send_status(s, p);
             s->cbw_state = USB_MSD_CBW_NONE;
+            trace_usb_msd_cbw_state(s->cbw_state);
         }
         break;
 
@@ -648,6 +666,7 @@  static void usb_msd_handle_data_in(USBDevice *dev, USBPacket *p)
                 s->data_len -= len;
                 if (s->data_len == 0) {
                     s->cbw_state = USB_MSD_CBW_CSW;
+                    trace_usb_msd_cbw_state(s->cbw_state);
                 }
             }
         }
diff --git a/hw/usb/trace-events b/hw/usb/trace-events
index dd04f14add1..688f7ba0b3d 100644
--- a/hw/usb/trace-events
+++ b/hw/usb/trace-events
@@ -264,12 +264,19 @@  usb_msd_maxlun(unsigned maxlun) "%d"
 usb_msd_send_status(unsigned status, unsigned tag, size_t size) "status %d, tag 0x%x, len %zd"
 usb_msd_data_in(unsigned packet, unsigned remaining, unsigned total) "%d/%d (scsi %d)"
 usb_msd_data_out(unsigned packet, unsigned remaining) "%d/%d"
+usb_msd_unknown_in(unsigned packet) "%d"
+usb_msd_csw_in(void) ""
 usb_msd_packet_async(void) ""
-usb_msd_packet_complete(void) ""
+usb_msd_data_packet_complete(void) ""
+usb_msd_csw_packet_complete(void) ""
 usb_msd_cmd_submit(unsigned lun, unsigned tag, unsigned flags, unsigned len, unsigned data_len) "lun %u, tag 0x%x, flags 0x%08x, len %d, data-len %d"
 usb_msd_cmd_complete(unsigned status, unsigned tag) "status %d, tag 0x%x"
+usb_msd_copy_data(unsigned tag, unsigned len) "tag 0x%x len %d"
+usb_msd_transfer_data(unsigned tag, unsigned len) "tag 0x%x len %d"
 usb_msd_cmd_cancel(unsigned tag) "tag 0x%x"
+usb_msd_cancel_io(void) ""
 usb_msd_fatal_error(void) ""
+usb_msd_cbw_state(unsigned cbw_state) "cbw-state %d"
 
 # dev-uas.c
 usb_uas_reset(int addr) "dev %d"