From patchwork Wed Sep 14 18:48:27 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Laurent Vivier X-Patchwork-Id: 9332263 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 5EDB46077F for ; Wed, 14 Sep 2016 18:51:10 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 4B4042A1C3 for ; Wed, 14 Sep 2016 18:51:10 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 3F37A2A247; Wed, 14 Sep 2016 18:51:10 +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 EDA442A1C3 for ; Wed, 14 Sep 2016 18:51:08 +0000 (UTC) Received: from localhost ([::1]:58141 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1bkFH2-0004wv-2w for patchwork-qemu-devel@patchwork.kernel.org; Wed, 14 Sep 2016 14:51:08 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:44252) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1bkFEm-0003Sn-Mt for qemu-devel@nongnu.org; Wed, 14 Sep 2016 14:48:50 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1bkFEk-0007ei-QZ for qemu-devel@nongnu.org; Wed, 14 Sep 2016 14:48:48 -0400 Received: from mx1.redhat.com ([209.132.183.28]:49158) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1bkFEk-0007eV-GV; Wed, 14 Sep 2016 14:48:46 -0400 Received: from int-mx14.intmail.prod.int.phx2.redhat.com (int-mx14.intmail.prod.int.phx2.redhat.com [10.5.11.27]) (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 F06EB72659; Wed, 14 Sep 2016 18:48:45 +0000 (UTC) Received: from thinkpad.redhat.com (ovpn-112-33.ams2.redhat.com [10.36.112.33]) by int-mx14.intmail.prod.int.phx2.redhat.com (8.14.4/8.14.4) with ESMTP id u8EImSNu010540; Wed, 14 Sep 2016 14:48:43 -0400 From: Laurent Vivier To: david@gibson.dropbear.id.au Date: Wed, 14 Sep 2016 20:48:27 +0200 Message-Id: <1473878907-10477-6-git-send-email-lvivier@redhat.com> In-Reply-To: <1473878907-10477-1-git-send-email-lvivier@redhat.com> References: <1473878907-10477-1-git-send-email-lvivier@redhat.com> X-Scanned-By: MIMEDefang 2.68 on 10.5.11.27 X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-4.5.16 (mx1.redhat.com [10.5.110.39]); Wed, 14 Sep 2016 18:48:46 +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 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 --- hw/scsi/spapr_vscsi.c | 89 +++++++++++++++++++++------------------------------ hw/scsi/trace-events | 27 ++++++++++++++++ 2 files changed, 63 insertions(+), 53 deletions(-) diff --git a/hw/scsi/spapr_vscsi.c b/hw/scsi/spapr_vscsi.c index 8fbd50f..29fef90 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,14 @@ 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_data(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", + req->sense[4], req->sense[5], req->sense[6], req->sense[7], 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 +620,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 +645,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 +657,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 +780,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 +792,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 +1124,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..e3770b5 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_data(uint32_t len, unsigned s0, unsigned s1, unsigned s2, unsigned s3, unsigned s4, unsigned s5, unsigned s6, unsigned s7, unsigned s8, unsigned s9, unsigned s10, unsigned s11, unsigned s12, unsigned s13, unsigned s14, unsigned s15) "Sense data, %d bytes: %02x %02x %02x %02x %02x %02x %02x %02x %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 ..."