Merge tag 'tracing-pull-request' of https://gitlab.com/stefanha/qemu into staging

Pull request

This commit is still worth having in QEMU 10.1 for the all-round improvements
made (consistent timestamping, binary size reduction, header pollution cleanup)
even if it's debatable whether this is a bug fix.

# -----BEGIN PGP SIGNATURE-----
#
# iQEzBAABCgAdFiEEhpWov9P5fNqsNXdanKSrs4Grc8gFAmiCR0UACgkQnKSrs4Gr
# c8g4AggAyBo1oNAVSMQIC6JRRcLrVBCWGPWVyU1/3AaayKLy8egs1pImmT09DcdQ
# D2CHCjEp0xbTzFlN3YiBymAOeq/a73G7NPzWdCi/PY1qBmB4td8Eli/tBoQUYvmE
# k0a0r6DrOo6vGddCqv6fAKnvamcs/IB2ogzpqLVLCC4oAP6TVG0LeHsaqTAtO8bv
# yZb+1YQxFZtum2yp9I4+mk8c1R04cCdDL17TRCrv4hTkpGRYfaDs8LRy5yJ4Nw6V
# AID3fkLTaxOcQpb2EItfcoGalF/JcCdZoOlJ/91clJ1MWFAnV9Y9gBZtlSF4dx+k
# c2rTlcBw9j402imuotLOP7Cl8mLNeg==
# =lXaI
# -----END PGP SIGNATURE-----
# gpg: Signature made Thu 24 Jul 2025 10:46:29 EDT
# gpg:                using RSA key 8695A8BFD3F97CDAAC35775A9CA4ABB381AB73C8
# gpg: Good signature from "Stefan Hajnoczi <stefanha@redhat.com>" [ultimate]
# gpg:                 aka "Stefan Hajnoczi <stefanha@gmail.com>" [ultimate]
# Primary key fingerprint: 8695 A8BF D3F9 7CDA AC35  775A 9CA4 ABB3 81AB 73C8

* tag 'tracing-pull-request' of https://gitlab.com/stefanha/qemu:
  log: make '-msg timestamp=on' apply to all qemu_log usage

Signed-off-by: Stefan Hajnoczi <stefanha@redhat.com>

2 files changed, 20 insertions, 14 deletions

diff --git a/scripts/tracetool/backend/log.py b/scripts/tracetool/backend/log.py
index 5c9d09d..eb50cee 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -20,7 +20,6 @@ PUBLIC = True
 
 def generate_h_begin(events, group):
     out('#include "qemu/log-for-trace.h"',
-        '#include "qemu/error-report.h"',
         '')
 
 
@@ -32,20 +31,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 58d24de..abdcb6b 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);