IDE: replace printfs with tracing

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 <[email protected]>

---
  hw/ide/core.c       | 12 +++++++++++-
  hw/ide/trace-events |  5 +++++
  2 files changed, 16 insertions(+), 1 deletion(-)

hw/ide/core.c +11 -1

index cb250e6..82a19b1 100644
@@ -2259,6 +2259,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)) {

@@ -2304,6 +2306,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;
  }
 

@@ -2313,6 +2317,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)) {

@@ -2343,7 +2349,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;

@@ -2358,6 +2365,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;
  }
 

hw/ide/trace-events +5 -0

index bff8f39..17bc6f1 100644
@@ -6,6 +6,11 @@ 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"
+# Warning: verbose
+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"

Signed-off-by John Snow <[email protected]>

---
  hw/ide/atapi.c            |  5 +----
  hw/ide/core.c             | 17 ++++++++++-------
  hw/ide/trace-events       |  3 +++
  include/hw/ide/internal.h |  6 ++++--
  4 files changed, 18 insertions(+), 13 deletions(-)

hw/ide/atapi.c +1 -4

index 37fa699..b8fc51e 100644
@@ -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);

hw/ide/core.c +10 -7

index 82a19b1..a1c90e9 100644
@@ -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__COUNT] = {
+    [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)) {

@@ -2391,9 +2396,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;
      }

hw/ide/trace-events +3 -0

index 8c79a6c..cc8949c 100644
@@ -18,6 +18,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"
 
  # BMDMA HBAs:
 

@@ -51,5 +53,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"

include/hw/ide/internal.h +0 -1

index 74efe8a..db9fde0 100644
@@ -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,15 @@ struct unreported_events {
  };
 

include/hw/ide/internal.h +1 -0

+
  #define ide_cmd_is_read(s) \
  	((s)->dma_cmd == IDE_DMA_READ)
 

Hi John,

Quoted 101 lines · John Snow

Signed-off-by John Snow <[email protected]>

---
  hw/ide/atapi.c            |  5 +----
  hw/ide/core.c             | 17 ++++++++++-------
  hw/ide/trace-events       |  3 +++
  include/hw/ide/internal.h |  6 ++++--
  4 files changed, 18 insertions(+), 13 deletions(-)

hw/ide/atapi.c +1 -4

index 37fa699..b8fc51e 100644
@@ -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);

hw/ide/core.c +8 -3

index 82a19b1..a1c90e9 100644
@@ -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__COUNT] = {
+    [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)) {

hw/ide/core.c +1 -3

@@ -2391,9 +2396,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;
      }

hw/ide/trace-events +0 -0

index 8c79a6c..cc8949c 100644
@@ -18,6 +18,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"

hw/ide/trace-events +2 -0

+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"
# BMDMA HBAs:
@@ -51,5 +53,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"

include/hw/ide/internal.h +0 -1

index 74efe8a..db9fde0 100644
@@ -14,7 +14,6 @@
  #include "block/scsi.h"
    /* debug IDE devices */
-//#define DEBUG_AIO
  #define USE_DMA_CDROM
    typedef struct IDEBus IDEBus;

include/hw/ide/internal.h struct unreported_events { · line 340

Quoted 10 lines

include/hw/ide/internal.h +2 -1

@@ -333,12 +332,15 @@ struct unreported_events {
  };
    enum ide_dma_cmd {
-    IDE_DMA_READ,
+    IDE_DMA_READ = 0,
      IDE_DMA_WRITE,
      IDE_DMA_TRIM,
      IDE_DMA_ATAPI,
+    IDE_DMA__COUNT
  };
  +extern const char *IDE_DMA_CMD_lookup[IDE_DMA__COUNT];

I recommend you to avoid this declaring extern const array with size, I remember some compilers (old GCC?) ignoring array size in extern. Eric will correct me!

It is much safer to use a getter:

const char *IDE_DMA_CMD_lookup(enum ide_dma_cmd cmd)

{
    static const char *IDE_DMA_CMD_name[IDE_DMA__COUNT] = {
        [IDE_DMA_READ] = "DMA READ",
        [IDE_DMA_WRITE] = "DMA WRITE",
        [IDE_DMA_TRIM] = "DMA TRIM",
        [IDE_DMA_ATAPI] = "DMA ATAPI"
    };

    return IDE_DMA_CMD_name[cmd];
};

If you agree:

Reviewed-by Philippe Mathieu-Daudé <[email protected]>

Quoted 4 lines

include/hw/ide/internal.h +1 -0

+
  #define ide_cmd_is_read(s) \
      ((s)->dma_cmd == IDE_DMA_READ)
 

CCing Laszlo Ersek literally just for laughs, as he is the most entertaining language lawyer I know of.

Laszlo, please feel free to ignore this if you don't care :P

Quoted 119 lines · Philippe Mathieu-Daudé

Hi John,

Quoted 101 lines · John Snow

Signed-off-by John Snow <[email protected]>

---
  hw/ide/atapi.c            |  5 +----
  hw/ide/core.c             | 17 ++++++++++-------
  hw/ide/trace-events       |  3 +++
  include/hw/ide/internal.h |  6 ++++--
  4 files changed, 18 insertions(+), 13 deletions(-)

hw/ide/atapi.c +1 -4

index 37fa699..b8fc51e 100644
@@ -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);

hw/ide/core.c +8 -3

index 82a19b1..a1c90e9 100644
@@ -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__COUNT] = {
+    [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)) {

hw/ide/core.c +1 -3

@@ -2391,9 +2396,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;
      }

hw/ide/trace-events +0 -0

index 8c79a6c..cc8949c 100644
@@ -18,6 +18,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"

hw/ide/trace-events +2 -0

+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"
# BMDMA HBAs:
@@ -51,5 +53,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"

include/hw/ide/internal.h +0 -1

index 74efe8a..db9fde0 100644
@@ -14,7 +14,6 @@
  #include "block/scsi.h"
    /* debug IDE devices */
-//#define DEBUG_AIO
  #define USE_DMA_CDROM
    typedef struct IDEBus IDEBus;

include/hw/ide/internal.h struct unreported_events { · line 340

Quoted 10 lines

include/hw/ide/internal.h +2 -1

@@ -333,12 +332,15 @@ struct unreported_events {
  };
    enum ide_dma_cmd {
-    IDE_DMA_READ,
+    IDE_DMA_READ = 0,
      IDE_DMA_WRITE,
      IDE_DMA_TRIM,
      IDE_DMA_ATAPI,
+    IDE_DMA__COUNT
  };
  +extern const char *IDE_DMA_CMD_lookup[IDE_DMA__COUNT];

I recommend you to avoid this declaring extern const array with size, I remember some compilers (old GCC?) ignoring array size in extern. Eric will correct me!

Quoted 2 lines

It is much safer to use a getter:

Well, whether or not the compiler ignores it, you're right that it's safer to use a getter. I don't think the width being declared HURTS any compiler though, does it?

Quoted 13 lines

const char *IDE_DMA_CMD_lookup(enum ide_dma_cmd cmd)

{
    static const char *IDE_DMA_CMD_name[IDE_DMA__COUNT] = {
        [IDE_DMA_READ] = "DMA READ",
        [IDE_DMA_WRITE] = "DMA WRITE",
        [IDE_DMA_TRIM] = "DMA TRIM",
        [IDE_DMA_ATAPI] = "DMA ATAPI"
    };

    return IDE_DMA_CMD_name[cmd];
};

Why is this safer...?

Here's my opinion of enums:

jhuston@probe ~/s/scratch> cat enum.c

enum foo {
    FOO_A = 0,
    FOO_B
};

int fn(enum foo in)

{
    switch (in) {
    case FOO_A:
    case FOO_B:
        return 0;
    default:
        return 1;
    }
}

int main(int argc, char *argv[])

{
    return fn(2);
}

jhuston@probe ~/s/scratch> gcc -ansi -Wall -pedantic -o enum enum.c jhuston@probe ~/s/scratch> ./enum
jhuston@probe ~/s/scratch> echo $status
1

No warnings, no messages, it just happily takes a value outside the domain and in this case it doesn't explode because I caught it, but, take a look:

jhuston@probe ~/s/scratch> cat enum.c
#include <stdio.h>

enum foo {
    FOO_A = 0,
    FOO_B,
    FOO__COUNT
};

const char *table[FOO__COUNT] = {"FOO_A", "FOO_B"};

int fn(enum foo in)

{
    fprintf(stderr, "%s\n", table[in]);
    switch (in) {
    case FOO_A:
    case FOO_B:
        return 0;
    default:
        return 1;
    }
}

int main(int argc, char *argv[])

{
    return fn(2);
}

Similar program, let's compile it:

jhuston@probe ~/s/scratch> gcc -ansi -Wall -pedantic -o enum enum.c jhuston@probe ~/s/scratch> ./enum
� �

Ah, dang.

This is why I prefer to have my assertions and don't trust enums to be checked rigorously.

For anyone playing along at home, yes, if you specify at least -O1 here it will catch it:

jhuston@probe ~/s/scratch> gcc -ansi -Wall -pedantic -O3 -o enum enum.c enum.c: In function ‘main’:
enum.c:13:5: warning: array subscript is above array bounds [-Warray-bounds]

     fprintf(stderr, "%s\n", table[in]);
     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Oh no, what the hell is clang up to, though?

jhuston@probe ~/s/scratch> clang -ansi -Wall -pedantic -O3 -o enum enum.c jhuston@probe ~/s/scratch>

Oh no...

http://i.imgur.com/uRvorq3.jpg

Quoted 4 lines

If you agree:

Reviewed-by Philippe Mathieu-Daudé <[email protected]>

Somewhat. I will write a getter that does bounds checking. It _is_ safer that way, though I don't think we'll ever run into a situation where it would come up.

Quoted 5 lines

Quoted 4 lines

include/hw/ide/internal.h +1 -0

+
  #define ide_cmd_is_read(s) \
      ((s)->dma_cmd == IDE_DMA_READ)
 

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

Signed-off-by John Snow <[email protected]>

---
  hw/ide/ahci.c       | 157 +++++++++++++++++++++++-----------------------------
  hw/ide/trace-events |  49 ++++++++++++++++
  2 files changed, 117 insertions(+), 89 deletions(-)

hw/ide/ahci.c +68 -89

index 406a1b5..c60a000 100644
@@ -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, size, addr, val);
          }
      } 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;
  }
 

hw/ide/trace-events +49 -0

index cc8949c..0b61c5d 100644
@@ -56,3 +56,52 @@ 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"
+
+# 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, unsigned size, uint64_t addr, uint64_t val) "ahci(%p): write%u to unknown register 0x%"PRIx64": 0x%016"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"

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 <[email protected]>

---
  hw/ide/ahci.c          | 49 ++++++++++++++++++++++++++++++++++++++-----------
  hw/ide/ahci_internal.h | 44 +++++++++++++++++++++++++++++++++++---------
  hw/ide/trace-events    |  2 +-
  3 files changed, 74 insertions(+), 21 deletions(-)

hw/ide/ahci.c +21 -0

index c60a000..a0a4dd6 100644
@@ -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)
  {

hw/ide/ahci.c +15 -8

+    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;
      }

hw/ide/ahci_internal.h +35 -9

index 1e21169..7e67add 100644
@@ -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 |    \

hw/ide/trace-events +1 -1

index 0b61c5d..e15fd77 100644
@@ -62,7 +62,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

Quoted 52 lines · 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 <[email protected]>

---
  hw/ide/ahci.c          | 49
++++++++++++++++++++++++++++++++++++++-----------
  hw/ide/ahci_internal.h | 44
+++++++++++++++++++++++++++++++++++---------
  hw/ide/trace-events    |  2 +-
  3 files changed, 74 insertions(+), 21 deletions(-)

hw/ide/ahci.c +20 -0

index c60a000..a0a4dd6 100644
@@ -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)
  {

hw/ide/ahci.c static void ahci_check_irq(AHCIState *s) · line 195

Quoted 8 lines

hw/ide/ahci.c +2 -3

@@ -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);

I still think this assert is superfluous, anyway (and having hard time reading C99 statement before declarations - I need to grow):

Reviewed-by Philippe Mathieu-Daudé <[email protected]>

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 <[email protected]>

---
 hw/ide/ahci.c       | 54 +++++++++++++++++++++++++++++++++++++++++++----------
 hw/ide/trace-events |  4 ++++
 2 files changed, 48 insertions(+), 10 deletions(-)

hw/ide/ahci.c +0 -0

index a0a4dd6..2e75f9b 100644

hw/ide/ahci.c +30 -6

 {
-#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)

hw/ide/ahci.c +5 -0

+            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 */
     }

hw/ide/ahci.c +5 -0

+        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);

hw/ide/trace-events +0 -0

index e15fd77..77ed3c1 100644

Quoted 15 lines · 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 <[email protected]>

---
 hw/ide/ahci.c       | 54 +++++++++++++++++++++++++++++++++++++++++++----------
 hw/ide/trace-events |  4 ++++
 2 files changed, 48 insertions(+), 10 deletions(-)

hw/ide/ahci.c +0 -0

index a0a4dd6..2e75f9b 100644

hw/ide/ahci.c static void ahci_reset_port(AHCIState *s, int port) · line 648

Quoted 6 lines

hw/ide/ahci.c +2 -1

@@ -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)

Simplified function using GString:

  static char *ahci_pretty_buffer_fis(const uint8_t *fis, int cmd_len)
  {
      GString *s = g_string_new("FIS:");
      int i;

      for (i = 0; i < cmd_len; i++) {
          if (i % 16 == 0) {
              g_string_append_printf(s, "\n0x%02x:", i);
	  }

          g_string_append_printf(s, " %02x", fis[i]);
      }

      g_string_append_c('\n');
      return g_string_free(s, FALSE);

}

It's less efficient due to extra mallocs but a lot easier to read.

Quoted 47 lines

hw/ide/ahci.c +30 -6

 {
-#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)

hw/ide/ahci.c static void handle_reg_h2d_fis(AHCIState *s, int port, · line 1229

Quoted 5 lines

hw/ide/ahci.c +1 -1

@@ -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) {

This should probably be:

  if (trace_event_get_state_backends(TRACE_HANDLE_REG_H2D_FIS_DUMP)) {

The difference is that TRACE_HANDLE_REG_H2D_FIS_DUMP_ENABLED is set at compile time while trace_event_get_state_backends() checks if the event is enabled at run-time.

Therefore TRACE_HANDLE_REG_H2D_FIS_DUMP_ENABLED causes the trace event to fire even when the user hasn't enabled the trace event yet. That would be a waste of CPU.

Quoted 9 lines

hw/ide/ahci.c +5 -0

+            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)

hw/ide/ahci.c static int handle_cmd(AHCIState *s, int port, uint8_t slot) · line 1289

Quoted 6 lines

hw/ide/ahci.c +1 -2

         trace_handle_cmd_badmap(s, port, cmd_len);
         goto out;
     }
-    debug_print_fis(cmd_fis, 0x80);
-
+    if (TRACE_HANDLE_CMD_FIS_DUMP_ENABLED) {

Same here.

Quoted 13 lines

hw/ide/ahci.c +5 -0

+        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);

hw/ide/trace-events +0 -0

index e15fd77..77ed3c1 100644

hw/ide/trace-events ahci_cmd_done(void *s, int port) "ahci(%p)[%d]: cmd done" · line 110

Quoted 6 lines

hw/ide/trace-events +3 -0

@@ -105,3 +105,7 @@ 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"
+
+# Warning: Verbose
+handle_reg_h2d_fis_dump(void *s, int port, char *fis) "ahci(%p)[%d]: %s"

const char *fis

hw/ide/trace-events ahci_cmd_done(void *s, int port) "ahci(%p)[%d]: cmd done" · line 111

Quoted 1 line

hw/ide/trace-events +1 -0

+handle_cmd_fis_dump(void *s, int port, char *fis) "ahci(%p)[%d]: %s"

const char *fis

Signed-off-by John Snow <[email protected]>

---
  hw/ide/ahci.c | 9 ---------
  1 file changed, 9 deletions(-)

hw/ide/ahci.c +0 -9

index 2e75f9b..57bb59d 100644
@@ -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);

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.

For V2, I opted to leave in the nearly redundant tracers for now with their individual names so that they can be targeted individually.