[RFC] vfio: migration to trace points

This patch removes all DPRINTF and replace them by trace points.
A few DPRINTF used in error cases were transformed into error_report.

Signed-off-by: Eric Auger <eric.auger@linaro.org>

---

- __func__ is removed since trace point name does the same job
- HWADDR_PRIx were replaced by PRIx64

Besides those changes format strings were kept the same. in few
cases however I was forced to change them due to parsing errors
(always related to parenthesis handling). This is indicated in
trace-events. Cases than are not correctly handled are given below:
- "(%04x:%02x:%02x.%x)" need to be replaced by " (%04x:%02x:%02x.%x)"
- "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d) = 0x%"PRIx64 ->
  "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64 ->
- "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d)"
  "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"
This is a temporary fix.

- This leads to a too large amount of trace points which may not be
eligible as trace points - I don't know?-
- this transformation just is tested compiled on PCI. Tested on platform
  qemu configured with --enable-trace-backends=stderr
- in future, format strings and calls may be simplified by using a single
  name argument instead of domain, bus, slot, function.
---
 hw/misc/vfio.c | 403 +++++++++++++++++++++++++++++----------------------------
 trace-events   |  79 +++++++++++
 2 files changed, 285 insertions(+), 197 deletions(-)

On 03.09.14 10:45, Eric Auger wrote:
> This patch removes all DPRINTF and replace them by trace points.
> A few DPRINTF used in error cases were transformed into error_report.
> 
> Signed-off-by: Eric Auger <eric.auger@linaro.org>
> 
> ---
> 
> - __func__ is removed since trace point name does the same job
> - HWADDR_PRIx were replaced by PRIx64
> 
> Besides those changes format strings were kept the same. in few
> cases however I was forced to change them due to parsing errors
> (always related to parenthesis handling). This is indicated in
> trace-events. Cases than are not correctly handled are given below:
> - "(%04x:%02x:%02x.%x)" need to be replaced by " (%04x:%02x:%02x.%x)"
> - "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d) = 0x%"PRIx64 ->
>   "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64 ->
> - "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d)"
>   "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"
> This is a temporary fix.
> 
> - This leads to a too large amount of trace points which may not be
> eligible as trace points - I don't know?-
> - this transformation just is tested compiled on PCI. Tested on platform
>   qemu configured with --enable-trace-backends=stderr
> - in future, format strings and calls may be simplified by using a single
>   name argument instead of domain, bus, slot, function.

I think it's a nice step into the right direction.


Alex

Hi,

For those who would like to try that patch and are not familiar with
trace points, here are some very basic instructions to start with.
- in your qemu configure command line, add
  --enable-trace-backends=stderr
  This enables the stderr trace backend.

- create a events.txt file where you launch qemu
  add the trace points you want to observe.
  list of trace points can be found in trace-events (qemu root dir).
  In the VFIO device, they are trace_<event>

  for instance add:
  vfio_intx_interrupt
  vfio_eoi

  wildcard seems to work as well. lines can be commented with #

- when launching qemu, add
  -trace events=events.txt

Complete details can be found in docs/tracing.txt

Best Regards

Eric



On 09/03/2014 10:45 AM, Eric Auger wrote:
> This patch removes all DPRINTF and replace them by trace points.
> A few DPRINTF used in error cases were transformed into error_report.
> 
> Signed-off-by: Eric Auger <eric.auger@linaro.org>
> 
> ---
> 
> - __func__ is removed since trace point name does the same job
> - HWADDR_PRIx were replaced by PRIx64
> 
> Besides those changes format strings were kept the same. in few
> cases however I was forced to change them due to parsing errors
> (always related to parenthesis handling). This is indicated in
> trace-events. Cases than are not correctly handled are given below:
> - "(%04x:%02x:%02x.%x)" need to be replaced by " (%04x:%02x:%02x.%x)"
> - "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d) = 0x%"PRIx64 ->
>   "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64 ->
> - "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d)"
>   "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"
> This is a temporary fix.
> 
> - This leads to a too large amount of trace points which may not be
> eligible as trace points - I don't know?-
> - this transformation just is tested compiled on PCI. Tested on platform
>   qemu configured with --enable-trace-backends=stderr
> - in future, format strings and calls may be simplified by using a single
>   name argument instead of domain, bus, slot, function.
> ---
>  hw/misc/vfio.c | 403 +++++++++++++++++++++++++++++----------------------------
>  trace-events   |  79 +++++++++++
>  2 files changed, 285 insertions(+), 197 deletions(-)
> 
> diff --git a/hw/misc/vfio.c b/hw/misc/vfio.c
> index 40dcaa6..6b6dee9 100644
> --- a/hw/misc/vfio.c
> +++ b/hw/misc/vfio.c
> @@ -40,15 +40,7 @@
>  #include "sysemu/kvm.h"
>  #include "sysemu/sysemu.h"
>  #include "hw/misc/vfio.h"
> -
> -/* #define DEBUG_VFIO */
> -#ifdef DEBUG_VFIO
> -#define DPRINTF(fmt, ...) \
> -    do { fprintf(stderr, "vfio: " fmt, ## __VA_ARGS__); } while (0)
> -#else
> -#define DPRINTF(fmt, ...) \
> -    do { } while (0)
> -#endif
> +#include "trace.h"
>  
>  /* Extra debugging, trap acceleration paths for more logging */
>  #define VFIO_ALLOW_MMAP 1
> @@ -365,9 +357,9 @@ static void vfio_intx_interrupt(void *opaque)
>          return;
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) Pin %c\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function,
> -            'A' + vdev->intx.pin);
> +    trace_vfio_intx_interrupt(vdev->host.domain, vdev->host.bus,
> +                              vdev->host.slot, vdev->host.function,
> +                              'A' + vdev->intx.pin);
>  
>      vdev->intx.pending = true;
>      pci_irq_assert(&vdev->pdev);
> @@ -384,8 +376,8 @@ static void vfio_eoi(VFIODevice *vdev)
>          return;
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) EOI\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_eoi(vdev->host.domain, vdev->host.bus,
> +                   vdev->host.slot, vdev->host.function);
>  
>      vdev->intx.pending = false;
>      pci_irq_deassert(&vdev->pdev);
> @@ -454,9 +446,8 @@ static void vfio_enable_intx_kvm(VFIODevice *vdev)
>  
>      vdev->intx.kvm_accel = true;
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) KVM INTx accel enabled\n",
> -            __func__, vdev->host.domain, vdev->host.bus,
> -            vdev->host.slot, vdev->host.function);
> +    trace_vfio_enable_intx_kvm(vdev->host.domain, vdev->host.bus,
> +                               vdev->host.slot, vdev->host.function);
>  
>      return;
>  
> @@ -508,9 +499,8 @@ static void vfio_disable_intx_kvm(VFIODevice *vdev)
>      /* If we've missed an event, let it re-fire through QEMU */
>      vfio_unmask_intx(vdev);
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) KVM INTx accel disabled\n",
> -            __func__, vdev->host.domain, vdev->host.bus,
> -            vdev->host.slot, vdev->host.function);
> +    trace_vfio_disable_intx_kvm(vdev->host.domain, vdev->host.bus,
> +                                vdev->host.slot, vdev->host.function);
>  #endif
>  }
>  
> @@ -529,9 +519,9 @@ static void vfio_update_irq(PCIDevice *pdev)
>          return; /* Nothing changed */
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) IRQ moved %d -> %d\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, vdev->intx.route.irq, route.irq);
> +    trace_vfio_update_irq(vdev->host.domain, vdev->host.bus,
> +                          vdev->host.slot, vdev->host.function,
> +                          vdev->intx.route.irq, route.irq);
>  
>      vfio_disable_intx_kvm(vdev);
>  
> @@ -607,8 +597,8 @@ static int vfio_enable_intx(VFIODevice *vdev)
>  
>      vdev->interrupt = VFIO_INT_INTx;
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x)\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_enable_intx(vdev->host.domain, vdev->host.bus,
> +                           vdev->host.slot, vdev->host.function);
>  
>      return 0;
>  }
> @@ -630,8 +620,8 @@ static void vfio_disable_intx(VFIODevice *vdev)
>  
>      vdev->interrupt = VFIO_INT_NONE;
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x)\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_disable_intx(vdev->host.domain, vdev->host.bus,
> +                            vdev->host.slot, vdev->host.function);
>  }
>  
>  /*
> @@ -658,9 +648,9 @@ static void vfio_msi_interrupt(void *opaque)
>          abort();
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) vector %d 0x%"PRIx64"/0x%x\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, nr, msg.address, msg.data);
> +    trace_vfio_msi_interrupt(vdev->host.domain, vdev->host.bus,
> +                             vdev->host.slot, vdev->host.function,
> +                             nr, msg.address, msg.data);
>  #endif
>  
>      if (vdev->interrupt == VFIO_INT_MSIX) {
> @@ -767,9 +757,9 @@ static int vfio_msix_vector_do_use(PCIDevice *pdev, unsigned int nr,
>      VFIOMSIVector *vector;
>      int ret;
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) vector %d used\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, nr);
> +    trace_vfio_msix_vector_do_use(vdev->host.domain, vdev->host.bus,
> +                                  vdev->host.slot, vdev->host.function,
> +                                  nr);
>  
>      vector = &vdev->msi_vectors[nr];
>  
> @@ -855,9 +845,9 @@ static void vfio_msix_vector_release(PCIDevice *pdev, unsigned int nr)
>      VFIODevice *vdev = DO_UPCAST(VFIODevice, pdev, pdev);
>      VFIOMSIVector *vector = &vdev->msi_vectors[nr];
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) vector %d released\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, nr);
> +    trace_vfio_msix_vector_release(vdev->host.domain, vdev->host.bus,
> +                                   vdev->host.slot, vdev->host.function,
> +                                   nr);
>  
>      /*
>       * There are still old guests that mask and unmask vectors on every
> @@ -920,8 +910,8 @@ static void vfio_enable_msix(VFIODevice *vdev)
>          error_report("vfio: msix_set_vector_notifiers failed");
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x)\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_enable_msix(vdev->host.domain, vdev->host.bus,
> +                           vdev->host.slot, vdev->host.function);
>  }
>  
>  static void vfio_enable_msi(VFIODevice *vdev)
> @@ -997,9 +987,9 @@ retry:
>          return;
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) Enabled %d MSI vectors\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, vdev->nr_vectors);
> +    trace_vfio_enable_msi(vdev->host.domain, vdev->host.bus,
> +                          vdev->host.slot, vdev->host.function,
> +                          vdev->nr_vectors);
>  }
>  
>  static void vfio_disable_msi_common(VFIODevice *vdev)
> @@ -1049,8 +1039,8 @@ static void vfio_disable_msix(VFIODevice *vdev)
>  
>      vfio_disable_msi_common(vdev);
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x)\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_disable_msix(vdev->host.domain, vdev->host.bus,
> +                            vdev->host.slot, vdev->host.function);
>  }
>  
>  static void vfio_disable_msi(VFIODevice *vdev)
> @@ -1058,8 +1048,8 @@ static void vfio_disable_msi(VFIODevice *vdev)
>      vfio_disable_irqindex(vdev, VFIO_PCI_MSI_IRQ_INDEX);
>      vfio_disable_msi_common(vdev);
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x)\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_disable_msi(vdev->host.domain, vdev->host.bus,
> +                           vdev->host.slot, vdev->host.function);
>  }
>  
>  static void vfio_update_msi(VFIODevice *vdev)
> @@ -1117,10 +1107,9 @@ static void vfio_bar_write(void *opaque, hwaddr addr,
>      {
>          VFIODevice *vdev = container_of(bar, VFIODevice, bars[bar->nr]);
>  
> -        DPRINTF("%s(%04x:%02x:%02x.%x:BAR%d+0x%"HWADDR_PRIx", 0x%"PRIx64
> -                ", %d)\n", __func__, vdev->host.domain, vdev->host.bus,
> -                vdev->host.slot, vdev->host.function, bar->nr, addr,
> -                data, size);
> +        trace_vfio_bar_write(vdev->host.domain, vdev->host.bus,
> +                             vdev->host.slot, vdev->host.function,
> +                             region->nr, addr, data, size);
>      }
>  #endif
>  
> @@ -1172,10 +1161,9 @@ static uint64_t vfio_bar_read(void *opaque,
>      {
>          VFIODevice *vdev = container_of(bar, VFIODevice, bars[bar->nr]);
>  
> -        DPRINTF("%s(%04x:%02x:%02x.%x:BAR%d+0x%"HWADDR_PRIx
> -                ", %d) = 0x%"PRIx64"\n", __func__, vdev->host.domain,
> -                vdev->host.bus, vdev->host.slot, vdev->host.function,
> -                bar->nr, addr, size, data);
> +        trace_vfio_bar_read(vdev->host.domain, vdev->host.bus,
> +                            vdev->host.slot, vdev->host.function,
> +                            region->nr, addr, size, data);
>      }
>  #endif
>  
> @@ -1206,11 +1194,11 @@ static void vfio_pci_load_rom(VFIODevice *vdev)
>          return;
>      }
>  
> -    DPRINTF("Device %04x:%02x:%02x.%x ROM:\n", vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> -    DPRINTF("  size: 0x%lx, offset: 0x%lx, flags: 0x%lx\n",
> -            (unsigned long)reg_info.size, (unsigned long)reg_info.offset,
> -            (unsigned long)reg_info.flags);
> +    trace_vfio_pci_load_rom(vdev->host.domain, vdev->host.bus,
> +                            vdev->host.slot, vdev->host.function,
> +                            (unsigned long)reg_info.size,
> +                            (unsigned long)reg_info.offset,
> +                            (unsigned long)reg_info.flags);
>  
>      vdev->rom_size = size = reg_info.size;
>      vdev->rom_offset = reg_info.offset;
> @@ -1281,9 +1269,9 @@ static uint64_t vfio_rom_read(void *opaque, hwaddr addr, unsigned size)
>          break;
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x, 0x%"HWADDR_PRIx", 0x%x) = 0x%"PRIx64"\n",
> -            __func__, vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, addr, size, data);
> +    trace_vfio_rom_read(vdev->host.domain, vdev->host.bus,
> +                        vdev->host.slot, vdev->host.function,
> +                        addr, size, data);
>  
>      return data;
>  }
> @@ -1379,8 +1367,9 @@ static void vfio_pci_size_rom(VFIODevice *vdev)
>          }
>      }
>  
> -    DPRINTF("%04x:%02x:%02x.%x ROM size 0x%x\n", vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function, size);
> +    trace_vfio_pci_size_rom(vdev->host.domain, vdev->host.bus,
> +                            vdev->host.slot, vdev->host.function,
> +                            size);
>  
>      snprintf(name, sizeof(name), "vfio[%04x:%02x:%02x.%x].rom",
>               vdev->host.domain, vdev->host.bus, vdev->host.slot,
> @@ -1429,8 +1418,7 @@ static void vfio_vga_write(void *opaque, hwaddr addr,
>                       __func__, region->offset + addr, data, size);
>      }
>  
> -    DPRINTF("%s(0x%"HWADDR_PRIx", 0x%"PRIx64", %d)\n",
> -            __func__, region->offset + addr, data, size);
> +    trace_vfio_vga_write(region->offset + addr, data, size);
>  }
>  
>  static uint64_t vfio_vga_read(void *opaque, hwaddr addr, unsigned size)
> @@ -1467,8 +1455,7 @@ static uint64_t vfio_vga_read(void *opaque, hwaddr addr, unsigned size)
>          break;
>      }
>  
> -    DPRINTF("%s(0x%"HWADDR_PRIx", %d) = 0x%"PRIx64"\n",
> -            __func__, region->offset + addr, size, data);
> +    trace_vfio_vga_read(region->offset + addr, size, data);
>  
>      return data;
>  }
> @@ -1515,10 +1502,13 @@ static uint64_t vfio_generic_window_quirk_read(void *opaque,
>          data = vfio_pci_read_config(&vdev->pdev,
>                                      quirk->data.address_val + offset, size);
>  
> -        DPRINTF("%s read(%04x:%02x:%02x.%x:BAR%d+0x%"HWADDR_PRIx", %d) = 0x%"
> -                PRIx64"\n", memory_region_name(&quirk->mem), vdev->host.domain,
> -                vdev->host.bus, vdev->host.slot, vdev->host.function,
> -                quirk->data.bar, addr, size, data);
> +        trace_vfio_generic_window_quirk_read(memory_region_name(&quirk->mem),
> +                                             vdev->host.domain,
> +                                             vdev->host.bus,
> +                                             vdev->host.slot,
> +                                             vdev->host.function,
> +                                             quirk->data.bar,
> +                                             addr, size, data);
>      } else {
>          data = vfio_bar_read(&vdev->bars[quirk->data.bar],
>                               addr + quirk->data.base_offset, size);
> @@ -1564,10 +1554,14 @@ static void vfio_generic_window_quirk_write(void *opaque, hwaddr addr,
>  
>          vfio_pci_write_config(&vdev->pdev,
>                                quirk->data.address_val + offset, data, size);
> -        DPRINTF("%s write(%04x:%02x:%02x.%x:BAR%d+0x%"HWADDR_PRIx", 0x%"
> -                PRIx64", %d)\n", memory_region_name(&quirk->mem),
> -                vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -                vdev->host.function, quirk->data.bar, addr, data, size);
> +
> +        trace_vfio_generic_window_quirk_write(memory_region_name(&quirk->mem),
> +                                             vdev->host.domain,
> +                                             vdev->host.bus,
> +                                             vdev->host.slot,
> +                                             vdev->host.function,
> +                                             quirk->data.bar,
> +                                             addr, data, size);
>          return;
>      }
>  
> @@ -1600,10 +1594,13 @@ static uint64_t vfio_generic_quirk_read(void *opaque,
>  
>          data = vfio_pci_read_config(&vdev->pdev, addr - offset, size);
>  
> -        DPRINTF("%s read(%04x:%02x:%02x.%x:BAR%d+0x%"HWADDR_PRIx", %d) = 0x%"
> -                PRIx64"\n", memory_region_name(&quirk->mem), vdev->host.domain,
> -                vdev->host.bus, vdev->host.slot, vdev->host.function,
> -                quirk->data.bar, addr + base, size, data);
> +        trace_vfio_generic_quirk_read(memory_region_name(&quirk->mem),
> +                                      vdev->host.domain,
> +                                      vdev->host.bus,
> +                                      vdev->host.slot,
> +                                      vdev->host.function,
> +                                      quirk->data.bar,
> +                                      addr + base, size, data);
>      } else {
>          data = vfio_bar_read(&vdev->bars[quirk->data.bar], addr + base, size);
>      }
> @@ -1629,10 +1626,13 @@ static void vfio_generic_quirk_write(void *opaque, hwaddr addr,
>  
>          vfio_pci_write_config(&vdev->pdev, addr - offset, data, size);
>  
> -        DPRINTF("%s write(%04x:%02x:%02x.%x:BAR%d+0x%"HWADDR_PRIx", 0x%"
> -                PRIx64", %d)\n", memory_region_name(&quirk->mem),
> -                vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -                vdev->host.function, quirk->data.bar, addr + base, data, size);
> +        trace_vfio_generic_quirk_write(memory_region_name(&quirk->mem),
> +                                       vdev->host.domain,
> +                                       vdev->host.bus,
> +                                       vdev->host.slot,
> +                                       vdev->host.function,
> +                                       quirk->data.bar,
> +                                       addr + base, data, size);
>      } else {
>          vfio_bar_write(&vdev->bars[quirk->data.bar], addr + base, data, size);
>      }
> @@ -1664,7 +1664,7 @@ static uint64_t vfio_ati_3c3_quirk_read(void *opaque,
>      uint64_t data = vfio_pci_read_config(&vdev->pdev,
>                                           PCI_BASE_ADDRESS_0 + (4 * 4) + 1,
>                                           size);
> -    DPRINTF("%s(0x3c3, 1) = 0x%"PRIx64"\n", __func__, data);
> +    trace_vfio_ati_3c3_quirk_read(data);
>  
>      return data;
>  }
> @@ -1702,9 +1702,8 @@ static void vfio_vga_probe_ati_3c3_quirk(VFIODevice *vdev)
>      QLIST_INSERT_HEAD(&vdev->vga.region[QEMU_PCI_VGA_IO_HI].quirks,
>                        quirk, next);
>  
> -    DPRINTF("Enabled ATI/AMD quirk 0x3c3 BAR4for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_vga_probe_ati_3c3_quirk(vdev->host.domain, vdev->host.bus,
> +                                       vdev->host.slot, vdev->host.function);
>  }
>  
>  /*
> @@ -1745,9 +1744,10 @@ static void vfio_probe_ati_bar4_window_quirk(VFIODevice *vdev, int nr)
>  
>      QLIST_INSERT_HEAD(&vdev->bars[nr].quirks, quirk, next);
>  
> -    DPRINTF("Enabled ATI/AMD BAR4 window quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_probe_ati_bar4_window_quirk(vdev->host.domain,
> +                                           vdev->host.bus,
> +                                           vdev->host.slot,
> +                                           vdev->host.function);
>  }
>  
>  #define PCI_VENDOR_ID_REALTEK 0x10ec
> @@ -1784,9 +1784,10 @@ static uint64_t vfio_rtl8168_window_quirk_read(void *opaque,
>      switch (addr) {
>      case 4: /* address */
>          if (quirk->data.flags) {
> -            DPRINTF("%s fake read(%04x:%02x:%02x.%d)\n",
> -                    memory_region_name(&quirk->mem), vdev->host.domain,
> -                    vdev->host.bus, vdev->host.slot, vdev->host.function);
> +            trace_vfio_rtl8168_window_quirk_read_fake(
> +                    memory_region_name(&quirk->mem),
> +                    vdev->host.domain, vdev->host.bus,
> +                    vdev->host.slot, vdev->host.function);
>  
>              return quirk->data.address_match ^ 0x10000000U;
>          }
> @@ -1795,9 +1796,11 @@ static uint64_t vfio_rtl8168_window_quirk_read(void *opaque,
>          if (quirk->data.flags) {
>              uint64_t val;
>  
> -            DPRINTF("%s MSI-X table read(%04x:%02x:%02x.%d)\n",
> -                    memory_region_name(&quirk->mem), vdev->host.domain,
> -                    vdev->host.bus, vdev->host.slot, vdev->host.function);
> +            trace_vfio_rtl8168_window_quirk_read_table(
> +                    memory_region_name(&quirk->mem),
> +                    vdev->host.domain, vdev->host.bus,
> +                    vdev->host.slot, vdev->host.function
> +               );
>  
>              if (!(vdev->pdev.cap_present & QEMU_PCI_CAP_MSIX)) {
>                  return 0;
> @@ -1810,9 +1813,10 @@ static uint64_t vfio_rtl8168_window_quirk_read(void *opaque,
>          }
>      }
>  
> -    DPRINTF("%s direct read(%04x:%02x:%02x.%d)\n",
> -            memory_region_name(&quirk->mem), vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_rtl8168_window_quirk_read_direct(
> +                        memory_region_name(&quirk->mem),
> +                        vdev->host.domain, vdev->host.bus,
> +                        vdev->host.slot, vdev->host.function);
>  
>      return vfio_bar_read(&vdev->bars[quirk->data.bar], addr + 0x70, size);
>  }
> @@ -1829,9 +1833,10 @@ static void vfio_rtl8168_window_quirk_write(void *opaque, hwaddr addr,
>              if (data & 0x10000000U &&
>                  vdev->pdev.cap_present & QEMU_PCI_CAP_MSIX) {
>  
> -                DPRINTF("%s MSI-X table write(%04x:%02x:%02x.%d)\n",
> -                        memory_region_name(&quirk->mem), vdev->host.domain,
> -                        vdev->host.bus, vdev->host.slot, vdev->host.function);
> +                trace_vfio_rtl8168_window_quirk_write_table(
> +                        memory_region_name(&quirk->mem),
> +                        vdev->host.domain, vdev->host.bus,
> +                        vdev->host.slot, vdev->host.function);
>  
>                  io_mem_write(&vdev->pdev.msix_table_mmio,
>                               (hwaddr)(quirk->data.address_match & 0xfff),
> @@ -1850,9 +1855,10 @@ static void vfio_rtl8168_window_quirk_write(void *opaque, hwaddr addr,
>          break;
>      }
>  
> -    DPRINTF("%s direct write(%04x:%02x:%02x.%d)\n",
> -            memory_region_name(&quirk->mem), vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_rtl8168_window_quirk_write_direct(
> +            memory_region_name(&quirk->mem),
> +            vdev->host.domain, vdev->host.bus,
> +            vdev->host.slot, vdev->host.function);
>  
>      vfio_bar_write(&vdev->bars[quirk->data.bar], addr + 0x70, data, size);
>  }
> @@ -1889,9 +1895,10 @@ static void vfio_probe_rtl8168_bar2_window_quirk(VFIODevice *vdev, int nr)
>  
>      QLIST_INSERT_HEAD(&vdev->bars[nr].quirks, quirk, next);
>  
> -    DPRINTF("Enabled RTL8168 BAR2 window quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_probe_rtl8168_bar2_window_quirk(vdev->host.domain,
> +                                               vdev->host.bus,
> +                                               vdev->host.slot,
> +                                               vdev->host.function);
>  }
>  /*
>   * Trap the BAR2 MMIO window to config space as well.
> @@ -1923,9 +1930,10 @@ static void vfio_probe_ati_bar2_4000_quirk(VFIODevice *vdev, int nr)
>  
>      QLIST_INSERT_HEAD(&vdev->bars[nr].quirks, quirk, next);
>  
> -    DPRINTF("Enabled ATI/AMD BAR2 0x4000 quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_probe_ati_bar2_4000_quirk(vdev->host.domain,
> +                                         vdev->host.bus,
> +                                         vdev->host.slot,
> +                                         vdev->host.function);
>  }
>  
>  /*
> @@ -1971,7 +1979,7 @@ static uint64_t vfio_nvidia_3d0_quirk_read(void *opaque,
>  
>      if (quirk->data.flags == NV_3D0_READ && addr == quirk->data.data_offset) {
>          data = vfio_pci_read_config(pdev, quirk->data.address_val, size);
> -        DPRINTF("%s(0x3d0, %d) = 0x%"PRIx64"\n", __func__, size, data);
> +        trace_vfio_nvidia_3d0_quirk_read(size, data);
>      }
>  
>      quirk->data.flags = NV_3D0_NONE;
> @@ -2014,7 +2022,7 @@ static void vfio_nvidia_3d0_quirk_write(void *opaque, hwaddr addr,
>          quirk->data.flags = NV_3D0_NONE;
>          if (addr == quirk->data.data_offset) {
>              vfio_pci_write_config(pdev, quirk->data.address_val, data, size);
> -            DPRINTF("%s(0x3d0, 0x%"PRIx64", %d)\n", __func__, data, size);
> +            trace_vfio_nvidia_3d0_quirk_write(data, size);
>              return;
>          }
>          break;
> @@ -2058,9 +2066,10 @@ static void vfio_vga_probe_nvidia_3d0_quirk(VFIODevice *vdev)
>      QLIST_INSERT_HEAD(&vdev->vga.region[QEMU_PCI_VGA_IO_HI].quirks,
>                        quirk, next);
>  
> -    DPRINTF("Enabled NVIDIA VGA 0x3d0 quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_vga_probe_nvidia_3d0_quirk(vdev->host.domain,
> +                                          vdev->host.bus,
> +                                          vdev->host.slot,
> +                                          vdev->host.function);
>  }
>  
>  /*
> @@ -2148,9 +2157,10 @@ static void vfio_probe_nvidia_bar5_window_quirk(VFIODevice *vdev, int nr)
>  
>      QLIST_INSERT_HEAD(&vdev->bars[nr].quirks, quirk, next);
>  
> -    DPRINTF("Enabled NVIDIA BAR5 window quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_probe_nvidia_bar5_window_quirk(vdev->host.domain,
> +                                              vdev->host.bus,
> +                                              vdev->host.slot,
> +                                              vdev->host.function);
>  }
>  
>  static void vfio_nvidia_88000_quirk_write(void *opaque, hwaddr addr,
> @@ -2220,9 +2230,10 @@ static void vfio_probe_nvidia_bar0_88000_quirk(VFIODevice *vdev, int nr)
>  
>      QLIST_INSERT_HEAD(&vdev->bars[nr].quirks, quirk, next);
>  
> -    DPRINTF("Enabled NVIDIA BAR0 0x88000 quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_probe_nvidia_bar0_88000_quirk(vdev->host.domain,
> +                                             vdev->host.bus,
> +                                             vdev->host.slot,
> +                                             vdev->host.function);
>  }
>  
>  /*
> @@ -2239,7 +2250,7 @@ static void vfio_probe_nvidia_bar0_1800_quirk(VFIODevice *vdev, int nr)
>      }
>  
>      /* Log the chipset ID */
> -    DPRINTF("Nvidia NV%02x\n",
> +    trace_vfio_probe_nvidia_bar0_1800_quirk_id(
>              (unsigned int)(vfio_bar_read(&vdev->bars[0], 0, 4) >> 20) & 0xff);
>  
>      quirk = g_malloc0(sizeof(*quirk));
> @@ -2258,9 +2269,10 @@ static void vfio_probe_nvidia_bar0_1800_quirk(VFIODevice *vdev, int nr)
>  
>      QLIST_INSERT_HEAD(&vdev->bars[nr].quirks, quirk, next);
>  
> -    DPRINTF("Enabled NVIDIA BAR0 0x1800 quirk for device %04x:%02x:%02x.%x\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_probe_nvidia_bar0_1800_quirk(vdev->host.domain,
> +                                            vdev->host.bus,
> +                                            vdev->host.slot,
> +                                            vdev->host.function);
>  }
>  
>  /*
> @@ -2346,9 +2358,9 @@ static uint32_t vfio_pci_read_config(PCIDevice *pdev, uint32_t addr, int len)
>  
>      val = (emu_val & emu_bits) | (phys_val & ~emu_bits);
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x, @0x%x, len=0x%x) %x\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, addr, len, val);
> +    trace_vfio_pci_read_config(vdev->host.domain, vdev->host.bus,
> +                               vdev->host.slot, vdev->host.function,
> +                               addr, len, val);
>  
>      return val;
>  }
> @@ -2359,9 +2371,9 @@ static void vfio_pci_write_config(PCIDevice *pdev, uint32_t addr,
>      VFIODevice *vdev = DO_UPCAST(VFIODevice, pdev, pdev);
>      uint32_t val_le = cpu_to_le32(val);
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x, @0x%x, 0x%x, len=0x%x)\n", __func__,
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, addr, val, len);
> +    trace_vfio_pci_write_config(vdev->host.domain, vdev->host.bus,
> +                                vdev->host.slot, vdev->host.function,
> +                                addr, val, len);
>  
>      /* Write everything to VFIO, let it filter out what we can't write */
>      if (pwrite(vdev->fd, &val_le, len, vdev->config_offset + addr) != len) {
> @@ -2423,7 +2435,7 @@ static int vfio_dma_unmap(VFIOContainer *container,
>      };
>  
>      if (ioctl(container->fd, VFIO_IOMMU_UNMAP_DMA, &unmap)) {
> -        DPRINTF("VFIO_UNMAP_DMA: %d\n", -errno);
> +        error_report("VFIO_UNMAP_DMA: %d\n", -errno);
>          return -errno;
>      }
>  
> @@ -2456,7 +2468,7 @@ static int vfio_dma_map(VFIOContainer *container, hwaddr iova,
>          return 0;
>      }
>  
> -    DPRINTF("VFIO_MAP_DMA: %d\n", -errno);
> +    error_report("VFIO_MAP_DMA: %d\n", -errno);
>      return -errno;
>  }
>  
> @@ -2484,8 +2496,8 @@ static void vfio_iommu_map_notify(Notifier *n, void *data)
>      void *vaddr;
>      int ret;
>  
> -    DPRINTF("iommu map @ %"HWADDR_PRIx" - %"HWADDR_PRIx"\n",
> -            iotlb->iova, iotlb->iova + iotlb->addr_mask);
> +    trace_vfio_iommu_map_notify(iotlb->iova,
> +                                iotlb->iova + iotlb->addr_mask);
>  
>      /*
>       * The IOMMU TLB entry we have just covers translation through
> @@ -2496,7 +2508,7 @@ static void vfio_iommu_map_notify(Notifier *n, void *data)
>                                   iotlb->translated_addr,
>                                   &xlat, &len, iotlb->perm & IOMMU_WO);
>      if (!memory_region_is_ram(mr)) {
> -        DPRINTF("iommu map to non memory area %"HWADDR_PRIx"\n",
> +        error_report("iommu map to non memory area %"HWADDR_PRIx"\n",
>                  xlat);
>          return;
>      }
> @@ -2505,7 +2517,7 @@ static void vfio_iommu_map_notify(Notifier *n, void *data)
>       * check that it did not truncate too much.
>       */
>      if (len & iotlb->addr_mask) {
> -        DPRINTF("iommu has granularity incompatible with target AS\n");
> +        error_report("iommu has granularity incompatible with target AS\n");
>          return;
>      }
>  
> @@ -2543,7 +2555,7 @@ static void vfio_listener_region_add(MemoryListener *listener,
>      int ret;
>  
>      if (vfio_listener_skipped_section(section)) {
> -        DPRINTF("SKIPPING region_add %"HWADDR_PRIx" - %"PRIx64"\n",
> +        trace_vfio_listener_region_add_skip(
>                  section->offset_within_address_space,
>                  section->offset_within_address_space +
>                  int128_get64(int128_sub(section->size, int128_one())));
> @@ -2570,8 +2582,8 @@ static void vfio_listener_region_add(MemoryListener *listener,
>      if (memory_region_is_iommu(section->mr)) {
>          VFIOGuestIOMMU *giommu;
>  
> -        DPRINTF("region_add [iommu] %"HWADDR_PRIx" - %"HWADDR_PRIx"\n",
> -                iova, int128_get64(int128_sub(llend, int128_one())));
> +        trace_vfio_listener_region_add_iommu(iova,
> +                    int128_get64(int128_sub(llend, int128_one())));
>          /*
>           * FIXME: We should do some checking to see if the
>           * capabilities of the host VFIO IOMMU are adequate to model
> @@ -2613,8 +2625,7 @@ static void vfio_listener_region_add(MemoryListener *listener,
>              section->offset_within_region +
>              (iova - section->offset_within_address_space);
>  
> -    DPRINTF("region_add [ram] %"HWADDR_PRIx" - %"HWADDR_PRIx" [%p]\n",
> -            iova, end - 1, vaddr);
> +    trace_vfio_listener_region_add_ram(iova, end - 1, vaddr);
>  
>      ret = vfio_dma_map(container, iova, end - iova, vaddr, section->readonly);
>      if (ret) {
> @@ -2646,7 +2657,7 @@ static void vfio_listener_region_del(MemoryListener *listener,
>      int ret;
>  
>      if (vfio_listener_skipped_section(section)) {
> -        DPRINTF("SKIPPING region_del %"HWADDR_PRIx" - %"PRIx64"\n",
> +        trace_vfio_listener_region_del_skip(
>                  section->offset_within_address_space,
>                  section->offset_within_address_space +
>                  int128_get64(int128_sub(section->size, int128_one())));
> @@ -2688,8 +2699,7 @@ static void vfio_listener_region_del(MemoryListener *listener,
>          return;
>      }
>  
> -    DPRINTF("region_del %"HWADDR_PRIx" - %"HWADDR_PRIx"\n",
> -            iova, end - 1);
> +    trace_vfio_listener_region_del(iova, end - 1);
>  
>      ret = vfio_dma_unmap(container, iova, end - iova);
>      memory_region_unref(section->mr);
> @@ -2744,8 +2754,8 @@ static int vfio_setup_msi(VFIODevice *vdev, int pos)
>      msi_maskbit = !!(ctrl & PCI_MSI_FLAGS_MASKBIT);
>      entries = 1 << ((ctrl & PCI_MSI_FLAGS_QMASK) >> 1);
>  
> -    DPRINTF("%04x:%02x:%02x.%x PCI MSI CAP @0x%x\n", vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function, pos);
> +    trace_vfio_setup_msi(vdev->host.domain, vdev->host.bus,
> +                         vdev->host.slot, vdev->host.function, pos);
>  
>      ret = msi_init(&vdev->pdev, pos, entries, msi_64bit, msi_maskbit);
>      if (ret < 0) {
> @@ -2805,11 +2815,11 @@ static int vfio_early_setup_msix(VFIODevice *vdev)
>      vdev->msix->pba_offset = pba & ~PCI_MSIX_FLAGS_BIRMASK;
>      vdev->msix->entries = (ctrl & PCI_MSIX_FLAGS_QSIZE) + 1;
>  
> -    DPRINTF("%04x:%02x:%02x.%x "
> -            "PCI MSI-X CAP @0x%x, BAR %d, offset 0x%x, entries %d\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function, pos, vdev->msix->table_bar,
> -            vdev->msix->table_offset, vdev->msix->entries);
> +    trace_vfio_early_setup_msix(vdev->host.domain, vdev->host.bus,
> +                                vdev->host.slot, vdev->host.function,
> +                                pos, vdev->msix->table_bar,
> +                                vdev->msix->table_offset,
> +                                vdev->msix->entries);
>  
>      return 0;
>  }
> @@ -3177,9 +3187,8 @@ static void vfio_check_pcie_flr(VFIODevice *vdev, uint8_t pos)
>      uint32_t cap = pci_get_long(vdev->pdev.config + pos + PCI_EXP_DEVCAP);
>  
>      if (cap & PCI_EXP_DEVCAP_FLR) {
> -        DPRINTF("%04x:%02x:%02x.%x Supports FLR via PCIe cap\n",
> -                vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -                vdev->host.function);
> +        trace_vfio_check_pcie_flr(vdev->host.domain, vdev->host.bus,
> +                                  vdev->host.slot, vdev->host.function);
>          vdev->has_flr = true;
>      }
>  }
> @@ -3189,9 +3198,8 @@ static void vfio_check_pm_reset(VFIODevice *vdev, uint8_t pos)
>      uint16_t csr = pci_get_word(vdev->pdev.config + pos + PCI_PM_CTRL);
>  
>      if (!(csr & PCI_PM_CTRL_NO_SOFT_RESET)) {
> -        DPRINTF("%04x:%02x:%02x.%x Supports PM reset\n",
> -                vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -                vdev->host.function);
> +        trace_vfio_check_pm_reset(vdev->host.domain, vdev->host.bus,
> +                                  vdev->host.slot, vdev->host.function);
>          vdev->has_pm_reset = true;
>      }
>  }
> @@ -3201,9 +3209,8 @@ static void vfio_check_af_flr(VFIODevice *vdev, uint8_t pos)
>      uint8_t cap = pci_get_byte(vdev->pdev.config + pos + PCI_AF_CAP);
>  
>      if ((cap & PCI_AF_CAP_TP) && (cap & PCI_AF_CAP_FLR)) {
> -        DPRINTF("%04x:%02x:%02x.%x Supports FLR via AF cap\n",
> -                vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -                vdev->host.function);
> +        trace_vfio_check_af_flr(vdev->host.domain, vdev->host.bus,
> +                                vdev->host.slot, vdev->host.function);
>          vdev->has_flr = true;
>      }
>  }
> @@ -3354,9 +3361,9 @@ static int vfio_pci_hot_reset(VFIODevice *vdev, bool single)
>      int ret, i, count;
>      bool multi = false;
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) %s\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function,
> -            single ? "one" : "multi");
> +    trace_vfio_pci_hot_reset(vdev->host.domain, vdev->host.bus,
> +                             vdev->host.slot, vdev->host.function,
> +                             single ? "one" : "multi");
>  
>      vfio_pci_pre_reset(vdev);
>      vdev->needs_reset = false;
> @@ -3387,9 +3394,10 @@ static int vfio_pci_hot_reset(VFIODevice *vdev, bool single)
>          goto out_single;
>      }
>  
> -    DPRINTF("%04x:%02x:%02x.%x: hot reset dependent devices:\n",
> -            vdev->host.domain, vdev->host.bus, vdev->host.slot,
> -            vdev->host.function);
> +    trace_vfio_pci_hot_reset_has_dep_devices(vdev->host.domain,
> +                                             vdev->host.bus,
> +                                             vdev->host.slot,
> +                                             vdev->host.function);
>  
>      /* Verify that we have all the groups required */
>      for (i = 0; i < info->count; i++) {
> @@ -3401,7 +3409,7 @@ static int vfio_pci_hot_reset(VFIODevice *vdev, bool single)
>          host.slot = PCI_SLOT(devices[i].devfn);
>          host.function = PCI_FUNC(devices[i].devfn);
>  
> -        DPRINTF("\t%04x:%02x:%02x.%x group %d\n", host.domain,
> +        trace_vfio_pci_hot_reset_dep_devices(host.domain,
>                  host.bus, host.slot, host.function, devices[i].group_id);
>  
>          if (vfio_pci_host_match(&host, &vdev->host)) {
> @@ -3429,7 +3437,7 @@ static int vfio_pci_hot_reset(VFIODevice *vdev, bool single)
>          QLIST_FOREACH(tmp, &group->device_list, next) {
>              if (vfio_pci_host_match(&host, &tmp->host)) {
>                  if (single) {
> -                    DPRINTF("vfio: found another in-use device "
> +                    error_report("vfio: found another in-use device "
>                              "%04x:%02x:%02x.%x\n", host.domain, host.bus,
>                              host.slot, host.function);
>                      ret = -EINVAL;
> @@ -3444,7 +3452,7 @@ static int vfio_pci_hot_reset(VFIODevice *vdev, bool single)
>      }
>  
>      if (!single && !multi) {
> -        DPRINTF("vfio: No other in-use devices for multi hot reset\n");
> +        error_report("vfio: No other in-use devices for multi hot reset\n");
>          ret = -EINVAL;
>          goto out_single;
>      }
> @@ -3478,9 +3486,11 @@ static int vfio_pci_hot_reset(VFIODevice *vdev, bool single)
>      ret = ioctl(vdev->fd, VFIO_DEVICE_PCI_HOT_RESET, reset);
>      g_free(reset);
>  
> -    DPRINTF("%04x:%02x:%02x.%x hot reset: %s\n", vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function,
> -            ret ? "%m" : "Success");
> +    trace_vfio_pci_hot_reset_result(vdev->host.domain,
> +                                    vdev->host.bus,
> +                                    vdev->host.slot,
> +                                    vdev->host.function,
> +                                    ret ? "%m" : "Success");
>  
>  out:
>      /* Re-enable INTx on affected devices */
> @@ -3587,7 +3597,7 @@ static void vfio_kvm_device_add_group(VFIOGroup *group)
>          };
>  
>          if (kvm_vm_ioctl(kvm_state, KVM_CREATE_DEVICE, &cd)) {
> -            DPRINTF("KVM_CREATE_DEVICE: %m\n");
> +            error_report("KVM_CREATE_DEVICE: %m\n");
>              return;
>          }
>  
> @@ -3794,7 +3804,7 @@ static void vfio_disconnect_container(VFIOGroup *group)
>              container->iommu_data.release(container);
>          }
>          QLIST_REMOVE(container, next);
> -        DPRINTF("vfio_disconnect_container: close container->fd\n");
> +        trace_vfio_disconnect_container(container->fd);
>          close(container->fd);
>          g_free(container);
>  
> @@ -3878,7 +3888,7 @@ static void vfio_put_group(VFIOGroup *group)
>      vfio_kvm_device_del_group(group);
>      vfio_disconnect_container(group);
>      QLIST_REMOVE(group, next);
> -    DPRINTF("vfio_put_group: close group->fd\n");
> +    trace_vfio_put_group(group->fd);
>      close(group->fd);
>      g_free(group);
>  
> @@ -3914,8 +3924,8 @@ static int vfio_get_device(VFIOGroup *group, const char *name, VFIODevice *vdev)
>          goto error;
>      }
>  
> -    DPRINTF("Device %s flags: %u, regions: %u, irgs: %u\n", name,
> -            dev_info.flags, dev_info.num_regions, dev_info.num_irqs);
> +    trace_vfio_get_device_irq(name, dev_info.flags,
> +                              dev_info.num_regions, dev_info.num_irqs);
>  
>      if (!(dev_info.flags & VFIO_DEVICE_FLAGS_PCI)) {
>          error_report("vfio: Um, this isn't a PCI device");
> @@ -3944,10 +3954,10 @@ static int vfio_get_device(VFIOGroup *group, const char *name, VFIODevice *vdev)
>              goto error;
>          }
>  
> -        DPRINTF("Device %s region %d:\n", name, i);
> -        DPRINTF("  size: 0x%lx, offset: 0x%lx, flags: 0x%lx\n",
> -                (unsigned long)reg_info.size, (unsigned long)reg_info.offset,
> -                (unsigned long)reg_info.flags);
> +        trace_vfio_get_device_region(name, i,
> +                                     (unsigned long)reg_info.size,
> +                                     (unsigned long)reg_info.offset,
> +                                     (unsigned long)reg_info.flags);
>  
>          vdev->bars[i].flags = reg_info.flags;
>          vdev->bars[i].size = reg_info.size;
> @@ -3965,10 +3975,9 @@ static int vfio_get_device(VFIOGroup *group, const char *name, VFIODevice *vdev)
>          goto error;
>      }
>  
> -    DPRINTF("Device %s config:\n", name);
> -    DPRINTF("  size: 0x%lx, offset: 0x%lx, flags: 0x%lx\n",
> -            (unsigned long)reg_info.size, (unsigned long)reg_info.offset,
> -            (unsigned long)reg_info.flags);
> +    trace_vfio_get_device_config(name, (unsigned long)reg_info.size,
> +                                 (unsigned long)reg_info.offset,
> +                                 (unsigned long)reg_info.flags);
>  
>      vdev->config_size = reg_info.size;
>      if (vdev->config_size == PCI_CONFIG_SPACE_SIZE) {
> @@ -4021,7 +4030,7 @@ static int vfio_get_device(VFIOGroup *group, const char *name, VFIODevice *vdev)
>      ret = ioctl(vdev->fd, VFIO_DEVICE_GET_IRQ_INFO, &irq_info);
>      if (ret) {
>          /* This can fail for an old kernel or legacy PCI dev */
> -        DPRINTF("VFIO_DEVICE_GET_IRQ_INFO failure: %m\n");
> +        trace_vfio_get_device_get_irq_info_failure();
>          ret = 0;
>      } else if (irq_info.count == 1) {
>          vdev->pci_aer = true;
> @@ -4045,7 +4054,7 @@ static void vfio_put_device(VFIODevice *vdev)
>  {
>      QLIST_REMOVE(vdev, next);
>      vdev->group = NULL;
> -    DPRINTF("vfio_put_device: close vdev->fd\n");
> +    trace_vfio_put_device(vdev->fd);
>      close(vdev->fd);
>      if (vdev->msix) {
>          g_free(vdev->msix);
> @@ -4194,8 +4203,8 @@ static int vfio_initfn(PCIDevice *pdev)
>          return -errno;
>      }
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x) group %d\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function, groupid);
> +    trace_vfio_initfn(vdev->host.domain, vdev->host.bus,
> +                      vdev->host.slot, vdev->host.function, groupid);
>  
>      group = vfio_get_group(groupid, pci_device_iommu_address_space(pdev));
>      if (!group) {
> @@ -4336,15 +4345,15 @@ static void vfio_pci_reset(DeviceState *dev)
>      PCIDevice *pdev = DO_UPCAST(PCIDevice, qdev, dev);
>      VFIODevice *vdev = DO_UPCAST(VFIODevice, pdev, pdev);
>  
> -    DPRINTF("%s(%04x:%02x:%02x.%x)\n", __func__, vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +    trace_vfio_pci_reset(vdev->host.domain, vdev->host.bus,
> +                         vdev->host.slot, vdev->host.function);
>  
>      vfio_pci_pre_reset(vdev);
>  
>      if (vdev->reset_works && (vdev->has_flr || !vdev->has_pm_reset) &&
>          !ioctl(vdev->fd, VFIO_DEVICE_RESET)) {
> -        DPRINTF("%04x:%02x:%02x.%x FLR/VFIO_DEVICE_RESET\n", vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +        trace_vfio_pci_reset_flr(vdev->host.domain, vdev->host.bus,
> +                                  vdev->host.slot, vdev->host.function);
>          goto post_reset;
>      }
>  
> @@ -4356,8 +4365,8 @@ static void vfio_pci_reset(DeviceState *dev)
>      /* If nothing else works and the device supports PM reset, use it */
>      if (vdev->reset_works && vdev->has_pm_reset &&
>          !ioctl(vdev->fd, VFIO_DEVICE_RESET)) {
> -        DPRINTF("%04x:%02x:%02x.%x PCI PM Reset\n", vdev->host.domain,
> -            vdev->host.bus, vdev->host.slot, vdev->host.function);
> +        trace_vfio_pci_reset_pm(vdev->host.domain, vdev->host.bus,
> +                                vdev->host.slot, vdev->host.function);
>          goto post_reset;
>      }
>  
> diff --git a/trace-events b/trace-events
> index 03ac5d2..7931760 100644
> --- a/trace-events
> +++ b/trace-events
> @@ -1298,6 +1298,85 @@ xen_pv_mmio_write(uint64_t addr) "WARNING: write to Xen PV Device MMIO space (ad
>  pci_cfg_read(const char *dev, unsigned devid, unsigned fnid, unsigned offs, unsigned val) "%s %02u:%u @0x%x -> 0x%x"
>  pci_cfg_write(const char *dev, unsigned devid, unsigned fnid, unsigned offs, unsigned val) "%s %02u:%u @0x%x <- 0x%x"
>  
> +# hw/vfio/vfio-pci.c
> +#forced to add a white space before ( due to parsing error
> +vfio_intx_interrupt(int domain, int bus, int slot, int fn, char line) " (%04x:%02x:%02x.%x) Pin %c"
> +vfio_eoi(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x) EOI"
> +vfio_enable_intx_kvm(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x) KVM INTx accel enabled"
> +vfio_disable_intx_kvm(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x) KVM INTx accel disabled"
> +vfio_update_irq(int domain, int bus, int slot, int fn, int new_irq, int target_irq) " (%04x:%02x:%02x.%x) IRQ moved %d -> %d"
> +vfio_enable_intx(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x)"
> +vfio_disable_intx(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x)"
> +vfio_msi_interrupt(int domain, int bus, int slot, int fn, int index, uint64_t addr, int data) " (%04x:%02x:%02x.%x) vector %d 0x%"PRIx64"/0x%x"
> +vfio_msix_vector_do_use(int domain, int bus, int slot, int fn, int index) " (%04x:%02x:%02x.%x) vector %d used"
> +vfio_msix_vector_release(int domain, int bus, int slot, int fn, int index) " (%04x:%02x:%02x.%x) vector %d released"
> +vfio_enable_msix(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x)"
> +vfio_enable_msi(int domain, int bus, int slot, int fn, int nr_vectors) " (%04x:%02x:%02x.%x) Enabled %d MSI vectors"
> +vfio_disable_msix(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x)"
> +vfio_disable_msi(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x)"
> +vfio_pci_load_rom(int domain, int bus, int slot, int fn, unsigned long size, unsigned long offset, unsigned long flags) "Device %04x:%02x:%02x.%x ROM:\n  size: 0x%lx, offset: 0x%lx, flags: 0x%lx"
> +vfio_rom_read(int domain, int bus, int slot, int fn, uint64_t addr, int size, uint64_t data) " (%04x:%02x:%02x.%x, 0x%"PRIx64", 0x%x) = 0x%"PRIx64
> +vfio_pci_size_rom(int domain, int bus, int slot, int fn, int size) "%04x:%02x:%02x.%x ROM size 0x%x"
> +vfio_vga_write(uint64_t addr, uint64_t data, int size) " (0x%"PRIx64", 0x%"PRIx64", %d)"
> +vfio_vga_read(uint64_t addr, int size, uint64_t data) " (0x%"PRIx64", %d) = 0x%"PRIx64
> +# remove ) = due to parser error
> +vfio_generic_window_quirk_read(const char * region_name, int domain, int bus, int slot, int fn, int index, uint64_t addr, int size, uint64_t data) "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64
> +# remove )
> +vfio_generic_window_quirk_write(const char * region_name, int domain, int bus, int slot, int fn, int index, uint64_t addr, uint64_t data, int size) "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"
> +# remove ) =
> +vfio_generic_quirk_read(const char * region_name, int domain, int bus, int slot, int fn, int index, uint64_t addr, int size, uint64_t data) "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64
> +# remove )
> +vfio_generic_quirk_write(const char * region_name, int domain, int bus, int slot, int fn, int index, uint64_t addr, uint64_t data, int size) "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"
> +vfio_ati_3c3_quirk_read(uint64_t data) " (0x3c3, 1) = 0x%"PRIx64
> +vfio_vga_probe_ati_3c3_quirk(int domain, int bus, int slot, int fn) "Enabled ATI/AMD quirk 0x3c3 BAR4 for device %04x:%02x:%02x.%x"
> +vfio_probe_ati_bar4_window_quirk(int domain, int bus, int slot, int fn) "Enabled ATI/AMD BAR4 window quirk for device %04x:%02x:%02x.%x"
> +#issue with )
> +vfio_rtl8168_window_quirk_read_fake(const char *region_name, int domain, int bus, int slot, int fn) "%s fake read(%04x:%02x:%02x.%d"
> +vfio_rtl8168_window_quirk_read_table(const char *region_name, int domain, int bus, int slot, int fn) "%s MSI-X table read(%04x:%02x:%02x.%d"
> +vfio_rtl8168_window_quirk_read_direct(const char *region_name, int domain, int bus, int slot, int fn) "%s direct read(%04x:%02x:%02x.%d"
> +vfio_rtl8168_window_quirk_write_table(const char *region_name, int domain, int bus, int slot, int fn) "%s MSI-X table write(%04x:%02x:%02x.%d"
> +vfio_rtl8168_window_quirk_write_direct(const char *region_name, int domain, int bus, int slot, int fn) "%s direct write(%04x:%02x:%02x.%d"
> +vfio_probe_rtl8168_bar2_window_quirk(int domain, int bus, int slot, int fn) "Enabled RTL8168 BAR2 window quirk for device %04x:%02x:%02x.%x"
> +vfio_probe_ati_bar2_4000_quirk(int domain, int bus, int slot, int fn) "Enabled ATI/AMD BAR2 0x4000 quirk for device %04x:%02x:%02x.%x"
> +vfio_nvidia_3d0_quirk_read(int size, uint64_t data) " (0x3d0, %d) = 0x%"PRIx64
> +vfio_nvidia_3d0_quirk_write(uint64_t data, int size) " (0x3d0, 0x%"PRIx64", %d)"
> +vfio_vga_probe_nvidia_3d0_quirk(int domain, int bus, int slot, int fn) "Enabled NVIDIA VGA 0x3d0 quirk for device %04x:%02x:%02x.%x"
> +vfio_probe_nvidia_bar5_window_quirk(int domain, int bus, int slot, int fn) "Enabled NVIDIA BAR5 window quirk for device %04x:%02x:%02x.%x"
> +vfio_probe_nvidia_bar0_88000_quirk(int domain, int bus, int slot, int fn) "Enabled NVIDIA BAR0 0x88000 quirk for device %04x:%02x:%02x.%x"
> +vfio_probe_nvidia_bar0_1800_quirk_id(int id) "Nvidia NV%02x"
> +vfio_probe_nvidia_bar0_1800_quirk(int domain, int bus, int slot, int fn) "Enabled NVIDIA BAR0 0x1800 quirk for device %04x:%02x:%02x.%x"
> +vfio_pci_read_config(int domain, int bus, int slot, int fn, int addr, int len, int val) " (%04x:%02x:%02x.%x, @0x%x, len=0x%x) %x"
> +vfio_pci_write_config(int domain, int bus, int slot, int fn, int addr, int val, int len) " (%04x:%02x:%02x.%x, @0x%x, 0x%x, len=0x%x)"
> +vfio_setup_msi(int domain, int bus, int slot, int fn, int pos) "%04x:%02x:%02x.%x PCI MSI CAP @0x%x"
> +vfio_early_setup_msix(int domain, int bus, int slot, int fn, int pos, int table_bar, int offset, int entries) "%04x:%02x:%02x.%x PCI MSI-X CAP @0x%x, BAR %d, offset 0x%x, entries %d"
> +vfio_check_pcie_flr(int domain, int bus, int slot, int fn) "%04x:%02x:%02x.%x Supports FLR via PCIe cap"
> +vfio_check_pm_reset(int domain, int bus, int slot, int fn) "%04x:%02x:%02x.%x Supports PM reset"
> +vfio_check_af_flr(int domain, int bus, int slot, int fn) "%04x:%02x:%02x.%x Supports FLR via AF cap"
> +vfio_pci_hot_reset(int domain, int bus, int slot, int fn, const char *type) " (%04x:%02x:%02x.%x) %s"
> +vfio_pci_hot_reset_has_dep_devices(int domain, int bus, int slot, int fn) "%04x:%02x:%02x.%x: hot reset dependent devices:"
> +vfio_pci_hot_reset_dep_devices(int domain, int bus, int slot, int function, int group_id) "\t%04x:%02x:%02x.%x group %d"
> +vfio_pci_hot_reset_result(int domain, int bus, int slot, int fn, const char *result) "%04x:%02x:%02x.%x hot reset: %s"
> +vfio_get_device_region(const char *region_name, int index, unsigned long size, unsigned long offset, unsigned long flags) "Device %s region %d:\n  size: 0x%lx, offset: 0x%lx, flags: 0x%lx"
> +vfio_get_device_config(const char *name, unsigned long size, unsigned long offset, unsigned long flags) "Device %s config:\n  size: 0x%lx, offset: 0x%lx, flags: 0x%lx"
> +vfio_get_device_get_irq_info_failure(void) "VFIO_DEVICE_GET_IRQ_INFO failure: %m"
> +vfio_get_device_irq(const char *name, unsigned flags, unsigned num_regions, unsigned num_irqs) "Device %s flags: %u, regions: %u, irgs: %u"
> +vfio_initfn(int domain, int bus, int slot, int fn, int group_id) " (%04x:%02x:%02x.%x) group %d"
> +vfio_pci_reset(int domain, int bus, int slot, int fn) " (%04x:%02x:%02x.%x)"
> +vfio_pci_reset_flr(int domain, int bus, int slot, int fn) "%04x:%02x:%02x.%x FLR/VFIO_DEVICE_RESET"
> +vfio_pci_reset_pm(int domain, int bus, int slot, int fn) "%04x:%02x:%02x.%x PCI PM Reset"
> +
> +vfio_bar_write(int domain, int bus, int slot, int fn, int index, uint64_t addr, uint64_t data, unsigned size) " (%04x:%02x:%02x.%x:region%d+0x%"PRIx64", 0x%"PRIx64 ", %d)"
> +vfio_bar_read(int domain, int bus, int slot, int fn, int index, uint64_t addr, unsigned size, uint64_t data) " (%04x:%02x:%02x.%x:region%d+0x%"PRIx64", %d) = 0x%"PRIx64
> +vfio_iommu_map_notify(uint64_t iova_start, uint64_t iova_end) "iommu map @ %"PRIx64" - %"PRIx64
> +vfio_listener_region_add_skip(uint64_t start, uint64_t end) "SKIPPING region_add %"PRIx64" - %"PRIx64
> +vfio_listener_region_add_iommu(uint64_t start, uint64_t end) "region_add [iommu] %"PRIx64" - %"PRIx64
> +vfio_listener_region_add_ram(uint64_t iova_start, uint64_t iova_end, void *vaddr) "region_add [ram] %"PRIx64" - %"PRIx64" [%p]"
> +vfio_listener_region_del_skip(uint64_t start, uint64_t end) "SKIPPING region_del %"PRIx64" - %"PRIx64
> +vfio_listener_region_del(uint64_t start, uint64_t end) "region_del %"PRIx64" - %"PRIx64
> +vfio_disconnect_container(int fd) "close container->fd=%d"
> +vfio_put_group(int fd) "close group->fd=%d"
> +vfio_put_device(int fd) "close vdev->fd=%d"
> +
>  #hw/acpi/memory_hotplug.c
>  mhp_acpi_invalid_slot_selected(uint32_t slot) "0x%"PRIx32
>  mhp_acpi_read_addr_lo(uint32_t slot, uint32_t addr) "slot[0x%"PRIx32"] addr lo: 0x%"PRIx32
>

On Wed, Sep 03, 2014 at 09:45:14AM +0100, Eric Auger wrote:
> This patch removes all DPRINTF and replace them by trace points.
> A few DPRINTF used in error cases were transformed into error_report.
> 
> Signed-off-by: Eric Auger <eric.auger@linaro.org>

The subject line says "RFC".  Are you proposing this patch for merge?

Did you want me to take it into the tracing tree?

Stefan

Hi Stefan,

Thanks for asking. Actually I think this is a bit early. I would like
some VFIO PCI users experiencing it a little bit (typically Alex) and
confirm they are happy with it.

Also as I mentionned in the commit message, I identified some parsing
issues that forced me to change few format strings. I don't know if you
have time or are willing to fix those - you may be more efficient doing
those fixes than I would;-) - Nethertheless if you can't afford, I will
have a look at the Python code.

For convenience I put the issues again, all related to parenthesis:

Cases than are not correctly handled are given below:
- "(%04x:%02x:%02x.%x)" need to be replaced by " (%04x:%02x:%02x.%x)"
- "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d) = 0x%"PRIx64 replaced by
  "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64
- "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d)"
replaced by
  "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"

Best Regards

Eric




On 09/19/2014 11:03 AM, Stefan Hajnoczi wrote:
> On Wed, Sep 03, 2014 at 09:45:14AM +0100, Eric Auger wrote:
>> This patch removes all DPRINTF and replace them by trace points.
>> A few DPRINTF used in error cases were transformed into error_report.
>>
>> Signed-off-by: Eric Auger <eric.auger@linaro.org>
> 
> The subject line says "RFC".  Are you proposing this patch for merge?
> 
> Did you want me to take it into the tracing tree?
> 
> Stefan
>

On 19.09.14 18:07, Eric Auger wrote:
> Hi Stefan,
> 
> Thanks for asking. Actually I think this is a bit early. I would like
> some VFIO PCI users experiencing it a little bit (typically Alex) and
> confirm they are happy with it.

Don't be so reluctant - this patch is a step forward, so just mark it as
a real patch. There's nothing controversial in here.

> 
> Also as I mentionned in the commit message, I identified some parsing
> issues that forced me to change few format strings. I don't know if you
> have time or are willing to fix those - you may be more efficient doing
> those fixes than I would;-) - Nethertheless if you can't afford, I will
> have a look at the Python code.
> 
> For convenience I put the issues again, all related to parenthesis:
> 
> Cases than are not correctly handled are given below:
> - "(%04x:%02x:%02x.%x)" need to be replaced by " (%04x:%02x:%02x.%x)"
> - "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d) = 0x%"PRIx64 replaced by
>   "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64
> - "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d)"
> replaced by
>   "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"

Looks like cosmetic problems that can be solved later :).


Alex

On Fri, Sep 19, 2014 at 06:07:02PM +0200, Eric Auger wrote:
> Also as I mentionned in the commit message, I identified some parsing
> issues that forced me to change few format strings. I don't know if you
> have time or are willing to fix those - you may be more efficient doing
> those fixes than I would;-) - Nethertheless if you can't afford, I will
> have a look at the Python code.
> 
> For convenience I put the issues again, all related to parenthesis:
> 
> Cases than are not correctly handled are given below:
> - "(%04x:%02x:%02x.%x)" need to be replaced by " (%04x:%02x:%02x.%x)"
> - "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d) = 0x%"PRIx64 replaced by
>   "%s read(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", %d = 0x%"PRIx64
> - "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d)"
> replaced by
>   "%s write(%04x:%02x:%02x.%x:BAR%d+0x%"PRIx64", 0x%"PRIx64", %d"

Thanks for pointing this out.  I have sent a fix:

  [PATCH] trace: tighten up trace-events regex to fix bad parse

Please let me know if it solves the issues for you.

Stefan