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)"