[PULL 0/1] Tracing patches

[PULL 0/1] Tracing patches

[Stefan Hajnoczi]

The following changes since commit 56a3033abcfcf72a2f4f1376a605a0b1ad526b67:

  Merge tag 'pull-request-2025-07-21' of https://gitlab.com/thuth/qemu into staging (2025-07-21 06:34:56 -0400)

are available in the Git repository at:

  https://gitlab.com/stefanha/qemu.git tags/tracing-pull-request

for you to fetch changes up to 50700e97d85e435363ca4525754b5f00b13491c0:

  trace: log.py: human-readable timestamp (2025-07-21 14:02:52 -0400)

----------------------------------------------------------------
Pull request

----------------------------------------------------------------

Vladimir Sementsov-Ogievskiy (1):
  trace: log.py: human-readable timestamp

 scripts/tracetool/backend/log.py | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

-- 
2.50.1

[PULL 1/1] trace: log.py: human-readable timestamp

[Stefan Hajnoczi]

From: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>

So tired to parse all these timestamps, when need to compare them
with other logs.

Use iso8601 format as in warn_report() (info_report(), error_report())
already used.

Also, start line with date, to be similar with warn_report() as well.

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
Message-id: 20250626195514.366177-1-vsementsov@yandex-team.ru
Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
---
 scripts/tracetool/backend/log.py | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index 17ba1cd90e..61118474b1 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -39,10 +39,15 @@ def generate_h(event, group):
         '        if (message_with_timestamp) {',
         '            struct timeval _now;',
         '            gettimeofday(&_now, NULL);',
+        '            time_t _seconds = _now.tv_sec;',
+        '            struct tm _tm;',
+        '            gmtime_r(&_seconds, &_tm);',
         '#line %(event_lineno)d "%(event_filename)s"',
-        '            qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
-        '                     qemu_get_thread_id(),',
-        '                     (size_t)_now.tv_sec, (size_t)_now.tv_usec',
+        '            qemu_log("%%04d-%%02d-%%02dT%%02d:%%02d:%%02d.%%06ldZ'
+        ' (%%d) %(name)s " %(fmt)s "\\n",',
+        '                     _tm.tm_year + 1900, _tm.tm_mon + 1, _tm.tm_mday,',
+        '                     _tm.tm_hour, _tm.tm_min, _tm.tm_sec, _now.tv_usec,',
+        '                     qemu_get_thread_id()',
         '                     %(argnames)s);',
         '#line %(out_next_lineno)d "%(out_filename)s"',
         '        } else {',
-- 
2.50.1

Re: [PULL 1/1] trace: log.py: human-readable timestamp

[Daniel P. Berrangé]

On Mon, Jul 21, 2025 at 02:10:51PM -0400, Stefan Hajnoczi wrote:
> From: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
> 
> So tired to parse all these timestamps, when need to compare them
> with other logs.
> 
> Use iso8601 format as in warn_report() (info_report(), error_report())
> already used.
> 
> Also, start line with date, to be similar with warn_report() as well.
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
> Message-id: 20250626195514.366177-1-vsementsov@yandex-team.ru
> Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> ---
>  scripts/tracetool/backend/log.py | 11 ++++++++---
>  1 file changed, 8 insertions(+), 3 deletions(-)
> 
> diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
> index 17ba1cd90e..61118474b1 100644
> --- a/scripts/tracetool/backend/log.py
> +++ b/scripts/tracetool/backend/log.py
> @@ -39,10 +39,15 @@ def generate_h(event, group):
>          '        if (message_with_timestamp) {',
>          '            struct timeval _now;',
>          '            gettimeofday(&_now, NULL);',
> +        '            time_t _seconds = _now.tv_sec;',
> +        '            struct tm _tm;',
> +        '            gmtime_r(&_seconds, &_tm);',
>          '#line %(event_lineno)d "%(event_filename)s"',
> -        '            qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
> -        '                     qemu_get_thread_id(),',
> -        '                     (size_t)_now.tv_sec, (size_t)_now.tv_usec',
> +        '            qemu_log("%%04d-%%02d-%%02dT%%02d:%%02d:%%02d.%%06ldZ'
> +        ' (%%d) %(name)s " %(fmt)s "\\n",',
> +        '                     _tm.tm_year + 1900, _tm.tm_mon + 1, _tm.tm_mday,',
> +        '                     _tm.tm_hour, _tm.tm_min, _tm.tm_sec, _now.tv_usec,',
> +        '                     qemu_get_thread_id()',
>          '                     %(argnames)s);',

IMHO this is undesirable, as it bloats the QEMU binaries by another 1 MB
as we have an excessive amount of code being inlined in every trace call
location. I've co-incidentally just sent a patch that would fix the same
problem based on a discussion last week about a bug caused by this log
backend adding 'error-report.h' into all files:

  https://lists.nongnu.org/archive/html/qemu-devel/2025-07/msg04905.html

>          '#line %(out_next_lineno)d "%(out_filename)s"',
>          '        } else {',

With 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: [PULL 1/1] trace: log.py: human-readable timestamp

[Stefan Hajnoczi]

On Mon, Jul 21, 2025 at 3:04 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
>
> On Mon, Jul 21, 2025 at 02:10:51PM -0400, Stefan Hajnoczi wrote:
> > From: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
> >
> > So tired to parse all these timestamps, when need to compare them
> > with other logs.
> >
> > Use iso8601 format as in warn_report() (info_report(), error_report())
> > already used.
> >
> > Also, start line with date, to be similar with warn_report() as well.
> >
> > Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru>
> > Message-id: 20250626195514.366177-1-vsementsov@yandex-team.ru
> > Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>
> > ---
> >  scripts/tracetool/backend/log.py | 11 ++++++++---
> >  1 file changed, 8 insertions(+), 3 deletions(-)
> >
> > diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
> > index 17ba1cd90e..61118474b1 100644
> > --- a/scripts/tracetool/backend/log.py
> > +++ b/scripts/tracetool/backend/log.py
> > @@ -39,10 +39,15 @@ def generate_h(event, group):
> >          '        if (message_with_timestamp) {',
> >          '            struct timeval _now;',
> >          '            gettimeofday(&_now, NULL);',
> > +        '            time_t _seconds = _now.tv_sec;',
> > +        '            struct tm _tm;',
> > +        '            gmtime_r(&_seconds, &_tm);',
> >          '#line %(event_lineno)d "%(event_filename)s"',
> > -        '            qemu_log("%%d@%%zu.%%06zu:%(name)s " %(fmt)s "\\n",',
> > -        '                     qemu_get_thread_id(),',
> > -        '                     (size_t)_now.tv_sec, (size_t)_now.tv_usec',
> > +        '            qemu_log("%%04d-%%02d-%%02dT%%02d:%%02d:%%02d.%%06ldZ'
> > +        ' (%%d) %(name)s " %(fmt)s "\\n",',
> > +        '                     _tm.tm_year + 1900, _tm.tm_mon + 1, _tm.tm_mday,',
> > +        '                     _tm.tm_hour, _tm.tm_min, _tm.tm_sec, _now.tv_usec,',
> > +        '                     qemu_get_thread_id()',
> >          '                     %(argnames)s);',
>
> IMHO this is undesirable, as it bloats the QEMU binaries by another 1 MB
> as we have an excessive amount of code being inlined in every trace call
> location. I've co-incidentally just sent a patch that would fix the same
> problem based on a discussion last week about a bug caused by this log
> backend adding 'error-report.h' into all files:
>
>   https://lists.nongnu.org/archive/html/qemu-devel/2025-07/msg04905.html
>
> >          '#line %(out_next_lineno)d "%(out_filename)s"',
> >          '        } else {',

There is also a format string portability issue that CI has just found:
https://gitlab.com/qemu-project/qemu/-/jobs/10761777777#L2294

This patch will need to be reworked.

Stefan

>
> With 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 :|
>
>