Re: [Qemu-devel] [PATCH 06/10] hw/mips/gt64xxx_pci: Convert debug printf()s to trace events

[Philippe Mathieu-Daudé]

Hi Aleksandar,

On 6/25/19 2:40 AM, Aleksandar Markovic wrote:
> 
> Philippe, can you hust clarify (explain) what is the criterium when to
> use log message, and when to use trace event, which are bith present in
> gt64xxx implementation.

The criterium is rather generic.

All those log/events are meant for developpers, and are disabled by default.

- DPRINTF()

  This is the older printf() method, flooding the stdout (confuse when
  the serial console is displayed on stdio).
  It is deprecated because you have to edit the source and recompile to
  be able to use it, and once enabled you can not disable it.
  Since it is compile-time disabled, it tends to bitrot (string formats
  are not updated).
  Not recommended for new design.

- qemu_log_mask(loglevel_bits, ...)

  These calls are filtered with the global qemu_loglevel.
  The log is output to the 'log_file' file if set, or to stderr.

  You can set the global loglevel from command line with '-d bits,...'
  and the global logfile with the '-D file.log' command line option.

  You can also set those globals at runtime using the HMP 'log' and
  'logfile' commands:

  (qemu) log help
  Log items (comma separated):
  none       remove all logs
  out_asm    show generated host assembly code for each compiled TB
  in_asm     show target assembly code for each compiled TB
  op         show micro ops for each compiled TB
  op_opt     show micro ops after optimization
  op_ind     show micro ops before indirect lowering
  [...]
  (qemu) log in_asm
  [...]
  (qemu) log none

  Note that this logging doesn't have precise timing information.

- qemu_log_mask(LOG_GUEST_ERROR, ...)

  You select this level with '-d guest_errors' or via HMP.
  This reports invalid hardware accesses from the guest (buggy firmware,
  code running on an incorrect machine).
  This is useful for developpers of bootloader, who might want to fix
  their incorrect accesses before trying the fw on real hardware.
  Hardware not always generate exception for these incorrect accesses.

  Error reported come from the guest, and QEMU is not responsible, nor
  need modification in its models.

- qemu_log_mask(LOG_UNIMP, ...)

  You select this one with '-d unimp' or via HMP.
  This reports accesses to devices QEMU is not modeling.
  Having the missing device correctly modeled is likely to change the
  guest code flow (device/driver initialization).
  This also log accesses to not-yet-implemented registers within a
  partially implemented device.
  The common case is an OS driver added new functionalities. The model
  was developped with a limited driver, newer drivers expect to set
  more features up.
  I don't use it with guests image I know are already working, but I
  often use it when trying an image with a newer/older kernel for
  example.

- trace events

  Tracing is more powerful than the previous items, but usually requires
  post-processing effort. It is usually targetting live/post-mortem
  debugging. You can use various trace backends. It has precise timing,
  is not invasite, thus is suitable for enterprise grade products.
  You tipically want to use the 'nop' backend which totally disable
  tracing when building a production release binary.

  Trace events are useful to debug the guest but also the QEMU code.
  They are better to debug asynchrone issues than log_mask.
  They are also very useful to measure timings.
  <Many more features to add here...>

  Some backends allow easy parsing of events for further (graphical)
  analysis.

  You can enable/disable traces at runtime with the HMP
  'trace-event NAME on|off' command:

  (qemu) info trace-events
  [...]
  memory_region_ops_write : state 0
  memory_region_ops_read : state 0
  ram_block_discard_range : state 0
  find_ram_offset_loop : state 0
  find_ram_offset : state 0
  dma_map_wait : state 0
  dma_blk_cb : state 0
  [...]
  (qemu) trace-event find* on
  (qemu) info trace-events
  [...]
  memory_region_ops_write : state 0
  memory_region_ops_read : state 0
  ram_block_discard_range : state 0
  find_ram_offset_loop : state 1
  find_ram_offset : state 1
  dma_map_wait : state 0
  dma_blk_cb : state 0
  [...]

  You can also use a file with filtered events.
  Example tracing how YAMON access the flash and setup the
  PCI bars:

  $ cat yamon.trace
  # all flash i/o, no data
  pflash*
  -pflash_data
  pci*
  gt64120*

  $ qemu-system-mipsel -M malta \
    -serial vc \
    -pflash dump.bin \
    -trace events=yamon.trace
  11281@1561456612.571933:gt64120_isd_remap ISD: 0x00000000@0x00000000
-> 0x00001000@0x14000000
  11284@1561456612.576392:gt64120_isd_remap ISD: 0x00001000@0x14000000
-> 0x00001000@0x1be00000
  11284@1561456612.627574:pci_cfg_write gt64120_pci 00:0 @0x20 <- 0x1be00000
  11284@1561456614.825315:gt64120_write gt64120 write INTRCAUSE
value:0xfff3ffff
  ...
  11284@1561456615.176261:pci_cfg_write cirrus-vga 18:0 @0x4 <- 0x2
  11284@1561456615.176275:pci_update_mappings_add d=0x564efb01dd50
00:12.0 0,0x10000000+0x2000000
  11284@1561456615.176672:pci_update_mappings_add d=0x564efb01dd50
00:12.0 1,0x12050000+0x1000
  ...

Hope that help!

Regards,

Phil.

>>  Makefile.objs         |  1 +
>>  hw/mips/gt64xxx_pci.c | 29 ++++++++++-------------------
>>  hw/mips/trace-events  |  4 ++++
>>  3 files changed, 15 insertions(+), 19 deletions(-)
>>  create mode 100644 hw/mips/trace-events
>>
>> diff --git a/Makefile.objs b/Makefile.objs
>> index 658cfc9d9f..3b83621f32 100644
>> --- a/Makefile.objs
>> +++ b/Makefile.objs
>> @@ -163,6 +163,7 @@ trace-events-subdirs += hw/input
>>  trace-events-subdirs += hw/intc
>>  trace-events-subdirs += hw/isa
>>  trace-events-subdirs += hw/mem
>> +trace-events-subdirs += hw/mips
>>  trace-events-subdirs += hw/misc
>>  trace-events-subdirs += hw/misc/macio
>>  trace-events-subdirs += hw/net
>> diff --git a/hw/mips/gt64xxx_pci.c b/hw/mips/gt64xxx_pci.c
>> index f44326f14f..815ef0711d 100644
>> --- a/hw/mips/gt64xxx_pci.c
>> +++ b/hw/mips/gt64xxx_pci.c
>> @@ -30,14 +30,7 @@
>>  #include "hw/pci/pci_host.h"
>>  #include "hw/i386/pc.h"
>>  #include "exec/address-spaces.h"
>> -
>> -//#define DEBUG
>> -
>> -#ifdef DEBUG
>> -#define DPRINTF(fmt, ...) fprintf(stderr, "%s: " fmt, __func__,
> ##__VA_ARGS__)
>> -#else
>> -#define DPRINTF(fmt, ...)
>> -#endif
>> +#include "trace.h"
>>
>>  #define GT_REGS                 (0x1000 >> 2)
>>
>> @@ -294,9 +287,7 @@ static void gt64120_isd_mapping(GT64120State *s)
>>      check_reserved_space(&start, &length);
>>      length = 0x1000;
>>      /* Map new address */
>> -    DPRINTF("ISD: "TARGET_FMT_plx"@"TARGET_FMT_plx
>> -        " -> "TARGET_FMT_plx"@"TARGET_FMT_plx"\n",
>> -        s->ISD_length, s->ISD_start, length, start);
>> +    trace_gt64120_isd_remap(s->ISD_length, s->ISD_start, length, start);
[...]