[Qemu-devel] [PATCH 0/2] some virtio-scsi tracing

[Qemu-devel] [PATCH 0/2] some virtio-scsi tracing

[Laszlo Ersek]

[-- Attachment #1: Type: text/plain, Size: 1152 bytes --]

Recently we had to track down a (remote) problem with virtio-scsi tape
passthrough. Paolo asked me if I could turn my ad-hoc debug printf()s
into trace events.

I tested the series in the following way:
- enabled the two "processing hungry" events in "trace-events",
- built & installed qemu,
- using libvirt, started a guest with a passthru USB flash drive,
- logged in to the guest,
- on the host, enabled all virtio_scsi_* events using "virsh
  qemu-monitor-command",
- in the guest:
  - mounted the disk,
  - listed the directory tree,
  - unmounted the disk,
- on the host, physically disconnected the flash drive.

I'm attaching the trace output (stderr backend, saved by libvirt); you
should be able to pair segments of the file with the above actions.

Laszlo Ersek (2):
  qemu_hexstr(): hexdump a small buffer to a string, for in-line
    printing
  add some virtio-scsi trace events

 include/qemu-common.h |   11 +++++++
 hw/scsi/virtio-scsi.c |   76 +++++++++++++++++++++++++++++++++++++++++++++++--
 util/hexdump.c        |   20 +++++++++++++
 trace-events          |   19 ++++++++++++
 4 files changed, 123 insertions(+), 3 deletions(-)


[-- Attachment #2: fw-ovmf.g-rhel7.e-upstream.log.xz --]
[-- Type: application/x-xz, Size: 4084 bytes --]

[Qemu-devel] [PATCH 1/2] qemu_hexstr(): hexdump a small buffer to a string, for in-line printing

[Laszlo Ersek]

This function should primarily serve tracing needs.

Signed-off-by: Laszlo Ersek <lersek@redhat.com>
---
 include/qemu-common.h |   11 +++++++++++
 util/hexdump.c        |   20 ++++++++++++++++++++
 2 files changed, 31 insertions(+), 0 deletions(-)

diff --git a/include/qemu-common.h b/include/qemu-common.h
index 6948bb9..18a373f 100644
--- a/include/qemu-common.h
+++ b/include/qemu-common.h
@@ -433,6 +433,17 @@ int mod_utf8_codepoint(const char *s, size_t n, char **end);
 
 void qemu_hexdump(const char *buf, FILE *fp, const char *prefix, size_t size);
 
+/*
+ * Hexdump @size bytes from @buf to a dynamically allocated string.
+ * If @size is NULL, then @buf can be a NULL pointer, and an empty string will
+ * be formatted.
+ * If @str_len is non-NULL, then the length of the output string (excluding the
+ * terminating NUL) will be stored in *@str_len.
+ * The output is meant to be printed on a single line, hence it contains no
+ * newlines, and @size should be reasonable.
+ */
+char *qemu_hexstr(const void *buf, size_t size, size_t *str_len);
+
 /* vector definitions */
 #ifdef __ALTIVEC__
 #include <altivec.h>
diff --git a/util/hexdump.c b/util/hexdump.c
index 969b340..5c7e1a2 100644
--- a/util/hexdump.c
+++ b/util/hexdump.c
@@ -35,3 +35,23 @@ void qemu_hexdump(const char *buf, FILE *fp, const char *prefix, size_t size)
         fprintf(fp, "\n");
     }
 }
+
+char *qemu_hexstr(const void *buf, size_t size, size_t *str_len)
+{
+    size_t str_size, i;
+    char *ret, *output;
+
+    str_size = size * 3 + (size == 0);
+    ret = g_malloc(str_size);
+    output = ret;
+
+    for (i = 0; i < size; ++i) {
+        output += sprintf(output, "%s%02x", (i == 0) ? "" : " ",
+                          ((uint8_t *)buf)[i]);
+    }
+    *output = '\0';
+    if (str_len != NULL) {
+        *str_len = str_size - 1;
+    }
+    return ret;
+}
-- 
1.7.1

Re: [Qemu-devel] [PATCH 1/2] qemu_hexstr(): hexdump a small buffer to a string, for in-line printing

[Markus Armbruster]

Laszlo Ersek <lersek@redhat.com> writes:

> This function should primarily serve tracing needs.
>
> Signed-off-by: Laszlo Ersek <lersek@redhat.com>
> ---
>  include/qemu-common.h |   11 +++++++++++
>  util/hexdump.c        |   20 ++++++++++++++++++++
>  2 files changed, 31 insertions(+), 0 deletions(-)
>
> diff --git a/include/qemu-common.h b/include/qemu-common.h
> index 6948bb9..18a373f 100644
> --- a/include/qemu-common.h
> +++ b/include/qemu-common.h
> @@ -433,6 +433,17 @@ int mod_utf8_codepoint(const char *s, size_t n, char **end);
>  
>  void qemu_hexdump(const char *buf, FILE *fp, const char *prefix, size_t size);
>  
> +/*
> + * Hexdump @size bytes from @buf to a dynamically allocated string.
> + * If @size is NULL, then @buf can be a NULL pointer, and an empty string will

If @size is zero

> + * be formatted.
> + * If @str_len is non-NULL, then the length of the output string (excluding the
> + * terminating NUL) will be stored in *@str_len.
> + * The output is meant to be printed on a single line, hence it contains no
> + * newlines, and @size should be reasonable.
> + */
> +char *qemu_hexstr(const void *buf, size_t size, size_t *str_len);
> +
>  /* vector definitions */
>  #ifdef __ALTIVEC__
>  #include <altivec.h>
[...]

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

[Laszlo Ersek]

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

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

[Paolo Bonzini]

Il 29/08/2013 15:37, Laszlo Ersek ha scritto:
> 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>

trace_event_get_state doesn't work with the dtrace backend.  Can you
prepare v2 without those tracepoints?

> ---
>  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);

Also please add the VirtIOSCSI variable here and everywhere else.

>      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"
> 

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

[Laszlo Ersek]

On 08/29/13 15:59, Paolo Bonzini wrote:
> Il 29/08/2013 15:37, Laszlo Ersek ha scritto:
>> 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>
>
> trace_event_get_state doesn't work with the dtrace backend.  Can you
> prepare v2 without those tracepoints?

(a) I was just following "docs/tracing.txt"; see the last section in
there.

(b) If I kill those two events, this is what you get:

Incoming request:

  virtio_scsi_handle_cmd_enter vdev 0x7f1be4054468 vq 0x7f1be4054b60
  virtio_scsi_pop_req req 0x7f1be5d77650
  virtio_scsi_handle_cmd_exit vdev 0x7f1be4054468 vq 0x7f1be4054b60

This gives you the address of the request, so you can look up the
corresponding completion. However you don't know the actual command
(cdb) without "virtio_scsi_dump_cmd_req".

Then,

  virtio_scsi_command_complete_enter req 0x7f1be5d77650 status 2 resid 0
  virtio_scsi_complete_req_enter req 0x7f1be5d77650
  virtio_scsi_complete_req_exit req 0x7f1be5d77650
  virtio_scsi_command_complete_exit req 0x7f1be5d77650 status 2 resid 0 sense_len 18

this will not tell you the virtio-scsi transport response code, or the
actual sense data.

(c) The way I submitted the series, the events in question are disabled
in "trace-events". Check out the functions themselves: they are
protected (ie. even the trace_event_get_state() calls are protected)
with preprocessing directives. I did it this way because I call them in
several places, and I wanted to keep the #if's centralized.

The function calls should be completely eliminated when the events are
disabled in "trace-events" (which is what the patch contains). They
should incur no performance penalty, and also not allow
trace_event_get_state() to conflict with dtrace -- if you build with the
dtrace backend, just leave these two disabled in "trace-events".

(d) I don't have more time for this, sorry.

Thanks,
Laszlo

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

[Paolo Bonzini]

Il 29/08/2013 16:18, Laszlo Ersek ha scritto:
> On 08/29/13 15:59, Paolo Bonzini wrote:
>> Il 29/08/2013 15:37, Laszlo Ersek ha scritto:
>>> 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>
>>
>> trace_event_get_state doesn't work with the dtrace backend.  Can you
>> prepare v2 without those tracepoints?
> 
> (a) I was just following "docs/tracing.txt"; see the last section in
> there.
> 
> (b) If I kill those two events, this is what you get:
> 
> Incoming request:
> 
>   virtio_scsi_handle_cmd_enter vdev 0x7f1be4054468 vq 0x7f1be4054b60
>   virtio_scsi_pop_req req 0x7f1be5d77650
>   virtio_scsi_handle_cmd_exit vdev 0x7f1be4054468 vq 0x7f1be4054b60
> 
> This gives you the address of the request, so you can look up the
> corresponding completion. However you don't know the actual command
> (cdb) without "virtio_scsi_dump_cmd_req".

Yes, but you can see almost all of the cdb from scsi_req_parsed and
scsi_req_parsed_lba.

>   virtio_scsi_command_complete_enter req 0x7f1be5d77650 status 2 resid 0
>   virtio_scsi_complete_req_enter req 0x7f1be5d77650
>   virtio_scsi_complete_req_exit req 0x7f1be5d77650
>   virtio_scsi_command_complete_exit req 0x7f1be5d77650 status 2 resid 0 sense_len 18
> 
> this will not tell you the virtio-scsi transport response code, or the
> actual sense data.

Same here: scsi_req_build_sense can give the sense data, and we could
add another tracepoint scsi_req_complete for the response code.

> (c) The way I submitted the series, the events in question are disabled
> in "trace-events". Check out the functions themselves: they are
> protected (ie. even the trace_event_get_state() calls are protected)
> with preprocessing directives. I did it this way because I call them in
> several places, and I wanted to keep the #if's centralized.

Tracing was supposed to remove the need for #if... :)

I'll try to salvage the patch.

Paolo

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

[Laszlo Ersek]

On 08/29/13 16:53, Paolo Bonzini wrote:

>> (c) The way I submitted the series, the events in question are disabled
>> in "trace-events". Check out the functions themselves: they are
>> protected (ie. even the trace_event_get_state() calls are protected)
>> with preprocessing directives. I did it this way because I call them in
>> several places, and I wanted to keep the #if's centralized.
> 
> Tracing was supposed to remove the need for #if... :)

Tracing was supposed not to be broken under dtrace either I presume?

> I'll try to salvage the patch.

I won't bother next time. I wouldn't want you to waste your time on
"salvaging" the clearly broken patches that I submit.

To be clear, I considered this series a favor. I don't need it to be
accepted. It's easier for me to write ad-hoc debug printf()s each time.
They don't depend on anything, they can print just the right set of info
that I need, and they work in any component imaginable.

In comparison, the bikeshedding you repeatedly indulge in is unbearable.
You keep splitting hairs and rejecting patches just because they are not
in your taste; you don't need any other reason.

NB I haven't just thrown this over the wall. I spent most of today on
this series and tried to cover all my bases, perusing the documentation,
testing the series, making an honest effort. The one thing that I
*can't* prepare for is your adoration of your own taste.

If you attribute such paramount importance to your taste, perhaps next
time write the crap yourself that you tend to ask me for.

Of course there are times when I can't just ignore you and walk away.
Maybe I'll look for different responsibilities if that becomes the norm.

Laszlo

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

[Paolo Bonzini]

Il 29/08/2013 17:35, Laszlo Ersek ha scritto:
> On 08/29/13 16:53, Paolo Bonzini wrote:
>> I'll try to salvage the patch.
> 
> I won't bother next time. I wouldn't want you to waste your time on
> "salvaging" the clearly broken patches that I submit.

WTF?

The patch is clearly a good thing, or I wouldn't have asked you to send it.

However, if you don't have time to follow up on my comments, all that a
maintainer can do is:

(1) ignore it and/or let it rot

(2) pick it up and gain something from a patch that isn't quite ready.

#2 is exactly the definition of salvage.

> To be clear, I considered this series a favor.

Sure, and it's very welcome.  But you shouldn't expect too much from
your interlocutor after writing "I don't have any more time for this".

If you don't have any more time for this, next time send me the patch
privately and say it in advance before I even start reviewing it.  I'll
make sure you're properly acknowledged with From and Signed-off-by headers.

Paolo, glad that this time he's on the receiving edge of a flame...

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

[Stefan Hajnoczi]

On Thu, Aug 29, 2013 at 03:37:50PM +0200, Laszlo Ersek wrote:
> +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);

There is a halfway solution to disable expensive trace events that works
across all backends (SystemTap, stderr, etc):

if (!TRACE_VIRTIO_SCSI_DUMP_CMD_REQ_ENABLED) {
    return;
}

This is a compile-time constant which can be toggled with the "disable"
keyword in the ./trace-events file:

disable my_expensive_event(const char *foo) "foo %s"

See the bottom of docs/tracing.txt for full documentation on the
"disable" keyword.

Stefan

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

[Laszlo Ersek]

On 09/04/13 16:21, Stefan Hajnoczi wrote:
> On Thu, Aug 29, 2013 at 03:37:50PM +0200, Laszlo Ersek wrote:
>> +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);
> 
> There is a halfway solution to disable expensive trace events that works
> across all backends (SystemTap, stderr, etc):
> 
> if (!TRACE_VIRTIO_SCSI_DUMP_CMD_REQ_ENABLED) {
>     return;
> }
> 
> This is a compile-time constant which can be toggled with the "disable"
> keyword in the ./trace-events file:
> 
> disable my_expensive_event(const char *foo) "foo %s"
> 
> See the bottom of docs/tracing.txt for full documentation on the
> "disable" keyword.

Yes, I've read it :)

The compile-time constant is already used (just not in an if() but in a
surrounding #if, snipped from the context above), and the corresponding
tracepoints are already disabled in ./trace-events.

I do read documentation if it exists.

I guess I'll rework this sometime later.

Thanks,
Laszlo