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 |  4 ++++
 2 files changed, 48 insertions(+), 10 deletions(-)

diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
index a0a4dd6..2e75f9b 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 e15fd77..77ed3c1 100644
--- a/hw/ide/trace-events
+++ b/hw/ide/trace-events
@@ -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"
+handle_cmd_fis_dump(void *s, int port, char *fis) "ahci(%p)[%d]: %s"
-- 
2.9.5

On Tue, Aug 29, 2017 at 04:49:33PM -0400, John Snow wrote:
> 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 |  4 ++++
>  2 files changed, 48 insertions(+), 10 deletions(-)
> 
> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
> index a0a4dd6..2e75f9b 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)

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.

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

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.

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

Same here.

> +        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 e15fd77..77ed3c1 100644
> --- a/hw/ide/trace-events
> +++ b/hw/ide/trace-events
> @@ -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

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

const char *fis

On 08/30/2017 05:17 AM, Stefan Hajnoczi wrote:
> On Tue, Aug 29, 2017 at 04:49:33PM -0400, John Snow wrote:
>> 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 |  4 ++++
>>  2 files changed, 48 insertions(+), 10 deletions(-)
>>
>> diff --git a/hw/ide/ahci.c b/hw/ide/ahci.c
>> index a0a4dd6..2e75f9b 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)
> 
> 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.
> 

eeeyyyyeahhhh I guess I don't need to be bleedingly efficient with debug
printfs...

And in this example I don't need to worry about the math being precisely
correct. I'll make the change :(

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

Oh, cool! Nice tip!

>> +            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) {
> 
> Same here.
> 

Sure thing. There's probably a block in ATAPI that needs this treatment,
too.

>> +        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 e15fd77..77ed3c1 100644
>> --- a/hw/ide/trace-events
>> +++ b/hw/ide/trace-events
>> @@ -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
> 
>> +handle_cmd_fis_dump(void *s, int port, char *fis) "ahci(%p)[%d]: %s"
> 
> const char *fis
> 

Thanks for the 👀