All of lore.kernel.org
 help / color / mirror / Atom feed
* [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
@ 2018-12-07 13:17 Laurent Vivier
  2018-12-07 13:17 ` [Qemu-devel] [PATCH 2/2] scsi-generic: " Laurent Vivier
                   ` (3 more replies)
  0 siblings, 4 replies; 10+ messages in thread
From: Laurent Vivier @ 2018-12-07 13:17 UTC (permalink / raw)
  To: qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé, Laurent Vivier

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
---
 hw/scsi/scsi-disk.c  | 105 +++++++++++++++++++++----------------------
 hw/scsi/trace-events |  29 ++++++++++++
 2 files changed, 81 insertions(+), 53 deletions(-)

diff --git a/hw/scsi/scsi-disk.c b/hw/scsi/scsi-disk.c
index 0e9027c8f3..29e541efdb 100644
--- a/hw/scsi/scsi-disk.c
+++ b/hw/scsi/scsi-disk.c
@@ -19,15 +19,6 @@
  * the host adapter emulator.
  */
 
-//#define DEBUG_SCSI
-
-#ifdef DEBUG_SCSI
-#define DPRINTF(fmt, ...) \
-do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF(fmt, ...) do {} while(0)
-#endif
-
 #include "qemu/osdep.h"
 #include "qemu/units.h"
 #include "qapi/error.h"
@@ -41,6 +32,7 @@ do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
 #include "hw/block/block.h"
 #include "sysemu/dma.h"
 #include "qemu/cutils.h"
+#include "trace.h"
 
 #ifdef __linux
 #include <scsi/sg.h>
@@ -128,8 +120,8 @@ static void scsi_free_request(SCSIRequest *req)
 /* Helper function for command completion with sense.  */
 static void scsi_check_condition(SCSIDiskReq *r, SCSISense sense)
 {
-    DPRINTF("Command complete tag=0x%x sense=%d/%d/%d\n",
-            r->req.tag, sense.key, sense.asc, sense.ascq);
+    trace_scsi_disk_check_condition(r->req.tag, sense.key, sense.asc,
+                                    sense.ascq);
     scsi_req_build_sense(&r->req, sense);
     scsi_req_complete(&r->req, CHECK_CONDITION);
 }
@@ -317,7 +309,7 @@ static void scsi_read_complete(void * opaque, int ret)
     }
 
     block_acct_done(blk_get_stats(s->qdev.conf.blk), &r->acct);
-    DPRINTF("Data ready tag=0x%x len=%zd\n", r->req.tag, r->qiov.size);
+    trace_scsi_disk_read_complete(r->req.tag, r->qiov.size);
 
     n = r->qiov.size / 512;
     r->sector += n;
@@ -388,7 +380,7 @@ static void scsi_read_data(SCSIRequest *req)
     SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
     bool first;
 
-    DPRINTF("Read sector_count=%d\n", r->sector_count);
+    trace_scsi_disk_read_data_count(r->sector_count);
     if (r->sector_count == 0) {
         /* This also clears the sense buffer for REQUEST SENSE.  */
         scsi_req_complete(&r->req, GOOD);
@@ -401,7 +393,7 @@ static void scsi_read_data(SCSIRequest *req)
     /* The request is used as the AIO opaque value, so add a ref.  */
     scsi_req_ref(&r->req);
     if (r->req.cmd.mode == SCSI_XFER_TO_DEV) {
-        DPRINTF("Data transfer direction invalid\n");
+        trace_scsi_disk_read_data_invalid();
         scsi_read_complete(r, -EINVAL);
         return;
     }
@@ -502,7 +494,7 @@ static void scsi_write_complete_noio(SCSIDiskReq *r, int ret)
         return;
     } else {
         scsi_init_iovec(r, SCSI_DMA_BUF_SIZE);
-        DPRINTF("Write complete tag=0x%x more=%zd\n", r->req.tag, r->qiov.size);
+        trace_scsi_disk_write_complete_noio(r->req.tag, r->qiov.size);
         scsi_req_data(&r->req, r->qiov.size);
     }
 
@@ -540,7 +532,7 @@ static void scsi_write_data(SCSIRequest *req)
     /* The request is used as the AIO opaque value, so add a ref.  */
     scsi_req_ref(&r->req);
     if (r->req.cmd.mode != SCSI_XFER_TO_DEV) {
-        DPRINTF("Data transfer direction invalid\n");
+        trace_scsi_disk_write_data_invalid();
         scsi_write_complete_noio(r, -EINVAL);
         return;
     }
@@ -605,8 +597,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
     switch (page_code) {
     case 0x00: /* Supported page codes, mandatory */
     {
-        DPRINTF("Inquiry EVPD[Supported pages] "
-                "buffer size %zd\n", req->cmd.xfer);
+        trace_scsi_disk_emulate_vpd_page_00(req->cmd.xfer);
         outbuf[buflen++] = 0x00; /* list of supported pages (this page) */
         if (s->serial) {
             outbuf[buflen++] = 0x80; /* unit serial number */
@@ -624,7 +615,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
         int l;
 
         if (!s->serial) {
-            DPRINTF("Inquiry (EVPD[Serial number] not supported\n");
+            trace_scsi_disk_emulate_vpd_page_80_not_supported();
             return -1;
         }
 
@@ -633,8 +624,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
             l = 36;
         }
 
-        DPRINTF("Inquiry EVPD[Serial number] "
-                "buffer size %zd\n", req->cmd.xfer);
+        trace_scsi_disk_emulate_vpd_page_80(req->cmd.xfer);
         memcpy(outbuf + buflen, s->serial, l);
         buflen += l;
         break;
@@ -649,8 +639,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
         if (id_len > max_len) {
             id_len = max_len;
         }
-        DPRINTF("Inquiry EVPD[Device identification] "
-                "buffer size %zd\n", req->cmd.xfer);
+        trace_scsi_disk_emulate_vpd_page_83(req->cmd.xfer);
 
         outbuf[buflen++] = 0x2; /* ASCII */
         outbuf[buflen++] = 0;   /* not officially assigned */
@@ -695,8 +684,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
         SCSIBlockLimits bl = {};
 
         if (s->qdev.type == TYPE_ROM) {
-            DPRINTF("Inquiry (EVPD[%02X] not supported for CDROM\n",
-                    page_code);
+            trace_scsi_disk_emulate_vpd_page_b0_not_supported();
             return -1;
         }
         bl.wsnz = 1;
@@ -1243,8 +1231,9 @@ static int scsi_disk_emulate_mode_sense(SCSIDiskReq *r, uint8_t *outbuf)
     dbd = (r->req.cmd.buf[1] & 0x8) != 0;
     page = r->req.cmd.buf[2] & 0x3f;
     page_control = (r->req.cmd.buf[2] & 0xc0) >> 6;
-    DPRINTF("Mode Sense(%d) (page %d, xfer %zd, page_control %d)\n",
-        (r->req.cmd.buf[0] == MODE_SENSE) ? 6 : 10, page, r->req.cmd.xfer, page_control);
+
+    trace_scsi_disk_emulate_mode_sense((r->req.cmd.buf[0] == MODE_SENSE) ? 6 :
+                                       10, page, r->req.cmd.xfer, page_control);
     memset(outbuf, 0, r->req.cmd.xfer);
     p = outbuf;
 
@@ -1336,7 +1325,7 @@ static int scsi_disk_emulate_read_toc(SCSIRequest *req, uint8_t *outbuf)
     format = req->cmd.buf[2] & 0xf;
     start_track = req->cmd.buf[6];
     blk_get_geometry(s->qdev.conf.blk, &nb_sectors);
-    DPRINTF("Read TOC (track %d format %d msf %d)\n", start_track, format, msf >> 1);
+    trace_scsi_disk_emulate_read_toc(start_track, format, msf >> 1);
     nb_sectors /= s->qdev.blocksize / 512;
     switch (format) {
     case 0:
@@ -1395,7 +1384,7 @@ static void scsi_disk_emulate_read_data(SCSIRequest *req)
     int buflen = r->iov.iov_len;
 
     if (buflen) {
-        DPRINTF("Read buf_len=%d\n", buflen);
+        trace_scsi_disk_emulate_read_data(buflen);
         r->iov.iov_len = 0;
         r->started = true;
         scsi_req_data(&r->req, buflen);
@@ -1814,7 +1803,7 @@ static void scsi_disk_emulate_write_data(SCSIRequest *req)
 
     if (r->iov.iov_len) {
         int buflen = r->iov.iov_len;
-        DPRINTF("Write buf_len=%d\n", buflen);
+        trace_scsi_disk_emulate_write_data(buflen);
         r->iov.iov_len = 0;
         scsi_req_data(&r->req, buflen);
         return;
@@ -2023,7 +2012,7 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
     case SERVICE_ACTION_IN_16:
         /* Service Action In subcommands. */
         if ((req->cmd.buf[1] & 31) == SAI_READ_CAPACITY_16) {
-            DPRINTF("SAI READ CAPACITY(16)\n");
+            trace_scsi_disk_emulate_command_SAI_16();
             memset(outbuf, 0, req->cmd.xfer);
             blk_get_geometry(s->qdev.conf.blk, &nb_sectors);
             if (!nb_sectors) {
@@ -2061,7 +2050,7 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
             /* Protection, exponent and lowest lba field left blank. */
             break;
         }
-        DPRINTF("Unsupported Service Action In\n");
+        trace_scsi_disk_emulate_command_SAI_unsupported();
         goto illegal_request;
     case SYNCHRONIZE_CACHE:
         /* The request is used as the AIO opaque value, so add a ref.  */
@@ -2071,37 +2060,36 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
         r->req.aiocb = blk_aio_flush(s->qdev.conf.blk, scsi_aio_complete, r);
         return 0;
     case SEEK_10:
-        DPRINTF("Seek(10) (sector %" PRId64 ")\n", r->req.cmd.lba);
+        trace_scsi_disk_emulate_command_SEEK_10(r->req.cmd.lba);
         if (r->req.cmd.lba > s->qdev.max_lba) {
             goto illegal_lba;
         }
         break;
     case MODE_SELECT:
-        DPRINTF("Mode Select(6) (len %lu)\n", (unsigned long)r->req.cmd.xfer);
+        trace_scsi_disk_emulate_command_MODE_SELECT(r->req.cmd.xfer);
         break;
     case MODE_SELECT_10:
-        DPRINTF("Mode Select(10) (len %lu)\n", (unsigned long)r->req.cmd.xfer);
+        trace_scsi_disk_emulate_command_MODE_SELECT_10(r->req.cmd.xfer);
         break;
     case UNMAP:
-        DPRINTF("Unmap (len %lu)\n", (unsigned long)r->req.cmd.xfer);
+        trace_scsi_disk_emulate_command_UNMAP(r->req.cmd.xfer);
         break;
     case VERIFY_10:
     case VERIFY_12:
     case VERIFY_16:
-        DPRINTF("Verify (bytchk %d)\n", (req->cmd.buf[1] >> 1) & 3);
+        trace_scsi_disk_emulate_command_VERIFY((req->cmd.buf[1] >> 1) & 3);
         if (req->cmd.buf[1] & 6) {
             goto illegal_request;
         }
         break;
     case WRITE_SAME_10:
     case WRITE_SAME_16:
-        DPRINTF("WRITE SAME %d (len %lu)\n",
-                req->cmd.buf[0] == WRITE_SAME_10 ? 10 : 16,
-                (unsigned long)r->req.cmd.xfer);
+        trace_scsi_disk_emulate_command_WRITE_SAME(
+                req->cmd.buf[0] == WRITE_SAME_10 ? 10 : 16, r->req.cmd.xfer);
         break;
     default:
-        DPRINTF("Unknown SCSI command (%2.2x=%s)\n", buf[0],
-                scsi_command_name(buf[0]));
+        trace_scsi_disk_emulate_command_UNKNOWN(buf[0],
+                                                scsi_command_name(buf[0]));
         scsi_check_condition(r, SENSE_CODE(INVALID_OPCODE));
         return 0;
     }
@@ -2154,7 +2142,7 @@ static int32_t scsi_disk_dma_command(SCSIRequest *req, uint8_t *buf)
     case READ_10:
     case READ_12:
     case READ_16:
-        DPRINTF("Read (sector %" PRId64 ", count %u)\n", r->req.cmd.lba, len);
+        trace_scsi_disk_dma_command_READ(r->req.cmd.lba, len);
         /* Protection information is not supported.  For SCSI versions 2 and
          * older (as determined by snooping the guest's INQUIRY commands),
          * there is no RD/WR/VRPROTECT, so skip this check in these versions.
@@ -2179,7 +2167,7 @@ static int32_t scsi_disk_dma_command(SCSIRequest *req, uint8_t *buf)
             scsi_check_condition(r, SENSE_CODE(WRITE_PROTECTED));
             return 0;
         }
-        DPRINTF("Write %s(sector %" PRId64 ", count %u)\n",
+        trace_scsi_disk_dma_command_WRITE(
                 (command & 0xe) == 0xe ? "And Verify " : "",
                 r->req.cmd.lba, len);
         /* fall through */
@@ -2497,6 +2485,24 @@ static const SCSIReqOps *const scsi_disk_reqops_dispatch[256] = {
     [WRITE_VERIFY_16]                 = &scsi_disk_dma_reqops,
 };
 
+static void scsi_disk_new_request_dump(uint32_t lun, uint32_t tag, uint8_t *buf,
+                                       void (*trace_fn)(uint32_t, uint32_t,
+                                                        char const *))
+{
+    int i;
+    int len = scsi_cdb_length(buf);
+    char *line_buffer, *p;
+
+    line_buffer = g_malloc(len * 5 + 1);
+
+    for (i = 0, p = line_buffer; i < len; i++) {
+        p += sprintf(p, " 0x%02x", buf[i]);
+    }
+    trace_fn(lun, tag, line_buffer);
+
+    g_free(line_buffer);
+}
+
 static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
                                      uint8_t *buf, void *hba_private)
 {
@@ -2512,16 +2518,9 @@ static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
     }
     req = scsi_req_alloc(ops, &s->qdev, tag, lun, hba_private);
 
-#ifdef DEBUG_SCSI
-    DPRINTF("Command: lun=%d tag=0x%x data=0x%02x", lun, tag, buf[0]);
-    {
-        int i;
-        for (i = 1; i < scsi_cdb_length(buf); i++) {
-            printf(" 0x%02x", buf[i]);
-        }
-        printf("\n");
+    if (trace_event_get_state_backends(TRACE_SCSI_DISK_NEW_REQUEST)) {
+        scsi_disk_new_request_dump(lun, tag, buf, trace_scsi_disk_new_request);
     }
-#endif
 
     return req;
 }
diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
index 0fb6a99616..e9625f790c 100644
--- a/hw/scsi/trace-events
+++ b/hw/scsi/trace-events
@@ -291,3 +291,32 @@ lsi_execute_script_stop(void) "SCRIPTS execution stopped"
 lsi_awoken(void) "Woken by SIGP"
 lsi_reg_read(const char *name, int offset, uint8_t ret) "Read reg %s 0x%x = 0x%02x"
 lsi_reg_write(const char *name, int offset, uint8_t val) "Write reg %s 0x%x = 0x%02x"
+
+# hw/scsi/scsi-disk.c
+scsi_disk_check_condition(uint32_t tag, uint8_t key, uint8_t asc, uint8_t ascq) "Command complete tag=0x%x sense=%d/%d/%d"
+scsi_disk_read_complete(uint32_t tag, size_t size) "Data ready tag=0x%x len=%zd"
+scsi_disk_read_data_count(uint32_t sector_count) "Read sector_count=%d"
+scsi_disk_read_data_invalid(void) "Data transfer direction invalid"
+scsi_disk_write_complete_noio(uint32_t tag, size_t size) "Write complete tag=0x%x more=%zd"
+scsi_disk_write_data_invalid(void) "Data transfer direction invalid"
+scsi_disk_emulate_vpd_page_00(size_t xfer) "Inquiry EVPD[Supported pages] buffer size %zd"
+scsi_disk_emulate_vpd_page_80_not_supported(void) "Inquiry (EVPD[Serial number] not supported"
+scsi_disk_emulate_vpd_page_80(size_t xfer) "Inquiry EVPD[Serial number] buffer size %zd"
+scsi_disk_emulate_vpd_page_83(size_t xfer) "Inquiry EVPD[Device identification] buffer size %zd"
+scsi_disk_emulate_vpd_page_b0_not_supported(void) "Inquiry (EVPD[Block limits] not supported for CDROM"
+scsi_disk_emulate_mode_sense(int cmd, int page, size_t xfer, int control) "Mode Sense(%d) (page %d, xfer %zd, page_control %d)"
+scsi_disk_emulate_read_toc(int start_track, int format, int msf) "Read TOC (track %d format %d msf %d)"
+scsi_disk_emulate_read_data(int buflen) "Read buf_len=%d"
+scsi_disk_emulate_write_data(int buflen) "Write buf_len=%d"
+scsi_disk_emulate_command_SAI_16(void) "SAI READ CAPACITY(16)"
+scsi_disk_emulate_command_SAI_unsupported(void) "Unsupported Service Action In"
+scsi_disk_emulate_command_SEEK_10(uint64_t lba) "Seek(10) (sector %" PRId64 ")"
+scsi_disk_emulate_command_MODE_SELECT(size_t xfer) "Mode Select(6) (len %zd)"
+scsi_disk_emulate_command_MODE_SELECT_10(size_t xfer) "Mode Select(10) (len %zd)"
+scsi_disk_emulate_command_UNMAP(size_t xfer) "Unmap (len %zd)"
+scsi_disk_emulate_command_VERIFY(int bytchk) "Verify (bytchk %d)"
+scsi_disk_emulate_command_WRITE_SAME(int cmd, size_t xfer) "WRITE SAME %d (len %zd)"
+scsi_disk_emulate_command_UNKNOWN(int cmd, const char *name) "Unknown SCSI command (0x%2.2x=%s)"
+scsi_disk_dma_command_READ(uint64_t lba, uint32_t len) "Read (sector %" PRId64 ", count %u)"
+scsi_disk_dma_command_WRITE(const char *cmd, uint64_t lba, int len) "Write %s(sector %" PRId64 ", count %u)"
+scsi_disk_new_request(uint32_t lun, uint32_t tag, const char *line) "Command: lun=%d tag=0x%x data=%s"
-- 
2.19.2

^ permalink raw reply related	[flat|nested] 10+ messages in thread

* [Qemu-devel] [PATCH 2/2] scsi-generic: Convert from DPRINTF() macro to trace events
  2018-12-07 13:17 [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events Laurent Vivier
@ 2018-12-07 13:17 ` Laurent Vivier
  2018-12-07 15:38   ` Philippe Mathieu-Daudé
  2018-12-07 15:37 ` [Qemu-devel] [PATCH 1/2] scsi-disk: " Philippe Mathieu-Daudé
                   ` (2 subsequent siblings)
  3 siblings, 1 reply; 10+ messages in thread
From: Laurent Vivier @ 2018-12-07 13:17 UTC (permalink / raw)
  To: qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé, Laurent Vivier

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
---
 hw/scsi/scsi-generic.c | 56 ++++++++++++++++++++----------------------
 hw/scsi/trace-events   | 11 +++++++++
 2 files changed, 37 insertions(+), 30 deletions(-)

diff --git a/hw/scsi/scsi-generic.c b/hw/scsi/scsi-generic.c
index 7237b4162e..842f8e0893 100644
--- a/hw/scsi/scsi-generic.c
+++ b/hw/scsi/scsi-generic.c
@@ -18,21 +18,10 @@
 #include "hw/scsi/scsi.h"
 #include "hw/scsi/emulation.h"
 #include "sysemu/block-backend.h"
+#include "trace.h"
 
 #ifdef __linux__
 
-//#define DEBUG_SCSI
-
-#ifdef DEBUG_SCSI
-#define DPRINTF(fmt, ...) \
-do { printf("scsi-generic: " fmt , ## __VA_ARGS__); } while (0)
-#else
-#define DPRINTF(fmt, ...) do {} while(0)
-#endif
-
-#define BADF(fmt, ...) \
-do { fprintf(stderr, "scsi-generic: " fmt , ## __VA_ARGS__); } while (0)
-
 #include <scsi/sg.h>
 #include "scsi/constants.h"
 
@@ -98,8 +87,7 @@ static void scsi_command_complete_noio(SCSIGenericReq *r, int ret)
         }
     }
 
-    DPRINTF("Command complete 0x%p tag=0x%x status=%d\n",
-            r, r->req.tag, status);
+    trace_scsi_generic_command_complete_noio(r, r->req.tag, status);
 
     scsi_req_complete(&r->req, status);
 done:
@@ -259,7 +247,7 @@ static void scsi_read_complete(void * opaque, int ret)
     }
 
     len = r->io_header.dxfer_len - r->io_header.resid;
-    DPRINTF("Data ready tag=0x%x len=%d\n", r->req.tag, len);
+    trace_scsi_generic_read_complete(r->req.tag, len);
 
     r->len = -1;
 
@@ -335,7 +323,7 @@ static void scsi_read_data(SCSIRequest *req)
     SCSIDevice *s = r->req.dev;
     int ret;
 
-    DPRINTF("scsi_read_data tag=0x%x\n", req->tag);
+    trace_scsi_generic_read_data(req->tag);
 
     /* The request is used as the AIO opaque value, so add a ref.  */
     scsi_req_ref(&r->req);
@@ -356,7 +344,7 @@ static void scsi_write_complete(void * opaque, int ret)
     SCSIGenericReq *r = (SCSIGenericReq *)opaque;
     SCSIDevice *s = r->req.dev;
 
-    DPRINTF("scsi_write_complete() ret = %d\n", ret);
+    trace_scsi_generic_write_complete(ret);
 
     assert(r->req.aiocb != NULL);
     r->req.aiocb = NULL;
@@ -371,7 +359,7 @@ static void scsi_write_complete(void * opaque, int ret)
     if (r->req.cmd.buf[0] == MODE_SELECT && r->req.cmd.buf[4] == 12 &&
         s->type == TYPE_TAPE) {
         s->blocksize = (r->buf[9] << 16) | (r->buf[10] << 8) | r->buf[11];
-        DPRINTF("block size %d\n", s->blocksize);
+        trace_scsi_generic_write_complete_blocksize(s->blocksize);
     }
 
     scsi_command_complete_noio(r, ret);
@@ -388,7 +376,7 @@ static void scsi_write_data(SCSIRequest *req)
     SCSIDevice *s = r->req.dev;
     int ret;
 
-    DPRINTF("scsi_write_data tag=0x%x\n", req->tag);
+    trace_scsi_generic_write_data(req->tag);
     if (r->len == 0) {
         r->len = r->buflen;
         scsi_req_data(&r->req, r->len);
@@ -411,6 +399,21 @@ static uint8_t *scsi_get_buf(SCSIRequest *req)
     return r->buf;
 }
 
+static void scsi_generic_command_dump(uint8_t *cmd, int len)
+{
+    int i;
+    char *line_buffer, *p;
+
+    line_buffer = g_malloc(len * 5 + 1);
+
+    for (i = 0, p = line_buffer; i < len; i++) {
+        p += sprintf(p, " 0x%02x", cmd[i]);
+    }
+    trace_scsi_generic_send_command(line_buffer);
+
+    g_free(line_buffer);
+}
+
 /* Execute a scsi command.  Returns the length of the data expected by the
    command.  This will be Positive for data transfers from the device
    (eg. disk reads), negative for transfers to the device (eg. disk writes),
@@ -422,16 +425,9 @@ static int32_t scsi_send_command(SCSIRequest *req, uint8_t *cmd)
     SCSIDevice *s = r->req.dev;
     int ret;
 
-#ifdef DEBUG_SCSI
-    DPRINTF("Command: data=0x%02x", cmd[0]);
-    {
-        int i;
-        for (i = 1; i < r->req.cmd.len; i++) {
-            printf(" 0x%02x", cmd[i]);
-        }
-        printf("\n");
+    if (trace_event_get_state_backends(TRACE_SCSI_GENERIC_SEND_COMMAND)) {
+        scsi_generic_command_dump(cmd, r->req.cmd.len);
     }
-#endif
 
     if (r->req.cmd.xfer == 0) {
         g_free(r->buf);
@@ -693,7 +689,7 @@ static void scsi_generic_realize(SCSIDevice *s, Error **errp)
 
     /* define device state */
     s->type = scsiid.scsi_type;
-    DPRINTF("device type %d\n", s->type);
+    trace_scsi_generic_realize_type(s->type);
 
     switch (s->type) {
     case TYPE_TAPE:
@@ -716,7 +712,7 @@ static void scsi_generic_realize(SCSIDevice *s, Error **errp)
         break;
     }
 
-    DPRINTF("block size %d\n", s->blocksize);
+    trace_scsi_generic_realize_blocksize(s->blocksize);
 
     /* Only used by scsi-block, but initialize it nevertheless to be clean.  */
     s->default_scsi_version = -1;
diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
index e9625f790c..3c2fd7f52f 100644
--- a/hw/scsi/trace-events
+++ b/hw/scsi/trace-events
@@ -320,3 +320,14 @@ scsi_disk_emulate_command_UNKNOWN(int cmd, const char *name) "Unknown SCSI comma
 scsi_disk_dma_command_READ(uint64_t lba, uint32_t len) "Read (sector %" PRId64 ", count %u)"
 scsi_disk_dma_command_WRITE(const char *cmd, uint64_t lba, int len) "Write %s(sector %" PRId64 ", count %u)"
 scsi_disk_new_request(uint32_t lun, uint32_t tag, const char *line) "Command: lun=%d tag=0x%x data=%s"
+
+# hw/scsi/scsi-generic.c
+scsi_generic_command_complete_noio(void *req, uint32_t tag, int statuc) "Command complete %p tag=0x%x status=%d"
+scsi_generic_read_complete(uint32_t tag, int len) "Data ready tag=0x%x len=%d"
+scsi_generic_read_data(uint32_t tag) "scsi_read_data tag=0x%x"
+scsi_generic_write_complete(int ret) "scsi_write_complete() ret = %d"
+scsi_generic_write_complete_blocksize(int blocksize) "block size %d"
+scsi_generic_write_data(uint32_t tag) "scsi_write_data tag=0x%x"
+scsi_generic_send_command(const char *line) "Command: data=%s"
+scsi_generic_realize_type(int type) "device type %d"
+scsi_generic_realize_blocksize(int blocksize) "block size %d"
-- 
2.19.2

^ permalink raw reply related	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-07 13:17 [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events Laurent Vivier
  2018-12-07 13:17 ` [Qemu-devel] [PATCH 2/2] scsi-generic: " Laurent Vivier
@ 2018-12-07 15:37 ` Philippe Mathieu-Daudé
  2018-12-07 16:37   ` Laurent Vivier
  2018-12-07 16:47 ` Eric Blake
  2018-12-19 21:29 ` Paolo Bonzini
  3 siblings, 1 reply; 10+ messages in thread
From: Philippe Mathieu-Daudé @ 2018-12-07 15:37 UTC (permalink / raw)
  To: Laurent Vivier, qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé

On 12/7/18 2:17 PM, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  hw/scsi/scsi-disk.c  | 105 +++++++++++++++++++++----------------------
>  hw/scsi/trace-events |  29 ++++++++++++
>  2 files changed, 81 insertions(+), 53 deletions(-)
> 
> diff --git a/hw/scsi/scsi-disk.c b/hw/scsi/scsi-disk.c
> index 0e9027c8f3..29e541efdb 100644
> --- a/hw/scsi/scsi-disk.c
> +++ b/hw/scsi/scsi-disk.c
> @@ -19,15 +19,6 @@
>   * the host adapter emulator.
>   */
>  
> -//#define DEBUG_SCSI
> -
> -#ifdef DEBUG_SCSI
> -#define DPRINTF(fmt, ...) \
> -do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF(fmt, ...) do {} while(0)
> -#endif
> -
>  #include "qemu/osdep.h"
>  #include "qemu/units.h"
>  #include "qapi/error.h"
> @@ -41,6 +32,7 @@ do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
>  #include "hw/block/block.h"
>  #include "sysemu/dma.h"
>  #include "qemu/cutils.h"
> +#include "trace.h"
>  
>  #ifdef __linux
>  #include <scsi/sg.h>
> @@ -128,8 +120,8 @@ static void scsi_free_request(SCSIRequest *req)
>  /* Helper function for command completion with sense.  */
>  static void scsi_check_condition(SCSIDiskReq *r, SCSISense sense)
>  {
> -    DPRINTF("Command complete tag=0x%x sense=%d/%d/%d\n",
> -            r->req.tag, sense.key, sense.asc, sense.ascq);
> +    trace_scsi_disk_check_condition(r->req.tag, sense.key, sense.asc,
> +                                    sense.ascq);
>      scsi_req_build_sense(&r->req, sense);
>      scsi_req_complete(&r->req, CHECK_CONDITION);
>  }
> @@ -317,7 +309,7 @@ static void scsi_read_complete(void * opaque, int ret)
>      }
>  
>      block_acct_done(blk_get_stats(s->qdev.conf.blk), &r->acct);
> -    DPRINTF("Data ready tag=0x%x len=%zd\n", r->req.tag, r->qiov.size);
> +    trace_scsi_disk_read_complete(r->req.tag, r->qiov.size);
>  
>      n = r->qiov.size / 512;
>      r->sector += n;
> @@ -388,7 +380,7 @@ static void scsi_read_data(SCSIRequest *req)
>      SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
>      bool first;
>  
> -    DPRINTF("Read sector_count=%d\n", r->sector_count);
> +    trace_scsi_disk_read_data_count(r->sector_count);
>      if (r->sector_count == 0) {
>          /* This also clears the sense buffer for REQUEST SENSE.  */
>          scsi_req_complete(&r->req, GOOD);
> @@ -401,7 +393,7 @@ static void scsi_read_data(SCSIRequest *req)
>      /* The request is used as the AIO opaque value, so add a ref.  */
>      scsi_req_ref(&r->req);
>      if (r->req.cmd.mode == SCSI_XFER_TO_DEV) {
> -        DPRINTF("Data transfer direction invalid\n");
> +        trace_scsi_disk_read_data_invalid();
>          scsi_read_complete(r, -EINVAL);
>          return;
>      }
> @@ -502,7 +494,7 @@ static void scsi_write_complete_noio(SCSIDiskReq *r, int ret)
>          return;
>      } else {
>          scsi_init_iovec(r, SCSI_DMA_BUF_SIZE);
> -        DPRINTF("Write complete tag=0x%x more=%zd\n", r->req.tag, r->qiov.size);
> +        trace_scsi_disk_write_complete_noio(r->req.tag, r->qiov.size);
>          scsi_req_data(&r->req, r->qiov.size);
>      }
>  
> @@ -540,7 +532,7 @@ static void scsi_write_data(SCSIRequest *req)
>      /* The request is used as the AIO opaque value, so add a ref.  */
>      scsi_req_ref(&r->req);
>      if (r->req.cmd.mode != SCSI_XFER_TO_DEV) {
> -        DPRINTF("Data transfer direction invalid\n");
> +        trace_scsi_disk_write_data_invalid();
>          scsi_write_complete_noio(r, -EINVAL);
>          return;
>      }
> @@ -605,8 +597,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>      switch (page_code) {
>      case 0x00: /* Supported page codes, mandatory */
>      {
> -        DPRINTF("Inquiry EVPD[Supported pages] "
> -                "buffer size %zd\n", req->cmd.xfer);
> +        trace_scsi_disk_emulate_vpd_page_00(req->cmd.xfer);
>          outbuf[buflen++] = 0x00; /* list of supported pages (this page) */
>          if (s->serial) {
>              outbuf[buflen++] = 0x80; /* unit serial number */
> @@ -624,7 +615,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>          int l;
>  
>          if (!s->serial) {
> -            DPRINTF("Inquiry (EVPD[Serial number] not supported\n");
> +            trace_scsi_disk_emulate_vpd_page_80_not_supported();
>              return -1;
>          }
>  
> @@ -633,8 +624,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>              l = 36;
>          }
>  
> -        DPRINTF("Inquiry EVPD[Serial number] "
> -                "buffer size %zd\n", req->cmd.xfer);
> +        trace_scsi_disk_emulate_vpd_page_80(req->cmd.xfer);
>          memcpy(outbuf + buflen, s->serial, l);
>          buflen += l;
>          break;
> @@ -649,8 +639,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>          if (id_len > max_len) {
>              id_len = max_len;
>          }
> -        DPRINTF("Inquiry EVPD[Device identification] "
> -                "buffer size %zd\n", req->cmd.xfer);
> +        trace_scsi_disk_emulate_vpd_page_83(req->cmd.xfer);
>  
>          outbuf[buflen++] = 0x2; /* ASCII */
>          outbuf[buflen++] = 0;   /* not officially assigned */
> @@ -695,8 +684,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>          SCSIBlockLimits bl = {};
>  
>          if (s->qdev.type == TYPE_ROM) {
> -            DPRINTF("Inquiry (EVPD[%02X] not supported for CDROM\n",
> -                    page_code);
> +            trace_scsi_disk_emulate_vpd_page_b0_not_supported();
>              return -1;
>          }
>          bl.wsnz = 1;
> @@ -1243,8 +1231,9 @@ static int scsi_disk_emulate_mode_sense(SCSIDiskReq *r, uint8_t *outbuf)
>      dbd = (r->req.cmd.buf[1] & 0x8) != 0;
>      page = r->req.cmd.buf[2] & 0x3f;
>      page_control = (r->req.cmd.buf[2] & 0xc0) >> 6;
> -    DPRINTF("Mode Sense(%d) (page %d, xfer %zd, page_control %d)\n",
> -        (r->req.cmd.buf[0] == MODE_SENSE) ? 6 : 10, page, r->req.cmd.xfer, page_control);
> +
> +    trace_scsi_disk_emulate_mode_sense((r->req.cmd.buf[0] == MODE_SENSE) ? 6 :
> +                                       10, page, r->req.cmd.xfer, page_control);
>      memset(outbuf, 0, r->req.cmd.xfer);
>      p = outbuf;
>  
> @@ -1336,7 +1325,7 @@ static int scsi_disk_emulate_read_toc(SCSIRequest *req, uint8_t *outbuf)
>      format = req->cmd.buf[2] & 0xf;
>      start_track = req->cmd.buf[6];
>      blk_get_geometry(s->qdev.conf.blk, &nb_sectors);
> -    DPRINTF("Read TOC (track %d format %d msf %d)\n", start_track, format, msf >> 1);
> +    trace_scsi_disk_emulate_read_toc(start_track, format, msf >> 1);
>      nb_sectors /= s->qdev.blocksize / 512;
>      switch (format) {
>      case 0:
> @@ -1395,7 +1384,7 @@ static void scsi_disk_emulate_read_data(SCSIRequest *req)
>      int buflen = r->iov.iov_len;
>  
>      if (buflen) {
> -        DPRINTF("Read buf_len=%d\n", buflen);
> +        trace_scsi_disk_emulate_read_data(buflen);
>          r->iov.iov_len = 0;
>          r->started = true;
>          scsi_req_data(&r->req, buflen);
> @@ -1814,7 +1803,7 @@ static void scsi_disk_emulate_write_data(SCSIRequest *req)
>  
>      if (r->iov.iov_len) {
>          int buflen = r->iov.iov_len;
> -        DPRINTF("Write buf_len=%d\n", buflen);
> +        trace_scsi_disk_emulate_write_data(buflen);
>          r->iov.iov_len = 0;
>          scsi_req_data(&r->req, buflen);
>          return;
> @@ -2023,7 +2012,7 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
>      case SERVICE_ACTION_IN_16:
>          /* Service Action In subcommands. */
>          if ((req->cmd.buf[1] & 31) == SAI_READ_CAPACITY_16) {
> -            DPRINTF("SAI READ CAPACITY(16)\n");
> +            trace_scsi_disk_emulate_command_SAI_16();
>              memset(outbuf, 0, req->cmd.xfer);
>              blk_get_geometry(s->qdev.conf.blk, &nb_sectors);
>              if (!nb_sectors) {
> @@ -2061,7 +2050,7 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
>              /* Protection, exponent and lowest lba field left blank. */
>              break;
>          }
> -        DPRINTF("Unsupported Service Action In\n");
> +        trace_scsi_disk_emulate_command_SAI_unsupported();
>          goto illegal_request;
>      case SYNCHRONIZE_CACHE:
>          /* The request is used as the AIO opaque value, so add a ref.  */
> @@ -2071,37 +2060,36 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
>          r->req.aiocb = blk_aio_flush(s->qdev.conf.blk, scsi_aio_complete, r);
>          return 0;
>      case SEEK_10:
> -        DPRINTF("Seek(10) (sector %" PRId64 ")\n", r->req.cmd.lba);
> +        trace_scsi_disk_emulate_command_SEEK_10(r->req.cmd.lba);
>          if (r->req.cmd.lba > s->qdev.max_lba) {
>              goto illegal_lba;
>          }
>          break;
>      case MODE_SELECT:
> -        DPRINTF("Mode Select(6) (len %lu)\n", (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_MODE_SELECT(r->req.cmd.xfer);
>          break;
>      case MODE_SELECT_10:
> -        DPRINTF("Mode Select(10) (len %lu)\n", (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_MODE_SELECT_10(r->req.cmd.xfer);
>          break;
>      case UNMAP:
> -        DPRINTF("Unmap (len %lu)\n", (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_UNMAP(r->req.cmd.xfer);
>          break;
>      case VERIFY_10:
>      case VERIFY_12:
>      case VERIFY_16:
> -        DPRINTF("Verify (bytchk %d)\n", (req->cmd.buf[1] >> 1) & 3);
> +        trace_scsi_disk_emulate_command_VERIFY((req->cmd.buf[1] >> 1) & 3);
>          if (req->cmd.buf[1] & 6) {
>              goto illegal_request;
>          }
>          break;
>      case WRITE_SAME_10:
>      case WRITE_SAME_16:
> -        DPRINTF("WRITE SAME %d (len %lu)\n",
> -                req->cmd.buf[0] == WRITE_SAME_10 ? 10 : 16,
> -                (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_WRITE_SAME(
> +                req->cmd.buf[0] == WRITE_SAME_10 ? 10 : 16, r->req.cmd.xfer);
>          break;
>      default:
> -        DPRINTF("Unknown SCSI command (%2.2x=%s)\n", buf[0],
> -                scsi_command_name(buf[0]));
> +        trace_scsi_disk_emulate_command_UNKNOWN(buf[0],
> +                                                scsi_command_name(buf[0]));
>          scsi_check_condition(r, SENSE_CODE(INVALID_OPCODE));
>          return 0;
>      }
> @@ -2154,7 +2142,7 @@ static int32_t scsi_disk_dma_command(SCSIRequest *req, uint8_t *buf)
>      case READ_10:
>      case READ_12:
>      case READ_16:
> -        DPRINTF("Read (sector %" PRId64 ", count %u)\n", r->req.cmd.lba, len);
> +        trace_scsi_disk_dma_command_READ(r->req.cmd.lba, len);
>          /* Protection information is not supported.  For SCSI versions 2 and
>           * older (as determined by snooping the guest's INQUIRY commands),
>           * there is no RD/WR/VRPROTECT, so skip this check in these versions.
> @@ -2179,7 +2167,7 @@ static int32_t scsi_disk_dma_command(SCSIRequest *req, uint8_t *buf)
>              scsi_check_condition(r, SENSE_CODE(WRITE_PROTECTED));
>              return 0;
>          }
> -        DPRINTF("Write %s(sector %" PRId64 ", count %u)\n",
> +        trace_scsi_disk_dma_command_WRITE(
>                  (command & 0xe) == 0xe ? "And Verify " : "",
>                  r->req.cmd.lba, len);
>          /* fall through */
> @@ -2497,6 +2485,24 @@ static const SCSIReqOps *const scsi_disk_reqops_dispatch[256] = {
>      [WRITE_VERIFY_16]                 = &scsi_disk_dma_reqops,
>  };
>  
> +static void scsi_disk_new_request_dump(uint32_t lun, uint32_t tag, uint8_t *buf,
> +                                       void (*trace_fn)(uint32_t, uint32_t,
> +                                                        char const *))
> +{
> +    int i;
> +    int len = scsi_cdb_length(buf);
> +    char *line_buffer, *p;
> +
> +    line_buffer = g_malloc(len * 5 + 1);
> +
> +    for (i = 0, p = line_buffer; i < len; i++) {
> +        p += sprintf(p, " 0x%02x", buf[i]);
> +    }
> +    trace_fn(lun, tag, line_buffer);
> +
> +    g_free(line_buffer);
> +}
> +
>  static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
>                                       uint8_t *buf, void *hba_private)
>  {
> @@ -2512,16 +2518,9 @@ static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
>      }
>      req = scsi_req_alloc(ops, &s->qdev, tag, lun, hba_private);
>  
> -#ifdef DEBUG_SCSI
> -    DPRINTF("Command: lun=%d tag=0x%x data=0x%02x", lun, tag, buf[0]);
> -    {
> -        int i;
> -        for (i = 1; i < scsi_cdb_length(buf); i++) {
> -            printf(" 0x%02x", buf[i]);
> -        }
> -        printf("\n");
> +    if (trace_event_get_state_backends(TRACE_SCSI_DISK_NEW_REQUEST)) {
> +        scsi_disk_new_request_dump(lun, tag, buf, trace_scsi_disk_new_request);

TIL about trace_event_get_state_backends(), I'll use it to clean other
hexdump traces, thanks :)

Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Tested-by: Philippe Mathieu-Daudé <philmd@redhat.com>

>      }
> -#endif
>  
>      return req;
>  }
> diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
> index 0fb6a99616..e9625f790c 100644
> --- a/hw/scsi/trace-events
> +++ b/hw/scsi/trace-events
> @@ -291,3 +291,32 @@ lsi_execute_script_stop(void) "SCRIPTS execution stopped"
>  lsi_awoken(void) "Woken by SIGP"
>  lsi_reg_read(const char *name, int offset, uint8_t ret) "Read reg %s 0x%x = 0x%02x"
>  lsi_reg_write(const char *name, int offset, uint8_t val) "Write reg %s 0x%x = 0x%02x"
> +
> +# hw/scsi/scsi-disk.c
> +scsi_disk_check_condition(uint32_t tag, uint8_t key, uint8_t asc, uint8_t ascq) "Command complete tag=0x%x sense=%d/%d/%d"
> +scsi_disk_read_complete(uint32_t tag, size_t size) "Data ready tag=0x%x len=%zd"
> +scsi_disk_read_data_count(uint32_t sector_count) "Read sector_count=%d"
> +scsi_disk_read_data_invalid(void) "Data transfer direction invalid"
> +scsi_disk_write_complete_noio(uint32_t tag, size_t size) "Write complete tag=0x%x more=%zd"
> +scsi_disk_write_data_invalid(void) "Data transfer direction invalid"
> +scsi_disk_emulate_vpd_page_00(size_t xfer) "Inquiry EVPD[Supported pages] buffer size %zd"
> +scsi_disk_emulate_vpd_page_80_not_supported(void) "Inquiry (EVPD[Serial number] not supported"
> +scsi_disk_emulate_vpd_page_80(size_t xfer) "Inquiry EVPD[Serial number] buffer size %zd"
> +scsi_disk_emulate_vpd_page_83(size_t xfer) "Inquiry EVPD[Device identification] buffer size %zd"
> +scsi_disk_emulate_vpd_page_b0_not_supported(void) "Inquiry (EVPD[Block limits] not supported for CDROM"
> +scsi_disk_emulate_mode_sense(int cmd, int page, size_t xfer, int control) "Mode Sense(%d) (page %d, xfer %zd, page_control %d)"
> +scsi_disk_emulate_read_toc(int start_track, int format, int msf) "Read TOC (track %d format %d msf %d)"
> +scsi_disk_emulate_read_data(int buflen) "Read buf_len=%d"
> +scsi_disk_emulate_write_data(int buflen) "Write buf_len=%d"
> +scsi_disk_emulate_command_SAI_16(void) "SAI READ CAPACITY(16)"
> +scsi_disk_emulate_command_SAI_unsupported(void) "Unsupported Service Action In"
> +scsi_disk_emulate_command_SEEK_10(uint64_t lba) "Seek(10) (sector %" PRId64 ")"
> +scsi_disk_emulate_command_MODE_SELECT(size_t xfer) "Mode Select(6) (len %zd)"
> +scsi_disk_emulate_command_MODE_SELECT_10(size_t xfer) "Mode Select(10) (len %zd)"
> +scsi_disk_emulate_command_UNMAP(size_t xfer) "Unmap (len %zd)"
> +scsi_disk_emulate_command_VERIFY(int bytchk) "Verify (bytchk %d)"
> +scsi_disk_emulate_command_WRITE_SAME(int cmd, size_t xfer) "WRITE SAME %d (len %zd)"
> +scsi_disk_emulate_command_UNKNOWN(int cmd, const char *name) "Unknown SCSI command (0x%2.2x=%s)"
> +scsi_disk_dma_command_READ(uint64_t lba, uint32_t len) "Read (sector %" PRId64 ", count %u)"
> +scsi_disk_dma_command_WRITE(const char *cmd, uint64_t lba, int len) "Write %s(sector %" PRId64 ", count %u)"
> +scsi_disk_new_request(uint32_t lun, uint32_t tag, const char *line) "Command: lun=%d tag=0x%x data=%s"
> 

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 2/2] scsi-generic: Convert from DPRINTF() macro to trace events
  2018-12-07 13:17 ` [Qemu-devel] [PATCH 2/2] scsi-generic: " Laurent Vivier
@ 2018-12-07 15:38   ` Philippe Mathieu-Daudé
  0 siblings, 0 replies; 10+ messages in thread
From: Philippe Mathieu-Daudé @ 2018-12-07 15:38 UTC (permalink / raw)
  To: Laurent Vivier, qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé

On 12/7/18 2:17 PM, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  hw/scsi/scsi-generic.c | 56 ++++++++++++++++++++----------------------
>  hw/scsi/trace-events   | 11 +++++++++
>  2 files changed, 37 insertions(+), 30 deletions(-)
> 
> diff --git a/hw/scsi/scsi-generic.c b/hw/scsi/scsi-generic.c
> index 7237b4162e..842f8e0893 100644
> --- a/hw/scsi/scsi-generic.c
> +++ b/hw/scsi/scsi-generic.c
> @@ -18,21 +18,10 @@
>  #include "hw/scsi/scsi.h"
>  #include "hw/scsi/emulation.h"
>  #include "sysemu/block-backend.h"
> +#include "trace.h"
>  
>  #ifdef __linux__
>  
> -//#define DEBUG_SCSI
> -
> -#ifdef DEBUG_SCSI
> -#define DPRINTF(fmt, ...) \
> -do { printf("scsi-generic: " fmt , ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF(fmt, ...) do {} while(0)
> -#endif
> -
> -#define BADF(fmt, ...) \
> -do { fprintf(stderr, "scsi-generic: " fmt , ## __VA_ARGS__); } while (0)
> -
>  #include <scsi/sg.h>
>  #include "scsi/constants.h"
>  
> @@ -98,8 +87,7 @@ static void scsi_command_complete_noio(SCSIGenericReq *r, int ret)
>          }
>      }
>  
> -    DPRINTF("Command complete 0x%p tag=0x%x status=%d\n",
> -            r, r->req.tag, status);
> +    trace_scsi_generic_command_complete_noio(r, r->req.tag, status);
>  
>      scsi_req_complete(&r->req, status);
>  done:
> @@ -259,7 +247,7 @@ static void scsi_read_complete(void * opaque, int ret)
>      }
>  
>      len = r->io_header.dxfer_len - r->io_header.resid;
> -    DPRINTF("Data ready tag=0x%x len=%d\n", r->req.tag, len);
> +    trace_scsi_generic_read_complete(r->req.tag, len);
>  
>      r->len = -1;
>  
> @@ -335,7 +323,7 @@ static void scsi_read_data(SCSIRequest *req)
>      SCSIDevice *s = r->req.dev;
>      int ret;
>  
> -    DPRINTF("scsi_read_data tag=0x%x\n", req->tag);
> +    trace_scsi_generic_read_data(req->tag);
>  
>      /* The request is used as the AIO opaque value, so add a ref.  */
>      scsi_req_ref(&r->req);
> @@ -356,7 +344,7 @@ static void scsi_write_complete(void * opaque, int ret)
>      SCSIGenericReq *r = (SCSIGenericReq *)opaque;
>      SCSIDevice *s = r->req.dev;
>  
> -    DPRINTF("scsi_write_complete() ret = %d\n", ret);
> +    trace_scsi_generic_write_complete(ret);
>  
>      assert(r->req.aiocb != NULL);
>      r->req.aiocb = NULL;
> @@ -371,7 +359,7 @@ static void scsi_write_complete(void * opaque, int ret)
>      if (r->req.cmd.buf[0] == MODE_SELECT && r->req.cmd.buf[4] == 12 &&
>          s->type == TYPE_TAPE) {
>          s->blocksize = (r->buf[9] << 16) | (r->buf[10] << 8) | r->buf[11];
> -        DPRINTF("block size %d\n", s->blocksize);
> +        trace_scsi_generic_write_complete_blocksize(s->blocksize);
>      }
>  
>      scsi_command_complete_noio(r, ret);
> @@ -388,7 +376,7 @@ static void scsi_write_data(SCSIRequest *req)
>      SCSIDevice *s = r->req.dev;
>      int ret;
>  
> -    DPRINTF("scsi_write_data tag=0x%x\n", req->tag);
> +    trace_scsi_generic_write_data(req->tag);
>      if (r->len == 0) {
>          r->len = r->buflen;
>          scsi_req_data(&r->req, r->len);
> @@ -411,6 +399,21 @@ static uint8_t *scsi_get_buf(SCSIRequest *req)
>      return r->buf;
>  }
>  
> +static void scsi_generic_command_dump(uint8_t *cmd, int len)
> +{
> +    int i;
> +    char *line_buffer, *p;
> +
> +    line_buffer = g_malloc(len * 5 + 1);
> +
> +    for (i = 0, p = line_buffer; i < len; i++) {
> +        p += sprintf(p, " 0x%02x", cmd[i]);
> +    }
> +    trace_scsi_generic_send_command(line_buffer);
> +
> +    g_free(line_buffer);
> +}
> +
>  /* Execute a scsi command.  Returns the length of the data expected by the
>     command.  This will be Positive for data transfers from the device
>     (eg. disk reads), negative for transfers to the device (eg. disk writes),
> @@ -422,16 +425,9 @@ static int32_t scsi_send_command(SCSIRequest *req, uint8_t *cmd)
>      SCSIDevice *s = r->req.dev;
>      int ret;
>  
> -#ifdef DEBUG_SCSI
> -    DPRINTF("Command: data=0x%02x", cmd[0]);
> -    {
> -        int i;
> -        for (i = 1; i < r->req.cmd.len; i++) {
> -            printf(" 0x%02x", cmd[i]);
> -        }
> -        printf("\n");
> +    if (trace_event_get_state_backends(TRACE_SCSI_GENERIC_SEND_COMMAND)) {
> +        scsi_generic_command_dump(cmd, r->req.cmd.len);
>      }
> -#endif
>  
>      if (r->req.cmd.xfer == 0) {
>          g_free(r->buf);
> @@ -693,7 +689,7 @@ static void scsi_generic_realize(SCSIDevice *s, Error **errp)
>  
>      /* define device state */
>      s->type = scsiid.scsi_type;
> -    DPRINTF("device type %d\n", s->type);
> +    trace_scsi_generic_realize_type(s->type);
>  
>      switch (s->type) {
>      case TYPE_TAPE:
> @@ -716,7 +712,7 @@ static void scsi_generic_realize(SCSIDevice *s, Error **errp)
>          break;
>      }
>  
> -    DPRINTF("block size %d\n", s->blocksize);
> +    trace_scsi_generic_realize_blocksize(s->blocksize);
>  
>      /* Only used by scsi-block, but initialize it nevertheless to be clean.  */
>      s->default_scsi_version = -1;
> diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
> index e9625f790c..3c2fd7f52f 100644
> --- a/hw/scsi/trace-events
> +++ b/hw/scsi/trace-events
> @@ -320,3 +320,14 @@ scsi_disk_emulate_command_UNKNOWN(int cmd, const char *name) "Unknown SCSI comma
>  scsi_disk_dma_command_READ(uint64_t lba, uint32_t len) "Read (sector %" PRId64 ", count %u)"
>  scsi_disk_dma_command_WRITE(const char *cmd, uint64_t lba, int len) "Write %s(sector %" PRId64 ", count %u)"
>  scsi_disk_new_request(uint32_t lun, uint32_t tag, const char *line) "Command: lun=%d tag=0x%x data=%s"
> +
> +# hw/scsi/scsi-generic.c
> +scsi_generic_command_complete_noio(void *req, uint32_t tag, int statuc) "Command complete %p tag=0x%x status=%d"
> +scsi_generic_read_complete(uint32_t tag, int len) "Data ready tag=0x%x len=%d"
> +scsi_generic_read_data(uint32_t tag) "scsi_read_data tag=0x%x"
> +scsi_generic_write_complete(int ret) "scsi_write_complete() ret = %d"
> +scsi_generic_write_complete_blocksize(int blocksize) "block size %d"
> +scsi_generic_write_data(uint32_t tag) "scsi_write_data tag=0x%x"
> +scsi_generic_send_command(const char *line) "Command: data=%s"
> +scsi_generic_realize_type(int type) "device type %d"
> +scsi_generic_realize_blocksize(int blocksize) "block size %d"
> 

Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>
Tested-by: Philippe Mathieu-Daudé <philmd@redhat.com>

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-07 15:37 ` [Qemu-devel] [PATCH 1/2] scsi-disk: " Philippe Mathieu-Daudé
@ 2018-12-07 16:37   ` Laurent Vivier
  2018-12-07 16:46     ` Eric Blake
  2018-12-19 21:30     ` Paolo Bonzini
  0 siblings, 2 replies; 10+ messages in thread
From: Laurent Vivier @ 2018-12-07 16:37 UTC (permalink / raw)
  To: Philippe Mathieu-Daudé, qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé

On 07/12/2018 16:37, Philippe Mathieu-Daudé wrote:
> On 12/7/18 2:17 PM, Laurent Vivier wrote:
>> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
>> ---
>>  hw/scsi/scsi-disk.c  | 105 +++++++++++++++++++++----------------------
>>  hw/scsi/trace-events |  29 ++++++++++++
>>  2 files changed, 81 insertions(+), 53 deletions(-)
...
>>  
>> +static void scsi_disk_new_request_dump(uint32_t lun, uint32_t tag, uint8_t *buf,
>> +                                       void (*trace_fn)(uint32_t, uint32_t,
>> +                                                        char const *))
>> +{
>> +    int i;
>> +    int len = scsi_cdb_length(buf);
>> +    char *line_buffer, *p;
>> +
>> +    line_buffer = g_malloc(len * 5 + 1);
>> +
>> +    for (i = 0, p = line_buffer; i < len; i++) {
>> +        p += sprintf(p, " 0x%02x", buf[i]);
>> +    }
>> +    trace_fn(lun, tag, line_buffer);
>> +
>> +    g_free(line_buffer);
>> +}
>> +
>>  static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
>>                                       uint8_t *buf, void *hba_private)
>>  {
>> @@ -2512,16 +2518,9 @@ static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
>>      }
>>      req = scsi_req_alloc(ops, &s->qdev, tag, lun, hba_private);
>>  
>> -#ifdef DEBUG_SCSI
>> -    DPRINTF("Command: lun=%d tag=0x%x data=0x%02x", lun, tag, buf[0]);
>> -    {
>> -        int i;
>> -        for (i = 1; i < scsi_cdb_length(buf); i++) {
>> -            printf(" 0x%02x", buf[i]);
>> -        }
>> -        printf("\n");
>> +    if (trace_event_get_state_backends(TRACE_SCSI_DISK_NEW_REQUEST)) {
>> +        scsi_disk_new_request_dump(lun, tag, buf, trace_scsi_disk_new_request);
> 
> TIL about trace_event_get_state_backends(), I'll use it to clean other
> hexdump traces, thanks :)

I've copied that from gdbstub.c where there is an hexdump() function
using it.

I'm going to send a v2 of this patch, because I think it is not needed
in this case to pass the function in the parameters.

Thanks,
Laurent

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-07 16:37   ` Laurent Vivier
@ 2018-12-07 16:46     ` Eric Blake
  2018-12-19 21:30     ` Paolo Bonzini
  1 sibling, 0 replies; 10+ messages in thread
From: Eric Blake @ 2018-12-07 16:46 UTC (permalink / raw)
  To: Laurent Vivier, Philippe Mathieu-Daudé, qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé

On 12/7/18 10:37 AM, Laurent Vivier wrote:
> On 07/12/2018 16:37, Philippe Mathieu-Daudé wrote:
>> On 12/7/18 2:17 PM, Laurent Vivier wrote:
>>> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
>>> ---

>>
>> TIL about trace_event_get_state_backends(), I'll use it to clean other
>> hexdump traces, thanks :)
> 
> I've copied that from gdbstub.c where there is an hexdump() function
> using it.
> 
> I'm going to send a v2 of this patch, because I think it is not needed
> in this case to pass the function in the parameters.

Don't forget the 0/2 cover letter in that case (all series of >1 patch 
are easier to process with a cover letter, even if it is just 2 patches)

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-07 13:17 [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events Laurent Vivier
  2018-12-07 13:17 ` [Qemu-devel] [PATCH 2/2] scsi-generic: " Laurent Vivier
  2018-12-07 15:37 ` [Qemu-devel] [PATCH 1/2] scsi-disk: " Philippe Mathieu-Daudé
@ 2018-12-07 16:47 ` Eric Blake
  2018-12-19 21:29 ` Paolo Bonzini
  3 siblings, 0 replies; 10+ messages in thread
From: Eric Blake @ 2018-12-07 16:47 UTC (permalink / raw)
  To: Laurent Vivier, qemu-devel
  Cc: Fam Zheng, Paolo Bonzini, Philippe Mathieu-Daudé

On 12/7/18 7:17 AM, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>   hw/scsi/scsi-disk.c  | 105 +++++++++++++++++++++----------------------
>   hw/scsi/trace-events |  29 ++++++++++++
>   2 files changed, 81 insertions(+), 53 deletions(-)
> 
> diff --git a/hw/scsi/scsi-disk.c b/hw/scsi/scsi-disk.c
> index 0e9027c8f3..29e541efdb 100644
> --- a/hw/scsi/scsi-disk.c
> +++ b/hw/scsi/scsi-disk.c
> @@ -19,15 +19,6 @@
>    * the host adapter emulator.
>    */
>   
> -//#define DEBUG_SCSI
> -
> -#ifdef DEBUG_SCSI
> -#define DPRINTF(fmt, ...) \
> -do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF(fmt, ...) do {} while(0)
> -#endif
> -

Yay for getting rid of yet another bit-rottable debug statement.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-07 13:17 [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events Laurent Vivier
                   ` (2 preceding siblings ...)
  2018-12-07 16:47 ` Eric Blake
@ 2018-12-19 21:29 ` Paolo Bonzini
  3 siblings, 0 replies; 10+ messages in thread
From: Paolo Bonzini @ 2018-12-19 21:29 UTC (permalink / raw)
  To: Laurent Vivier, qemu-devel; +Cc: Fam Zheng, Philippe Mathieu-Daudé

On 07/12/18 14:17, Laurent Vivier wrote:
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  hw/scsi/scsi-disk.c  | 105 +++++++++++++++++++++----------------------
>  hw/scsi/trace-events |  29 ++++++++++++
>  2 files changed, 81 insertions(+), 53 deletions(-)
> 
> diff --git a/hw/scsi/scsi-disk.c b/hw/scsi/scsi-disk.c
> index 0e9027c8f3..29e541efdb 100644
> --- a/hw/scsi/scsi-disk.c
> +++ b/hw/scsi/scsi-disk.c
> @@ -19,15 +19,6 @@
>   * the host adapter emulator.
>   */
>  
> -//#define DEBUG_SCSI
> -
> -#ifdef DEBUG_SCSI
> -#define DPRINTF(fmt, ...) \
> -do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF(fmt, ...) do {} while(0)
> -#endif
> -
>  #include "qemu/osdep.h"
>  #include "qemu/units.h"
>  #include "qapi/error.h"
> @@ -41,6 +32,7 @@ do { printf("scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
>  #include "hw/block/block.h"
>  #include "sysemu/dma.h"
>  #include "qemu/cutils.h"
> +#include "trace.h"
>  
>  #ifdef __linux
>  #include <scsi/sg.h>
> @@ -128,8 +120,8 @@ static void scsi_free_request(SCSIRequest *req)
>  /* Helper function for command completion with sense.  */
>  static void scsi_check_condition(SCSIDiskReq *r, SCSISense sense)
>  {
> -    DPRINTF("Command complete tag=0x%x sense=%d/%d/%d\n",
> -            r->req.tag, sense.key, sense.asc, sense.ascq);
> +    trace_scsi_disk_check_condition(r->req.tag, sense.key, sense.asc,
> +                                    sense.ascq);
>      scsi_req_build_sense(&r->req, sense);
>      scsi_req_complete(&r->req, CHECK_CONDITION);
>  }
> @@ -317,7 +309,7 @@ static void scsi_read_complete(void * opaque, int ret)
>      }
>  
>      block_acct_done(blk_get_stats(s->qdev.conf.blk), &r->acct);
> -    DPRINTF("Data ready tag=0x%x len=%zd\n", r->req.tag, r->qiov.size);
> +    trace_scsi_disk_read_complete(r->req.tag, r->qiov.size);
>  
>      n = r->qiov.size / 512;
>      r->sector += n;
> @@ -388,7 +380,7 @@ static void scsi_read_data(SCSIRequest *req)
>      SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
>      bool first;
>  
> -    DPRINTF("Read sector_count=%d\n", r->sector_count);
> +    trace_scsi_disk_read_data_count(r->sector_count);
>      if (r->sector_count == 0) {
>          /* This also clears the sense buffer for REQUEST SENSE.  */
>          scsi_req_complete(&r->req, GOOD);
> @@ -401,7 +393,7 @@ static void scsi_read_data(SCSIRequest *req)
>      /* The request is used as the AIO opaque value, so add a ref.  */
>      scsi_req_ref(&r->req);
>      if (r->req.cmd.mode == SCSI_XFER_TO_DEV) {
> -        DPRINTF("Data transfer direction invalid\n");
> +        trace_scsi_disk_read_data_invalid();
>          scsi_read_complete(r, -EINVAL);
>          return;
>      }
> @@ -502,7 +494,7 @@ static void scsi_write_complete_noio(SCSIDiskReq *r, int ret)
>          return;
>      } else {
>          scsi_init_iovec(r, SCSI_DMA_BUF_SIZE);
> -        DPRINTF("Write complete tag=0x%x more=%zd\n", r->req.tag, r->qiov.size);
> +        trace_scsi_disk_write_complete_noio(r->req.tag, r->qiov.size);
>          scsi_req_data(&r->req, r->qiov.size);
>      }
>  
> @@ -540,7 +532,7 @@ static void scsi_write_data(SCSIRequest *req)
>      /* The request is used as the AIO opaque value, so add a ref.  */
>      scsi_req_ref(&r->req);
>      if (r->req.cmd.mode != SCSI_XFER_TO_DEV) {
> -        DPRINTF("Data transfer direction invalid\n");
> +        trace_scsi_disk_write_data_invalid();
>          scsi_write_complete_noio(r, -EINVAL);
>          return;
>      }
> @@ -605,8 +597,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>      switch (page_code) {
>      case 0x00: /* Supported page codes, mandatory */
>      {
> -        DPRINTF("Inquiry EVPD[Supported pages] "
> -                "buffer size %zd\n", req->cmd.xfer);
> +        trace_scsi_disk_emulate_vpd_page_00(req->cmd.xfer);
>          outbuf[buflen++] = 0x00; /* list of supported pages (this page) */
>          if (s->serial) {
>              outbuf[buflen++] = 0x80; /* unit serial number */
> @@ -624,7 +615,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>          int l;
>  
>          if (!s->serial) {
> -            DPRINTF("Inquiry (EVPD[Serial number] not supported\n");
> +            trace_scsi_disk_emulate_vpd_page_80_not_supported();
>              return -1;
>          }
>  
> @@ -633,8 +624,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>              l = 36;
>          }
>  
> -        DPRINTF("Inquiry EVPD[Serial number] "
> -                "buffer size %zd\n", req->cmd.xfer);
> +        trace_scsi_disk_emulate_vpd_page_80(req->cmd.xfer);
>          memcpy(outbuf + buflen, s->serial, l);
>          buflen += l;
>          break;
> @@ -649,8 +639,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>          if (id_len > max_len) {
>              id_len = max_len;
>          }
> -        DPRINTF("Inquiry EVPD[Device identification] "
> -                "buffer size %zd\n", req->cmd.xfer);
> +        trace_scsi_disk_emulate_vpd_page_83(req->cmd.xfer);
>  
>          outbuf[buflen++] = 0x2; /* ASCII */
>          outbuf[buflen++] = 0;   /* not officially assigned */
> @@ -695,8 +684,7 @@ static int scsi_disk_emulate_vpd_page(SCSIRequest *req, uint8_t *outbuf)
>          SCSIBlockLimits bl = {};
>  
>          if (s->qdev.type == TYPE_ROM) {
> -            DPRINTF("Inquiry (EVPD[%02X] not supported for CDROM\n",
> -                    page_code);
> +            trace_scsi_disk_emulate_vpd_page_b0_not_supported();
>              return -1;
>          }
>          bl.wsnz = 1;
> @@ -1243,8 +1231,9 @@ static int scsi_disk_emulate_mode_sense(SCSIDiskReq *r, uint8_t *outbuf)
>      dbd = (r->req.cmd.buf[1] & 0x8) != 0;
>      page = r->req.cmd.buf[2] & 0x3f;
>      page_control = (r->req.cmd.buf[2] & 0xc0) >> 6;
> -    DPRINTF("Mode Sense(%d) (page %d, xfer %zd, page_control %d)\n",
> -        (r->req.cmd.buf[0] == MODE_SENSE) ? 6 : 10, page, r->req.cmd.xfer, page_control);
> +
> +    trace_scsi_disk_emulate_mode_sense((r->req.cmd.buf[0] == MODE_SENSE) ? 6 :
> +                                       10, page, r->req.cmd.xfer, page_control);
>      memset(outbuf, 0, r->req.cmd.xfer);
>      p = outbuf;
>  
> @@ -1336,7 +1325,7 @@ static int scsi_disk_emulate_read_toc(SCSIRequest *req, uint8_t *outbuf)
>      format = req->cmd.buf[2] & 0xf;
>      start_track = req->cmd.buf[6];
>      blk_get_geometry(s->qdev.conf.blk, &nb_sectors);
> -    DPRINTF("Read TOC (track %d format %d msf %d)\n", start_track, format, msf >> 1);
> +    trace_scsi_disk_emulate_read_toc(start_track, format, msf >> 1);
>      nb_sectors /= s->qdev.blocksize / 512;
>      switch (format) {
>      case 0:
> @@ -1395,7 +1384,7 @@ static void scsi_disk_emulate_read_data(SCSIRequest *req)
>      int buflen = r->iov.iov_len;
>  
>      if (buflen) {
> -        DPRINTF("Read buf_len=%d\n", buflen);
> +        trace_scsi_disk_emulate_read_data(buflen);
>          r->iov.iov_len = 0;
>          r->started = true;
>          scsi_req_data(&r->req, buflen);
> @@ -1814,7 +1803,7 @@ static void scsi_disk_emulate_write_data(SCSIRequest *req)
>  
>      if (r->iov.iov_len) {
>          int buflen = r->iov.iov_len;
> -        DPRINTF("Write buf_len=%d\n", buflen);
> +        trace_scsi_disk_emulate_write_data(buflen);
>          r->iov.iov_len = 0;
>          scsi_req_data(&r->req, buflen);
>          return;
> @@ -2023,7 +2012,7 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
>      case SERVICE_ACTION_IN_16:
>          /* Service Action In subcommands. */
>          if ((req->cmd.buf[1] & 31) == SAI_READ_CAPACITY_16) {
> -            DPRINTF("SAI READ CAPACITY(16)\n");
> +            trace_scsi_disk_emulate_command_SAI_16();
>              memset(outbuf, 0, req->cmd.xfer);
>              blk_get_geometry(s->qdev.conf.blk, &nb_sectors);
>              if (!nb_sectors) {
> @@ -2061,7 +2050,7 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
>              /* Protection, exponent and lowest lba field left blank. */
>              break;
>          }
> -        DPRINTF("Unsupported Service Action In\n");
> +        trace_scsi_disk_emulate_command_SAI_unsupported();
>          goto illegal_request;
>      case SYNCHRONIZE_CACHE:
>          /* The request is used as the AIO opaque value, so add a ref.  */
> @@ -2071,37 +2060,36 @@ static int32_t scsi_disk_emulate_command(SCSIRequest *req, uint8_t *buf)
>          r->req.aiocb = blk_aio_flush(s->qdev.conf.blk, scsi_aio_complete, r);
>          return 0;
>      case SEEK_10:
> -        DPRINTF("Seek(10) (sector %" PRId64 ")\n", r->req.cmd.lba);
> +        trace_scsi_disk_emulate_command_SEEK_10(r->req.cmd.lba);
>          if (r->req.cmd.lba > s->qdev.max_lba) {
>              goto illegal_lba;
>          }
>          break;
>      case MODE_SELECT:
> -        DPRINTF("Mode Select(6) (len %lu)\n", (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_MODE_SELECT(r->req.cmd.xfer);
>          break;
>      case MODE_SELECT_10:
> -        DPRINTF("Mode Select(10) (len %lu)\n", (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_MODE_SELECT_10(r->req.cmd.xfer);
>          break;
>      case UNMAP:
> -        DPRINTF("Unmap (len %lu)\n", (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_UNMAP(r->req.cmd.xfer);
>          break;
>      case VERIFY_10:
>      case VERIFY_12:
>      case VERIFY_16:
> -        DPRINTF("Verify (bytchk %d)\n", (req->cmd.buf[1] >> 1) & 3);
> +        trace_scsi_disk_emulate_command_VERIFY((req->cmd.buf[1] >> 1) & 3);
>          if (req->cmd.buf[1] & 6) {
>              goto illegal_request;
>          }
>          break;
>      case WRITE_SAME_10:
>      case WRITE_SAME_16:
> -        DPRINTF("WRITE SAME %d (len %lu)\n",
> -                req->cmd.buf[0] == WRITE_SAME_10 ? 10 : 16,
> -                (unsigned long)r->req.cmd.xfer);
> +        trace_scsi_disk_emulate_command_WRITE_SAME(
> +                req->cmd.buf[0] == WRITE_SAME_10 ? 10 : 16, r->req.cmd.xfer);
>          break;
>      default:
> -        DPRINTF("Unknown SCSI command (%2.2x=%s)\n", buf[0],
> -                scsi_command_name(buf[0]));
> +        trace_scsi_disk_emulate_command_UNKNOWN(buf[0],
> +                                                scsi_command_name(buf[0]));
>          scsi_check_condition(r, SENSE_CODE(INVALID_OPCODE));
>          return 0;
>      }
> @@ -2154,7 +2142,7 @@ static int32_t scsi_disk_dma_command(SCSIRequest *req, uint8_t *buf)
>      case READ_10:
>      case READ_12:
>      case READ_16:
> -        DPRINTF("Read (sector %" PRId64 ", count %u)\n", r->req.cmd.lba, len);
> +        trace_scsi_disk_dma_command_READ(r->req.cmd.lba, len);
>          /* Protection information is not supported.  For SCSI versions 2 and
>           * older (as determined by snooping the guest's INQUIRY commands),
>           * there is no RD/WR/VRPROTECT, so skip this check in these versions.
> @@ -2179,7 +2167,7 @@ static int32_t scsi_disk_dma_command(SCSIRequest *req, uint8_t *buf)
>              scsi_check_condition(r, SENSE_CODE(WRITE_PROTECTED));
>              return 0;
>          }
> -        DPRINTF("Write %s(sector %" PRId64 ", count %u)\n",
> +        trace_scsi_disk_dma_command_WRITE(
>                  (command & 0xe) == 0xe ? "And Verify " : "",
>                  r->req.cmd.lba, len);
>          /* fall through */
> @@ -2497,6 +2485,24 @@ static const SCSIReqOps *const scsi_disk_reqops_dispatch[256] = {
>      [WRITE_VERIFY_16]                 = &scsi_disk_dma_reqops,
>  };
>  
> +static void scsi_disk_new_request_dump(uint32_t lun, uint32_t tag, uint8_t *buf,
> +                                       void (*trace_fn)(uint32_t, uint32_t,
> +                                                        char const *))
> +{
> +    int i;
> +    int len = scsi_cdb_length(buf);
> +    char *line_buffer, *p;
> +
> +    line_buffer = g_malloc(len * 5 + 1);
> +
> +    for (i = 0, p = line_buffer; i < len; i++) {
> +        p += sprintf(p, " 0x%02x", buf[i]);
> +    }
> +    trace_fn(lun, tag, line_buffer);
> +
> +    g_free(line_buffer);
> +}
> +
>  static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
>                                       uint8_t *buf, void *hba_private)
>  {
> @@ -2512,16 +2518,9 @@ static SCSIRequest *scsi_new_request(SCSIDevice *d, uint32_t tag, uint32_t lun,
>      }
>      req = scsi_req_alloc(ops, &s->qdev, tag, lun, hba_private);
>  
> -#ifdef DEBUG_SCSI
> -    DPRINTF("Command: lun=%d tag=0x%x data=0x%02x", lun, tag, buf[0]);
> -    {
> -        int i;
> -        for (i = 1; i < scsi_cdb_length(buf); i++) {
> -            printf(" 0x%02x", buf[i]);
> -        }
> -        printf("\n");
> +    if (trace_event_get_state_backends(TRACE_SCSI_DISK_NEW_REQUEST)) {
> +        scsi_disk_new_request_dump(lun, tag, buf, trace_scsi_disk_new_request);
>      }
> -#endif
>  
>      return req;
>  }
> diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events
> index 0fb6a99616..e9625f790c 100644
> --- a/hw/scsi/trace-events
> +++ b/hw/scsi/trace-events
> @@ -291,3 +291,32 @@ lsi_execute_script_stop(void) "SCRIPTS execution stopped"
>  lsi_awoken(void) "Woken by SIGP"
>  lsi_reg_read(const char *name, int offset, uint8_t ret) "Read reg %s 0x%x = 0x%02x"
>  lsi_reg_write(const char *name, int offset, uint8_t val) "Write reg %s 0x%x = 0x%02x"
> +
> +# hw/scsi/scsi-disk.c
> +scsi_disk_check_condition(uint32_t tag, uint8_t key, uint8_t asc, uint8_t ascq) "Command complete tag=0x%x sense=%d/%d/%d"
> +scsi_disk_read_complete(uint32_t tag, size_t size) "Data ready tag=0x%x len=%zd"
> +scsi_disk_read_data_count(uint32_t sector_count) "Read sector_count=%d"
> +scsi_disk_read_data_invalid(void) "Data transfer direction invalid"
> +scsi_disk_write_complete_noio(uint32_t tag, size_t size) "Write complete tag=0x%x more=%zd"
> +scsi_disk_write_data_invalid(void) "Data transfer direction invalid"
> +scsi_disk_emulate_vpd_page_00(size_t xfer) "Inquiry EVPD[Supported pages] buffer size %zd"
> +scsi_disk_emulate_vpd_page_80_not_supported(void) "Inquiry (EVPD[Serial number] not supported"
> +scsi_disk_emulate_vpd_page_80(size_t xfer) "Inquiry EVPD[Serial number] buffer size %zd"
> +scsi_disk_emulate_vpd_page_83(size_t xfer) "Inquiry EVPD[Device identification] buffer size %zd"
> +scsi_disk_emulate_vpd_page_b0_not_supported(void) "Inquiry (EVPD[Block limits] not supported for CDROM"
> +scsi_disk_emulate_mode_sense(int cmd, int page, size_t xfer, int control) "Mode Sense(%d) (page %d, xfer %zd, page_control %d)"
> +scsi_disk_emulate_read_toc(int start_track, int format, int msf) "Read TOC (track %d format %d msf %d)"
> +scsi_disk_emulate_read_data(int buflen) "Read buf_len=%d"
> +scsi_disk_emulate_write_data(int buflen) "Write buf_len=%d"
> +scsi_disk_emulate_command_SAI_16(void) "SAI READ CAPACITY(16)"
> +scsi_disk_emulate_command_SAI_unsupported(void) "Unsupported Service Action In"
> +scsi_disk_emulate_command_SEEK_10(uint64_t lba) "Seek(10) (sector %" PRId64 ")"
> +scsi_disk_emulate_command_MODE_SELECT(size_t xfer) "Mode Select(6) (len %zd)"
> +scsi_disk_emulate_command_MODE_SELECT_10(size_t xfer) "Mode Select(10) (len %zd)"
> +scsi_disk_emulate_command_UNMAP(size_t xfer) "Unmap (len %zd)"
> +scsi_disk_emulate_command_VERIFY(int bytchk) "Verify (bytchk %d)"
> +scsi_disk_emulate_command_WRITE_SAME(int cmd, size_t xfer) "WRITE SAME %d (len %zd)"
> +scsi_disk_emulate_command_UNKNOWN(int cmd, const char *name) "Unknown SCSI command (0x%2.2x=%s)"
> +scsi_disk_dma_command_READ(uint64_t lba, uint32_t len) "Read (sector %" PRId64 ", count %u)"
> +scsi_disk_dma_command_WRITE(const char *cmd, uint64_t lba, int len) "Write %s(sector %" PRId64 ", count %u)"
> +scsi_disk_new_request(uint32_t lun, uint32_t tag, const char *line) "Command: lun=%d tag=0x%x data=%s"
> 

Queued both, thanks.

Paolo

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-07 16:37   ` Laurent Vivier
  2018-12-07 16:46     ` Eric Blake
@ 2018-12-19 21:30     ` Paolo Bonzini
  2018-12-19 21:31       ` Paolo Bonzini
  1 sibling, 1 reply; 10+ messages in thread
From: Paolo Bonzini @ 2018-12-19 21:30 UTC (permalink / raw)
  To: Laurent Vivier, Philippe Mathieu-Daudé, qemu-devel
  Cc: Fam Zheng, Philippe Mathieu-Daudé

On 07/12/18 17:37, Laurent Vivier wrote:
>> TIL about trace_event_get_state_backends(), I'll use it to clean other
>> hexdump traces, thanks :)
> I've copied that from gdbstub.c where there is an hexdump() function
> using it.
> 
> I'm going to send a v2 of this patch, because I think it is not needed
> in this case to pass the function in the parameters.

I think it's better like this, you'd have to free the buffer in the
caller and that's also ugly.

Paolo

^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events
  2018-12-19 21:30     ` Paolo Bonzini
@ 2018-12-19 21:31       ` Paolo Bonzini
  0 siblings, 0 replies; 10+ messages in thread
From: Paolo Bonzini @ 2018-12-19 21:31 UTC (permalink / raw)
  To: Laurent Vivier, Philippe Mathieu-Daudé, qemu-devel
  Cc: Fam Zheng, Philippe Mathieu-Daudé

On 19/12/18 22:30, Paolo Bonzini wrote:
> On 07/12/18 17:37, Laurent Vivier wrote:
>>> TIL about trace_event_get_state_backends(), I'll use it to clean other
>>> hexdump traces, thanks :)
>> I've copied that from gdbstub.c where there is an hexdump() function
>> using it.
>>
>> I'm going to send a v2 of this patch, because I think it is not needed
>> in this case to pass the function in the parameters.
> 
> I think it's better like this, you'd have to free the buffer in the
> caller and that's also ugly.

Nevermind, I diffed v1 and v2 and I see what I mean.  I queued v2.

Paolo

^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2018-12-19 21:31 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-12-07 13:17 [Qemu-devel] [PATCH 1/2] scsi-disk: Convert from DPRINTF() macro to trace events Laurent Vivier
2018-12-07 13:17 ` [Qemu-devel] [PATCH 2/2] scsi-generic: " Laurent Vivier
2018-12-07 15:38   ` Philippe Mathieu-Daudé
2018-12-07 15:37 ` [Qemu-devel] [PATCH 1/2] scsi-disk: " Philippe Mathieu-Daudé
2018-12-07 16:37   ` Laurent Vivier
2018-12-07 16:46     ` Eric Blake
2018-12-19 21:30     ` Paolo Bonzini
2018-12-19 21:31       ` Paolo Bonzini
2018-12-07 16:47 ` Eric Blake
2018-12-19 21:29 ` Paolo Bonzini

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.