Re: [Qemu-devel] [Qemu-block] [PATCH v2 8/9] AHCI: pretty-print FIS to buffer instead of stderr

[John Snow]

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 <address@hidden>
>> ---
>>  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 👀