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