[Qemu-devel] [PATCH] trace: Trace SCSI request lifecycle

[Qemu-devel] [PATCH] trace: Trace SCSI request lifecycle

[Stefan Hajnoczi]

This patch adds trace events for SCSI request allocation, freeing, CDB
parsing, read, and write.  These trace events can be used to instrument
the SCSI request lifecycle.

Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
---
 hw/scsi-bus.c  |    5 +++++
 hw/scsi-disk.c |    9 +++++++++
 trace-events   |   11 +++++++++++
 3 files changed, 25 insertions(+), 0 deletions(-)

diff --git a/hw/scsi-bus.c b/hw/scsi-bus.c
index 5a3fd4b..0228d4f 100644
--- a/hw/scsi-bus.c
+++ b/hw/scsi-bus.c
@@ -4,6 +4,7 @@
 #include "scsi-defs.h"
 #include "qdev.h"
 #include "blockdev.h"
+#include "trace.h"
 
 static struct BusInfo scsi_bus_info = {
     .name  = "SCSI",
@@ -145,6 +146,8 @@ SCSIRequest *scsi_req_alloc(size_t size, SCSIDevice *d, uint32_t tag, uint32_t l
     req->status = -1;
     req->enqueued = true;
     QTAILQ_INSERT_TAIL(&d->requests, req, next);
+
+    trace_scsi_req_alloc(d, tag, lun, req);
     return req;
 }
 
@@ -172,6 +175,7 @@ void scsi_req_free(SCSIRequest *req)
 {
     scsi_req_dequeue(req);
     qemu_free(req);
+    trace_scsi_req_free(req);
 }
 
 static int scsi_req_length(SCSIRequest *req, uint8_t *cmd)
@@ -395,6 +399,7 @@ int scsi_req_parse(SCSIRequest *req, uint8_t *buf)
     memcpy(req->cmd.buf, buf, req->cmd.len);
     scsi_req_xfer_mode(req);
     req->cmd.lba = scsi_req_lba(req);
+    trace_scsi_req_parse(req, req->cmd.len, req->cmd.lba, req->cmd.buf[0]);
     return 0;
 }
 
diff --git a/hw/scsi-disk.c b/hw/scsi-disk.c
index dc71957..c7a3f2a 100644
--- a/hw/scsi-disk.c
+++ b/hw/scsi-disk.c
@@ -37,6 +37,7 @@ do { fprintf(stderr, "scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
 #include "scsi-defs.h"
 #include "sysemu.h"
 #include "blockdev.h"
+#include "trace.h"
 
 #define SCSI_DMA_BUF_SIZE    131072
 #define SCSI_MAX_INQUIRY_LEN 256
@@ -136,6 +137,8 @@ static void scsi_read_complete(void * opaque, int ret)
     SCSIDiskReq *r = (SCSIDiskReq *)opaque;
     int n;
 
+    trace_scsi_read_complete(r, ret);
+
     r->req.aiocb = NULL;
 
     if (ret) {
@@ -158,6 +161,8 @@ static void scsi_read_request(SCSIDiskReq *r)
     SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
     uint32_t n;
 
+    trace_scsi_read_request(r, r->sector, r->sector_count);
+
     if (r->sector_count == (uint32_t)-1) {
         DPRINTF("Read buf_len=%zd\n", r->iov.iov_len);
         r->sector_count = 0;
@@ -240,6 +245,8 @@ static void scsi_write_complete(void * opaque, int ret)
     uint32_t len;
     uint32_t n;
 
+    trace_scsi_write_complete(r, ret);
+
     r->req.aiocb = NULL;
 
     if (ret) {
@@ -269,6 +276,8 @@ static void scsi_write_request(SCSIDiskReq *r)
     SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
     uint32_t n;
 
+    trace_scsi_write_request(r, r->sector, r->iov.iov_len);
+
     n = r->iov.iov_len / 512;
     if (n) {
         qemu_iovec_init_external(&r->qiov, &r->iov, 1);
diff --git a/trace-events b/trace-events
index 947f8b0..7069628 100644
--- a/trace-events
+++ b/trace-events
@@ -189,3 +189,14 @@ disable sun4m_iommu_mem_writel_pgflush(uint32_t val) "page flush %x"
 disable sun4m_iommu_page_get_flags(uint64_t pa, uint64_t iopte, uint32_t ret) "get flags addr %"PRIx64" => pte %"PRIx64", *pte = %x"
 disable sun4m_iommu_translate_pa(uint64_t addr, uint64_t pa, uint32_t iopte) "xlate dva %"PRIx64" => pa %"PRIx64" iopte = %x"
 disable sun4m_iommu_bad_addr(uint64_t addr) "bad addr %"PRIx64""
+
+# hw/scsi-bus.c
+disable scsi_req_alloc(void *dev, uint32_t tag, uint32_t lun, void *req) "dev %p tag %#x lun %#x req %p"
+disable scsi_req_free(void *req) "req %p"
+disable scsi_req_parse(void *req, int len, uint64_t lba, uint8_t cmd) "req %p len %d lba %"PRIu64" cmd %#x"
+
+# hw/scsi-disk.c
+disable scsi_read_request(void *req, uint64_t sector, uint32_t sector_count) "req %p sector %"PRIu64" sector_count %u"
+disable scsi_read_complete(void *req, int ret) "req %p ret %d"
+disable scsi_write_request(void *req, uint64_t sector, size_t len) "req %p sector %"PRIu64" len %zu"
+disable scsi_write_complete(void *req, int ret) "req %p ret %d"
-- 
1.7.2.3

Re: [Qemu-devel] [PATCH] trace: Trace SCSI request lifecycle

[Blue Swirl]

On Mon, Nov 8, 2010 at 9:44 AM, Stefan Hajnoczi
<stefanha@linux.vnet.ibm.com> wrote:
> This patch adds trace events for SCSI request allocation, freeing, CDB
> parsing, read, and write.  These trace events can be used to instrument
> the SCSI request lifecycle.

How about converting also the DPRINTFs in hw/scsi-disk.c to tracepoints?

>
> Signed-off-by: Stefan Hajnoczi <stefanha@linux.vnet.ibm.com>
> ---
>  hw/scsi-bus.c  |    5 +++++
>  hw/scsi-disk.c |    9 +++++++++
>  trace-events   |   11 +++++++++++
>  3 files changed, 25 insertions(+), 0 deletions(-)
>
> diff --git a/hw/scsi-bus.c b/hw/scsi-bus.c
> index 5a3fd4b..0228d4f 100644
> --- a/hw/scsi-bus.c
> +++ b/hw/scsi-bus.c
> @@ -4,6 +4,7 @@
>  #include "scsi-defs.h"
>  #include "qdev.h"
>  #include "blockdev.h"
> +#include "trace.h"
>
>  static struct BusInfo scsi_bus_info = {
>     .name  = "SCSI",
> @@ -145,6 +146,8 @@ SCSIRequest *scsi_req_alloc(size_t size, SCSIDevice *d, uint32_t tag, uint32_t l
>     req->status = -1;
>     req->enqueued = true;
>     QTAILQ_INSERT_TAIL(&d->requests, req, next);
> +
> +    trace_scsi_req_alloc(d, tag, lun, req);
>     return req;
>  }
>
> @@ -172,6 +175,7 @@ void scsi_req_free(SCSIRequest *req)
>  {
>     scsi_req_dequeue(req);
>     qemu_free(req);
> +    trace_scsi_req_free(req);
>  }
>
>  static int scsi_req_length(SCSIRequest *req, uint8_t *cmd)
> @@ -395,6 +399,7 @@ int scsi_req_parse(SCSIRequest *req, uint8_t *buf)
>     memcpy(req->cmd.buf, buf, req->cmd.len);
>     scsi_req_xfer_mode(req);
>     req->cmd.lba = scsi_req_lba(req);
> +    trace_scsi_req_parse(req, req->cmd.len, req->cmd.lba, req->cmd.buf[0]);
>     return 0;
>  }
>
> diff --git a/hw/scsi-disk.c b/hw/scsi-disk.c
> index dc71957..c7a3f2a 100644
> --- a/hw/scsi-disk.c
> +++ b/hw/scsi-disk.c
> @@ -37,6 +37,7 @@ do { fprintf(stderr, "scsi-disk: " fmt , ## __VA_ARGS__); } while (0)
>  #include "scsi-defs.h"
>  #include "sysemu.h"
>  #include "blockdev.h"
> +#include "trace.h"
>
>  #define SCSI_DMA_BUF_SIZE    131072
>  #define SCSI_MAX_INQUIRY_LEN 256
> @@ -136,6 +137,8 @@ static void scsi_read_complete(void * opaque, int ret)
>     SCSIDiskReq *r = (SCSIDiskReq *)opaque;
>     int n;
>
> +    trace_scsi_read_complete(r, ret);
> +
>     r->req.aiocb = NULL;
>
>     if (ret) {
> @@ -158,6 +161,8 @@ static void scsi_read_request(SCSIDiskReq *r)
>     SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
>     uint32_t n;
>
> +    trace_scsi_read_request(r, r->sector, r->sector_count);
> +
>     if (r->sector_count == (uint32_t)-1) {
>         DPRINTF("Read buf_len=%zd\n", r->iov.iov_len);
>         r->sector_count = 0;
> @@ -240,6 +245,8 @@ static void scsi_write_complete(void * opaque, int ret)
>     uint32_t len;
>     uint32_t n;
>
> +    trace_scsi_write_complete(r, ret);
> +
>     r->req.aiocb = NULL;
>
>     if (ret) {
> @@ -269,6 +276,8 @@ static void scsi_write_request(SCSIDiskReq *r)
>     SCSIDiskState *s = DO_UPCAST(SCSIDiskState, qdev, r->req.dev);
>     uint32_t n;
>
> +    trace_scsi_write_request(r, r->sector, r->iov.iov_len);
> +
>     n = r->iov.iov_len / 512;
>     if (n) {
>         qemu_iovec_init_external(&r->qiov, &r->iov, 1);
> diff --git a/trace-events b/trace-events
> index 947f8b0..7069628 100644
> --- a/trace-events
> +++ b/trace-events
> @@ -189,3 +189,14 @@ disable sun4m_iommu_mem_writel_pgflush(uint32_t val) "page flush %x"
>  disable sun4m_iommu_page_get_flags(uint64_t pa, uint64_t iopte, uint32_t ret) "get flags addr %"PRIx64" => pte %"PRIx64", *pte = %x"
>  disable sun4m_iommu_translate_pa(uint64_t addr, uint64_t pa, uint32_t iopte) "xlate dva %"PRIx64" => pa %"PRIx64" iopte = %x"
>  disable sun4m_iommu_bad_addr(uint64_t addr) "bad addr %"PRIx64""
> +
> +# hw/scsi-bus.c
> +disable scsi_req_alloc(void *dev, uint32_t tag, uint32_t lun, void *req) "dev %p tag %#x lun %#x req %p"
> +disable scsi_req_free(void *req) "req %p"
> +disable scsi_req_parse(void *req, int len, uint64_t lba, uint8_t cmd) "req %p len %d lba %"PRIu64" cmd %#x"
> +
> +# hw/scsi-disk.c
> +disable scsi_read_request(void *req, uint64_t sector, uint32_t sector_count) "req %p sector %"PRIu64" sector_count %u"
> +disable scsi_read_complete(void *req, int ret) "req %p ret %d"
> +disable scsi_write_request(void *req, uint64_t sector, size_t len) "req %p sector %"PRIu64" len %zu"
> +disable scsi_write_complete(void *req, int ret) "req %p ret %d"
> --
> 1.7.2.3
>
>
>

Re: [Qemu-devel] [PATCH] trace: Trace SCSI request lifecycle

[Stefan Hajnoczi]

On Mon, Nov 8, 2010 at 7:18 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
> On Mon, Nov 8, 2010 at 9:44 AM, Stefan Hajnoczi
> <stefanha@linux.vnet.ibm.com> wrote:
>> This patch adds trace events for SCSI request allocation, freeing, CDB
>> parsing, read, and write.  These trace events can be used to instrument
>> the SCSI request lifecycle.
>
> How about converting also the DPRINTFs in hw/scsi-disk.c to tracepoints?

Good idea.  I don't understand the SCSI emulation well enough to trace
the rest, so I couldn't do much besides a mechanical conversion.

Stefan

Re: [Qemu-devel] [PATCH] trace: Trace SCSI request lifecycle

[Blue Swirl]

On Mon, Nov 8, 2010 at 9:30 PM, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> On Mon, Nov 8, 2010 at 7:18 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
>> On Mon, Nov 8, 2010 at 9:44 AM, Stefan Hajnoczi
>> <stefanha@linux.vnet.ibm.com> wrote:
>>> This patch adds trace events for SCSI request allocation, freeing, CDB
>>> parsing, read, and write.  These trace events can be used to instrument
>>> the SCSI request lifecycle.
>>
>> How about converting also the DPRINTFs in hw/scsi-disk.c to tracepoints?
>
> Good idea.  I don't understand the SCSI emulation well enough to trace
> the rest, so I couldn't do much besides a mechanical conversion.

I also did only a mechanical conversion of Sparc32 devices earlier. I
thought about removing or merging some of them, but then I considered
that more tracepoints may be better to fewer. Is there a downside?

There's a difference in the viewpoints. DPRINTFs may have been
designed with debugging internal logic in mind. Alternatively we could
be interested in only tracing the external interfaces. I don't think
these views are in conflict since tracepoints are much more precise
than DPRINTFs.

Re: [Qemu-devel] [PATCH] trace: Trace SCSI request lifecycle

[Stefan Hajnoczi]

On Tue, Nov 09, 2010 at 05:47:24PM +0000, Blue Swirl wrote:
> On Mon, Nov 8, 2010 at 9:30 PM, Stefan Hajnoczi <stefanha@gmail.com> wrote:
> > On Mon, Nov 8, 2010 at 7:18 PM, Blue Swirl <blauwirbel@gmail.com> wrote:
> >> On Mon, Nov 8, 2010 at 9:44 AM, Stefan Hajnoczi
> >> <stefanha@linux.vnet.ibm.com> wrote:
> >>> This patch adds trace events for SCSI request allocation, freeing, CDB
> >>> parsing, read, and write.  These trace events can be used to instrument
> >>> the SCSI request lifecycle.
> >>
> >> How about converting also the DPRINTFs in hw/scsi-disk.c to tracepoints?
> >
> > Good idea.  I don't understand the SCSI emulation well enough to trace
> > the rest, so I couldn't do much besides a mechanical conversion.
> 
> I also did only a mechanical conversion of Sparc32 devices earlier. I
> thought about removing or merging some of them, but then I considered
> that more tracepoints may be better to fewer. Is there a downside?
> 
> There's a difference in the viewpoints. DPRINTFs may have been
> designed with debugging internal logic in mind. Alternatively we could
> be interested in only tracing the external interfaces. I don't think
> these views are in conflict since tracepoints are much more precise
> than DPRINTFs.

Having too many trace events makes it harder to choose which ones to
look at.  But when distros build in trace events by default we'll be
thankful for the ones we have available in production.  There needs to
be a balance between too much noise and not enough information.

I'll send a patch to cover more of SCSI soon.

Stefan