Daniel P. Berrangé <berra...@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é <berra...@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 <arm...@redhat.com>
