[PATCH 0/6] hw/{arm,xen} convert printfs to trace/reports

[PATCH 0/6] hw/{arm,xen} convert printfs to trace/reports

[Manos Pitsidianakis]

This series changes some printfs to use the trace event framework. 
Additionally, it converts some error/warning reporting fprintfs to 
error_report/warn_report.

Manos Pitsidianakis (6):
  hw/arm/z2: convert DPRINTF to tracepoints
  hw/arm/strongarm.c: convert DPRINTF to tracepoints
  hw/arm/xen_arm.c: replace DPRINTF with traces
  hw/xen/xen-mapcache.c: convert DPRINTF to tracepoints
  hw/xen/xen-hvm-common.c: convert DPRINTF to tracepoints
  hw/xen: convert stderr prints to error/warn reports

 hw/arm/strongarm.c      | 49 +++++++++++++++-------------------
 hw/arm/trace-events     | 33 +++++++++++++++++++++++
 hw/arm/xen_arm.c        | 26 ++++++++++--------
 hw/arm/z2.c             | 26 +++++++-----------
 hw/xen/trace-events     | 21 ++++++++++++++-
 hw/xen/xen-hvm-common.c | 47 ++++++++++++++++----------------
 hw/xen/xen-mapcache.c   | 59 ++++++++++++++++++-----------------------
 7 files changed, 148 insertions(+), 113 deletions(-)


base-commit: d0f4aa7d50d485b1fb5ec8ab6f934e5df852ab07
-- 
γαῖα πυρί μιχθήτω

[PATCH 1/6] hw/arm/z2: convert DPRINTF to tracepoints

[Manos Pitsidianakis]

Tracing DPRINTFs to stderr might not be desired. A developer that relies
on tracepoints should be able to opt-in to each tracepoint and rely on
QEMU's log redirection, instead of stderr by default.

This commit converts DPRINTFs in this file that are used for tracing
into tracepoints.

Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
---
 hw/arm/trace-events |  8 ++++++++
 hw/arm/z2.c         | 26 +++++++++-----------------
 2 files changed, 17 insertions(+), 17 deletions(-)

diff --git a/hw/arm/trace-events b/hw/arm/trace-events
index cdc1ea06a8..a262ad2e6a 100644
--- a/hw/arm/trace-events
+++ b/hw/arm/trace-events
@@ -55,3 +55,11 @@ smmuv3_notify_flag_add(const char *iommu) "ADD SMMUNotifier node for iommu mr=%s
 smmuv3_notify_flag_del(const char *iommu) "DEL SMMUNotifier node for iommu mr=%s"
 smmuv3_inv_notifiers_iova(const char *name, uint16_t asid, uint16_t vmid, uint64_t iova, uint8_t tg, uint64_t num_pages) "iommu mr=%s asid=%d vmid=%d iova=0x%"PRIx64" tg=%d num_pages=0x%"PRIx64
 
+# z2.c
+z2_lcd_cur_reg_update(uint8_t r) "reg: 0x%x"
+z2_lcd_enable_disable(uint16_t v) "value: 0x%x"
+z2_lcd_enable_disable_result(const char * result) "LCD %s"
+z2_lcd_invalid_command(uint8_t value) "0x%x"
+z2_aer915_send_too_log(int8_t msg) "message too long (%i bytes)"
+z2_aer915_send(uint8_t reg, uint8_t value) "reg %d value 0x%02x"
+z2_aer915_i2c_start_recv(uint16_t len) "I2C_START_RECV: short message with len %d"
diff --git a/hw/arm/z2.c b/hw/arm/z2.c
index 83741a4909..6c0889d698 100644
--- a/hw/arm/z2.c
+++ b/hw/arm/z2.c
@@ -28,13 +28,7 @@
 #include "cpu.h"
 #include "qom/object.h"
 #include "qapi/error.h"
-
-#ifdef DEBUG_Z2
-#define DPRINTF(fmt, ...) \
-        printf(fmt, ## __VA_ARGS__)
-#else
-#define DPRINTF(fmt, ...)
-#endif
+#include "trace.h"
 
 static const struct keymap map[0x100] = {
     [0 ... 0xff] = { -1, -1 },
@@ -127,22 +121,22 @@ static uint32_t zipit_lcd_transfer(SSIPeripheral *dev, uint32_t value)
     if (z->pos == 3) {
         switch (z->buf[0]) {
         case 0x74:
-            DPRINTF("%s: reg: 0x%.2x\n", __func__, z->buf[2]);
+            trace_z2_lcd_cur_reg_update(z->buf[2]);
             z->cur_reg = z->buf[2];
             break;
         case 0x76:
             val = z->buf[1] << 8 | z->buf[2];
-            DPRINTF("%s: value: 0x%.4x\n", __func__, val);
+            trace_z2_lcd_enable_disable(val);
             if (z->cur_reg == 0x22 && val == 0x0000) {
                 z->enabled = 1;
-                printf("%s: LCD enabled\n", __func__);
+                trace_z2_lcd_enable_disable_result("enabled");
             } else if (z->cur_reg == 0x10 && val == 0x0000) {
                 z->enabled = 0;
-                printf("%s: LCD disabled\n", __func__);
+                trace_z2_lcd_enable_disable_result("disabled");
             }
             break;
         default:
-            DPRINTF("%s: unknown command!\n", __func__);
+            trace_z2_lcd_invalid_command(z->buf[0]);
             break;
         }
         z->pos = 0;
@@ -212,14 +206,12 @@ static int aer915_send(I2CSlave *i2c, uint8_t data)
 
     s->buf[s->len] = data;
     if (s->len++ > 2) {
-        DPRINTF("%s: message too long (%i bytes)\n",
-            __func__, s->len);
+        trace_z2_aer915_send_too_log(s->len);
         return 1;
     }
 
     if (s->len == 2) {
-        DPRINTF("%s: reg %d value 0x%02x\n", __func__,
-                s->buf[0], s->buf[1]);
+        trace_z2_aer915_send(s->buf[0], s->buf[1]);
     }
 
     return 0;
@@ -235,7 +227,7 @@ static int aer915_event(I2CSlave *i2c, enum i2c_event event)
         break;
     case I2C_START_RECV:
         if (s->len != 1) {
-            DPRINTF("%s: short message!?\n", __func__);
+            trace_z2_aer915_i2c_start_recv(s->len);
         }
         break;
     case I2C_FINISH:
-- 
γαῖα πυρί μιχθήτω

[PATCH 2/6] hw/arm/strongarm.c: convert DPRINTF to tracepoints

[Manos Pitsidianakis]

Tracing DPRINTFs to stderr might not be desired. A developer that relies
on tracepoints should be able to opt-in to each tracepoint and rely on
QEMU's log redirection, instead of stderr by default.

This commit converts DPRINTFs in this file that are used for tracing
into tracepoints.

Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
---
 hw/arm/strongarm.c  | 49 +++++++++++++++++++--------------------------
 hw/arm/trace-events | 18 +++++++++++++++++
 2 files changed, 39 insertions(+), 28 deletions(-)

diff --git a/hw/arm/strongarm.c b/hw/arm/strongarm.c
index fef3638aca..3ff748e826 100644
--- a/hw/arm/strongarm.c
+++ b/hw/arm/strongarm.c
@@ -46,8 +46,7 @@
 #include "qemu/cutils.h"
 #include "qemu/log.h"
 #include "qom/object.h"
-
-//#define DEBUG
+#include "trace.h"
 
 /*
  TODO
@@ -66,12 +65,6 @@
  - Enhance UART with modem signals
  */
 
-#ifdef DEBUG
-# define DPRINTF(format, ...) printf(format , ## __VA_ARGS__)
-#else
-# define DPRINTF(format, ...) do { } while (0)
-#endif
-
 static struct {
     hwaddr io_base;
     int irq;
@@ -151,8 +144,7 @@ static uint64_t strongarm_pic_mem_read(void *opaque, hwaddr offset,
     case ICPR:
         return s->pending;
     default:
-        printf("%s: Bad register offset 0x" HWADDR_FMT_plx "\n",
-                        __func__, offset);
+        trace_strongarm_pic_mem_read(offset);
         return 0;
     }
 }
@@ -173,8 +165,7 @@ static void strongarm_pic_mem_write(void *opaque, hwaddr offset,
         s->int_idle = (value & 1) ? 0 : ~0;
         break;
     default:
-        printf("%s: Bad register offset 0x" HWADDR_FMT_plx "\n",
-                        __func__, offset);
+        trace_strongarm_pic_mem_write(offset);
         break;
     }
     strongarm_pic_update(s);
@@ -333,7 +324,7 @@ static uint64_t strongarm_rtc_read(void *opaque, hwaddr addr,
                 ((qemu_clock_get_ms(rtc_clock) - s->last_hz) << 15) /
                 (1000 * ((s->rttr & 0xffff) + 1));
     default:
-        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
+        trace_strongarm_rtc_read(addr);
         return 0;
     }
 }
@@ -375,7 +366,7 @@ static void strongarm_rtc_write(void *opaque, hwaddr addr,
         break;
 
     default:
-        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
+        trace_strongarm_rtc_write(addr);
     }
 }
 
@@ -581,7 +572,7 @@ static uint64_t strongarm_gpio_read(void *opaque, hwaddr offset,
         return s->status;
 
     default:
-        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
+        trace_strongarm_gpio_read(offset);
     }
 
     return 0;
@@ -626,7 +617,7 @@ static void strongarm_gpio_write(void *opaque, hwaddr offset,
         break;
 
     default:
-        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
+        trace_strongarm_gpio_write(offset);
     }
 }
 
@@ -782,7 +773,7 @@ static uint64_t strongarm_ppc_read(void *opaque, hwaddr offset,
         return s->ppfr | ~0x7f001;
 
     default:
-        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
+        trace_strongarm_ppc_read(offset);
     }
 
     return 0;
@@ -817,7 +808,7 @@ static void strongarm_ppc_write(void *opaque, hwaddr offset,
         break;
 
     default:
-        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
+        trace_strongarm_ppc_write(offset);
     }
 }
 
@@ -1029,8 +1020,11 @@ static void strongarm_uart_update_parameters(StrongARMUARTState *s)
     s->char_transmit_time =  (NANOSECONDS_PER_SECOND / speed) * frame_size;
     qemu_chr_fe_ioctl(&s->chr, CHR_IOCTL_SERIAL_SET_PARAMS, &ssp);
 
-    DPRINTF(stderr, "%s speed=%d parity=%c data=%d stop=%d\n", s->chr->label,
-            speed, parity, data_bits, stop_bits);
+    trace_strongarm_uart_update_parameters(s->chr.chr->label?:"NULL",
+                                           speed,
+                                           parity,
+                                           data_bits,
+                                           stop_bits);
 }
 
 static void strongarm_uart_rx_to(void *opaque)
@@ -1164,7 +1158,7 @@ static uint64_t strongarm_uart_read(void *opaque, hwaddr addr,
         return s->utsr1;
 
     default:
-        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
+        trace_strongarm_uart_read_bad_register(addr);
         return 0;
     }
 }
@@ -1221,7 +1215,7 @@ static void strongarm_uart_write(void *opaque, hwaddr addr,
         break;
 
     default:
-        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
+        trace_strongarm_uart_write_bad_register(addr);
     }
 }
 
@@ -1434,7 +1428,7 @@ static uint64_t strongarm_ssp_read(void *opaque, hwaddr addr,
             return 0xffffffff;
         }
         if (s->rx_level < 1) {
-            printf("%s: SSP Rx Underrun\n", __func__);
+            trace_strongarm_ssp_read_underrun();
             return 0xffffffff;
         }
         s->rx_level--;
@@ -1443,7 +1437,7 @@ static uint64_t strongarm_ssp_read(void *opaque, hwaddr addr,
         strongarm_ssp_fifo_update(s);
         return retval;
     default:
-        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
+        trace_strongarm_ssp_read(addr);
         break;
     }
     return 0;
@@ -1458,8 +1452,7 @@ static void strongarm_ssp_write(void *opaque, hwaddr addr,
     case SSCR0:
         s->sscr[0] = value & 0xffbf;
         if ((s->sscr[0] & SSCR0_SSE) && SSCR0_DSS(value) < 4) {
-            printf("%s: Wrong data size: %i bits\n", __func__,
-                   (int)SSCR0_DSS(value));
+            trace_strongarm_ssp_write_wrong_data_size((int)SSCR0_DSS(value));
         }
         if (!(value & SSCR0_SSE)) {
             s->sssr = 0;
@@ -1471,7 +1464,7 @@ static void strongarm_ssp_write(void *opaque, hwaddr addr,
     case SSCR1:
         s->sscr[1] = value & 0x2f;
         if (value & SSCR1_LBM) {
-            printf("%s: Attempt to use SSP LBM mode\n", __func__);
+            trace_strongarm_ssp_write_wrong_data_size_invalid();
         }
         strongarm_ssp_fifo_update(s);
         break;
@@ -1509,7 +1502,7 @@ static void strongarm_ssp_write(void *opaque, hwaddr addr,
         break;
 
     default:
-        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
+        trace_strongarm_ssp_write_bad_register(addr);
         break;
     }
 }
diff --git a/hw/arm/trace-events b/hw/arm/trace-events
index a262ad2e6a..a6a67d5f16 100644
--- a/hw/arm/trace-events
+++ b/hw/arm/trace-events
@@ -63,3 +63,21 @@ z2_lcd_invalid_command(uint8_t value) "0x%x"
 z2_aer915_send_too_log(int8_t msg) "message too long (%i bytes)"
 z2_aer915_send(uint8_t reg, uint8_t value) "reg %d value 0x%02x"
 z2_aer915_i2c_start_recv(uint16_t len) "I2C_START_RECV: short message with len %d"
+
+# strongarm.c
+strongarm_uart_update_parameters(const char *label, int speed, char parity, int data_bits, int stop_bits) "%s speed=%d parity=%c data=%d stop=%d"
+strongarm_uart_read_bad_register(uint64_t addr) "Bad uart register 0x%zu"
+strongarm_uart_write_bad_register(uint64_t addr) "Bad uart register 0x%zu"
+strongarm_pic_mem_read(uint64_t offset) "Bad pic mem register read offset 0x%zu"
+strongarm_pic_mem_write(uint64_t offset) "Bad pic mem register write offset 0x%zu"
+strongarm_rtc_read(uint64_t addr) "Bad rtc register read 0x%zu"
+strongarm_rtc_write(uint64_t addr) "Bad rtc register write 0x%zu"
+strongarm_gpio_read(uint64_t offset) "Bad gpio read offset 0x%zu"
+strongarm_gpio_write(uint64_t offset) "Bad gpio write offset 0x%zu"
+strongarm_ppc_write(uint64_t offset) "Bad ppc write offset 0x%zu"
+strongarm_ppc_read(uint64_t offset) "Bad ppc write offset 0x%zu"
+strongarm_ssp_read_underrun(void) "SSP Rx Underrun"
+strongarm_ssp_read(uint64_t addr) "Bad register 0x%zu"
+strongarm_ssp_write_wrong_data_size(int v) "Wrong data size: %i bits"
+strongarm_ssp_write_wrong_data_size_invalid(void) "Attempt to use SSP LBM mode"
+strongarm_ssp_write_bad_register(uint64_t addr) "Bad register 0x%zu"
-- 
γαῖα πυρί μιχθήτω

[PATCH 3/6] hw/arm/xen_arm.c: convert DPRINTF to tracepoints

[Manos Pitsidianakis]

Tracing DPRINTFs to stderr might not be desired. A developer that relies
on tracepoints should be able to opt-in to each tracepoint and rely on
QEMU's log redirection, instead of stderr by default.

This commit converts DPRINTFs in this file that are used for tracing
into tracepoints.

Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
---
 hw/arm/trace-events |  7 +++++++
 hw/arm/xen_arm.c    | 26 +++++++++++++++-----------
 2 files changed, 22 insertions(+), 11 deletions(-)

diff --git a/hw/arm/trace-events b/hw/arm/trace-events
index a6a67d5f16..e3f5d677d7 100644
--- a/hw/arm/trace-events
+++ b/hw/arm/trace-events
@@ -81,3 +81,10 @@ strongarm_ssp_read(uint64_t addr) "Bad register 0x%zu"
 strongarm_ssp_write_wrong_data_size(int v) "Wrong data size: %i bits"
 strongarm_ssp_write_wrong_data_size_invalid(void) "Attempt to use SSP LBM mode"
 strongarm_ssp_write_bad_register(uint64_t addr) "Bad register 0x%zu"
+
+# xen_arm.c
+xen_create_virtio_mmio_devices(int i, int irq, uint64_t base) "Created virtio-mmio device %d: irq %d base 0x%lx"
+xen_init_ram(const char *hi_xor_low, uint64_t base, uint64_t size) "Initialized region xen.ram.%s: base 0x%lx size 0x%lx"
+xen_enable_tpm_not_found(void) "Couldn't find tmp0 backend"
+xen_enable_tpm(uint64_t addr) "Connected tpmdev at address 0x%lx"
+xen_arm_init(const char *msg) "%s"
diff --git a/hw/arm/xen_arm.c b/hw/arm/xen_arm.c
index a5631529d0..a024117d22 100644
--- a/hw/arm/xen_arm.c
+++ b/hw/arm/xen_arm.c
@@ -34,6 +34,7 @@
 #include "hw/xen/xen-hvm-common.h"
 #include "sysemu/tpm.h"
 #include "hw/xen/arch_hvm.h"
+#include "trace.h"
 
 #define TYPE_XEN_ARM  MACHINE_TYPE_NAME("xenpvh")
 OBJECT_DECLARE_SIMPLE_TYPE(XenArmState, XEN_ARM)
@@ -91,8 +92,9 @@ static void xen_create_virtio_mmio_devices(XenArmState *xam)
 
         sysbus_create_simple("virtio-mmio", base, irq);
 
-        DPRINTF("Created virtio-mmio device %d: irq %d base 0x%lx\n",
-                i, GUEST_VIRTIO_MMIO_SPI_FIRST + i, base);
+        trace_xen_create_virtio_mmio_devices(i,
+                                             GUEST_VIRTIO_MMIO_SPI_FIRST + i,
+                                             base);
     }
 }
 
@@ -117,15 +119,13 @@ static void xen_init_ram(MachineState *machine)
     memory_region_init_alias(&ram_lo, NULL, "xen.ram.lo", &ram_memory,
                              GUEST_RAM0_BASE, ram_size[0]);
     memory_region_add_subregion(sysmem, GUEST_RAM0_BASE, &ram_lo);
-    DPRINTF("Initialized region xen.ram.lo: base 0x%llx size 0x%lx\n",
-            GUEST_RAM0_BASE, ram_size[0]);
+    trace_xen_init_ram("lo", GUEST_RAM0_BASE, ram_size[0]);
 
     if (ram_size[1] > 0) {
         memory_region_init_alias(&ram_hi, NULL, "xen.ram.hi", &ram_memory,
                                  GUEST_RAM1_BASE, ram_size[1]);
         memory_region_add_subregion(sysmem, GUEST_RAM1_BASE, &ram_hi);
-        DPRINTF("Initialized region xen.ram.hi: base 0x%llx size 0x%lx\n",
-                GUEST_RAM1_BASE, ram_size[1]);
+        trace_xen_init_ram("hi", GUEST_RAM1_BASE, ram_size[1]);
     }
 }
 
@@ -158,7 +158,7 @@ static void xen_enable_tpm(XenArmState *xam)
 
     TPMBackend *be = qemu_find_tpm_be("tpm0");
     if (be == NULL) {
-        DPRINTF("Couldn't fine the backend for tpm0\n");
+        trace_xen_enable_tpm_not_found();
         return;
     }
     dev = qdev_new(TYPE_TPM_TIS_SYSBUS);
@@ -168,7 +168,7 @@ static void xen_enable_tpm(XenArmState *xam)
     sysbus_realize_and_unref(busdev, &error_fatal);
     sysbus_mmio_map(busdev, 0, xam->cfg.tpm_base_addr);
 
-    DPRINTF("Connected tpmdev at address 0x%lx\n", xam->cfg.tpm_base_addr);
+    trace_xen_enable_tpm(xam->cfg.tpm_base_addr);
 }
 #endif
 
@@ -179,8 +179,11 @@ static void xen_arm_init(MachineState *machine)
     xam->state =  g_new0(XenIOState, 1);
 
     if (machine->ram_size == 0) {
-        DPRINTF("ram_size not specified. QEMU machine started without IOREQ"
-                "(no emulated devices including Virtio)\n");
+        trace_xen_arm_init("ram_size not specified. "
+                           "QEMU machine started "
+                           "without IOREQ "
+                           "(no emulated devices"
+                           "including Virtio)");
         return;
     }
 
@@ -194,7 +197,8 @@ static void xen_arm_init(MachineState *machine)
     if (xam->cfg.tpm_base_addr) {
         xen_enable_tpm(xam);
     } else {
-        DPRINTF("tpm-base-addr is not provided. TPM will not be enabled\n");
+        trace_xen_arm_init("tpm-base-addr is not provided."
+                           "TPM will not be enabled");
     }
 #endif
 }
-- 
γαῖα πυρί μιχθήτω

[PATCH 4/6] hw/xen/xen-mapcache.c: convert DPRINTF to tracepoints

[Manos Pitsidianakis]

Tracing DPRINTFs to stderr might not be desired. A developer that relies
on tracepoints should be able to opt-in to each tracepoint and rely on
QEMU's log redirection, instead of stderr by default.

This commit converts DPRINTFs in this file that are used for tracing
into tracepoints.

Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
---
 hw/xen/trace-events   | 11 +++++++++
 hw/xen/xen-mapcache.c | 54 +++++++++++++++++++------------------------
 2 files changed, 35 insertions(+), 30 deletions(-)

diff --git a/hw/xen/trace-events b/hw/xen/trace-events
index 67a6c41926..1b748dba09 100644
--- a/hw/xen/trace-events
+++ b/hw/xen/trace-events
@@ -60,3 +60,14 @@ cpu_ioreq_config_write(void *req, uint32_t sbdf, uint32_t reg, uint32_t size, ui
 xen_map_cache(uint64_t phys_addr) "want 0x%"PRIx64
 xen_remap_bucket(uint64_t index) "index 0x%"PRIx64
 xen_map_cache_return(void* ptr) "%p"
+xen_map_cache_init(uint64_t nr_buckets, uint64_t size) "nr_buckets = 0x%lx size %lu"
+xen_replace_cache_entry_dummy(uint64_t old_phys_addr, uint64_t new_phys_addr) "Replacing a dummy mapcache entry for 0x%"PRIx64" with 0x%"PRIx64
+xen_invalidate_map_cache_entry_unlocked_not_found(void *p) "could not find %p"
+xen_invalidate_map_cache_entry_unlocked_found(uint64_t addr, void *p) "   0x%"PRIx64" -> %p is present"
+xen_invalidate_map_cache_entry_unlocked_miss(void *buffer) "Trying to unmap address %p that is not in the mapcache"
+xen_replace_cache_entry_unlocked_could_not_update_entry(uint64_t old_phys_addr) "Unable to update a mapcache entry for 0x%"PRIx64
+xen_ram_addr_from_mapcache_not_found(void *p) "could not find %p"
+xen_ram_addr_from_mapcache_found(uint64_t addr, void *p) "   0x%"PRIx64" -> %p is present"
+xen_ram_addr_from_mapcache_not_in_cache(void *p) "Trying to find address %p that is not in the mapcache"
+xen_replace_cache_entry_unlocked(uint64_t old_phys_addr) "Trying to update an entry for 0x%"PRIx64" that is not in the mapcache"
+xen_invalidate_map_cache(uint64_t paddr_index, void *vaddr_req) "Locked DMA mapping while invalidating mapcache 0x%"PRIx64" -> %p is present"
diff --git a/hw/xen/xen-mapcache.c b/hw/xen/xen-mapcache.c
index f7d974677d..336c212376 100644
--- a/hw/xen/xen-mapcache.c
+++ b/hw/xen/xen-mapcache.c
@@ -22,16 +22,6 @@
 #include "trace.h"
 
 
-//#define MAPCACHE_DEBUG
-
-#ifdef MAPCACHE_DEBUG
-#  define DPRINTF(fmt, ...) do { \
-    fprintf(stderr, "xen_mapcache: " fmt, ## __VA_ARGS__); \
-} while (0)
-#else
-#  define DPRINTF(fmt, ...) do { } while (0)
-#endif
-
 #if HOST_LONG_BITS == 32
 #  define MCACHE_BUCKET_SHIFT 16
 #  define MCACHE_MAX_SIZE     (1UL<<31) /* 2GB Cap */
@@ -145,8 +135,7 @@ void xen_map_cache_init(phys_offset_to_gaddr_t f, void *opaque)
 
     size = mapcache->nr_buckets * sizeof (MapCacheEntry);
     size = (size + XC_PAGE_SIZE - 1) & ~(XC_PAGE_SIZE - 1);
-    DPRINTF("%s, nr_buckets = %lx size %lu\n", __func__,
-            mapcache->nr_buckets, size);
+    trace_xen_map_cache_init(mapcache->nr_buckets, size);
     mapcache->entry = g_malloc0(size);
 }
 
@@ -286,7 +275,9 @@ tryagain:
         test_bits(address_offset >> XC_PAGE_SHIFT,
                   test_bit_size >> XC_PAGE_SHIFT,
                   mapcache->last_entry->valid_mapping)) {
-        trace_xen_map_cache_return(mapcache->last_entry->vaddr_base + address_offset);
+        trace_xen_map_cache_return(
+            mapcache->last_entry->vaddr_base + address_offset
+        );
         return mapcache->last_entry->vaddr_base + address_offset;
     }
 
@@ -368,7 +359,9 @@ tryagain:
         QTAILQ_INSERT_HEAD(&mapcache->locked_entries, reventry, next);
     }
 
-    trace_xen_map_cache_return(mapcache->last_entry->vaddr_base + address_offset);
+    trace_xen_map_cache_return(
+        mapcache->last_entry->vaddr_base + address_offset
+    );
     return mapcache->last_entry->vaddr_base + address_offset;
 }
 
@@ -402,10 +395,10 @@ ram_addr_t xen_ram_addr_from_mapcache(void *ptr)
         }
     }
     if (!found) {
-        fprintf(stderr, "%s, could not find %p\n", __func__, ptr);
+        trace_xen_ram_addr_from_mapcache_not_found(ptr);
         QTAILQ_FOREACH(reventry, &mapcache->locked_entries, next) {
-            DPRINTF("   "HWADDR_FMT_plx" -> %p is present\n", reventry->paddr_index,
-                    reventry->vaddr_req);
+            trace_xen_ram_addr_from_mapcache_found(reventry->paddr_index,
+                                                   reventry->vaddr_req);
         }
         abort();
         return 0;
@@ -416,7 +409,7 @@ ram_addr_t xen_ram_addr_from_mapcache(void *ptr)
         entry = entry->next;
     }
     if (!entry) {
-        DPRINTF("Trying to find address %p that is not in the mapcache!\n", ptr);
+        trace_xen_ram_addr_from_mapcache_not_in_cache(ptr);
         raddr = 0;
     } else {
         raddr = (reventry->paddr_index << MCACHE_BUCKET_SHIFT) +
@@ -443,9 +436,12 @@ static void xen_invalidate_map_cache_entry_unlocked(uint8_t *buffer)
         }
     }
     if (!found) {
-        DPRINTF("%s, could not find %p\n", __func__, buffer);
+        trace_xen_invalidate_map_cache_entry_unlocked_not_found(buffer);
         QTAILQ_FOREACH(reventry, &mapcache->locked_entries, next) {
-            DPRINTF("   "HWADDR_FMT_plx" -> %p is present\n", reventry->paddr_index, reventry->vaddr_req);
+            trace_xen_invalidate_map_cache_entry_unlocked_found(
+                reventry->paddr_index,
+                reventry->vaddr_req
+            );
         }
         return;
     }
@@ -463,7 +459,7 @@ static void xen_invalidate_map_cache_entry_unlocked(uint8_t *buffer)
         entry = entry->next;
     }
     if (!entry) {
-        DPRINTF("Trying to unmap address %p that is not in the mapcache!\n", buffer);
+        trace_xen_invalidate_map_cache_entry_unlocked_miss(buffer);
         return;
     }
     entry->lock--;
@@ -502,9 +498,8 @@ void xen_invalidate_map_cache(void)
         if (!reventry->dma) {
             continue;
         }
-        fprintf(stderr, "Locked DMA mapping while invalidating mapcache!"
-                " "HWADDR_FMT_plx" -> %p is present\n",
-                reventry->paddr_index, reventry->vaddr_req);
+        trace_xen_invalidate_map_cache(reventry->paddr_index,
+                                       reventry->vaddr_req);
     }
 
     for (i = 0; i < mapcache->nr_buckets; i++) {
@@ -562,24 +557,23 @@ static uint8_t *xen_replace_cache_entry_unlocked(hwaddr old_phys_addr,
         entry = entry->next;
     }
     if (!entry) {
-        DPRINTF("Trying to update an entry for "HWADDR_FMT_plx \
-                "that is not in the mapcache!\n", old_phys_addr);
+        trace_xen_replace_cache_entry_unlocked(old_phys_addr);
         return NULL;
     }
 
     address_index  = new_phys_addr >> MCACHE_BUCKET_SHIFT;
     address_offset = new_phys_addr & (MCACHE_BUCKET_SIZE - 1);
 
-    fprintf(stderr, "Replacing a dummy mapcache entry for "HWADDR_FMT_plx \
-            " with "HWADDR_FMT_plx"\n", old_phys_addr, new_phys_addr);
+    trace_xen_replace_cache_entry_dummy(old_phys_addr, new_phys_addr);
 
     xen_remap_bucket(entry, entry->vaddr_base,
                      cache_size, address_index, false);
     if (!test_bits(address_offset >> XC_PAGE_SHIFT,
                 test_bit_size >> XC_PAGE_SHIFT,
                 entry->valid_mapping)) {
-        DPRINTF("Unable to update a mapcache entry for "HWADDR_FMT_plx"!\n",
-                old_phys_addr);
+        trace_xen_replace_cache_entry_unlocked_could_not_update_entry(
+            old_phys_addr
+        );
         return NULL;
     }
 
-- 
γαῖα πυρί μιχθήτω

[PATCH 5/6] hw/xen/xen-hvm-common.c: convert DPRINTF to tracepoints

[Manos Pitsidianakis]

Tracing DPRINTFs to stderr might not be desired. A developer that relies
on tracepoints should be able to opt-in to each tracepoint and rely on
QEMU's log redirection, instead of stderr by default.

This commit converts DPRINTFs in this file that are used for tracing
into tracepoints.

Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
---
 hw/xen/trace-events     | 10 +++++++++-
 hw/xen/xen-hvm-common.c | 35 ++++++++++++++++++-----------------
 2 files changed, 27 insertions(+), 18 deletions(-)

diff --git a/hw/xen/trace-events b/hw/xen/trace-events
index 1b748dba09..dd5b5a7f35 100644
--- a/hw/xen/trace-events
+++ b/hw/xen/trace-events
@@ -42,7 +42,7 @@ xs_node_vscanf(char *path, char *value) "%s %s"
 xs_node_watch(char *path) "%s"
 xs_node_unwatch(char *path) "%s"
 
-# xen-hvm.c
+# xen-hvm-common.c
 xen_ram_alloc(unsigned long ram_addr, unsigned long size) "requested: 0x%lx, size 0x%lx"
 xen_client_set_memory(uint64_t start_addr, unsigned long size, bool log_dirty) "0x%"PRIx64" size 0x%lx, log_dirty %i"
 handle_ioreq(void *req, uint32_t type, uint32_t dir, uint32_t df, uint32_t data_is_ptr, uint64_t addr, uint64_t data, uint32_t count, uint32_t size) "I/O=%p type=%d dir=%d df=%d ptr=%d port=0x%"PRIx64" data=0x%"PRIx64" count=%d size=%d"
@@ -55,6 +55,14 @@ cpu_ioreq_move(void *req, uint32_t dir, uint32_t df, uint32_t data_is_ptr, uint6
 xen_map_resource_ioreq(uint32_t id, void *addr) "id: %u addr: %p"
 cpu_ioreq_config_read(void *req, uint32_t sbdf, uint32_t reg, uint32_t size, uint32_t data) "I/O=%p sbdf=0x%x reg=%u size=%u data=0x%x"
 cpu_ioreq_config_write(void *req, uint32_t sbdf, uint32_t reg, uint32_t size, uint32_t data) "I/O=%p sbdf=0x%x reg=%u size=%u data=0x%x"
+cpu_get_ioreq_from_shared_memory_req_not_ready(int state, int data_is_ptr, uint64_t addr, uint64_t data, uint32_t count, uint32_t size) "I/O request not ready: 0x%x, ptr: 0x%x, port: 0x%"PRIx64", data: 0x%"PRIx64", count: %u, size: %u"
+xen_main_loop_prepare_init_cpu(int id, void *cpu) "cpu_by_vcpu_id[%d]=%p"
+xen_map_ioreq_server_shared_page(long unsigned int ioreq_pfn) "shared page at pfn 0x%lx"
+xen_map_ioreq_server_buffered_io_page(long unsigned int ioreq_pfn) "buffered io page at pfn 0x%lx"
+xen_map_ioreq_server_buffered_io_evtchn(int bufioreq_evtchn) "buffered io evtchn is 0x%x"
+destroy_hvm_domain_cannot_acquire_handle(void) "Cannot acquire xenctrl handle"
+destroy_hvm_domain_failed_action(const char *action, int sts, char *errno_s) "xc_domain_shutdown failed to issue %s, sts %d, %s"
+destroy_hvm_domain_action(int xen_domid, const char *action) "Issued domain %d %s"
 
 # xen-mapcache.c
 xen_map_cache(uint64_t phys_addr) "want 0x%"PRIx64
diff --git a/hw/xen/xen-hvm-common.c b/hw/xen/xen-hvm-common.c
index 47e6cb1db3..05a29c6f11 100644
--- a/hw/xen/xen-hvm-common.c
+++ b/hw/xen/xen-hvm-common.c
@@ -169,11 +169,12 @@ static ioreq_t *cpu_get_ioreq_from_shared_memory(XenIOState *state, int vcpu)
     ioreq_t *req = xen_vcpu_ioreq(state->shared_page, vcpu);
 
     if (req->state != STATE_IOREQ_READY) {
-        DPRINTF("I/O request not ready: "
-                "%x, ptr: %x, port: %"PRIx64", "
-                "data: %"PRIx64", count: %u, size: %u\n",
-                req->state, req->data_is_ptr, req->addr,
-                req->data, req->count, req->size);
+        trace_cpu_get_ioreq_from_shared_memory_req_not_ready(req->state,
+                                                             req->data_is_ptr,
+                                                             req->addr,
+                                                             req->data,
+                                                             req->count,
+                                                             req->size);
         return NULL;
     }
 
@@ -601,10 +602,9 @@ static void xen_main_loop_prepare(XenIOState *state)
     if (evtchn_fd != -1) {
         CPUState *cpu_state;
 
-        DPRINTF("%s: Init cpu_by_vcpu_id\n", __func__);
         CPU_FOREACH(cpu_state) {
-            DPRINTF("%s: cpu_by_vcpu_id[%d]=%p\n",
-                    __func__, cpu_state->cpu_index, cpu_state);
+            trace_xen_main_loop_prepare_init_cpu(cpu_state->cpu_index,
+                                                 cpu_state);
             state->cpu_by_vcpu_id[cpu_state->cpu_index] = cpu_state;
         }
         qemu_set_fd_handler(evtchn_fd, cpu_handle_ioreq, NULL, state);
@@ -681,7 +681,7 @@ static int xen_map_ioreq_server(XenIOState *state)
     }
 
     if (state->shared_page == NULL) {
-        DPRINTF("shared page at pfn %lx\n", ioreq_pfn);
+        trace_xen_map_ioreq_server_shared_page(ioreq_pfn);
 
         state->shared_page = xenforeignmemory_map(xen_fmem, xen_domid,
                                                   PROT_READ | PROT_WRITE,
@@ -693,7 +693,7 @@ static int xen_map_ioreq_server(XenIOState *state)
     }
 
     if (state->buffered_io_page == NULL) {
-        DPRINTF("buffered io page at pfn %lx\n", bufioreq_pfn);
+        trace_xen_map_ioreq_server_buffered_io_page(bufioreq_pfn);
 
         state->buffered_io_page = xenforeignmemory_map(xen_fmem, xen_domid,
                                                        PROT_READ | PROT_WRITE,
@@ -709,7 +709,7 @@ static int xen_map_ioreq_server(XenIOState *state)
         return -1;
     }
 
-    DPRINTF("buffered io evtchn is %x\n", bufioreq_evtchn);
+    trace_xen_map_ioreq_server_buffered_io_evtchn(bufioreq_evtchn);
 
     state->bufioreq_remote_port = bufioreq_evtchn;
 
@@ -737,16 +737,17 @@ void destroy_hvm_domain(bool reboot)
 
     xc_handle = xc_interface_open(0, 0, 0);
     if (xc_handle == NULL) {
-        fprintf(stderr, "Cannot acquire xenctrl handle\n");
+        trace_destroy_hvm_domain_cannot_acquire_handle();
     } else {
         sts = xc_domain_shutdown(xc_handle, xen_domid, reason);
         if (sts != 0) {
-            fprintf(stderr, "xc_domain_shutdown failed to issue %s, "
-                    "sts %d, %s\n", reboot ? "reboot" : "poweroff",
-                    sts, strerror(errno));
+            trace_destroy_hvm_domain_failed_action(
+                reboot ? "reboot" : "poweroff", sts, strerror(errno)
+            );
         } else {
-            fprintf(stderr, "Issued domain %d %s\n", xen_domid,
-                    reboot ? "reboot" : "poweroff");
+            trace_destroy_hvm_domain_action(
+                xen_domid, reboot ? "reboot" : "poweroff"
+            );
         }
         xc_interface_close(xc_handle);
     }
-- 
γαῖα πυρί μιχθήτω

[PATCH 6/6] hw/xen: convert stderr prints to error/warn reports

[Manos Pitsidianakis]

According to the QEMU Coding Style document:

> Do not use printf(), fprintf() or monitor_printf(). Instead, use
> error_report() or error_vreport() from error-report.h. This ensures the
> error is reported in the right place (current monitor or stderr), and in
> a uniform format.
> Use error_printf() & friends to print additional information.

This commit changes fprintfs that report warnings and errors to the
appropriate report functions.

Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
---
 hw/xen/xen-hvm-common.c | 12 ++++++------
 hw/xen/xen-mapcache.c   |  5 ++---
 2 files changed, 8 insertions(+), 9 deletions(-)

diff --git a/hw/xen/xen-hvm-common.c b/hw/xen/xen-hvm-common.c
index 05a29c6f11..baa1adb9f2 100644
--- a/hw/xen/xen-hvm-common.c
+++ b/hw/xen/xen-hvm-common.c
@@ -20,8 +20,8 @@ void xen_ram_alloc(ram_addr_t ram_addr, ram_addr_t size, MemoryRegion *mr,
 
     if (runstate_check(RUN_STATE_INMIGRATE)) {
         /* RAM already populated in Xen */
-        fprintf(stderr, "%s: do not alloc "RAM_ADDR_FMT
-                " bytes of ram at "RAM_ADDR_FMT" when runstate is INMIGRATE\n",
+        warn_report("%s: do not alloc "RAM_ADDR_FMT
+                " bytes of ram at "RAM_ADDR_FMT" when runstate is INMIGRATE",
                 __func__, size, ram_addr);
         return;
     }
@@ -552,9 +552,9 @@ static void cpu_handle_ioreq(void *opaque)
         req->data = copy.data;
 
         if (req->state != STATE_IOREQ_INPROCESS) {
-            fprintf(stderr, "Badness in I/O request ... not in service?!: "
+            warn_report("Badness in I/O request ... not in service?!: "
                     "%x, ptr: %x, port: %"PRIx64", "
-                    "data: %"PRIx64", count: %u, size: %u, type: %u\n",
+                    "data: %"PRIx64", count: %u, size: %u, type: %u",
                     req->state, req->data_is_ptr, req->addr,
                     req->data, req->count, req->size, req->type);
             destroy_hvm_domain(false);
@@ -758,9 +758,9 @@ void xen_shutdown_fatal_error(const char *fmt, ...)
     va_list ap;
 
     va_start(ap, fmt);
-    vfprintf(stderr, fmt, ap);
+    error_vreport(fmt, ap);
     va_end(ap);
-    fprintf(stderr, "Will destroy the domain.\n");
+    error_report("Will destroy the domain.");
     /* destroy the domain */
     qemu_system_shutdown_request(SHUTDOWN_CAUSE_HOST_ERROR);
 }
diff --git a/hw/xen/xen-mapcache.c b/hw/xen/xen-mapcache.c
index 336c212376..4f956d048e 100644
--- a/hw/xen/xen-mapcache.c
+++ b/hw/xen/xen-mapcache.c
@@ -347,9 +347,8 @@ tryagain:
         MapCacheRev *reventry = g_new0(MapCacheRev, 1);
         entry->lock++;
         if (entry->lock == 0) {
-            fprintf(stderr,
-                    "mapcache entry lock overflow: "HWADDR_FMT_plx" -> %p\n",
-                    entry->paddr_index, entry->vaddr_base);
+            error_report("mapcache entry lock overflow: "HWADDR_FMT_plx" -> %p",
+                         entry->paddr_index, entry->vaddr_base);
             abort();
         }
         reventry->dma = dma;
-- 
γαῖα πυρί μιχθήτω

Re: [PATCH 1/6] hw/arm/z2: convert DPRINTF to tracepoints

[Alex Bennée]

Manos Pitsidianakis <manos.pitsidianakis@linaro.org> writes:

> Tracing DPRINTFs to stderr might not be desired. A developer that relies
> on tracepoints should be able to opt-in to each tracepoint and rely on
> QEMU's log redirection, instead of stderr by default.
>
> This commit converts DPRINTFs in this file that are used for tracing
> into tracepoints.
>
> Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
> ---
>  hw/arm/trace-events |  8 ++++++++
>  hw/arm/z2.c         | 26 +++++++++-----------------
>  2 files changed, 17 insertions(+), 17 deletions(-)
>
> diff --git a/hw/arm/trace-events b/hw/arm/trace-events
> index cdc1ea06a8..a262ad2e6a 100644
> --- a/hw/arm/trace-events
> +++ b/hw/arm/trace-events
> @@ -55,3 +55,11 @@ smmuv3_notify_flag_add(const char *iommu) "ADD SMMUNotifier node for iommu mr=%s
>  smmuv3_notify_flag_del(const char *iommu) "DEL SMMUNotifier node for iommu mr=%s"
>  smmuv3_inv_notifiers_iova(const char *name, uint16_t asid, uint16_t vmid, uint64_t iova, uint8_t tg, uint64_t num_pages) "iommu mr=%s asid=%d vmid=%d iova=0x%"PRIx64" tg=%d num_pages=0x%"PRIx64
>  
> +# z2.c
> +z2_lcd_cur_reg_update(uint8_t r) "reg: 0x%x"
> +z2_lcd_enable_disable(uint16_t v) "value: 0x%x"
> +z2_lcd_enable_disable_result(const char * result) "LCD %s"
> +z2_lcd_invalid_command(uint8_t value) "0x%x"
> +z2_aer915_send_too_log(int8_t msg) "message too long (%i bytes)"
> +z2_aer915_send(uint8_t reg, uint8_t value) "reg %d value 0x%02x"
> +z2_aer915_i2c_start_recv(uint16_t len) "I2C_START_RECV: short message with len %d"
> diff --git a/hw/arm/z2.c b/hw/arm/z2.c
> index 83741a4909..6c0889d698 100644
> --- a/hw/arm/z2.c
> +++ b/hw/arm/z2.c
> @@ -28,13 +28,7 @@
>  #include "cpu.h"
>  #include "qom/object.h"
>  #include "qapi/error.h"
> -
> -#ifdef DEBUG_Z2
> -#define DPRINTF(fmt, ...) \
> -        printf(fmt, ## __VA_ARGS__)
> -#else
> -#define DPRINTF(fmt, ...)
> -#endif
> +#include "trace.h"
>  
>  static const struct keymap map[0x100] = {
>      [0 ... 0xff] = { -1, -1 },
> @@ -127,22 +121,22 @@ static uint32_t zipit_lcd_transfer(SSIPeripheral *dev, uint32_t value)
>      if (z->pos == 3) {

Maybe we could just have:

   trace_z2_lcd_reg_update(z->buf[0], z->buf[1], z->buf[2]);

here

>          switch (z->buf[0]) {
>          case 0x74:
> -            DPRINTF("%s: reg: 0x%.2x\n", __func__, z->buf[2]);
> +            trace_z2_lcd_cur_reg_update(z->buf[2]);

drop this

>              z->cur_reg = z->buf[2];
>              break;
>          case 0x76:
>              val = z->buf[1] << 8 | z->buf[2];
> -            DPRINTF("%s: value: 0x%.4x\n", __func__, val);
> +            trace_z2_lcd_enable_disable(val);

and this

>              if (z->cur_reg == 0x22 && val == 0x0000) {
>                  z->enabled = 1;
> -                printf("%s: LCD enabled\n", __func__);
> +                trace_z2_lcd_enable_disable_result("enabled");
>              } else if (z->cur_reg == 0x10 && val == 0x0000) {
>                  z->enabled = 0;
> -                printf("%s: LCD disabled\n", __func__);
> +                trace_z2_lcd_enable_disable_result("disabled");

and just have two trace points, one for enable and one for disable to
save spamming a string into the log.

>              }
>              break;
>          default:
> -            DPRINTF("%s: unknown command!\n", __func__);
> +            trace_z2_lcd_invalid_command(z->buf[0]);

drop this, it can be inferred if we trace the command stream above.

>              break;
>          }
>          z->pos = 0;
> @@ -212,14 +206,12 @@ static int aer915_send(I2CSlave *i2c, uint8_t data)
>  
>      s->buf[s->len] = data;
>      if (s->len++ > 2) {
> -        DPRINTF("%s: message too long (%i bytes)\n",
> -            __func__, s->len);
> +        trace_z2_aer915_send_too_log(s->len);

long

>          return 1;
>      }
>  
>      if (s->len == 2) {
> -        DPRINTF("%s: reg %d value 0x%02x\n", __func__,
> -                s->buf[0], s->buf[1]);
> +        trace_z2_aer915_send(s->buf[0], s->buf[1]);
>      }
>  
>      return 0;
> @@ -235,7 +227,7 @@ static int aer915_event(I2CSlave *i2c, enum i2c_event event)
>          break;
>      case I2C_START_RECV:
>          if (s->len != 1) {
> -            DPRINTF("%s: short message!?\n", __func__);
> +            trace_z2_aer915_i2c_start_recv(s->len);
>          }
>          break;
>      case I2C_FINISH:

maybe better just to have a:

  trace_aer915_event(event, s->len)

before the return?

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

Re: [PATCH 2/6] hw/arm/strongarm.c: convert DPRINTF to tracepoints

[Alex Bennée]

Manos Pitsidianakis <manos.pitsidianakis@linaro.org> writes:

> Tracing DPRINTFs to stderr might not be desired. A developer that relies
> on tracepoints should be able to opt-in to each tracepoint and rely on
> QEMU's log redirection, instead of stderr by default.
>
> This commit converts DPRINTFs in this file that are used for tracing
> into tracepoints.
>
> Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
> ---
>  hw/arm/strongarm.c  | 49 +++++++++++++++++++--------------------------
>  hw/arm/trace-events | 18 +++++++++++++++++
>  2 files changed, 39 insertions(+), 28 deletions(-)
>
> diff --git a/hw/arm/strongarm.c b/hw/arm/strongarm.c
> index fef3638aca..3ff748e826 100644
> --- a/hw/arm/strongarm.c
> +++ b/hw/arm/strongarm.c
> @@ -46,8 +46,7 @@
>  #include "qemu/cutils.h"
>  #include "qemu/log.h"
>  #include "qom/object.h"
> -
> -//#define DEBUG
> +#include "trace.h"
>  
>  /*
>   TODO
> @@ -66,12 +65,6 @@
>   - Enhance UART with modem signals
>   */
>  
> -#ifdef DEBUG
> -# define DPRINTF(format, ...) printf(format , ## __VA_ARGS__)
> -#else
> -# define DPRINTF(format, ...) do { } while (0)
> -#endif
> -
>  static struct {
>      hwaddr io_base;
>      int irq;
> @@ -151,8 +144,7 @@ static uint64_t strongarm_pic_mem_read(void *opaque, hwaddr offset,
>      case ICPR:
>          return s->pending;
>      default:
> -        printf("%s: Bad register offset 0x" HWADDR_FMT_plx "\n",
> -                        __func__, offset);
> +        trace_strongarm_pic_mem_read(offset);

I think these should be:

  qemu_log_mask(LOG_GUEST_ERROR, "...")

>          return 0;
>      }
>  }
> @@ -173,8 +165,7 @@ static void strongarm_pic_mem_write(void *opaque, hwaddr offset,
>          s->int_idle = (value & 1) ? 0 : ~0;
>          break;
>      default:
> -        printf("%s: Bad register offset 0x" HWADDR_FMT_plx "\n",
> -                        __func__, offset);
> +        trace_strongarm_pic_mem_write(offset);

LOG_GUEST_ERROR again.

>          break;
>      }
>      strongarm_pic_update(s);
> @@ -333,7 +324,7 @@ static uint64_t strongarm_rtc_read(void *opaque, hwaddr addr,
>                  ((qemu_clock_get_ms(rtc_clock) - s->last_hz) << 15) /
>                  (1000 * ((s->rttr & 0xffff) + 1));
>      default:
> -        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
> +        trace_strongarm_rtc_read(addr);
>          return 0;
>      }
>  }
> @@ -375,7 +366,7 @@ static void strongarm_rtc_write(void *opaque, hwaddr addr,
>          break;
>  
>      default:
> -        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
> +        trace_strongarm_rtc_write(addr);
>      }
>  }
>  
> @@ -581,7 +572,7 @@ static uint64_t strongarm_gpio_read(void *opaque, hwaddr offset,
>          return s->status;
>  
>      default:
> -        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
> +        trace_strongarm_gpio_read(offset);
>      }
>  
>      return 0;
> @@ -626,7 +617,7 @@ static void strongarm_gpio_write(void *opaque, hwaddr offset,
>          break;
>  
>      default:
> -        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
> +        trace_strongarm_gpio_write(offset);
>      }
>  }
>  
> @@ -782,7 +773,7 @@ static uint64_t strongarm_ppc_read(void *opaque, hwaddr offset,
>          return s->ppfr | ~0x7f001;
>  
>      default:
> -        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
> +        trace_strongarm_ppc_read(offset);
>      }
>  
>      return 0;
> @@ -817,7 +808,7 @@ static void strongarm_ppc_write(void *opaque, hwaddr offset,
>          break;
>  
>      default:
> -        printf("%s: Bad offset 0x" HWADDR_FMT_plx "\n", __func__, offset);
> +        trace_strongarm_ppc_write(offset);
>      }
>  }
>

In fact all of the above I thing are LOG_GUEST_ERRORs


> @@ -1029,8 +1020,11 @@ static void strongarm_uart_update_parameters(StrongARMUARTState *s)
>      s->char_transmit_time =  (NANOSECONDS_PER_SECOND / speed) * frame_size;
>      qemu_chr_fe_ioctl(&s->chr, CHR_IOCTL_SERIAL_SET_PARAMS, &ssp);
>  
> -    DPRINTF(stderr, "%s speed=%d parity=%c data=%d stop=%d\n", s->chr->label,
> -            speed, parity, data_bits, stop_bits);
> +    trace_strongarm_uart_update_parameters(s->chr.chr->label?:"NULL",
> +                                           speed,
> +                                           parity,
> +                                           data_bits,
> +                                           stop_bits);
>  }

This one is good, and the remaining ones are also guest errors.

>  
>  static void strongarm_uart_rx_to(void *opaque)
> @@ -1164,7 +1158,7 @@ static uint64_t strongarm_uart_read(void *opaque, hwaddr addr,
>          return s->utsr1;
>  
>      default:
> -        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
> +        trace_strongarm_uart_read_bad_register(addr);
>          return 0;
>      }
>  }
> @@ -1221,7 +1215,7 @@ static void strongarm_uart_write(void *opaque, hwaddr addr,
>          break;
>  
>      default:
> -        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
> +        trace_strongarm_uart_write_bad_register(addr);
>      }
>  }
>  
> @@ -1434,7 +1428,7 @@ static uint64_t strongarm_ssp_read(void *opaque, hwaddr addr,
>              return 0xffffffff;
>          }
>          if (s->rx_level < 1) {
> -            printf("%s: SSP Rx Underrun\n", __func__);
> +            trace_strongarm_ssp_read_underrun();

I think is ok for a tracepoint.

>              return 0xffffffff;
>          }
>          s->rx_level--;
> @@ -1443,7 +1437,7 @@ static uint64_t strongarm_ssp_read(void *opaque, hwaddr addr,
>          strongarm_ssp_fifo_update(s);
>          return retval;
>      default:
> -        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
> +        trace_strongarm_ssp_read(addr);
>          break;
>      }
>      return 0;
> @@ -1458,8 +1452,7 @@ static void strongarm_ssp_write(void *opaque, hwaddr addr,
>      case SSCR0:
>          s->sscr[0] = value & 0xffbf;
>          if ((s->sscr[0] & SSCR0_SSE) && SSCR0_DSS(value) < 4) {
> -            printf("%s: Wrong data size: %i bits\n", __func__,
> -                   (int)SSCR0_DSS(value));
> +            trace_strongarm_ssp_write_wrong_data_size((int)SSCR0_DSS(value));
>          }
>          if (!(value & SSCR0_SSE)) {
>              s->sssr = 0;
> @@ -1471,7 +1464,7 @@ static void strongarm_ssp_write(void *opaque, hwaddr addr,
>      case SSCR1:
>          s->sscr[1] = value & 0x2f;
>          if (value & SSCR1_LBM) {
> -            printf("%s: Attempt to use SSP LBM mode\n", __func__);
> +            trace_strongarm_ssp_write_wrong_data_size_invalid();

Maybe it would just be better to have a:

  trace_strongarm_ssp_write(addr, value)

at the top of the function?

>          }
>          strongarm_ssp_fifo_update(s);
>          break;
> @@ -1509,7 +1502,7 @@ static void strongarm_ssp_write(void *opaque, hwaddr addr,
>          break;
>  
>      default:
> -        printf("%s: Bad register 0x" HWADDR_FMT_plx "\n", __func__, addr);
> +        trace_strongarm_ssp_write_bad_register(addr);

guest error.

>          break;
>      }
>  }
> diff --git a/hw/arm/trace-events b/hw/arm/trace-events
> index a262ad2e6a..a6a67d5f16 100644
> --- a/hw/arm/trace-events
> +++ b/hw/arm/trace-events
> @@ -63,3 +63,21 @@ z2_lcd_invalid_command(uint8_t value) "0x%x"
>  z2_aer915_send_too_log(int8_t msg) "message too long (%i bytes)"
>  z2_aer915_send(uint8_t reg, uint8_t value) "reg %d value 0x%02x"
>  z2_aer915_i2c_start_recv(uint16_t len) "I2C_START_RECV: short message with len %d"
> +
> +# strongarm.c
> +strongarm_uart_update_parameters(const char *label, int speed, char parity, int data_bits, int stop_bits) "%s speed=%d parity=%c data=%d stop=%d"
> +strongarm_uart_read_bad_register(uint64_t addr) "Bad uart register 0x%zu"
> +strongarm_uart_write_bad_register(uint64_t addr) "Bad uart register 0x%zu"
> +strongarm_pic_mem_read(uint64_t offset) "Bad pic mem register read offset 0x%zu"
> +strongarm_pic_mem_write(uint64_t offset) "Bad pic mem register write offset 0x%zu"
> +strongarm_rtc_read(uint64_t addr) "Bad rtc register read 0x%zu"
> +strongarm_rtc_write(uint64_t addr) "Bad rtc register write 0x%zu"
> +strongarm_gpio_read(uint64_t offset) "Bad gpio read offset 0x%zu"
> +strongarm_gpio_write(uint64_t offset) "Bad gpio write offset 0x%zu"
> +strongarm_ppc_write(uint64_t offset) "Bad ppc write offset 0x%zu"
> +strongarm_ppc_read(uint64_t offset) "Bad ppc write offset 0x%zu"
> +strongarm_ssp_read_underrun(void) "SSP Rx Underrun"
> +strongarm_ssp_read(uint64_t addr) "Bad register 0x%zu"
> +strongarm_ssp_write_wrong_data_size(int v) "Wrong data size: %i bits"
> +strongarm_ssp_write_wrong_data_size_invalid(void) "Attempt to use SSP LBM mode"
> +strongarm_ssp_write_bad_register(uint64_t addr) "Bad register 0x%zu"

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro

Re: [PATCH 3/6] hw/arm/xen_arm.c: convert DPRINTF to tracepoints

[Alex Bennée]

Manos Pitsidianakis <manos.pitsidianakis@linaro.org> writes:

> Tracing DPRINTFs to stderr might not be desired. A developer that relies
> on tracepoints should be able to opt-in to each tracepoint and rely on
> QEMU's log redirection, instead of stderr by default.
>
> This commit converts DPRINTFs in this file that are used for tracing
> into tracepoints.
>
> Signed-off-by: Manos Pitsidianakis <manos.pitsidianakis@linaro.org>
> ---
>  hw/arm/trace-events |  7 +++++++
>  hw/arm/xen_arm.c    | 26 +++++++++++++++-----------
>  2 files changed, 22 insertions(+), 11 deletions(-)
>
> diff --git a/hw/arm/trace-events b/hw/arm/trace-events
> index a6a67d5f16..e3f5d677d7 100644
> --- a/hw/arm/trace-events
> +++ b/hw/arm/trace-events
> @@ -81,3 +81,10 @@ strongarm_ssp_read(uint64_t addr) "Bad register 0x%zu"
>  strongarm_ssp_write_wrong_data_size(int v) "Wrong data size: %i bits"
>  strongarm_ssp_write_wrong_data_size_invalid(void) "Attempt to use SSP LBM mode"
>  strongarm_ssp_write_bad_register(uint64_t addr) "Bad register 0x%zu"
> +
> +# xen_arm.c
> +xen_create_virtio_mmio_devices(int i, int irq, uint64_t base) "Created virtio-mmio device %d: irq %d base 0x%lx"
> +xen_init_ram(const char *hi_xor_low, uint64_t base, uint64_t size) "Initialized region xen.ram.%s: base 0x%lx size 0x%lx"
> +xen_enable_tpm_not_found(void) "Couldn't find tmp0 backend"
> +xen_enable_tpm(uint64_t addr) "Connected tpmdev at address 0x%lx"
> +xen_arm_init(const char *msg) "%s"
> diff --git a/hw/arm/xen_arm.c b/hw/arm/xen_arm.c
> index a5631529d0..a024117d22 100644
> --- a/hw/arm/xen_arm.c
> +++ b/hw/arm/xen_arm.c
> @@ -34,6 +34,7 @@
>  #include "hw/xen/xen-hvm-common.h"
>  #include "sysemu/tpm.h"
>  #include "hw/xen/arch_hvm.h"
> +#include "trace.h"
>  
>  #define TYPE_XEN_ARM  MACHINE_TYPE_NAME("xenpvh")
>  OBJECT_DECLARE_SIMPLE_TYPE(XenArmState, XEN_ARM)
> @@ -91,8 +92,9 @@ static void xen_create_virtio_mmio_devices(XenArmState *xam)
>  
>          sysbus_create_simple("virtio-mmio", base, irq);
>  
> -        DPRINTF("Created virtio-mmio device %d: irq %d base 0x%lx\n",
> -                i, GUEST_VIRTIO_MMIO_SPI_FIRST + i, base);
> +        trace_xen_create_virtio_mmio_devices(i,
> +                                             GUEST_VIRTIO_MMIO_SPI_FIRST + i,
> +                                             base);
>      }
>  }
>  
> @@ -117,15 +119,13 @@ static void xen_init_ram(MachineState *machine)
>      memory_region_init_alias(&ram_lo, NULL, "xen.ram.lo", &ram_memory,
>                               GUEST_RAM0_BASE, ram_size[0]);
>      memory_region_add_subregion(sysmem, GUEST_RAM0_BASE, &ram_lo);
> -    DPRINTF("Initialized region xen.ram.lo: base 0x%llx size 0x%lx\n",
> -            GUEST_RAM0_BASE, ram_size[0]);
> +    trace_xen_init_ram("lo", GUEST_RAM0_BASE, ram_size[0]);
>  
>      if (ram_size[1] > 0) {
>          memory_region_init_alias(&ram_hi, NULL, "xen.ram.hi", &ram_memory,
>                                   GUEST_RAM1_BASE, ram_size[1]);
>          memory_region_add_subregion(sysmem, GUEST_RAM1_BASE, &ram_hi);
> -        DPRINTF("Initialized region xen.ram.hi: base 0x%llx size 0x%lx\n",
> -                GUEST_RAM1_BASE, ram_size[1]);
> +        trace_xen_init_ram("hi", GUEST_RAM1_BASE, ram_size[1]);
>      }

I wonder if a single trace_xen_init_ram(machine->ram_size) at the top
would be better as everything can be inferred from that.

>  }
>  
> @@ -158,7 +158,7 @@ static void xen_enable_tpm(XenArmState *xam)
>  
>      TPMBackend *be = qemu_find_tpm_be("tpm0");
>      if (be == NULL) {
> -        DPRINTF("Couldn't fine the backend for tpm0\n");
> +        trace_xen_enable_tpm_not_found();

This smells like it should be an error_report (or maybe warn_report) as
its a misconfiguration the user/tools should know about.

>          return;
>      }
>      dev = qdev_new(TYPE_TPM_TIS_SYSBUS);
> @@ -168,7 +168,7 @@ static void xen_enable_tpm(XenArmState *xam)
>      sysbus_realize_and_unref(busdev, &error_fatal);
>      sysbus_mmio_map(busdev, 0, xam->cfg.tpm_base_addr);
>  
> -    DPRINTF("Connected tpmdev at address 0x%lx\n", xam->cfg.tpm_base_addr);
> +    trace_xen_enable_tpm(xam->cfg.tpm_base_addr);
>  }
>  #endif
>  
> @@ -179,8 +179,11 @@ static void xen_arm_init(MachineState *machine)
>      xam->state =  g_new0(XenIOState, 1);
>  
>      if (machine->ram_size == 0) {
> -        DPRINTF("ram_size not specified. QEMU machine started without IOREQ"
> -                "(no emulated devices including Virtio)\n");
> +        trace_xen_arm_init("ram_size not specified. "
> +                           "QEMU machine started "
> +                           "without IOREQ "
> +                           "(no emulated devices"
> +                           "including Virtio)");

again at least an warn_report...

>          return;
>      }
>  
> @@ -194,7 +197,8 @@ static void xen_arm_init(MachineState *machine)
>      if (xam->cfg.tpm_base_addr) {
>          xen_enable_tpm(xam);
>      } else {
> -        DPRINTF("tpm-base-addr is not provided. TPM will not be enabled\n");
> +        trace_xen_arm_init("tpm-base-addr is not provided."
> +                           "TPM will not be enabled");

warn_report.

>      }
>  #endif
>  }

-- 
Alex Bennée
Virtualisation Tech Lead @ Linaro