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

[Markus Armbruster <armbru@redhat.com>]

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>