@samitouri / QOSamiQemu / commits / 338f63e5f0

util: avoid repeated prefix on incremental qemu_log calls

There are three general patterns to QEMU log output 1. Single complete message calls qemu_log("Some message\n"); 2. Direct use of fprintf FILE *f = qemu_log_trylock() fprintf(f, "..."); fprintf(f, "..."); fprintf(f, "...\n"); qemu_log_unlock(f) 3. Mixed use of qemu_log_trylock/qemu_log() FILE *f = qemu_log_trylock() qemu_log("...."); qemu_log("...."); qemu_log("....\n"); qemu_log_unlock(f) When message prefixes are enabled, the timestamp will be unconditionally emitted for all qemu_log() calls. This works fine in the 1st case, and has no effect in the 2nd case. In the 3rd case, however, we get the timestamp printed over & over in each fragment. One can suggest that pattern (3) is pointless as it is functionally identical to (2) but with extra indirection and overhead. None the less we have a fair bit of code that does this. The qemu_log() call itself is nothing more than a wrapper which does pattern (2) with a single fprintf() call. One might question whether (2) should include the message prefix in the same way that (1), but there are scenarios where this could be inappropriate / unhelpful such as the CPU register dumps or linux-user strace output. This patch fixes the problem in pattern (3) by keeping track of the call depth of qemu_log_trylock() and then only emitting the the prefix when the starting depth was zero. In doing this qemu_log_trylock_context() is also introduced as a variant of qemu_log_trylock() that emits the prefix. Callers doing to batch output can thus choose whether a prefix is appropriate or not. Fixes: 012842c07552 (log: make '-msg timestamp=on' apply to all qemu_log usage) Reported-by: Richard Henderson <richard.henderson@linaro.org> Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>

Daniel P. Berrangé committed Aug 29, 2025 at 17:04 UTC 338f63e5f0eac0b85988769f213c2edec6d13e2d
2 files changed +35 -21
include/qemu/log.h
+7
@@ -70,6 +70,13 @@ bool qemu_log_separate(void);
70 */
71 FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT;
72
73 +/**
74 + * As qemu_log_trylock(), but will also print the message
75 + * context, if any is configured and this caused the
76 + * acquisition of the FILE lock
77 + */
78 +FILE *qemu_log_trylock_with_context(void) G_GNUC_WARN_UNUSED_RESULT;
79 +
80 /**
81 * Releases the lock on the log output, previously
82 * acquired by qemu_log_trylock().
util/log.c
+28 -21
@@ -127,13 +127,39 @@ static FILE *qemu_log_trylock_with_err(Error **errp)
127 return logfile;
128 }
129
130 +/*
131 + * Zero if there's been no opening qemu_log_trylock call,
132 + * indicating the need for message context to be emitted
133 + *
134 + * Non-zero if we're in the middle of printing a message,
135 + * possibly over multiple lines and must skip further
136 + * message context
137 + */
138 +static __thread unsigned int log_depth;
139 +
140 FILE *qemu_log_trylock(void)
141 {
132 - return qemu_log_trylock_with_err(NULL);
142 + FILE *f = qemu_log_trylock_with_err(NULL);
143 + log_depth++;
144 + return f;
145 +}
146 +
147 +FILE *qemu_log_trylock_with_context(void)
148 +{
149 + FILE *f = qemu_log_trylock();
150 + if (f && log_depth == 1 && message_with_timestamp) {
151 + g_autofree const char *timestr = NULL;
152 + g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
153 + timestr = g_date_time_format_iso8601(dt);
154 + fprintf(f, "%s ", timestr);
155 + }
156 + return f;
157 }
158
159 void qemu_log_unlock(FILE *logfile)
160 {
161 + assert(log_depth);
162 + log_depth--;
163 if (logfile) {
164 fflush(logfile);
165 qemu_funlockfile(logfile);
@@ -145,28 +171,9 @@ void qemu_log_unlock(FILE *logfile)
171
172 void qemu_log(const char *fmt, ...)
173 {
148 - FILE *f;
149 - g_autofree const char *timestr = NULL;
150 -
151 - /*
152 - * Prepare the timestamp *outside* the logging
153 - * lock so it better reflects when the message
154 - * was emitted if we are delayed acquiring the
155 - * mutex
156 - */
157 - if (message_with_timestamp) {
158 - g_autoptr(GDateTime) dt = g_date_time_new_now_utc();
159 - timestr = g_date_time_format_iso8601(dt);
160 - }
161 -
162 - f = qemu_log_trylock();
174 + FILE *f = qemu_log_trylock_with_context();
175 if (f) {
176 va_list ap;
165 -
166 - if (timestr) {
167 - fprintf(f, "%s ", timestr);
168 - }
169 -
177 va_start(ap, fmt);
178 vfprintf(f, fmt, ap);
179 va_end(ap);