From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([2001:4830:134:3::10]:49223) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1VF2UE-0007SS-Ss for qemu-devel@nongnu.org; Thu, 29 Aug 2013 09:42:19 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1VF2U5-0001xe-V4 for qemu-devel@nongnu.org; Thu, 29 Aug 2013 09:42:10 -0400 Received: from mx1.redhat.com ([209.132.183.28]:62672) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1VF2U5-0001xD-NH for qemu-devel@nongnu.org; Thu, 29 Aug 2013 09:42:01 -0400 Received: from int-mx10.intmail.prod.int.phx2.redhat.com (int-mx10.intmail.prod.int.phx2.redhat.com [10.5.11.23]) by mx1.redhat.com (8.14.4/8.14.4) with ESMTP id r7TDfxdI016838 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=OK) for ; Thu, 29 Aug 2013 09:42:00 -0400 From: Laszlo Ersek Date: Thu, 29 Aug 2013 15:37:50 +0200 Message-Id: <1377783470-8981-2-git-send-email-lersek@redhat.com> In-Reply-To: <521F4E76.2090507@redhat.com> References: <521F4E76.2090507@redhat.com> Subject: [Qemu-devel] [PATCH 2/2] add some virtio-scsi trace events List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: qemu-devel@nongnu.org, pbonzini@redhat.com The events that log a hexdump of the cdb and the sense buffer are disabled by default, because they require more processing than a simple trace_XXX() function call. Signed-off-by: Laszlo Ersek --- 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 #include #include @@ -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