All of lore.kernel.org
 help / color / mirror / Atom feed
* [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing
@ 2017-08-08 18:32 John Snow
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system John Snow
                   ` (9 more replies)
  0 siblings, 10 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 18:32 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Wherever possible, replace all printfs with proper tracing.
In most places I've tried to do a straight replacement, but
forthcoming patches may calibrate the tracing to be a little nicer.

For now, it's nice to just remove the all-or-nothing tracing.

John Snow (9):
  IDE: replace DEBUG_IDE with tracing system
  IDE: Add register hints to tracing
  IDE: add tracing for data ports
  ATAPI: Replace DEBUG_IDE_ATAPI with tracing events
  IDE: replace DEBUG_AIO with trace events
  AHCI: Replace DPRINTF with trace-events
  AHCI: Rework IRQ constants
  AHCI: pretty-print FIS to buffer instead of stderr
  AHCI: remove DPRINTF macro

 Makefile.objs             |   1 +
 hw/ide/ahci.c             | 269 ++++++++++++++++++++++++++--------------------
 hw/ide/ahci_internal.h    |  44 ++++++--
 hw/ide/atapi.c            |  69 +++++-------
 hw/ide/cmd646.c           |  10 +-
 hw/ide/core.c             | 178 +++++++++++++++++++-----------
 hw/ide/pci.c              |  17 +--
 hw/ide/piix.c             |  11 +-
 hw/ide/trace-events       | 108 +++++++++++++++++++
 hw/ide/via.c              |  10 +-
 include/hw/ide/internal.h |   9 +-
 11 files changed, 454 insertions(+), 272 deletions(-)
 create mode 100644 hw/ide/trace-events

-- 
2.9.4

^ permalink raw reply	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
@ 2017-08-08 18:32 ` John Snow
  2017-08-08 20:00   ` Eric Blake
  2017-08-25 13:33   ` Philippe Mathieu-Daudé
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing John Snow
                   ` (8 subsequent siblings)
  9 siblings, 2 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 18:32 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Out with the old, in with the new.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 Makefile.objs             |  1 +
 hw/ide/cmd646.c           | 10 +++-----
 hw/ide/core.c             | 65 +++++++++++++++++++----------------------------
 hw/ide/pci.c              | 17 ++++---------
 hw/ide/piix.c             | 11 ++++----
 hw/ide/trace-events       | 33 ++++++++++++++++++++++++
 hw/ide/via.c              | 10 +++-----
 include/hw/ide/internal.h |  1 -
 8 files changed, 78 insertions(+), 70 deletions(-)
 create mode 100644 hw/ide/trace-events

diff --git a/Makefile.objs b/Makefile.objs
index 24a4ea0..967c092 100644
--- a/Makefile.objs
+++ b/Makefile.objs
@@ -153,6 +153,7 @@ trace-events-subdirs += hw/acpi
 trace-events-subdirs += hw/arm
 trace-events-subdirs += hw/alpha
 trace-events-subdirs += hw/xen
+trace-events-subdirs += hw/ide
 trace-events-subdirs += ui
 trace-events-subdirs += audio
 trace-events-subdirs += net
diff --git a/hw/ide/cmd646.c b/hw/ide/cmd646.c
index 9ebb8d4..86b2a8f 100644
--- a/hw/ide/cmd646.c
+++ b/hw/ide/cmd646.c
@@ -32,6 +32,7 @@
 #include "sysemu/dma.h"
 
 #include "hw/ide/pci.h"
+#include "trace.h"
 
 /* CMD646 specific */
 #define CFR		0x50
@@ -195,9 +196,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
         val = 0xff;
         break;
     }
-#ifdef DEBUG_IDE
-    printf("bmdma: readb " TARGET_FMT_plx " : 0x%02x\n", addr, val);
-#endif
+
+    trace_bmdma_read_cmd646(addr, val);
     return val;
 }
 
@@ -211,9 +211,7 @@ static void bmdma_write(void *opaque, hwaddr addr,
         return;
     }
 
-#ifdef DEBUG_IDE
-    printf("bmdma: writeb " TARGET_FMT_plx " : 0x%" PRIx64 "\n", addr, val);
-#endif
+    trace_bmdma_write_cmd646(addr, val);
     switch(addr & 3) {
     case 0:
         bmdma_cmd_writeb(bm, val);
diff --git a/hw/ide/core.c b/hw/ide/core.c
index 0b48b64..53fa084 100644
--- a/hw/ide/core.c
+++ b/hw/ide/core.c
@@ -36,6 +36,7 @@
 #include "qemu/cutils.h"
 
 #include "hw/ide/internal.h"
+#include "trace.h"
 
 /* These values were based on a Seagate ST3500418AS but have been modified
    to make more sense in QEMU */
@@ -656,10 +657,7 @@ void ide_cancel_dma_sync(IDEState *s)
      * write requests) pending and we can avoid to drain. */
     QLIST_FOREACH(req, &s->buffered_requests, list) {
         if (!req->orphaned) {
-#ifdef DEBUG_IDE
-            printf("%s: invoking cb %p of buffered request %p with"
-                   " -ECANCELED\n", __func__, req->original_cb, req);
-#endif
+            trace_ide_cancel_dma_sync_buffered(req->original_cb, req);
             req->original_cb(req->original_opaque, -ECANCELED);
         }
         req->orphaned = true;
@@ -678,9 +676,7 @@ void ide_cancel_dma_sync(IDEState *s)
      * aio operation with preadv/pwritev.
      */
     if (s->bus->dma->aiocb) {
-#ifdef DEBUG_IDE
-        printf("%s: draining all remaining requests", __func__);
-#endif
+        trace_ide_cancel_dma_sync_remaining();
         blk_drain(s->blk);
         assert(s->bus->dma->aiocb == NULL);
     }
@@ -741,9 +737,7 @@ static void ide_sector_read(IDEState *s)
         n = s->req_nb_sectors;
     }
 
-#if defined(DEBUG_IDE)
-    printf("sector=%" PRId64 "\n", sector_num);
-#endif
+    trace_ide_sector_read(sector_num, n);
 
     if (!ide_sect_range_ok(s, sector_num, n)) {
         ide_rw_error(s);
@@ -1005,14 +999,14 @@ static void ide_sector_write(IDEState *s)
 
     s->status = READY_STAT | SEEK_STAT | BUSY_STAT;
     sector_num = ide_get_sector(s);
-#if defined(DEBUG_IDE)
-    printf("sector=%" PRId64 "\n", sector_num);
-#endif
+
     n = s->nsector;
     if (n > s->req_nb_sectors) {
         n = s->req_nb_sectors;
     }
 
+    trace_ide_sector_write(sector_num, n);
+
     if (!ide_sect_range_ok(s, sector_num, n)) {
         ide_rw_error(s);
         block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
@@ -1186,18 +1180,17 @@ static void ide_clear_hob(IDEBus *bus)
 void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
 {
     IDEBus *bus = opaque;
+    IDEState *s = idebus_active_if(bus);
+    int reg_num = addr & 7;
 
-#ifdef DEBUG_IDE
-    printf("IDE: write addr=0x%x val=0x%02x\n", addr, val);
-#endif
-
-    addr &= 7;
+    trace_ide_ioport_write(addr, val, bus, s);
 
     /* ignore writes to command block while busy with previous command */
-    if (addr != 7 && (idebus_active_if(bus)->status & (BUSY_STAT|DRQ_STAT)))
+    if (reg_num != 7 && (s->status & (BUSY_STAT|DRQ_STAT))) {
         return;
+    }
 
-    switch(addr) {
+    switch(reg_num) {
     case 0:
         break;
     case 1:
@@ -1253,9 +1246,7 @@ void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
 
 static void ide_reset(IDEState *s)
 {
-#ifdef DEBUG_IDE
-    printf("ide: reset\n");
-#endif
+    trace_ide_reset(s);
 
     if (s->pio_aiocb) {
         blk_aio_cancel(s->pio_aiocb);
@@ -2013,10 +2004,9 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
     IDEState *s;
     bool complete;
 
-#if defined(DEBUG_IDE)
-    printf("ide: CMD=%02x\n", val);
-#endif
     s = idebus_active_if(bus);
+    trace_ide_exec_cmd(bus, s, val);
+
     /* ignore commands to non existent slave */
     if (s != bus->ifs && !s->blk) {
         return;
@@ -2054,18 +2044,18 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
     }
 }
 
-uint32_t ide_ioport_read(void *opaque, uint32_t addr1)
+uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 {
     IDEBus *bus = opaque;
     IDEState *s = idebus_active_if(bus);
-    uint32_t addr;
+    uint32_t reg_num;
     int ret, hob;
 
-    addr = addr1 & 7;
+    reg_num = addr & 7;
     /* FIXME: HOB readback uses bit 7, but it's always set right now */
     //hob = s->select & (1 << 7);
     hob = 0;
-    switch(addr) {
+    switch(reg_num) {
     case 0:
         ret = 0xff;
         break;
@@ -2133,9 +2123,8 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr1)
         qemu_irq_lower(bus->irq);
         break;
     }
-#ifdef DEBUG_IDE
-    printf("ide: read addr=0x%x val=%02x\n", addr1, ret);
-#endif
+
+    trace_ide_ioport_read(addr, ret, bus, s);
     return ret;
 }
 
@@ -2151,9 +2140,8 @@ uint32_t ide_status_read(void *opaque, uint32_t addr)
     } else {
         ret = s->status;
     }
-#ifdef DEBUG_IDE
-    printf("ide: read status addr=0x%x val=%02x\n", addr, ret);
-#endif
+
+    trace_ide_status_read(addr, ret, bus, s);
     return ret;
 }
 
@@ -2163,9 +2151,8 @@ void ide_cmd_write(void *opaque, uint32_t addr, uint32_t val)
     IDEState *s;
     int i;
 
-#ifdef DEBUG_IDE
-    printf("ide: write control addr=0x%x val=%02x\n", addr, val);
-#endif
+    trace_ide_cmd_write(addr, val, bus);
+
     /* common for both drives */
     if (!(bus->cmd & IDE_CMD_RESET) &&
         (val & IDE_CMD_RESET)) {
diff --git a/hw/ide/pci.c b/hw/ide/pci.c
index 3cfb510..f2dcc0e 100644
--- a/hw/ide/pci.c
+++ b/hw/ide/pci.c
@@ -31,6 +31,7 @@
 #include "sysemu/dma.h"
 #include "qemu/error-report.h"
 #include "hw/ide/pci.h"
+#include "trace.h"
 
 #define BMDMA_PAGE_SIZE 4096
 
@@ -196,9 +197,7 @@ static void bmdma_reset(IDEDMA *dma)
 {
     BMDMAState *bm = DO_UPCAST(BMDMAState, dma, dma);
 
-#ifdef DEBUG_IDE
-    printf("ide: dma_reset\n");
-#endif
+    trace_bmdma_reset();
     bmdma_cancel(bm);
     bm->cmd = 0;
     bm->status = 0;
@@ -227,9 +226,7 @@ static void bmdma_irq(void *opaque, int n, int level)
 
 void bmdma_cmd_writeb(BMDMAState *bm, uint32_t val)
 {
-#ifdef DEBUG_IDE
-    printf("%s: 0x%08x\n", __func__, val);
-#endif
+    trace_bmdma_cmd_writeb(val);
 
     /* Ignore writes to SSBM if it keeps the old value */
     if ((val & BM_CMD_START) != (bm->cmd & BM_CMD_START)) {
@@ -258,9 +255,7 @@ static uint64_t bmdma_addr_read(void *opaque, hwaddr addr,
     uint64_t data;
 
     data = (bm->addr >> (addr * 8)) & mask;
-#ifdef DEBUG_IDE
-    printf("%s: 0x%08x\n", __func__, (unsigned)data);
-#endif
+    trace_bmdma_addr_read(data);
     return data;
 }
 
@@ -271,9 +266,7 @@ static void bmdma_addr_write(void *opaque, hwaddr addr,
     int shift = addr * 8;
     uint32_t mask = (1ULL << (width * 8)) - 1;
 
-#ifdef DEBUG_IDE
-    printf("%s: 0x%08x\n", __func__, (unsigned)data);
-#endif
+    trace_bmdma_addr_write(data);
     bm->addr &= ~(mask << shift);
     bm->addr |= ((data & mask) << shift) & ~3;
 }
diff --git a/hw/ide/piix.c b/hw/ide/piix.c
index 7e2d767..dfb21f6 100644
--- a/hw/ide/piix.c
+++ b/hw/ide/piix.c
@@ -33,6 +33,7 @@
 #include "sysemu/dma.h"
 
 #include "hw/ide/pci.h"
+#include "trace.h"
 
 static uint64_t bmdma_read(void *opaque, hwaddr addr, unsigned size)
 {
@@ -54,9 +55,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr, unsigned size)
         val = 0xff;
         break;
     }
-#ifdef DEBUG_IDE
-    printf("bmdma: readb 0x%02x : 0x%02x\n", (uint8_t)addr, val);
-#endif
+
+    trace_bmdma_read(addr, val);
     return val;
 }
 
@@ -69,9 +69,8 @@ static void bmdma_write(void *opaque, hwaddr addr,
         return;
     }
 
-#ifdef DEBUG_IDE
-    printf("bmdma: writeb 0x%02x : 0x%02x\n", (uint8_t)addr, (uint8_t)val);
-#endif
+    trace_bmdma_write(addr, val);
+
     switch(addr & 3) {
     case 0:
         bmdma_cmd_writeb(bm, val);
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
new file mode 100644
index 0000000..68ad96a
--- /dev/null
+++ b/hw/ide/trace-events
@@ -0,0 +1,33 @@
+# See docs/devel/tracing.txt for syntax documentation.
+
+# hw/ide/core.c
+# portio
+ide_ioport_read(uint32_t addr, uint32_t val, void *bus, void *s)  "IDE PIO rd @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
+ide_ioport_write(uint32_t addr, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
+ide_status_read(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO rd @ 0x%"PRIx32" (Alt Status); val 0x%02"PRIx32"; bus %p; IDEState %p"
+ide_cmd_write(uint32_t addr, uint32_t val, void *bus)                              "IDE PIO wr @ 0x%"PRIx32" (Device Control); val 0x%02"PRIx32"; bus %p"
+# misc
+ide_exec_cmd(void *bus, void *state, uint32_t cmd) "IDE exec cmd: bus %p; state %p; cmd 0x%02x"
+ide_cancel_dma_sync_buffered(void *fn, void *req) "invoking cb %p of buffered request %p with -ECANCELED"
+ide_cancel_dma_sync_remaining(void) "draining all remaining requests"
+ide_sector_read(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
+ide_sector_write(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
+ide_reset(void *s) "IDEstate %p"
+
+# hw/ide/pci.c
+bmdma_reset(void) ""
+bmdma_cmd_writeb(uint32_t val) "val: 0x%08x"
+bmdma_addr_read(uint64_t data) "data: 0x%016"PRIx64
+bmdma_addr_write(uint64_t data) "data: 0x%016"PRIx64
+
+# hw/ide/piix.c
+bmdma_read(uint64_t addr, uint8_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
+bmdma_write(uint64_t addr, uint8_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02x"
+
+# hw/ide/cmd646.c
+bmdma_read_cmd646(uint64_t addr, uint32_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
+bmdma_write_cmd646(uint64_t addr, uint64_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02"PRIx64
+
+# hw/ide/via.c
+bmdma_read_via(uint64_t addr, uint32_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
+bmdma_write_via(uint64_t addr, uint64_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02"PRIx64
diff --git a/hw/ide/via.c b/hw/ide/via.c
index 5b32ecb..35c3059 100644
--- a/hw/ide/via.c
+++ b/hw/ide/via.c
@@ -33,6 +33,7 @@
 #include "sysemu/dma.h"
 
 #include "hw/ide/pci.h"
+#include "trace.h"
 
 static uint64_t bmdma_read(void *opaque, hwaddr addr,
                            unsigned size)
@@ -55,9 +56,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
         val = 0xff;
         break;
     }
-#ifdef DEBUG_IDE
-    printf("bmdma: readb 0x%02x : 0x%02x\n", addr, val);
-#endif
+
+    trace_bmdma_read_via(addr, val);
     return val;
 }
 
@@ -70,9 +70,7 @@ static void bmdma_write(void *opaque, hwaddr addr,
         return;
     }
 
-#ifdef DEBUG_IDE
-    printf("bmdma: writeb 0x%02x : 0x%02x\n", addr, val);
-#endif
+    trace_bmdma_write_via(addr, val);
     switch (addr & 3) {
     case 0:
         bmdma_cmd_writeb(bm, val);
diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
index 482a951..4a92f0a 100644
--- a/include/hw/ide/internal.h
+++ b/include/hw/ide/internal.h
@@ -14,7 +14,6 @@
 #include "block/scsi.h"
 
 /* debug IDE devices */
-//#define DEBUG_IDE
 //#define DEBUG_IDE_ATAPI
 //#define DEBUG_AIO
 #define USE_DMA_CDROM
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system John Snow
@ 2017-08-08 18:32 ` John Snow
  2017-08-08 20:05   ` Eric Blake
  2017-08-25 13:43   ` Philippe Mathieu-Daudé
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports John Snow
                   ` (7 subsequent siblings)
  9 siblings, 2 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 18:32 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Name the registers for tracing purposes.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/core.c       | 88 +++++++++++++++++++++++++++++++++++++++++------------
 hw/ide/trace-events |  4 +--
 2 files changed, 70 insertions(+), 22 deletions(-)

diff --git a/hw/ide/core.c b/hw/ide/core.c
index 53fa084..6235bdf 100644
--- a/hw/ide/core.c
+++ b/hw/ide/core.c
@@ -1177,13 +1177,37 @@ static void ide_clear_hob(IDEBus *bus)
     bus->ifs[1].select &= ~(1 << 7);
 }
 
+/* IOport [W]rite [R]egisters */
+enum ATA_IOPORT_WR {
+    ATA_IOPORT_WR_DATA = 0,
+    ATA_IOPORT_WR_FEATURES = 1,
+    ATA_IOPORT_WR_SECTOR_COUNT = 2,
+    ATA_IOPORT_WR_SECTOR_NUMBER = 3,
+    ATA_IOPORT_WR_CYLINDER_LOW = 4,
+    ATA_IOPORT_WR_CYLINDER_HIGH = 5,
+    ATA_IOPORT_WR_DEVICE_HEAD = 6,
+    ATA_IOPORT_WR_COMMAND = 7,
+    ATA_IOPORT_WR_NUM_REGISTERS,
+};
+
+const char *ATA_IOPORT_WR_lookup[ATA_IOPORT_WR_NUM_REGISTERS] = {
+    [ATA_IOPORT_WR_DATA] = "Data",
+    [ATA_IOPORT_WR_FEATURES] = "Features",
+    [ATA_IOPORT_WR_SECTOR_COUNT] = "Sector Count",
+    [ATA_IOPORT_WR_SECTOR_NUMBER] = "Sector Number",
+    [ATA_IOPORT_WR_CYLINDER_LOW] = "Cylinder Low",
+    [ATA_IOPORT_WR_CYLINDER_HIGH] = "Cylinder High",
+    [ATA_IOPORT_WR_DEVICE_HEAD] = "Device/Head",
+    [ATA_IOPORT_WR_COMMAND] = "Command"
+};
+
 void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
 {
     IDEBus *bus = opaque;
     IDEState *s = idebus_active_if(bus);
     int reg_num = addr & 7;
 
-    trace_ide_ioport_write(addr, val, bus, s);
+    trace_ide_ioport_write(addr, ATA_IOPORT_WR_lookup[reg_num], val, bus, s);
 
     /* ignore writes to command block while busy with previous command */
     if (reg_num != 7 && (s->status & (BUSY_STAT|DRQ_STAT))) {
@@ -1193,43 +1217,43 @@ void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
     switch(reg_num) {
     case 0:
         break;
-    case 1:
-	ide_clear_hob(bus);
+    case ATA_IOPORT_WR_FEATURES:
+        ide_clear_hob(bus);
         /* NOTE: data is written to the two drives */
-	bus->ifs[0].hob_feature = bus->ifs[0].feature;
-	bus->ifs[1].hob_feature = bus->ifs[1].feature;
+        bus->ifs[0].hob_feature = bus->ifs[0].feature;
+        bus->ifs[1].hob_feature = bus->ifs[1].feature;
         bus->ifs[0].feature = val;
         bus->ifs[1].feature = val;
         break;
-    case 2:
+    case ATA_IOPORT_WR_SECTOR_COUNT:
 	ide_clear_hob(bus);
 	bus->ifs[0].hob_nsector = bus->ifs[0].nsector;
 	bus->ifs[1].hob_nsector = bus->ifs[1].nsector;
         bus->ifs[0].nsector = val;
         bus->ifs[1].nsector = val;
         break;
-    case 3:
+    case ATA_IOPORT_WR_SECTOR_NUMBER:
 	ide_clear_hob(bus);
 	bus->ifs[0].hob_sector = bus->ifs[0].sector;
 	bus->ifs[1].hob_sector = bus->ifs[1].sector;
         bus->ifs[0].sector = val;
         bus->ifs[1].sector = val;
         break;
-    case 4:
+    case ATA_IOPORT_WR_CYLINDER_LOW:
 	ide_clear_hob(bus);
 	bus->ifs[0].hob_lcyl = bus->ifs[0].lcyl;
 	bus->ifs[1].hob_lcyl = bus->ifs[1].lcyl;
         bus->ifs[0].lcyl = val;
         bus->ifs[1].lcyl = val;
         break;
-    case 5:
+    case ATA_IOPORT_WR_CYLINDER_HIGH:
 	ide_clear_hob(bus);
 	bus->ifs[0].hob_hcyl = bus->ifs[0].hcyl;
 	bus->ifs[1].hob_hcyl = bus->ifs[1].hcyl;
         bus->ifs[0].hcyl = val;
         bus->ifs[1].hcyl = val;
         break;
-    case 6:
+    case ATA_IOPORT_WR_DEVICE_HEAD:
 	/* FIXME: HOB readback uses bit 7 */
         bus->ifs[0].select = (val & ~0x10) | 0xa0;
         bus->ifs[1].select = (val | 0x10) | 0xa0;
@@ -1237,7 +1261,7 @@ void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
         bus->unit = (val >> 4) & 1;
         break;
     default:
-    case 7:
+    case ATA_IOPORT_WR_COMMAND:
         /* command */
         ide_exec_cmd(bus, val);
         break;
@@ -2044,6 +2068,30 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
     }
 }
 
+/* IOport [R]ead [R]egisters */
+enum ATA_IOPORT_RR {
+    ATA_IOPORT_RR_DATA = 0,
+    ATA_IOPORT_RR_ERROR = 1,
+    ATA_IOPORT_RR_SECTOR_COUNT = 2,
+    ATA_IOPORT_RR_SECTOR_NUMBER = 3,
+    ATA_IOPORT_RR_CYLINDER_LOW = 4,
+    ATA_IOPORT_RR_CYLINDER_HIGH = 5,
+    ATA_IOPORT_RR_DEVICE_HEAD = 6,
+    ATA_IOPORT_RR_STATUS = 7,
+    ATA_IOPORT_RR_NUM_REGISTERS,
+};
+
+const char *ATA_IOPORT_RR_lookup[ATA_IOPORT_RR_NUM_REGISTERS] = {
+    [ATA_IOPORT_RR_DATA] = "Data",
+    [ATA_IOPORT_RR_ERROR] = "Error",
+    [ATA_IOPORT_RR_SECTOR_COUNT] = "Sector Count",
+    [ATA_IOPORT_RR_SECTOR_NUMBER] = "Sector Number",
+    [ATA_IOPORT_RR_CYLINDER_LOW] = "Cylinder Low",
+    [ATA_IOPORT_RR_CYLINDER_HIGH] = "Cylinder High",
+    [ATA_IOPORT_RR_DEVICE_HEAD] = "Device/Head",
+    [ATA_IOPORT_RR_STATUS] = "Status"
+};
+
 uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 {
     IDEBus *bus = opaque;
@@ -2056,10 +2104,10 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
     //hob = s->select & (1 << 7);
     hob = 0;
     switch(reg_num) {
-    case 0:
+    case ATA_IOPORT_RR_DATA:
         ret = 0xff;
         break;
-    case 1:
+    case ATA_IOPORT_RR_ERROR:
         if ((!bus->ifs[0].blk && !bus->ifs[1].blk) ||
             (s != bus->ifs && !s->blk)) {
             ret = 0;
@@ -2069,7 +2117,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 	    ret = s->hob_feature;
         }
         break;
-    case 2:
+    case ATA_IOPORT_RR_SECTOR_COUNT:
         if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
             ret = 0;
         } else if (!hob) {
@@ -2078,7 +2126,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 	    ret = s->hob_nsector;
         }
         break;
-    case 3:
+    case ATA_IOPORT_RR_SECTOR_NUMBER:
         if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
             ret = 0;
         } else if (!hob) {
@@ -2087,7 +2135,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 	    ret = s->hob_sector;
         }
         break;
-    case 4:
+    case ATA_IOPORT_RR_CYLINDER_LOW:
         if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
             ret = 0;
         } else if (!hob) {
@@ -2096,7 +2144,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 	    ret = s->hob_lcyl;
         }
         break;
-    case 5:
+    case ATA_IOPORT_RR_CYLINDER_HIGH:
         if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
             ret = 0;
         } else if (!hob) {
@@ -2105,7 +2153,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
 	    ret = s->hob_hcyl;
         }
         break;
-    case 6:
+    case ATA_IOPORT_RR_DEVICE_HEAD:
         if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
             ret = 0;
         } else {
@@ -2113,7 +2161,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
         }
         break;
     default:
-    case 7:
+    case ATA_IOPORT_RR_STATUS:
         if ((!bus->ifs[0].blk && !bus->ifs[1].blk) ||
             (s != bus->ifs && !s->blk)) {
             ret = 0;
@@ -2124,7 +2172,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
         break;
     }
 
-    trace_ide_ioport_read(addr, ret, bus, s);
+    trace_ide_ioport_read(addr, ATA_IOPORT_RR_lookup[reg_num], ret, bus, s);
     return ret;
 }
 
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
index 68ad96a..6c156ac 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -2,8 +2,8 @@
 
 # hw/ide/core.c
 # portio
-ide_ioport_read(uint32_t addr, uint32_t val, void *bus, void *s)  "IDE PIO rd @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
-ide_ioport_write(uint32_t addr, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
+ide_ioport_read(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s)  "IDE PIO rd @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"
+ide_ioport_write(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"
 ide_status_read(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO rd @ 0x%"PRIx32" (Alt Status); val 0x%02"PRIx32"; bus %p; IDEState %p"
 ide_cmd_write(uint32_t addr, uint32_t val, void *bus)                              "IDE PIO wr @ 0x%"PRIx32" (Device Control); val 0x%02"PRIx32"; bus %p"
 # misc
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system John Snow
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-08 20:10   ` Eric Blake
  2017-08-08 20:30   ` Eric Blake
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events John Snow
                   ` (6 subsequent siblings)
  9 siblings, 2 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

To be used sparingly, but still interesting in the case of small
firmwares designed to reproduce bugs in QEMU IDE.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/core.c | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/hw/ide/core.c b/hw/ide/core.c
index 6235bdf..29848ff 100644
--- a/hw/ide/core.c
+++ b/hw/ide/core.c
@@ -2251,6 +2251,8 @@ void ide_data_writew(void *opaque, uint32_t addr, uint32_t val)
     IDEState *s = idebus_active_if(bus);
     uint8_t *p;
 
+    trace_ide_data_writew(addr, val, bus, s);
+
     /* PIO data access allowed only when DRQ bit is set. The result of a write
      * during PIO out is indeterminate, just ignore it. */
     if (!(s->status & DRQ_STAT) || ide_is_pio_out(s)) {
@@ -2296,6 +2298,8 @@ uint32_t ide_data_readw(void *opaque, uint32_t addr)
         s->status &= ~DRQ_STAT;
         s->end_transfer_func(s);
     }
+
+    trace_ide_data_readw(addr, ret, bus, s);
     return ret;
 }
 
@@ -2305,6 +2309,8 @@ void ide_data_writel(void *opaque, uint32_t addr, uint32_t val)
     IDEState *s = idebus_active_if(bus);
     uint8_t *p;
 
+    trace_ide_data_writel(addr, val, bus, s);
+
     /* PIO data access allowed only when DRQ bit is set. The result of a write
      * during PIO out is indeterminate, just ignore it. */
     if (!(s->status & DRQ_STAT) || ide_is_pio_out(s)) {
@@ -2335,7 +2341,8 @@ uint32_t ide_data_readl(void *opaque, uint32_t addr)
     /* PIO data access allowed only when DRQ bit is set. The result of a read
      * during PIO in is indeterminate, return 0 and don't move forward. */
     if (!(s->status & DRQ_STAT) || !ide_is_pio_out(s)) {
-        return 0;
+        ret = 0;
+        goto out;
     }
 
     p = s->data_ptr;
@@ -2350,6 +2357,9 @@ uint32_t ide_data_readl(void *opaque, uint32_t addr)
         s->status &= ~DRQ_STAT;
         s->end_transfer_func(s);
     }
+
+out:
+    trace_ide_data_readl(addr, ret, bus, s);
     return ret;
 }
 
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (2 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-08 20:59   ` Eric Blake
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events John Snow
                   ` (5 subsequent siblings)
  9 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Goodbye, printfs.
Hello, fancy printfs.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/atapi.c            | 64 +++++++++++++++++------------------------------
 hw/ide/trace-events       | 19 ++++++++++++++
 include/hw/ide/internal.h |  1 -
 3 files changed, 42 insertions(+), 42 deletions(-)

diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
index fc1d19c..37fa699 100644
--- a/hw/ide/atapi.c
+++ b/hw/ide/atapi.c
@@ -27,6 +27,7 @@
 #include "hw/ide/internal.h"
 #include "hw/scsi/scsi.h"
 #include "sysemu/block-backend.h"
+#include "trace.h"
 
 #define ATAPI_SECTOR_BITS (2 + BDRV_SECTOR_BITS)
 #define ATAPI_SECTOR_SIZE (1 << ATAPI_SECTOR_BITS)
@@ -116,9 +117,7 @@ cd_read_sector_sync(IDEState *s)
     block_acct_start(blk_get_stats(s->blk), &s->acct,
                      ATAPI_SECTOR_SIZE, BLOCK_ACCT_READ);
 
-#ifdef DEBUG_IDE_ATAPI
-    printf("cd_read_sector_sync: lba=%d\n", s->lba);
-#endif
+    trace_cd_read_sector_sync(s->lba);
 
     switch (s->cd_sector_size) {
     case 2048:
@@ -152,9 +151,7 @@ static void cd_read_sector_cb(void *opaque, int ret)
 {
     IDEState *s = opaque;
 
-#ifdef DEBUG_IDE_ATAPI
-    printf("cd_read_sector_cb: lba=%d ret=%d\n", s->lba, ret);
-#endif
+    trace_cd_read_sector_cb(s->lba, ret);
 
     if (ret < 0) {
         block_acct_failed(blk_get_stats(s->blk), &s->acct);
@@ -188,9 +185,7 @@ static int cd_read_sector(IDEState *s)
     s->iov.iov_len = ATAPI_SECTOR_SIZE;
     qemu_iovec_init_external(&s->qiov, &s->iov, 1);
 
-#ifdef DEBUG_IDE_ATAPI
-    printf("cd_read_sector: lba=%d\n", s->lba);
-#endif
+    trace_cd_read_sector(s->lba);
 
     block_acct_start(blk_get_stats(s->blk), &s->acct,
                      ATAPI_SECTOR_SIZE, BLOCK_ACCT_READ);
@@ -213,9 +208,7 @@ void ide_atapi_cmd_ok(IDEState *s)
 
 void ide_atapi_cmd_error(IDEState *s, int sense_key, int asc)
 {
-#ifdef DEBUG_IDE_ATAPI
-    printf("atapi_cmd_error: sense=0x%x asc=0x%x\n", sense_key, asc);
-#endif
+    trace_ide_atapi_cmd_error(s, sense_key, asc);
     s->error = sense_key << 4;
     s->status = READY_STAT | ERR_STAT;
     s->nsector = (s->nsector & ~7) | ATAPI_INT_REASON_IO | ATAPI_INT_REASON_CD;
@@ -252,19 +245,14 @@ static uint16_t atapi_byte_count_limit(IDEState *s)
 void ide_atapi_cmd_reply_end(IDEState *s)
 {
     int byte_count_limit, size, ret;
-#ifdef DEBUG_IDE_ATAPI
-    printf("reply: tx_size=%d elem_tx_size=%d index=%d\n",
-           s->packet_transfer_size,
-           s->elementary_transfer_size,
-           s->io_buffer_index);
-#endif
+    trace_ide_atapi_cmd_reply_end(s, s->packet_transfer_size,
+                                  s->elementary_transfer_size,
+                                  s->io_buffer_index);
     if (s->packet_transfer_size <= 0) {
         /* end of transfer */
         ide_atapi_cmd_ok(s);
         ide_set_irq(s->bus);
-#ifdef DEBUG_IDE_ATAPI
-        printf("end of transfer, status=0x%x\n", s->status);
-#endif
+        trace_ide_atapi_cmd_reply_end_eot(s, s->status);
     } else {
         /* see if a new sector must be read */
         if (s->lba != -1 && s->io_buffer_index >= s->cd_sector_size) {
@@ -300,9 +288,7 @@ void ide_atapi_cmd_reply_end(IDEState *s)
             /* a new transfer is needed */
             s->nsector = (s->nsector & ~7) | ATAPI_INT_REASON_IO;
             byte_count_limit = atapi_byte_count_limit(s);
-#ifdef DEBUG_IDE_ATAPI
-            printf("byte_count_limit=%d\n", byte_count_limit);
-#endif
+            trace_ide_atapi_cmd_reply_end_bcl(s, byte_count_limit);
             size = s->packet_transfer_size;
             if (size > byte_count_limit) {
                 /* byte count limit must be even if this case */
@@ -324,9 +310,7 @@ void ide_atapi_cmd_reply_end(IDEState *s)
             ide_transfer_start(s, s->io_buffer + s->io_buffer_index - size,
                                size, ide_atapi_cmd_reply_end);
             ide_set_irq(s->bus);
-#ifdef DEBUG_IDE_ATAPI
-            printf("status=0x%x\n", s->status);
-#endif
+            trace_ide_atapi_cmd_reply_end_new(s, s->status);
         }
     }
 }
@@ -368,9 +352,7 @@ static void ide_atapi_cmd_read_pio(IDEState *s, int lba, int nb_sectors,
 
 static void ide_atapi_cmd_check_status(IDEState *s)
 {
-#ifdef DEBUG_IDE_ATAPI
-    printf("atapi_cmd_check_status\n");
-#endif
+    trace_ide_atapi_cmd_check_status(s);
     s->error = MC_ERR | (UNIT_ATTENTION << 4);
     s->status = ERR_STAT;
     s->nsector = 0;
@@ -477,10 +459,8 @@ static void ide_atapi_cmd_read_dma(IDEState *s, int lba, int nb_sectors,
 static void ide_atapi_cmd_read(IDEState *s, int lba, int nb_sectors,
                                int sector_size)
 {
-#ifdef DEBUG_IDE_ATAPI
-    printf("read %s: LBA=%d nb_sectors=%d\n", s->atapi_dma ? "dma" : "pio",
-        lba, nb_sectors);
-#endif
+    trace_ide_atapi_cmd_read(s, s->atapi_dma ? "dma" : "pio",
+                             lba, nb_sectors);
     if (s->atapi_dma) {
         ide_atapi_cmd_read_dma(s, lba, nb_sectors, sector_size);
     } else {
@@ -1330,16 +1310,18 @@ void ide_atapi_cmd(IDEState *s)
     uint8_t *buf = s->io_buffer;
     const struct AtapiCmd *cmd = &atapi_cmd_table[s->io_buffer[0]];
 
-#ifdef DEBUG_IDE_ATAPI
-    {
+    trace_ide_atapi_cmd(s, s->io_buffer[0]);
+
+    if (TRACE_IDE_ATAPI_CMD_PACKET_ENABLED) {
+        /* Each pretty-printed byte needs two bytes and a space; */
+        char *ppacket = g_malloc(ATAPI_PACKET_SIZE * 3 + 1);
         int i;
-        printf("ATAPI limit=0x%x packet:", s->lcyl | (s->hcyl << 8));
-        for(i = 0; i < ATAPI_PACKET_SIZE; i++) {
-            printf(" %02x", buf[i]);
+        for (i = 0; i < ATAPI_PACKET_SIZE; i++) {
+            sprintf(ppacket + (i * 3), "%02x ", buf[i]);
         }
-        printf("\n");
+        trace_ide_atapi_cmd_packet(s, s->lcyl | (s->hcyl << 8), ppacket);
+        g_free(ppacket);
     }
-#endif
 
     /*
      * If there's a UNIT_ATTENTION condition pending, only command flagged with
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
index 6c156ac..ade1e76 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -6,6 +6,10 @@ ide_ioport_read(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s
 ide_ioport_write(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"
 ide_status_read(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO rd @ 0x%"PRIx32" (Alt Status); val 0x%02"PRIx32"; bus %p; IDEState %p"
 ide_cmd_write(uint32_t addr, uint32_t val, void *bus)                              "IDE PIO wr @ 0x%"PRIx32" (Device Control); val 0x%02"PRIx32"; bus %p"
+ide_data_readw(uint32_t addr, uint32_t val, void *bus, void *s)                    "IDE PIO rd @ 0x%"PRIx32" (Data: Word); val 0x%04"PRIx32"; bus %p; IDEState %p"
+ide_data_writew(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO wr @ 0x%"PRIx32" (Data: Word); val 0x%04"PRIx32"; bus %p; IDEState %p"
+ide_data_readl(uint32_t addr, uint32_t val, void *bus, void *s)                    "IDE PIO rd @ 0x%"PRIx32" (Data: Long); val 0x%08"PRIx32"; bus %p; IDEState %p"
+ide_data_writel(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO wr @ 0x%"PRIx32" (Data: Long); val 0x%08"PRIx32"; bus %p; IDEState %p"
 # misc
 ide_exec_cmd(void *bus, void *state, uint32_t cmd) "IDE exec cmd: bus %p; state %p; cmd 0x%02x"
 ide_cancel_dma_sync_buffered(void *fn, void *req) "invoking cb %p of buffered request %p with -ECANCELED"
@@ -31,3 +35,18 @@ bmdma_write_cmd646(uint64_t addr, uint64_t val) "bmdma: writeb 0x%"PRIx64" : 0x%
 # hw/ide/via.c
 bmdma_read_via(uint64_t addr, uint32_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
 bmdma_write_via(uint64_t addr, uint64_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02"PRIx64
+
+# hw/ide/atapi.c
+cd_read_sector_sync(int lba) "lba=%d"
+cd_read_sector_cb(int lba, int ret) "lba=%d ret=%d"
+cd_read_sector(int lba) "lba=%d"
+ide_atapi_cmd_error(void *s, int sense_key, int asc) "IDEState: %p; sense=0x%x asc=0x%x"
+ide_atapi_cmd_reply_end(void *s, int tx_size, int elem_tx_size, int32_t index) "IDEState %p; reply: tx_size=%d elem_tx_size=%d index=%"PRId32
+ide_atapi_cmd_reply_end_eot(void *s, int status) "IDEState: %p; end of transfer, status=0x%x"
+ide_atapi_cmd_reply_end_bcl(void *s, int bcl) "IDEState: %p; byte_count_limit=%d"
+ide_atapi_cmd_reply_end_new(void *s, int status) "IDEState: %p; new transfer started, status=0x%x"
+ide_atapi_cmd_check_status(void *s) "IDEState: %p"
+ide_atapi_cmd_read(void *s, const char *method, int lba, int nb_sectors) "IDEState: %p; read %s: LBA=%d nb_sectors=%d"
+ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
+# Warning: Verbose
+ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
\ No newline at end of file
diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
index 4a92f0a..74efe8a 100644
--- a/include/hw/ide/internal.h
+++ b/include/hw/ide/internal.h
@@ -14,7 +14,6 @@
 #include "block/scsi.h"
 
 /* debug IDE devices */
-//#define DEBUG_IDE_ATAPI
 //#define DEBUG_AIO
 #define USE_DMA_CDROM
 
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (3 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-25 13:46   ` Philippe Mathieu-Daudé
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events John Snow
                   ` (4 subsequent siblings)
  9 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/atapi.c            |  5 +----
 hw/ide/core.c             | 17 ++++++++++-------
 hw/ide/trace-events       |  3 +++
 include/hw/ide/internal.h |  7 +++++--
 4 files changed, 19 insertions(+), 13 deletions(-)

diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
index 37fa699..b8fc51e 100644
--- a/hw/ide/atapi.c
+++ b/hw/ide/atapi.c
@@ -416,10 +416,7 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
         s->io_buffer_size = n * 2048;
         data_offset = 0;
     }
-#ifdef DEBUG_AIO
-    printf("aio_read_cd: lba=%u n=%d\n", s->lba, n);
-#endif
-
+    trace_ide_atapi_cmd_read_dma_cb_aio(s, s->lba, n);
     s->bus->dma->iov.iov_base = (void *)(s->io_buffer + data_offset);
     s->bus->dma->iov.iov_len = n * ATAPI_SECTOR_SIZE;
     qemu_iovec_init_external(&s->bus->dma->qiov, &s->bus->dma->iov, 1);
diff --git a/hw/ide/core.c b/hw/ide/core.c
index 29848ff..1358029 100644
--- a/hw/ide/core.c
+++ b/hw/ide/core.c
@@ -58,6 +58,13 @@ static const int smart_attributes[][12] = {
     { 190,  0x03, 0x00, 0x45, 0x45, 0x1f, 0x00, 0x1f, 0x1f, 0x00, 0x00, 0x32},
 };
 
+const char *IDE_DMA_CMD_lookup[IDE_DMA__END] = {
+    [IDE_DMA_READ] = "DMA_READ",
+    [IDE_DMA_WRITE] = "DMA_WRITE",
+    [IDE_DMA_TRIM] = "DMA TRIM",
+    [IDE_DMA_ATAPI] = "DMA ATAPI"
+};
+
 static void ide_dummy_transfer_stop(IDEState *s);
 
 static void padstr(char *str, const char *src, int len)
@@ -860,10 +867,8 @@ static void ide_dma_cb(void *opaque, int ret)
         goto eot;
     }
 
-#ifdef DEBUG_AIO
-    printf("ide_dma_cb: sector_num=%" PRId64 " n=%d, cmd_cmd=%d\n",
-           sector_num, n, s->dma_cmd);
-#endif
+    trace_ide_dma_cb(s, sector_num, n,
+                     IDE_DMA_CMD_lookup[s->dma_cmd]);
 
     if ((s->dma_cmd == IDE_DMA_READ || s->dma_cmd == IDE_DMA_WRITE) &&
         !ide_sect_range_ok(s, sector_num, n)) {
@@ -2383,9 +2388,7 @@ void ide_bus_reset(IDEBus *bus)
 
     /* pending async DMA */
     if (bus->dma->aiocb) {
-#ifdef DEBUG_AIO
-        printf("aio_cancel\n");
-#endif
+        trace_ide_bus_reset_aio();
         blk_aio_cancel(bus->dma->aiocb);
         bus->dma->aiocb = NULL;
     }
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
index ade1e76..6e33cb3 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -17,6 +17,8 @@ ide_cancel_dma_sync_remaining(void) "draining all remaining requests"
 ide_sector_read(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
 ide_sector_write(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
 ide_reset(void *s) "IDEstate %p"
+ide_bus_reset_aio(void) "aio_cancel"
+ide_dma_cb(void *s, int64_t sector_num, int n, const char *dma) "IDEState %p; sector_num=%"PRId64" n=%d cmd=%s"
 
 # hw/ide/pci.c
 bmdma_reset(void) ""
@@ -48,5 +50,6 @@ ide_atapi_cmd_reply_end_new(void *s, int status) "IDEState: %p; new transfer sta
 ide_atapi_cmd_check_status(void *s) "IDEState: %p"
 ide_atapi_cmd_read(void *s, const char *method, int lba, int nb_sectors) "IDEState: %p; read %s: LBA=%d nb_sectors=%d"
 ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
+ide_atapi_cmd_read_dma_cb_aio(void *s, int lba, int n) "IDEState: %p; aio read: lba=%d n=%d"
 # Warning: Verbose
 ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
\ No newline at end of file
diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
index 74efe8a..97e97a2 100644
--- a/include/hw/ide/internal.h
+++ b/include/hw/ide/internal.h
@@ -14,7 +14,6 @@
 #include "block/scsi.h"
 
 /* debug IDE devices */
-//#define DEBUG_AIO
 #define USE_DMA_CDROM
 
 typedef struct IDEBus IDEBus;
@@ -333,12 +332,16 @@ struct unreported_events {
 };
 
 enum ide_dma_cmd {
-    IDE_DMA_READ,
+    IDE_DMA__BEGIN = 0,
+    IDE_DMA_READ = IDE_DMA__BEGIN,
     IDE_DMA_WRITE,
     IDE_DMA_TRIM,
     IDE_DMA_ATAPI,
+    IDE_DMA__END
 };
 
+extern const char *IDE_DMA_CMD_lookup[IDE_DMA__END];
+
 #define ide_cmd_is_read(s) \
 	((s)->dma_cmd == IDE_DMA_READ)
 
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (4 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-25 13:17   ` Philippe Mathieu-Daudé
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants John Snow
                   ` (3 subsequent siblings)
  9 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

There are a few hangers-on that will be dealt with individually
in forthcoming patches.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/ahci.c       | 157 +++++++++++++++++++++++-----------------------------
 hw/ide/trace-events |  52 ++++++++++++++++-
 2 files changed, 119 insertions(+), 90 deletions(-)

diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
index 406a1b5..d5acceb 100644
--- a/hw/ide/ahci.c
+++ b/hw/ide/ahci.c
@@ -35,6 +35,7 @@
 #include "hw/ide/ahci_internal.h"
 
 #define DEBUG_AHCI 0
+#include "trace.h"
 
 #define DPRINTF(port, fmt, ...) \
 do { \
@@ -114,9 +115,9 @@ static uint32_t  ahci_port_read(AHCIState *s, int port, int offset)
     default:
         val = 0;
     }
-    DPRINTF(port, "offset: 0x%x val: 0x%x\n", offset, val);
-    return val;
 
+    trace_ahci_port_read(s, port, offset, val);
+    return val;
 }
 
 static void ahci_irq_raise(AHCIState *s, AHCIDevice *dev)
@@ -125,7 +126,7 @@ static void ahci_irq_raise(AHCIState *s, AHCIDevice *dev)
     PCIDevice *pci_dev = (PCIDevice *) object_dynamic_cast(OBJECT(dev_state),
                                                            TYPE_PCI_DEVICE);
 
-    DPRINTF(0, "raise irq\n");
+    trace_ahci_irq_raise(s);
 
     if (pci_dev && msi_enabled(pci_dev)) {
         msi_notify(pci_dev, 0);
@@ -140,7 +141,7 @@ static void ahci_irq_lower(AHCIState *s, AHCIDevice *dev)
     PCIDevice *pci_dev = (PCIDevice *) object_dynamic_cast(OBJECT(dev_state),
                                                            TYPE_PCI_DEVICE);
 
-    DPRINTF(0, "lower irq\n");
+    trace_ahci_irq_lower(s);
 
     if (!pci_dev || !msi_enabled(pci_dev)) {
         qemu_irq_lower(s->irq);
@@ -150,8 +151,7 @@ static void ahci_irq_lower(AHCIState *s, AHCIDevice *dev)
 static void ahci_check_irq(AHCIState *s)
 {
     int i;
-
-    DPRINTF(-1, "check irq %#x\n", s->control_regs.irqstatus);
+    uint32_t old_irq = s->control_regs.irqstatus;
 
     s->control_regs.irqstatus = 0;
     for (i = 0; i < s->ports; i++) {
@@ -160,7 +160,7 @@ static void ahci_check_irq(AHCIState *s)
             s->control_regs.irqstatus |= (1 << i);
         }
     }
-
+    trace_ahci_check_irq(s, old_irq, s->control_regs.irqstatus);
     if (s->control_regs.irqstatus &&
         (s->control_regs.ghc & HOST_CTL_IRQ_EN)) {
             ahci_irq_raise(s, NULL);
@@ -240,7 +240,7 @@ static void  ahci_port_write(AHCIState *s, int port, int offset, uint32_t val)
 {
     AHCIPortRegs *pr = &s->dev[port].port_regs;
 
-    DPRINTF(port, "offset: 0x%x val: 0x%x\n", offset, val);
+    trace_ahci_port_write(s, port, offset, val);
     switch (offset) {
         case PORT_LST_ADDR:
             pr->lst_addr = val;
@@ -341,8 +341,6 @@ static uint64_t ahci_mem_read_32(void *opaque, hwaddr addr)
             val = s->control_regs.version;
             break;
         }
-
-        DPRINTF(-1, "(addr 0x%08X), val 0x%08X\n", (unsigned) addr, val);
     } else if ((addr >= AHCI_PORT_REGS_START_ADDR) &&
                (addr < (AHCI_PORT_REGS_START_ADDR +
                 (s->ports * AHCI_PORT_ADDR_OFFSET_LEN)))) {
@@ -350,6 +348,7 @@ static uint64_t ahci_mem_read_32(void *opaque, hwaddr addr)
                              addr & AHCI_PORT_ADDR_OFFSET_MASK);
     }
 
+    trace_ahci_mem_read_32(s, addr, val);
     return val;
 }
 
@@ -379,8 +378,7 @@ static uint64_t ahci_mem_read(void *opaque, hwaddr addr, unsigned size)
         val = (hi << 32 | lo) >> (ofst * 8);
     }
 
-    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
-            addr, val, size);
+    trace_ahci_mem_read(opaque, size, addr, val);
     return val;
 }
 
@@ -390,8 +388,7 @@ static void ahci_mem_write(void *opaque, hwaddr addr,
 {
     AHCIState *s = opaque;
 
-    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
-            addr, val, size);
+    trace_ahci_mem_write(s, size, addr, val);
 
     /* Only aligned reads are allowed on AHCI */
     if (addr & 3) {
@@ -401,15 +398,12 @@ static void ahci_mem_write(void *opaque, hwaddr addr,
     }
 
     if (addr < AHCI_GENERIC_HOST_CONTROL_REGS_MAX_ADDR) {
-        DPRINTF(-1, "(addr 0x%08X), val 0x%08"PRIX64"\n", (unsigned) addr, val);
-
         switch (addr) {
             case HOST_CAP: /* R/WO, RO */
                 /* FIXME handle R/WO */
                 break;
             case HOST_CTL: /* R/W */
                 if (val & HOST_CTL_RESET) {
-                    DPRINTF(-1, "HBA Reset\n");
                     ahci_reset(s);
                 } else {
                     s->control_regs.ghc = (val & 0x3) | HOST_CTL_AHCI_EN;
@@ -427,7 +421,7 @@ static void ahci_mem_write(void *opaque, hwaddr addr,
                 /* FIXME report write? */
                 break;
             default:
-                DPRINTF(-1, "write to unknown register 0x%x\n", (unsigned)addr);
+                trace_ahci_mem_write_unknown(s, addr);
         }
     } else if ((addr >= AHCI_PORT_REGS_START_ADDR) &&
                (addr < (AHCI_PORT_REGS_START_ADDR +
@@ -559,7 +553,8 @@ static void ahci_set_signature(AHCIDevice *ad, uint32_t sig)
     s->sector = sig >> 8 & 0xFF;
     s->nsector = sig & 0xFF;
 
-    DPRINTF(ad->port_no, "set hcyl:lcyl:sect:nsect = 0x%08x\n", sig);
+    trace_ahci_set_signature(ad->hba, ad->port_no, s->nsector, s->sector,
+                             s->lcyl, s->hcyl, sig);
 }
 
 static void ahci_reset_port(AHCIState *s, int port)
@@ -569,7 +564,7 @@ static void ahci_reset_port(AHCIState *s, int port)
     IDEState *ide_state = &d->port.ifs[0];
     int i;
 
-    DPRINTF(port, "reset port\n");
+    trace_ahci_reset_port(s, port);
 
     ide_bus_reset(&d->port);
     ide_state->ncq_queues = AHCI_MAX_CMDS;
@@ -655,7 +650,7 @@ static bool ahci_map_fis_address(AHCIDevice *ad)
 static void ahci_unmap_fis_address(AHCIDevice *ad)
 {
     if (ad->res_fis == NULL) {
-        DPRINTF(ad->port_no, "Attempt to unmap NULL FIS address\n");
+        trace_ahci_unmap_fis_address_null(ad->hba, ad->port_no);
         return;
     }
     ad->port_regs.cmd &= ~PORT_CMD_FIS_ON;
@@ -682,7 +677,7 @@ static bool ahci_map_clb_address(AHCIDevice *ad)
 static void ahci_unmap_clb_address(AHCIDevice *ad)
 {
     if (ad->lst == NULL) {
-        DPRINTF(ad->port_no, "Attempt to unmap NULL CLB address\n");
+        trace_ahci_unmap_clb_address_null(ad->hba, ad->port_no);
         return;
     }
     ad->port_regs.cmd &= ~PORT_CMD_LIST_ON;
@@ -854,20 +849,22 @@ static int ahci_populate_sglist(AHCIDevice *ad, QEMUSGList *sglist,
     IDEBus *bus = &ad->port;
     BusState *qbus = BUS(bus);
 
+    trace_ahci_populate_sglist(ad->hba, ad->port_no);
+
     if (!prdtl) {
-        DPRINTF(ad->port_no, "no sg list given by guest: 0x%08x\n", opts);
+        trace_ahci_populate_sglist_no_prdtl(ad->hba, ad->port_no, opts);
         return -1;
     }
 
     /* map PRDT */
     if (!(prdt = dma_memory_map(ad->hba->as, prdt_addr, &prdt_len,
                                 DMA_DIRECTION_TO_DEVICE))){
-        DPRINTF(ad->port_no, "map failed\n");
+        trace_ahci_populate_sglist_no_map(ad->hba, ad->port_no);
         return -1;
     }
 
     if (prdt_len < real_prdt_len) {
-        DPRINTF(ad->port_no, "mapped less than expected\n");
+        trace_ahci_populate_sglist_short_map(ad->hba, ad->port_no);
         r = -1;
         goto out;
     }
@@ -886,9 +883,8 @@ static int ahci_populate_sglist(AHCIDevice *ad, QEMUSGList *sglist,
             sum += tbl_entry_size;
         }
         if ((off_idx == -1) || (off_pos < 0) || (off_pos > tbl_entry_size)) {
-            DPRINTF(ad->port_no, "%s: Incorrect offset! "
-                            "off_idx: %d, off_pos: %"PRId64"\n",
-                            __func__, off_idx, off_pos);
+            trace_ahci_populate_sglist_bad_offset(ad->hba, ad->port_no,
+                                                  off_idx, off_pos);
             r = -1;
             goto out;
         }
@@ -934,8 +930,8 @@ static void ncq_finish(NCQTransferState *ncq_tfs)
 
     ahci_write_fis_sdb(ncq_tfs->drive->hba, ncq_tfs);
 
-    DPRINTF(ncq_tfs->drive->port_no, "NCQ transfer tag %d finished\n",
-            ncq_tfs->tag);
+    trace_ncq_finish(ncq_tfs->drive->hba, ncq_tfs->drive->port_no,
+                     ncq_tfs->tag);
 
     block_acct_done(blk_get_stats(ncq_tfs->drive->port.ifs[0].blk),
                     &ncq_tfs->acct);
@@ -999,12 +995,8 @@ static void execute_ncq_command(NCQTransferState *ncq_tfs)
 
     switch (ncq_tfs->cmd) {
     case READ_FPDMA_QUEUED:
-        DPRINTF(port, "NCQ reading %d sectors from LBA %"PRId64", tag %d\n",
-                ncq_tfs->sector_count, ncq_tfs->lba, ncq_tfs->tag);
-
-        DPRINTF(port, "tag %d aio read %"PRId64"\n",
-                ncq_tfs->tag, ncq_tfs->lba);
-
+        trace_execute_ncq_command_read(ad->hba, port, ncq_tfs->tag,
+                                       ncq_tfs->sector_count, ncq_tfs->lba);
         dma_acct_start(ide_state->blk, &ncq_tfs->acct,
                        &ncq_tfs->sglist, BLOCK_ACCT_READ);
         ncq_tfs->aiocb = dma_blk_read(ide_state->blk, &ncq_tfs->sglist,
@@ -1013,12 +1005,8 @@ static void execute_ncq_command(NCQTransferState *ncq_tfs)
                                       ncq_cb, ncq_tfs);
         break;
     case WRITE_FPDMA_QUEUED:
-        DPRINTF(port, "NCQ writing %d sectors to LBA %"PRId64", tag %d\n",
-                ncq_tfs->sector_count, ncq_tfs->lba, ncq_tfs->tag);
-
-        DPRINTF(port, "tag %d aio write %"PRId64"\n",
-                ncq_tfs->tag, ncq_tfs->lba);
-
+        trace_execute_ncq_command_read(ad->hba, port, ncq_tfs->tag,
+                                       ncq_tfs->sector_count, ncq_tfs->lba);
         dma_acct_start(ide_state->blk, &ncq_tfs->acct,
                        &ncq_tfs->sglist, BLOCK_ACCT_WRITE);
         ncq_tfs->aiocb = dma_blk_write(ide_state->blk, &ncq_tfs->sglist,
@@ -1027,8 +1015,8 @@ static void execute_ncq_command(NCQTransferState *ncq_tfs)
                                        ncq_cb, ncq_tfs);
         break;
     default:
-        DPRINTF(port, "error: unsupported NCQ command (0x%02x) received\n",
-                ncq_tfs->cmd);
+        trace_execute_ncq_command_unsup(ad->hba, port,
+                                        ncq_tfs->tag, ncq_tfs->cmd);
         ncq_err(ncq_tfs);
     }
 }
@@ -1038,7 +1026,6 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
                                 uint8_t slot)
 {
     AHCIDevice *ad = &s->dev[port];
-    IDEState *ide_state = &ad->port.ifs[0];
     NCQFrame *ncq_fis = (NCQFrame*)cmd_fis;
     uint8_t tag = ncq_fis->tag >> 3;
     NCQTransferState *ncq_tfs = &ad->ncq_tfs[tag];
@@ -1066,21 +1053,20 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
 
     /* Sanity-check the NCQ packet */
     if (tag != slot) {
-        DPRINTF(port, "Warn: NCQ slot (%d) did not match the given tag (%d)\n",
-                slot, tag);
+        trace_process_ncq_command_mismatch(s, port, tag, slot);
     }
 
     if (ncq_fis->aux0 || ncq_fis->aux1 || ncq_fis->aux2 || ncq_fis->aux3) {
-        DPRINTF(port, "Warn: Attempt to use NCQ auxiliary fields.\n");
+        trace_process_ncq_command_aux(s, port, tag);
     }
     if (ncq_fis->prio || ncq_fis->icc) {
-        DPRINTF(port, "Warn: Unsupported attempt to use PRIO/ICC fields\n");
+        trace_process_ncq_command_prioicc(s, port, tag);
     }
     if (ncq_fis->fua & NCQ_FIS_FUA_MASK) {
-        DPRINTF(port, "Warn: Unsupported attempt to use Force Unit Access\n");
+        trace_process_ncq_command_fua(s, port, tag);
     }
     if (ncq_fis->tag & NCQ_FIS_RARC_MASK) {
-        DPRINTF(port, "Warn: Unsupported attempt to use Rebuild Assist\n");
+        trace_process_ncq_command_rarc(s, port, tag);
     }
 
     ncq_tfs->sector_count = ((ncq_fis->sector_count_high << 8) |
@@ -1099,16 +1085,14 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
         ahci_trigger_irq(ad->hba, ad, PORT_IRQ_OVERFLOW);
         return;
     } else if (ncq_tfs->sglist.size != size) {
-        DPRINTF(port, "Warn: PRDTL (0x%zx)"
-                " does not match requested size (0x%zx)",
-                ncq_tfs->sglist.size, size);
+        trace_process_ncq_command_large(s, port, tag,
+                                        ncq_tfs->sglist.size, size);
     }
 
-    DPRINTF(port, "NCQ transfer LBA from %"PRId64" to %"PRId64", "
-            "drive max %"PRId64"\n",
-            ncq_tfs->lba, ncq_tfs->lba + ncq_tfs->sector_count - 1,
-            ide_state->nb_sectors - 1);
-
+    trace_process_ncq_command(s, port, tag,
+                              ncq_fis->command,
+                              ncq_tfs->lba,
+                              ncq_tfs->lba + ncq_tfs->sector_count - 1);
     execute_ncq_command(ncq_tfs);
 }
 
@@ -1129,16 +1113,14 @@ static void handle_reg_h2d_fis(AHCIState *s, int port,
     uint16_t opts = le16_to_cpu(cmd->opts);
 
     if (cmd_fis[1] & 0x0F) {
-        DPRINTF(port, "Port Multiplier not supported."
-                " cmd_fis[0]=%02x cmd_fis[1]=%02x cmd_fis[2]=%02x\n",
-                cmd_fis[0], cmd_fis[1], cmd_fis[2]);
+        trace_handle_reg_h2d_fis_pmp(s, port, cmd_fis[1],
+                                     cmd_fis[2], cmd_fis[3]);
         return;
     }
 
     if (cmd_fis[1] & 0x70) {
-        DPRINTF(port, "Reserved flags set in H2D Register FIS."
-                " cmd_fis[0]=%02x cmd_fis[1]=%02x cmd_fis[2]=%02x\n",
-                cmd_fis[0], cmd_fis[1], cmd_fis[2]);
+        trace_handle_reg_h2d_fis_res(s, port, cmd_fis[1],
+                                     cmd_fis[2], cmd_fis[3]);
         return;
     }
 
@@ -1216,12 +1198,12 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
 
     if (s->dev[port].port.ifs[0].status & (BUSY_STAT|DRQ_STAT)) {
         /* Engine currently busy, try again later */
-        DPRINTF(port, "engine busy\n");
+        trace_handle_cmd_busy(s, port);
         return -1;
     }
 
     if (!s->dev[port].lst) {
-        DPRINTF(port, "error: lst not given but cmd handled");
+        trace_handle_cmd_nolist(s, port);
         return -1;
     }
     cmd = get_cmd_header(s, port, slot);
@@ -1231,7 +1213,7 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
     /* The device we are working for */
     ide_state = &s->dev[port].port.ifs[0];
     if (!ide_state->blk) {
-        DPRINTF(port, "error: guest accessed unused port");
+        trace_handle_cmd_badport(s, port);
         return -1;
     }
 
@@ -1240,13 +1222,11 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
     cmd_fis = dma_memory_map(s->as, tbl_addr, &cmd_len,
                              DMA_DIRECTION_FROM_DEVICE);
     if (!cmd_fis) {
-        DPRINTF(port, "error: guest passed us an invalid cmd fis\n");
+        trace_handle_cmd_badfis(s, port);
         return -1;
     } else if (cmd_len != 0x80) {
         ahci_trigger_irq(s, &s->dev[port], PORT_IRQ_HBUS_ERR);
-        DPRINTF(port, "error: dma_memory_map failed: "
-                "(len(%02"PRIx64") != 0x80)\n",
-                cmd_len);
+        trace_handle_cmd_badmap(s, port, cmd_len);
         goto out;
     }
     debug_print_fis(cmd_fis, 0x80);
@@ -1256,9 +1236,8 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
             handle_reg_h2d_fis(s, port, slot, cmd_fis);
             break;
         default:
-            DPRINTF(port, "unknown command cmd_fis[0]=%02x cmd_fis[1]=%02x "
-                          "cmd_fis[2]=%02x\n", cmd_fis[0], cmd_fis[1],
-                          cmd_fis[2]);
+            trace_handle_cmd_unhandled_fis(s, port,
+                                           cmd_fis[0], cmd_fis[1], cmd_fis[2]);
             break;
     }
 
@@ -1299,9 +1278,9 @@ static void ahci_start_transfer(IDEDMA *dma)
         has_sglist = 1;
     }
 
-    DPRINTF(ad->port_no, "%sing %d bytes on %s w/%s sglist\n",
-            is_write ? "writ" : "read", size, is_atapi ? "atapi" : "ata",
-            has_sglist ? "" : "o");
+    trace_ahci_start_transfer(ad->hba, ad->port_no, is_write ? "writ" : "read",
+                              size, is_atapi ? "atapi" : "ata",
+                              has_sglist ? "" : "o");
 
     if (has_sglist && size) {
         if (is_write) {
@@ -1330,7 +1309,7 @@ static void ahci_start_dma(IDEDMA *dma, IDEState *s,
                            BlockCompletionFunc *dma_cb)
 {
     AHCIDevice *ad = DO_UPCAST(AHCIDevice, dma, dma);
-    DPRINTF(ad->port_no, "\n");
+    trace_ahci_start_dma(ad->hba, ad->port_no);
     s->io_buffer_offset = 0;
     dma_cb(s, 0);
 }
@@ -1368,12 +1347,12 @@ static int32_t ahci_dma_prepare_buf(IDEDMA *dma, int32_t limit)
 
     if (ahci_populate_sglist(ad, &s->sg, ad->cur_cmd,
                              limit, s->io_buffer_offset) == -1) {
-        DPRINTF(ad->port_no, "ahci_dma_prepare_buf failed.\n");
+        trace_ahci_dma_prepare_buf_fail(ad->hba, ad->port_no);
         return -1;
     }
     s->io_buffer_size = s->sg.size;
 
-    DPRINTF(ad->port_no, "len=%#x\n", s->io_buffer_size);
+    trace_ahci_dma_prepare_buf(ad->hba, ad->port_no, limit, s->io_buffer_size);
     return s->io_buffer_size;
 }
 
@@ -1409,11 +1388,9 @@ static int ahci_dma_rw_buf(IDEDMA *dma, int is_write)
 
     /* free sglist, update byte count */
     dma_buf_commit(s, l);
-
     s->io_buffer_index += l;
 
-    DPRINTF(ad->port_no, "len=%#x\n", l);
-
+    trace_ahci_dma_rw_buf(ad->hba, ad->port_no, l);
     return 1;
 }
 
@@ -1421,7 +1398,7 @@ static void ahci_cmd_done(IDEDMA *dma)
 {
     AHCIDevice *ad = DO_UPCAST(AHCIDevice, dma, dma);
 
-    DPRINTF(ad->port_no, "cmd done\n");
+    trace_ahci_cmd_done(ad->hba, ad->port_no);
 
     /* update d2h status */
     ahci_write_fis_d2h(ad);
@@ -1505,6 +1482,8 @@ void ahci_reset(AHCIState *s)
     AHCIPortRegs *pr;
     int i;
 
+    trace_ahci_reset(s);
+
     s->control_regs.irqstatus = 0;
     /* AHCI Enable (AE)
      * The implementation of this bit is dependent upon the value of the
@@ -1755,6 +1734,7 @@ static uint64_t allwinner_ahci_mem_read(void *opaque, hwaddr addr,
                                         unsigned size)
 {
     AllwinnerAHCIState *a = opaque;
+    AHCIState *s = &(SYSBUS_AHCI(a)->ahci);
     uint64_t val = a->regs[addr/4];
 
     switch (addr / 4) {
@@ -1765,8 +1745,7 @@ static uint64_t allwinner_ahci_mem_read(void *opaque, hwaddr addr,
         val &= ~(0x1 << 24);
         break;
     }
-    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
-            addr, val, size);
+    trace_allwinner_ahci_mem_read(s, a, addr, val, size);
     return  val;
 }
 
@@ -1774,9 +1753,9 @@ static void allwinner_ahci_mem_write(void *opaque, hwaddr addr,
                                      uint64_t val, unsigned size)
 {
     AllwinnerAHCIState *a = opaque;
+    AHCIState *s = &(SYSBUS_AHCI(a)->ahci);
 
-    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
-            addr, val, size);
+    trace_allwinner_ahci_mem_write(s, a, addr, val, size);
     a->regs[addr/4] = val;
 }
 
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
index 6e33cb3..e1a0457 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -52,4 +52,54 @@ ide_atapi_cmd_read(void *s, const char *method, int lba, int nb_sectors) "IDESta
 ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
 ide_atapi_cmd_read_dma_cb_aio(void *s, int lba, int n) "IDEState: %p; aio read: lba=%d n=%d"
 # Warning: Verbose
-ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
\ No newline at end of file
+ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
+
+# hw/ide/ahci.c
+ahci_port_read(void *s, int port, int offset, uint32_t ret) "ahci(%p)[%d]: port read @ 0x%x: 0x%08x"
+ahci_irq_raise(void *s) "ahci(%p): raise irq"
+ahci_irq_lower(void *s) "ahci(%p): lower irq"
+ahci_check_irq(void *s, uint32_t old, uint32_t new) "ahci(%p): check irq 0x%08x --> 0x%08x"
+
+ahci_port_write(void *s, int port, int offset, uint32_t val) "ahci(%p)[%d]: port write @ 0x%x: 0x%08x"
+ahci_mem_read_32(void *s, uint64_t addr, uint32_t val) "ahci(%p): mem read @ 0x%"PRIx64": 0x%08x"
+ahci_mem_read(void *s, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): read%u @ 0x%"PRIx64": 0x%016"PRIx64
+ahci_mem_write(void *s, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64
+ahci_mem_write_unknown(void *s, uint64_t addr) "ahci(%p): write to unknown register 0x%"PRIx64
+ahci_set_signature(void *s, int port, uint8_t nsector, uint8_t sector, uint8_t lcyl, uint8_t hcyl, uint32_t sig) "ahci(%p)[%d]: set signature sector:0x%02x nsector:0x%02x lcyl:0x%02x hcyl:0x%02x (cumulatively: 0x%08x)"
+ahci_reset_port(void *s, int port) "ahci(%p)[%d]: reset port"
+ahci_unmap_fis_address_null(void *s, int port) "ahci(%p)[%d]: Attempt to unmap NULL FIS address"
+ahci_unmap_clb_address_null(void *s, int port) "ahci(%p)[%d]: Attempt to unmap NULL CLB address"
+ahci_populate_sglist(void *s, int port) "ahci(%p)[%d]"
+ahci_populate_sglist_no_prdtl(void *s, int port, uint16_t opts) "ahci(%p)[%d]: no sg list given by guest: 0x%04x"
+ahci_populate_sglist_no_map(void *s, int port) "ahci(%p)[%d]: DMA mapping failed"
+ahci_populate_sglist_short_map(void *s, int port) "ahci(%p)[%d]: mapped less than expected"
+ahci_populate_sglist_bad_offset(void *s, int port, int off_idx, int64_t off_pos) "ahci(%p)[%d]: Incorrect offset! off_idx: %d, off_pos: %"PRId64
+ncq_finish(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: NCQ transfer finished"
+execute_ncq_command_read(void *s, int port, uint8_t tag, int count, int64_t lba) "ahci(%p)[%d][tag:%d]: NCQ reading %d sectors from LBA %"PRId64
+execute_ncq_command_write(void *s, int port, uint8_t tag, int count, int64_t lba) "ahci(%p)[%d][tag:%d]: NCQ writing %d sectors to LBA %"PRId64
+execute_ncq_command_unsup(void *s, int port, uint8_t tag, uint8_t cmd) "ahci(%p)[%d][tag:%d]: error: unsupported NCQ command (0x%02x) received"
+process_ncq_command_mismatch(void *s, int port, uint8_t tag, uint8_t slot) "ahci(%p)[%d][tag:%d]: Warning: NCQ slot (%d) did not match the given tag"
+process_ncq_command_aux(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Attempt to use NCQ auxiliary fields"
+process_ncq_command_prioicc(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Unsupported attempt to use PRIO/ICC fields"
+process_ncq_command_fua(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Unsupported attempt to use Force Unit Access"
+process_ncq_command_rarc(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Unsupported attempt to use Rebuild Assist"
+process_ncq_command_large(void *s, int port, uint8_t tag, size_t prdtl, size_t size) "ahci(%p)[%d][tag:%d]: Warn: PRDTL (0x%zx) does not match requested size (0x%zx)"
+process_ncq_command(void *s, int port, uint8_t tag, uint8_t cmd, uint64_t lba, uint64_t end) "ahci(%p)[%d][tag:%d]: NCQ op 0x%02x on sectors [%"PRId64",%"PRId64"]"
+handle_reg_h2d_fis_pmp(void *s, int port, char b0, char b1, char b2) "ahci(%p)[%d]: Port Multiplier not supported, FIS: 0x%02x-%02x-%02x"
+handle_reg_h2d_fis_res(void *s, int port, char b0, char b1, char b2) "ahci(%p)[%d]: Reserved flags set in H2D Register FIS, FIS: 0x%02x-%02x-%02x"
+handle_cmd_busy(void *s, int port) "ahci(%p)[%d]: engine busy"
+handle_cmd_nolist(void *s, int port) "ahci(%p)[%d]: handle_cmd called without s->dev[port].lst"
+handle_cmd_badport(void *s, int port) "ahci(%p)[%d]: guest accessed unused port"
+handle_cmd_badfis(void *s, int port) "ahci(%p)[%d]: guest provided an invalid cmd FIS"
+handle_cmd_badmap(void *s, int port, uint64_t len) "ahci(%p)[%d]: dma_memory_map failed, 0x%02"PRIx64" != 0x80"
+handle_cmd_unhandled_fis(void *s, int port, uint8_t b0, uint8_t b1, uint8_t b2) "ahci(%p)[%d]: unhandled FIS type. cmd_fis: 0x%02x-%02x-%02x"
+ahci_start_transfer(void *s, int port, const char *rw, uint32_t size, const char *tgt, const char *sgl) "ahci(%p)[%d]: %sing %d bytes on %s w/%s sglist"
+ahci_start_dma(void *s, int port) "ahci(%p)[%d]: start dma"
+ahci_dma_prepare_buf(void *s, int port, int32_t io_buffer_size, int32_t limit) "ahci(%p)[%d]: prepare buf limit=%"PRId32" prepared=%"PRId32
+ahci_dma_prepare_buf_fail(void *s, int port) "ahci(%p)[%d]: sglist population failed"
+ahci_dma_rw_buf(void *s, int port, int l) "ahci(%p)[%d] len=0x%x"
+ahci_cmd_done(void *s, int port) "ahci(%p)[%d]: cmd done"
+ahci_reset(void *s) "ahci(%p): HBA reset"
+allwinner_ahci_mem_read(void *s, void *a, uint64_t addr, uint64_t val, unsigned size) "ahci(%p): read a=%p addr=0x%"HWADDR_PRIx" val=0x%"PRIx64", size=%d"
+allwinner_ahci_mem_write(void *s, void *a, uint64_t addr, uint64_t val, unsigned size) "ahci(%p): write a=%p addr=0x%"HWADDR_PRIx" val=0x%"PRIx64", size=%d"
+
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (5 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-25 14:00   ` Philippe Mathieu-Daudé
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 8/9] AHCI: pretty-print FIS to buffer instead of stderr John Snow
                   ` (2 subsequent siblings)
  9 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Create a new enum so that we can name the IRQ bits, which will make debugging
them a little nicer if we can print them out. Not handled in this patch, but
this will make it possible to get a nice debug printf detailing exactly which
status bits are set, as it can be multiple at any given time.

As a consequence of this patch, it is no longer possible to set multiple IRQ
codes at once, but nothing was utilizing this ability anyway.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/ahci.c          | 49 ++++++++++++++++++++++++++++++++++++++-----------
 hw/ide/ahci_internal.h | 44 +++++++++++++++++++++++++++++++++++---------
 hw/ide/trace-events    |  2 +-
 3 files changed, 74 insertions(+), 21 deletions(-)

diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
index d5acceb..c5a9b69 100644
--- a/hw/ide/ahci.c
+++ b/hw/ide/ahci.c
@@ -56,6 +56,27 @@ static bool ahci_map_fis_address(AHCIDevice *ad);
 static void ahci_unmap_clb_address(AHCIDevice *ad);
 static void ahci_unmap_fis_address(AHCIDevice *ad);
 
+static const char *AHCIPortIRQ_lookup[AHCI_PORT_IRQ__END] = {
+    [AHCI_PORT_IRQ_BIT_DHRS] = "DHRS",
+    [AHCI_PORT_IRQ_BIT_PSS]  = "PSS",
+    [AHCI_PORT_IRQ_BIT_DSS]  = "DSS",
+    [AHCI_PORT_IRQ_BIT_SDBS] = "SDBS",
+    [AHCI_PORT_IRQ_BIT_UFS]  = "UFS",
+    [AHCI_PORT_IRQ_BIT_DPS]  = "DPS",
+    [AHCI_PORT_IRQ_BIT_PCS]  = "PCS",
+    [AHCI_PORT_IRQ_BIT_DMPS] = "DMPS",
+    [8 ... 21]               = "RESERVED",
+    [AHCI_PORT_IRQ_BIT_PRCS] = "PRCS",
+    [AHCI_PORT_IRQ_BIT_IPMS] = "IPMS",
+    [AHCI_PORT_IRQ_BIT_OFS]  = "OFS",
+    [25]                     = "RESERVED",
+    [AHCI_PORT_IRQ_BIT_INFS] = "INFS",
+    [AHCI_PORT_IRQ_BIT_IFS]  = "IFS",
+    [AHCI_PORT_IRQ_BIT_HBDS] = "HBDS",
+    [AHCI_PORT_IRQ_BIT_HBFS] = "HBFS",
+    [AHCI_PORT_IRQ_BIT_TFES] = "TFES",
+    [AHCI_PORT_IRQ_BIT_CPDS] = "CPDS"
+};
 
 static uint32_t  ahci_port_read(AHCIState *s, int port, int offset)
 {
@@ -170,12 +191,18 @@ static void ahci_check_irq(AHCIState *s)
 }
 
 static void ahci_trigger_irq(AHCIState *s, AHCIDevice *d,
-                             int irq_type)
+                             enum AHCIPortIRQ irqbit)
 {
-    DPRINTF(d->port_no, "trigger irq %#x -> %x\n",
-            irq_type, d->port_regs.irq_mask & irq_type);
+    g_assert(irqbit >= 0 && irqbit < 32);
+    uint32_t irq = 1U << irqbit;
+    uint32_t irqstat = d->port_regs.irq_stat | irq;
 
-    d->port_regs.irq_stat |= irq_type;
+    trace_ahci_trigger_irq(s, d->port_no,
+                           AHCIPortIRQ_lookup[irqbit], irq,
+                           d->port_regs.irq_stat, irqstat,
+                           irqstat & d->port_regs.irq_mask);
+
+    d->port_regs.irq_stat = irqstat;
     ahci_check_irq(s);
 }
 
@@ -718,7 +745,7 @@ static void ahci_write_fis_sdb(AHCIState *s, NCQTransferState *ncq_tfs)
 
     /* Trigger IRQ if interrupt bit is set (which currently, it always is) */
     if (sdb_fis->flags & 0x40) {
-        ahci_trigger_irq(s, ad, PORT_IRQ_SDB_FIS);
+        ahci_trigger_irq(s, ad, AHCI_PORT_IRQ_BIT_SDBS);
     }
 }
 
@@ -761,10 +788,10 @@ static void ahci_write_fis_pio(AHCIDevice *ad, uint16_t len)
         ad->port.ifs[0].status;
 
     if (pio_fis[2] & ERR_STAT) {
-        ahci_trigger_irq(ad->hba, ad, PORT_IRQ_TF_ERR);
+        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_TFES);
     }
 
-    ahci_trigger_irq(ad->hba, ad, PORT_IRQ_PIOS_FIS);
+    ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_PSS);
 }
 
 static bool ahci_write_fis_d2h(AHCIDevice *ad)
@@ -804,10 +831,10 @@ static bool ahci_write_fis_d2h(AHCIDevice *ad)
         ad->port.ifs[0].status;
 
     if (d2h_fis[2] & ERR_STAT) {
-        ahci_trigger_irq(ad->hba, ad, PORT_IRQ_TF_ERR);
+        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_TFES);
     }
 
-    ahci_trigger_irq(ad->hba, ad, PORT_IRQ_D2H_REG_FIS);
+    ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_DHRS);
     return true;
 }
 
@@ -1082,7 +1109,7 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
                      "is smaller than the requested size (0x%zx)",
                      ncq_tfs->sglist.size, size);
         ncq_err(ncq_tfs);
-        ahci_trigger_irq(ad->hba, ad, PORT_IRQ_OVERFLOW);
+        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_OFS);
         return;
     } else if (ncq_tfs->sglist.size != size) {
         trace_process_ncq_command_large(s, port, tag,
@@ -1225,7 +1252,7 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
         trace_handle_cmd_badfis(s, port);
         return -1;
     } else if (cmd_len != 0x80) {
-        ahci_trigger_irq(s, &s->dev[port], PORT_IRQ_HBUS_ERR);
+        ahci_trigger_irq(s, &s->dev[port], AHCI_PORT_IRQ_BIT_HBFS);
         trace_handle_cmd_badmap(s, port, cmd_len);
         goto out;
     }
diff --git a/hw/ide/ahci_internal.h b/hw/ide/ahci_internal.h
index 1e21169..7e67add 100644
--- a/hw/ide/ahci_internal.h
+++ b/hw/ide/ahci_internal.h
@@ -91,6 +91,31 @@
 #define PORT_CMD_ISSUE            0x38 /* command issue */
 #define PORT_RESERVED             0x3c /* reserved */
 
+/* Port interrupt bit descriptors */
+enum AHCIPortIRQ {
+    AHCI_PORT_IRQ_BIT_DHRS = 0,
+    AHCI_PORT_IRQ_BIT_PSS  = 1,
+    AHCI_PORT_IRQ_BIT_DSS  = 2,
+    AHCI_PORT_IRQ_BIT_SDBS = 3,
+    AHCI_PORT_IRQ_BIT_UFS  = 4,
+    AHCI_PORT_IRQ_BIT_DPS  = 5,
+    AHCI_PORT_IRQ_BIT_PCS  = 6,
+    AHCI_PORT_IRQ_BIT_DMPS = 7,
+    /* RESERVED */
+    AHCI_PORT_IRQ_BIT_PRCS = 22,
+    AHCI_PORT_IRQ_BIT_IPMS = 23,
+    AHCI_PORT_IRQ_BIT_OFS  = 24,
+    /* RESERVED */
+    AHCI_PORT_IRQ_BIT_INFS = 26,
+    AHCI_PORT_IRQ_BIT_IFS  = 27,
+    AHCI_PORT_IRQ_BIT_HBDS = 28,
+    AHCI_PORT_IRQ_BIT_HBFS = 29,
+    AHCI_PORT_IRQ_BIT_TFES = 30,
+    AHCI_PORT_IRQ_BIT_CPDS = 31,
+    AHCI_PORT_IRQ__END     = 32
+};
+
+
 /* PORT_IRQ_{STAT,MASK} bits */
 #define PORT_IRQ_COLD_PRES        (1U << 31) /* cold presence detect */
 #define PORT_IRQ_TF_ERR           (1 << 30) /* task file error */
@@ -98,18 +123,19 @@
 #define PORT_IRQ_HBUS_DATA_ERR    (1 << 28) /* host bus data error */
 #define PORT_IRQ_IF_ERR           (1 << 27) /* interface fatal error */
 #define PORT_IRQ_IF_NONFATAL      (1 << 26) /* interface non-fatal error */
+                                            /* reserved */
 #define PORT_IRQ_OVERFLOW         (1 << 24) /* xfer exhausted available S/G */
 #define PORT_IRQ_BAD_PMP          (1 << 23) /* incorrect port multiplier */
-
 #define PORT_IRQ_PHYRDY           (1 << 22) /* PhyRdy changed */
-#define PORT_IRQ_DEV_ILCK         (1 << 7) /* device interlock */
-#define PORT_IRQ_CONNECT          (1 << 6) /* port connect change status */
-#define PORT_IRQ_SG_DONE          (1 << 5) /* descriptor processed */
-#define PORT_IRQ_UNK_FIS          (1 << 4) /* unknown FIS rx'd */
-#define PORT_IRQ_SDB_FIS          (1 << 3) /* Set Device Bits FIS rx'd */
-#define PORT_IRQ_DMAS_FIS         (1 << 2) /* DMA Setup FIS rx'd */
-#define PORT_IRQ_PIOS_FIS         (1 << 1) /* PIO Setup FIS rx'd */
-#define PORT_IRQ_D2H_REG_FIS      (1 << 0) /* D2H Register FIS rx'd */
+                                            /* reserved */
+#define PORT_IRQ_DEV_ILCK         (1 << 7)  /* device interlock */
+#define PORT_IRQ_CONNECT          (1 << 6)  /* port connect change status */
+#define PORT_IRQ_SG_DONE          (1 << 5)  /* descriptor processed */
+#define PORT_IRQ_UNK_FIS          (1 << 4)  /* unknown FIS rx'd */
+#define PORT_IRQ_SDB_FIS          (1 << 3)  /* Set Device Bits FIS rx'd */
+#define PORT_IRQ_DMAS_FIS         (1 << 2)  /* DMA Setup FIS rx'd */
+#define PORT_IRQ_PIOS_FIS         (1 << 1)  /* PIO Setup FIS rx'd */
+#define PORT_IRQ_D2H_REG_FIS      (1 << 0)  /* D2H Register FIS rx'd */
 
 #define PORT_IRQ_FREEZE           (PORT_IRQ_HBUS_ERR | PORT_IRQ_IF_ERR |   \
                                    PORT_IRQ_CONNECT | PORT_IRQ_PHYRDY |    \
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
index e1a0457..5b321e1 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -59,7 +59,7 @@ ahci_port_read(void *s, int port, int offset, uint32_t ret) "ahci(%p)[%d]: port
 ahci_irq_raise(void *s) "ahci(%p): raise irq"
 ahci_irq_lower(void *s) "ahci(%p): lower irq"
 ahci_check_irq(void *s, uint32_t old, uint32_t new) "ahci(%p): check irq 0x%08x --> 0x%08x"
-
+ahci_trigger_irq(void *s, int port, const char *name, uint32_t val, uint32_t old, uint32_t new, uint32_t effective) "ahci(%p)[%d]: trigger irq +%s (0x%08x); irqstat: 0x%08x --> 0x%08x; effective: 0x%08x"
 ahci_port_write(void *s, int port, int offset, uint32_t val) "ahci(%p)[%d]: port write @ 0x%x: 0x%08x"
 ahci_mem_read_32(void *s, uint64_t addr, uint32_t val) "ahci(%p): mem read @ 0x%"PRIx64": 0x%08x"
 ahci_mem_read(void *s, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): read%u @ 0x%"PRIx64": 0x%016"PRIx64
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 8/9] AHCI: pretty-print FIS to buffer instead of stderr
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (6 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro John Snow
  2017-08-09  1:17 ` [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing no-reply
  9 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

The current FIS printing routines dump the FIS to screen. adjust this
such that it dumps to buffer instead, then use this ability to have
FIS dump mechanisms via trace-events instead of compiled defines.

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/ahci.c       | 54 +++++++++++++++++++++++++++++++++++++++++++----------
 hw/ide/trace-events |  3 +++
 2 files changed, 47 insertions(+), 10 deletions(-)

diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
index c5a9b69..1a4d4db 100644
--- a/hw/ide/ahci.c
+++ b/hw/ide/ahci.c
@@ -644,20 +644,45 @@ static void ahci_reset_port(AHCIState *s, int port)
     ahci_init_d2h(d);
 }
 
-static void debug_print_fis(uint8_t *fis, int cmd_len)
+/* Buffer pretty output based on a raw FIS structure. */
+static void ahci_pretty_buffer_fis(uint8_t *fis, int cmd_len, char **out)
 {
-#if DEBUG_AHCI
+    size_t bufsize;
+    char *pbuf;
+    char *pptr;
+    size_t lines = DIV_ROUND_UP(cmd_len, 16);
+    const char *preamble = "FIS:";
     int i;
 
-    fprintf(stderr, "fis:");
+    /* Total amount of memory to store FISes in HBA memory */
+    g_assert_cmpint(cmd_len, <=, 0x100);
+    g_assert(out);
+
+    /* Printed like:
+     * FIS:\n
+     * 0x00: 00 11 22 33 44 55 66 77 88 99 aa bb cc dd ee \n
+     * 0x10: ff \n
+     * \0
+     *
+     * Four bytes for the preamble, seven for each line prefix (including a
+     * newline to start a new line), three bytes for each source byte,
+     * a trailing newline and a terminal null byte.
+     */
+
+    bufsize = strlen(preamble) + ((6 + 1) * lines) + (3 * cmd_len) + 1 + 1;
+    pbuf = g_malloc(bufsize);
+    pptr = pbuf;
+    pptr += sprintf(pptr, "%s", preamble);
     for (i = 0; i < cmd_len; i++) {
         if ((i & 0xf) == 0) {
-            fprintf(stderr, "\n%02x:",i);
+            pptr += sprintf(pptr, "\n0x%02x: ", i);
         }
-        fprintf(stderr, "%02x ",fis[i]);
+        pptr += sprintf(pptr, "%02x ", fis[i]);
     }
-    fprintf(stderr, "\n");
-#endif
+    pptr += sprintf(pptr, "\n");
+    pptr += 1; /* \0 */
+    g_assert(pbuf + bufsize == pptr);
+    *out = pbuf;
 }
 
 static bool ahci_map_fis_address(AHCIDevice *ad)
@@ -1201,7 +1226,12 @@ static void handle_reg_h2d_fis(AHCIState *s, int port,
      * table to ide_state->io_buffer */
     if (opts & AHCI_CMD_ATAPI) {
         memcpy(ide_state->io_buffer, &cmd_fis[AHCI_COMMAND_TABLE_ACMD], 0x10);
-        debug_print_fis(ide_state->io_buffer, 0x10);
+        if (TRACE_HANDLE_REG_H2D_FIS_DUMP_ENABLED) {
+            char *pretty_fis;
+            ahci_pretty_buffer_fis(ide_state->io_buffer, 0x10, &pretty_fis);
+            trace_handle_reg_h2d_fis_dump(s, port, pretty_fis);
+            g_free(pretty_fis);
+        }
         s->dev[port].done_atapi_packet = false;
         /* XXX send PIO setup FIS */
     }
@@ -1256,8 +1286,12 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
         trace_handle_cmd_badmap(s, port, cmd_len);
         goto out;
     }
-    debug_print_fis(cmd_fis, 0x80);
-
+    if (TRACE_HANDLE_CMD_FIS_DUMP_ENABLED) {
+        char *pretty_fis;
+        ahci_pretty_buffer_fis(cmd_fis, 0x80, &pretty_fis);
+        trace_handle_cmd_fis_dump(s, port, pretty_fis);
+        g_free(pretty_fis);
+    }
     switch (cmd_fis[0]) {
         case SATA_FIS_TYPE_REGISTER_H2D:
             handle_reg_h2d_fis(s, port, slot, cmd_fis);
diff --git a/hw/ide/trace-events b/hw/ide/trace-events
index 5b321e1..082e804 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -103,3 +103,6 @@ ahci_reset(void *s) "ahci(%p): HBA reset"
 allwinner_ahci_mem_read(void *s, void *a, uint64_t addr, uint64_t val, unsigned size) "ahci(%p): read a=%p addr=0x%"HWADDR_PRIx" val=0x%"PRIx64", size=%d"
 allwinner_ahci_mem_write(void *s, void *a, uint64_t addr, uint64_t val, unsigned size) "ahci(%p): write a=%p addr=0x%"HWADDR_PRIx" val=0x%"PRIx64", size=%d"
 
+# Warning: Verbose
+handle_reg_h2d_fis_dump(void *s, int port, char *fis) "ahci(%p)[%d]: %s"
+handle_cmd_fis_dump(void *s, int port, char *fis) "ahci(%p)[%d]: %s"
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (7 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 8/9] AHCI: pretty-print FIS to buffer instead of stderr John Snow
@ 2017-08-08 18:33 ` John Snow
  2017-08-25 13:48   ` Philippe Mathieu-Daudé
  2017-08-09  1:17 ` [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing no-reply
  9 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-08 18:33 UTC (permalink / raw)
  To: qemu-block; +Cc: qemu-devel, John Snow

Signed-off-by: John Snow <jsnow@redhat.com>
---
 hw/ide/ahci.c | 9 ---------
 1 file changed, 9 deletions(-)

diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
index 1a4d4db..ce2010c 100644
--- a/hw/ide/ahci.c
+++ b/hw/ide/ahci.c
@@ -34,17 +34,8 @@
 #include "hw/ide/pci.h"
 #include "hw/ide/ahci_internal.h"
 
-#define DEBUG_AHCI 0
 #include "trace.h"
 
-#define DPRINTF(port, fmt, ...) \
-do { \
-    if (DEBUG_AHCI) { \
-        fprintf(stderr, "ahci: %s: [%d] ", __func__, port); \
-        fprintf(stderr, fmt, ## __VA_ARGS__); \
-    } \
-} while (0)
-
 static void check_cmd(AHCIState *s, int port);
 static int handle_cmd(AHCIState *s, int port, uint8_t slot);
 static void ahci_reset_port(AHCIState *s, int port);
-- 
2.9.4

^ permalink raw reply related	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system John Snow
@ 2017-08-08 20:00   ` Eric Blake
  2017-08-08 20:12     ` John Snow
                       ` (2 more replies)
  2017-08-25 13:33   ` Philippe Mathieu-Daudé
  1 sibling, 3 replies; 36+ messages in thread
From: Eric Blake @ 2017-08-08 20:00 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 1828 bytes --]

On 08/08/2017 01:32 PM, John Snow wrote:
> Out with the old, in with the new.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---

>  hw/ide/piix.c             | 11 ++++----
>  hw/ide/trace-events       | 33 ++++++++++++++++++++++++
>  hw/ide/via.c              | 10 +++-----

Hmm - should we tweak scripts/git.orderfile to prioritize trace-events
over .c files? Then again, right now it prioritizes all .c files before
anything that didn't match, so that things like trace-events will at
least avoid falling in the middle of a patch if you use the project's
orderfile.

> +++ b/hw/ide/cmd646.c
> @@ -32,6 +32,7 @@
>  #include "sysemu/dma.h"
>  
>  #include "hw/ide/pci.h"
> +#include "trace.h"
>  
>  /* CMD646 specific */
>  #define CFR		0x50
> @@ -195,9 +196,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>          val = 0xff;
>          break;
>      }
> -#ifdef DEBUG_IDE
> -    printf("bmdma: readb " TARGET_FMT_plx " : 0x%02x\n", addr, val);
> -#endif

Yay for killing code prone to bitrot.

> +++ b/hw/ide/core.c

> @@ -2054,18 +2044,18 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>      }

>      hob = 0;
> -    switch(addr) {
> +    switch(reg_num) {

Worth fixing the style to put space after switch while touching this?

> +++ b/hw/ide/trace-events
> @@ -0,0 +1,33 @@
> +# See docs/devel/tracing.txt for syntax documentation.
> +
> +# hw/ide/core.c

> +
> +# hw/ide/pci.c
> +bmdma_reset(void) ""

An empty trace? Do all the backends support it?

> +# hw/ide/cmd646.c

Worth sorting the sections by filename?

Whether or not you tweak based on my nits,

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing John Snow
@ 2017-08-08 20:05   ` Eric Blake
  2017-08-25 13:43   ` Philippe Mathieu-Daudé
  1 sibling, 0 replies; 36+ messages in thread
From: Eric Blake @ 2017-08-08 20:05 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 778 bytes --]

On 08/08/2017 01:32 PM, John Snow wrote:
> Name the registers for tracing purposes.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  hw/ide/core.c       | 88 +++++++++++++++++++++++++++++++++++++++++------------
>  hw/ide/trace-events |  4 +--
>  2 files changed, 70 insertions(+), 22 deletions(-)

> -    case 1:
> -	ide_clear_hob(bus);
> +    case ATA_IOPORT_WR_FEATURES:
> +        ide_clear_hob(bus);

Cool, fixing tab damage in the process.

I did a similar improvement to NBD traces, and it's definitely worth it
to have traces include names in addition to numbers.

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports John Snow
@ 2017-08-08 20:10   ` Eric Blake
  2017-08-08 20:17     ` John Snow
  2017-08-08 20:30   ` Eric Blake
  1 sibling, 1 reply; 36+ messages in thread
From: Eric Blake @ 2017-08-08 20:10 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 831 bytes --]

On 08/08/2017 01:33 PM, John Snow wrote:
> To be used sparingly, but still interesting in the case of small
> firmwares designed to reproduce bugs in QEMU IDE.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  hw/ide/core.c | 12 +++++++++++-
>  1 file changed, 11 insertions(+), 1 deletion(-)
> 
> diff --git a/hw/ide/core.c b/hw/ide/core.c
> index 6235bdf..29848ff 100644
> --- a/hw/ide/core.c
> +++ b/hw/ide/core.c
> @@ -2251,6 +2251,8 @@ void ide_data_writew(void *opaque, uint32_t addr, uint32_t val)
>      IDEState *s = idebus_active_if(bus);
>      uint8_t *p;
>  
> +    trace_ide_data_writew(addr, val, bus, s);

Umm, where's the trace-events addition for this?

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-08 20:00   ` Eric Blake
@ 2017-08-08 20:12     ` John Snow
  2017-08-08 23:20     ` Philippe Mathieu-Daudé
  2017-08-22 19:03     ` John Snow
  2 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 20:12 UTC (permalink / raw)
  To: Eric Blake, qemu-block; +Cc: qemu-devel



On 08/08/2017 04:00 PM, Eric Blake wrote:
> On 08/08/2017 01:32 PM, John Snow wrote:
>> Out with the old, in with the new.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
> 
>>  hw/ide/piix.c             | 11 ++++----
>>  hw/ide/trace-events       | 33 ++++++++++++++++++++++++
>>  hw/ide/via.c              | 10 +++-----
> 
> Hmm - should we tweak scripts/git.orderfile to prioritize trace-events
> over .c files? Then again, right now it prioritizes all .c files before
> anything that didn't match, so that things like trace-events will at
> least avoid falling in the middle of a patch if you use the project's
> orderfile.
> 

Sorry!

>> +++ b/hw/ide/cmd646.c
>> @@ -32,6 +32,7 @@
>>  #include "sysemu/dma.h"
>>  
>>  #include "hw/ide/pci.h"
>> +#include "trace.h"
>>  
>>  /* CMD646 specific */
>>  #define CFR		0x50
>> @@ -195,9 +196,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>>          val = 0xff;
>>          break;
>>      }
>> -#ifdef DEBUG_IDE
>> -    printf("bmdma: readb " TARGET_FMT_plx " : 0x%02x\n", addr, val);
>> -#endif
> 
> Yay for killing code prone to bitrot.
> 

Yup, seeya later.

>> +++ b/hw/ide/core.c
> 
>> @@ -2054,18 +2044,18 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>>      }
> 
>>      hob = 0;
>> -    switch(addr) {
>> +    switch(reg_num) {
> 
> Worth fixing the style to put space after switch while touching this?
> 

Yes.

>> +++ b/hw/ide/trace-events
>> @@ -0,0 +1,33 @@
>> +# See docs/devel/tracing.txt for syntax documentation.
>> +
>> +# hw/ide/core.c
> 
>> +
>> +# hw/ide/pci.c
>> +bmdma_reset(void) ""
> 
> An empty trace? Do all the backends support it?
> 

Oh, I don't know... I guess I can just repeat the function name in here,
or add something arbitrary.

>> +# hw/ide/cmd646.c
> 
> Worth sorting the sections by filename?
> 

Oh, you mean alphabetically?

I'd like to keep the BMDMA HBA tracers near each other, but otherwise I
can, yes.

> Whether or not you tweak based on my nits,
> 
> Reviewed-by: Eric Blake <eblake@redhat.com>
> 

There's likely to be many nits, so I'll accept all the critique.

John

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports
  2017-08-08 20:10   ` Eric Blake
@ 2017-08-08 20:17     ` John Snow
  0 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 20:17 UTC (permalink / raw)
  To: Eric Blake, qemu-block; +Cc: qemu-devel



On 08/08/2017 04:10 PM, Eric Blake wrote:
> On 08/08/2017 01:33 PM, John Snow wrote:
>> To be used sparingly, but still interesting in the case of small
>> firmwares designed to reproduce bugs in QEMU IDE.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>  hw/ide/core.c | 12 +++++++++++-
>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>
>> diff --git a/hw/ide/core.c b/hw/ide/core.c
>> index 6235bdf..29848ff 100644
>> --- a/hw/ide/core.c
>> +++ b/hw/ide/core.c
>> @@ -2251,6 +2251,8 @@ void ide_data_writew(void *opaque, uint32_t addr, uint32_t val)
>>      IDEState *s = idebus_active_if(bus);
>>      uint8_t *p;
>>  
>> +    trace_ide_data_writew(addr, val, bus, s);
> 
> Umm, where's the trace-events addition for this?
> 

Accidentally traveled forward through time to patch 04.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports John Snow
  2017-08-08 20:10   ` Eric Blake
@ 2017-08-08 20:30   ` Eric Blake
  2017-08-08 20:36     ` Eric Blake
  2017-08-08 20:44     ` John Snow
  1 sibling, 2 replies; 36+ messages in thread
From: Eric Blake @ 2017-08-08 20:30 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 603 bytes --]

On 08/08/2017 01:33 PM, John Snow wrote:
> To be used sparingly, but still interesting in the case of small
> firmwares designed to reproduce bugs in QEMU IDE.

Is that because the trace would fire so frequently in normal usage that
it will drown the user in noise?

> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  hw/ide/core.c | 12 +++++++++++-
>  1 file changed, 11 insertions(+), 1 deletion(-)
> 

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports
  2017-08-08 20:30   ` Eric Blake
@ 2017-08-08 20:36     ` Eric Blake
  2017-08-08 20:44     ` John Snow
  1 sibling, 0 replies; 36+ messages in thread
From: Eric Blake @ 2017-08-08 20:36 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 788 bytes --]

On 08/08/2017 03:30 PM, Eric Blake wrote:
> On 08/08/2017 01:33 PM, John Snow wrote:
>> To be used sparingly, but still interesting in the case of small
>> firmwares designed to reproduce bugs in QEMU IDE.
> 
> Is that because the trace would fire so frequently in normal usage that
> it will drown the user in noise?
> 
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>  hw/ide/core.c | 12 +++++++++++-
>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>
> 
> Reviewed-by: Eric Blake <eblake@redhat.com>

Argh. I had two compose windows open at once. R-b is only valid if you
fix the time-traveling trace-events changes :)

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports
  2017-08-08 20:30   ` Eric Blake
  2017-08-08 20:36     ` Eric Blake
@ 2017-08-08 20:44     ` John Snow
  1 sibling, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-08 20:44 UTC (permalink / raw)
  To: Eric Blake, qemu-block; +Cc: qemu-devel



On 08/08/2017 04:30 PM, Eric Blake wrote:
> On 08/08/2017 01:33 PM, John Snow wrote:
>> To be used sparingly, but still interesting in the case of small
>> firmwares designed to reproduce bugs in QEMU IDE.
> 
> Is that because the trace would fire so frequently in normal usage that
> it will drown the user in noise?
> 

Yeah, and it's of little use for a real guest due to the volume and
relative unimportance of what that data actually is

>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>  hw/ide/core.c | 12 +++++++++++-
>>  1 file changed, 11 insertions(+), 1 deletion(-)
>>
> 
> Reviewed-by: Eric Blake <eblake@redhat.com>
> 

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events John Snow
@ 2017-08-08 20:59   ` Eric Blake
  2017-08-28 23:43     ` John Snow
  0 siblings, 1 reply; 36+ messages in thread
From: Eric Blake @ 2017-08-08 20:59 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

[-- Attachment #1: Type: text/plain, Size: 2115 bytes --]

On 08/08/2017 01:33 PM, John Snow wrote:
> Goodbye, printfs.
> Hello, fancy printfs.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>  hw/ide/atapi.c            | 64 +++++++++++++++++------------------------------
>  hw/ide/trace-events       | 19 ++++++++++++++
>  include/hw/ide/internal.h |  1 -
>  3 files changed, 42 insertions(+), 42 deletions(-)

> @@ -1330,16 +1310,18 @@ void ide_atapi_cmd(IDEState *s)
>      uint8_t *buf = s->io_buffer;
>      const struct AtapiCmd *cmd = &atapi_cmd_table[s->io_buffer[0]];
>  
> -#ifdef DEBUG_IDE_ATAPI
> -    {
> +    trace_ide_atapi_cmd(s, s->io_buffer[0]);
> +
> +    if (TRACE_IDE_ATAPI_CMD_PACKET_ENABLED) {
> +        /* Each pretty-printed byte needs two bytes and a space; */
> +        char *ppacket = g_malloc(ATAPI_PACKET_SIZE * 3 + 1);

Nice use of an extra conditional to make a pretty trace without the
overhead when tracing is off.  (Oh yeah, you asked me on IRC how to do
it, and I pointed to commit bd6952a3 as the example)


> +++ b/hw/ide/trace-events
> @@ -6,6 +6,10 @@ ide_ioport_read(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s
>  ide_ioport_write(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"

Wouldn't it be nice if our trace generator would let us line-wrap?

> +# Warning: Verbose

Cute.  Should you also add it to the ide_data_* traces, per the commit
message in 3/9?

> +ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
> \ No newline at end of file

Umm, that should be fixed (I know that 'diff' uses both / and \ to
differentiate whether it was the pre- or post-patch version that had the
issue, but never remember which is which - so the fix may be in an
earlier patch).  Also fix the trace-events rebase for 3/9; with that,
you can add

Reviewed-by: Eric Blake <eblake@redhat.com>

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3266
Virtualization:  qemu.org | libvirt.org


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 619 bytes --]

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-08 20:00   ` Eric Blake
  2017-08-08 20:12     ` John Snow
@ 2017-08-08 23:20     ` Philippe Mathieu-Daudé
  2017-08-22 19:03     ` John Snow
  2 siblings, 0 replies; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-08 23:20 UTC (permalink / raw)
  To: Eric Blake, John Snow, qemu-block; +Cc: qemu-devel

On 08/08/2017 05:00 PM, Eric Blake wrote:
> On 08/08/2017 01:32 PM, John Snow wrote:
>> Out with the old, in with the new.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
> 
>>   hw/ide/piix.c             | 11 ++++----
>>   hw/ide/trace-events       | 33 ++++++++++++++++++++++++
>>   hw/ide/via.c              | 10 +++-----
> 
> Hmm - should we tweak scripts/git.orderfile to prioritize trace-events
> over .c files? Then again, right now it prioritizes all .c files before
> anything that didn't match, so that things like trace-events will at
> least avoid falling in the middle of a patch if you use the project's
> orderfile.

It sounds like a good idea, although I'd rather prioritize .c, having 
trace-events at bottom. At least we can agree about top-to-bottom 
scripting here :)

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing
  2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
                   ` (8 preceding siblings ...)
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro John Snow
@ 2017-08-09  1:17 ` no-reply
  9 siblings, 0 replies; 36+ messages in thread
From: no-reply @ 2017-08-09  1:17 UTC (permalink / raw)
  To: jsnow; +Cc: famz, qemu-block, qemu-devel

Hi,

This series seems to have some coding style problems. See output below for
more information:

Message-id: 20170808183306.27474-1-jsnow@redhat.com
Subject: [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing
Type: series

=== TEST SCRIPT BEGIN ===
#!/bin/bash

BASE=base
n=1
total=$(git log --oneline $BASE.. | wc -l)
failed=0

git config --local diff.renamelimit 0
git config --local diff.renames True

commits="$(git log --format=%H --reverse $BASE..)"
for c in $commits; do
    echo "Checking PATCH $n/$total: $(git log -n 1 --format=%s $c)..."
    if ! git show $c --format=email | ./scripts/checkpatch.pl --mailback -; then
        failed=1
        echo
    fi
    n=$((n+1))
done

exit $failed
=== TEST SCRIPT END ===

Updating 3c8cf5a9c21ff8782164d1def7f44bd888713384
Switched to a new branch 'test'
56439344ef AHCI: remove DPRINTF macro
6ad85afba9 AHCI: pretty-print FIS to buffer instead of stderr
dfcd58be6d AHCI: Rework IRQ constants
77feb08d1d AHCI: Replace DPRINTF with trace-events
5657a4914e IDE: replace DEBUG_AIO with trace events
7708ba0158 ATAPI: Replace DEBUG_IDE_ATAPI with tracing events
c007da81b2 IDE: add tracing for data ports
07cc43a5ff IDE: Add register hints to tracing
a5a7b507be IDE: replace DEBUG_IDE with tracing system

=== OUTPUT BEGIN ===
Checking PATCH 1/9: IDE: replace DEBUG_IDE with tracing system...
ERROR: spaces required around that '|' (ctx:VxV)
#139: FILE: hw/ide/core.c:1189:
+    if (reg_num != 7 && (s->status & (BUSY_STAT|DRQ_STAT))) {
                                                ^

ERROR: space required before the open parenthesis '('
#144: FILE: hw/ide/core.c:1193:
+    switch(reg_num) {

ERROR: space required before the open parenthesis '('
#191: FILE: hw/ide/core.c:2058:
+    switch(reg_num) {

total: 3 errors, 0 warnings, 335 lines checked

Your patch has style problems, please review.  If any of these errors
are false positives report them to the maintainer, see
CHECKPATCH in MAINTAINERS.

Checking PATCH 2/9: IDE: Add register hints to tracing...
Checking PATCH 3/9: IDE: add tracing for data ports...
Checking PATCH 4/9: ATAPI: Replace DEBUG_IDE_ATAPI with tracing events...
Checking PATCH 5/9: IDE: replace DEBUG_AIO with trace events...
Checking PATCH 6/9: AHCI: Replace DPRINTF with trace-events...
ERROR: Hex numbers must be prefixed with '0x'
#543: FILE: hw/ide/trace-events:88:
+handle_reg_h2d_fis_pmp(void *s, int port, char b0, char b1, char b2) "ahci(%p)[%d]: Port Multiplier not supported, FIS: 0x%02x-%02x-%02x"

ERROR: Hex numbers must be prefixed with '0x'
#544: FILE: hw/ide/trace-events:89:
+handle_reg_h2d_fis_res(void *s, int port, char b0, char b1, char b2) "ahci(%p)[%d]: Reserved flags set in H2D Register FIS, FIS: 0x%02x-%02x-%02x"

ERROR: Hex numbers must be prefixed with '0x'
#550: FILE: hw/ide/trace-events:95:
+handle_cmd_unhandled_fis(void *s, int port, uint8_t b0, uint8_t b1, uint8_t b2) "ahci(%p)[%d]: unhandled FIS type. cmd_fis: 0x%02x-%02x-%02x"

total: 3 errors, 0 warnings, 500 lines checked

Your patch has style problems, please review.  If any of these errors
are false positives report them to the maintainer, see
CHECKPATCH in MAINTAINERS.

Checking PATCH 7/9: AHCI: Rework IRQ constants...
Checking PATCH 8/9: AHCI: pretty-print FIS to buffer instead of stderr...
ERROR: Use g_assert or g_assert_not_reached
#35: FILE: hw/ide/ahci.c:658:
+    g_assert_cmpint(cmd_len, <=, 0x100);

total: 1 errors, 0 warnings, 85 lines checked

Your patch has style problems, please review.  If any of these errors
are false positives report them to the maintainer, see
CHECKPATCH in MAINTAINERS.

Checking PATCH 9/9: AHCI: remove DPRINTF macro...
=== OUTPUT END ===

Test command exited with code: 1


---
Email generated automatically by Patchew [http://patchew.org/].
Please send your feedback to patchew-devel@freelists.org

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-08 20:00   ` Eric Blake
  2017-08-08 20:12     ` John Snow
  2017-08-08 23:20     ` Philippe Mathieu-Daudé
@ 2017-08-22 19:03     ` John Snow
  2 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-22 19:03 UTC (permalink / raw)
  To: Eric Blake, qemu-block; +Cc: qemu-devel



On 08/08/2017 04:00 PM, Eric Blake wrote:
> On 08/08/2017 01:32 PM, John Snow wrote:
>> Out with the old, in with the new.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
> 
>>  hw/ide/piix.c             | 11 ++++----
>>  hw/ide/trace-events       | 33 ++++++++++++++++++++++++
>>  hw/ide/via.c              | 10 +++-----
> 
> Hmm - should we tweak scripts/git.orderfile to prioritize trace-events
> over .c files? Then again, right now it prioritizes all .c files before
> anything that didn't match, so that things like trace-events will at
> least avoid falling in the middle of a patch if you use the project's
> orderfile.
> 
>> +++ b/hw/ide/cmd646.c
>> @@ -32,6 +32,7 @@
>>  #include "sysemu/dma.h"
>>  
>>  #include "hw/ide/pci.h"
>> +#include "trace.h"
>>  
>>  /* CMD646 specific */
>>  #define CFR		0x50
>> @@ -195,9 +196,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>>          val = 0xff;
>>          break;
>>      }
>> -#ifdef DEBUG_IDE
>> -    printf("bmdma: readb " TARGET_FMT_plx " : 0x%02x\n", addr, val);
>> -#endif
> 
> Yay for killing code prone to bitrot.
> 
>> +++ b/hw/ide/core.c
> 
>> @@ -2054,18 +2044,18 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>>      }
> 
>>      hob = 0;
>> -    switch(addr) {
>> +    switch(reg_num) {
> 
> Worth fixing the style to put space after switch while touching this?
> 
>> +++ b/hw/ide/trace-events
>> @@ -0,0 +1,33 @@
>> +# See docs/devel/tracing.txt for syntax documentation.
>> +
>> +# hw/ide/core.c
> 
>> +
>> +# hw/ide/pci.c
>> +bmdma_reset(void) ""
> 
> An empty trace? Do all the backends support it?
> 

Not the first instance of this, so I'm assuming yes.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events John Snow
@ 2017-08-25 13:17   ` Philippe Mathieu-Daudé
  2017-08-29  0:15     ` John Snow
  0 siblings, 1 reply; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-25 13:17 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

Hi John,

On 08/08/2017 03:33 PM, John Snow wrote:
> There are a few hangers-on that will be dealt with individually
> in forthcoming patches.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>   hw/ide/ahci.c       | 157 +++++++++++++++++++++++-----------------------------
>   hw/ide/trace-events |  52 ++++++++++++++++-
>   2 files changed, 119 insertions(+), 90 deletions(-)
> 
> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
> index 406a1b5..d5acceb 100644
> --- a/hw/ide/ahci.c
> +++ b/hw/ide/ahci.c
> @@ -35,6 +35,7 @@
>   #include "hw/ide/ahci_internal.h"
>   
>   #define DEBUG_AHCI 0
> +#include "trace.h"
>   
>   #define DPRINTF(port, fmt, ...) \
>   do { \
> @@ -114,9 +115,9 @@ static uint32_t  ahci_port_read(AHCIState *s, int port, int offset)
>       default:
>           val = 0;
>       }
> -    DPRINTF(port, "offset: 0x%x val: 0x%x\n", offset, val);
> -    return val;
>   
> +    trace_ahci_port_read(s, port, offset, val);
> +    return val;
>   }
>   
>   static void ahci_irq_raise(AHCIState *s, AHCIDevice *dev)
> @@ -125,7 +126,7 @@ static void ahci_irq_raise(AHCIState *s, AHCIDevice *dev)
>       PCIDevice *pci_dev = (PCIDevice *) object_dynamic_cast(OBJECT(dev_state),
>                                                              TYPE_PCI_DEVICE);
>   
> -    DPRINTF(0, "raise irq\n");
> +    trace_ahci_irq_raise(s);
>   
>       if (pci_dev && msi_enabled(pci_dev)) {
>           msi_notify(pci_dev, 0);
> @@ -140,7 +141,7 @@ static void ahci_irq_lower(AHCIState *s, AHCIDevice *dev)
>       PCIDevice *pci_dev = (PCIDevice *) object_dynamic_cast(OBJECT(dev_state),
>                                                              TYPE_PCI_DEVICE);
>   
> -    DPRINTF(0, "lower irq\n");
> +    trace_ahci_irq_lower(s);
>   
>       if (!pci_dev || !msi_enabled(pci_dev)) {
>           qemu_irq_lower(s->irq);
> @@ -150,8 +151,7 @@ static void ahci_irq_lower(AHCIState *s, AHCIDevice *dev)
>   static void ahci_check_irq(AHCIState *s)
>   {
>       int i;
> -
> -    DPRINTF(-1, "check irq %#x\n", s->control_regs.irqstatus);
> +    uint32_t old_irq = s->control_regs.irqstatus;
>   
>       s->control_regs.irqstatus = 0;
>       for (i = 0; i < s->ports; i++) {
> @@ -160,7 +160,7 @@ static void ahci_check_irq(AHCIState *s)
>               s->control_regs.irqstatus |= (1 << i);
>           }
>       }
> -
> +    trace_ahci_check_irq(s, old_irq, s->control_regs.irqstatus);
>       if (s->control_regs.irqstatus &&
>           (s->control_regs.ghc & HOST_CTL_IRQ_EN)) {
>               ahci_irq_raise(s, NULL);
> @@ -240,7 +240,7 @@ static void  ahci_port_write(AHCIState *s, int port, int offset, uint32_t val)
>   {
>       AHCIPortRegs *pr = &s->dev[port].port_regs;
>   
> -    DPRINTF(port, "offset: 0x%x val: 0x%x\n", offset, val);
> +    trace_ahci_port_write(s, port, offset, val);
>       switch (offset) {
>           case PORT_LST_ADDR:
>               pr->lst_addr = val;
> @@ -341,8 +341,6 @@ static uint64_t ahci_mem_read_32(void *opaque, hwaddr addr)
>               val = s->control_regs.version;
>               break;
>           }
> -
> -        DPRINTF(-1, "(addr 0x%08X), val 0x%08X\n", (unsigned) addr, val);
>       } else if ((addr >= AHCI_PORT_REGS_START_ADDR) &&
>                  (addr < (AHCI_PORT_REGS_START_ADDR +
>                   (s->ports * AHCI_PORT_ADDR_OFFSET_LEN)))) {
> @@ -350,6 +348,7 @@ static uint64_t ahci_mem_read_32(void *opaque, hwaddr addr)
>                                addr & AHCI_PORT_ADDR_OFFSET_MASK);
>       }
>   
> +    trace_ahci_mem_read_32(s, addr, val);
>       return val;
>   }
>   
> @@ -379,8 +378,7 @@ static uint64_t ahci_mem_read(void *opaque, hwaddr addr, unsigned size)
>           val = (hi << 32 | lo) >> (ofst * 8);
>       }
>   
> -    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
> -            addr, val, size);
> +    trace_ahci_mem_read(opaque, size, addr, val);
>       return val;
>   }
>   
> @@ -390,8 +388,7 @@ static void ahci_mem_write(void *opaque, hwaddr addr,
>   {
>       AHCIState *s = opaque;
>   
> -    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
> -            addr, val, size);
> +    trace_ahci_mem_write(s, size, addr, val);
>   
>       /* Only aligned reads are allowed on AHCI */
>       if (addr & 3) {
> @@ -401,15 +398,12 @@ static void ahci_mem_write(void *opaque, hwaddr addr,
>       }
>   
>       if (addr < AHCI_GENERIC_HOST_CONTROL_REGS_MAX_ADDR) {
> -        DPRINTF(-1, "(addr 0x%08X), val 0x%08"PRIX64"\n", (unsigned) addr, val);
> -
>           switch (addr) {
>               case HOST_CAP: /* R/WO, RO */
>                   /* FIXME handle R/WO */
>                   break;
>               case HOST_CTL: /* R/W */
>                   if (val & HOST_CTL_RESET) {
> -                    DPRINTF(-1, "HBA Reset\n");
>                       ahci_reset(s);
>                   } else {
>                       s->control_regs.ghc = (val & 0x3) | HOST_CTL_AHCI_EN;
> @@ -427,7 +421,7 @@ static void ahci_mem_write(void *opaque, hwaddr addr,
>                   /* FIXME report write? */
>                   break;
>               default:
> -                DPRINTF(-1, "write to unknown register 0x%x\n", (unsigned)addr);
> +                trace_ahci_mem_write_unknown(s, addr);
>           }
>       } else if ((addr >= AHCI_PORT_REGS_START_ADDR) &&
>                  (addr < (AHCI_PORT_REGS_START_ADDR +
> @@ -559,7 +553,8 @@ static void ahci_set_signature(AHCIDevice *ad, uint32_t sig)
>       s->sector = sig >> 8 & 0xFF;
>       s->nsector = sig & 0xFF;
>   
> -    DPRINTF(ad->port_no, "set hcyl:lcyl:sect:nsect = 0x%08x\n", sig);
> +    trace_ahci_set_signature(ad->hba, ad->port_no, s->nsector, s->sector,
> +                             s->lcyl, s->hcyl, sig);
>   }
>   
>   static void ahci_reset_port(AHCIState *s, int port)
> @@ -569,7 +564,7 @@ static void ahci_reset_port(AHCIState *s, int port)
>       IDEState *ide_state = &d->port.ifs[0];
>       int i;
>   
> -    DPRINTF(port, "reset port\n");
> +    trace_ahci_reset_port(s, port);
>   
>       ide_bus_reset(&d->port);
>       ide_state->ncq_queues = AHCI_MAX_CMDS;
> @@ -655,7 +650,7 @@ static bool ahci_map_fis_address(AHCIDevice *ad)
>   static void ahci_unmap_fis_address(AHCIDevice *ad)
>   {
>       if (ad->res_fis == NULL) {
> -        DPRINTF(ad->port_no, "Attempt to unmap NULL FIS address\n");
> +        trace_ahci_unmap_fis_address_null(ad->hba, ad->port_no);
>           return;
>       }
>       ad->port_regs.cmd &= ~PORT_CMD_FIS_ON;
> @@ -682,7 +677,7 @@ static bool ahci_map_clb_address(AHCIDevice *ad)
>   static void ahci_unmap_clb_address(AHCIDevice *ad)
>   {
>       if (ad->lst == NULL) {
> -        DPRINTF(ad->port_no, "Attempt to unmap NULL CLB address\n");
> +        trace_ahci_unmap_clb_address_null(ad->hba, ad->port_no);
>           return;
>       }
>       ad->port_regs.cmd &= ~PORT_CMD_LIST_ON;
> @@ -854,20 +849,22 @@ static int ahci_populate_sglist(AHCIDevice *ad, QEMUSGList *sglist,
>       IDEBus *bus = &ad->port;
>       BusState *qbus = BUS(bus);
>   
> +    trace_ahci_populate_sglist(ad->hba, ad->port_no);
> +
>       if (!prdtl) {
> -        DPRINTF(ad->port_no, "no sg list given by guest: 0x%08x\n", opts);
> +        trace_ahci_populate_sglist_no_prdtl(ad->hba, ad->port_no, opts);
>           return -1;
>       }
>   
>       /* map PRDT */
>       if (!(prdt = dma_memory_map(ad->hba->as, prdt_addr, &prdt_len,
>                                   DMA_DIRECTION_TO_DEVICE))){
> -        DPRINTF(ad->port_no, "map failed\n");
> +        trace_ahci_populate_sglist_no_map(ad->hba, ad->port_no);
>           return -1;
>       }
>   
>       if (prdt_len < real_prdt_len) {
> -        DPRINTF(ad->port_no, "mapped less than expected\n");
> +        trace_ahci_populate_sglist_short_map(ad->hba, ad->port_no);
>           r = -1;
>           goto out;
>       }
> @@ -886,9 +883,8 @@ static int ahci_populate_sglist(AHCIDevice *ad, QEMUSGList *sglist,
>               sum += tbl_entry_size;
>           }
>           if ((off_idx == -1) || (off_pos < 0) || (off_pos > tbl_entry_size)) {
> -            DPRINTF(ad->port_no, "%s: Incorrect offset! "
> -                            "off_idx: %d, off_pos: %"PRId64"\n",
> -                            __func__, off_idx, off_pos);
> +            trace_ahci_populate_sglist_bad_offset(ad->hba, ad->port_no,
> +                                                  off_idx, off_pos);
>               r = -1;
>               goto out;
>           }
> @@ -934,8 +930,8 @@ static void ncq_finish(NCQTransferState *ncq_tfs)
>   
>       ahci_write_fis_sdb(ncq_tfs->drive->hba, ncq_tfs);
>   
> -    DPRINTF(ncq_tfs->drive->port_no, "NCQ transfer tag %d finished\n",
> -            ncq_tfs->tag);
> +    trace_ncq_finish(ncq_tfs->drive->hba, ncq_tfs->drive->port_no,
> +                     ncq_tfs->tag);
>   
>       block_acct_done(blk_get_stats(ncq_tfs->drive->port.ifs[0].blk),
>                       &ncq_tfs->acct);
> @@ -999,12 +995,8 @@ static void execute_ncq_command(NCQTransferState *ncq_tfs)
>   
>       switch (ncq_tfs->cmd) {
>       case READ_FPDMA_QUEUED:
> -        DPRINTF(port, "NCQ reading %d sectors from LBA %"PRId64", tag %d\n",
> -                ncq_tfs->sector_count, ncq_tfs->lba, ncq_tfs->tag);
> -
> -        DPRINTF(port, "tag %d aio read %"PRId64"\n",
> -                ncq_tfs->tag, ncq_tfs->lba);
> -
> +        trace_execute_ncq_command_read(ad->hba, port, ncq_tfs->tag,
> +                                       ncq_tfs->sector_count, ncq_tfs->lba);
>           dma_acct_start(ide_state->blk, &ncq_tfs->acct,
>                          &ncq_tfs->sglist, BLOCK_ACCT_READ);
>           ncq_tfs->aiocb = dma_blk_read(ide_state->blk, &ncq_tfs->sglist,
> @@ -1013,12 +1005,8 @@ static void execute_ncq_command(NCQTransferState *ncq_tfs)
>                                         ncq_cb, ncq_tfs);
>           break;
>       case WRITE_FPDMA_QUEUED:
> -        DPRINTF(port, "NCQ writing %d sectors to LBA %"PRId64", tag %d\n",
> -                ncq_tfs->sector_count, ncq_tfs->lba, ncq_tfs->tag);
> -
> -        DPRINTF(port, "tag %d aio write %"PRId64"\n",
> -                ncq_tfs->tag, ncq_tfs->lba);
> -
> +        trace_execute_ncq_command_read(ad->hba, port, ncq_tfs->tag,
> +                                       ncq_tfs->sector_count, ncq_tfs->lba);
>           dma_acct_start(ide_state->blk, &ncq_tfs->acct,
>                          &ncq_tfs->sglist, BLOCK_ACCT_WRITE);
>           ncq_tfs->aiocb = dma_blk_write(ide_state->blk, &ncq_tfs->sglist,
> @@ -1027,8 +1015,8 @@ static void execute_ncq_command(NCQTransferState *ncq_tfs)
>                                          ncq_cb, ncq_tfs);
>           break;
>       default:
> -        DPRINTF(port, "error: unsupported NCQ command (0x%02x) received\n",
> -                ncq_tfs->cmd);
> +        trace_execute_ncq_command_unsup(ad->hba, port,
> +                                        ncq_tfs->tag, ncq_tfs->cmd);
>           ncq_err(ncq_tfs);
>       }
>   }
> @@ -1038,7 +1026,6 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
>                                   uint8_t slot)
>   {
>       AHCIDevice *ad = &s->dev[port];
> -    IDEState *ide_state = &ad->port.ifs[0];
>       NCQFrame *ncq_fis = (NCQFrame*)cmd_fis;
>       uint8_t tag = ncq_fis->tag >> 3;
>       NCQTransferState *ncq_tfs = &ad->ncq_tfs[tag];
> @@ -1066,21 +1053,20 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
>   
>       /* Sanity-check the NCQ packet */
>       if (tag != slot) {
> -        DPRINTF(port, "Warn: NCQ slot (%d) did not match the given tag (%d)\n",
> -                slot, tag);
> +        trace_process_ncq_command_mismatch(s, port, tag, slot);
>       }
>   
>       if (ncq_fis->aux0 || ncq_fis->aux1 || ncq_fis->aux2 || ncq_fis->aux3) {
> -        DPRINTF(port, "Warn: Attempt to use NCQ auxiliary fields.\n");
> +        trace_process_ncq_command_aux(s, port, tag);
>       }
>       if (ncq_fis->prio || ncq_fis->icc) {
> -        DPRINTF(port, "Warn: Unsupported attempt to use PRIO/ICC fields\n");
> +        trace_process_ncq_command_prioicc(s, port, tag);
>       }
>       if (ncq_fis->fua & NCQ_FIS_FUA_MASK) {
> -        DPRINTF(port, "Warn: Unsupported attempt to use Force Unit Access\n");
> +        trace_process_ncq_command_fua(s, port, tag);
>       }
>       if (ncq_fis->tag & NCQ_FIS_RARC_MASK) {
> -        DPRINTF(port, "Warn: Unsupported attempt to use Rebuild Assist\n");
> +        trace_process_ncq_command_rarc(s, port, tag);
>       }
>   
>       ncq_tfs->sector_count = ((ncq_fis->sector_count_high << 8) |
> @@ -1099,16 +1085,14 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
>           ahci_trigger_irq(ad->hba, ad, PORT_IRQ_OVERFLOW);
>           return;
>       } else if (ncq_tfs->sglist.size != size) {
> -        DPRINTF(port, "Warn: PRDTL (0x%zx)"
> -                " does not match requested size (0x%zx)",
> -                ncq_tfs->sglist.size, size);
> +        trace_process_ncq_command_large(s, port, tag,
> +                                        ncq_tfs->sglist.size, size);
>       }
>   
> -    DPRINTF(port, "NCQ transfer LBA from %"PRId64" to %"PRId64", "
> -            "drive max %"PRId64"\n",
> -            ncq_tfs->lba, ncq_tfs->lba + ncq_tfs->sector_count - 1,
> -            ide_state->nb_sectors - 1);
> -
> +    trace_process_ncq_command(s, port, tag,
> +                              ncq_fis->command,
> +                              ncq_tfs->lba,
> +                              ncq_tfs->lba + ncq_tfs->sector_count - 1);
>       execute_ncq_command(ncq_tfs);
>   }
>   
> @@ -1129,16 +1113,14 @@ static void handle_reg_h2d_fis(AHCIState *s, int port,
>       uint16_t opts = le16_to_cpu(cmd->opts);
>   
>       if (cmd_fis[1] & 0x0F) {
> -        DPRINTF(port, "Port Multiplier not supported."
> -                " cmd_fis[0]=%02x cmd_fis[1]=%02x cmd_fis[2]=%02x\n",
> -                cmd_fis[0], cmd_fis[1], cmd_fis[2]);
> +        trace_handle_reg_h2d_fis_pmp(s, port, cmd_fis[1],
> +                                     cmd_fis[2], cmd_fis[3]);
>           return;
>       }
>   
>       if (cmd_fis[1] & 0x70) {
> -        DPRINTF(port, "Reserved flags set in H2D Register FIS."
> -                " cmd_fis[0]=%02x cmd_fis[1]=%02x cmd_fis[2]=%02x\n",
> -                cmd_fis[0], cmd_fis[1], cmd_fis[2]);
> +        trace_handle_reg_h2d_fis_res(s, port, cmd_fis[1],
> +                                     cmd_fis[2], cmd_fis[3]);
>           return;
>       }
>   
> @@ -1216,12 +1198,12 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
>   
>       if (s->dev[port].port.ifs[0].status & (BUSY_STAT|DRQ_STAT)) {
>           /* Engine currently busy, try again later */
> -        DPRINTF(port, "engine busy\n");
> +        trace_handle_cmd_busy(s, port);
>           return -1;
>       }
>   
>       if (!s->dev[port].lst) {
> -        DPRINTF(port, "error: lst not given but cmd handled");
> +        trace_handle_cmd_nolist(s, port);
>           return -1;
>       }
>       cmd = get_cmd_header(s, port, slot);
> @@ -1231,7 +1213,7 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
>       /* The device we are working for */
>       ide_state = &s->dev[port].port.ifs[0];
>       if (!ide_state->blk) {
> -        DPRINTF(port, "error: guest accessed unused port");
> +        trace_handle_cmd_badport(s, port);
>           return -1;
>       }
>   
> @@ -1240,13 +1222,11 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
>       cmd_fis = dma_memory_map(s->as, tbl_addr, &cmd_len,
>                                DMA_DIRECTION_FROM_DEVICE);
>       if (!cmd_fis) {
> -        DPRINTF(port, "error: guest passed us an invalid cmd fis\n");
> +        trace_handle_cmd_badfis(s, port);
>           return -1;
>       } else if (cmd_len != 0x80) {
>           ahci_trigger_irq(s, &s->dev[port], PORT_IRQ_HBUS_ERR);
> -        DPRINTF(port, "error: dma_memory_map failed: "
> -                "(len(%02"PRIx64") != 0x80)\n",
> -                cmd_len);
> +        trace_handle_cmd_badmap(s, port, cmd_len);
>           goto out;
>       }
>       debug_print_fis(cmd_fis, 0x80);
> @@ -1256,9 +1236,8 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
>               handle_reg_h2d_fis(s, port, slot, cmd_fis);
>               break;
>           default:
> -            DPRINTF(port, "unknown command cmd_fis[0]=%02x cmd_fis[1]=%02x "
> -                          "cmd_fis[2]=%02x\n", cmd_fis[0], cmd_fis[1],
> -                          cmd_fis[2]);
> +            trace_handle_cmd_unhandled_fis(s, port,
> +                                           cmd_fis[0], cmd_fis[1], cmd_fis[2]);
>               break;
>       }
>   
> @@ -1299,9 +1278,9 @@ static void ahci_start_transfer(IDEDMA *dma)
>           has_sglist = 1;
>       }
>   
> -    DPRINTF(ad->port_no, "%sing %d bytes on %s w/%s sglist\n",
> -            is_write ? "writ" : "read", size, is_atapi ? "atapi" : "ata",
> -            has_sglist ? "" : "o");
> +    trace_ahci_start_transfer(ad->hba, ad->port_no, is_write ? "writ" : "read",
> +                              size, is_atapi ? "atapi" : "ata",
> +                              has_sglist ? "" : "o");
>   
>       if (has_sglist && size) {
>           if (is_write) {
> @@ -1330,7 +1309,7 @@ static void ahci_start_dma(IDEDMA *dma, IDEState *s,
>                              BlockCompletionFunc *dma_cb)
>   {
>       AHCIDevice *ad = DO_UPCAST(AHCIDevice, dma, dma);
> -    DPRINTF(ad->port_no, "\n");
> +    trace_ahci_start_dma(ad->hba, ad->port_no);
>       s->io_buffer_offset = 0;
>       dma_cb(s, 0);
>   }
> @@ -1368,12 +1347,12 @@ static int32_t ahci_dma_prepare_buf(IDEDMA *dma, int32_t limit)
>   
>       if (ahci_populate_sglist(ad, &s->sg, ad->cur_cmd,
>                                limit, s->io_buffer_offset) == -1) {
> -        DPRINTF(ad->port_no, "ahci_dma_prepare_buf failed.\n");
> +        trace_ahci_dma_prepare_buf_fail(ad->hba, ad->port_no);
>           return -1;
>       }
>       s->io_buffer_size = s->sg.size;
>   
> -    DPRINTF(ad->port_no, "len=%#x\n", s->io_buffer_size);
> +    trace_ahci_dma_prepare_buf(ad->hba, ad->port_no, limit, s->io_buffer_size);
>       return s->io_buffer_size;
>   }
>   
> @@ -1409,11 +1388,9 @@ static int ahci_dma_rw_buf(IDEDMA *dma, int is_write)
>   
>       /* free sglist, update byte count */
>       dma_buf_commit(s, l);
> -
>       s->io_buffer_index += l;
>   
> -    DPRINTF(ad->port_no, "len=%#x\n", l);
> -
> +    trace_ahci_dma_rw_buf(ad->hba, ad->port_no, l);
>       return 1;
>   }
>   
> @@ -1421,7 +1398,7 @@ static void ahci_cmd_done(IDEDMA *dma)
>   {
>       AHCIDevice *ad = DO_UPCAST(AHCIDevice, dma, dma);
>   
> -    DPRINTF(ad->port_no, "cmd done\n");
> +    trace_ahci_cmd_done(ad->hba, ad->port_no);
>   
>       /* update d2h status */
>       ahci_write_fis_d2h(ad);
> @@ -1505,6 +1482,8 @@ void ahci_reset(AHCIState *s)
>       AHCIPortRegs *pr;
>       int i;
>   
> +    trace_ahci_reset(s);
> +
>       s->control_regs.irqstatus = 0;
>       /* AHCI Enable (AE)
>        * The implementation of this bit is dependent upon the value of the
> @@ -1755,6 +1734,7 @@ static uint64_t allwinner_ahci_mem_read(void *opaque, hwaddr addr,
>                                           unsigned size)
>   {
>       AllwinnerAHCIState *a = opaque;
> +    AHCIState *s = &(SYSBUS_AHCI(a)->ahci);
>       uint64_t val = a->regs[addr/4];
>   
>       switch (addr / 4) {
> @@ -1765,8 +1745,7 @@ static uint64_t allwinner_ahci_mem_read(void *opaque, hwaddr addr,
>           val &= ~(0x1 << 24);
>           break;
>       }
> -    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
> -            addr, val, size);
> +    trace_allwinner_ahci_mem_read(s, a, addr, val, size);
>       return  val;
>   }
>   
> @@ -1774,9 +1753,9 @@ static void allwinner_ahci_mem_write(void *opaque, hwaddr addr,
>                                        uint64_t val, unsigned size)
>   {
>       AllwinnerAHCIState *a = opaque;
> +    AHCIState *s = &(SYSBUS_AHCI(a)->ahci);
>   
> -    DPRINTF(-1, "addr=0x%" HWADDR_PRIx " val=0x%" PRIx64 ", size=%d\n",
> -            addr, val, size);
> +    trace_allwinner_ahci_mem_write(s, a, addr, val, size);
>       a->regs[addr/4] = val;
>   }
>   
> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
> index 6e33cb3..e1a0457 100644
> --- a/hw/ide/trace-events
> +++ b/hw/ide/trace-events
> @@ -52,4 +52,54 @@ ide_atapi_cmd_read(void *s, const char *method, int lba, int nb_sectors) "IDESta
>   ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
>   ide_atapi_cmd_read_dma_cb_aio(void *s, int lba, int n) "IDEState: %p; aio read: lba=%d n=%d"
>   # Warning: Verbose
> -ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
> \ No newline at end of file
> +ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
> +
> +# hw/ide/ahci.c
> +ahci_port_read(void *s, int port, int offset, uint32_t ret) "ahci(%p)[%d]: port read @ 0x%x: 0x%08x"
> +ahci_irq_raise(void *s) "ahci(%p): raise irq"
> +ahci_irq_lower(void *s) "ahci(%p): lower irq"
> +ahci_check_irq(void *s, uint32_t old, uint32_t new) "ahci(%p): check irq 0x%08x --> 0x%08x"
> +
> +ahci_port_write(void *s, int port, int offset, uint32_t val) "ahci(%p)[%d]: port write @ 0x%x: 0x%08x"
> +ahci_mem_read_32(void *s, uint64_t addr, uint32_t val) "ahci(%p): mem read @ 0x%"PRIx64": 0x%08x"

can you use same format than ahci_mem_read()?

"ahci(%p): read%u @ 0x%"PRIx64":     0x%08x"

> +ahci_mem_read(void *s, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): read%u @ 0x%"PRIx64": 0x%016"PRIx64
> +ahci_mem_write(void *s, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64
> +ahci_mem_write_unknown(void *s, uint64_t addr) "ahci(%p): write to unknown register 0x%"PRIx64

report the value written, eventually:

"ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64" UNKNOWN"

> +ahci_set_signature(void *s, int port, uint8_t nsector, uint8_t sector, uint8_t lcyl, uint8_t hcyl, uint32_t sig) "ahci(%p)[%d]: set signature sector:0x%02x nsector:0x%02x lcyl:0x%02x hcyl:0x%02x (cumulatively: 0x%08x)"
> +ahci_reset_port(void *s, int port) "ahci(%p)[%d]: reset port"

could be generic:

ahci_port(void *s, int port) "ahci(%p)[%d]: %s"

then

trace_ahci_port(s, port, "reset port");

> +ahci_unmap_fis_address_null(void *s, int port) "ahci(%p)[%d]: Attempt to unmap NULL FIS address"

trace_ahci_port(s, port, "Attempt to unmap NULL FIS address");

> +ahci_unmap_clb_address_null(void *s, int port) "ahci(%p)[%d]: Attempt to unmap NULL CLB address"

trace_ahci_port(s, port, "Attempt to unmap NULL CLB address");

> +ahci_populate_sglist(void *s, int port) "ahci(%p)[%d]"

trace_ahci_port(s, port, "");

> +ahci_populate_sglist_no_prdtl(void *s, int port, uint16_t opts) "ahci(%p)[%d]: no sg list given by guest: 0x%04x"
> +ahci_populate_sglist_no_map(void *s, int port) "ahci(%p)[%d]: DMA mapping failed"

trace_ahci_port(s, port, "DMA mapping failed");

> +ahci_populate_sglist_short_map(void *s, int port) "ahci(%p)[%d]: mapped less than expected"

trace_ahci_port(s, port, "mapped less than expected");

> +ahci_populate_sglist_bad_offset(void *s, int port, int off_idx, int64_t off_pos) "ahci(%p)[%d]: Incorrect offset! off_idx: %d, off_pos: %"PRId64
> +ncq_finish(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: NCQ transfer finished"

ahci_port_tag(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: %s"

then

trace_ahci_port_tag(s, port, tag, "NCQ transfer finished");

> +execute_ncq_command_read(void *s, int port, uint8_t tag, int count, int64_t lba) "ahci(%p)[%d][tag:%d]: NCQ reading %d sectors from LBA %"PRId64
> +execute_ncq_command_write(void *s, int port, uint8_t tag, int count, int64_t lba) "ahci(%p)[%d][tag:%d]: NCQ writing %d sectors to LBA %"PRId64
> +execute_ncq_command_unsup(void *s, int port, uint8_t tag, uint8_t cmd) "ahci(%p)[%d][tag:%d]: error: unsupported NCQ command (0x%02x) received"
> +process_ncq_command_mismatch(void *s, int port, uint8_t tag, uint8_t slot) "ahci(%p)[%d][tag:%d]: Warning: NCQ slot (%d) did not match the given tag"
> +process_ncq_command_aux(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Attempt to use NCQ auxiliary fields"

trace_ahci_port_tag(s, port, tag, "Warn: Attempt to use NCQ auxiliary 
fields);

> +process_ncq_command_prioicc(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Unsupported attempt to use PRIO/ICC fields"
> +process_ncq_command_fua(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Unsupported attempt to use Force Unit Access"
> +process_ncq_command_rarc(void *s, int port, uint8_t tag) "ahci(%p)[%d][tag:%d]: Warn: Unsupported attempt to use Rebuild Assist"

same: trace_ahci_port_tag(...)

> +process_ncq_command_large(void *s, int port, uint8_t tag, size_t prdtl, size_t size) "ahci(%p)[%d][tag:%d]: Warn: PRDTL (0x%zx) does not match requested size (0x%zx)"
> +process_ncq_command(void *s, int port, uint8_t tag, uint8_t cmd, uint64_t lba, uint64_t end) "ahci(%p)[%d][tag:%d]: NCQ op 0x%02x on sectors [%"PRId64",%"PRId64"]"
> +handle_reg_h2d_fis_pmp(void *s, int port, char b0, char b1, char b2) "ahci(%p)[%d]: Port Multiplier not supported, FIS: 0x%02x-%02x-%02x"
> +handle_reg_h2d_fis_res(void *s, int port, char b0, char b1, char b2) "ahci(%p)[%d]: Reserved flags set in H2D Register FIS, FIS: 0x%02x-%02x-%02x"
> +handle_cmd_busy(void *s, int port) "ahci(%p)[%d]: engine busy"

trace_ahci_port(s, port, "engine busy");

> +handle_cmd_nolist(void *s, int port) "ahci(%p)[%d]: handle_cmd called without s->dev[port].lst"
> +handle_cmd_badport(void *s, int port) "ahci(%p)[%d]: guest accessed unused port"
> +handle_cmd_badfis(void *s, int port) "ahci(%p)[%d]: guest provided an invalid cmd FIS"

same, trace_ahci_port(...)

> +handle_cmd_badmap(void *s, int port, uint64_t len) "ahci(%p)[%d]: dma_memory_map failed, 0x%02"PRIx64" != 0x80"
> +handle_cmd_unhandled_fis(void *s, int port, uint8_t b0, uint8_t b1, uint8_t b2) "ahci(%p)[%d]: unhandled FIS type. cmd_fis: 0x%02x-%02x-%02x"
> +ahci_start_transfer(void *s, int port, const char *rw, uint32_t size, const char *tgt, const char *sgl) "ahci(%p)[%d]: %sing %d bytes on %s w/%s sglist"
> +ahci_start_dma(void *s, int port) "ahci(%p)[%d]: start dma"

trace_ahci_port(s, port, "start dma");

> +ahci_dma_prepare_buf(void *s, int port, int32_t io_buffer_size, int32_t limit) "ahci(%p)[%d]: prepare buf limit=%"PRId32" prepared=%"PRId32
> +ahci_dma_prepare_buf_fail(void *s, int port) "ahci(%p)[%d]: sglist population failed"

trace_ahci_port(s, port, "sglist population failed");

> +ahci_dma_rw_buf(void *s, int port, int l) "ahci(%p)[%d] len=0x%x"
> +ahci_cmd_done(void *s, int port) "ahci(%p)[%d]: cmd done"

trace_ahci_port(s, port, "cmd done");

> +ahci_reset(void *s) "ahci(%p): HBA reset"
> +allwinner_ahci_mem_read(void *s, void *a, uint64_t addr, uint64_t val, unsigned size) "ahci(%p): read a=%p addr=0x%"HWADDR_PRIx" val=0x%"PRIx64", size=%d"

is AllwinnerAHCIState useful?

I'd rather use directly trace_ahci_mem_read(s, size, addr, val)

> +allwinner_ahci_mem_write(void *s, void *a, uint64_t addr, uint64_t val, unsigned size) "ahci(%p): write a=%p addr=0x%"HWADDR_PRIx" val=0x%"PRIx64", size=%d"

and trace_ahci_mem_write(s, size, addr, val)

Regards,

Phil.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system John Snow
  2017-08-08 20:00   ` Eric Blake
@ 2017-08-25 13:33   ` Philippe Mathieu-Daudé
  2017-08-28 23:34     ` John Snow
  1 sibling, 1 reply; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-25 13:33 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

Hi John,

On 08/08/2017 03:32 PM, John Snow wrote:
> Out with the old, in with the new.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>   Makefile.objs             |  1 +
>   hw/ide/cmd646.c           | 10 +++-----
>   hw/ide/core.c             | 65 +++++++++++++++++++----------------------------
>   hw/ide/pci.c              | 17 ++++---------
>   hw/ide/piix.c             | 11 ++++----
>   hw/ide/trace-events       | 33 ++++++++++++++++++++++++
>   hw/ide/via.c              | 10 +++-----
>   include/hw/ide/internal.h |  1 -
>   8 files changed, 78 insertions(+), 70 deletions(-)
>   create mode 100644 hw/ide/trace-events
> 
> diff --git a/Makefile.objs b/Makefile.objs
> index 24a4ea0..967c092 100644
> --- a/Makefile.objs
> +++ b/Makefile.objs
> @@ -153,6 +153,7 @@ trace-events-subdirs += hw/acpi
>   trace-events-subdirs += hw/arm
>   trace-events-subdirs += hw/alpha
>   trace-events-subdirs += hw/xen
> +trace-events-subdirs += hw/ide
>   trace-events-subdirs += ui
>   trace-events-subdirs += audio
>   trace-events-subdirs += net
> diff --git a/hw/ide/cmd646.c b/hw/ide/cmd646.c
> index 9ebb8d4..86b2a8f 100644
> --- a/hw/ide/cmd646.c
> +++ b/hw/ide/cmd646.c
> @@ -32,6 +32,7 @@
>   #include "sysemu/dma.h"
>   
>   #include "hw/ide/pci.h"
> +#include "trace.h"
>   
>   /* CMD646 specific */
>   #define CFR		0x50
> @@ -195,9 +196,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>           val = 0xff;
>           break;
>       }
> -#ifdef DEBUG_IDE
> -    printf("bmdma: readb " TARGET_FMT_plx " : 0x%02x\n", addr, val);
> -#endif
> +
> +    trace_bmdma_read_cmd646(addr, val);
>       return val;
>   }
>   
> @@ -211,9 +211,7 @@ static void bmdma_write(void *opaque, hwaddr addr,
>           return;
>       }
>   
> -#ifdef DEBUG_IDE
> -    printf("bmdma: writeb " TARGET_FMT_plx " : 0x%" PRIx64 "\n", addr, val);
> -#endif
> +    trace_bmdma_write_cmd646(addr, val);
>       switch(addr & 3) {
>       case 0:
>           bmdma_cmd_writeb(bm, val);
> diff --git a/hw/ide/core.c b/hw/ide/core.c
> index 0b48b64..53fa084 100644
> --- a/hw/ide/core.c
> +++ b/hw/ide/core.c
> @@ -36,6 +36,7 @@
>   #include "qemu/cutils.h"
>   
>   #include "hw/ide/internal.h"
> +#include "trace.h"
>   
>   /* These values were based on a Seagate ST3500418AS but have been modified
>      to make more sense in QEMU */
> @@ -656,10 +657,7 @@ void ide_cancel_dma_sync(IDEState *s)
>        * write requests) pending and we can avoid to drain. */
>       QLIST_FOREACH(req, &s->buffered_requests, list) {
>           if (!req->orphaned) {
> -#ifdef DEBUG_IDE
> -            printf("%s: invoking cb %p of buffered request %p with"
> -                   " -ECANCELED\n", __func__, req->original_cb, req);
> -#endif
> +            trace_ide_cancel_dma_sync_buffered(req->original_cb, req);
>               req->original_cb(req->original_opaque, -ECANCELED);
>           }
>           req->orphaned = true;
> @@ -678,9 +676,7 @@ void ide_cancel_dma_sync(IDEState *s)
>        * aio operation with preadv/pwritev.
>        */
>       if (s->bus->dma->aiocb) {
> -#ifdef DEBUG_IDE
> -        printf("%s: draining all remaining requests", __func__);
> -#endif
> +        trace_ide_cancel_dma_sync_remaining();
>           blk_drain(s->blk);
>           assert(s->bus->dma->aiocb == NULL);
>       }
> @@ -741,9 +737,7 @@ static void ide_sector_read(IDEState *s)
>           n = s->req_nb_sectors;
>       }
>   
> -#if defined(DEBUG_IDE)
> -    printf("sector=%" PRId64 "\n", sector_num);
> -#endif
> +    trace_ide_sector_read(sector_num, n);
>   
>       if (!ide_sect_range_ok(s, sector_num, n)) {
>           ide_rw_error(s);
> @@ -1005,14 +999,14 @@ static void ide_sector_write(IDEState *s)
>   
>       s->status = READY_STAT | SEEK_STAT | BUSY_STAT;
>       sector_num = ide_get_sector(s);
> -#if defined(DEBUG_IDE)
> -    printf("sector=%" PRId64 "\n", sector_num);
> -#endif
> +
>       n = s->nsector;
>       if (n > s->req_nb_sectors) {
>           n = s->req_nb_sectors;
>       }
>   
> +    trace_ide_sector_write(sector_num, n);
> +
>       if (!ide_sect_range_ok(s, sector_num, n)) {
>           ide_rw_error(s);
>           block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
> @@ -1186,18 +1180,17 @@ static void ide_clear_hob(IDEBus *bus)
>   void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
>   {
>       IDEBus *bus = opaque;
> +    IDEState *s = idebus_active_if(bus);
> +    int reg_num = addr & 7;
>   
> -#ifdef DEBUG_IDE
> -    printf("IDE: write addr=0x%x val=0x%02x\n", addr, val);
> -#endif
> -
> -    addr &= 7;
> +    trace_ide_ioport_write(addr, val, bus, s);
>   
>       /* ignore writes to command block while busy with previous command */
> -    if (addr != 7 && (idebus_active_if(bus)->status & (BUSY_STAT|DRQ_STAT)))
> +    if (reg_num != 7 && (s->status & (BUSY_STAT|DRQ_STAT))) {
>           return;
> +    }
>   
> -    switch(addr) {
> +    switch(reg_num) {
>       case 0:
>           break;
>       case 1:
> @@ -1253,9 +1246,7 @@ void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
>   
>   static void ide_reset(IDEState *s)
>   {
> -#ifdef DEBUG_IDE
> -    printf("ide: reset\n");
> -#endif
> +    trace_ide_reset(s);
>   
>       if (s->pio_aiocb) {
>           blk_aio_cancel(s->pio_aiocb);
> @@ -2013,10 +2004,9 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>       IDEState *s;
>       bool complete;
>   
> -#if defined(DEBUG_IDE)
> -    printf("ide: CMD=%02x\n", val);
> -#endif
>       s = idebus_active_if(bus);
> +    trace_ide_exec_cmd(bus, s, val);
> +
>       /* ignore commands to non existent slave */
>       if (s != bus->ifs && !s->blk) {
>           return;
> @@ -2054,18 +2044,18 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>       }
>   }
>   
> -uint32_t ide_ioport_read(void *opaque, uint32_t addr1)
> +uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   {
>       IDEBus *bus = opaque;
>       IDEState *s = idebus_active_if(bus);
> -    uint32_t addr;
> +    uint32_t reg_num;
>       int ret, hob;
>   
> -    addr = addr1 & 7;
> +    reg_num = addr & 7;
>       /* FIXME: HOB readback uses bit 7, but it's always set right now */
>       //hob = s->select & (1 << 7);
>       hob = 0;
> -    switch(addr) {
> +    switch(reg_num) {
>       case 0:
>           ret = 0xff;
>           break;
> @@ -2133,9 +2123,8 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr1)
>           qemu_irq_lower(bus->irq);
>           break;
>       }
> -#ifdef DEBUG_IDE
> -    printf("ide: read addr=0x%x val=%02x\n", addr1, ret);
> -#endif
> +
> +    trace_ide_ioport_read(addr, ret, bus, s);
>       return ret;
>   }
>   
> @@ -2151,9 +2140,8 @@ uint32_t ide_status_read(void *opaque, uint32_t addr)
>       } else {
>           ret = s->status;
>       }
> -#ifdef DEBUG_IDE
> -    printf("ide: read status addr=0x%x val=%02x\n", addr, ret);
> -#endif
> +
> +    trace_ide_status_read(addr, ret, bus, s);
>       return ret;
>   }
>   
> @@ -2163,9 +2151,8 @@ void ide_cmd_write(void *opaque, uint32_t addr, uint32_t val)
>       IDEState *s;
>       int i;
>   
> -#ifdef DEBUG_IDE
> -    printf("ide: write control addr=0x%x val=%02x\n", addr, val);
> -#endif
> +    trace_ide_cmd_write(addr, val, bus);
> +
>       /* common for both drives */
>       if (!(bus->cmd & IDE_CMD_RESET) &&
>           (val & IDE_CMD_RESET)) {
> diff --git a/hw/ide/pci.c b/hw/ide/pci.c
> index 3cfb510..f2dcc0e 100644
> --- a/hw/ide/pci.c
> +++ b/hw/ide/pci.c
> @@ -31,6 +31,7 @@
>   #include "sysemu/dma.h"
>   #include "qemu/error-report.h"
>   #include "hw/ide/pci.h"
> +#include "trace.h"
>   
>   #define BMDMA_PAGE_SIZE 4096
>   
> @@ -196,9 +197,7 @@ static void bmdma_reset(IDEDMA *dma)
>   {
>       BMDMAState *bm = DO_UPCAST(BMDMAState, dma, dma);
>   
> -#ifdef DEBUG_IDE
> -    printf("ide: dma_reset\n");
> -#endif
> +    trace_bmdma_reset();
>       bmdma_cancel(bm);
>       bm->cmd = 0;
>       bm->status = 0;
> @@ -227,9 +226,7 @@ static void bmdma_irq(void *opaque, int n, int level)
>   
>   void bmdma_cmd_writeb(BMDMAState *bm, uint32_t val)
>   {
> -#ifdef DEBUG_IDE
> -    printf("%s: 0x%08x\n", __func__, val);
> -#endif
> +    trace_bmdma_cmd_writeb(val);
>   
>       /* Ignore writes to SSBM if it keeps the old value */
>       if ((val & BM_CMD_START) != (bm->cmd & BM_CMD_START)) {
> @@ -258,9 +255,7 @@ static uint64_t bmdma_addr_read(void *opaque, hwaddr addr,
>       uint64_t data;
>   
>       data = (bm->addr >> (addr * 8)) & mask;
> -#ifdef DEBUG_IDE
> -    printf("%s: 0x%08x\n", __func__, (unsigned)data);
> -#endif
> +    trace_bmdma_addr_read(data);
>       return data;
>   }
>   
> @@ -271,9 +266,7 @@ static void bmdma_addr_write(void *opaque, hwaddr addr,
>       int shift = addr * 8;
>       uint32_t mask = (1ULL << (width * 8)) - 1;
>   
> -#ifdef DEBUG_IDE
> -    printf("%s: 0x%08x\n", __func__, (unsigned)data);
> -#endif
> +    trace_bmdma_addr_write(data);
>       bm->addr &= ~(mask << shift);
>       bm->addr |= ((data & mask) << shift) & ~3;
>   }
> diff --git a/hw/ide/piix.c b/hw/ide/piix.c
> index 7e2d767..dfb21f6 100644
> --- a/hw/ide/piix.c
> +++ b/hw/ide/piix.c
> @@ -33,6 +33,7 @@
>   #include "sysemu/dma.h"
>   
>   #include "hw/ide/pci.h"
> +#include "trace.h"
>   
>   static uint64_t bmdma_read(void *opaque, hwaddr addr, unsigned size)
>   {
> @@ -54,9 +55,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr, unsigned size)
>           val = 0xff;
>           break;
>       }
> -#ifdef DEBUG_IDE
> -    printf("bmdma: readb 0x%02x : 0x%02x\n", (uint8_t)addr, val);
> -#endif
> +
> +    trace_bmdma_read(addr, val);
>       return val;
>   }
>   
> @@ -69,9 +69,8 @@ static void bmdma_write(void *opaque, hwaddr addr,
>           return;
>       }
>   
> -#ifdef DEBUG_IDE
> -    printf("bmdma: writeb 0x%02x : 0x%02x\n", (uint8_t)addr, (uint8_t)val);
> -#endif
> +    trace_bmdma_write(addr, val);
> +
>       switch(addr & 3) {
>       case 0:
>           bmdma_cmd_writeb(bm, val);
> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
> new file mode 100644
> index 0000000..68ad96a
> --- /dev/null
> +++ b/hw/ide/trace-events
> @@ -0,0 +1,33 @@
> +# See docs/devel/tracing.txt for syntax documentation.
> +
> +# hw/ide/core.c
> +# portio
> +ide_ioport_read(uint32_t addr, uint32_t val, void *bus, void *s)  "IDE PIO rd @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
> +ide_ioport_write(uint32_t addr, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"

ide_ioport_access(char *access, uint32_t addr, uint32_t val, void *bus, 
void *s);

> +ide_status_read(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO rd @ 0x%"PRIx32" (Alt Status); val 0x%02"PRIx32"; bus %p; IDEState %p"
> +ide_cmd_write(uint32_t addr, uint32_t val, void *bus)                              "IDE PIO wr @ 0x%"PRIx32" (Device Control); val 0x%02"PRIx32"; bus %p"
> +# misc
> +ide_exec_cmd(void *bus, void *state, uint32_t cmd) "IDE exec cmd: bus %p; state %p; cmd 0x%02x"
> +ide_cancel_dma_sync_buffered(void *fn, void *req) "invoking cb %p of buffered request %p with -ECANCELED"
> +ide_cancel_dma_sync_remaining(void) "draining all remaining requests"
> +ide_sector_read(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
> +ide_sector_write(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"

ide_sector_access(char *access, int64_t sector_num, int nsectors) "%s 
sector=%"PRId64" nsectors=%d"

> +ide_reset(void *s) "IDEstate %p"
> +
> +# hw/ide/pci.c
> +bmdma_reset(void) ""
> +bmdma_cmd_writeb(uint32_t val) "val: 0x%08x"
> +bmdma_addr_read(uint64_t data) "data: 0x%016"PRIx64
> +bmdma_addr_write(uint64_t data) "data: 0x%016"PRIx64

bmdma_data_access(char *access, uint64_t data) "%s data: 0x%016"PRIx64

> +
> +# hw/ide/piix.c
> +bmdma_read(uint64_t addr, uint8_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
> +bmdma_write(uint64_t addr, uint8_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02x"

bmdma_io_access(char *access, uint64_t addr, uint64_t val) "bmdma: %sb 
0x%"PRIx64" : 0x%02x"

> +
> +# hw/ide/cmd646.c
> +bmdma_read_cmd646(uint64_t addr, uint32_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
> +bmdma_write_cmd646(uint64_t addr, uint64_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02"PRIx64

use trace_bmdma_io_access()

> +
> +# hw/ide/via.c
> +bmdma_read_via(uint64_t addr, uint32_t val) "bmdma: readb 0x%"PRIx64" : 0x%02x"
> +bmdma_write_via(uint64_t addr, uint64_t val) "bmdma: writeb 0x%"PRIx64" : 0x%02"PRIx64

use trace_bmdma_io_access()

> diff --git a/hw/ide/via.c b/hw/ide/via.c
> index 5b32ecb..35c3059 100644
> --- a/hw/ide/via.c
> +++ b/hw/ide/via.c
> @@ -33,6 +33,7 @@
>   #include "sysemu/dma.h"
>   
>   #include "hw/ide/pci.h"
> +#include "trace.h"
>   
>   static uint64_t bmdma_read(void *opaque, hwaddr addr,
>                              unsigned size)
> @@ -55,9 +56,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>           val = 0xff;
>           break;
>       }
> -#ifdef DEBUG_IDE
> -    printf("bmdma: readb 0x%02x : 0x%02x\n", addr, val);
> -#endif
> +
> +    trace_bmdma_read_via(addr, val);
>       return val;
>   }
>   
> @@ -70,9 +70,7 @@ static void bmdma_write(void *opaque, hwaddr addr,
>           return;
>       }
>   
> -#ifdef DEBUG_IDE
> -    printf("bmdma: writeb 0x%02x : 0x%02x\n", addr, val);
> -#endif
> +    trace_bmdma_write_via(addr, val);
>       switch (addr & 3) {
>       case 0:
>           bmdma_cmd_writeb(bm, val);
> diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
> index 482a951..4a92f0a 100644
> --- a/include/hw/ide/internal.h
> +++ b/include/hw/ide/internal.h
> @@ -14,7 +14,6 @@
>   #include "block/scsi.h"
>   
>   /* debug IDE devices */
> -//#define DEBUG_IDE
>   //#define DEBUG_IDE_ATAPI
>   //#define DEBUG_AIO
>   #define USE_DMA_CDROM
> 

If you agree you can add:
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

Regards,

Phil.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing
  2017-08-08 18:32 ` [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing John Snow
  2017-08-08 20:05   ` Eric Blake
@ 2017-08-25 13:43   ` Philippe Mathieu-Daudé
  1 sibling, 0 replies; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-25 13:43 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

On 08/08/2017 03:32 PM, John Snow wrote:
> Name the registers for tracing purposes.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>   hw/ide/core.c       | 88 +++++++++++++++++++++++++++++++++++++++++------------
>   hw/ide/trace-events |  4 +--
>   2 files changed, 70 insertions(+), 22 deletions(-)
> 
> diff --git a/hw/ide/core.c b/hw/ide/core.c
> index 53fa084..6235bdf 100644
> --- a/hw/ide/core.c
> +++ b/hw/ide/core.c
> @@ -1177,13 +1177,37 @@ static void ide_clear_hob(IDEBus *bus)
>       bus->ifs[1].select &= ~(1 << 7);
>   }
>   
> +/* IOport [W]rite [R]egisters */
> +enum ATA_IOPORT_WR {
> +    ATA_IOPORT_WR_DATA = 0,
> +    ATA_IOPORT_WR_FEATURES = 1,
> +    ATA_IOPORT_WR_SECTOR_COUNT = 2,
> +    ATA_IOPORT_WR_SECTOR_NUMBER = 3,
> +    ATA_IOPORT_WR_CYLINDER_LOW = 4,
> +    ATA_IOPORT_WR_CYLINDER_HIGH = 5,
> +    ATA_IOPORT_WR_DEVICE_HEAD = 6,
> +    ATA_IOPORT_WR_COMMAND = 7,
> +    ATA_IOPORT_WR_NUM_REGISTERS,
> +};
> +
> +const char *ATA_IOPORT_WR_lookup[ATA_IOPORT_WR_NUM_REGISTERS] = {
> +    [ATA_IOPORT_WR_DATA] = "Data",
> +    [ATA_IOPORT_WR_FEATURES] = "Features",
> +    [ATA_IOPORT_WR_SECTOR_COUNT] = "Sector Count",
> +    [ATA_IOPORT_WR_SECTOR_NUMBER] = "Sector Number",
> +    [ATA_IOPORT_WR_CYLINDER_LOW] = "Cylinder Low",
> +    [ATA_IOPORT_WR_CYLINDER_HIGH] = "Cylinder High",
> +    [ATA_IOPORT_WR_DEVICE_HEAD] = "Device/Head",
> +    [ATA_IOPORT_WR_COMMAND] = "Command"
> +};
> +
>   void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
>   {
>       IDEBus *bus = opaque;
>       IDEState *s = idebus_active_if(bus);
>       int reg_num = addr & 7;
>   
> -    trace_ide_ioport_write(addr, val, bus, s);
> +    trace_ide_ioport_write(addr, ATA_IOPORT_WR_lookup[reg_num], val, bus, s);
>   
>       /* ignore writes to command block while busy with previous command */
>       if (reg_num != 7 && (s->status & (BUSY_STAT|DRQ_STAT))) {
> @@ -1193,43 +1217,43 @@ void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
>       switch(reg_num) {
>       case 0:
>           break;
> -    case 1:
> -	ide_clear_hob(bus);
> +    case ATA_IOPORT_WR_FEATURES:
> +        ide_clear_hob(bus);
>           /* NOTE: data is written to the two drives */
> -	bus->ifs[0].hob_feature = bus->ifs[0].feature;
> -	bus->ifs[1].hob_feature = bus->ifs[1].feature;
> +        bus->ifs[0].hob_feature = bus->ifs[0].feature;
> +        bus->ifs[1].hob_feature = bus->ifs[1].feature;
>           bus->ifs[0].feature = val;
>           bus->ifs[1].feature = val;
>           break;
> -    case 2:
> +    case ATA_IOPORT_WR_SECTOR_COUNT:
>   	ide_clear_hob(bus);
>   	bus->ifs[0].hob_nsector = bus->ifs[0].nsector;
>   	bus->ifs[1].hob_nsector = bus->ifs[1].nsector;
>           bus->ifs[0].nsector = val;
>           bus->ifs[1].nsector = val;
>           break;
> -    case 3:
> +    case ATA_IOPORT_WR_SECTOR_NUMBER:
>   	ide_clear_hob(bus);
>   	bus->ifs[0].hob_sector = bus->ifs[0].sector;
>   	bus->ifs[1].hob_sector = bus->ifs[1].sector;
>           bus->ifs[0].sector = val;
>           bus->ifs[1].sector = val;
>           break;
> -    case 4:
> +    case ATA_IOPORT_WR_CYLINDER_LOW:
>   	ide_clear_hob(bus);
>   	bus->ifs[0].hob_lcyl = bus->ifs[0].lcyl;
>   	bus->ifs[1].hob_lcyl = bus->ifs[1].lcyl;
>           bus->ifs[0].lcyl = val;
>           bus->ifs[1].lcyl = val;
>           break;
> -    case 5:
> +    case ATA_IOPORT_WR_CYLINDER_HIGH:
>   	ide_clear_hob(bus);
>   	bus->ifs[0].hob_hcyl = bus->ifs[0].hcyl;
>   	bus->ifs[1].hob_hcyl = bus->ifs[1].hcyl;
>           bus->ifs[0].hcyl = val;
>           bus->ifs[1].hcyl = val;
>           break;
> -    case 6:
> +    case ATA_IOPORT_WR_DEVICE_HEAD:
>   	/* FIXME: HOB readback uses bit 7 */
>           bus->ifs[0].select = (val & ~0x10) | 0xa0;
>           bus->ifs[1].select = (val | 0x10) | 0xa0;
> @@ -1237,7 +1261,7 @@ void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
>           bus->unit = (val >> 4) & 1;
>           break;
>       default:
> -    case 7:
> +    case ATA_IOPORT_WR_COMMAND:
>           /* command */
>           ide_exec_cmd(bus, val);
>           break;
> @@ -2044,6 +2068,30 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>       }
>   }
>   
> +/* IOport [R]ead [R]egisters */
> +enum ATA_IOPORT_RR {
> +    ATA_IOPORT_RR_DATA = 0,
> +    ATA_IOPORT_RR_ERROR = 1,
> +    ATA_IOPORT_RR_SECTOR_COUNT = 2,
> +    ATA_IOPORT_RR_SECTOR_NUMBER = 3,
> +    ATA_IOPORT_RR_CYLINDER_LOW = 4,
> +    ATA_IOPORT_RR_CYLINDER_HIGH = 5,
> +    ATA_IOPORT_RR_DEVICE_HEAD = 6,
> +    ATA_IOPORT_RR_STATUS = 7,
> +    ATA_IOPORT_RR_NUM_REGISTERS,
> +};
> +
> +const char *ATA_IOPORT_RR_lookup[ATA_IOPORT_RR_NUM_REGISTERS] = {
> +    [ATA_IOPORT_RR_DATA] = "Data",
> +    [ATA_IOPORT_RR_ERROR] = "Error",
> +    [ATA_IOPORT_RR_SECTOR_COUNT] = "Sector Count",
> +    [ATA_IOPORT_RR_SECTOR_NUMBER] = "Sector Number",
> +    [ATA_IOPORT_RR_CYLINDER_LOW] = "Cylinder Low",
> +    [ATA_IOPORT_RR_CYLINDER_HIGH] = "Cylinder High",
> +    [ATA_IOPORT_RR_DEVICE_HEAD] = "Device/Head",
> +    [ATA_IOPORT_RR_STATUS] = "Status"
> +};
> +
>   uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   {
>       IDEBus *bus = opaque;
> @@ -2056,10 +2104,10 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>       //hob = s->select & (1 << 7);
>       hob = 0;
>       switch(reg_num) {
> -    case 0:
> +    case ATA_IOPORT_RR_DATA:
>           ret = 0xff;
>           break;
> -    case 1:
> +    case ATA_IOPORT_RR_ERROR:
>           if ((!bus->ifs[0].blk && !bus->ifs[1].blk) ||
>               (s != bus->ifs && !s->blk)) {
>               ret = 0;
> @@ -2069,7 +2117,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   	    ret = s->hob_feature;
>           }
>           break;
> -    case 2:
> +    case ATA_IOPORT_RR_SECTOR_COUNT:
>           if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
>               ret = 0;
>           } else if (!hob) {
> @@ -2078,7 +2126,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   	    ret = s->hob_nsector;
>           }
>           break;
> -    case 3:
> +    case ATA_IOPORT_RR_SECTOR_NUMBER:
>           if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
>               ret = 0;
>           } else if (!hob) {
> @@ -2087,7 +2135,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   	    ret = s->hob_sector;
>           }
>           break;
> -    case 4:
> +    case ATA_IOPORT_RR_CYLINDER_LOW:
>           if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
>               ret = 0;
>           } else if (!hob) {
> @@ -2096,7 +2144,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   	    ret = s->hob_lcyl;
>           }
>           break;
> -    case 5:
> +    case ATA_IOPORT_RR_CYLINDER_HIGH:
>           if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
>               ret = 0;
>           } else if (!hob) {
> @@ -2105,7 +2153,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>   	    ret = s->hob_hcyl;
>           }
>           break;
> -    case 6:
> +    case ATA_IOPORT_RR_DEVICE_HEAD:
>           if (!bus->ifs[0].blk && !bus->ifs[1].blk) {
>               ret = 0;
>           } else {
> @@ -2113,7 +2161,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>           }
>           break;
>       default:
> -    case 7:
> +    case ATA_IOPORT_RR_STATUS:
>           if ((!bus->ifs[0].blk && !bus->ifs[1].blk) ||
>               (s != bus->ifs && !s->blk)) {
>               ret = 0;
> @@ -2124,7 +2172,7 @@ uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>           break;
>       }
>   
> -    trace_ide_ioport_read(addr, ret, bus, s);
> +    trace_ide_ioport_read(addr, ATA_IOPORT_RR_lookup[reg_num], ret, bus, s);
>       return ret;
>   }
>   
> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
> index 68ad96a..6c156ac 100644
> --- a/hw/ide/trace-events
> +++ b/hw/ide/trace-events
> @@ -2,8 +2,8 @@
>   
>   # hw/ide/core.c
>   # portio
> -ide_ioport_read(uint32_t addr, uint32_t val, void *bus, void *s)  "IDE PIO rd @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
> -ide_ioport_write(uint32_t addr, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
> +ide_ioport_read(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s)  "IDE PIO rd @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"

what about:

ide_pio_reg_access(char *access, uint32_t addr, const char *reg, 
uint32_t val, void *bus, void *s) "IDE PIO %s @ 0x%"PRIx32" (%s); val 
0x%02"PRIx32"; bus %p; IDEState %p"

so:

   trace_ide_pio_reg_access("rd", addr, ATA_IOPORT_RR_lookup[reg_num], 
ret, bus, s);

> +ide_ioport_write(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"
>   ide_status_read(uint32_t addr, uint32_t val, void *bus, void *s)                   "IDE PIO rd @ 0x%"PRIx32" (Alt Status); val 0x%02"PRIx32"; bus %p; IDEState %p"
>   ide_cmd_write(uint32_t addr, uint32_t val, void *bus)                              "IDE PIO wr @ 0x%"PRIx32" (Device Control); val 0x%02"PRIx32"; bus %p"
and:

   trace_ide_pio_reg_access("wr", addr, "Device Control", val, bus, s);

>   # misc
> 

If agreed:
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events John Snow
@ 2017-08-25 13:46   ` Philippe Mathieu-Daudé
  2017-08-29  0:26     ` John Snow
  0 siblings, 1 reply; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-25 13:46 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

Hi John,

On 08/08/2017 03:33 PM, John Snow wrote:
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>   hw/ide/atapi.c            |  5 +----
>   hw/ide/core.c             | 17 ++++++++++-------
>   hw/ide/trace-events       |  3 +++
>   include/hw/ide/internal.h |  7 +++++--
>   4 files changed, 19 insertions(+), 13 deletions(-)
> 
> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
> index 37fa699..b8fc51e 100644
> --- a/hw/ide/atapi.c
> +++ b/hw/ide/atapi.c
> @@ -416,10 +416,7 @@ static void ide_atapi_cmd_read_dma_cb(void *opaque, int ret)
>           s->io_buffer_size = n * 2048;
>           data_offset = 0;
>       }
> -#ifdef DEBUG_AIO
> -    printf("aio_read_cd: lba=%u n=%d\n", s->lba, n);
> -#endif
> -
> +    trace_ide_atapi_cmd_read_dma_cb_aio(s, s->lba, n);
>       s->bus->dma->iov.iov_base = (void *)(s->io_buffer + data_offset);
>       s->bus->dma->iov.iov_len = n * ATAPI_SECTOR_SIZE;
>       qemu_iovec_init_external(&s->bus->dma->qiov, &s->bus->dma->iov, 1);
> diff --git a/hw/ide/core.c b/hw/ide/core.c
> index 29848ff..1358029 100644
> --- a/hw/ide/core.c
> +++ b/hw/ide/core.c
> @@ -58,6 +58,13 @@ static const int smart_attributes[][12] = {
>       { 190,  0x03, 0x00, 0x45, 0x45, 0x1f, 0x00, 0x1f, 0x1f, 0x00, 0x00, 0x32},
>   };
>   
> +const char *IDE_DMA_CMD_lookup[IDE_DMA__END] = {
> +    [IDE_DMA_READ] = "DMA_READ",
> +    [IDE_DMA_WRITE] = "DMA_WRITE",
> +    [IDE_DMA_TRIM] = "DMA TRIM",
> +    [IDE_DMA_ATAPI] = "DMA ATAPI"
> +};
> +
>   static void ide_dummy_transfer_stop(IDEState *s);
>   
>   static void padstr(char *str, const char *src, int len)
> @@ -860,10 +867,8 @@ static void ide_dma_cb(void *opaque, int ret)
>           goto eot;
>       }
>   
> -#ifdef DEBUG_AIO
> -    printf("ide_dma_cb: sector_num=%" PRId64 " n=%d, cmd_cmd=%d\n",
> -           sector_num, n, s->dma_cmd);
> -#endif
> +    trace_ide_dma_cb(s, sector_num, n,
> +                     IDE_DMA_CMD_lookup[s->dma_cmd]);
>   
>       if ((s->dma_cmd == IDE_DMA_READ || s->dma_cmd == IDE_DMA_WRITE) &&
>           !ide_sect_range_ok(s, sector_num, n)) {
> @@ -2383,9 +2388,7 @@ void ide_bus_reset(IDEBus *bus)
>   
>       /* pending async DMA */
>       if (bus->dma->aiocb) {
> -#ifdef DEBUG_AIO
> -        printf("aio_cancel\n");
> -#endif
> +        trace_ide_bus_reset_aio();
>           blk_aio_cancel(bus->dma->aiocb);
>           bus->dma->aiocb = NULL;
>       }
> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
> index ade1e76..6e33cb3 100644
> --- a/hw/ide/trace-events
> +++ b/hw/ide/trace-events
> @@ -17,6 +17,8 @@ ide_cancel_dma_sync_remaining(void) "draining all remaining requests"
>   ide_sector_read(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
>   ide_sector_write(int64_t sector_num, int nsectors) "sector=%"PRId64" nsectors=%d"
>   ide_reset(void *s) "IDEstate %p"
> +ide_bus_reset_aio(void) "aio_cancel"
> +ide_dma_cb(void *s, int64_t sector_num, int n, const char *dma) "IDEState %p; sector_num=%"PRId64" n=%d cmd=%s"
>   
>   # hw/ide/pci.c
>   bmdma_reset(void) ""
> @@ -48,5 +50,6 @@ ide_atapi_cmd_reply_end_new(void *s, int status) "IDEState: %p; new transfer sta
>   ide_atapi_cmd_check_status(void *s) "IDEState: %p"
>   ide_atapi_cmd_read(void *s, const char *method, int lba, int nb_sectors) "IDEState: %p; read %s: LBA=%d nb_sectors=%d"
>   ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
> +ide_atapi_cmd_read_dma_cb_aio(void *s, int lba, int n) "IDEState: %p; aio read: lba=%d n=%d"
>   # Warning: Verbose
>   ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
> \ No newline at end of file
> diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
> index 74efe8a..97e97a2 100644
> --- a/include/hw/ide/internal.h
> +++ b/include/hw/ide/internal.h
> @@ -14,7 +14,6 @@
>   #include "block/scsi.h"
>   
>   /* debug IDE devices */
> -//#define DEBUG_AIO
>   #define USE_DMA_CDROM
>   
>   typedef struct IDEBus IDEBus;
> @@ -333,12 +332,16 @@ struct unreported_events {
>   };
>   
>   enum ide_dma_cmd {
> -    IDE_DMA_READ,
> +    IDE_DMA__BEGIN = 0,
> +    IDE_DMA_READ = IDE_DMA__BEGIN,

not that useful, you can use directly:

	IDE_DMA_READ = 0,

>       IDE_DMA_WRITE,
>       IDE_DMA_TRIM,
>       IDE_DMA_ATAPI,
> +    IDE_DMA__END

IDE_DMA__COUNT sounds better.

>   };
>   
> +extern const char *IDE_DMA_CMD_lookup[IDE_DMA__END];
> +
>   #define ide_cmd_is_read(s) \
>   	((s)->dma_cmd == IDE_DMA_READ)
>   
> 

removing IDE_DMA__BEGIN and using IDE_DMA__COUNT:
Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro John Snow
@ 2017-08-25 13:48   ` Philippe Mathieu-Daudé
  2017-08-29  0:33     ` John Snow
  0 siblings, 1 reply; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-25 13:48 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

On 08/08/2017 03:33 PM, John Snow wrote:
> Signed-off-by: John Snow <jsnow@redhat.com>

Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

> ---
>   hw/ide/ahci.c | 9 ---------
>   1 file changed, 9 deletions(-)
> 
> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
> index 1a4d4db..ce2010c 100644
> --- a/hw/ide/ahci.c
> +++ b/hw/ide/ahci.c
> @@ -34,17 +34,8 @@
>   #include "hw/ide/pci.h"
>   #include "hw/ide/ahci_internal.h"
>   
> -#define DEBUG_AHCI 0
>   #include "trace.h"
>   
> -#define DPRINTF(port, fmt, ...) \
> -do { \
> -    if (DEBUG_AHCI) { \
> -        fprintf(stderr, "ahci: %s: [%d] ", __func__, port); \
> -        fprintf(stderr, fmt, ## __VA_ARGS__); \
> -    } \
> -} while (0)
> -
>   static void check_cmd(AHCIState *s, int port);
>   static int handle_cmd(AHCIState *s, int port, uint8_t slot);
>   static void ahci_reset_port(AHCIState *s, int port);
> 

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants
  2017-08-08 18:33 ` [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants John Snow
@ 2017-08-25 14:00   ` Philippe Mathieu-Daudé
  2017-08-29  0:28     ` John Snow
  0 siblings, 1 reply; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-25 14:00 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

Hi John,

On 08/08/2017 03:33 PM, John Snow wrote:
> Create a new enum so that we can name the IRQ bits, which will make debugging
> them a little nicer if we can print them out. Not handled in this patch, but
> this will make it possible to get a nice debug printf detailing exactly which
> status bits are set, as it can be multiple at any given time.
> 
> As a consequence of this patch, it is no longer possible to set multiple IRQ
> codes at once, but nothing was utilizing this ability anyway.
> 
> Signed-off-by: John Snow <jsnow@redhat.com>
> ---
>   hw/ide/ahci.c          | 49 ++++++++++++++++++++++++++++++++++++++-----------
>   hw/ide/ahci_internal.h | 44 +++++++++++++++++++++++++++++++++++---------
>   hw/ide/trace-events    |  2 +-
>   3 files changed, 74 insertions(+), 21 deletions(-)
> 
> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
> index d5acceb..c5a9b69 100644
> --- a/hw/ide/ahci.c
> +++ b/hw/ide/ahci.c
> @@ -56,6 +56,27 @@ static bool ahci_map_fis_address(AHCIDevice *ad);
>   static void ahci_unmap_clb_address(AHCIDevice *ad);
>   static void ahci_unmap_fis_address(AHCIDevice *ad);
>   
> +static const char *AHCIPortIRQ_lookup[AHCI_PORT_IRQ__END] = {
> +    [AHCI_PORT_IRQ_BIT_DHRS] = "DHRS",
> +    [AHCI_PORT_IRQ_BIT_PSS]  = "PSS",
> +    [AHCI_PORT_IRQ_BIT_DSS]  = "DSS",
> +    [AHCI_PORT_IRQ_BIT_SDBS] = "SDBS",
> +    [AHCI_PORT_IRQ_BIT_UFS]  = "UFS",
> +    [AHCI_PORT_IRQ_BIT_DPS]  = "DPS",
> +    [AHCI_PORT_IRQ_BIT_PCS]  = "PCS",
> +    [AHCI_PORT_IRQ_BIT_DMPS] = "DMPS",
> +    [8 ... 21]               = "RESERVED",
> +    [AHCI_PORT_IRQ_BIT_PRCS] = "PRCS",
> +    [AHCI_PORT_IRQ_BIT_IPMS] = "IPMS",
> +    [AHCI_PORT_IRQ_BIT_OFS]  = "OFS",
> +    [25]                     = "RESERVED",
> +    [AHCI_PORT_IRQ_BIT_INFS] = "INFS",
> +    [AHCI_PORT_IRQ_BIT_IFS]  = "IFS",
> +    [AHCI_PORT_IRQ_BIT_HBDS] = "HBDS",
> +    [AHCI_PORT_IRQ_BIT_HBFS] = "HBFS",
> +    [AHCI_PORT_IRQ_BIT_TFES] = "TFES",
> +    [AHCI_PORT_IRQ_BIT_CPDS] = "CPDS"
> +};
>   
>   static uint32_t  ahci_port_read(AHCIState *s, int port, int offset)
>   {
> @@ -170,12 +191,18 @@ static void ahci_check_irq(AHCIState *s)
>   }
>   
>   static void ahci_trigger_irq(AHCIState *s, AHCIDevice *d,
> -                             int irq_type)
> +                             enum AHCIPortIRQ irqbit)
>   {
> -    DPRINTF(d->port_no, "trigger irq %#x -> %x\n",
> -            irq_type, d->port_regs.irq_mask & irq_type);
> +    g_assert(irqbit >= 0 && irqbit < 32);

Since you now use an enum this check is no more necessary.

However ...

> +    uint32_t irq = 1U << irqbit;
> +    uint32_t irqstat = d->port_regs.irq_stat | irq;
>   
> -    d->port_regs.irq_stat |= irq_type;
> +    trace_ahci_trigger_irq(s, d->port_no,
> +                           AHCIPortIRQ_lookup[irqbit], irq,
> +                           d->port_regs.irq_stat, irqstat,
> +                           irqstat & d->port_regs.irq_mask);
> +

Why not keep using masked irqs, and iterate over AHCI_PORT_IRQ__END 
bits? Something like:

     if (TRACE_AHCI_IRQ_ENABLED) {
         int irqbit;
         for (irqbit = 0; irqbit < AHCI_PORT_IRQ__END; irqbit++) {
             if (irqmask & BIT(irqbit)) {
                 trace_ahci_trigger_irq(s, d->port_no, ...

> +    d->port_regs.irq_stat = irqstat;
>       ahci_check_irq(s);
>   }
>   
> @@ -718,7 +745,7 @@ static void ahci_write_fis_sdb(AHCIState *s, NCQTransferState *ncq_tfs)
>   
>       /* Trigger IRQ if interrupt bit is set (which currently, it always is) */
>       if (sdb_fis->flags & 0x40) {
> -        ahci_trigger_irq(s, ad, PORT_IRQ_SDB_FIS);
> +        ahci_trigger_irq(s, ad, AHCI_PORT_IRQ_BIT_SDBS);
>       }
>   }
>   
> @@ -761,10 +788,10 @@ static void ahci_write_fis_pio(AHCIDevice *ad, uint16_t len)
>           ad->port.ifs[0].status;
>   
>       if (pio_fis[2] & ERR_STAT) {
> -        ahci_trigger_irq(ad->hba, ad, PORT_IRQ_TF_ERR);
> +        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_TFES);
>       }
>   
> -    ahci_trigger_irq(ad->hba, ad, PORT_IRQ_PIOS_FIS);
> +    ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_PSS);
>   }
>   
>   static bool ahci_write_fis_d2h(AHCIDevice *ad)
> @@ -804,10 +831,10 @@ static bool ahci_write_fis_d2h(AHCIDevice *ad)
>           ad->port.ifs[0].status;
>   
>       if (d2h_fis[2] & ERR_STAT) {
> -        ahci_trigger_irq(ad->hba, ad, PORT_IRQ_TF_ERR);
> +        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_TFES);
>       }
>   
> -    ahci_trigger_irq(ad->hba, ad, PORT_IRQ_D2H_REG_FIS);
> +    ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_DHRS);
>       return true;
>   }
>   
> @@ -1082,7 +1109,7 @@ static void process_ncq_command(AHCIState *s, int port, uint8_t *cmd_fis,
>                        "is smaller than the requested size (0x%zx)",
>                        ncq_tfs->sglist.size, size);
>           ncq_err(ncq_tfs);
> -        ahci_trigger_irq(ad->hba, ad, PORT_IRQ_OVERFLOW);
> +        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_OFS);
>           return;
>       } else if (ncq_tfs->sglist.size != size) {
>           trace_process_ncq_command_large(s, port, tag,
> @@ -1225,7 +1252,7 @@ static int handle_cmd(AHCIState *s, int port, uint8_t slot)
>           trace_handle_cmd_badfis(s, port);
>           return -1;
>       } else if (cmd_len != 0x80) {
> -        ahci_trigger_irq(s, &s->dev[port], PORT_IRQ_HBUS_ERR);
> +        ahci_trigger_irq(s, &s->dev[port], AHCI_PORT_IRQ_BIT_HBFS);
>           trace_handle_cmd_badmap(s, port, cmd_len);
>           goto out;
>       }
> diff --git a/hw/ide/ahci_internal.h b/hw/ide/ahci_internal.h
> index 1e21169..7e67add 100644
> --- a/hw/ide/ahci_internal.h
> +++ b/hw/ide/ahci_internal.h
> @@ -91,6 +91,31 @@
>   #define PORT_CMD_ISSUE            0x38 /* command issue */
>   #define PORT_RESERVED             0x3c /* reserved */
>   
> +/* Port interrupt bit descriptors */
> +enum AHCIPortIRQ {
> +    AHCI_PORT_IRQ_BIT_DHRS = 0,
> +    AHCI_PORT_IRQ_BIT_PSS  = 1,
> +    AHCI_PORT_IRQ_BIT_DSS  = 2,
> +    AHCI_PORT_IRQ_BIT_SDBS = 3,
> +    AHCI_PORT_IRQ_BIT_UFS  = 4,
> +    AHCI_PORT_IRQ_BIT_DPS  = 5,
> +    AHCI_PORT_IRQ_BIT_PCS  = 6,
> +    AHCI_PORT_IRQ_BIT_DMPS = 7,
> +    /* RESERVED */
> +    AHCI_PORT_IRQ_BIT_PRCS = 22,
> +    AHCI_PORT_IRQ_BIT_IPMS = 23,
> +    AHCI_PORT_IRQ_BIT_OFS  = 24,
> +    /* RESERVED */
> +    AHCI_PORT_IRQ_BIT_INFS = 26,
> +    AHCI_PORT_IRQ_BIT_IFS  = 27,
> +    AHCI_PORT_IRQ_BIT_HBDS = 28,
> +    AHCI_PORT_IRQ_BIT_HBFS = 29,
> +    AHCI_PORT_IRQ_BIT_TFES = 30,
> +    AHCI_PORT_IRQ_BIT_CPDS = 31,
> +    AHCI_PORT_IRQ__END     = 32
> +};
> +
> +
>   /* PORT_IRQ_{STAT,MASK} bits */
>   #define PORT_IRQ_COLD_PRES        (1U << 31) /* cold presence detect */
>   #define PORT_IRQ_TF_ERR           (1 << 30) /* task file error */
> @@ -98,18 +123,19 @@
>   #define PORT_IRQ_HBUS_DATA_ERR    (1 << 28) /* host bus data error */
>   #define PORT_IRQ_IF_ERR           (1 << 27) /* interface fatal error */
>   #define PORT_IRQ_IF_NONFATAL      (1 << 26) /* interface non-fatal error */
> +                                            /* reserved */
>   #define PORT_IRQ_OVERFLOW         (1 << 24) /* xfer exhausted available S/G */
>   #define PORT_IRQ_BAD_PMP          (1 << 23) /* incorrect port multiplier */
> -
>   #define PORT_IRQ_PHYRDY           (1 << 22) /* PhyRdy changed */
> -#define PORT_IRQ_DEV_ILCK         (1 << 7) /* device interlock */
> -#define PORT_IRQ_CONNECT          (1 << 6) /* port connect change status */
> -#define PORT_IRQ_SG_DONE          (1 << 5) /* descriptor processed */
> -#define PORT_IRQ_UNK_FIS          (1 << 4) /* unknown FIS rx'd */
> -#define PORT_IRQ_SDB_FIS          (1 << 3) /* Set Device Bits FIS rx'd */
> -#define PORT_IRQ_DMAS_FIS         (1 << 2) /* DMA Setup FIS rx'd */
> -#define PORT_IRQ_PIOS_FIS         (1 << 1) /* PIO Setup FIS rx'd */
> -#define PORT_IRQ_D2H_REG_FIS      (1 << 0) /* D2H Register FIS rx'd */
> +                                            /* reserved */
> +#define PORT_IRQ_DEV_ILCK         (1 << 7)  /* device interlock */
> +#define PORT_IRQ_CONNECT          (1 << 6)  /* port connect change status */
> +#define PORT_IRQ_SG_DONE          (1 << 5)  /* descriptor processed */
> +#define PORT_IRQ_UNK_FIS          (1 << 4)  /* unknown FIS rx'd */
> +#define PORT_IRQ_SDB_FIS          (1 << 3)  /* Set Device Bits FIS rx'd */
> +#define PORT_IRQ_DMAS_FIS         (1 << 2)  /* DMA Setup FIS rx'd */
> +#define PORT_IRQ_PIOS_FIS         (1 << 1)  /* PIO Setup FIS rx'd */
> +#define PORT_IRQ_D2H_REG_FIS      (1 << 0)  /* D2H Register FIS rx'd */
>   
>   #define PORT_IRQ_FREEZE           (PORT_IRQ_HBUS_ERR | PORT_IRQ_IF_ERR |   \
>                                      PORT_IRQ_CONNECT | PORT_IRQ_PHYRDY |    \
> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
> index e1a0457..5b321e1 100644
> --- a/hw/ide/trace-events
> +++ b/hw/ide/trace-events
> @@ -59,7 +59,7 @@ ahci_port_read(void *s, int port, int offset, uint32_t ret) "ahci(%p)[%d]: port
>   ahci_irq_raise(void *s) "ahci(%p): raise irq"
>   ahci_irq_lower(void *s) "ahci(%p): lower irq"
>   ahci_check_irq(void *s, uint32_t old, uint32_t new) "ahci(%p): check irq 0x%08x --> 0x%08x"
> -
> +ahci_trigger_irq(void *s, int port, const char *name, uint32_t val, uint32_t old, uint32_t new, uint32_t effective) "ahci(%p)[%d]: trigger irq +%s (0x%08x); irqstat: 0x%08x --> 0x%08x; effective: 0x%08x"
>   ahci_port_write(void *s, int port, int offset, uint32_t val) "ahci(%p)[%d]: port write @ 0x%x: 0x%08x"
>   ahci_mem_read_32(void *s, uint64_t addr, uint32_t val) "ahci(%p): mem read @ 0x%"PRIx64": 0x%08x"
>   ahci_mem_read(void *s, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): read%u @ 0x%"PRIx64": 0x%016"PRIx64
> 

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system
  2017-08-25 13:33   ` Philippe Mathieu-Daudé
@ 2017-08-28 23:34     ` John Snow
  0 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-28 23:34 UTC (permalink / raw)
  To: Philippe Mathieu-Daudé, qemu-block; +Cc: qemu-devel, Stefan Hajnoczi



On 08/25/2017 09:33 AM, Philippe Mathieu-Daudé wrote:
> Hi John,
> 
> On 08/08/2017 03:32 PM, John Snow wrote:
>> Out with the old, in with the new.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>   Makefile.objs             |  1 +
>>   hw/ide/cmd646.c           | 10 +++-----
>>   hw/ide/core.c             | 65
>> +++++++++++++++++++----------------------------
>>   hw/ide/pci.c              | 17 ++++---------
>>   hw/ide/piix.c             | 11 ++++----
>>   hw/ide/trace-events       | 33 ++++++++++++++++++++++++
>>   hw/ide/via.c              | 10 +++-----
>>   include/hw/ide/internal.h |  1 -
>>   8 files changed, 78 insertions(+), 70 deletions(-)
>>   create mode 100644 hw/ide/trace-events
>>
>> diff --git a/Makefile.objs b/Makefile.objs
>> index 24a4ea0..967c092 100644
>> --- a/Makefile.objs
>> +++ b/Makefile.objs
>> @@ -153,6 +153,7 @@ trace-events-subdirs += hw/acpi
>>   trace-events-subdirs += hw/arm
>>   trace-events-subdirs += hw/alpha
>>   trace-events-subdirs += hw/xen
>> +trace-events-subdirs += hw/ide
>>   trace-events-subdirs += ui
>>   trace-events-subdirs += audio
>>   trace-events-subdirs += net
>> diff --git a/hw/ide/cmd646.c b/hw/ide/cmd646.c
>> index 9ebb8d4..86b2a8f 100644
>> --- a/hw/ide/cmd646.c
>> +++ b/hw/ide/cmd646.c
>> @@ -32,6 +32,7 @@
>>   #include "sysemu/dma.h"
>>     #include "hw/ide/pci.h"
>> +#include "trace.h"
>>     /* CMD646 specific */
>>   #define CFR        0x50
>> @@ -195,9 +196,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>>           val = 0xff;
>>           break;
>>       }
>> -#ifdef DEBUG_IDE
>> -    printf("bmdma: readb " TARGET_FMT_plx " : 0x%02x\n", addr, val);
>> -#endif
>> +
>> +    trace_bmdma_read_cmd646(addr, val);
>>       return val;
>>   }
>>   @@ -211,9 +211,7 @@ static void bmdma_write(void *opaque, hwaddr addr,
>>           return;
>>       }
>>   -#ifdef DEBUG_IDE
>> -    printf("bmdma: writeb " TARGET_FMT_plx " : 0x%" PRIx64 "\n",
>> addr, val);
>> -#endif
>> +    trace_bmdma_write_cmd646(addr, val);
>>       switch(addr & 3) {
>>       case 0:
>>           bmdma_cmd_writeb(bm, val);
>> diff --git a/hw/ide/core.c b/hw/ide/core.c
>> index 0b48b64..53fa084 100644
>> --- a/hw/ide/core.c
>> +++ b/hw/ide/core.c
>> @@ -36,6 +36,7 @@
>>   #include "qemu/cutils.h"
>>     #include "hw/ide/internal.h"
>> +#include "trace.h"
>>     /* These values were based on a Seagate ST3500418AS but have been
>> modified
>>      to make more sense in QEMU */
>> @@ -656,10 +657,7 @@ void ide_cancel_dma_sync(IDEState *s)
>>        * write requests) pending and we can avoid to drain. */
>>       QLIST_FOREACH(req, &s->buffered_requests, list) {
>>           if (!req->orphaned) {
>> -#ifdef DEBUG_IDE
>> -            printf("%s: invoking cb %p of buffered request %p with"
>> -                   " -ECANCELED\n", __func__, req->original_cb, req);
>> -#endif
>> +            trace_ide_cancel_dma_sync_buffered(req->original_cb, req);
>>               req->original_cb(req->original_opaque, -ECANCELED);
>>           }
>>           req->orphaned = true;
>> @@ -678,9 +676,7 @@ void ide_cancel_dma_sync(IDEState *s)
>>        * aio operation with preadv/pwritev.
>>        */
>>       if (s->bus->dma->aiocb) {
>> -#ifdef DEBUG_IDE
>> -        printf("%s: draining all remaining requests", __func__);
>> -#endif
>> +        trace_ide_cancel_dma_sync_remaining();
>>           blk_drain(s->blk);
>>           assert(s->bus->dma->aiocb == NULL);
>>       }
>> @@ -741,9 +737,7 @@ static void ide_sector_read(IDEState *s)
>>           n = s->req_nb_sectors;
>>       }
>>   -#if defined(DEBUG_IDE)
>> -    printf("sector=%" PRId64 "\n", sector_num);
>> -#endif
>> +    trace_ide_sector_read(sector_num, n);
>>         if (!ide_sect_range_ok(s, sector_num, n)) {
>>           ide_rw_error(s);
>> @@ -1005,14 +999,14 @@ static void ide_sector_write(IDEState *s)
>>         s->status = READY_STAT | SEEK_STAT | BUSY_STAT;
>>       sector_num = ide_get_sector(s);
>> -#if defined(DEBUG_IDE)
>> -    printf("sector=%" PRId64 "\n", sector_num);
>> -#endif
>> +
>>       n = s->nsector;
>>       if (n > s->req_nb_sectors) {
>>           n = s->req_nb_sectors;
>>       }
>>   +    trace_ide_sector_write(sector_num, n);
>> +
>>       if (!ide_sect_range_ok(s, sector_num, n)) {
>>           ide_rw_error(s);
>>           block_acct_invalid(blk_get_stats(s->blk), BLOCK_ACCT_WRITE);
>> @@ -1186,18 +1180,17 @@ static void ide_clear_hob(IDEBus *bus)
>>   void ide_ioport_write(void *opaque, uint32_t addr, uint32_t val)
>>   {
>>       IDEBus *bus = opaque;
>> +    IDEState *s = idebus_active_if(bus);
>> +    int reg_num = addr & 7;
>>   -#ifdef DEBUG_IDE
>> -    printf("IDE: write addr=0x%x val=0x%02x\n", addr, val);
>> -#endif
>> -
>> -    addr &= 7;
>> +    trace_ide_ioport_write(addr, val, bus, s);
>>         /* ignore writes to command block while busy with previous
>> command */
>> -    if (addr != 7 && (idebus_active_if(bus)->status &
>> (BUSY_STAT|DRQ_STAT)))
>> +    if (reg_num != 7 && (s->status & (BUSY_STAT|DRQ_STAT))) {
>>           return;
>> +    }
>>   -    switch(addr) {
>> +    switch(reg_num) {
>>       case 0:
>>           break;
>>       case 1:
>> @@ -1253,9 +1246,7 @@ void ide_ioport_write(void *opaque, uint32_t
>> addr, uint32_t val)
>>     static void ide_reset(IDEState *s)
>>   {
>> -#ifdef DEBUG_IDE
>> -    printf("ide: reset\n");
>> -#endif
>> +    trace_ide_reset(s);
>>         if (s->pio_aiocb) {
>>           blk_aio_cancel(s->pio_aiocb);
>> @@ -2013,10 +2004,9 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>>       IDEState *s;
>>       bool complete;
>>   -#if defined(DEBUG_IDE)
>> -    printf("ide: CMD=%02x\n", val);
>> -#endif
>>       s = idebus_active_if(bus);
>> +    trace_ide_exec_cmd(bus, s, val);
>> +
>>       /* ignore commands to non existent slave */
>>       if (s != bus->ifs && !s->blk) {
>>           return;
>> @@ -2054,18 +2044,18 @@ void ide_exec_cmd(IDEBus *bus, uint32_t val)
>>       }
>>   }
>>   -uint32_t ide_ioport_read(void *opaque, uint32_t addr1)
>> +uint32_t ide_ioport_read(void *opaque, uint32_t addr)
>>   {
>>       IDEBus *bus = opaque;
>>       IDEState *s = idebus_active_if(bus);
>> -    uint32_t addr;
>> +    uint32_t reg_num;
>>       int ret, hob;
>>   -    addr = addr1 & 7;
>> +    reg_num = addr & 7;
>>       /* FIXME: HOB readback uses bit 7, but it's always set right now */
>>       //hob = s->select & (1 << 7);
>>       hob = 0;
>> -    switch(addr) {
>> +    switch(reg_num) {
>>       case 0:
>>           ret = 0xff;
>>           break;
>> @@ -2133,9 +2123,8 @@ uint32_t ide_ioport_read(void *opaque, uint32_t
>> addr1)
>>           qemu_irq_lower(bus->irq);
>>           break;
>>       }
>> -#ifdef DEBUG_IDE
>> -    printf("ide: read addr=0x%x val=%02x\n", addr1, ret);
>> -#endif
>> +
>> +    trace_ide_ioport_read(addr, ret, bus, s);
>>       return ret;
>>   }
>>   @@ -2151,9 +2140,8 @@ uint32_t ide_status_read(void *opaque,
>> uint32_t addr)
>>       } else {
>>           ret = s->status;
>>       }
>> -#ifdef DEBUG_IDE
>> -    printf("ide: read status addr=0x%x val=%02x\n", addr, ret);
>> -#endif
>> +
>> +    trace_ide_status_read(addr, ret, bus, s);
>>       return ret;
>>   }
>>   @@ -2163,9 +2151,8 @@ void ide_cmd_write(void *opaque, uint32_t
>> addr, uint32_t val)
>>       IDEState *s;
>>       int i;
>>   -#ifdef DEBUG_IDE
>> -    printf("ide: write control addr=0x%x val=%02x\n", addr, val);
>> -#endif
>> +    trace_ide_cmd_write(addr, val, bus);
>> +
>>       /* common for both drives */
>>       if (!(bus->cmd & IDE_CMD_RESET) &&
>>           (val & IDE_CMD_RESET)) {
>> diff --git a/hw/ide/pci.c b/hw/ide/pci.c
>> index 3cfb510..f2dcc0e 100644
>> --- a/hw/ide/pci.c
>> +++ b/hw/ide/pci.c
>> @@ -31,6 +31,7 @@
>>   #include "sysemu/dma.h"
>>   #include "qemu/error-report.h"
>>   #include "hw/ide/pci.h"
>> +#include "trace.h"
>>     #define BMDMA_PAGE_SIZE 4096
>>   @@ -196,9 +197,7 @@ static void bmdma_reset(IDEDMA *dma)
>>   {
>>       BMDMAState *bm = DO_UPCAST(BMDMAState, dma, dma);
>>   -#ifdef DEBUG_IDE
>> -    printf("ide: dma_reset\n");
>> -#endif
>> +    trace_bmdma_reset();
>>       bmdma_cancel(bm);
>>       bm->cmd = 0;
>>       bm->status = 0;
>> @@ -227,9 +226,7 @@ static void bmdma_irq(void *opaque, int n, int level)
>>     void bmdma_cmd_writeb(BMDMAState *bm, uint32_t val)
>>   {
>> -#ifdef DEBUG_IDE
>> -    printf("%s: 0x%08x\n", __func__, val);
>> -#endif
>> +    trace_bmdma_cmd_writeb(val);
>>         /* Ignore writes to SSBM if it keeps the old value */
>>       if ((val & BM_CMD_START) != (bm->cmd & BM_CMD_START)) {
>> @@ -258,9 +255,7 @@ static uint64_t bmdma_addr_read(void *opaque,
>> hwaddr addr,
>>       uint64_t data;
>>         data = (bm->addr >> (addr * 8)) & mask;
>> -#ifdef DEBUG_IDE
>> -    printf("%s: 0x%08x\n", __func__, (unsigned)data);
>> -#endif
>> +    trace_bmdma_addr_read(data);
>>       return data;
>>   }
>>   @@ -271,9 +266,7 @@ static void bmdma_addr_write(void *opaque,
>> hwaddr addr,
>>       int shift = addr * 8;
>>       uint32_t mask = (1ULL << (width * 8)) - 1;
>>   -#ifdef DEBUG_IDE
>> -    printf("%s: 0x%08x\n", __func__, (unsigned)data);
>> -#endif
>> +    trace_bmdma_addr_write(data);
>>       bm->addr &= ~(mask << shift);
>>       bm->addr |= ((data & mask) << shift) & ~3;
>>   }
>> diff --git a/hw/ide/piix.c b/hw/ide/piix.c
>> index 7e2d767..dfb21f6 100644
>> --- a/hw/ide/piix.c
>> +++ b/hw/ide/piix.c
>> @@ -33,6 +33,7 @@
>>   #include "sysemu/dma.h"
>>     #include "hw/ide/pci.h"
>> +#include "trace.h"
>>     static uint64_t bmdma_read(void *opaque, hwaddr addr, unsigned size)
>>   {
>> @@ -54,9 +55,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr
>> addr, unsigned size)
>>           val = 0xff;
>>           break;
>>       }
>> -#ifdef DEBUG_IDE
>> -    printf("bmdma: readb 0x%02x : 0x%02x\n", (uint8_t)addr, val);
>> -#endif
>> +
>> +    trace_bmdma_read(addr, val);
>>       return val;
>>   }
>>   @@ -69,9 +69,8 @@ static void bmdma_write(void *opaque, hwaddr addr,
>>           return;
>>       }
>>   -#ifdef DEBUG_IDE
>> -    printf("bmdma: writeb 0x%02x : 0x%02x\n", (uint8_t)addr,
>> (uint8_t)val);
>> -#endif
>> +    trace_bmdma_write(addr, val);
>> +
>>       switch(addr & 3) {
>>       case 0:
>>           bmdma_cmd_writeb(bm, val);
>> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
>> new file mode 100644
>> index 0000000..68ad96a
>> --- /dev/null
>> +++ b/hw/ide/trace-events
>> @@ -0,0 +1,33 @@
>> +# See docs/devel/tracing.txt for syntax documentation.
>> +
>> +# hw/ide/core.c
>> +# portio
>> +ide_ioport_read(uint32_t addr, uint32_t val, void *bus, void *s) 
>> "IDE PIO rd @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
>> +ide_ioport_write(uint32_t addr, uint32_t val, void *bus, void *s)
>> "IDE PIO wr @ 0x%"PRIx32"; val 0x%02"PRIx32"; bus %p IDEState %p"
> 
> ide_ioport_access(char *access, uint32_t addr, uint32_t val, void *bus,
> void *s);
> 
>> +ide_status_read(uint32_t addr, uint32_t val, void *bus, void
>> *s)                   "IDE PIO rd @ 0x%"PRIx32" (Alt Status); val
>> 0x%02"PRIx32"; bus %p; IDEState %p"
>> +ide_cmd_write(uint32_t addr, uint32_t val, void
>> *bus)                              "IDE PIO wr @ 0x%"PRIx32" (Device
>> Control); val 0x%02"PRIx32"; bus %p"
>> +# misc
>> +ide_exec_cmd(void *bus, void *state, uint32_t cmd) "IDE exec cmd: bus
>> %p; state %p; cmd 0x%02x"
>> +ide_cancel_dma_sync_buffered(void *fn, void *req) "invoking cb %p of
>> buffered request %p with -ECANCELED"
>> +ide_cancel_dma_sync_remaining(void) "draining all remaining requests"
>> +ide_sector_read(int64_t sector_num, int nsectors) "sector=%"PRId64"
>> nsectors=%d"
>> +ide_sector_write(int64_t sector_num, int nsectors) "sector=%"PRId64"
>> nsectors=%d"
> 
> ide_sector_access(char *access, int64_t sector_num, int nsectors) "%s
> sector=%"PRId64" nsectors=%d"
> 
>> +ide_reset(void *s) "IDEstate %p"
>> +
>> +# hw/ide/pci.c
>> +bmdma_reset(void) ""
>> +bmdma_cmd_writeb(uint32_t val) "val: 0x%08x"
>> +bmdma_addr_read(uint64_t data) "data: 0x%016"PRIx64
>> +bmdma_addr_write(uint64_t data) "data: 0x%016"PRIx64
> 
> bmdma_data_access(char *access, uint64_t data) "%s data: 0x%016"PRIx64
> 
>> +
>> +# hw/ide/piix.c
>> +bmdma_read(uint64_t addr, uint8_t val) "bmdma: readb 0x%"PRIx64" :
>> 0x%02x"
>> +bmdma_write(uint64_t addr, uint8_t val) "bmdma: writeb 0x%"PRIx64" :
>> 0x%02x"
> 
> bmdma_io_access(char *access, uint64_t addr, uint64_t val) "bmdma: %sb
> 0x%"PRIx64" : 0x%02x"
> 
>> +
>> +# hw/ide/cmd646.c
>> +bmdma_read_cmd646(uint64_t addr, uint32_t val) "bmdma: readb
>> 0x%"PRIx64" : 0x%02x"
>> +bmdma_write_cmd646(uint64_t addr, uint64_t val) "bmdma: writeb
>> 0x%"PRIx64" : 0x%02"PRIx64
> 
> use trace_bmdma_io_access()
> 
>> +
>> +# hw/ide/via.c
>> +bmdma_read_via(uint64_t addr, uint32_t val) "bmdma: readb 0x%"PRIx64"
>> : 0x%02x"
>> +bmdma_write_via(uint64_t addr, uint64_t val) "bmdma: writeb
>> 0x%"PRIx64" : 0x%02"PRIx64
> 
> use trace_bmdma_io_access()
> 
>> diff --git a/hw/ide/via.c b/hw/ide/via.c
>> index 5b32ecb..35c3059 100644
>> --- a/hw/ide/via.c
>> +++ b/hw/ide/via.c
>> @@ -33,6 +33,7 @@
>>   #include "sysemu/dma.h"
>>     #include "hw/ide/pci.h"
>> +#include "trace.h"
>>     static uint64_t bmdma_read(void *opaque, hwaddr addr,
>>                              unsigned size)
>> @@ -55,9 +56,8 @@ static uint64_t bmdma_read(void *opaque, hwaddr addr,
>>           val = 0xff;
>>           break;
>>       }
>> -#ifdef DEBUG_IDE
>> -    printf("bmdma: readb 0x%02x : 0x%02x\n", addr, val);
>> -#endif
>> +
>> +    trace_bmdma_read_via(addr, val);
>>       return val;
>>   }
>>   @@ -70,9 +70,7 @@ static void bmdma_write(void *opaque, hwaddr addr,
>>           return;
>>       }
>>   -#ifdef DEBUG_IDE
>> -    printf("bmdma: writeb 0x%02x : 0x%02x\n", addr, val);
>> -#endif
>> +    trace_bmdma_write_via(addr, val);
>>       switch (addr & 3) {
>>       case 0:
>>           bmdma_cmd_writeb(bm, val);
>> diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
>> index 482a951..4a92f0a 100644
>> --- a/include/hw/ide/internal.h
>> +++ b/include/hw/ide/internal.h
>> @@ -14,7 +14,6 @@
>>   #include "block/scsi.h"
>>     /* debug IDE devices */
>> -//#define DEBUG_IDE
>>   //#define DEBUG_IDE_ATAPI
>>   //#define DEBUG_AIO
>>   #define USE_DMA_CDROM
>>
> 
> If you agree you can add:
> Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
> 
> Regards,
> 
> Phil.
No complaints with your suggested changes, but in practice we seem to
prefer names of functions first, followed by differentiators on those
functions.

docs/devel/tracing says only this:

"4. Name trace events after their function.  If there are multiple trace
events in one function, append a unique distinguisher at the end of the
name."

I'd be happy to deviate, but I don't immediately know what adverse
effect it might have w/r/t various tracing backends. The collapse may
not be favorable.

With the tracing already written, I'd rather not optimize for the sake
of optimizing.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events
  2017-08-08 20:59   ` Eric Blake
@ 2017-08-28 23:43     ` John Snow
  0 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-28 23:43 UTC (permalink / raw)
  To: Eric Blake, qemu-block; +Cc: qemu-devel



On 08/08/2017 04:59 PM, Eric Blake wrote:
> On 08/08/2017 01:33 PM, John Snow wrote:
>> Goodbye, printfs.
>> Hello, fancy printfs.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>  hw/ide/atapi.c            | 64 +++++++++++++++++------------------------------
>>  hw/ide/trace-events       | 19 ++++++++++++++
>>  include/hw/ide/internal.h |  1 -
>>  3 files changed, 42 insertions(+), 42 deletions(-)
> 
>> @@ -1330,16 +1310,18 @@ void ide_atapi_cmd(IDEState *s)
>>      uint8_t *buf = s->io_buffer;
>>      const struct AtapiCmd *cmd = &atapi_cmd_table[s->io_buffer[0]];
>>  
>> -#ifdef DEBUG_IDE_ATAPI
>> -    {
>> +    trace_ide_atapi_cmd(s, s->io_buffer[0]);
>> +
>> +    if (TRACE_IDE_ATAPI_CMD_PACKET_ENABLED) {
>> +        /* Each pretty-printed byte needs two bytes and a space; */
>> +        char *ppacket = g_malloc(ATAPI_PACKET_SIZE * 3 + 1);
> 
> Nice use of an extra conditional to make a pretty trace without the
> overhead when tracing is off.  (Oh yeah, you asked me on IRC how to do
> it, and I pointed to commit bd6952a3 as the example)
> 
> 
>> +++ b/hw/ide/trace-events
>> @@ -6,6 +6,10 @@ ide_ioport_read(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s
>>  ide_ioport_write(uint32_t addr, const char *reg, uint32_t val, void *bus, void *s) "IDE PIO wr @ 0x%"PRIx32" (%s); val 0x%02"PRIx32"; bus %p IDEState %p"
> 
> Wouldn't it be nice if our trace generator would let us line-wrap?
> 
>> +# Warning: Verbose
> 
> Cute.  Should you also add it to the ide_data_* traces, per the commit
> message in 3/9?
> 

Probably.

>> +ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet) "IDEState: %p; limit=0x%x packet: %s"
>> \ No newline at end of file
> 
> Umm, that should be fixed (I know that 'diff' uses both / and \ to
> differentiate whether it was the pre- or post-patch version that had the
> issue, but never remember which is which - so the fix may be in an
> earlier patch).  Also fix the trace-events rebase for 3/9; with that,
> you can add
> 

I'll fix these and let you re-bestow me with RBs, to err on the side of
caution.

> Reviewed-by: Eric Blake <eblake@redhat.com>
> 

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events
  2017-08-25 13:17   ` Philippe Mathieu-Daudé
@ 2017-08-29  0:15     ` John Snow
  2017-08-30  3:51       ` Philippe Mathieu-Daudé
  0 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-29  0:15 UTC (permalink / raw)
  To: Philippe Mathieu-Daudé, qemu-block; +Cc: qemu-devel, Stefan Hajnoczi



On 08/25/2017 09:17 AM, Philippe Mathieu-Daudé wrote:
> Hi John,
> 
> On 08/08/2017 03:33 PM, John Snow wrote:
>> There are a few hangers-on that will be dealt with individually
>> in forthcoming patches.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>   hw/ide/ahci.c       | 157
>> +++++++++++++++++++++++-----------------------------
>>   hw/ide/trace-events |  52 ++++++++++++++++-
>>   2 files changed, 119 insertions(+), 90 deletions(-)
>>

snip, snip

>>   diff --git a/hw/ide/trace-events b/hw/ide/trace-events
>> index 6e33cb3..e1a0457 100644
>> --- a/hw/ide/trace-events
>> +++ b/hw/ide/trace-events
>> @@ -52,4 +52,54 @@ ide_atapi_cmd_read(void *s, const char *method, int
>> lba, int nb_sectors) "IDESta
>>   ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
>>   ide_atapi_cmd_read_dma_cb_aio(void *s, int lba, int n) "IDEState:
>> %p; aio read: lba=%d n=%d"
>>   # Warning: Verbose
>> -ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet)
>> "IDEState: %p; limit=0x%x packet: %s"
>> \ No newline at end of file
>> +ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet)
>> "IDEState: %p; limit=0x%x packet: %s"
>> +
>> +# hw/ide/ahci.c
>> +ahci_port_read(void *s, int port, int offset, uint32_t ret)
>> "ahci(%p)[%d]: port read @ 0x%x: 0x%08x"
>> +ahci_irq_raise(void *s) "ahci(%p): raise irq"
>> +ahci_irq_lower(void *s) "ahci(%p): lower irq"
>> +ahci_check_irq(void *s, uint32_t old, uint32_t new) "ahci(%p): check
>> irq 0x%08x --> 0x%08x"
>> +
>> +ahci_port_write(void *s, int port, int offset, uint32_t val)
>> "ahci(%p)[%d]: port write @ 0x%x: 0x%08x"
>> +ahci_mem_read_32(void *s, uint64_t addr, uint32_t val) "ahci(%p): mem
>> read @ 0x%"PRIx64": 0x%08x"
> 
> can you use same format than ahci_mem_read()?
> 
> "ahci(%p): read%u @ 0x%"PRIx64":     0x%08x"
> 
>> +ahci_mem_read(void *s, unsigned size, uint64_t addr, uint64_t val)
>> "ahci(%p): read%u @ 0x%"PRIx64": 0x%016"PRIx64
>> +ahci_mem_write(void *s, unsigned size, uint64_t addr, uint64_t val)
>> "ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64
>> +ahci_mem_write_unknown(void *s, uint64_t addr) "ahci(%p): write to
>> unknown register 0x%"PRIx64
> 
> report the value written, eventually:
> 
> "ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64" UNKNOWN"
> 

Not necessary here; it's reported by the more generic
trace_ahci_mem_write which gets all of the writes no matter where they
go. In this case, too, the write is actually ignored and doesn't wind up
going anywhere ...

... but I suppose it wouldn't hurt to know what that value would have
been. If we enable just this trace that will probably help illuminate
what the errant write is.

>> +ahci_set_signature(void *s, int port, uint8_t nsector, uint8_t
>> sector, uint8_t lcyl, uint8_t hcyl, uint32_t sig) "ahci(%p)[%d]: set
>> signature sector:0x%02x nsector:0x%02x lcyl:0x%02x hcyl:0x%02x
>> (cumulatively: 0x%08x)"
>> +ahci_reset_port(void *s, int port) "ahci(%p)[%d]: reset port"
> 
> could be generic:
> 
> ahci_port(void *s, int port) "ahci(%p)[%d]: %s"
> 
> then
> 
> trace_ahci_port(s, port, "reset port");
> 

I don't disagree, just more trepidation on what that means for the trace
events which are otherwise all named exactly for the functions that call
them.

Also, the problem with combining these sorts of traces becomes one with
the DPRINTF we're replacing: you can't target individual sections of
code anymore, and you either turn on "ahci_port" or off.

If there is a better suggestion for avoiding the ahci(%p)[%d]: pattern
here over and over and over and over again I'd happily take it.

Stefan?

[...snip...]

>> +ahci_reset(void *s) "ahci(%p): HBA reset"
>> +allwinner_ahci_mem_read(void *s, void *a, uint64_t addr, uint64_t
>> val, unsigned size) "ahci(%p): read a=%p addr=0x%"HWADDR_PRIx"
>> val=0x%"PRIx64", size=%d"
> 
> is AllwinnerAHCIState useful?
> 

Only as far as it happens to be the argument to this function; of course
AHCIState is the real prize, but we have to fish it out of
AllwinnerAHCIState first.

> I'd rather use directly trace_ahci_mem_read(s, size, addr, val)
> >> +allwinner_ahci_mem_write(void *s, void *a, uint64_t addr, uint64_t
>> val, unsigned size) "ahci(%p): write a=%p addr=0x%"HWADDR_PRIx"
>> val=0x%"PRIx64", size=%d"
> 
> and trace_ahci_mem_write(s, size, addr, val)
> 
> Regards,
> 
> Phil.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events
  2017-08-25 13:46   ` Philippe Mathieu-Daudé
@ 2017-08-29  0:26     ` John Snow
  0 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-29  0:26 UTC (permalink / raw)
  To: Philippe Mathieu-Daudé, qemu-block; +Cc: qemu-devel



On 08/25/2017 09:46 AM, Philippe Mathieu-Daudé wrote:
> Hi John,
> 
> On 08/08/2017 03:33 PM, John Snow wrote:
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>   hw/ide/atapi.c            |  5 +----
>>   hw/ide/core.c             | 17 ++++++++++-------
>>   hw/ide/trace-events       |  3 +++
>>   include/hw/ide/internal.h |  7 +++++--
>>   4 files changed, 19 insertions(+), 13 deletions(-)
>>
>> diff --git a/hw/ide/atapi.c b/hw/ide/atapi.c
>> index 37fa699..b8fc51e 100644
>> --- a/hw/ide/atapi.c
>> +++ b/hw/ide/atapi.c
>> @@ -416,10 +416,7 @@ static void ide_atapi_cmd_read_dma_cb(void
>> *opaque, int ret)
>>           s->io_buffer_size = n * 2048;
>>           data_offset = 0;
>>       }
>> -#ifdef DEBUG_AIO
>> -    printf("aio_read_cd: lba=%u n=%d\n", s->lba, n);
>> -#endif
>> -
>> +    trace_ide_atapi_cmd_read_dma_cb_aio(s, s->lba, n);
>>       s->bus->dma->iov.iov_base = (void *)(s->io_buffer + data_offset);
>>       s->bus->dma->iov.iov_len = n * ATAPI_SECTOR_SIZE;
>>       qemu_iovec_init_external(&s->bus->dma->qiov, &s->bus->dma->iov, 1);
>> diff --git a/hw/ide/core.c b/hw/ide/core.c
>> index 29848ff..1358029 100644
>> --- a/hw/ide/core.c
>> +++ b/hw/ide/core.c
>> @@ -58,6 +58,13 @@ static const int smart_attributes[][12] = {
>>       { 190,  0x03, 0x00, 0x45, 0x45, 0x1f, 0x00, 0x1f, 0x1f, 0x00,
>> 0x00, 0x32},
>>   };
>>   +const char *IDE_DMA_CMD_lookup[IDE_DMA__END] = {
>> +    [IDE_DMA_READ] = "DMA_READ",
>> +    [IDE_DMA_WRITE] = "DMA_WRITE",
>> +    [IDE_DMA_TRIM] = "DMA TRIM",
>> +    [IDE_DMA_ATAPI] = "DMA ATAPI"
>> +};
>> +
>>   static void ide_dummy_transfer_stop(IDEState *s);
>>     static void padstr(char *str, const char *src, int len)
>> @@ -860,10 +867,8 @@ static void ide_dma_cb(void *opaque, int ret)
>>           goto eot;
>>       }
>>   -#ifdef DEBUG_AIO
>> -    printf("ide_dma_cb: sector_num=%" PRId64 " n=%d, cmd_cmd=%d\n",
>> -           sector_num, n, s->dma_cmd);
>> -#endif
>> +    trace_ide_dma_cb(s, sector_num, n,
>> +                     IDE_DMA_CMD_lookup[s->dma_cmd]);
>>         if ((s->dma_cmd == IDE_DMA_READ || s->dma_cmd ==
>> IDE_DMA_WRITE) &&
>>           !ide_sect_range_ok(s, sector_num, n)) {
>> @@ -2383,9 +2388,7 @@ void ide_bus_reset(IDEBus *bus)
>>         /* pending async DMA */
>>       if (bus->dma->aiocb) {
>> -#ifdef DEBUG_AIO
>> -        printf("aio_cancel\n");
>> -#endif
>> +        trace_ide_bus_reset_aio();
>>           blk_aio_cancel(bus->dma->aiocb);
>>           bus->dma->aiocb = NULL;
>>       }
>> diff --git a/hw/ide/trace-events b/hw/ide/trace-events
>> index ade1e76..6e33cb3 100644
>> --- a/hw/ide/trace-events
>> +++ b/hw/ide/trace-events
>> @@ -17,6 +17,8 @@ ide_cancel_dma_sync_remaining(void) "draining all
>> remaining requests"
>>   ide_sector_read(int64_t sector_num, int nsectors) "sector=%"PRId64"
>> nsectors=%d"
>>   ide_sector_write(int64_t sector_num, int nsectors) "sector=%"PRId64"
>> nsectors=%d"
>>   ide_reset(void *s) "IDEstate %p"
>> +ide_bus_reset_aio(void) "aio_cancel"
>> +ide_dma_cb(void *s, int64_t sector_num, int n, const char *dma)
>> "IDEState %p; sector_num=%"PRId64" n=%d cmd=%s"
>>     # hw/ide/pci.c
>>   bmdma_reset(void) ""
>> @@ -48,5 +50,6 @@ ide_atapi_cmd_reply_end_new(void *s, int status)
>> "IDEState: %p; new transfer sta
>>   ide_atapi_cmd_check_status(void *s) "IDEState: %p"
>>   ide_atapi_cmd_read(void *s, const char *method, int lba, int
>> nb_sectors) "IDEState: %p; read %s: LBA=%d nb_sectors=%d"
>>   ide_atapi_cmd(void *s, uint8_t cmd) "IDEState: %p; cmd: 0x%02x"
>> +ide_atapi_cmd_read_dma_cb_aio(void *s, int lba, int n) "IDEState: %p;
>> aio read: lba=%d n=%d"
>>   # Warning: Verbose
>>   ide_atapi_cmd_packet(void *s, uint16_t limit, const char *packet)
>> "IDEState: %p; limit=0x%x packet: %s"
>> \ No newline at end of file
>> diff --git a/include/hw/ide/internal.h b/include/hw/ide/internal.h
>> index 74efe8a..97e97a2 100644
>> --- a/include/hw/ide/internal.h
>> +++ b/include/hw/ide/internal.h
>> @@ -14,7 +14,6 @@
>>   #include "block/scsi.h"
>>     /* debug IDE devices */
>> -//#define DEBUG_AIO
>>   #define USE_DMA_CDROM
>>     typedef struct IDEBus IDEBus;
>> @@ -333,12 +332,16 @@ struct unreported_events {
>>   };
>>     enum ide_dma_cmd {
>> -    IDE_DMA_READ,
>> +    IDE_DMA__BEGIN = 0,
>> +    IDE_DMA_READ = IDE_DMA__BEGIN,
> 
> not that useful, you can use directly:
> 
>     IDE_DMA_READ = 0,
> 

I could do lots of things; one of the things I like to do out of habit
is to name an enumerator after the beginning so that if I were to ever
loop over the items contained within, I can write a loop that looks like
this:

for (i = IDE_DMA__BEGIN; i < IDE_DMA__END; i++) {
	...foo...;
}

instead of having to name a specific constant in the beginning.

Why?

Because, heaven help us, someone reorders the enum for whatever reason,
the program is still going to compile and nobody will notice this change
halfway across the globe.

Having a distinct __START __END (or even COUNT as you suggest) clues us
in to the notion that there are users that don't care about the order,
per se, but do care that the enum is iterable.

"Cool story John, but do you use that feature here?"

Nope ...

I'll remove it! I only really needed the COUNT as you say, and the rest
came along by habit.

>>       IDE_DMA_WRITE,
>>       IDE_DMA_TRIM,
>>       IDE_DMA_ATAPI,
>> +    IDE_DMA__END
> 
> IDE_DMA__COUNT sounds better.
> 

I'll take both suggestions.

>>   };
>>   +extern const char *IDE_DMA_CMD_lookup[IDE_DMA__END];
>> +
>>   #define ide_cmd_is_read(s) \
>>       ((s)->dma_cmd == IDE_DMA_READ)
>>  
> 
> removing IDE_DMA__BEGIN and using IDE_DMA__COUNT:
> Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>

Thanks.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants
  2017-08-25 14:00   ` Philippe Mathieu-Daudé
@ 2017-08-29  0:28     ` John Snow
  2017-08-30  3:24       ` Philippe Mathieu-Daudé
  0 siblings, 1 reply; 36+ messages in thread
From: John Snow @ 2017-08-29  0:28 UTC (permalink / raw)
  To: Philippe Mathieu-Daudé, qemu-block; +Cc: qemu-devel



On 08/25/2017 10:00 AM, Philippe Mathieu-Daudé wrote:
> Hi John,
> 
> On 08/08/2017 03:33 PM, John Snow wrote:
>> Create a new enum so that we can name the IRQ bits, which will make
>> debugging
>> them a little nicer if we can print them out. Not handled in this
>> patch, but
>> this will make it possible to get a nice debug printf detailing
>> exactly which
>> status bits are set, as it can be multiple at any given time.
>>
>> As a consequence of this patch, it is no longer possible to set
>> multiple IRQ
>> codes at once, but nothing was utilizing this ability anyway.
>>
>> Signed-off-by: John Snow <jsnow@redhat.com>
>> ---
>>   hw/ide/ahci.c          | 49
>> ++++++++++++++++++++++++++++++++++++++-----------
>>   hw/ide/ahci_internal.h | 44
>> +++++++++++++++++++++++++++++++++++---------
>>   hw/ide/trace-events    |  2 +-
>>   3 files changed, 74 insertions(+), 21 deletions(-)
>>
>> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
>> index d5acceb..c5a9b69 100644
>> --- a/hw/ide/ahci.c
>> +++ b/hw/ide/ahci.c
>> @@ -56,6 +56,27 @@ static bool ahci_map_fis_address(AHCIDevice *ad);
>>   static void ahci_unmap_clb_address(AHCIDevice *ad);
>>   static void ahci_unmap_fis_address(AHCIDevice *ad);
>>   +static const char *AHCIPortIRQ_lookup[AHCI_PORT_IRQ__END] = {
>> +    [AHCI_PORT_IRQ_BIT_DHRS] = "DHRS",
>> +    [AHCI_PORT_IRQ_BIT_PSS]  = "PSS",
>> +    [AHCI_PORT_IRQ_BIT_DSS]  = "DSS",
>> +    [AHCI_PORT_IRQ_BIT_SDBS] = "SDBS",
>> +    [AHCI_PORT_IRQ_BIT_UFS]  = "UFS",
>> +    [AHCI_PORT_IRQ_BIT_DPS]  = "DPS",
>> +    [AHCI_PORT_IRQ_BIT_PCS]  = "PCS",
>> +    [AHCI_PORT_IRQ_BIT_DMPS] = "DMPS",
>> +    [8 ... 21]               = "RESERVED",
>> +    [AHCI_PORT_IRQ_BIT_PRCS] = "PRCS",
>> +    [AHCI_PORT_IRQ_BIT_IPMS] = "IPMS",
>> +    [AHCI_PORT_IRQ_BIT_OFS]  = "OFS",
>> +    [25]                     = "RESERVED",
>> +    [AHCI_PORT_IRQ_BIT_INFS] = "INFS",
>> +    [AHCI_PORT_IRQ_BIT_IFS]  = "IFS",
>> +    [AHCI_PORT_IRQ_BIT_HBDS] = "HBDS",
>> +    [AHCI_PORT_IRQ_BIT_HBFS] = "HBFS",
>> +    [AHCI_PORT_IRQ_BIT_TFES] = "TFES",
>> +    [AHCI_PORT_IRQ_BIT_CPDS] = "CPDS"
>> +};
>>     static uint32_t  ahci_port_read(AHCIState *s, int port, int offset)
>>   {
>> @@ -170,12 +191,18 @@ static void ahci_check_irq(AHCIState *s)
>>   }
>>     static void ahci_trigger_irq(AHCIState *s, AHCIDevice *d,
>> -                             int irq_type)
>> +                             enum AHCIPortIRQ irqbit)
>>   {
>> -    DPRINTF(d->port_no, "trigger irq %#x -> %x\n",
>> -            irq_type, d->port_regs.irq_mask & irq_type);
>> +    g_assert(irqbit >= 0 && irqbit < 32);
> 
> Since you now use an enum this check is no more necessary.
> 

You can actually still pass in a wrong value if you wanted to. This is
to prevent old-style IRQ masks from getting passed in by accident.

> However ...
> 
>> +    uint32_t irq = 1U << irqbit;
>> +    uint32_t irqstat = d->port_regs.irq_stat | irq;
>>   -    d->port_regs.irq_stat |= irq_type;
>> +    trace_ahci_trigger_irq(s, d->port_no,
>> +                           AHCIPortIRQ_lookup[irqbit], irq,
>> +                           d->port_regs.irq_stat, irqstat,
>> +                           irqstat & d->port_regs.irq_mask);
>> +
> 
> Why not keep using masked irqs, and iterate over AHCI_PORT_IRQ__END
> bits? Something like:
> 
>     if (TRACE_AHCI_IRQ_ENABLED) {
>         int irqbit;
>         for (irqbit = 0; irqbit < AHCI_PORT_IRQ__END; irqbit++) {
>             if (irqmask & BIT(irqbit)) {
>                 trace_ahci_trigger_irq(s, d->port_no, ...
> 

Would rather not iterate like that for the IRQ path. Generally no place
in the codebase needs to raise more than one IRQ type at a time, so why
bother allowing it?

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro
  2017-08-25 13:48   ` Philippe Mathieu-Daudé
@ 2017-08-29  0:33     ` John Snow
  0 siblings, 0 replies; 36+ messages in thread
From: John Snow @ 2017-08-29  0:33 UTC (permalink / raw)
  To: Philippe Mathieu-Daudé, qemu-block; +Cc: qemu-devel



On 08/25/2017 09:48 AM, Philippe Mathieu-Daudé wrote:
> On 08/08/2017 03:33 PM, John Snow wrote:
>> Signed-off-by: John Snow <jsnow@redhat.com>
> 
> Reviewed-by: Philippe Mathieu-Daudé <f4bug@amsat.org>
> 

:)

I'll wait on V2 to hear back. Thank you for your feedback so far.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants
  2017-08-29  0:28     ` John Snow
@ 2017-08-30  3:24       ` Philippe Mathieu-Daudé
  0 siblings, 0 replies; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-30  3:24 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel

>> On 08/08/2017 03:33 PM, John Snow wrote:
>>> Create a new enum so that we can name the IRQ bits, which will make
>>> debugging
>>> them a little nicer if we can print them out. Not handled in this
>>> patch, but
>>> this will make it possible to get a nice debug printf detailing
>>> exactly which
>>> status bits are set, as it can be multiple at any given time.
>>>
>>> As a consequence of this patch, it is no longer possible to set
>>> multiple IRQ
>>> codes at once, but nothing was utilizing this ability anyway.
>>>
>>> Signed-off-by: John Snow <jsnow@redhat.com>
>>> ---
>>>    hw/ide/ahci.c          | 49
>>> ++++++++++++++++++++++++++++++++++++++-----------
>>>    hw/ide/ahci_internal.h | 44
>>> +++++++++++++++++++++++++++++++++++---------
>>>    hw/ide/trace-events    |  2 +-
>>>    3 files changed, 74 insertions(+), 21 deletions(-)
>>>
>>> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
>>> index d5acceb..c5a9b69 100644
>>> --- a/hw/ide/ahci.c
>>> +++ b/hw/ide/ahci.c
>>> @@ -56,6 +56,27 @@ static bool ahci_map_fis_address(AHCIDevice *ad);
>>>    static void ahci_unmap_clb_address(AHCIDevice *ad);
>>>    static void ahci_unmap_fis_address(AHCIDevice *ad);
>>>    +static const char *AHCIPortIRQ_lookup[AHCI_PORT_IRQ__END] = {
>>> +    [AHCI_PORT_IRQ_BIT_DHRS] = "DHRS",
>>> +    [AHCI_PORT_IRQ_BIT_PSS]  = "PSS",
>>> +    [AHCI_PORT_IRQ_BIT_DSS]  = "DSS",
>>> +    [AHCI_PORT_IRQ_BIT_SDBS] = "SDBS",
>>> +    [AHCI_PORT_IRQ_BIT_UFS]  = "UFS",
>>> +    [AHCI_PORT_IRQ_BIT_DPS]  = "DPS",
>>> +    [AHCI_PORT_IRQ_BIT_PCS]  = "PCS",
>>> +    [AHCI_PORT_IRQ_BIT_DMPS] = "DMPS",
>>> +    [8 ... 21]               = "RESERVED",
>>> +    [AHCI_PORT_IRQ_BIT_PRCS] = "PRCS",
>>> +    [AHCI_PORT_IRQ_BIT_IPMS] = "IPMS",
>>> +    [AHCI_PORT_IRQ_BIT_OFS]  = "OFS",
>>> +    [25]                     = "RESERVED",
>>> +    [AHCI_PORT_IRQ_BIT_INFS] = "INFS",
>>> +    [AHCI_PORT_IRQ_BIT_IFS]  = "IFS",
>>> +    [AHCI_PORT_IRQ_BIT_HBDS] = "HBDS",
>>> +    [AHCI_PORT_IRQ_BIT_HBFS] = "HBFS",
>>> +    [AHCI_PORT_IRQ_BIT_TFES] = "TFES",
>>> +    [AHCI_PORT_IRQ_BIT_CPDS] = "CPDS"
>>> +};
>>>      static uint32_t  ahci_port_read(AHCIState *s, int port, int offset)
>>>    {
>>> @@ -170,12 +191,18 @@ static void ahci_check_irq(AHCIState *s)
>>>    }
>>>      static void ahci_trigger_irq(AHCIState *s, AHCIDevice *d,
>>> -                             int irq_type)
>>> +                             enum AHCIPortIRQ irqbit)
>>>    {
>>> -    DPRINTF(d->port_no, "trigger irq %#x -> %x\n",
>>> -            irq_type, d->port_regs.irq_mask & irq_type);
>>> +    g_assert(irqbit >= 0 && irqbit < 32);
>>
>> Since you now use an enum this check is no more necessary.
>>
> 
> You can actually still pass in a wrong value if you wanted to. This is
> to prevent old-style IRQ masks from getting passed in by accident.

No accident :) This is now an enum, also:

hw/ide$ git grep ahci_trigger_irq
ahci.c:764:        ahci_trigger_irq(s, ad, AHCI_PORT_IRQ_BIT_SDBS);
ahci.c:807:        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_TFES);
ahci.c:810:    ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_PSS);
ahci.c:850:        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_TFES);
ahci.c:853:    ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_DHRS);
ahci.c:1128:        ahci_trigger_irq(ad->hba, ad, AHCI_PORT_IRQ_BIT_OFS);
ahci.c:1276:        ahci_trigger_irq(s, &s->dev[port], 
AHCI_PORT_IRQ_BIT_HBFS);

You only use enum values, not any cast.

> 
>> However ...
>>
>>> +    uint32_t irq = 1U << irqbit;
>>> +    uint32_t irqstat = d->port_regs.irq_stat | irq;
>>>    -    d->port_regs.irq_stat |= irq_type;
>>> +    trace_ahci_trigger_irq(s, d->port_no,
>>> +                           AHCIPortIRQ_lookup[irqbit], irq,
>>> +                           d->port_regs.irq_stat, irqstat,
>>> +                           irqstat & d->port_regs.irq_mask);
>>> +
>>
>> Why not keep using masked irqs, and iterate over AHCI_PORT_IRQ__END
>> bits? Something like:
>>
>>      if (TRACE_AHCI_IRQ_ENABLED) {
>>          int irqbit;
>>          for (irqbit = 0; irqbit < AHCI_PORT_IRQ__END; irqbit++) {
>>              if (irqmask & BIT(irqbit)) {
>>                  trace_ahci_trigger_irq(s, d->port_no, ...
>>
> 
> Would rather not iterate like that for the IRQ path. Generally no place
> in the codebase needs to raise more than one IRQ type at a time, so why
> bother allowing it?

Indeed.

^ permalink raw reply	[flat|nested] 36+ messages in thread

* Re: [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events
  2017-08-29  0:15     ` John Snow
@ 2017-08-30  3:51       ` Philippe Mathieu-Daudé
  0 siblings, 0 replies; 36+ messages in thread
From: Philippe Mathieu-Daudé @ 2017-08-30  3:51 UTC (permalink / raw)
  To: John Snow, qemu-block; +Cc: qemu-devel, Stefan Hajnoczi

[...]
>>> +# hw/ide/ahci.c
>>> +ahci_port_read(void *s, int port, int offset, uint32_t ret)
>>> "ahci(%p)[%d]: port read @ 0x%x: 0x%08x"
>>> +ahci_irq_raise(void *s) "ahci(%p): raise irq"
>>> +ahci_irq_lower(void *s) "ahci(%p): lower irq"
>>> +ahci_check_irq(void *s, uint32_t old, uint32_t new) "ahci(%p): check
>>> irq 0x%08x --> 0x%08x"
>>> +
>>> +ahci_port_write(void *s, int port, int offset, uint32_t val)
>>> "ahci(%p)[%d]: port write @ 0x%x: 0x%08x"
>>> +ahci_mem_read_32(void *s, uint64_t addr, uint32_t val) "ahci(%p): mem
>>> read @ 0x%"PRIx64": 0x%08x"
>>
>> can you use same format than ahci_mem_read()?
>>
>> "ahci(%p): read%u @ 0x%"PRIx64":     0x%08x"
>>
>>> +ahci_mem_read(void *s, unsigned size, uint64_t addr, uint64_t val)
>>> "ahci(%p): read%u @ 0x%"PRIx64": 0x%016"PRIx64
>>> +ahci_mem_write(void *s, unsigned size, uint64_t addr, uint64_t val)
>>> "ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64
>>> +ahci_mem_write_unknown(void *s, uint64_t addr) "ahci(%p): write to
>>> unknown register 0x%"PRIx64
>>
>> report the value written, eventually:
>>
>> "ahci(%p): write%u @ 0x%"PRIx64": 0x%016"PRIx64" UNKNOWN"
>>
> 
> Not necessary here; it's reported by the more generic
> trace_ahci_mem_write which gets all of the writes no matter where they
> go. In this case, too, the write is actually ignored and doesn't wind up
> going anywhere ...
> 
> ... but I suppose it wouldn't hurt to know what that value would have
> been. If we enable just this trace that will probably help illuminate
> what the errant write is.
> 
>>> +ahci_set_signature(void *s, int port, uint8_t nsector, uint8_t
>>> sector, uint8_t lcyl, uint8_t hcyl, uint32_t sig) "ahci(%p)[%d]: set
>>> signature sector:0x%02x nsector:0x%02x lcyl:0x%02x hcyl:0x%02x
>>> (cumulatively: 0x%08x)"
>>> +ahci_reset_port(void *s, int port) "ahci(%p)[%d]: reset port"
>>
>> could be generic:
>>
>> ahci_port(void *s, int port) "ahci(%p)[%d]: %s"
>>
>> then
>>
>> trace_ahci_port(s, port, "reset port");
>>
> 
> I don't disagree, just more trepidation on what that means for the trace
> events which are otherwise all named exactly for the functions that call
> them.
> 
> Also, the problem with combining these sorts of traces becomes one with
> the DPRINTF we're replacing: you can't target individual sections of
> code anymore, and you either turn on "ahci_port" or off.

Oh I did not think of that, good point.

> 
> If there is a better suggestion for avoiding the ahci(%p)[%d]: pattern
> here over and over and over and over again I'd happily take it.
> 
> Stefan?
> 
> [...snip...]
> 
>>> +ahci_reset(void *s) "ahci(%p): HBA reset"
>>> +allwinner_ahci_mem_read(void *s, void *a, uint64_t addr, uint64_t
>>> val, unsigned size) "ahci(%p): read a=%p addr=0x%"HWADDR_PRIx"
>>> val=0x%"PRIx64", size=%d"
>>
>> is AllwinnerAHCIState useful?
>>
> 
> Only as far as it happens to be the argument to this function; of course
> AHCIState is the real prize, but we have to fish it out of
> AllwinnerAHCIState first.
> 
>> I'd rather use directly trace_ahci_mem_read(s, size, addr, val)
>>>> +allwinner_ahci_mem_write(void *s, void *a, uint64_t addr, uint64_t
>>> val, unsigned size) "ahci(%p): write a=%p addr=0x%"HWADDR_PRIx"
>>> val=0x%"PRIx64", size=%d"
>>
>> and trace_ahci_mem_write(s, size, addr, val)
>>
>> Regards,
>>
>> Phil.
> 

^ permalink raw reply	[flat|nested] 36+ messages in thread

end of thread, other threads:[~2017-08-30  3:51 UTC | newest]

Thread overview: 36+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-08-08 18:32 [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing John Snow
2017-08-08 18:32 ` [Qemu-devel] [PATCH 1/9] IDE: replace DEBUG_IDE with tracing system John Snow
2017-08-08 20:00   ` Eric Blake
2017-08-08 20:12     ` John Snow
2017-08-08 23:20     ` Philippe Mathieu-Daudé
2017-08-22 19:03     ` John Snow
2017-08-25 13:33   ` Philippe Mathieu-Daudé
2017-08-28 23:34     ` John Snow
2017-08-08 18:32 ` [Qemu-devel] [PATCH 2/9] IDE: Add register hints to tracing John Snow
2017-08-08 20:05   ` Eric Blake
2017-08-25 13:43   ` Philippe Mathieu-Daudé
2017-08-08 18:33 ` [Qemu-devel] [PATCH 3/9] IDE: add tracing for data ports John Snow
2017-08-08 20:10   ` Eric Blake
2017-08-08 20:17     ` John Snow
2017-08-08 20:30   ` Eric Blake
2017-08-08 20:36     ` Eric Blake
2017-08-08 20:44     ` John Snow
2017-08-08 18:33 ` [Qemu-devel] [PATCH 4/9] ATAPI: Replace DEBUG_IDE_ATAPI with tracing events John Snow
2017-08-08 20:59   ` Eric Blake
2017-08-28 23:43     ` John Snow
2017-08-08 18:33 ` [Qemu-devel] [PATCH 5/9] IDE: replace DEBUG_AIO with trace events John Snow
2017-08-25 13:46   ` Philippe Mathieu-Daudé
2017-08-29  0:26     ` John Snow
2017-08-08 18:33 ` [Qemu-devel] [PATCH 6/9] AHCI: Replace DPRINTF with trace-events John Snow
2017-08-25 13:17   ` Philippe Mathieu-Daudé
2017-08-29  0:15     ` John Snow
2017-08-30  3:51       ` Philippe Mathieu-Daudé
2017-08-08 18:33 ` [Qemu-devel] [PATCH 7/9] AHCI: Rework IRQ constants John Snow
2017-08-25 14:00   ` Philippe Mathieu-Daudé
2017-08-29  0:28     ` John Snow
2017-08-30  3:24       ` Philippe Mathieu-Daudé
2017-08-08 18:33 ` [Qemu-devel] [PATCH 8/9] AHCI: pretty-print FIS to buffer instead of stderr John Snow
2017-08-08 18:33 ` [Qemu-devel] [PATCH 9/9] AHCI: remove DPRINTF macro John Snow
2017-08-25 13:48   ` Philippe Mathieu-Daudé
2017-08-29  0:33     ` John Snow
2017-08-09  1:17 ` [Qemu-devel] [PATCH 0/9] IDE: replace printfs with tracing no-reply

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.