[PATCH v2 0/3] hw: Remove dynamic field width from trace events

[PATCH v2 0/3] hw: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

Eric noted in [1] the dtrace via stap backend can not support
the dynamic '*' width format.
I'd really like to use dynamic width in trace event because the
read/write accesses are easier to read but it is not a priority.
Since next release is close, time to fix LP#1844817 [2].

Since v1:
- Do not update the qemu_log_mask() calls in hw/mips/gt64xxx_pci.c

[1] https://lists.gnu.org/archive/html/qemu-devel/2019-09/msg04720.html
[2] https://bugs.launchpad.net/qemu/+bug/1844817

Philippe Mathieu-Daudé (3):
  hw/block/pflash: Remove dynamic field width from trace events
  hw/mips/gt64xxx: Remove dynamic field width from trace events
  trace: Forbid dynamic field width in event format

 hw/block/pflash_cfi01.c       |  8 ++++----
 hw/block/pflash_cfi02.c       |  8 ++++----
 hw/mips/gt64xxx_pci.c         | 16 ++++++++--------
 hw/block/trace-events         |  8 ++++----
 hw/mips/trace-events          |  4 ++--
 scripts/tracetool/__init__.py |  3 +++
 6 files changed, 25 insertions(+), 22 deletions(-)

-- 
2.21.0

[PATCH v2 1/3] hw/block/pflash: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

Since not all trace backends support dynamic field width in
format (dtrace via stap does not), replace by a static field
width instead.

Reported-by: Eric Blake <eblake@redhat.com>
Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---
 hw/block/pflash_cfi01.c | 8 ++++----
 hw/block/pflash_cfi02.c | 8 ++++----
 hw/block/trace-events   | 8 ++++----
 3 files changed, 12 insertions(+), 12 deletions(-)

diff --git a/hw/block/pflash_cfi01.c b/hw/block/pflash_cfi01.c
index 566c0acb77..787d1196f2 100644
--- a/hw/block/pflash_cfi01.c
+++ b/hw/block/pflash_cfi01.c
@@ -276,7 +276,7 @@ static uint32_t pflash_data_read(PFlashCFI01 *pfl, hwaddr offset,
         DPRINTF("BUG in %s\n", __func__);
         abort();
     }
-    trace_pflash_data_read(offset, width << 1, ret);
+    trace_pflash_data_read(offset, width << 3, ret);
     return ret;
 }
 
@@ -389,7 +389,7 @@ static uint32_t pflash_read(PFlashCFI01 *pfl, hwaddr offset,
 
         break;
     }
-    trace_pflash_io_read(offset, width, width << 1, ret, pfl->cmd, pfl->wcycle);
+    trace_pflash_io_read(offset, width << 3, ret, pfl->cmd, pfl->wcycle);
 
     return ret;
 }
@@ -414,7 +414,7 @@ static inline void pflash_data_write(PFlashCFI01 *pfl, hwaddr offset,
 {
     uint8_t *p = pfl->storage;
 
-    trace_pflash_data_write(offset, width << 1, value, pfl->counter);
+    trace_pflash_data_write(offset, width << 3, value, pfl->counter);
     switch (width) {
     case 1:
         p[offset] = value;
@@ -453,7 +453,7 @@ static void pflash_write(PFlashCFI01 *pfl, hwaddr offset,
 
     cmd = value;
 
-    trace_pflash_io_write(offset, width, width << 1, value, pfl->wcycle);
+    trace_pflash_io_write(offset, width << 3, value, pfl->wcycle);
     if (!pfl->wcycle) {
         /* Set the device in I/O access mode */
         memory_region_rom_device_set_romd(&pfl->mem, false);
diff --git a/hw/block/pflash_cfi02.c b/hw/block/pflash_cfi02.c
index 4baca701b7..f2993cdfaa 100644
--- a/hw/block/pflash_cfi02.c
+++ b/hw/block/pflash_cfi02.c
@@ -260,7 +260,7 @@ static uint64_t pflash_data_read(PFlashCFI02 *pfl, hwaddr offset,
 {
     uint8_t *p = (uint8_t *)pfl->storage + offset;
     uint64_t ret = pfl->be ? ldn_be_p(p, width) : ldn_le_p(p, width);
-    trace_pflash_data_read(offset, width << 1, ret);
+    trace_pflash_data_read(offset, width << 3, ret);
     return ret;
 }
 
@@ -385,7 +385,7 @@ static uint64_t pflash_read(void *opaque, hwaddr offset, unsigned int width)
         }
         break;
     }
-    trace_pflash_io_read(offset, width, width << 1, ret, pfl->cmd, pfl->wcycle);
+    trace_pflash_io_read(offset, width << 3, ret, pfl->cmd, pfl->wcycle);
 
     return ret;
 }
@@ -432,7 +432,7 @@ static void pflash_write(void *opaque, hwaddr offset, uint64_t value,
     uint8_t *p;
     uint8_t cmd;
 
-    trace_pflash_io_write(offset, width, width << 1, value, pfl->wcycle);
+    trace_pflash_io_write(offset, width << 3, value, pfl->wcycle);
     cmd = value;
     if (pfl->cmd != 0xA0) {
         /* Reset does nothing during chip erase and sector erase. */
@@ -542,7 +542,7 @@ static void pflash_write(void *opaque, hwaddr offset, uint64_t value,
                 }
                 goto reset_flash;
             }
-            trace_pflash_data_write(offset, width << 1, value, 0);
+            trace_pflash_data_write(offset, width << 3, value, 0);
             if (!pfl->ro) {
                 p = (uint8_t *)pfl->storage + offset;
                 if (pfl->be) {
diff --git a/hw/block/trace-events b/hw/block/trace-events
index 13d1b21dd4..b9e195e172 100644
--- a/hw/block/trace-events
+++ b/hw/block/trace-events
@@ -8,10 +8,10 @@ fdc_ioport_write(uint8_t reg, uint8_t value) "write reg 0x%02x val 0x%02x"
 # pflash_cfi01.c
 pflash_reset(void) "reset"
 pflash_timer_expired(uint8_t cmd) "command 0x%02x done"
-pflash_io_read(uint64_t offset, int width, int fmt_width, uint32_t value, uint8_t cmd, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%0*x cmd:0x%02x wcycle:%u"
-pflash_io_write(uint64_t offset, int width, int fmt_width, uint32_t value, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%0*x wcycle:%u"
-pflash_data_read(uint64_t offset, int width, uint32_t value) "data offset:0x%04"PRIx64" value:0x%0*x"
-pflash_data_write(uint64_t offset, int width, uint32_t value, uint64_t counter) "data offset:0x%04"PRIx64" value:0x%0*x counter:0x%016"PRIx64
+pflash_io_read(uint64_t offset, int width, uint32_t value, uint8_t cmd, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%04x cmd:0x%02x wcycle:%u"
+pflash_io_write(uint64_t offset, int width, uint32_t value, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%04x wcycle:%u"
+pflash_data_read(uint64_t offset, int width, uint32_t value) "data offset:0x%04"PRIx64" width:%d value:0x%04x"
+pflash_data_write(uint64_t offset, int width, uint32_t value, uint64_t counter) "data offset:0x%04"PRIx64" width:%d value:0x%04x counter:0x%016"PRIx64
 pflash_manufacturer_id(uint16_t id) "Read Manufacturer ID: 0x%04x"
 pflash_device_id(uint16_t id) "Read Device ID: 0x%04x"
 pflash_device_info(uint64_t offset) "Read Device Information offset:0x%04"PRIx64
-- 
2.21.0

Re: [PATCH v2 1/3] hw/block/pflash: Remove dynamic field width from trace events

[Eric Blake]

On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
> Since not all trace backends support dynamic field width in
> format (dtrace via stap does not), replace by a static field
> width instead.
> 
> Reported-by: Eric Blake <eblake@redhat.com>
> Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
> Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> ---
>   hw/block/pflash_cfi01.c | 8 ++++----
>   hw/block/pflash_cfi02.c | 8 ++++----
>   hw/block/trace-events   | 8 ++++----
>   3 files changed, 12 insertions(+), 12 deletions(-)
> 
> diff --git a/hw/block/pflash_cfi01.c b/hw/block/pflash_cfi01.c
> index 566c0acb77..787d1196f2 100644
> --- a/hw/block/pflash_cfi01.c
> +++ b/hw/block/pflash_cfi01.c
> @@ -276,7 +276,7 @@ static uint32_t pflash_data_read(PFlashCFI01 *pfl, hwaddr offset,
>           DPRINTF("BUG in %s\n", __func__);
>           abort();
>       }
> -    trace_pflash_data_read(offset, width << 1, ret);
> +    trace_pflash_data_read(offset, width << 3, ret);

Umm, why is width changing?  That's not mentioned in the commit message.

> @@ -389,7 +389,7 @@ static uint32_t pflash_read(PFlashCFI01 *pfl, hwaddr offset,
>   
>           break;
>       }
> -    trace_pflash_io_read(offset, width, width << 1, ret, pfl->cmd, pfl->wcycle);
> +    trace_pflash_io_read(offset, width << 3, ret, pfl->cmd, pfl->wcycle);

And even this one is odd.  Matching up to the trace messages:


> -pflash_io_read(uint64_t offset, int width, int fmt_width, uint32_t value, uint8_t cmd, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%0*x cmd:0x%02x wcycle:%u"

> +pflash_io_read(uint64_t offset, int width, uint32_t value, uint8_t cmd, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%04x cmd:0x%02x wcycle:%u"

you are changing from:

"%04"PRIx64" %d %0*x...", offset, width, width << 1, ret,...

(where width<<1, ret matches *x)

into

"%04"PRIx64" %d %04x...", offset, width << 3, ret,...

where you are now printing a different value for width.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

Re: [PATCH v2 1/3] hw/block/pflash: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

Hi Eric,

On 11/8/19 4:56 PM, Eric Blake wrote:
> On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
>> Since not all trace backends support dynamic field width in
>> format (dtrace via stap does not), replace by a static field
>> width instead.
>>
>> Reported-by: Eric Blake <eblake@redhat.com>
>> Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
>> Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>> ---
>>   hw/block/pflash_cfi01.c | 8 ++++----
>>   hw/block/pflash_cfi02.c | 8 ++++----
>>   hw/block/trace-events   | 8 ++++----
>>   3 files changed, 12 insertions(+), 12 deletions(-)
>>
>> diff --git a/hw/block/pflash_cfi01.c b/hw/block/pflash_cfi01.c
>> index 566c0acb77..787d1196f2 100644
>> --- a/hw/block/pflash_cfi01.c
>> +++ b/hw/block/pflash_cfi01.c
>> @@ -276,7 +276,7 @@ static uint32_t pflash_data_read(PFlashCFI01 *pfl, 
>> hwaddr offset,
>>           DPRINTF("BUG in %s\n", __func__);
>>           abort();
>>       }
>> -    trace_pflash_data_read(offset, width << 1, ret);
>> +    trace_pflash_data_read(offset, width << 3, ret);
> 
> Umm, why is width changing?  That's not mentioned in the commit message.

Previously it was used to set the format width: [1, 2, 4] -> [2, 4, 8].

We usually log the width in byte (accessed at memory location) or bits 
(used by the bus). When using this device I'm custom to think in bus 
access width.

Regardless whichever format we prefer, a change is needed.

> 
>> @@ -389,7 +389,7 @@ static uint32_t pflash_read(PFlashCFI01 *pfl, 
>> hwaddr offset,
>>           break;
>>       }
>> -    trace_pflash_io_read(offset, width, width << 1, ret, pfl->cmd, 
>> pfl->wcycle);
>> +    trace_pflash_io_read(offset, width << 3, ret, pfl->cmd, 
>> pfl->wcycle);
> 
> And even this one is odd.  Matching up to the trace messages:
> 
> 
>> -pflash_io_read(uint64_t offset, int width, int fmt_width, uint32_t 
>> value, uint8_t cmd, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d 
>> value:0x%0*x cmd:0x%02x wcycle:%u"
> 
>> +pflash_io_read(uint64_t offset, int width, uint32_t value, uint8_t 
>> cmd, uint8_t wcycle) "offset:0x%04"PRIx64" width:%d value:0x%04x 
>> cmd:0x%02x wcycle:%u"
> 
> you are changing from:
> 
> "%04"PRIx64" %d %0*x...", offset, width, width << 1, ret,...
> 
> (where width<<1, ret matches *x)
> 
> into
> 
> "%04"PRIx64" %d %04x...", offset, width << 3, ret,...
> 
> where you are now printing a different value for width.

Do you prefer using a "-bit" suffix? As

"offset:0x%04"PRIx64" width:%d-bit value:0x%04x cmd:0x%02x wcycle:%u"

I can also simply remove this information. Ideally I'd revert this patch 
once the we get this format parsable by the SystemTap backend.

Re: [PATCH v2 1/3] hw/block/pflash: Remove dynamic field width from trace events

[Eric Blake]

On 11/14/19 3:26 PM, Philippe Mathieu-Daudé wrote:

>>> -    trace_pflash_data_read(offset, width << 1, ret);
>>> +    trace_pflash_data_read(offset, width << 3, ret);
>>
>> Umm, why is width changing?  That's not mentioned in the commit message.
> 
> Previously it was used to set the format width: [1, 2, 4] -> [2, 4, 8].
> 
> We usually log the width in byte (accessed at memory location) or bits 
> (used by the bus). When using this device I'm custom to think in bus 
> access width.
> 
> Regardless whichever format we prefer, a change is needed.
> 

> 
> Do you prefer using a "-bit" suffix? As
> 
> "offset:0x%04"PRIx64" width:%d-bit value:0x%04x cmd:0x%02x wcycle:%u"
> 
> I can also simply remove this information. Ideally I'd revert this patch 
> once the we get this format parsable by the SystemTap backend.

Reporting either 'width:8-bit'/'width:16-bit' (explicit bits) or 
'width:1'/'width:2' (implying byte) is fine by me.  Showing a bus width 
in bytes adequately explains why you are using <<3 (aka converting bits 
to bytes), and how it compares to the previous <<1 (converting bits to 
number of hex characters).  But whichever you pick (tracing bit width 
vs. byte width, and how it differs from previous usage of width as 
output-character count), documenting it in the commit message will make 
life easier to understand the change.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

Re: [PATCH v2 1/3] hw/block/pflash: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

On 11/18/19 8:21 PM, Eric Blake wrote:
> On 11/14/19 3:26 PM, Philippe Mathieu-Daudé wrote:
> 
>>>> -    trace_pflash_data_read(offset, width << 1, ret);
>>>> +    trace_pflash_data_read(offset, width << 3, ret);
>>>
>>> Umm, why is width changing?  That's not mentioned in the commit message.
>>
>> Previously it was used to set the format width: [1, 2, 4] -> [2, 4, 8].
>>
>> We usually log the width in byte (accessed at memory location) or bits 
>> (used by the bus). When using this device I'm custom to think in bus 
>> access width.
>>
>> Regardless whichever format we prefer, a change is needed.
>>
> 
>>
>> Do you prefer using a "-bit" suffix? As
>>
>> "offset:0x%04"PRIx64" width:%d-bit value:0x%04x cmd:0x%02x wcycle:%u"
>>
>> I can also simply remove this information. Ideally I'd revert this 
>> patch once the we get this format parsable by the SystemTap backend.
> 
> Reporting either 'width:8-bit'/'width:16-bit' (explicit bits) or 
> 'width:1'/'width:2' (implying byte) is fine by me.  Showing a bus width 
> in bytes adequately explains why you are using <<3 (aka converting bits 
> to bytes), and how it compares to the previous <<1 (converting bits to 
> number of hex characters).  But whichever you pick (tracing bit width 
> vs. byte width, and how it differs from previous usage of width as 
> output-character count), documenting it in the commit message will make 
> life easier to understand the change.

Yes you are right, I should have documented to avoid wasting review time 
clearing the confusion.

[PATCH v2 2/3] hw/mips/gt64xxx: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

Since not all trace backends support dynamic field width in
format (dtrace via stap does not), replace by a static field
width instead.

Reported-by: Eric Blake <eblake@redhat.com>
Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---
v2: Do not update qemu_log_mask()
---
 hw/mips/gt64xxx_pci.c | 16 ++++++++--------
 hw/mips/trace-events  |  4 ++--
 2 files changed, 10 insertions(+), 10 deletions(-)

diff --git a/hw/mips/gt64xxx_pci.c b/hw/mips/gt64xxx_pci.c
index 5cab9c1ee1..6743e7c929 100644
--- a/hw/mips/gt64xxx_pci.c
+++ b/hw/mips/gt64xxx_pci.c
@@ -642,19 +642,19 @@ static void gt64120_writel(void *opaque, hwaddr addr,
         /* not really implemented */
         s->regs[saddr] = ~(~(s->regs[saddr]) | ~(val & 0xfffffffe));
         s->regs[saddr] |= !!(s->regs[saddr] & 0xfffffffe);
-        trace_gt64120_write("INTRCAUSE", size << 1, val);
+        trace_gt64120_write("INTRCAUSE", size << 3, val);
         break;
     case GT_INTRMASK:
         s->regs[saddr] = val & 0x3c3ffffe;
-        trace_gt64120_write("INTRMASK", size << 1, val);
+        trace_gt64120_write("INTRMASK", size << 3, val);
         break;
     case GT_PCI0_ICMASK:
         s->regs[saddr] = val & 0x03fffffe;
-        trace_gt64120_write("ICMASK", size << 1, val);
+        trace_gt64120_write("ICMASK", size << 3, val);
         break;
     case GT_PCI0_SERR0MASK:
         s->regs[saddr] = val & 0x0000003f;
-        trace_gt64120_write("SERR0MASK", size << 1, val);
+        trace_gt64120_write("SERR0MASK", size << 3, val);
         break;
 
     /* Reserved when only PCI_0 is configured. */
@@ -930,19 +930,19 @@ static uint64_t gt64120_readl(void *opaque,
     /* Interrupts */
     case GT_INTRCAUSE:
         val = s->regs[saddr];
-        trace_gt64120_read("INTRCAUSE", size << 1, val);
+        trace_gt64120_read("INTRCAUSE", size << 3, val);
         break;
     case GT_INTRMASK:
         val = s->regs[saddr];
-        trace_gt64120_read("INTRMASK", size << 1, val);
+        trace_gt64120_read("INTRMASK", size << 3, val);
         break;
     case GT_PCI0_ICMASK:
         val = s->regs[saddr];
-        trace_gt64120_read("ICMASK", size << 1, val);
+        trace_gt64120_read("ICMASK", size << 3, val);
         break;
     case GT_PCI0_SERR0MASK:
         val = s->regs[saddr];
-        trace_gt64120_read("SERR0MASK", size << 1, val);
+        trace_gt64120_read("SERR0MASK", size << 3, val);
         break;
 
     /* Reserved when only PCI_0 is configured. */
diff --git a/hw/mips/trace-events b/hw/mips/trace-events
index 75d4c73f2e..86a0213c77 100644
--- a/hw/mips/trace-events
+++ b/hw/mips/trace-events
@@ -1,4 +1,4 @@
 # gt64xxx.c
-gt64120_read(const char *regname, int width, uint64_t value) "gt64120 read %s value:0x%0*" PRIx64
-gt64120_write(const char *regname, int width, uint64_t value) "gt64120 write %s value:0x%0*" PRIx64
+gt64120_read(const char *regname, int width, uint64_t value) "gt64120 read %s width:%d value:0x%08" PRIx64
+gt64120_write(const char *regname, int width, uint64_t value) "gt64120 write %s width:%d value:0x%08" PRIx64
 gt64120_isd_remap(uint64_t from_length, uint64_t from_addr, uint64_t to_length, uint64_t to_addr) "ISD: 0x%08" PRIx64 "@0x%08" PRIx64 " -> 0x%08" PRIx64 "@0x%08" PRIx64
-- 
2.21.0

Re: [PATCH v2 2/3] hw/mips/gt64xxx: Remove dynamic field width from trace events

[Eric Blake]

On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
> Since not all trace backends support dynamic field width in
> format (dtrace via stap does not), replace by a static field
> width instead.
> 
> Reported-by: Eric Blake <eblake@redhat.com>
> Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
> Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
> ---
> v2: Do not update qemu_log_mask()
> ---
>   hw/mips/gt64xxx_pci.c | 16 ++++++++--------
>   hw/mips/trace-events  |  4 ++--
>   2 files changed, 10 insertions(+), 10 deletions(-)
> 
> diff --git a/hw/mips/gt64xxx_pci.c b/hw/mips/gt64xxx_pci.c
> index 5cab9c1ee1..6743e7c929 100644
> --- a/hw/mips/gt64xxx_pci.c
> +++ b/hw/mips/gt64xxx_pci.c
> @@ -642,19 +642,19 @@ static void gt64120_writel(void *opaque, hwaddr addr,
>           /* not really implemented */
>           s->regs[saddr] = ~(~(s->regs[saddr]) | ~(val & 0xfffffffe));
>           s->regs[saddr] |= !!(s->regs[saddr] & 0xfffffffe);
> -        trace_gt64120_write("INTRCAUSE", size << 1, val);
> +        trace_gt64120_write("INTRCAUSE", size << 3, val);

Again, this isn't mentioned in the commit message.  Why are you changing 
parameter values?


> +++ b/hw/mips/trace-events
> @@ -1,4 +1,4 @@
>   # gt64xxx.c
> -gt64120_read(const char *regname, int width, uint64_t value) "gt64120 read %s value:0x%0*" PRIx64
> -gt64120_write(const char *regname, int width, uint64_t value) "gt64120 write %s value:0x%0*" PRIx64
> +gt64120_read(const char *regname, int width, uint64_t value) "gt64120 read %s width:%d value:0x%08" PRIx64
> +gt64120_write(const char *regname, int width, uint64_t value) "gt64120 write %s width:%d value:0x%08" PRIx64

Huh, we were really broken - the old code (if passed to printf) would 
try to parse 4 parameters, even though it was only passed 3.  But it 
looks like you still need a v3.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

Re: [PATCH v2 2/3] hw/mips/gt64xxx: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

On 11/8/19 4:58 PM, Eric Blake wrote:
> On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
>> Since not all trace backends support dynamic field width in
>> format (dtrace via stap does not), replace by a static field
>> width instead.
>>
>> Reported-by: Eric Blake <eblake@redhat.com>
>> Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
>> Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>> ---
>> v2: Do not update qemu_log_mask()
>> ---
>>   hw/mips/gt64xxx_pci.c | 16 ++++++++--------
>>   hw/mips/trace-events  |  4 ++--
>>   2 files changed, 10 insertions(+), 10 deletions(-)
>>
>> diff --git a/hw/mips/gt64xxx_pci.c b/hw/mips/gt64xxx_pci.c
>> index 5cab9c1ee1..6743e7c929 100644
>> --- a/hw/mips/gt64xxx_pci.c
>> +++ b/hw/mips/gt64xxx_pci.c
>> @@ -642,19 +642,19 @@ static void gt64120_writel(void *opaque, hwaddr 
>> addr,
>>           /* not really implemented */
>>           s->regs[saddr] = ~(~(s->regs[saddr]) | ~(val & 0xfffffffe));
>>           s->regs[saddr] |= !!(s->regs[saddr] & 0xfffffffe);
>> -        trace_gt64120_write("INTRCAUSE", size << 1, val);
>> +        trace_gt64120_write("INTRCAUSE", size << 3, val);
> 
> Again, this isn't mentioned in the commit message.  Why are you changing 
> parameter values?
> 
> 
>> +++ b/hw/mips/trace-events
>> @@ -1,4 +1,4 @@
>>   # gt64xxx.c
>> -gt64120_read(const char *regname, int width, uint64_t value) "gt64120 
>> read %s value:0x%0*" PRIx64
>> -gt64120_write(const char *regname, int width, uint64_t value) 
>> "gt64120 write %s value:0x%0*" PRIx64
>> +gt64120_read(const char *regname, int width, uint64_t value) "gt64120 
>> read %s width:%d value:0x%08" PRIx64
>> +gt64120_write(const char *regname, int width, uint64_t value) 
>> "gt64120 write %s width:%d value:0x%08" PRIx64
> 
> Huh, we were really broken - the old code (if passed to printf) would 
> try to parse 4 parameters, even though it was only passed 3.  But it 
> looks like you still need a v3.

Oops. I am surprise the compiler doesn't emit a warning here...

Re: [PATCH v2 2/3] hw/mips/gt64xxx: Remove dynamic field width from trace events

[Philippe Mathieu-Daudé]

On 11/14/19 10:24 PM, Philippe Mathieu-Daudé wrote:
> On 11/8/19 4:58 PM, Eric Blake wrote:
>> On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
>>> Since not all trace backends support dynamic field width in
>>> format (dtrace via stap does not), replace by a static field
>>> width instead.
>>>
>>> Reported-by: Eric Blake <eblake@redhat.com>
>>> Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
>>> Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
>>> ---
>>> v2: Do not update qemu_log_mask()
>>> ---
>>>   hw/mips/gt64xxx_pci.c | 16 ++++++++--------
>>>   hw/mips/trace-events  |  4 ++--
>>>   2 files changed, 10 insertions(+), 10 deletions(-)
>>>
>>> diff --git a/hw/mips/gt64xxx_pci.c b/hw/mips/gt64xxx_pci.c
>>> index 5cab9c1ee1..6743e7c929 100644
>>> --- a/hw/mips/gt64xxx_pci.c
>>> +++ b/hw/mips/gt64xxx_pci.c
>>> @@ -642,19 +642,19 @@ static void gt64120_writel(void *opaque, hwaddr 
>>> addr,
>>>           /* not really implemented */
>>>           s->regs[saddr] = ~(~(s->regs[saddr]) | ~(val & 0xfffffffe));
>>>           s->regs[saddr] |= !!(s->regs[saddr] & 0xfffffffe);
>>> -        trace_gt64120_write("INTRCAUSE", size << 1, val);
>>> +        trace_gt64120_write("INTRCAUSE", size << 3, val);
>>
>> Again, this isn't mentioned in the commit message.  Why are you 
>> changing parameter values?
>>
>>
>>> +++ b/hw/mips/trace-events
>>> @@ -1,4 +1,4 @@
>>>   # gt64xxx.c
>>> -gt64120_read(const char *regname, int width, uint64_t value) 
>>> "gt64120 read %s value:0x%0*" PRIx64
>>> -gt64120_write(const char *regname, int width, uint64_t value) 
>>> "gt64120 write %s value:0x%0*" PRIx64
>>> +gt64120_read(const char *regname, int width, uint64_t value) 
>>> "gt64120 read %s width:%d value:0x%08" PRIx64
>>> +gt64120_write(const char *regname, int width, uint64_t value) 
>>> "gt64120 write %s width:%d value:0x%08" PRIx64
>>
>> Huh, we were really broken - the old code (if passed to printf) would 
>> try to parse 4 parameters, even though it was only passed 3.  But it 
>> looks like you still need a v3.
> 
> Oops. I am surprise the compiler doesn't emit a warning here...

I'm sorry I can't see the 4th parameter.

Before: "gt64120 read %s value:0x%0*" PRIx64

#1 's' for 'const char *regname'
#2 '0*' for 'int width'
#3 'x' for 'uint64_t value'

After: "gt64120 read %s width:%d value:0x%08" PRIx64

#1 's' for 'const char *regname'
#2 'd' for 'int width'
#3 '08x' for 'uint64_t value'

Am I missing something?

Re: [PATCH v2 2/3] hw/mips/gt64xxx: Remove dynamic field width from trace events

[Eric Blake]

On 11/18/19 1:10 PM, Philippe Mathieu-Daudé wrote:

>>>> -        trace_gt64120_write("INTRCAUSE", size << 1, val);
>>>> +        trace_gt64120_write("INTRCAUSE", size << 3, val);
>>>
>>> Again, this isn't mentioned in the commit message.  Why are you 
>>> changing parameter values?
>>>
>>>
>>>> +++ b/hw/mips/trace-events
>>>> @@ -1,4 +1,4 @@
>>>>   # gt64xxx.c
>>>> -gt64120_read(const char *regname, int width, uint64_t value) 
>>>> "gt64120 read %s value:0x%0*" PRIx64
>>>> -gt64120_write(const char *regname, int width, uint64_t value) 
>>>> "gt64120 write %s value:0x%0*" PRIx64
>>>> +gt64120_read(const char *regname, int width, uint64_t value) 
>>>> "gt64120 read %s width:%d value:0x%08" PRIx64
>>>> +gt64120_write(const char *regname, int width, uint64_t value) 
>>>> "gt64120 write %s width:%d value:0x%08" PRIx64
>>>
>>> Huh, we were really broken - the old code (if passed to printf) would 
>>> try to parse 4 parameters, even though it was only passed 3.  But it 
>>> looks like you still need a v3.
>>
>> Oops. I am surprise the compiler doesn't emit a warning here...
> 
> I'm sorry I can't see the 4th parameter.

My fault for chasing a red herring.  I guess I was mixing the three % 
post-patch with the two % and one * pre-patch, and somehow mis-counting 
three % plus one * as four arguments.  But re-reading your confusion, 
yes, there were only three parameters being consumed.

> 
> Before: "gt64120 read %s value:0x%0*" PRIx64
> 
> #1 's' for 'const char *regname'
> #2 '0*' for 'int width'
> #3 'x' for 'uint64_t value'
> 
> After: "gt64120 read %s width:%d value:0x%08" PRIx64
> 
> #1 's' for 'const char *regname'
> #2 'd' for 'int width'
> #3 '08x' for 'uint64_t value'
> 
> Am I missing something?

Rather, I was.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

[PATCH v2 3/3] trace: Forbid dynamic field width in event format

[Philippe Mathieu-Daudé]

Since not all trace backends support dynamic field width in
format (dtrace via stap does not), forbid them.

Add a check to refuse field width in new formats:

  $ make
  [...]
    GEN     hw/block/trace.h
  Traceback (most recent call last):
    File "scripts/tracetool.py", line 152, in <module>
      main(sys.argv)
    File "scripts/tracetool.py", line 143, in main
      events.extend(tracetool.read_events(fh, arg))
    File "scripts/tracetool/__init__.py", line 371, in read_events
      event = Event.build(line)
    File "scripts/tracetool/__init__.py", line 285, in build
      raise ValueError("Event format must not contain field width '%*'")
  ValueError: Error at hw/block/trace-events:11: Event format must not contain field width '%*'

Reported-by: Eric Blake <eblake@redhat.com>
Buglink: https://bugs.launchpad.net/qemu/+bug/1844817
Signed-off-by: Philippe Mathieu-Daudé <philmd@redhat.com>
---
 scripts/tracetool/__init__.py | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/scripts/tracetool/__init__.py b/scripts/tracetool/__init__.py
index 44c118bc2a..e239be602b 100644
--- a/scripts/tracetool/__init__.py
+++ b/scripts/tracetool/__init__.py
@@ -206,6 +206,7 @@ class Event(object):
                       "\s*"
                       "(?:(?:(?P<fmt_trans>\".+),)?\s*(?P<fmt>\".+))?"
                       "\s*")
+    _DFWRE = re.compile(".*(%0?\*).*")
 
     _VALID_PROPS = set(["disable", "tcg", "tcg-trans", "tcg-exec", "vcpu"])
 
@@ -280,6 +281,8 @@ class Event(object):
         if fmt.endswith(r'\n"'):
             raise ValueError("Event format must not end with a newline "
                              "character")
+        if Event._DFWRE.match(fmt):
+            raise ValueError("Event format must not contain field width '%*'")
 
         if len(fmt_trans) > 0:
             fmt = [fmt_trans, fmt]
-- 
2.21.0

Re: [PATCH v2 3/3] trace: Forbid dynamic field width in event format

[Eric Blake]

On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
> Since not all trace backends support dynamic field width in
> format (dtrace via stap does not), forbid them.
> 
> Add a check to refuse field width in new formats:
> 

> +++ b/scripts/tracetool/__init__.py
> @@ -206,6 +206,7 @@ class Event(object):
>                         "\s*"
>                         "(?:(?:(?P<fmt_trans>\".+),)?\s*(?P<fmt>\".+))?"
>                         "\s*")
> +    _DFWRE = re.compile(".*(%0?\*).*")

The use of leading and trailing .* is pointless if the RE itself is used 
unanchored and where you only care if the () matched.

This doesn't catch all valid uses of * in a printf format.  Better might 
be something like:

_DFWRE = re.compile("%[\d\.\- +#']*\*")

which matches only if there is a %, any number of characters that can 
form a printf flag, as well as a numeric field width but dynamic precision.


> +        if Event._DFWRE.match(fmt):
> +            raise ValueError("Event format must not contain field width '%*'")
>   
>           if len(fmt_trans) > 0:
>               fmt = [fmt_trans, fmt]
> 

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

Re: [PATCH v2 3/3] trace: Forbid dynamic field width in event format

[Eric Blake]

On 11/8/19 10:07 AM, Eric Blake wrote:
> On 11/8/19 8:40 AM, Philippe Mathieu-Daudé wrote:
>> Since not all trace backends support dynamic field width in
>> format (dtrace via stap does not), forbid them.
>>
>> Add a check to refuse field width in new formats:
>>
> 
>> +++ b/scripts/tracetool/__init__.py
>> @@ -206,6 +206,7 @@ class Event(object):
>>                         "\s*"
>>                         "(?:(?:(?P<fmt_trans>\".+),)?\s*(?P<fmt>\".+))?"
>>                         "\s*")
>> +    _DFWRE = re.compile(".*(%0?\*).*")
> 
> The use of leading and trailing .* is pointless if the RE itself is used 
> unanchored and where you only care if the () matched.

Following up on this (based on an IRC conversation):

re.match _is_ anchored by default, while re.search is unanchored

> 
> This doesn't catch all valid uses of * in a printf format.  Better might 
> be something like:
> 
> _DFWRE = re.compile("%[\d\.\- +#']*\*")
> 
> which matches only if there is a %, any number of characters that can 
> form a printf flag, as well as a numeric field width but dynamic precision.
> 
> 
>> +        if Event._DFWRE.match(fmt):

Or put differently, if you want to drop the .* from the compiled regex, 
then you need to use .search(fmt) here rather than .match(fmt).

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org