[PATCH 0/6] Various tracing patches

[PATCH 0/6] Various tracing patches

[Bernhard Beschow]

This series enhances the tracing experience of some i.MX devices by adding new
trace events and by converting from DPRINTF. SMBus gets also converted from
DPRINTF to trace events. Finally, when tracing memory region operations, host
pointers aren't traced any longer and are substituted by their memory region
names.

Bernhard Beschow (6):
  hw/watchdog/wdt_imx2: Trace MMIO access
  hw/watchdog/wdt_imx2: Trace timer activity
  hw/misc/imx7_snvs: Trace MMIO access
  hw/misc/imx6_ccm: Convert DPRINTF to trace events
  hw/i2c/pm_smbus: Convert DPRINTF to trace events
  system/memory: Trace names of MemoryRegions rather than host pointers

 docs/devel/tracing.rst   |  4 ++--
 hw/i2c/pm_smbus.c        | 18 ++++--------------
 hw/misc/imx6_ccm.c       | 41 ++++++++++++++--------------------------
 hw/misc/imx7_snvs.c      |  5 +++++
 hw/watchdog/wdt_imx2.c   | 28 +++++++++++++++++++++------
 system/memory.c          | 26 +++++++++++++++----------
 hw/i2c/trace-events      |  6 ++++++
 hw/misc/trace-events     | 19 +++++++++++++++++++
 hw/watchdog/trace-events |  6 ++++++
 system/trace-events      | 12 ++++++------
 10 files changed, 100 insertions(+), 65 deletions(-)

-- 
2.42.0

[PATCH 1/6] hw/watchdog/wdt_imx2: Trace MMIO access

[Bernhard Beschow]

Signed-off-by: Bernhard Beschow <shentey@gmail.com>
---
 hw/watchdog/wdt_imx2.c   | 24 ++++++++++++++++++------
 hw/watchdog/trace-events |  4 ++++
 2 files changed, 22 insertions(+), 6 deletions(-)

diff --git a/hw/watchdog/wdt_imx2.c b/hw/watchdog/wdt_imx2.c
index e776a2fbd4..885ebd3978 100644
--- a/hw/watchdog/wdt_imx2.c
+++ b/hw/watchdog/wdt_imx2.c
@@ -17,6 +17,7 @@
 #include "hw/qdev-properties.h"
 
 #include "hw/watchdog/wdt_imx2.h"
+#include "trace.h"
 
 static void imx2_wdt_interrupt(void *opaque)
 {
@@ -67,20 +68,29 @@ static void imx2_wdt_reset(DeviceState *dev)
 static uint64_t imx2_wdt_read(void *opaque, hwaddr addr, unsigned int size)
 {
     IMX2WdtState *s = IMX2_WDT(opaque);
+    uint16_t value = 0;
 
     switch (addr) {
     case IMX2_WDT_WCR:
-        return s->wcr;
+        value = s->wcr;
+        break;
     case IMX2_WDT_WSR:
-        return s->wsr;
+        value = s->wsr;
+        break;
     case IMX2_WDT_WRSR:
-        return s->wrsr;
+        value = s->wrsr;
+        break;
     case IMX2_WDT_WICR:
-        return s->wicr;
+        value = s->wicr;
+        break;
     case IMX2_WDT_WMCR:
-        return s->wmcr;
+        value = s->wmcr;
+        break;
     }
-    return 0;
+
+    trace_imx2_wdt_read(addr, value);
+
+    return value;
 }
 
 static void imx_wdt2_update_itimer(IMX2WdtState *s, bool start)
@@ -137,6 +147,8 @@ static void imx2_wdt_write(void *opaque, hwaddr addr,
 {
     IMX2WdtState *s = IMX2_WDT(opaque);
 
+    trace_imx2_wdt_write(addr, value);
+
     switch (addr) {
     case IMX2_WDT_WCR:
         if (s->wcr_locked) {
diff --git a/hw/watchdog/trace-events b/hw/watchdog/trace-events
index 2739570652..874968cc06 100644
--- a/hw/watchdog/trace-events
+++ b/hw/watchdog/trace-events
@@ -17,6 +17,10 @@ cmsdk_apb_watchdog_lock(uint32_t lock) "CMSDK APB watchdog: lock %" PRIu32
 aspeed_wdt_read(uint64_t addr, uint32_t size) "@0x%" PRIx64 " size=%d"
 aspeed_wdt_write(uint64_t addr, uint32_t size, uint64_t data) "@0x%" PRIx64 " size=%d value=0x%"PRIx64
 
+# wdt_imx2.c
+imx2_wdt_read(uint32_t addr, uint16_t data) "[0x%" PRIx32 "] -> 0x%" PRIx16
+imx2_wdt_write(uint32_t addr, uint16_t data) "[0x%" PRIx32 "] <- 0x%" PRIx16
+
 # spapr_watchdog.c
 spapr_watchdog_start(uint64_t flags, uint64_t num, uint64_t timeout) "Flags 0x%" PRIx64 " num=%" PRId64 " %" PRIu64 "ms"
 spapr_watchdog_stop(uint64_t num, uint64_t ret) "num=%" PRIu64 " ret=%" PRId64
-- 
2.42.0

Re: [PATCH 1/6] hw/watchdog/wdt_imx2: Trace MMIO access

[Philippe Mathieu-Daudé]

On 28/10/23 14:24, Bernhard Beschow wrote:
> Signed-off-by: Bernhard Beschow <shentey@gmail.com>
> ---
>   hw/watchdog/wdt_imx2.c   | 24 ++++++++++++++++++------
>   hw/watchdog/trace-events |  4 ++++
>   2 files changed, 22 insertions(+), 6 deletions(-)

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>

[PATCH 2/6] hw/watchdog/wdt_imx2: Trace timer activity

[Bernhard Beschow]

Signed-off-by: Bernhard Beschow <shentey@gmail.com>
---
 hw/watchdog/wdt_imx2.c   | 4 ++++
 hw/watchdog/trace-events | 2 ++
 2 files changed, 6 insertions(+)

diff --git a/hw/watchdog/wdt_imx2.c b/hw/watchdog/wdt_imx2.c
index 885ebd3978..891d7beb2a 100644
--- a/hw/watchdog/wdt_imx2.c
+++ b/hw/watchdog/wdt_imx2.c
@@ -23,6 +23,8 @@ static void imx2_wdt_interrupt(void *opaque)
 {
     IMX2WdtState *s = IMX2_WDT(opaque);
 
+    trace_imx2_wdt_interrupt();
+
     s->wicr |= IMX2_WDT_WICR_WTIS;
     qemu_set_irq(s->irq, 1);
 }
@@ -31,6 +33,8 @@ static void imx2_wdt_expired(void *opaque)
 {
     IMX2WdtState *s = IMX2_WDT(opaque);
 
+    trace_imx2_wdt_expired();
+
     s->wrsr = IMX2_WDT_WRSR_TOUT;
 
     /* Perform watchdog action if watchdog is enabled */
diff --git a/hw/watchdog/trace-events b/hw/watchdog/trace-events
index 874968cc06..ad3be1e9bd 100644
--- a/hw/watchdog/trace-events
+++ b/hw/watchdog/trace-events
@@ -20,6 +20,8 @@ aspeed_wdt_write(uint64_t addr, uint32_t size, uint64_t data) "@0x%" PRIx64 " si
 # wdt_imx2.c
 imx2_wdt_read(uint32_t addr, uint16_t data) "[0x%" PRIx32 "] -> 0x%" PRIx16
 imx2_wdt_write(uint32_t addr, uint16_t data) "[0x%" PRIx32 "] <- 0x%" PRIx16
+imx2_wdt_interrupt(void) ""
+imx2_wdt_expired(void) ""
 
 # spapr_watchdog.c
 spapr_watchdog_start(uint64_t flags, uint64_t num, uint64_t timeout) "Flags 0x%" PRIx64 " num=%" PRId64 " %" PRIu64 "ms"
-- 
2.42.0

[PATCH 3/6] hw/misc/imx7_snvs: Trace MMIO access

[Bernhard Beschow]

Signed-off-by: Bernhard Beschow <shentey@gmail.com>
---
 hw/misc/imx7_snvs.c  | 5 +++++
 hw/misc/trace-events | 4 ++++
 2 files changed, 9 insertions(+)

diff --git a/hw/misc/imx7_snvs.c b/hw/misc/imx7_snvs.c
index ee7698bd9c..a245f96cd4 100644
--- a/hw/misc/imx7_snvs.c
+++ b/hw/misc/imx7_snvs.c
@@ -16,9 +16,12 @@
 #include "hw/misc/imx7_snvs.h"
 #include "qemu/module.h"
 #include "sysemu/runstate.h"
+#include "trace.h"
 
 static uint64_t imx7_snvs_read(void *opaque, hwaddr offset, unsigned size)
 {
+    trace_imx7_snvs_read(offset, 0);
+
     return 0;
 }
 
@@ -28,6 +31,8 @@ static void imx7_snvs_write(void *opaque, hwaddr offset,
     const uint32_t value = v;
     const uint32_t mask  = SNVS_LPCR_TOP | SNVS_LPCR_DP_EN;
 
+    trace_imx7_snvs_write(offset, value);
+
     if (offset == SNVS_LPCR && ((value & mask) == mask)) {
         qemu_system_shutdown_request(SHUTDOWN_CAUSE_GUEST_SHUTDOWN);
     }
diff --git a/hw/misc/trace-events b/hw/misc/trace-events
index 24ba7cc4d0..426a8472b6 100644
--- a/hw/misc/trace-events
+++ b/hw/misc/trace-events
@@ -115,6 +115,10 @@ msf2_sysreg_write_pll_status(void) "Invalid write to read only PLL status regist
 imx7_gpr_read(uint64_t offset) "addr 0x%08" PRIx64
 imx7_gpr_write(uint64_t offset, uint64_t value) "addr 0x%08" PRIx64 "value 0x%08" PRIx64
 
+# imx7_snvs.c
+imx7_snvs_read(uint64_t offset, uint32_t value) "addr 0x%08" PRIx64 "value 0x%08" PRIx32
+imx7_snvs_write(uint64_t offset, uint32_t value) "addr 0x%08" PRIx64 "value 0x%08" PRIx32
+
 # mos6522.c
 mos6522_set_counter(int index, unsigned int val) "T%d.counter=%d"
 mos6522_get_next_irq_time(uint16_t latch, int64_t d, int64_t delta) "latch=%d counter=0x%"PRIx64 " delta_next=0x%"PRIx64
-- 
2.42.0

Re: [PATCH 3/6] hw/misc/imx7_snvs: Trace MMIO access

[Philippe Mathieu-Daudé]

On 28/10/23 14:24, Bernhard Beschow wrote:
> Signed-off-by: Bernhard Beschow <shentey@gmail.com>
> ---
>   hw/misc/imx7_snvs.c  | 5 +++++
>   hw/misc/trace-events | 4 ++++
>   2 files changed, 9 insertions(+)

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>

[PATCH 4/6] hw/misc/imx6_ccm: Convert DPRINTF to trace events

[Bernhard Beschow]

Signed-off-by: Bernhard Beschow <shentey@gmail.com>
---
 hw/misc/imx6_ccm.c   | 41 ++++++++++++++---------------------------
 hw/misc/trace-events | 15 +++++++++++++++
 2 files changed, 29 insertions(+), 27 deletions(-)

diff --git a/hw/misc/imx6_ccm.c b/hw/misc/imx6_ccm.c
index 4c830fd89a..85af466c2b 100644
--- a/hw/misc/imx6_ccm.c
+++ b/hw/misc/imx6_ccm.c
@@ -15,18 +15,7 @@
 #include "migration/vmstate.h"
 #include "qemu/log.h"
 #include "qemu/module.h"
-
-#ifndef DEBUG_IMX6_CCM
-#define DEBUG_IMX6_CCM 0
-#endif
-
-#define DPRINTF(fmt, args...) \
-    do { \
-        if (DEBUG_IMX6_CCM) { \
-            fprintf(stderr, "[%s]%s: " fmt , TYPE_IMX6_CCM, \
-                                             __func__, ##args); \
-        } \
-    } while (0)
+#include "trace.h"
 
 static const char *imx6_ccm_reg_name(uint32_t reg)
 {
@@ -263,7 +252,7 @@ static uint64_t imx6_analog_get_pll2_clk(IMX6CCMState *dev)
         freq *= 20;
     }
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_analog_get_pll2_clk(freq);
 
     return freq;
 }
@@ -275,7 +264,7 @@ static uint64_t imx6_analog_get_pll2_pfd0_clk(IMX6CCMState *dev)
     freq = imx6_analog_get_pll2_clk(dev) * 18
            / EXTRACT(dev->analog[CCM_ANALOG_PFD_528], PFD0_FRAC);
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_analog_get_pll2_pfd0_clk(freq);
 
     return freq;
 }
@@ -287,7 +276,7 @@ static uint64_t imx6_analog_get_pll2_pfd2_clk(IMX6CCMState *dev)
     freq = imx6_analog_get_pll2_clk(dev) * 18
            / EXTRACT(dev->analog[CCM_ANALOG_PFD_528], PFD2_FRAC);
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_analog_get_pll2_pfd2_clk(freq);
 
     return freq;
 }
@@ -315,7 +304,7 @@ static uint64_t imx6_analog_get_periph_clk(IMX6CCMState *dev)
         break;
     }
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_analog_get_periph_clk(freq);
 
     return freq;
 }
@@ -327,7 +316,7 @@ static uint64_t imx6_ccm_get_ahb_clk(IMX6CCMState *dev)
     freq = imx6_analog_get_periph_clk(dev)
            / (1 + EXTRACT(dev->ccm[CCM_CBCDR], AHB_PODF));
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_ccm_get_ahb_clk(freq);
 
     return freq;
 }
@@ -339,7 +328,7 @@ static uint64_t imx6_ccm_get_ipg_clk(IMX6CCMState *dev)
     freq = imx6_ccm_get_ahb_clk(dev)
            / (1 + EXTRACT(dev->ccm[CCM_CBCDR], IPG_PODF));
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_ccm_get_ipg_clk(freq);
 
     return freq;
 }
@@ -351,7 +340,7 @@ static uint64_t imx6_ccm_get_per_clk(IMX6CCMState *dev)
     freq = imx6_ccm_get_ipg_clk(dev)
            / (1 + EXTRACT(dev->ccm[CCM_CSCMR1], PERCLK_PODF));
 
-    DPRINTF("freq = %u\n", (uint32_t)freq);
+    trace_imx6_ccm_get_per_clk(freq);
 
     return freq;
 }
@@ -385,7 +374,7 @@ static uint32_t imx6_ccm_get_clock_frequency(IMXCCMState *dev, IMXClk clock)
         break;
     }
 
-    DPRINTF("Clock = %d) = %u\n", clock, freq);
+    trace_imx6_ccm_get_clock_frequency(clock, freq);
 
     return freq;
 }
@@ -394,7 +383,7 @@ static void imx6_ccm_reset(DeviceState *dev)
 {
     IMX6CCMState *s = IMX6_CCM(dev);
 
-    DPRINTF("\n");
+    trace_imx6_ccm_reset();
 
     s->ccm[CCM_CCR] = 0x040116FF;
     s->ccm[CCM_CCDR] = 0x00000000;
@@ -483,7 +472,7 @@ static uint64_t imx6_ccm_read(void *opaque, hwaddr offset, unsigned size)
 
     value = s->ccm[index];
 
-    DPRINTF("reg[%s] => 0x%" PRIx32 "\n", imx6_ccm_reg_name(index), value);
+    trace_imx6_ccm_read(imx6_ccm_reg_name(index), value);
 
     return (uint64_t)value;
 }
@@ -494,8 +483,7 @@ static void imx6_ccm_write(void *opaque, hwaddr offset, uint64_t value,
     uint32_t index = offset >> 2;
     IMX6CCMState *s = (IMX6CCMState *)opaque;
 
-    DPRINTF("reg[%s] <= 0x%" PRIx32 "\n", imx6_ccm_reg_name(index),
-            (uint32_t)value);
+    trace_imx6_ccm_write(imx6_ccm_reg_name(index), (uint32_t)value);
 
     /*
      * We will do a better implementation later. In particular some bits
@@ -591,7 +579,7 @@ static uint64_t imx6_analog_read(void *opaque, hwaddr offset, unsigned size)
         break;
     }
 
-    DPRINTF("reg[%s] => 0x%" PRIx32 "\n", imx6_analog_reg_name(index), value);
+    trace_imx6_analog_read(imx6_analog_reg_name(index), value);
 
     return (uint64_t)value;
 }
@@ -602,8 +590,7 @@ static void imx6_analog_write(void *opaque, hwaddr offset, uint64_t value,
     uint32_t index = offset >> 2;
     IMX6CCMState *s = (IMX6CCMState *)opaque;
 
-    DPRINTF("reg[%s] <= 0x%" PRIx32 "\n", imx6_analog_reg_name(index),
-            (uint32_t)value);
+    trace_imx6_analog_write(imx6_analog_reg_name(index), (uint32_t)value);
 
     switch (index) {
     case CCM_ANALOG_PLL_ARM_SET:
diff --git a/hw/misc/trace-events b/hw/misc/trace-events
index 426a8472b6..f359fb3add 100644
--- a/hw/misc/trace-events
+++ b/hw/misc/trace-events
@@ -196,6 +196,21 @@ iotkit_secctl_s_write(uint32_t offset, uint64_t data, unsigned size) "IoTKit Sec
 iotkit_secctl_ns_read(uint32_t offset, uint64_t data, unsigned size) "IoTKit SecCtl NS regs read: offset 0x%x data 0x%" PRIx64 " size %u"
 iotkit_secctl_ns_write(uint32_t offset, uint64_t data, unsigned size) "IoTKit SecCtl NS regs write: offset 0x%x data 0x%" PRIx64 " size %u"
 
+# imx6_ccm.c
+imx6_analog_get_periph_clk(uint32_t freq) "freq = %u"
+imx6_analog_get_pll2_clk(uint32_t freq) "freq = %u"
+imx6_analog_get_pll2_pfd0_clk(uint32_t freq) "freq = %u"
+imx6_analog_get_pll2_pfd2_clk(uint32_t freq) "freq = %u"
+imx6_analog_read(const char *reg, uint32_t value) "reg[%s] => 0x%" PRIx32
+imx6_analog_write(const char *reg, uint32_t value) "reg[%s] <= 0x%" PRIx32
+imx6_ccm_get_ahb_clk(uint32_t freq) "freq = %u"
+imx6_ccm_get_ipg_clk(uint32_t freq) "freq = %u"
+imx6_ccm_get_per_clk(uint32_t freq) "freq = %u"
+imx6_ccm_get_clock_frequency(unsigned clock, uint32_t freq) "(Clock = %d) = %u"
+imx6_ccm_read(const char *reg, uint32_t value) "reg[%s] => 0x%" PRIx32
+imx6_ccm_reset(void) ""
+imx6_ccm_write(const char *reg, uint32_t value) "reg[%s] <= 0x%" PRIx32
+
 # imx6ul_ccm.c
 ccm_entry(void) ""
 ccm_freq(uint32_t freq) "freq = %d"
-- 
2.42.0

Re: [PATCH 4/6] hw/misc/imx6_ccm: Convert DPRINTF to trace events

[Philippe Mathieu-Daudé]

Hi Bernhard,

On 28/10/23 14:24, Bernhard Beschow wrote:
> Signed-off-by: Bernhard Beschow <shentey@gmail.com>
> ---
>   hw/misc/imx6_ccm.c   | 41 ++++++++++++++---------------------------
>   hw/misc/trace-events | 15 +++++++++++++++
>   2 files changed, 29 insertions(+), 27 deletions(-)


> +# imx6_ccm.c
> +imx6_analog_get_periph_clk(uint32_t freq) "freq = %u"

Preferably explicit the unit, as "freq = %u Hz".

> +imx6_analog_get_pll2_clk(uint32_t freq) "freq = %u"
> +imx6_analog_get_pll2_pfd0_clk(uint32_t freq) "freq = %u"
> +imx6_analog_get_pll2_pfd2_clk(uint32_t freq) "freq = %u"

> +imx6_ccm_get_ahb_clk(uint32_t freq) "freq = %u"
> +imx6_ccm_get_ipg_clk(uint32_t freq) "freq = %u"
> +imx6_ccm_get_per_clk(uint32_t freq) "freq = %u"
> +imx6_ccm_get_clock_frequency(unsigned clock, uint32_t freq) "(Clock = %d) = %u"

'freq' is uint64_t, but I suppose 32-bit is enough, so I'm
not against the implicit cast.

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>

[PATCH 5/6] hw/i2c/pm_smbus: Convert DPRINTF to trace events

[Bernhard Beschow]

Let the trace messages slightly deviate from the function names
("smb" -> "smbus") being traced in order to avoid conflights with the SMB
protocol.

Signed-off-by: Bernhard Beschow <shentey@gmail.com>
---
 hw/i2c/pm_smbus.c   | 18 ++++--------------
 hw/i2c/trace-events |  6 ++++++
 2 files changed, 10 insertions(+), 14 deletions(-)

diff --git a/hw/i2c/pm_smbus.c b/hw/i2c/pm_smbus.c
index 4e1b8a5182..78e7c229a8 100644
--- a/hw/i2c/pm_smbus.c
+++ b/hw/i2c/pm_smbus.c
@@ -23,6 +23,7 @@
 #include "hw/i2c/pm_smbus.h"
 #include "hw/i2c/smbus_master.h"
 #include "migration/vmstate.h"
+#include "trace.h"
 
 #define SMBHSTSTS       0x00
 #define SMBHSTCNT       0x02
@@ -64,15 +65,6 @@
 #define AUX_BLK       (1 << 1)
 #define AUX_MASK      0x3
 
-/*#define DEBUG*/
-
-#ifdef DEBUG
-# define SMBUS_DPRINTF(format, ...)     printf(format, ## __VA_ARGS__)
-#else
-# define SMBUS_DPRINTF(format, ...)     do { } while (0)
-#endif
-
-
 static void smb_transaction(PMSMBus *s)
 {
     uint8_t prot = (s->smb_ctl >> 2) & 0x07;
@@ -82,7 +74,7 @@ static void smb_transaction(PMSMBus *s)
     I2CBus *bus = s->smbus;
     int ret;
 
-    SMBUS_DPRINTF("SMBus trans addr=0x%02x prot=0x%02x\n", addr, prot);
+    trace_smbus_transaction(addr, prot);
     /* Transaction isn't exec if STS_DEV_ERR bit set */
     if ((s->smb_stat & STS_DEV_ERR) != 0)  {
         goto error;
@@ -258,8 +250,7 @@ static void smb_ioport_writeb(void *opaque, hwaddr addr, uint64_t val,
     PMSMBus *s = opaque;
     uint8_t clear_byte_done;
 
-    SMBUS_DPRINTF("SMB writeb port=0x%04" HWADDR_PRIx
-                  " val=0x%02" PRIx64 "\n", addr, val);
+    trace_smbus_ioport_writeb(addr, val);
     switch(addr) {
     case SMBHSTSTS:
         clear_byte_done = s->smb_stat & val & STS_BYTE_DONE;
@@ -429,8 +420,7 @@ static uint64_t smb_ioport_readb(void *opaque, hwaddr addr, unsigned width)
         val = 0;
         break;
     }
-    SMBUS_DPRINTF("SMB readb port=0x%04" HWADDR_PRIx " val=0x%02x\n",
-                  addr, val);
+    trace_smbus_ioport_readb(addr, val);
 
     if (s->set_irq) {
         s->set_irq(s, smb_irq_value(s));
diff --git a/hw/i2c/trace-events b/hw/i2c/trace-events
index d7b1e25858..6900e06eda 100644
--- a/hw/i2c/trace-events
+++ b/hw/i2c/trace-events
@@ -15,6 +15,12 @@ i2c_send_async(uint8_t address, uint8_t data) "send_async(addr:0x%02x) data:0x%0
 i2c_recv(uint8_t address, uint8_t data) "recv(addr:0x%02x) data:0x%02x"
 i2c_ack(void) ""
 
+# pm_smbus.c
+
+smbus_ioport_readb(uint16_t addr, uint8_t data) "[0x%04" PRIx16 "] -> val=0x%02x"
+smbus_ioport_writeb(uint16_t addr, uint8_t data) "[0x%04" PRIx16 "] <- val=0x%02x"
+smbus_transaction(uint8_t addr, uint8_t prot) "addr=0x%02x prot=0x%02x"
+
 # allwinner_i2c.c
 
 allwinner_i2c_read(const char* reg_name, uint64_t offset, uint64_t value) "read %s [0x%" PRIx64 "]: -> 0x%" PRIx64
-- 
2.42.0

Re: [PATCH 5/6] hw/i2c/pm_smbus: Convert DPRINTF to trace events

[Philippe Mathieu-Daudé]

On 28/10/23 14:24, Bernhard Beschow wrote:
> Let the trace messages slightly deviate from the function names
> ("smb" -> "smbus") being traced in order to avoid conflights with the SMB
> protocol.
> 
> Signed-off-by: Bernhard Beschow <shentey@gmail.com>
> ---
>   hw/i2c/pm_smbus.c   | 18 ++++--------------
>   hw/i2c/trace-events |  6 ++++++
>   2 files changed, 10 insertions(+), 14 deletions(-)

Reviewed-by: Philippe Mathieu-Daudé <philmd@linaro.org>

Re: [PATCH 5/6] hw/i2c/pm_smbus: Convert DPRINTF to trace events

[Corey Minyard]

On Sat, Oct 28, 2023 at 02:24:14PM +0200, Bernhard Beschow wrote:
> Let the trace messages slightly deviate from the function names
> ("smb" -> "smbus") being traced in order to avoid conflights with the SMB
> protocol.
> 
> Signed-off-by: Bernhard Beschow <shentey@gmail.com>

Looks good to me.

Acked-by: Corey Minyard <cminyard@mvista.com>

> ---
>  hw/i2c/pm_smbus.c   | 18 ++++--------------
>  hw/i2c/trace-events |  6 ++++++
>  2 files changed, 10 insertions(+), 14 deletions(-)
> 
> diff --git a/hw/i2c/pm_smbus.c b/hw/i2c/pm_smbus.c
> index 4e1b8a5182..78e7c229a8 100644
> --- a/hw/i2c/pm_smbus.c
> +++ b/hw/i2c/pm_smbus.c
> @@ -23,6 +23,7 @@
>  #include "hw/i2c/pm_smbus.h"
>  #include "hw/i2c/smbus_master.h"
>  #include "migration/vmstate.h"
> +#include "trace.h"
>  
>  #define SMBHSTSTS       0x00
>  #define SMBHSTCNT       0x02
> @@ -64,15 +65,6 @@
>  #define AUX_BLK       (1 << 1)
>  #define AUX_MASK      0x3
>  
> -/*#define DEBUG*/
> -
> -#ifdef DEBUG
> -# define SMBUS_DPRINTF(format, ...)     printf(format, ## __VA_ARGS__)
> -#else
> -# define SMBUS_DPRINTF(format, ...)     do { } while (0)
> -#endif
> -
> -
>  static void smb_transaction(PMSMBus *s)
>  {
>      uint8_t prot = (s->smb_ctl >> 2) & 0x07;
> @@ -82,7 +74,7 @@ static void smb_transaction(PMSMBus *s)
>      I2CBus *bus = s->smbus;
>      int ret;
>  
> -    SMBUS_DPRINTF("SMBus trans addr=0x%02x prot=0x%02x\n", addr, prot);
> +    trace_smbus_transaction(addr, prot);
>      /* Transaction isn't exec if STS_DEV_ERR bit set */
>      if ((s->smb_stat & STS_DEV_ERR) != 0)  {
>          goto error;
> @@ -258,8 +250,7 @@ static void smb_ioport_writeb(void *opaque, hwaddr addr, uint64_t val,
>      PMSMBus *s = opaque;
>      uint8_t clear_byte_done;
>  
> -    SMBUS_DPRINTF("SMB writeb port=0x%04" HWADDR_PRIx
> -                  " val=0x%02" PRIx64 "\n", addr, val);
> +    trace_smbus_ioport_writeb(addr, val);
>      switch(addr) {
>      case SMBHSTSTS:
>          clear_byte_done = s->smb_stat & val & STS_BYTE_DONE;
> @@ -429,8 +420,7 @@ static uint64_t smb_ioport_readb(void *opaque, hwaddr addr, unsigned width)
>          val = 0;
>          break;
>      }
> -    SMBUS_DPRINTF("SMB readb port=0x%04" HWADDR_PRIx " val=0x%02x\n",
> -                  addr, val);
> +    trace_smbus_ioport_readb(addr, val);
>  
>      if (s->set_irq) {
>          s->set_irq(s, smb_irq_value(s));
> diff --git a/hw/i2c/trace-events b/hw/i2c/trace-events
> index d7b1e25858..6900e06eda 100644
> --- a/hw/i2c/trace-events
> +++ b/hw/i2c/trace-events
> @@ -15,6 +15,12 @@ i2c_send_async(uint8_t address, uint8_t data) "send_async(addr:0x%02x) data:0x%0
>  i2c_recv(uint8_t address, uint8_t data) "recv(addr:0x%02x) data:0x%02x"
>  i2c_ack(void) ""
>  
> +# pm_smbus.c
> +
> +smbus_ioport_readb(uint16_t addr, uint8_t data) "[0x%04" PRIx16 "] -> val=0x%02x"
> +smbus_ioport_writeb(uint16_t addr, uint8_t data) "[0x%04" PRIx16 "] <- val=0x%02x"
> +smbus_transaction(uint8_t addr, uint8_t prot) "addr=0x%02x prot=0x%02x"
> +
>  # allwinner_i2c.c
>  
>  allwinner_i2c_read(const char* reg_name, uint64_t offset, uint64_t value) "read %s [0x%" PRIx64 "]: -> 0x%" PRIx64
> -- 
> 2.42.0
> 
> 

[PATCH 6/6] system/memory: Trace names of MemoryRegions rather than host pointers

[Bernhard Beschow]

Tracing the host pointer of the accessed MemoryRegion seems to be a debug
feature for developing QEMU itself. When analyzing guest behavior by comparing
traces, these pointers generate a lot of noise since the pointers differ between
QEMU invocations, making this task harder than it needs to be. Moreover, the
pointers seem to be redundant to the names already assigned to MemoryRegions.

Remove the pointers from the traces and trace the names where missing. When
developing QEMU, developers could just add the host pointer tracing for
themselves.

Signed-off-by: Bernhard Beschow <shentey@gmail.com>
---
 docs/devel/tracing.rst |  4 ++--
 system/memory.c        | 26 ++++++++++++++++----------
 system/trace-events    | 12 ++++++------
 3 files changed, 24 insertions(+), 18 deletions(-)

diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
index d288480db1..8c31d5f76e 100644
--- a/docs/devel/tracing.rst
+++ b/docs/devel/tracing.rst
@@ -18,8 +18,8 @@ events::
 
     $ qemu --trace "memory_region_ops_*" ...
     ...
-    719585@1608130130.441188:memory_region_ops_read cpu 0 mr 0x562fdfbb3820 addr 0x3cc value 0x67 size 1
-    719585@1608130130.441190:memory_region_ops_write cpu 0 mr 0x562fdfbd2f00 addr 0x3d4 value 0x70e size 2
+    719585@1608130130.441188:memory_region_ops_read cpu 0 addr 0x3cc value 0x67 size 1
+    719585@1608130130.441190:memory_region_ops_write cpu 0 addr 0x3d4 value 0x70e size 2
 
 This output comes from the "log" trace backend that is enabled by default when
 ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
diff --git a/system/memory.c b/system/memory.c
index 4928f2525d..076a992b74 100644
--- a/system/memory.c
+++ b/system/memory.c
@@ -444,10 +444,11 @@ static MemTxResult  memory_region_read_accessor(MemoryRegion *mr,
 
     tmp = mr->ops->read(mr->opaque, addr, size);
     if (mr->subpage) {
-        trace_memory_region_subpage_read(get_cpu_index(), mr, addr, tmp, size);
+        trace_memory_region_subpage_read(get_cpu_index(), addr, tmp, size,
+                                         memory_region_name(mr));
     } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_READ)) {
         hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
-        trace_memory_region_ops_read(get_cpu_index(), mr, abs_addr, tmp, size,
+        trace_memory_region_ops_read(get_cpu_index(), abs_addr, tmp, size,
                                      memory_region_name(mr));
     }
     memory_region_shift_read_access(value, shift, mask, tmp);
@@ -467,10 +468,11 @@ static MemTxResult memory_region_read_with_attrs_accessor(MemoryRegion *mr,
 
     r = mr->ops->read_with_attrs(mr->opaque, addr, &tmp, size, attrs);
     if (mr->subpage) {
-        trace_memory_region_subpage_read(get_cpu_index(), mr, addr, tmp, size);
+        trace_memory_region_subpage_read(get_cpu_index(), addr, tmp, size,
+                                         memory_region_name(mr));
     } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_READ)) {
         hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
-        trace_memory_region_ops_read(get_cpu_index(), mr, abs_addr, tmp, size,
+        trace_memory_region_ops_read(get_cpu_index(), abs_addr, tmp, size,
                                      memory_region_name(mr));
     }
     memory_region_shift_read_access(value, shift, mask, tmp);
@@ -488,10 +490,11 @@ static MemTxResult memory_region_write_accessor(MemoryRegion *mr,
     uint64_t tmp = memory_region_shift_write_access(value, shift, mask);
 
     if (mr->subpage) {
-        trace_memory_region_subpage_write(get_cpu_index(), mr, addr, tmp, size);
+        trace_memory_region_subpage_write(get_cpu_index(), addr, tmp, size,
+                                          memory_region_name(mr));
     } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_WRITE)) {
         hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
-        trace_memory_region_ops_write(get_cpu_index(), mr, abs_addr, tmp, size,
+        trace_memory_region_ops_write(get_cpu_index(), abs_addr, tmp, size,
                                       memory_region_name(mr));
     }
     mr->ops->write(mr->opaque, addr, tmp, size);
@@ -509,10 +512,11 @@ static MemTxResult memory_region_write_with_attrs_accessor(MemoryRegion *mr,
     uint64_t tmp = memory_region_shift_write_access(value, shift, mask);
 
     if (mr->subpage) {
-        trace_memory_region_subpage_write(get_cpu_index(), mr, addr, tmp, size);
+        trace_memory_region_subpage_write(get_cpu_index(), addr, tmp, size,
+                                          memory_region_name(mr));
     } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_WRITE)) {
         hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
-        trace_memory_region_ops_write(get_cpu_index(), mr, abs_addr, tmp, size,
+        trace_memory_region_ops_write(get_cpu_index(), abs_addr, tmp, size,
                                       memory_region_name(mr));
     }
     return mr->ops->write_with_attrs(mr->opaque, addr, tmp, size, attrs);
@@ -1356,7 +1360,8 @@ static uint64_t memory_region_ram_device_read(void *opaque,
         break;
     }
 
-    trace_memory_region_ram_device_read(get_cpu_index(), mr, addr, data, size);
+    trace_memory_region_ram_device_read(get_cpu_index(), addr, data, size,
+                                        memory_region_name(mr));
 
     return data;
 }
@@ -1366,7 +1371,8 @@ static void memory_region_ram_device_write(void *opaque, hwaddr addr,
 {
     MemoryRegion *mr = opaque;
 
-    trace_memory_region_ram_device_write(get_cpu_index(), mr, addr, data, size);
+    trace_memory_region_ram_device_write(get_cpu_index(), addr, data, size,
+                                         memory_region_name(mr));
 
     switch (size) {
     case 1:
diff --git a/system/trace-events b/system/trace-events
index 69c9044151..21f1c005e0 100644
--- a/system/trace-events
+++ b/system/trace-events
@@ -9,12 +9,12 @@ cpu_in(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
 cpu_out(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
 
 # memory.c
-memory_region_ops_read(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
-memory_region_ops_write(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
-memory_region_subpage_read(int cpu_index, void *mr, uint64_t offset, uint64_t value, unsigned size) "cpu %d mr %p offset 0x%"PRIx64" value 0x%"PRIx64" size %u"
-memory_region_subpage_write(int cpu_index, void *mr, uint64_t offset, uint64_t value, unsigned size) "cpu %d mr %p offset 0x%"PRIx64" value 0x%"PRIx64" size %u"
-memory_region_ram_device_read(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u"
-memory_region_ram_device_write(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u"
+memory_region_ops_read(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
+memory_region_ops_write(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
+memory_region_subpage_read(int cpu_index, uint64_t offset, uint64_t value, unsigned size, const char *name) "cpu %d offset 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
+memory_region_subpage_write(int cpu_index, uint64_t offset, uint64_t value, unsigned size, const char *name) "cpu %d offset 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
+memory_region_ram_device_read(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
+memory_region_ram_device_write(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
 memory_region_sync_dirty(const char *mr, const char *listener, int global) "mr '%s' listener '%s' synced (global=%d)"
 flatview_new(void *view, void *root) "%p (root %p)"
 flatview_destroy(void *view, void *root) "%p (root %p)"
-- 
2.42.0

Re: [PATCH 6/6] system/memory: Trace names of MemoryRegions rather than host pointers

[Philippe Mathieu-Daudé]

Hi Bernhard,

On 28/10/23 14:24, Bernhard Beschow wrote:
> Tracing the host pointer of the accessed MemoryRegion seems to be a debug
> feature for developing QEMU itself. When analyzing guest behavior by comparing
> traces, these pointers generate a lot of noise since the pointers differ between
> QEMU invocations, making this task harder than it needs to be. Moreover, the
> pointers seem to be redundant to the names already assigned to MemoryRegions.

I tried that few years ago but this got lost:
https://lore.kernel.org/qemu-devel/20210307074833.143106-1-f4bug@amsat.org/

> Remove the pointers from the traces and trace the names where missing. When
> developing QEMU, developers could just add the host pointer tracing for
> themselves.

But sometimes an object exposing a MR is instantiated multiple times,
each time, and now you can not distinct which object is accessed.

IIRC a suggestion was to cache the QOM parent path and display that,
which should be constant to diff tracing logs. But then IIRC again the
issue was the QOM path is resolved once the object is realized, which
happens *after* we initialize the MR within the object. Maybe the
solution is to add a memory_region_qom_pathname() getter and do lazy
initialization?

> Signed-off-by: Bernhard Beschow <shentey@gmail.com>
> ---
>   docs/devel/tracing.rst |  4 ++--
>   system/memory.c        | 26 ++++++++++++++++----------
>   system/trace-events    | 12 ++++++------
>   3 files changed, 24 insertions(+), 18 deletions(-)
> 
> diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
> index d288480db1..8c31d5f76e 100644
> --- a/docs/devel/tracing.rst
> +++ b/docs/devel/tracing.rst
> @@ -18,8 +18,8 @@ events::
>   
>       $ qemu --trace "memory_region_ops_*" ...
>       ...
> -    719585@1608130130.441188:memory_region_ops_read cpu 0 mr 0x562fdfbb3820 addr 0x3cc value 0x67 size 1
> -    719585@1608130130.441190:memory_region_ops_write cpu 0 mr 0x562fdfbd2f00 addr 0x3d4 value 0x70e size 2
> +    719585@1608130130.441188:memory_region_ops_read cpu 0 addr 0x3cc value 0x67 size 1
> +    719585@1608130130.441190:memory_region_ops_write cpu 0 addr 0x3d4 value 0x70e size 2

Is this example missing the MR name?

>   
>   This output comes from the "log" trace backend that is enabled by default when
>   ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
> diff --git a/system/memory.c b/system/memory.c
> index 4928f2525d..076a992b74 100644
> --- a/system/memory.c
> +++ b/system/memory.c
> @@ -444,10 +444,11 @@ static MemTxResult  memory_region_read_accessor(MemoryRegion *mr,
>   
>       tmp = mr->ops->read(mr->opaque, addr, size);
>       if (mr->subpage) {
> -        trace_memory_region_subpage_read(get_cpu_index(), mr, addr, tmp, size);
> +        trace_memory_region_subpage_read(get_cpu_index(), addr, tmp, size,
> +                                         memory_region_name(mr));
>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_READ)) {
>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
> -        trace_memory_region_ops_read(get_cpu_index(), mr, abs_addr, tmp, size,
> +        trace_memory_region_ops_read(get_cpu_index(), abs_addr, tmp, size,
>                                        memory_region_name(mr));
>       }
>       memory_region_shift_read_access(value, shift, mask, tmp);
> @@ -467,10 +468,11 @@ static MemTxResult memory_region_read_with_attrs_accessor(MemoryRegion *mr,
>   
>       r = mr->ops->read_with_attrs(mr->opaque, addr, &tmp, size, attrs);
>       if (mr->subpage) {
> -        trace_memory_region_subpage_read(get_cpu_index(), mr, addr, tmp, size);
> +        trace_memory_region_subpage_read(get_cpu_index(), addr, tmp, size,
> +                                         memory_region_name(mr));
>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_READ)) {
>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
> -        trace_memory_region_ops_read(get_cpu_index(), mr, abs_addr, tmp, size,
> +        trace_memory_region_ops_read(get_cpu_index(), abs_addr, tmp, size,
>                                        memory_region_name(mr));
>       }
>       memory_region_shift_read_access(value, shift, mask, tmp);
> @@ -488,10 +490,11 @@ static MemTxResult memory_region_write_accessor(MemoryRegion *mr,
>       uint64_t tmp = memory_region_shift_write_access(value, shift, mask);
>   
>       if (mr->subpage) {
> -        trace_memory_region_subpage_write(get_cpu_index(), mr, addr, tmp, size);
> +        trace_memory_region_subpage_write(get_cpu_index(), addr, tmp, size,
> +                                          memory_region_name(mr));
>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_WRITE)) {
>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
> -        trace_memory_region_ops_write(get_cpu_index(), mr, abs_addr, tmp, size,
> +        trace_memory_region_ops_write(get_cpu_index(), abs_addr, tmp, size,
>                                         memory_region_name(mr));
>       }
>       mr->ops->write(mr->opaque, addr, tmp, size);
> @@ -509,10 +512,11 @@ static MemTxResult memory_region_write_with_attrs_accessor(MemoryRegion *mr,
>       uint64_t tmp = memory_region_shift_write_access(value, shift, mask);
>   
>       if (mr->subpage) {
> -        trace_memory_region_subpage_write(get_cpu_index(), mr, addr, tmp, size);
> +        trace_memory_region_subpage_write(get_cpu_index(), addr, tmp, size,
> +                                          memory_region_name(mr));
>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_WRITE)) {
>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
> -        trace_memory_region_ops_write(get_cpu_index(), mr, abs_addr, tmp, size,
> +        trace_memory_region_ops_write(get_cpu_index(), abs_addr, tmp, size,
>                                         memory_region_name(mr));
>       }
>       return mr->ops->write_with_attrs(mr->opaque, addr, tmp, size, attrs);
> @@ -1356,7 +1360,8 @@ static uint64_t memory_region_ram_device_read(void *opaque,
>           break;
>       }
>   
> -    trace_memory_region_ram_device_read(get_cpu_index(), mr, addr, data, size);
> +    trace_memory_region_ram_device_read(get_cpu_index(), addr, data, size,
> +                                        memory_region_name(mr));
>   
>       return data;
>   }
> @@ -1366,7 +1371,8 @@ static void memory_region_ram_device_write(void *opaque, hwaddr addr,
>   {
>       MemoryRegion *mr = opaque;
>   
> -    trace_memory_region_ram_device_write(get_cpu_index(), mr, addr, data, size);
> +    trace_memory_region_ram_device_write(get_cpu_index(), addr, data, size,
> +                                         memory_region_name(mr));
>   
>       switch (size) {
>       case 1:
> diff --git a/system/trace-events b/system/trace-events
> index 69c9044151..21f1c005e0 100644
> --- a/system/trace-events
> +++ b/system/trace-events
> @@ -9,12 +9,12 @@ cpu_in(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>   cpu_out(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>   
>   # memory.c
> -memory_region_ops_read(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> -memory_region_ops_write(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> -memory_region_subpage_read(int cpu_index, void *mr, uint64_t offset, uint64_t value, unsigned size) "cpu %d mr %p offset 0x%"PRIx64" value 0x%"PRIx64" size %u"
> -memory_region_subpage_write(int cpu_index, void *mr, uint64_t offset, uint64_t value, unsigned size) "cpu %d mr %p offset 0x%"PRIx64" value 0x%"PRIx64" size %u"
> -memory_region_ram_device_read(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u"
> -memory_region_ram_device_write(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u"
> +memory_region_ops_read(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> +memory_region_ops_write(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> +memory_region_subpage_read(int cpu_index, uint64_t offset, uint64_t value, unsigned size, const char *name) "cpu %d offset 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> +memory_region_subpage_write(int cpu_index, uint64_t offset, uint64_t value, unsigned size, const char *name) "cpu %d offset 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> +memory_region_ram_device_read(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
> +memory_region_ram_device_write(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>   memory_region_sync_dirty(const char *mr, const char *listener, int global) "mr '%s' listener '%s' synced (global=%d)"
>   flatview_new(void *view, void *root) "%p (root %p)"
>   flatview_destroy(void *view, void *root) "%p (root %p)"

Re: [PATCH 6/6] system/memory: Trace names of MemoryRegions rather than host pointers

[Bernhard Beschow]

Am 30. Oktober 2023 03:36:44 UTC schrieb "Philippe Mathieu-Daudé" <philmd@linaro.org>:
>Hi Bernhard,
>
>On 28/10/23 14:24, Bernhard Beschow wrote:
>> Tracing the host pointer of the accessed MemoryRegion seems to be a debug
>> feature for developing QEMU itself. When analyzing guest behavior by comparing
>> traces, these pointers generate a lot of noise since the pointers differ between
>> QEMU invocations, making this task harder than it needs to be. Moreover, the
>> pointers seem to be redundant to the names already assigned to MemoryRegions.
>
>I tried that few years ago but this got lost:
>https://lore.kernel.org/qemu-devel/20210307074833.143106-1-f4bug@amsat.org/
>
>> Remove the pointers from the traces and trace the names where missing. When
>> developing QEMU, developers could just add the host pointer tracing for
>> themselves.
>
>But sometimes an object exposing a MR is instantiated multiple times,
>each time, and now you can not distinct which object is accessed.
>
>IIRC a suggestion was to cache the QOM parent path and display that,
>which should be constant to diff tracing logs. But then IIRC again the
>issue was the QOM path is resolved once the object is realized, which
>happens *after* we initialize the MR within the object. Maybe the
>solution is to add a memory_region_qom_pathname() getter and do lazy
>initialization?

Would logging the guest rather than the host address (in addition to the MR name) work?

Best regards,
Bernhard

>
>> Signed-off-by: Bernhard Beschow <shentey@gmail.com>
>> ---
>>   docs/devel/tracing.rst |  4 ++--
>>   system/memory.c        | 26 ++++++++++++++++----------
>>   system/trace-events    | 12 ++++++------
>>   3 files changed, 24 insertions(+), 18 deletions(-)
>> 
>> diff --git a/docs/devel/tracing.rst b/docs/devel/tracing.rst
>> index d288480db1..8c31d5f76e 100644
>> --- a/docs/devel/tracing.rst
>> +++ b/docs/devel/tracing.rst
>> @@ -18,8 +18,8 @@ events::
>>         $ qemu --trace "memory_region_ops_*" ...
>>       ...
>> -    719585@1608130130.441188:memory_region_ops_read cpu 0 mr 0x562fdfbb3820 addr 0x3cc value 0x67 size 1
>> -    719585@1608130130.441190:memory_region_ops_write cpu 0 mr 0x562fdfbd2f00 addr 0x3d4 value 0x70e size 2
>> +    719585@1608130130.441188:memory_region_ops_read cpu 0 addr 0x3cc value 0x67 size 1
>> +    719585@1608130130.441190:memory_region_ops_write cpu 0 addr 0x3d4 value 0x70e size 2
>
>Is this example missing the MR name?
>
>>     This output comes from the "log" trace backend that is enabled by default when
>>   ``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified.
>> diff --git a/system/memory.c b/system/memory.c
>> index 4928f2525d..076a992b74 100644
>> --- a/system/memory.c
>> +++ b/system/memory.c
>> @@ -444,10 +444,11 @@ static MemTxResult  memory_region_read_accessor(MemoryRegion *mr,
>>         tmp = mr->ops->read(mr->opaque, addr, size);
>>       if (mr->subpage) {
>> -        trace_memory_region_subpage_read(get_cpu_index(), mr, addr, tmp, size);
>> +        trace_memory_region_subpage_read(get_cpu_index(), addr, tmp, size,
>> +                                         memory_region_name(mr));
>>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_READ)) {
>>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
>> -        trace_memory_region_ops_read(get_cpu_index(), mr, abs_addr, tmp, size,
>> +        trace_memory_region_ops_read(get_cpu_index(), abs_addr, tmp, size,
>>                                        memory_region_name(mr));
>>       }
>>       memory_region_shift_read_access(value, shift, mask, tmp);
>> @@ -467,10 +468,11 @@ static MemTxResult memory_region_read_with_attrs_accessor(MemoryRegion *mr,
>>         r = mr->ops->read_with_attrs(mr->opaque, addr, &tmp, size, attrs);
>>       if (mr->subpage) {
>> -        trace_memory_region_subpage_read(get_cpu_index(), mr, addr, tmp, size);
>> +        trace_memory_region_subpage_read(get_cpu_index(), addr, tmp, size,
>> +                                         memory_region_name(mr));
>>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_READ)) {
>>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
>> -        trace_memory_region_ops_read(get_cpu_index(), mr, abs_addr, tmp, size,
>> +        trace_memory_region_ops_read(get_cpu_index(), abs_addr, tmp, size,
>>                                        memory_region_name(mr));
>>       }
>>       memory_region_shift_read_access(value, shift, mask, tmp);
>> @@ -488,10 +490,11 @@ static MemTxResult memory_region_write_accessor(MemoryRegion *mr,
>>       uint64_t tmp = memory_region_shift_write_access(value, shift, mask);
>>         if (mr->subpage) {
>> -        trace_memory_region_subpage_write(get_cpu_index(), mr, addr, tmp, size);
>> +        trace_memory_region_subpage_write(get_cpu_index(), addr, tmp, size,
>> +                                          memory_region_name(mr));
>>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_WRITE)) {
>>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
>> -        trace_memory_region_ops_write(get_cpu_index(), mr, abs_addr, tmp, size,
>> +        trace_memory_region_ops_write(get_cpu_index(), abs_addr, tmp, size,
>>                                         memory_region_name(mr));
>>       }
>>       mr->ops->write(mr->opaque, addr, tmp, size);
>> @@ -509,10 +512,11 @@ static MemTxResult memory_region_write_with_attrs_accessor(MemoryRegion *mr,
>>       uint64_t tmp = memory_region_shift_write_access(value, shift, mask);
>>         if (mr->subpage) {
>> -        trace_memory_region_subpage_write(get_cpu_index(), mr, addr, tmp, size);
>> +        trace_memory_region_subpage_write(get_cpu_index(), addr, tmp, size,
>> +                                          memory_region_name(mr));
>>       } else if (trace_event_get_state_backends(TRACE_MEMORY_REGION_OPS_WRITE)) {
>>           hwaddr abs_addr = memory_region_to_absolute_addr(mr, addr);
>> -        trace_memory_region_ops_write(get_cpu_index(), mr, abs_addr, tmp, size,
>> +        trace_memory_region_ops_write(get_cpu_index(), abs_addr, tmp, size,
>>                                         memory_region_name(mr));
>>       }
>>       return mr->ops->write_with_attrs(mr->opaque, addr, tmp, size, attrs);
>> @@ -1356,7 +1360,8 @@ static uint64_t memory_region_ram_device_read(void *opaque,
>>           break;
>>       }
>>   -    trace_memory_region_ram_device_read(get_cpu_index(), mr, addr, data, size);
>> +    trace_memory_region_ram_device_read(get_cpu_index(), addr, data, size,
>> +                                        memory_region_name(mr));
>>         return data;
>>   }
>> @@ -1366,7 +1371,8 @@ static void memory_region_ram_device_write(void *opaque, hwaddr addr,
>>   {
>>       MemoryRegion *mr = opaque;
>>   -    trace_memory_region_ram_device_write(get_cpu_index(), mr, addr, data, size);
>> +    trace_memory_region_ram_device_write(get_cpu_index(), addr, data, size,
>> +                                         memory_region_name(mr));
>>         switch (size) {
>>       case 1:
>> diff --git a/system/trace-events b/system/trace-events
>> index 69c9044151..21f1c005e0 100644
>> --- a/system/trace-events
>> +++ b/system/trace-events
>> @@ -9,12 +9,12 @@ cpu_in(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>>   cpu_out(unsigned int addr, char size, unsigned int val) "addr 0x%x(%c) value %u"
>>     # memory.c
>> -memory_region_ops_read(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> -memory_region_ops_write(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> -memory_region_subpage_read(int cpu_index, void *mr, uint64_t offset, uint64_t value, unsigned size) "cpu %d mr %p offset 0x%"PRIx64" value 0x%"PRIx64" size %u"
>> -memory_region_subpage_write(int cpu_index, void *mr, uint64_t offset, uint64_t value, unsigned size) "cpu %d mr %p offset 0x%"PRIx64" value 0x%"PRIx64" size %u"
>> -memory_region_ram_device_read(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u"
>> -memory_region_ram_device_write(int cpu_index, void *mr, uint64_t addr, uint64_t value, unsigned size) "cpu %d mr %p addr 0x%"PRIx64" value 0x%"PRIx64" size %u"
>> +memory_region_ops_read(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> +memory_region_ops_write(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> +memory_region_subpage_read(int cpu_index, uint64_t offset, uint64_t value, unsigned size, const char *name) "cpu %d offset 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> +memory_region_subpage_write(int cpu_index, uint64_t offset, uint64_t value, unsigned size, const char *name) "cpu %d offset 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> +memory_region_ram_device_read(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>> +memory_region_ram_device_write(int cpu_index, uint64_t addr, uint64_t value, unsigned size, const char *name) "cpu %d addr 0x%"PRIx64" value 0x%"PRIx64" size %u name '%s'"
>>   memory_region_sync_dirty(const char *mr, const char *listener, int global) "mr '%s' listener '%s' synced (global=%d)"
>>   flatview_new(void *view, void *root) "%p (root %p)"
>>   flatview_destroy(void *view, void *root) "%p (root %p)"
>

Re: [PATCH 0/6] Various tracing patches

[Peter Maydell]

On Sat, 28 Oct 2023 at 13:24, Bernhard Beschow <shentey@gmail.com> wrote:
>
> This series enhances the tracing experience of some i.MX devices by adding new
> trace events and by converting from DPRINTF. SMBus gets also converted from
> DPRINTF to trace events. Finally, when tracing memory region operations, host
> pointers aren't traced any longer and are substituted by their memory region
> names.
>
> Bernhard Beschow (6):
>   hw/watchdog/wdt_imx2: Trace MMIO access
>   hw/watchdog/wdt_imx2: Trace timer activity
>   hw/misc/imx7_snvs: Trace MMIO access
>   hw/misc/imx6_ccm: Convert DPRINTF to trace events
>   hw/i2c/pm_smbus: Convert DPRINTF to trace events
>   system/memory: Trace names of MemoryRegions rather than host pointers

Since these are mostly arm devices I've taken patches 1-5
into target-arm.next (with the addition of "Hz" to the
frequency traces in patch 4). Patch 6 looks like it needs
further discussion.

thanks
-- PMM

Re: [PATCH 0/6] Various tracing patches

[Bernhard Beschow]

Am 31. Oktober 2023 16:17:32 UTC schrieb Peter Maydell <peter.maydell@linaro.org>:
>On Sat, 28 Oct 2023 at 13:24, Bernhard Beschow <shentey@gmail.com> wrote:
>>
>> This series enhances the tracing experience of some i.MX devices by adding new
>> trace events and by converting from DPRINTF. SMBus gets also converted from
>> DPRINTF to trace events. Finally, when tracing memory region operations, host
>> pointers aren't traced any longer and are substituted by their memory region
>> names.
>>
>> Bernhard Beschow (6):
>>   hw/watchdog/wdt_imx2: Trace MMIO access
>>   hw/watchdog/wdt_imx2: Trace timer activity
>>   hw/misc/imx7_snvs: Trace MMIO access
>>   hw/misc/imx6_ccm: Convert DPRINTF to trace events
>>   hw/i2c/pm_smbus: Convert DPRINTF to trace events
>>   system/memory: Trace names of MemoryRegions rather than host pointers
>
>Since these are mostly arm devices I've taken patches 1-5
>into target-arm.next (with the addition of "Hz" to the
>frequency traces in patch 4).

Excellent. Thanks!

Best regards,
Bernhard

> Patch 6 looks like it needs
>further discussion.
>
>thanks
>-- PMM