From patchwork Fri Sep 16 12:39:11 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Laurent Vivier X-Patchwork-Id: 9335743 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 5918260839 for ; Fri, 16 Sep 2016 12:48:41 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 4A59129F86 for ; Fri, 16 Sep 2016 12:48:41 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 3F10429F88; Fri, 16 Sep 2016 12:48:41 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.9 required=2.0 tests=BAYES_00,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (No client certificate requested) by mail.wl.linuxfoundation.org (Postfix) with ESMTPS id 1A8DC29F86 for ; Fri, 16 Sep 2016 12:48:40 +0000 (UTC) Received: from localhost ([::1]:40382 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1bksZK-0005cr-SC for patchwork-qemu-devel@patchwork.kernel.org; Fri, 16 Sep 2016 08:48:38 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:32793) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1bksQU-0007Qz-OH for qemu-devel@nongnu.org; Fri, 16 Sep 2016 08:39:32 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1bksQR-0000jN-MG for qemu-devel@nongnu.org; Fri, 16 Sep 2016 08:39:29 -0400 Received: from mx1.redhat.com ([209.132.183.28]:45402) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1bksQR-0000ib-Cg; Fri, 16 Sep 2016 08:39:27 -0400 Received: from int-mx09.intmail.prod.int.phx2.redhat.com (int-mx09.intmail.prod.int.phx2.redhat.com [10.5.11.22]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id BCBE3344EB6; Fri, 16 Sep 2016 12:39:26 +0000 (UTC) Received: from thinkpad.redhat.com (ovpn-112-33.ams2.redhat.com [10.36.112.33]) by int-mx09.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id u8GCdB1i014983; Fri, 16 Sep 2016 08:39:24 -0400 From: Laurent Vivier To: david@gibson.dropbear.id.au Date: Fri, 16 Sep 2016 14:39:11 +0200 Message-Id: <1474029551-17739-6-git-send-email-lvivier@redhat.com> In-Reply-To: <1474029551-17739-1-git-send-email-lvivier@redhat.com> References: <1474029551-17739-1-git-send-email-lvivier@redhat.com> X-Scanned-By: MIMEDefang 2.68 on 10.5.11.22 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.29]); Fri, 16 Sep 2016 12:39:26 +0000 (UTC) X-detected-operating-system: by eggs.gnu.org: GNU/Linux 2.2.x-3.x [generic] X-Received-From: 209.132.183.28 Subject: [Qemu-devel] [PATCH v2 5/5] spapr_vscsi: convert to trace framework instead of DPRINTF X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.21 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Laurent Vivier , qemu-ppc@nongnu.org, qemu-devel@nongnu.org Errors-To: qemu-devel-bounces+patchwork-qemu-devel=patchwork.kernel.org@nongnu.org Sender: "Qemu-devel" X-Virus-Scanned: ClamAV using ClamSMTP Signed-off-by: Laurent Vivier Reviewed-by: Eric Blake --- v2: - fix spapr_vscsi with "ust" backend (limited number of arguments) - Remove blank line after the comment line in trace-events file - add Eric's R-b hw/scsi/spapr_vscsi.c | 88 +++++++++++++++++++++------------------------------ hw/scsi/trace-events | 27 ++++++++++++++++ 2 files changed, 63 insertions(+), 52 deletions(-) diff --git a/hw/scsi/spapr_vscsi.c b/hw/scsi/spapr_vscsi.c index 8fbd50f..d8a2296 100644 --- a/hw/scsi/spapr_vscsi.c +++ b/hw/scsi/spapr_vscsi.c @@ -42,19 +42,10 @@ #include "hw/ppc/spapr.h" #include "hw/ppc/spapr_vio.h" #include "viosrp.h" +#include "trace.h" #include -/*#define DEBUG_VSCSI*/ - -#ifdef DEBUG_VSCSI -#define DPRINTF(fmt, ...) \ - do { fprintf(stderr, fmt, ## __VA_ARGS__); } while (0) -#else -#define DPRINTF(fmt, ...) \ - do { } while (0) -#endif - /* * Virtual SCSI device */ @@ -237,8 +228,7 @@ static int vscsi_send_rsp(VSCSIState *s, vscsi_req *req, int total_len = sizeof(iu->srp.rsp); uint8_t sol_not = iu->srp.cmd.sol_not; - DPRINTF("VSCSI: Sending resp status: 0x%x, " - "res_in: %d, res_out: %d\n", status, res_in, res_out); + trace_spapr_vscsi_send_rsp(status, res_in, res_out); memset(iu, 0, sizeof(struct srp_rsp)); iu->srp.rsp.opcode = SRP_RSP; @@ -298,13 +288,13 @@ static int vscsi_fetch_desc(VSCSIState *s, struct vscsi_req *req, switch (req->dma_fmt) { case SRP_NO_DATA_DESC: { - DPRINTF("VSCSI: no data descriptor\n"); + trace_spapr_vscsi_fetch_desc_no_data(); return 0; } case SRP_DATA_DESC_DIRECT: { memcpy(ret, cmd->add_data + req->cdb_offset, sizeof(*ret)); assert(req->cur_desc_num == 0); - DPRINTF("VSCSI: direct segment\n"); + trace_spapr_vscsi_fetch_desc_direct(); break; } case SRP_DATA_DESC_INDIRECT: { @@ -312,30 +302,29 @@ static int vscsi_fetch_desc(VSCSIState *s, struct vscsi_req *req, (cmd->add_data + req->cdb_offset); if (n < req->local_desc) { *ret = tmp->desc_list[n]; - DPRINTF("VSCSI: indirect segment local tag=0x%x desc#%d/%d\n", - req->qtag, n, req->local_desc); - + trace_spapr_vscsi_fetch_desc_indirect(req->qtag, n, + req->local_desc); } else if (n < req->total_desc) { int rc; struct srp_direct_buf tbl_desc = vscsi_swap_desc(tmp->table_desc); unsigned desc_offset = n * sizeof(struct srp_direct_buf); if (desc_offset >= tbl_desc.len) { - DPRINTF("VSCSI: #%d is ouf of range (%d bytes)\n", - n, desc_offset); + trace_spapr_vscsi_fetch_desc_out_of_range(n, desc_offset); return -1; } rc = spapr_vio_dma_read(&s->vdev, tbl_desc.va + desc_offset, ret, sizeof(struct srp_direct_buf)); if (rc) { - DPRINTF("VSCSI: spapr_vio_dma_read -> %d reading ext_desc\n", - rc); + trace_spapr_vscsi_fetch_desc_dma_read_error(rc); return -1; } - DPRINTF("VSCSI: indirect segment ext. tag=0x%x desc#%d/%d { va=%"PRIx64" len=%x }\n", - req->qtag, n, req->total_desc, tbl_desc.va, tbl_desc.len); + trace_spapr_vscsi_fetch_desc_indirect_seg_ext(req->qtag, n, + req->total_desc, + tbl_desc.va, + tbl_desc.len); } else { - DPRINTF("VSCSI: Out of descriptors !\n"); + trace_spapr_vscsi_fetch_desc_out_of_desc(); return 0; } break; @@ -347,15 +336,16 @@ static int vscsi_fetch_desc(VSCSIState *s, struct vscsi_req *req, *ret = vscsi_swap_desc(*ret); if (buf_offset > ret->len) { - DPRINTF(" offset=%x is out of a descriptor #%d boundary=%x\n", - buf_offset, req->cur_desc_num, ret->len); + trace_spapr_vscsi_fetch_desc_out_of_desc_boundary(buf_offset, + req->cur_desc_num, + ret->len); return -1; } ret->va += buf_offset; ret->len -= buf_offset; - DPRINTF(" cur=%d offs=%x ret { va=%"PRIx64" len=%x }\n", - req->cur_desc_num, req->cur_desc_offset, ret->va, ret->len); + trace_spapr_vscsi_fetch_desc_done(req->cur_desc_num, req->cur_desc_offset, + ret->va, ret->len); return ret->len ? 1 : 0; } @@ -398,7 +388,7 @@ static int vscsi_srp_indirect_data(VSCSIState *s, vscsi_req *req, int rc = 0; uint32_t llen, total = 0; - DPRINTF("VSCSI: indirect segment 0x%x bytes\n", len); + trace_spapr_vscsi_srp_indirect_data(len); /* While we have data ... */ while (len) { @@ -417,11 +407,10 @@ static int vscsi_srp_indirect_data(VSCSIState *s, vscsi_req *req, rc = spapr_vio_dma_write(&s->vdev, md.va, buf, llen); } if (rc) { - DPRINTF("VSCSI: spapr_vio_dma_r/w(%d) -> %d\n", req->writing, rc); + trace_spapr_vscsi_srp_indirect_data_rw(req->writing, rc); break; } - DPRINTF("VSCSI: data: %02x %02x %02x %02x...\n", - buf[0], buf[1], buf[2], buf[3]); + trace_spapr_vscsi_srp_indirect_data_buf(buf[0], buf[1], buf[2], buf[3]); len -= llen; buf += llen; @@ -447,7 +436,7 @@ static int vscsi_srp_transfer_data(VSCSIState *s, vscsi_req *req, switch (req->dma_fmt) { case SRP_NO_DATA_DESC: - DPRINTF("VSCSI: no data desc transfer, skipping 0x%x bytes\n", len); + trace_spapr_vscsi_srp_transfer_data(len); break; case SRP_DATA_DESC_DIRECT: err = vscsi_srp_direct_data(s, req, buf, len); @@ -527,8 +516,7 @@ static void vscsi_transfer_data(SCSIRequest *sreq, uint32_t len) uint8_t *buf; int rc = 0; - DPRINTF("VSCSI: SCSI xfer complete tag=0x%x len=0x%x, req=%p\n", - sreq->tag, len, req); + trace_spapr_vscsi_transfer_data(sreq->tag, len, req); if (req == NULL) { fprintf(stderr, "VSCSI: Can't find request for tag 0x%x\n", sreq->tag); return; @@ -557,8 +545,7 @@ static void vscsi_command_complete(SCSIRequest *sreq, uint32_t status, size_t re vscsi_req *req = sreq->hba_private; int32_t res_in = 0, res_out = 0; - DPRINTF("VSCSI: SCSI cmd complete, tag=0x%x status=0x%x, req=%p\n", - sreq->tag, status, req); + trace_spapr_vscsi_command_complete(sreq->tag, status, req); if (req == NULL) { fprintf(stderr, "VSCSI: Can't find request for tag 0x%x\n", sreq->tag); return; @@ -567,16 +554,15 @@ static void vscsi_command_complete(SCSIRequest *sreq, uint32_t status, size_t re if (status == CHECK_CONDITION) { req->senselen = scsi_req_get_sense(req->sreq, req->sense, sizeof(req->sense)); - DPRINTF("VSCSI: Sense data, %d bytes:\n", req->senselen); - DPRINTF(" %02x %02x %02x %02x %02x %02x %02x %02x\n", + trace_spapr_vscsi_command_complete_sense_data1(req->senselen, req->sense[0], req->sense[1], req->sense[2], req->sense[3], req->sense[4], req->sense[5], req->sense[6], req->sense[7]); - DPRINTF(" %02x %02x %02x %02x %02x %02x %02x %02x\n", + trace_spapr_vscsi_command_complete_sense_data2( req->sense[8], req->sense[9], req->sense[10], req->sense[11], req->sense[12], req->sense[13], req->sense[14], req->sense[15]); } - DPRINTF("VSCSI: Command complete err=%d\n", status); + trace_spapr_vscsi_command_complete_status(status); if (status == 0) { /* We handle overflows, not underflows for normal commands, * but hopefully nobody cares @@ -635,8 +621,8 @@ static void vscsi_save_request(QEMUFile *f, SCSIRequest *sreq) vmstate_save_state(f, &vmstate_spapr_vscsi_req, req, NULL); - DPRINTF("VSCSI: saving tag=%u, current desc#%d, offset=%x\n", - req->qtag, req->cur_desc_num, req->cur_desc_offset); + trace_spapr_vscsi_save_request(req->qtag, req->cur_desc_num, + req->cur_desc_offset); } static void *vscsi_load_request(QEMUFile *f, SCSIRequest *sreq) @@ -660,8 +646,8 @@ static void *vscsi_load_request(QEMUFile *f, SCSIRequest *sreq) req->sreq = scsi_req_ref(sreq); - DPRINTF("VSCSI: restoring tag=%u, current desc#%d, offset=%x\n", - req->qtag, req->cur_desc_num, req->cur_desc_offset); + trace_spapr_vscsi_load_request(req->qtag, req->cur_desc_num, + req->cur_desc_offset); return req; } @@ -672,7 +658,7 @@ static void vscsi_process_login(VSCSIState *s, vscsi_req *req) struct srp_login_rsp *rsp = &iu->srp.login_rsp; uint64_t tag = iu->srp.rsp.tag; - DPRINTF("VSCSI: Got login, sendin response !\n"); + trace_spapr_vscsi__process_login(); /* TODO handle case that requested size is wrong and * buffer format is wrong @@ -795,8 +781,7 @@ static int vscsi_queue_cmd(VSCSIState *s, vscsi_req *req) sdev = vscsi_device_find(&s->bus, be64_to_cpu(srp->cmd.lun), &lun); if (!sdev) { - DPRINTF("VSCSI: Command for lun %08" PRIx64 " with no drive\n", - be64_to_cpu(srp->cmd.lun)); + trace_spapr_vscsi_queue_cmd_no_drive(be64_to_cpu(srp->cmd.lun)); if (srp->cmd.cdb[0] == INQUIRY) { vscsi_inquiry_no_target(s, req); } else { @@ -808,9 +793,8 @@ static int vscsi_queue_cmd(VSCSIState *s, vscsi_req *req) req->sreq = scsi_req_new(sdev, req->qtag, lun, srp->cmd.cdb, req); n = scsi_req_enqueue(req->sreq); - DPRINTF("VSCSI: Queued command tag 0x%x CMD 0x%x=%s LUN %d ret: %d\n", - req->qtag, srp->cmd.cdb[0], scsi_command_name(srp->cmd.cdb[0]), - lun, n); + trace_spapr_vscsi_queue_cmd(req->qtag, srp->cmd.cdb[0], + scsi_command_name(srp->cmd.cdb[0]), lun, n); if (n) { /* Transfer direction must be set before preprocessing the @@ -1141,7 +1125,7 @@ static int vscsi_do_crq(struct VIOsPAPRDevice *dev, uint8_t *crq_data) crq.s.IU_length = be16_to_cpu(crq.s.IU_length); crq.s.IU_data_ptr = be64_to_cpu(crq.s.IU_data_ptr); - DPRINTF("VSCSI: do_crq %02x %02x ...\n", crq.raw[0], crq.raw[1]); + trace_spapr_vscsi_do_crq(crq.raw[0], crq.raw[1]); switch (crq.s.valid) { case 0xc0: /* Init command/response */ diff --git a/hw/scsi/trace-events b/hw/scsi/trace-events index ed64858..d1995b8 100644 --- a/hw/scsi/trace-events +++ b/hw/scsi/trace-events @@ -202,3 +202,30 @@ esp_pci_dma_abort(uint32_t val) "ABORT (%.8x)" esp_pci_dma_start(uint32_t val) "START (%.8x)" esp_pci_sbac_read(uint32_t reg) "sbac: 0x%8.8x" esp_pci_sbac_write(uint32_t reg, uint32_t val) "sbac: 0x%8.8x -> 0x%8.8x" + +# hw/scsi/spapr_vscsi.c +spapr_vscsi_send_rsp(uint8_t status, int32_t res_in, int32_t res_out) "status: 0x%x, res_in: %"PRId32", res_out: %"PRId32 +spapr_vscsi_fetch_desc_no_data(void) "no data descriptor" +spapr_vscsi_fetch_desc_direct(void) "direct segment" +spapr_vscsi_fetch_desc_indirect(uint32_t qtag, unsigned desc, unsigned local_desc) "indirect segment local tag=0x%"PRIx32" desc#%u/%u" +spapr_vscsi_fetch_desc_out_of_range(unsigned desc, unsigned desc_offset) "#%u is ouf of range (%u bytes)" +spapr_vscsi_fetch_desc_dma_read_error(int rc) "spapr_vio_dma_read -> %d reading ext_desc" +spapr_vscsi_fetch_desc_indirect_seg_ext(uint32_t qtag, unsigned n, unsigned desc, uint64_t va, uint32_t len) "indirect segment ext. tag=0x%"PRIx32" desc#%u/%u { va=0x%"PRIx64" len=0x%"PRIx32" }" +spapr_vscsi_fetch_desc_out_of_desc(void) "Out of descriptors !" +spapr_vscsi_fetch_desc_out_of_desc_boundary(unsigned offset, unsigned desc, uint32_t len) " offset=0x%x is out of a descriptor #%u boundary=%"PRIx32 +spapr_vscsi_fetch_desc_done(unsigned desc_num, unsigned desc_offset, uint64_t va, uint32_t len) " cur=%u offs=0x%x ret { va=0x%"PRIx64" len=0x%"PRIx32" }" +spapr_vscsi_srp_indirect_data(uint32_t len) "indirect segment 0x%"PRIx32" bytes" +spapr_vscsi_srp_indirect_data_rw(int writing, int rc) "spapr_vio_dma_r/w(%d) -> %d" +spapr_vscsi_srp_indirect_data_buf(unsigned a, unsigned b, unsigned c, unsigned d) " data: %02x %02x %02x %02x..." +spapr_vscsi_srp_transfer_data(uint32_t len) "no data desc transfer, skipping 0x%"PRIx32" bytes" +spapr_vscsi_transfer_data(uint32_t tag, uint32_t len, void *req) "SCSI xfer complete tag=0x%"PRIx32" len=0x%"PRIx32", req=%p" +spapr_vscsi_command_complete(uint32_t tag, uint32_t status, void *req) "SCSI cmd complete, tag=0x%"PRIx32" status=0x%"PRIx32", req=%p" +spapr_vscsi_command_complete_sense_data1(uint32_t len, unsigned s0, unsigned s1, unsigned s2, unsigned s3, unsigned s4, unsigned s5, unsigned s6, unsigned s7) "Sense data, %d bytes: %02x %02x %02x %02x %02x %02x %02x %02x" +spapr_vscsi_command_complete_sense_data2(unsigned s8, unsigned s9, unsigned s10, unsigned s11, unsigned s12, unsigned s13, unsigned s14, unsigned s15) " %02x %02x %02x %02x %02x %02x %02x %02x" +spapr_vscsi_command_complete_status(uint32_t status) "Command complete err=%"PRIu32 +spapr_vscsi_save_request(uint32_t qtag, unsigned desc, unsigned offset) "saving tag=%"PRIu32", current desc#%u, offset=0x%x" +spapr_vscsi_load_request(uint32_t qtag, unsigned desc, unsigned offset) "restoring tag=%"PRIu32", current desc#%u, offset=0x%x" +spapr_vscsi__process_login(void) "Got login, sending response !" +spapr_vscsi_queue_cmd_no_drive(uint64_t lun) "Command for lun %08" PRIx64 " with no drive" +spapr_vscsi_queue_cmd(uint32_t qtag, unsigned cdb, const char *cmd, int lun, int ret) "Queued command tag 0x%"PRIx32" CMD 0x%x=%s LUN %d ret: %d" +spapr_vscsi_do_crq(unsigned c0, unsigned c1) "crq: %02x %02x ..."