[PATCH 0/2] tracetool: fix log-stap format

[PATCH 0/2] tracetool: fix log-stap format

[Laurent Vivier]

The first patch fixes a problem I have introduced in vhost-vdpa
traces by adding an unsupported format ("%llu").

The second patch fixes a problem I've seen while I was checking
the result of the first patch: %PRI formats are not decoded
correctly and we can end with things like "0x%u" because
the used format is always the one of the first format of the string.

Laurent Vivier (2):
  vhost-vdpa: fix "unsigned long long" error with stap
  tracetool: fix "PRI" macro decoding

 hw/virtio/trace-events               | 2 +-
 hw/virtio/vhost-vdpa.c               | 4 ++--
 scripts/tracetool/format/log_stap.py | 1 +
 3 files changed, 4 insertions(+), 3 deletions(-)

-- 
2.29.2

[PATCH 1/2] vhost-vdpa: fix "unsigned long long" error with stap

[Laurent Vivier]

The "%llu" format type is not understood by stap:

$ sudo stap -e 'probe begin{printf ("BEGIN")}'  -I .

parse error: invalid or missing conversion specifier
          saw: operator ',' at ./qemu-system-x86_64-log.stp:15118:101
       source:     printf("%d@%d vhost_vdpa_set_log_base dev: %p base: 0x%x size: %llu refcnt: %d fd: %d log: %p\n", pid(), gettimeofday_ns(), dev, base, size, refcnt, fd, log)
                                                                                                                 ^

  1 parse error.
  WARNING: tapset "./qemu-system-x86_64-log.stp" has errors, and will be skipped

commit 35e28cb0f210 ("scripts/tracetool: silence SystemTap dtrace(1)
long long warnings") has already fixed the problem for the dtrace format
by dynamically replacing "unsigned long long" by "uint64_t", but as it
seems the problem can happen with any format and this is the only
occurrence of this type, simply replace it directly by "uint64_t" in the
trace-events file.

Fixes: 778e67de4cd8 ("vhost-vdpa: add trace-events")
Signed-off-by: Laurent Vivier <lvivier@redhat.com>
---
 hw/virtio/trace-events | 2 +-
 hw/virtio/vhost-vdpa.c | 4 ++--
 2 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/hw/virtio/trace-events b/hw/virtio/trace-events
index 2060a144a2f4..6074bafeb147 100644
--- a/hw/virtio/trace-events
+++ b/hw/virtio/trace-events
@@ -42,7 +42,7 @@ vhost_vdpa_dump_config(void *dev, const char *line) "dev: %p %s"
 vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, uint32_t flags) "dev: %p offset: %"PRIu32" size: %"PRIu32" flags: 0x%"PRIx32
 vhost_vdpa_get_config(void *dev, void *config, uint32_t config_len) "dev: %p config: %p config_len: %"PRIu32
 vhost_vdpa_dev_start(void *dev, bool started) "dev: %p started: %d"
-vhost_vdpa_set_log_base(void *dev, uint64_t base, unsigned long long size, int refcnt, int fd, void *log) "dev: %p base: 0x%"PRIx64" size: %llu refcnt: %d fd: %d log: %p"
+vhost_vdpa_set_log_base(void *dev, uint64_t base, uint64_t size, int refcnt, int fd, void *log) "dev: %p base: 0x%"PRIx64" size: %"PRIu64" refcnt: %d fd: %d log: %p"
 vhost_vdpa_set_vring_addr(void *dev, unsigned int index, unsigned int flags, uint64_t desc_user_addr, uint64_t used_user_addr, uint64_t avail_user_addr, uint64_t log_guest_addr) "dev: %p index: %u flags: 0x%x desc_user_addr: 0x%"PRIx64" used_user_addr: 0x%"PRIx64" avail_user_addr: 0x%"PRIx64" log_guest_addr: 0x%"PRIx64
 vhost_vdpa_set_vring_num(void *dev, unsigned int index, unsigned int num) "dev: %p index: %u num: %u"
 vhost_vdpa_set_vring_base(void *dev, unsigned int index, unsigned int num) "dev: %p index: %u num: %u"
diff --git a/hw/virtio/vhost-vdpa.c b/hw/virtio/vhost-vdpa.c
index 01d2101d0976..436aa20d3f09 100644
--- a/hw/virtio/vhost-vdpa.c
+++ b/hw/virtio/vhost-vdpa.c
@@ -493,8 +493,8 @@ static int vhost_vdpa_dev_start(struct vhost_dev *dev, bool started)
 static int vhost_vdpa_set_log_base(struct vhost_dev *dev, uint64_t base,
                                      struct vhost_log *log)
 {
-    trace_vhost_vdpa_set_log_base(dev, base, log->size, log->refcnt, log->fd,
-                                  log->log);
+    trace_vhost_vdpa_set_log_base(dev, base, (uint64_t)log->size, log->refcnt,
+                                  log->fd, log->log);
     return vhost_vdpa_call(dev, VHOST_SET_LOG_BASE, &base);
 }
 
-- 
2.29.2

[PATCH 2/2] tracetool: fix "PRI" macro decoding

[Laurent Vivier]

macro is not reset after use, so the format decoded is always the
one of the first "PRI" in the format string.

For instance:

  vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, \
                        uint32_t flags) "dev: %p offset: %"PRIu32" \
                        size: %"PRIu32" flags: 0x%"PRIx32

generates:

  printf("%d@%d vhost_vdpa_set_config dev: %p offset: %u size: %u \
          flags: 0x%u\n", pid(), gettimeofday_ns(), dev, offset, \
          size, flags)

for the "flags" parameter, we can see a "0x%u" rather than a "0x%x"
because the first macro was "PRIu32" (for offset).

In the loop, macro becomes "PRIu32PRIu32PRIx32", and c_macro_to_format()
returns always macro[3] ('u' in this case). This patch resets macro after
the format has been decoded.

Signed-off-by: Laurent Vivier <lvivier@redhat.com>
---
 scripts/tracetool/format/log_stap.py | 1 +
 1 file changed, 1 insertion(+)

diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
index b486beb67239..3e1186ae9cc2 100644
--- a/scripts/tracetool/format/log_stap.py
+++ b/scripts/tracetool/format/log_stap.py
@@ -54,6 +54,7 @@ def c_fmt_to_stap(fmt):
             else:
                 if state == STATE_MACRO:
                     bits.append(c_macro_to_format(macro))
+                    macro = ""
                 state = STATE_LITERAL
         elif fmt[i] == ' ' or fmt[i] == '\t':
             if state == STATE_MACRO:
-- 
2.29.2

Re: [PATCH 2/2] tracetool: fix "PRI" macro decoding

[Philippe Mathieu-Daudé]

On 1/5/21 8:17 PM, Laurent Vivier wrote:
> macro is not reset after use, so the format decoded is always the
> one of the first "PRI" in the format string.
> 
> For instance:
> 
>   vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, \
>                         uint32_t flags) "dev: %p offset: %"PRIu32" \
>                         size: %"PRIu32" flags: 0x%"PRIx32
> 
> generates:
> 
>   printf("%d@%d vhost_vdpa_set_config dev: %p offset: %u size: %u \
>           flags: 0x%u\n", pid(), gettimeofday_ns(), dev, offset, \
>           size, flags)
> 
> for the "flags" parameter, we can see a "0x%u" rather than a "0x%x"
> because the first macro was "PRIu32" (for offset).
> 
> In the loop, macro becomes "PRIu32PRIu32PRIx32", and c_macro_to_format()
> returns always macro[3] ('u' in this case). This patch resets macro after
> the format has been decoded.
> 
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  scripts/tracetool/format/log_stap.py | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
> index b486beb67239..3e1186ae9cc2 100644
> --- a/scripts/tracetool/format/log_stap.py
> +++ b/scripts/tracetool/format/log_stap.py
> @@ -54,6 +54,7 @@ def c_fmt_to_stap(fmt):
>              else:
>                  if state == STATE_MACRO:
>                      bits.append(c_macro_to_format(macro))
> +                    macro = ""
>                  state = STATE_LITERAL
>          elif fmt[i] == ' ' or fmt[i] == '\t':
>              if state == STATE_MACRO:

What about the 'else' case?

Re: [PATCH 0/2] tracetool: fix log-stap format

[Philippe Mathieu-Daudé]

On 1/5/21 8:17 PM, Laurent Vivier wrote:
> The first patch fixes a problem I have introduced in vhost-vdpa
> traces by adding an unsupported format ("%llu").
> 
> The second patch fixes a problem I've seen while I was checking
> the result of the first patch: %PRI formats are not decoded
> correctly and we can end with things like "0x%u" because
> the used format is always the one of the first format of the string.
> 
> Laurent Vivier (2):
>   vhost-vdpa: fix "unsigned long long" error with stap
>   tracetool: fix "PRI" macro decoding
> 
>  hw/virtio/trace-events               | 2 +-
>  hw/virtio/vhost-vdpa.c               | 4 ++--
>  scripts/tracetool/format/log_stap.py | 1 +
>  3 files changed, 4 insertions(+), 3 deletions(-)

Reviewed-by: Philippe Mathieu-Daudé <philmd@redhat.com>

Re: [PATCH 2/2] tracetool: fix "PRI" macro decoding

[Laurent Vivier]

On 05/01/2021 20:44, Philippe Mathieu-Daudé wrote:
> On 1/5/21 8:17 PM, Laurent Vivier wrote:
>> macro is not reset after use, so the format decoded is always the
>> one of the first "PRI" in the format string.
>>
>> For instance:
>>
>>   vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, \
>>                         uint32_t flags) "dev: %p offset: %"PRIu32" \
>>                         size: %"PRIu32" flags: 0x%"PRIx32
>>
>> generates:
>>
>>   printf("%d@%d vhost_vdpa_set_config dev: %p offset: %u size: %u \
>>           flags: 0x%u\n", pid(), gettimeofday_ns(), dev, offset, \
>>           size, flags)
>>
>> for the "flags" parameter, we can see a "0x%u" rather than a "0x%x"
>> because the first macro was "PRIu32" (for offset).
>>
>> In the loop, macro becomes "PRIu32PRIu32PRIx32", and c_macro_to_format()
>> returns always macro[3] ('u' in this case). This patch resets macro after
>> the format has been decoded.
>>
>> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
>> ---
>>  scripts/tracetool/format/log_stap.py | 1 +
>>  1 file changed, 1 insertion(+)
>>
>> diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
>> index b486beb67239..3e1186ae9cc2 100644
>> --- a/scripts/tracetool/format/log_stap.py
>> +++ b/scripts/tracetool/format/log_stap.py
>> @@ -54,6 +54,7 @@ def c_fmt_to_stap(fmt):
>>              else:
>>                  if state == STATE_MACRO:
>>                      bits.append(c_macro_to_format(macro))
>> +                    macro = ""
>>                  state = STATE_LITERAL
>>          elif fmt[i] == ' ' or fmt[i] == '\t':
>>              if state == STATE_MACRO:
> 
> What about the 'else' case?
> 

It already has the 'macro = ""', so no need to fix it.

Thanks,
Laurent

Re: [PATCH 1/2] vhost-vdpa: fix "unsigned long long" error with stap

[Laurent Vivier]

On 05/01/2021 20:17, Laurent Vivier wrote:
> The "%llu" format type is not understood by stap:
> 
> $ sudo stap -e 'probe begin{printf ("BEGIN")}'  -I .
> 
> parse error: invalid or missing conversion specifier
>           saw: operator ',' at ./qemu-system-x86_64-log.stp:15118:101
>        source:     printf("%d@%d vhost_vdpa_set_log_base dev: %p base: 0x%x size: %llu refcnt: %d fd: %d log: %p\n", pid(), gettimeofday_ns(), dev, base, size, refcnt, fd, log)
>                                                                                                                  ^
> 
>   1 parse error.
>   WARNING: tapset "./qemu-system-x86_64-log.stp" has errors, and will be skipped
> 
> commit 35e28cb0f210 ("scripts/tracetool: silence SystemTap dtrace(1)
> long long warnings") has already fixed the problem for the dtrace format
> by dynamically replacing "unsigned long long" by "uint64_t", but as it
> seems the problem can happen with any format and this is the only
> occurrence of this type, simply replace it directly by "uint64_t" in the
> trace-events file.
> 
> Fixes: 778e67de4cd8 ("vhost-vdpa: add trace-events")
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  hw/virtio/trace-events | 2 +-
>  hw/virtio/vhost-vdpa.c | 4 ++--
>  2 files changed, 3 insertions(+), 3 deletions(-)

Ignore this patch, Daniel has proposed a better fix.

Thanks,
Laurent

Re: [PATCH 2/2] tracetool: fix "PRI" macro decoding

[Daniel P. Berrangé]

On Tue, Jan 05, 2021 at 08:17:21PM +0100, Laurent Vivier wrote:
> macro is not reset after use, so the format decoded is always the
> one of the first "PRI" in the format string.
> 
> For instance:
> 
>   vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, \
>                         uint32_t flags) "dev: %p offset: %"PRIu32" \
>                         size: %"PRIu32" flags: 0x%"PRIx32
> 
> generates:
> 
>   printf("%d@%d vhost_vdpa_set_config dev: %p offset: %u size: %u \
>           flags: 0x%u\n", pid(), gettimeofday_ns(), dev, offset, \
>           size, flags)
> 
> for the "flags" parameter, we can see a "0x%u" rather than a "0x%x"
> because the first macro was "PRIu32" (for offset).
> 
> In the loop, macro becomes "PRIu32PRIu32PRIx32", and c_macro_to_format()
> returns always macro[3] ('u' in this case). This patch resets macro after
> the format has been decoded.
> 
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  scripts/tracetool/format/log_stap.py | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/scripts/tracetool/format/log_stap.py b/scripts/tracetool/format/log_stap.py
> index b486beb67239..3e1186ae9cc2 100644
> --- a/scripts/tracetool/format/log_stap.py
> +++ b/scripts/tracetool/format/log_stap.py
> @@ -54,6 +54,7 @@ def c_fmt_to_stap(fmt):
>              else:
>                  if state == STATE_MACRO:
>                      bits.append(c_macro_to_format(macro))
> +                    macro = ""
>                  state = STATE_LITERAL
>          elif fmt[i] == ' ' or fmt[i] == '\t':
>              if state == STATE_MACRO:

Reviewed-by: Daniel P. Berrangé <berrange@redhat.com>


Regards,
Daniel
-- 
|: https://berrange.com      -o-    https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org         -o-            https://fstop138.berrange.com :|
|: https://entangle-photo.org    -o-    https://www.instagram.com/dberrange :|

Re: [PATCH 2/2] tracetool: fix "PRI" macro decoding

[Stefan Hajnoczi]

[-- Attachment #1: Type: text/plain, Size: 1165 bytes --]

On Tue, Jan 05, 2021 at 08:17:21PM +0100, Laurent Vivier wrote:
> macro is not reset after use, so the format decoded is always the
> one of the first "PRI" in the format string.
> 
> For instance:
> 
>   vhost_vdpa_set_config(void *dev, uint32_t offset, uint32_t size, \
>                         uint32_t flags) "dev: %p offset: %"PRIu32" \
>                         size: %"PRIu32" flags: 0x%"PRIx32
> 
> generates:
> 
>   printf("%d@%d vhost_vdpa_set_config dev: %p offset: %u size: %u \
>           flags: 0x%u\n", pid(), gettimeofday_ns(), dev, offset, \
>           size, flags)
> 
> for the "flags" parameter, we can see a "0x%u" rather than a "0x%x"
> because the first macro was "PRIu32" (for offset).
> 
> In the loop, macro becomes "PRIu32PRIu32PRIx32", and c_macro_to_format()
> returns always macro[3] ('u' in this case). This patch resets macro after
> the format has been decoded.
> 
> Signed-off-by: Laurent Vivier <lvivier@redhat.com>
> ---
>  scripts/tracetool/format/log_stap.py | 1 +
>  1 file changed, 1 insertion(+)

Thanks, applied to my tracing tree:
https://gitlab.com/stefanha/qemu/commits/tracing

Stefan

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]