Re: [PATCH] utils/log: add qemu_log_timestamp() to encapsulate timestamp logging

[BALATON Zoltan]

On Mon, 9 Jun 2025, BALATON Zoltan wrote:
On Mon, 9 Jun 2025, Tanish Desai wrote:
Moved the logic for timestamped logging (~6 lines) from 
a_nocheck__trace_foo(header) into a new qemu_log_timestamp() function in 
util/log.c. This avoids code duplication across binaries and enables reuse 
as a standalone utility.
Encapsulation helps reduce build size significantly, particularly when many 
trace points are present. On Ubuntu 22 with
./configure --target-list=aarch64-softmmu --enable-kvm 
--enable-trace-backends=log,
this change reduced the build directory size from ~1435.27 MB to ~1412 MB 
(~23 MB saved).
Notable reductions include:
   trace/: ~2.6 MB
   libqemuutil.a.p: ~3 MB
A detailed report of size changes (in bytes) for relevant folders and 
subfolders will follow in a trailing mail.

I think this is inline to avoid overhead of function call at runtime when 
logging is not enabled which is more important than saving build time or disk 
space but I could be wrong.

On second look this keeps the conditon inline only moves the timestamp so 
maybe OK but I'd let others more knowledgeable judge it.

Regards,
BALATON Zoltan

Signed-off-by: Tanish Desai <tanishdesa...@gmail.com>
---
include/qemu/log-for-trace.h     |  3 +++
scripts/tracetool/backend/log.py | 13 +------------
util/log.c                       | 18 ++++++++++++++++++
3 files changed, 22 insertions(+), 12 deletions(-)

diff --git a/include/qemu/log-for-trace.h b/include/qemu/log-for-trace.h
index d47c9cd446..680f30a8a9 100644
--- a/include/qemu/log-for-trace.h
+++ b/include/qemu/log-for-trace.h
@@ -32,4 +32,7 @@ static inline bool qemu_loglevel_mask(int mask)
/* main logging function */
void G_GNUC_PRINTF(1, 2) qemu_log(const char *fmt, ...);

+/* main logging function with timestamp */
+void G_GNUC_PRINTF(1, 2) qemu_log_timestamp(const char *fmt, ...);
+
#endif
diff --git a/scripts/tracetool/backend/log.py 
b/scripts/tracetool/backend/log.py
index de27b7e62e..3358afb43a 100644
--- a/scripts/tracetool/backend/log.py
+++ b/scripts/tracetool/backend/log.py
@@ -38,20 +38,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_timestamp("%(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 b87d399e4c..996530fe7e 100644
--- a/util/log.c
+++ b/util/log.c
@@ -143,6 +143,24 @@ void qemu_log_unlock(FILE *logfile)
    }
}

+
+void qemu_log_timestamp(const char *fmt, ...)
+{
+    FILE *f = qemu_log_trylock();
+    if (f) {
+        va_list ap;
+        if(message_with_timestamp){
+            struct timeval _now;
+            gettimeofday(&_now, NULL);
+ 
fprintf(f,"%d@%zu.%06zu:",qemu_get_thread_id(),(size_t)_now.tv_sec, 
(size_t)_now.tv_usec);
+        }
+        va_start(ap, fmt);
+        vfprintf(f, fmt, ap);
+        va_end(ap);
+    }
+    qemu_log_unlock(f);
+}
+
void qemu_log(const char *fmt, ...)
{
    FILE *f = qemu_log_trylock();