[Qemu-devel] [PATCH 5/5] spapr_vscsi: convert to trace framework instead of DPRINTF

[Laurent Vivier]

Signed-off-by: Laurent Vivier <address@hidden>
---
 hw/scsi/spapr_vscsi.c | 89 +++++++++++++++++++++------------------------------
 hw/scsi/trace-events  | 27 ++++++++++++++++
 2 files changed, 63 insertions(+), 53 deletions(-)

diff --git a/hw/scsi/spapr_vscsi.c b/hw/scsi/spapr_vscsi.c
index 8fbd50f..29fef90 100644
--- a/hw/scsi/spapr_vscsi.c
+++ b/hw/scsi/spapr_vscsi.c
@@ -42,19 +42,10 @@
 #include "hw/ppc/spapr.h"
 #include "hw/ppc/spapr_vio.h"
 #include "viosrp.h"
+#include "trace.h"
 
 #include <libfdt.h>
 
-/*#define DEBUG_VSCSI*/
-
-#ifdef DEBUG_VSCSI
-#define DPRINTF(fmt, ...) \
-    do { fprintf(stderr, fmt, ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF(fmt, ...) \
-    do { } while (0)
-#endif
-
 /*
  * Virtual SCSI device
  */
@@ -237,8 +228,7 @@ static int vscsi_send_rsp(VSCSIState *s, vscsi_req *req,
     int total_len = sizeof(iu->srp.rsp);
     uint8_t sol_not = iu->srp.cmd.sol_not;
 
-    DPRINTF("VSCSI: Sending resp status: 0x%x, "
-            "res_in: %d, res_out: %d\n", status, res_in, res_out);
+    trace_spapr_vscsi_send_rsp(status, res_in, res_out);
 
     memset(iu, 0, sizeof(struct srp_rsp));
     iu->srp.rsp.opcode = SRP_RSP;
@@ -298,13 +288,13 @@ static int vscsi_fetch_desc(VSCSIState *s, struct 
vscsi_req *req,
 
     switch (req->dma_fmt) {
     case SRP_NO_DATA_DESC: {
-        DPRINTF("VSCSI: no data descriptor\n");
+        trace_spapr_vscsi_fetch_desc_no_data();
         return 0;
     }
     case SRP_DATA_DESC_DIRECT: {
         memcpy(ret, cmd->add_data + req->cdb_offset, sizeof(*ret));
         assert(req->cur_desc_num == 0);
-        DPRINTF("VSCSI: direct segment\n");
+        trace_spapr_vscsi_fetch_desc_direct();
         break;
     }
     case SRP_DATA_DESC_INDIRECT: {
@@ -312,30 +302,29 @@ static int vscsi_fetch_desc(VSCSIState *s, struct 
vscsi_req *req,
                                        (cmd->add_data + req->cdb_offset);
         if (n < req->local_desc) {
             *ret = tmp->desc_list[n];
-            DPRINTF("VSCSI: indirect segment local tag=0x%x desc#%d/%d\n",
-                    req->qtag, n, req->local_desc);
-
+            trace_spapr_vscsi_fetch_desc_indirect(req->qtag, n,
+                                                  req->local_desc);
         } else if (n < req->total_desc) {
             int rc;
             struct srp_direct_buf tbl_desc = vscsi_swap_desc(tmp->table_desc);
             unsigned desc_offset = n * sizeof(struct srp_direct_buf);
 
             if (desc_offset >= tbl_desc.len) {
-                DPRINTF("VSCSI:   #%d is ouf of range (%d bytes)\n",
-                        n, desc_offset);
+                trace_spapr_vscsi_fetch_desc_out_of_range(n, desc_offset);
                 return -1;
             }
             rc = spapr_vio_dma_read(&s->vdev, tbl_desc.va + desc_offset,
                                     ret, sizeof(struct srp_direct_buf));
             if (rc) {
-                DPRINTF("VSCSI: spapr_vio_dma_read -> %d reading ext_desc\n",
-                        rc);
+                trace_spapr_vscsi_fetch_desc_dma_read_error(rc);
                 return -1;
             }
-            DPRINTF("VSCSI: indirect segment ext. tag=0x%x desc#%d/%d { 
va=%"PRIx64" len=%x }\n",
-                    req->qtag, n, req->total_desc, tbl_desc.va, tbl_desc.len);
+            trace_spapr_vscsi_fetch_desc_indirect_seg_ext(req->qtag, n,
+                                                          req->total_desc,
+                                                          tbl_desc.va,
+                                                          tbl_desc.len);
         } else {
-            DPRINTF("VSCSI:   Out of descriptors !\n");
+            trace_spapr_vscsi_fetch_desc_out_of_desc();
             return 0;
         }
         break;
@@ -347,15 +336,16 @@ static int vscsi_fetch_desc(VSCSIState *s, struct 
vscsi_req *req,
 
     *ret = vscsi_swap_desc(*ret);
     if (buf_offset > ret->len) {
-        DPRINTF("   offset=%x is out of a descriptor #%d boundary=%x\n",
-                buf_offset, req->cur_desc_num, ret->len);
+        trace_spapr_vscsi_fetch_desc_out_of_desc_boundary(buf_offset,
+                                                          req->cur_desc_num,
+                                                          ret->len);
         return -1;
     }
     ret->va += buf_offset;
     ret->len -= buf_offset;
 
-    DPRINTF("   cur=%d offs=%x ret { va=%"PRIx64" len=%x }\n",
-            req->cur_desc_num, req->cur_desc_offset, ret->va, ret->len);
+    trace_spapr_vscsi_fetch_desc_done(req->cur_desc_num, req->cur_desc_offset,
+                                      ret->va, ret->len);
 
     return ret->len ? 1 : 0;
 }
@@ -398,7 +388,7 @@ static int vscsi_srp_indirect_data(VSCSIState *s, vscsi_req 
*req,
     int rc = 0;
     uint32_t llen, total = 0;
 
-    DPRINTF("VSCSI: indirect segment 0x%x bytes\n", len);
+    trace_spapr_vscsi_srp_indirect_data(len);
 
     /* While we have data ... */
     while (len) {
@@ -417,11 +407,10 @@ static int vscsi_srp_indirect_data(VSCSIState *s, 
vscsi_req *req,
             rc = spapr_vio_dma_write(&s->vdev, md.va, buf, llen);
         }
         if (rc) {
-            DPRINTF("VSCSI: spapr_vio_dma_r/w(%d) -> %d\n", req->writing, rc);
+            trace_spapr_vscsi_srp_indirect_data_rw(req->writing, rc);
             break;
         }
-        DPRINTF("VSCSI:     data: %02x %02x %02x %02x...\n",
-                buf[0], buf[1], buf[2], buf[3]);
+        trace_spapr_vscsi_srp_indirect_data_buf(buf[0], buf[1], buf[2], 
buf[3]);
 
         len -= llen;
         buf += llen;
@@ -447,7 +436,7 @@ static int vscsi_srp_transfer_data(VSCSIState *s, vscsi_req 
*req,
 
     switch (req->dma_fmt) {
     case SRP_NO_DATA_DESC:
-        DPRINTF("VSCSI: no data desc transfer, skipping 0x%x bytes\n", len);
+        trace_spapr_vscsi_srp_transfer_data(len);
         break;
     case SRP_DATA_DESC_DIRECT:
         err = vscsi_srp_direct_data(s, req, buf, len);
@@ -527,8 +516,7 @@ static void vscsi_transfer_data(SCSIRequest *sreq, uint32_t 
len)
     uint8_t *buf;
     int rc = 0;
 
-    DPRINTF("VSCSI: SCSI xfer complete tag=0x%x len=0x%x, req=%p\n",
-            sreq->tag, len, req);
+    trace_spapr_vscsi_transfer_data(sreq->tag, len, req);
     if (req == NULL) {
         fprintf(stderr, "VSCSI: Can't find request for tag 0x%x\n", sreq->tag);
         return;
@@ -557,8 +545,7 @@ static void vscsi_command_complete(SCSIRequest *sreq, 
uint32_t status, size_t re
     vscsi_req *req = sreq->hba_private;
     int32_t res_in = 0, res_out = 0;
 
-    DPRINTF("VSCSI: SCSI cmd complete, tag=0x%x status=0x%x, req=%p\n",
-            sreq->tag, status, req);
+    trace_spapr_vscsi_command_complete(sreq->tag, status, req);
     if (req == NULL) {
         fprintf(stderr, "VSCSI: Can't find request for tag 0x%x\n", sreq->tag);
         return;
@@ -567,16 +554,14 @@ static void vscsi_command_complete(SCSIRequest *sreq, 
uint32_t status, size_t re
     if (status == CHECK_CONDITION) {
         req->senselen = scsi_req_get_sense(req->sreq, req->sense,
                                            sizeof(req->sense));
-        DPRINTF("VSCSI: Sense data, %d bytes:\n", req->senselen);
-        DPRINTF("       %02x  %02x  %02x  %02x  %02x  %02x  %02x  %02x\n",
+        trace_spapr_vscsi_command_complete_sense_data(req->senselen,
                 req->sense[0], req->sense[1], req->sense[2], req->sense[3],
-                req->sense[4], req->sense[5], req->sense[6], req->sense[7]);
-        DPRINTF("       %02x  %02x  %02x  %02x  %02x  %02x  %02x  %02x\n",
+                req->sense[4], req->sense[5], req->sense[6], req->sense[7],
                 req->sense[8], req->sense[9], req->sense[10], req->sense[11],
                 req->sense[12], req->sense[13], req->sense[14], 
req->sense[15]);
     }
 
-    DPRINTF("VSCSI: Command complete err=%d\n", status);
+    trace_spapr_vscsi_command_complete_status(status);
     if (status == 0) {
         /* We handle overflows, not underflows for normal commands,
          * but hopefully nobody cares
@@ -635,8 +620,8 @@ static void vscsi_save_request(QEMUFile *f, SCSIRequest 
*sreq)
 
     vmstate_save_state(f, &vmstate_spapr_vscsi_req, req, NULL);
 
-    DPRINTF("VSCSI: saving tag=%u, current desc#%d, offset=%x\n",
-            req->qtag, req->cur_desc_num, req->cur_desc_offset);
+    trace_spapr_vscsi_save_request(req->qtag, req->cur_desc_num,
+                                   req->cur_desc_offset);
 }
 
 static void *vscsi_load_request(QEMUFile *f, SCSIRequest *sreq)
@@ -660,8 +645,8 @@ static void *vscsi_load_request(QEMUFile *f, SCSIRequest 
*sreq)
 
     req->sreq = scsi_req_ref(sreq);
 
-    DPRINTF("VSCSI: restoring tag=%u, current desc#%d, offset=%x\n",
-            req->qtag, req->cur_desc_num, req->cur_desc_offset);
+    trace_spapr_vscsi_load_request(req->qtag, req->cur_desc_num,
+                                   req->cur_desc_offset);
 
     return req;
 }
@@ -672,7 +657,7 @@ static void vscsi_process_login(VSCSIState *s, vscsi_req 
*req)
     struct srp_login_rsp *rsp = &iu->srp.login_rsp;
     uint64_t tag = iu->srp.rsp.tag;
 
-    DPRINTF("VSCSI: Got login, sendin response !\n");
+    trace_spapr_vscsi__process_login();
 
     /* TODO handle case that requested size is wrong and
      * buffer format is wrong
@@ -795,8 +780,7 @@ static int vscsi_queue_cmd(VSCSIState *s, vscsi_req *req)
 
     sdev = vscsi_device_find(&s->bus, be64_to_cpu(srp->cmd.lun), &lun);
     if (!sdev) {
-        DPRINTF("VSCSI: Command for lun %08" PRIx64 " with no drive\n",
-                be64_to_cpu(srp->cmd.lun));
+        trace_spapr_vscsi_queue_cmd_no_drive(be64_to_cpu(srp->cmd.lun));
         if (srp->cmd.cdb[0] == INQUIRY) {
             vscsi_inquiry_no_target(s, req);
         } else {
@@ -808,9 +792,8 @@ static int vscsi_queue_cmd(VSCSIState *s, vscsi_req *req)
     req->sreq = scsi_req_new(sdev, req->qtag, lun, srp->cmd.cdb, req);
     n = scsi_req_enqueue(req->sreq);
 
-    DPRINTF("VSCSI: Queued command tag 0x%x CMD 0x%x=%s LUN %d ret: %d\n",
-            req->qtag, srp->cmd.cdb[0], scsi_command_name(srp->cmd.cdb[0]),
-            lun, n);
+    trace_spapr_vscsi_queue_cmd(req->qtag, srp->cmd.cdb[0],
+                                scsi_command_name(srp->cmd.cdb[0]), lun, n);
 
     if (n) {
         /* Transfer direction must be set before preprocessing the
@@ -1141,7 +1124,7 @@ static int vscsi_do_crq(struct VIOsPAPRDevice *dev, 
uint8_t *crq_data)
     crq.s.IU_length = be16_to_cpu(crq.s.IU_length);
     crq.s.IU_data_ptr = be64_to_cpu(crq.s.IU_data_ptr);
 
-    DPRINTF("VSCSI: do_crq %02x %02x ...\n", crq.raw[0], crq.raw[1]);
+    trace_spapr_vscsi_do_crq(crq.raw[0], crq.raw[1]);
 
     switch (crq.s.valid) {
     case 0xc0: /* Init command/response */
diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
index ed64858..e3770b5 100644
--- a/hw/scsi/trace-events
+++ b/hw/scsi/trace-events
@@ -202,3 +202,30 @@ esp_pci_dma_abort(uint32_t val) "ABORT (%.8x)"
 esp_pci_dma_start(uint32_t val) "START (%.8x)"
 esp_pci_sbac_read(uint32_t reg) "sbac: 0x%8.8x"
 esp_pci_sbac_write(uint32_t reg, uint32_t val) "sbac: 0x%8.8x -> 0x%8.8x"
+
+# hw/scsi/spapr_vscsi.c
+
+spapr_vscsi_send_rsp(uint8_t status, int32_t res_in, int32_t res_out) "status: 
0x%x, res_in: %"PRId32", res_out: %"PRId32
+spapr_vscsi_fetch_desc_no_data(void) "no data descriptor"
+spapr_vscsi_fetch_desc_direct(void) "direct segment"
+spapr_vscsi_fetch_desc_indirect(uint32_t qtag, unsigned desc, unsigned 
local_desc) "indirect segment local tag=0x%"PRIx32" desc#%u/%u"
+spapr_vscsi_fetch_desc_out_of_range(unsigned desc, unsigned desc_offset) "#%u 
is ouf of range (%u bytes)"
+spapr_vscsi_fetch_desc_dma_read_error(int rc) "spapr_vio_dma_read -> %d 
reading ext_desc"
+spapr_vscsi_fetch_desc_indirect_seg_ext(uint32_t qtag, unsigned n, unsigned 
desc, uint64_t va, uint32_t len) "indirect segment ext. tag=0x%"PRIx32" 
desc#%u/%u { va=0x%"PRIx64" len=0x%"PRIx32" }"
+spapr_vscsi_fetch_desc_out_of_desc(void) "Out of descriptors !"
+spapr_vscsi_fetch_desc_out_of_desc_boundary(unsigned offset, unsigned desc, 
uint32_t len) "   offset=0x%x is out of a descriptor #%u boundary=%"PRIx32
+spapr_vscsi_fetch_desc_done(unsigned desc_num, unsigned desc_offset, uint64_t 
va, uint32_t len) "   cur=%u offs=0x%x ret { va=0x%"PRIx64" len=0x%"PRIx32" }"
+spapr_vscsi_srp_indirect_data(uint32_t len) "indirect segment 0x%"PRIx32" 
bytes"
+spapr_vscsi_srp_indirect_data_rw(int writing, int rc) "spapr_vio_dma_r/w(%d) 
-> %d"
+spapr_vscsi_srp_indirect_data_buf(unsigned a, unsigned b, unsigned c, unsigned 
d) "     data: %02x %02x %02x %02x..."
+spapr_vscsi_srp_transfer_data(uint32_t len) "no data desc transfer, skipping 
0x%"PRIx32" bytes"
+spapr_vscsi_transfer_data(uint32_t tag, uint32_t len, void *req) "SCSI xfer 
complete tag=0x%"PRIx32" len=0x%"PRIx32", req=%p"
+spapr_vscsi_command_complete(uint32_t tag, uint32_t status, void *req) "SCSI 
cmd complete, tag=0x%"PRIx32" status=0x%"PRIx32", req=%p"
+spapr_vscsi_command_complete_sense_data(uint32_t len, unsigned s0, unsigned 
s1, unsigned s2, unsigned s3, unsigned s4, unsigned s5, unsigned s6, unsigned 
s7, unsigned s8, unsigned s9, unsigned s10, unsigned s11, unsigned s12, 
unsigned s13, unsigned s14, unsigned s15) "Sense data, %d bytes: %02x %02x %02x 
%02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x %02x"
+spapr_vscsi_command_complete_status(uint32_t status) "Command complete 
err=%"PRIu32
+spapr_vscsi_save_request(uint32_t qtag, unsigned desc, unsigned offset) 
"saving tag=%"PRIu32", current desc#%u, offset=0x%x"
+spapr_vscsi_load_request(uint32_t qtag, unsigned desc, unsigned offset) 
"restoring tag=%"PRIu32", current desc#%u, offset=0x%x"
+spapr_vscsi__process_login(void) "Got login, sending response !"
+spapr_vscsi_queue_cmd_no_drive(uint64_t lun) "Command for lun %08" PRIx64 " 
with no drive"
+spapr_vscsi_queue_cmd(uint32_t qtag, unsigned cdb, const char *cmd, int lun, 
int ret) "Queued command tag 0x%"PRIx32" CMD 0x%x=%s LUN %d ret: %d"
+spapr_vscsi_do_crq(unsigned c0, unsigned c1) "crq: %02x %02x ..."
-- 
2.5.5