[PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[Daniel P. Berrangé]

Currently the tracing 'log' back emits special code to add timestamps
to trace points sent via qemu_log(). This current impl is a bad design
for a number of reasons.

 * It changes the QEMU headers, such that 'error-report.h' content
   is visible to all files using tracing, but only when the 'log'
   backend is enabled. This has led to build failure bugs as devs
   rarely test without the (default) 'log' backend enabled, and
   CI can't cover every scenario for every trace backend.

 * It bloats the trace points definitions which are inlined into
   every probe location due to repeated inlining of timestamp
   formatting code, adding MBs of overhead to QEMU.

 * The tracing subsystem should not be treated any differently
   from other users of qemu_log. They all would benefit from
   having timestamps present.

 * The timestamp emitted with the tracepoints is in a needlessly
   different format to that used by error_report() in response
   to '-msg timestamp=on'.

This fixes all these issues simply by moving timestamp formatting
into qemu_log, using the same approach as for error_report.

The code before:

  static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
  {
      if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
          if (message_with_timestamp) {
              struct timeval _now;
              gettimeofday(&_now, NULL);
              qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
                       qemu_get_thread_id(),
                       (size_t)_now.tv_sec, (size_t)_now.tv_usec
                       , creds, filename, path);
          } else {
              qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
          }
      }
  }

and after:

  static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
  {
      if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
          qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
      }
  }

The log and error messages before:

  $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
  2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
  2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
  2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory

and after:

  $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
  2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
  2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
  2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory

The binary size before:

  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
  $ strip qemu-system-x86_64
  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64

and after:

  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
  $ strip qemu-system-x86_64
  $ ls -alh qemu-system-x86_64
  -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
---
 scripts/tracetool/backend/log.py | 14 +-------------
 util/log.c                       | 20 +++++++++++++++++++-
 2 files changed, 20 insertions(+), 14 deletions(-)

diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index 17ba1cd90e..bd6739ae41 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -20,7 +20,6 @@
 
 def generate_h_begin(events, group):
     out('#include "qemu/log-for-trace.h"',
-        '#include "qemu/error-report.h"',
         '')
 
 
@@ -36,20 +35,9 @@ def generate_h(event, group):
         cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
 
     out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
-        '        if (message_with_timestamp) {',
-        '            struct timeval _now;',
-        '            gettimeofday(&_now, NULL);',
         '#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',
-        '                     %(argnames)s);',
+        '        qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
         '#line %(out_next_lineno)d "%(out_filename)s"',
-        '        } else {',
-        '#line %(event_lineno)d "%(event_filename)s"',
-        '            qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
-        '#line %(out_next_lineno)d "%(out_filename)s"',
-        '        }',
         '    }',
         cond=cond,
         event_lineno=event.lineno,
diff --git a/util/log.c b/util/log.c
index 58d24de48a..abdcb6b311 100644
--- a/util/log.c
+++ b/util/log.c
@@ -145,10 +145,28 @@ void qemu_log_unlock(FILE *logfile)
 
 void qemu_log(const char *fmt, ...)
 {
-    FILE *f = qemu_log_trylock();
+    FILE *f;
+    g_autofree const char *timestr = NULL;
+
+    /*
+     * Prepare the timestamp *outside* the logging
+     * lock so it better reflects when the message
+     * was emitted if we are delayed acquiring the
+     * mutex
+     */
+    if (message_with_timestamp) {
+        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
+        timestr = g_date_time_format_iso8601(dt);
+    }
+
+    f = qemu_log_trylock();
     if (f) {
         va_list ap;
 
+        if (timestr) {
+            fprintf(f, "%s ", timestr);
+        }
+
         va_start(ap, fmt);
         vfprintf(f, fmt, ap);
         va_end(ap);
-- 
2.50.1

Re: [PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[Stefan Hajnoczi]

On Mon, Jul 21, 2025 at 2:58 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
>
> Currently the tracing 'log' back emits special code to add timestamps
> to trace points sent via qemu_log(). This current impl is a bad design
> for a number of reasons.
>
>  * It changes the QEMU headers, such that 'error-report.h' content
>    is visible to all files using tracing, but only when the 'log'
>    backend is enabled. This has led to build failure bugs as devs
>    rarely test without the (default) 'log' backend enabled, and
>    CI can't cover every scenario for every trace backend.
>
>  * It bloats the trace points definitions which are inlined into
>    every probe location due to repeated inlining of timestamp
>    formatting code, adding MBs of overhead to QEMU.
>
>  * The tracing subsystem should not be treated any differently
>    from other users of qemu_log. They all would benefit from
>    having timestamps present.
>
>  * The timestamp emitted with the tracepoints is in a needlessly
>    different format to that used by error_report() in response
>    to '-msg timestamp=on'.
>
> This fixes all these issues simply by moving timestamp formatting
> into qemu_log, using the same approach as for error_report.
>
> The code before:
>
>   static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>   {
>       if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>           if (message_with_timestamp) {
>               struct timeval _now;
>               gettimeofday(&_now, NULL);
>               qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
>                        qemu_get_thread_id(),
>                        (size_t)_now.tv_sec, (size_t)_now.tv_usec
>                        , creds, filename, path);
>           } else {
>               qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>           }
>       }
>   }
>
> and after:
>
>   static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>   {
>       if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>           qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>       }
>   }
>
> The log and error messages before:
>
>   $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>   2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
>   2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
>   2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
>
> and after:
>
>   $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>   2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
>   2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
>   2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory

This does what Vladimir's patch did but also reduces the binary size
and solves the #include pollution. I'll treat this as a replacement
for Vladimir's patch.

Vladimir: Please let me know if anything is missing from this patch.

>
> The binary size before:
>
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
>   $ strip qemu-system-x86_64
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64
>
> and after:
>
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
>   $ strip qemu-system-x86_64
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64
>
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  scripts/tracetool/backend/log.py | 14 +-------------
>  util/log.c                       | 20 +++++++++++++++++++-
>  2 files changed, 20 insertions(+), 14 deletions(-)
>
> diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
> index 17ba1cd90e..bd6739ae41 100644
> --- a/scripts/tracetool/backend/log.py
> +++ b/scripts/tracetool/backend/log.py
> @@ -20,7 +20,6 @@
>
>  def generate_h_begin(events, group):
>      out('#include "qemu/log-for-trace.h"',
> -        '#include "qemu/error-report.h"',
>          '')
>
>
> @@ -36,20 +35,9 @@ def generate_h(event, group):
>          cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
>
>      out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
> -        '        if (message_with_timestamp) {',
> -        '            struct timeval _now;',
> -        '            gettimeofday(&_now, NULL);',
>          '#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',
> -        '                     %(argnames)s);',
> +        '        qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
>          '#line %(out_next_lineno)d "%(out_filename)s"',
> -        '        } else {',
> -        '#line %(event_lineno)d "%(event_filename)s"',
> -        '            qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
> -        '#line %(out_next_lineno)d "%(out_filename)s"',
> -        '        }',
>          '    }',
>          cond=cond,
>          event_lineno=event.lineno,
> diff --git a/util/log.c b/util/log.c
> index 58d24de48a..abdcb6b311 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -145,10 +145,28 @@ void qemu_log_unlock(FILE *logfile)
>
>  void qemu_log(const char *fmt, ...)
>  {
> -    FILE *f = qemu_log_trylock();
> +    FILE *f;
> +    g_autofree const char *timestr = NULL;
> +
> +    /*
> +     * Prepare the timestamp *outside* the logging
> +     * lock so it better reflects when the message
> +     * was emitted if we are delayed acquiring the
> +     * mutex
> +     */
> +    if (message_with_timestamp) {
> +        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> +        timestr = g_date_time_format_iso8601(dt);
> +    }
> +
> +    f = qemu_log_trylock();
>      if (f) {
>          va_list ap;
>
> +        if (timestr) {
> +            fprintf(f, "%s ", timestr);
> +        }
> +
>          va_start(ap, fmt);
>          vfprintf(f, fmt, ap);
>          va_end(ap);
> --
> 2.50.1
>
>

Re: [PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[Markus Armbruster]

Daniel P. Berrangé <berrange@redhat.com> writes:

> Currently the tracing 'log' back emits special code to add timestamps
> to trace points sent via qemu_log(). This current impl is a bad design
> for a number of reasons.
>
>  * It changes the QEMU headers, such that 'error-report.h' content
>    is visible to all files using tracing, but only when the 'log'
>    backend is enabled. This has led to build failure bugs as devs
>    rarely test without the (default) 'log' backend enabled, and
>    CI can't cover every scenario for every trace backend.
>
>  * It bloats the trace points definitions which are inlined into
>    every probe location due to repeated inlining of timestamp
>    formatting code, adding MBs of overhead to QEMU.
>
>  * The tracing subsystem should not be treated any differently
>    from other users of qemu_log. They all would benefit from
>    having timestamps present.
>
>  * The timestamp emitted with the tracepoints is in a needlessly
>    different format to that used by error_report() in response
>    to '-msg timestamp=on'.
>
> This fixes all these issues simply by moving timestamp formatting
> into qemu_log, using the same approach as for error_report.
>
> The code before:
>
>   static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>   {
>       if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>           if (message_with_timestamp) {
>               struct timeval _now;
>               gettimeofday(&_now, NULL);
>               qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
>                        qemu_get_thread_id(),
>                        (size_t)_now.tv_sec, (size_t)_now.tv_usec
>                        , creds, filename, path);
>           } else {
>               qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>           }
>       }
>   }
>
> and after:
>
>   static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>   {
>       if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>           qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>       }
>   }
>
> The log and error messages before:
>
>   $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>   2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
>   2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
>   2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
>
> and after:
>
>   $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>   2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
>   2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
>   2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
>
> The binary size before:
>
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
>   $ strip qemu-system-x86_64
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64
>
> and after:
>
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
>   $ strip qemu-system-x86_64
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64
>
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  scripts/tracetool/backend/log.py | 14 +-------------
>  util/log.c                       | 20 +++++++++++++++++++-
>  2 files changed, 20 insertions(+), 14 deletions(-)
>
> diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
> index 17ba1cd90e..bd6739ae41 100644
> --- a/scripts/tracetool/backend/log.py
> +++ b/scripts/tracetool/backend/log.py
> @@ -20,7 +20,6 @@
>  
>  def generate_h_begin(events, group):
>      out('#include "qemu/log-for-trace.h"',
> -        '#include "qemu/error-report.h"',
>          '')
>  
>  
> @@ -36,20 +35,9 @@ def generate_h(event, group):
>          cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
>  
>      out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
> -        '        if (message_with_timestamp) {',
> -        '            struct timeval _now;',
> -        '            gettimeofday(&_now, NULL);',
>          '#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',
> -        '                     %(argnames)s);',
> +        '        qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
>          '#line %(out_next_lineno)d "%(out_filename)s"',
> -        '        } else {',
> -        '#line %(event_lineno)d "%(event_filename)s"',
> -        '            qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
> -        '#line %(out_next_lineno)d "%(out_filename)s"',
> -        '        }',
>          '    }',
>          cond=cond,
>          event_lineno=event.lineno,
> diff --git a/util/log.c b/util/log.c
> index 58d24de48a..abdcb6b311 100644
> --- a/util/log.c
> +++ b/util/log.c
> @@ -145,10 +145,28 @@ void qemu_log_unlock(FILE *logfile)
>  
>  void qemu_log(const char *fmt, ...)
>  {
> -    FILE *f = qemu_log_trylock();
> +    FILE *f;
> +    g_autofree const char *timestr = NULL;
> +
> +    /*
> +     * Prepare the timestamp *outside* the logging
> +     * lock so it better reflects when the message
> +     * was emitted if we are delayed acquiring the
> +     * mutex
> +     */
> +    if (message_with_timestamp) {
> +        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
> +        timestr = g_date_time_format_iso8601(dt);
> +    }

Duplicates real_time_iso8601() from error-report.c.  Tolerable.

> +
> +    f = qemu_log_trylock();
>      if (f) {
>          va_list ap;
>  
> +        if (timestr) {
> +            fprintf(f, "%s ", timestr);
> +        }
> +
>          va_start(ap, fmt);
>          vfprintf(f, fmt, ap);
>          va_end(ap);

Reviewed-by: Markus Armbruster <armbru@redhat.com>

Re: [PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[Vladimir Sementsov-Ogievskiy]

On 21.07.25 23:22, Stefan Hajnoczi wrote:
> On Mon, Jul 21, 2025 at 2:58 PM Daniel P. Berrangé <berrange@redhat.com> wrote:
>>
>> Currently the tracing 'log' back emits special code to add timestamps
>> to trace points sent via qemu_log(). This current impl is a bad design
>> for a number of reasons.
>>
>>   * It changes the QEMU headers, such that 'error-report.h' content
>>     is visible to all files using tracing, but only when the 'log'
>>     backend is enabled. This has led to build failure bugs as devs
>>     rarely test without the (default) 'log' backend enabled, and
>>     CI can't cover every scenario for every trace backend.
>>
>>   * It bloats the trace points definitions which are inlined into
>>     every probe location due to repeated inlining of timestamp
>>     formatting code, adding MBs of overhead to QEMU.
>>
>>   * The tracing subsystem should not be treated any differently
>>     from other users of qemu_log. They all would benefit from
>>     having timestamps present.
>>
>>   * The timestamp emitted with the tracepoints is in a needlessly
>>     different format to that used by error_report() in response
>>     to '-msg timestamp=on'.
>>
>> This fixes all these issues simply by moving timestamp formatting
>> into qemu_log, using the same approach as for error_report.
>>
>> The code before:
>>
>>    static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>>    {
>>        if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>>            if (message_with_timestamp) {
>>                struct timeval _now;
>>                gettimeofday(&_now, NULL);
>>                qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
>>                         qemu_get_thread_id(),
>>                         (size_t)_now.tv_sec, (size_t)_now.tv_usec
>>                         , creds, filename, path);
>>            } else {
>>                qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>>            }
>>        }
>>    }
>>
>> and after:
>>
>>    static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>>    {
>>        if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>>            qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>>        }
>>    }
>>
>> The log and error messages before:
>>
>>    $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>>    2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
>>    2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
>>    2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
>>
>> and after:
>>
>>    $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>>    2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
>>    2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
>>    2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
> 
> This does what Vladimir's patch did but also reduces the binary size
> and solves the #include pollution. I'll treat this as a replacement
> for Vladimir's patch.

Great, I agree.

> 
> Vladimir: Please let me know if anything is missing from this patch.
> 
>>
>> The binary size before:
>>
>>    $ ls -alh qemu-system-x86_64
>>    -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
>>    $ strip qemu-system-x86_64
>>    $ ls -alh qemu-system-x86_64
>>    -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64
>>
>> and after:
>>
>>    $ ls -alh qemu-system-x86_64
>>    -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
>>    $ strip qemu-system-x86_64
>>    $ ls -alh qemu-system-x86_64
>>    -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64
>>
>> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>> ---
>>   scripts/tracetool/backend/log.py | 14 +-------------
>>   util/log.c                       | 20 +++++++++++++++++++-
>>   2 files changed, 20 insertions(+), 14 deletions(-)
>>
>> diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
>> index 17ba1cd90e..bd6739ae41 100644
>> --- a/scripts/tracetool/backend/log.py
>> +++ b/scripts/tracetool/backend/log.py
>> @@ -20,7 +20,6 @@
>>
>>   def generate_h_begin(events, group):
>>       out('#include "qemu/log-for-trace.h"',
>> -        '#include "qemu/error-report.h"',
>>           '')
>>
>>
>> @@ -36,20 +35,9 @@ def generate_h(event, group):
>>           cond = "trace_event_get_state(%s)" % ("TRACE_" + event.name.upper())
>>
>>       out('    if (%(cond)s && qemu_loglevel_mask(LOG_TRACE)) {',
>> -        '        if (message_with_timestamp) {',
>> -        '            struct timeval _now;',
>> -        '            gettimeofday(&_now, NULL);',
>>           '#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',
>> -        '                     %(argnames)s);',
>> +        '        qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
>>           '#line %(out_next_lineno)d "%(out_filename)s"',
>> -        '        } else {',
>> -        '#line %(event_lineno)d "%(event_filename)s"',
>> -        '            qemu_log("%(name)s " %(fmt)s "\\n"%(argnames)s);',
>> -        '#line %(out_next_lineno)d "%(out_filename)s"',
>> -        '        }',
>>           '    }',
>>           cond=cond,
>>           event_lineno=event.lineno,
>> diff --git a/util/log.c b/util/log.c
>> index 58d24de48a..abdcb6b311 100644
>> --- a/util/log.c
>> +++ b/util/log.c
>> @@ -145,10 +145,28 @@ void qemu_log_unlock(FILE *logfile)
>>
>>   void qemu_log(const char *fmt, ...)
>>   {
>> -    FILE *f = qemu_log_trylock();
>> +    FILE *f;
>> +    g_autofree const char *timestr = NULL;
>> +
>> +    /*
>> +     * Prepare the timestamp *outside* the logging
>> +     * lock so it better reflects when the message
>> +     * was emitted if we are delayed acquiring the
>> +     * mutex
>> +     */
>> +    if (message_with_timestamp) {
>> +        g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
>> +        timestr = g_date_time_format_iso8601(dt);
>> +    }
>> +
>> +    f = qemu_log_trylock();
>>       if (f) {
>>           va_list ap;
>>
>> +        if (timestr) {
>> +            fprintf(f, "%s ", timestr);
>> +        }
>> +
>>           va_start(ap, fmt);
>>           vfprintf(f, fmt, ap);
>>           va_end(ap);
>> --
>> 2.50.1
>>
>>

-- 
Best regards,
Vladimir

Re: [PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[Vladimir Sementsov-Ogievskiy]

On 21.07.25 21:54, Daniel P. Berrangé wrote:
> Currently the tracing 'log' back emits special code to add timestamps
> to trace points sent via qemu_log(). This current impl is a bad design
> for a number of reasons.
> 
>   * It changes the QEMU headers, such that 'error-report.h' content
>     is visible to all files using tracing, but only when the 'log'
>     backend is enabled. This has led to build failure bugs as devs
>     rarely test without the (default) 'log' backend enabled, and
>     CI can't cover every scenario for every trace backend.
> 
>   * It bloats the trace points definitions which are inlined into
>     every probe location due to repeated inlining of timestamp
>     formatting code, adding MBs of overhead to QEMU.
> 
>   * The tracing subsystem should not be treated any differently
>     from other users of qemu_log. They all would benefit from
>     having timestamps present.
> 
>   * The timestamp emitted with the tracepoints is in a needlessly
>     different format to that used by error_report() in response
>     to '-msg timestamp=on'.
> 
> This fixes all these issues simply by moving timestamp formatting
> into qemu_log, using the same approach as for error_report.
> 
> The code before:
> 
>    static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>    {
>        if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>            if (message_with_timestamp) {
>                struct timeval _now;
>                gettimeofday(&_now, NULL);
>                qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path "  "TLS creds path creds=%p filename=%s path=%s" "\n",
>                         qemu_get_thread_id(),
>                         (size_t)_now.tv_sec, (size_t)_now.tv_usec
>                         , creds, filename, path);
>            } else {
>                qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>            }
>        }
>    }
> 
> and after:
> 
>    static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>    {
>        if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>            qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>        }
>    }
> 
> The log and error messages before:
> 
>    $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>    2986097@1753122905.917608:qcrypto_tls_creds_x509_load  TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
>    2986097@1753122905.917621:qcrypto_tls_creds_get_path
>   TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem
> path=<none>
>    2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access
> credentials /var/home/berrange/tls/ca-cert.pem: No such file or
> directory
> 
> and after:
> 
>    $ qemu-system-x86_64 -trace qcrypto* -object
> tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>    2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509
>   load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
>    2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path
> creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
>    2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access
> credentials /var/home/berrange/tls/ca-cert.pem: No such file or
> directory
> 
> The binary size before:
> 
>    $ ls -alh qemu-system-x86_64
>    -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
>    $ strip qemu-system-x86_64
>    $ ls -alh qemu-system-x86_64
>    -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64
> 
> and after:
> 
>    $ ls -alh qemu-system-x86_64
>    -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
>    $ strip qemu-system-x86_64
>    $ ls -alh qemu-system-x86_64
>    -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64
> 
> Signed-off-by: Daniel P. Berrangé<berrange@redhat.com>

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

-- 
Best regards,
Vladimir

Re: [PATCH] log: make '-msg timestamp=on' apply to all qemu_log usage

[Stefan Hajnoczi]

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

On Mon, Jul 21, 2025 at 07:54:52PM +0100, Daniel P. Berrangé wrote:
> Currently the tracing 'log' back emits special code to add timestamps
> to trace points sent via qemu_log(). This current impl is a bad design
> for a number of reasons.
> 
>  * It changes the QEMU headers, such that 'error-report.h' content
>    is visible to all files using tracing, but only when the 'log'
>    backend is enabled. This has led to build failure bugs as devs
>    rarely test without the (default) 'log' backend enabled, and
>    CI can't cover every scenario for every trace backend.
> 
>  * It bloats the trace points definitions which are inlined into
>    every probe location due to repeated inlining of timestamp
>    formatting code, adding MBs of overhead to QEMU.
> 
>  * The tracing subsystem should not be treated any differently
>    from other users of qemu_log. They all would benefit from
>    having timestamps present.
> 
>  * The timestamp emitted with the tracepoints is in a needlessly
>    different format to that used by error_report() in response
>    to '-msg timestamp=on'.
> 
> This fixes all these issues simply by moving timestamp formatting
> into qemu_log, using the same approach as for error_report.
> 
> The code before:
> 
>   static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>   {
>       if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>           if (message_with_timestamp) {
>               struct timeval _now;
>               gettimeofday(&_now, NULL);
>               qemu_log("%d@%zu.%06zu:qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n",
>                        qemu_get_thread_id(),
>                        (size_t)_now.tv_sec, (size_t)_now.tv_usec
>                        , creds, filename, path);
>           } else {
>               qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>           }
>       }
>   }
> 
> and after:
> 
>   static inline void _nocheck__trace_qcrypto_tls_creds_get_path(void * creds, const char * filename, const char * path)
>   {
>       if (trace_event_get_state(TRACE_QCRYPTO_TLS_CREDS_GET_PATH) && qemu_loglevel_mask(LOG_TRACE)) {
>           qemu_log("qcrypto_tls_creds_get_path " "TLS creds path creds=%p filename=%s path=%s" "\n", creds, filename, path);
>       }
>   }
> 
> The log and error messages before:
> 
>   $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>   2986097@1753122905.917608:qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55d925bd9490 dir=/var/home/berrange/tls
>   2986097@1753122905.917621:qcrypto_tls_creds_get_path TLS creds path creds=0x55d925bd9490 filename=ca-cert.pem path=<none>
>   2025-07-21T18:35:05.917626Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
> 
> and after:
> 
>   $ qemu-system-x86_64 -trace qcrypto* -object tls-creds-x509,id=tls0,dir=$HOME/tls -msg timestamp=on
>   2025-07-21T18:43:28.089797Z qcrypto_tls_creds_x509_load TLS creds x509 load creds=0x55bf5bf12380 dir=/var/home/berrange/tls
>   2025-07-21T18:43:28.089815Z qcrypto_tls_creds_get_path TLS creds path creds=0x55bf5bf12380 filename=ca-cert.pem path=<none>
>   2025-07-21T18:43:28.089819Z qemu-system-x86_64: Unable to access credentials /var/home/berrange/tls/ca-cert.pem: No such file or directory
> 
> The binary size before:
> 
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 87M Jul 21 19:39 qemu-system-x86_64
>   $ strip qemu-system-x86_64
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 30M Jul 21 19:39 qemu-system-x86_64
> 
> and after:
> 
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 85M Jul 21 19:41 qemu-system-x86_64
>   $ strip qemu-system-x86_64
>   $ ls -alh qemu-system-x86_64
>   -rwxr-xr-x. 1 berrange berrange 29M Jul 21 19:41 qemu-system-x86_64
> 
> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> ---
>  scripts/tracetool/backend/log.py | 14 +-------------
>  util/log.c                       | 20 +++++++++++++++++++-
>  2 files changed, 20 insertions(+), 14 deletions(-)

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 --]