[Qemu-devel] [PATCH 2/2] add some virtio-scsi trace events

[Laszlo Ersek <lersek@redhat.com>]

The events that log a hexdump of the cdb and the sense buffer are disabled
by default, because they require more processing than a simple trace_XXX()
function call.

Signed-off-by: Laszlo Ersek <lersek@redhat.com>
---
 hw/scsi/virtio-scsi.c |   76 +++++++++++++++++++++++++++++++++++++++++++++++--
 trace-events          |   19 ++++++++++++
 2 files changed, 92 insertions(+), 3 deletions(-)

diff --git a/hw/scsi/virtio-scsi.c b/hw/scsi/virtio-scsi.c
index 05da56b..22677f7 100644
--- a/hw/scsi/virtio-scsi.c
+++ b/hw/scsi/virtio-scsi.c
@@ -15,6 +15,7 @@
 
 #include "hw/virtio/virtio-scsi.h"
 #include "qemu/error-report.h"
+#include "trace.h"
 #include <hw/scsi/scsi.h>
 #include <block/scsi.h>
 #include <hw/virtio/virtio-bus.h>
@@ -61,6 +62,8 @@ static void virtio_scsi_complete_req(VirtIOSCSIReq *req)
     VirtIOSCSI *s = req->dev;
     VirtQueue *vq = req->vq;
     VirtIODevice *vdev = VIRTIO_DEVICE(s);
+
+    trace_virtio_scsi_complete_req_enter(req);
     virtqueue_push(vq, &req->elem, req->qsgl.size + req->elem.in_sg[0].iov_len);
     qemu_sglist_destroy(&req->qsgl);
     if (req->sreq) {
@@ -69,6 +72,7 @@ static void virtio_scsi_complete_req(VirtIOSCSIReq *req)
     }
     g_free(req);
     virtio_notify(vdev, vq);
+    trace_virtio_scsi_complete_req_exit(req);
 }
 
 static void virtio_scsi_bad_req(void)
@@ -121,6 +125,7 @@ static VirtIOSCSIReq *virtio_scsi_pop_req(VirtIOSCSI *s, VirtQueue *vq)
     }
 
     virtio_scsi_parse_req(s, vq, req);
+    trace_virtio_scsi_pop_req(req);
     return req;
 }
 
@@ -271,6 +276,7 @@ static void virtio_scsi_handle_ctrl(VirtIODevice *vdev, VirtQueue *vq)
     VirtIOSCSI *s = (VirtIOSCSI *)vdev;
     VirtIOSCSIReq *req;
 
+    trace_virtio_scsi_handle_ctrl_enter(vdev, vq);
     while ((req = virtio_scsi_pop_req(s, vq))) {
         int out_size, in_size;
         if (req->elem.out_num < 1 || req->elem.in_num < 1) {
@@ -298,14 +304,38 @@ static void virtio_scsi_handle_ctrl(VirtIODevice *vdev, VirtQueue *vq)
         }
         virtio_scsi_complete_req(req);
     }
+    trace_virtio_scsi_handle_ctrl_exit(vdev, vq);
 }
 
+#if TRACE_VIRTIO_SCSI_DUMP_CMD_RESP_ENABLED
+static void dump_cmd_resp(const VirtIOSCSIReq *req)
+{
+    const VirtIOSCSICmdResp *cr;
+    uint32_t sense_len;
+    char *sense_hex;
+
+    if (!trace_event_get_state(TRACE_VIRTIO_SCSI_DUMP_CMD_RESP)) {
+        return;
+    }
+    cr = req->resp.cmd;
+    sense_len = (cr->response == VIRTIO_SCSI_S_OK && cr->status != GOOD) ?
+                tswap32(cr->sense_len) : 0;
+    sense_hex = qemu_hexstr(cr->sense, sense_len, NULL);
+    trace_virtio_scsi_dump_cmd_resp((void *)req, sense_len, tswap32(cr->resid),
+                                    cr->status, cr->response, sense_hex);
+    g_free(sense_hex);
+}
+#else
+static inline void dump_cmd_resp(const VirtIOSCSIReq *req) {}
+#endif
+
 static void virtio_scsi_command_complete(SCSIRequest *r, uint32_t status,
                                          size_t resid)
 {
     VirtIOSCSIReq *req = r->hba_private;
-    uint32_t sense_len;
+    uint32_t sense_len = 0;
 
+    trace_virtio_scsi_command_complete_enter(req, status, resid);
     req->resp.cmd->response = VIRTIO_SCSI_S_OK;
     req->resp.cmd->status = status;
     if (req->resp.cmd->status == GOOD) {
@@ -316,7 +346,9 @@ static void virtio_scsi_command_complete(SCSIRequest *r, uint32_t status,
                                        VIRTIO_SCSI_SENSE_SIZE);
         req->resp.cmd->sense_len = tswap32(sense_len);
     }
+    dump_cmd_resp(req);
     virtio_scsi_complete_req(req);
+    trace_virtio_scsi_command_complete_exit(req, status, resid, sense_len);
 }
 
 static QEMUSGList *virtio_scsi_get_sg_list(SCSIRequest *r)
@@ -329,24 +361,51 @@ static QEMUSGList *virtio_scsi_get_sg_list(SCSIRequest *r)
 static void virtio_scsi_request_cancelled(SCSIRequest *r)
 {
     VirtIOSCSIReq *req = r->hba_private;
+    uint8_t resp = 0;
 
+    trace_virtio_scsi_request_cancelled_enter(req);
     if (!req) {
-        return;
+        goto out;
     }
     if (req->dev->resetting) {
         req->resp.cmd->response = VIRTIO_SCSI_S_RESET;
     } else {
         req->resp.cmd->response = VIRTIO_SCSI_S_ABORTED;
     }
+    resp = req->resp.cmd->response;
+    dump_cmd_resp(req);
     virtio_scsi_complete_req(req);
+out:
+    trace_virtio_scsi_request_cancelled_exit(req, resp);
 }
 
 static void virtio_scsi_fail_cmd_req(VirtIOSCSIReq *req)
 {
     req->resp.cmd->response = VIRTIO_SCSI_S_FAILURE;
+    dump_cmd_resp(req);
     virtio_scsi_complete_req(req);
 }
 
+#if TRACE_VIRTIO_SCSI_DUMP_CMD_REQ_ENABLED
+static void dump_cmd_req(const VirtIOSCSIReq *req, uint32_t cdb_size)
+{
+    const VirtIOSCSICmdReq *cr;
+    char *cdb_hex;
+
+    if (!trace_event_get_state(TRACE_VIRTIO_SCSI_DUMP_CMD_REQ)) {
+        return;
+    }
+    cr = req->req.cmd;
+    cdb_hex = qemu_hexstr(cr->cdb, cdb_size, NULL);
+    trace_virtio_scsi_dump_cmd_req((void *)req, cr->tag,
+                                   virtio_scsi_get_lun((uint8_t *)cr->lun),
+                                   cdb_hex);
+    g_free(cdb_hex);
+}
+#else
+static inline void dump_cmd_req(const VirtIOSCSIReq *req, uint32_t cdb_size) {}
+#endif
+
 static void virtio_scsi_handle_cmd(VirtIODevice *vdev, VirtQueue *vq)
 {
     /* use non-QOM casts in the data path */
@@ -356,6 +415,7 @@ static void virtio_scsi_handle_cmd(VirtIODevice *vdev, VirtQueue *vq)
     VirtIOSCSIReq *req;
     int n;
 
+    trace_virtio_scsi_handle_cmd_enter(vdev, vq);
     while ((req = virtio_scsi_pop_req(s, vq))) {
         SCSIDevice *d;
         int out_size, in_size;
@@ -378,9 +438,11 @@ static void virtio_scsi_handle_cmd(VirtIODevice *vdev, VirtQueue *vq)
         d = virtio_scsi_device_find(s, req->req.cmd->lun);
         if (!d) {
             req->resp.cmd->response = VIRTIO_SCSI_S_BAD_TARGET;
+            dump_cmd_resp(req);
             virtio_scsi_complete_req(req);
             continue;
         }
+        dump_cmd_req(req, vs->cdb_size);
         req->sreq = scsi_req_new(d, req->req.cmd->tag,
                                  virtio_scsi_get_lun(req->req.cmd->lun),
                                  req->req.cmd->cdb, req);
@@ -392,6 +454,7 @@ static void virtio_scsi_handle_cmd(VirtIODevice *vdev, VirtQueue *vq)
             if (req->sreq->cmd.mode != req_mode ||
                 req->sreq->cmd.xfer > req->qsgl.size) {
                 req->resp.cmd->response = VIRTIO_SCSI_S_OVERRUN;
+                dump_cmd_resp(req);
                 virtio_scsi_complete_req(req);
                 continue;
             }
@@ -402,6 +465,7 @@ static void virtio_scsi_handle_cmd(VirtIODevice *vdev, VirtQueue *vq)
             scsi_req_continue(req->sreq);
         }
     }
+    trace_virtio_scsi_handle_cmd_exit(vdev, vq);
 }
 
 static void virtio_scsi_get_config(VirtIODevice *vdev,
@@ -483,17 +547,22 @@ static void virtio_scsi_push_event(VirtIOSCSI *s, SCSIDevice *dev,
                                    uint32_t event, uint32_t reason)
 {
     VirtIOSCSICommon *vs = VIRTIO_SCSI_COMMON(s);
-    VirtIOSCSIReq *req = virtio_scsi_pop_req(s, vs->event_vq);
+    VirtIOSCSIReq *req;
     VirtIOSCSIEvent *evt;
     VirtIODevice *vdev = VIRTIO_DEVICE(s);
     int in_size;
 
+    trace_virtio_scsi_push_event_enter(vdev, vs->event_vq, event, reason);
+    req = virtio_scsi_pop_req(s, vs->event_vq);
+
     if (!(vdev->status & VIRTIO_CONFIG_S_DRIVER_OK)) {
+        trace_virtio_scsi_push_event_unconf(vdev, vs->event_vq, event, reason);
         return;
     }
 
     if (!req) {
         s->events_dropped = true;
+        trace_virtio_scsi_push_event_no_req(vdev, vs->event_vq, event, reason);
         return;
     }
 
@@ -528,6 +597,7 @@ static void virtio_scsi_push_event(VirtIOSCSI *s, SCSIDevice *dev,
         evt->lun[3] = dev->lun & 0xFF;
     }
     virtio_scsi_complete_req(req);
+    trace_virtio_scsi_push_event_exit(vdev, vs->event_vq, event, reason);
 }
 
 static void virtio_scsi_handle_event(VirtIODevice *vdev, VirtQueue *vq)
diff --git a/trace-events b/trace-events
index 3856b5c..68eebab 100644
--- a/trace-events
+++ b/trace-events
@@ -1176,3 +1176,22 @@ object_class_dynamic_cast_assert(const char *type, const char *target, const cha
 # hw/xen/xen_pvdevice.c
 xen_pv_mmio_read(uint64_t addr) "WARNING: read from Xen PV Device MMIO space (address %"PRIx64")"
 xen_pv_mmio_write(uint64_t addr) "WARNING: write to Xen PV Device MMIO space (address %"PRIx64")"
+
+# hw/scsi/virtio-scsi.c
+virtio_scsi_complete_req_enter(void *req) "req %p"
+virtio_scsi_complete_req_exit(void *req)  "req %p"
+virtio_scsi_pop_req(void *req) "req %p"
+virtio_scsi_handle_ctrl_enter(void *vdev, void *vq) "vdev %p vq %p"
+virtio_scsi_handle_ctrl_exit(void *vdev, void *vq)  "vdev %p vq %p"
+virtio_scsi_command_complete_enter(void *req, uint32_t status, size_t resid)                    "req %p status %"PRIu32" resid %zu"
+virtio_scsi_command_complete_exit(void *req, uint32_t status, size_t resid, uint32_t sense_len) "req %p status %"PRIu32" resid %zu sense_len %"PRIu32
+virtio_scsi_request_cancelled_enter(void *req)              "req %p"
+virtio_scsi_request_cancelled_exit(void *req, uint8_t resp) "req %p resp %d"
+virtio_scsi_handle_cmd_enter(void *vdev, void *vq) "vdev %p vq %p"
+virtio_scsi_handle_cmd_exit(void *vdev, void *vq)  "vdev %p vq %p"
+virtio_scsi_push_event_enter(void *vdev, void *vq, uint32_t event, uint32_t reason)  "vdev %p vq %p event %#"PRIx32" reason %#"PRIx32
+virtio_scsi_push_event_unconf(void *vdev, void *vq, uint32_t event, uint32_t reason) "vdev %p vq %p event %#"PRIx32" reason %#"PRIx32
+virtio_scsi_push_event_no_req(void *vdev, void *vq, uint32_t event, uint32_t reason) "vdev %p vq %p event %#"PRIx32" reason %#"PRIx32
+virtio_scsi_push_event_exit(void *vdev, void *vq, uint32_t event, uint32_t reason)   "vdev %p vq %p event %#"PRIx32" reason %#"PRIx32
+disable virtio_scsi_dump_cmd_resp(void *req, uint32_t sense_len, uint32_t resid, uint8_t status, uint8_t response, const char *sense_hex) "req %p sense_len %"PRIu32" resid %"PRIu32" status %d response %d sense_hex %s"
+disable virtio_scsi_dump_cmd_req(void *req, uint64_t tag, int lun, const char *cdb_hex) "req %p tag %#"PRIx64" lun %d cdb_hex %s"
-- 
1.7.1