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 <address@hidden>

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