Daniel P. Berrangé <[email protected]> writes: > 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.
I dislike pattern (3), but not nearly enough to chase it out of the tree myself. Hard to disagree with this patch then :) > Fixes: 012842c07552 (log: make '-msg timestamp=on' apply to all qemu_log > usage) > Reported-by: Richard Henderson <[email protected]> > Signed-off-by: Daniel P. Berrangé <[email protected]> > --- > include/qemu/log.h | 7 +++++++ > util/log.c | 49 ++++++++++++++++++++++++++-------------------- > 2 files changed, 35 insertions(+), 21 deletions(-) > > diff --git a/include/qemu/log.h b/include/qemu/log.h > index e9d3c6806b..95f417c2b7 100644 > --- a/include/qemu/log.h > +++ b/include/qemu/log.h > @@ -69,6 +69,13 @@ bool qemu_log_separate(void); > */ > FILE *qemu_log_trylock(void) G_GNUC_WARN_UNUSED_RESULT; > > +/** > + * As qemu_log_trylock(), but will also print the message > + * context, if any is configured and this caused the > + * acquisition of the FILE lock > + */ > +FILE *qemu_log_trylock_context(void) G_GNUC_WARN_UNUSED_RESULT; This is used just once, in qemu_log(). Could be inlined into qemu_log(). If you prefer to keep it as a function, you could make it static. I wouldn't guess that this prints from the function name. Dunno, qemu_log_start_line()? Might want to pair it with a qemu_log_end_line() then. Telling function name is less important if it's static. > + > /** > * Releases the lock on the log output, previously > * acquired by qemu_log_trylock(). > diff --git a/util/log.c b/util/log.c > index c44d66b5ce..2ce7286f31 100644 > --- a/util/log.c > +++ b/util/log.c > @@ -127,13 +127,39 @@ static FILE *qemu_log_trylock_with_err(Error **errp) Not this patch's fault, but here goes anyway: static FILE *qemu_log_trylock_with_err(Error **errp) { FILE *logfile; logfile = thread_file; if (!logfile) { if (log_per_thread) { g_autofree char *filename = g_strdup_printf(global_filename, log_thread_id()); logfile = fopen(filename, "w"); if (!logfile) { error_setg_errno(errp, errno, "Error opening logfile %s for thread %d", filename, log_thread_id()); return NULL; } thread_file = logfile; qemu_log_thread_cleanup_notifier.notify = qemu_log_thread_cleanup; qemu_thread_atexit_add(&qemu_log_thread_cleanup_notifier); } else { rcu_read_lock(); /* * FIXME: typeof_strip_qual, as used by qatomic_rcu_read, * does not work with pointers to undefined structures, * such as we have with struct _IO_FILE and musl libc. * Since all we want is a read of a pointer, cast to void**, * which does work with typeof_strip_qual. */ logfile = qatomic_rcu_read((void **)&global_file); if (!logfile) { rcu_read_unlock(); return NULL; Fails without setting @errp. } } } qemu_flockfile(logfile); > return logfile; > } > > +/* > + * Zero if there's been no opening qemu_log_trylock call, > + * indicating the need for message context to be emitted > + * > + * Non-zero if we're in the middle of printing a message, > + * possibly over multiple lines and must skip further > + * message context > + */ > +static __thread uint log_depth; > + > FILE *qemu_log_trylock(void) > { > - return qemu_log_trylock_with_err(NULL); > + FILE *f = qemu_log_trylock_with_err(NULL); > + log_depth++; > + return f; > +} > + > +FILE *qemu_log_trylock_context(void) > +{ > + FILE *f = qemu_log_trylock(); This can fail, and if it does... > + if (log_depth == 1 && message_with_timestamp) { > + g_autofree const char *timestr = NULL; > + g_autoptr(GDateTime) dt = g_date_time_new_now_utc(); > + timestr = g_date_time_format_iso8601(dt); > + fprintf(f, "%s ", timestr); ... we crash here. > + } > + return f; > } > > void qemu_log_unlock(FILE *logfile) > { > + assert(log_depth); > + log_depth--; > if (logfile) { > fflush(logfile); > qemu_funlockfile(logfile); > @@ -145,28 +171,9 @@ void qemu_log_unlock(FILE *logfile) > > void qemu_log(const char *fmt, ...) > { > - 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(); > + FILE *f = qemu_log_trylock_context(); > if (f) { > va_list ap; > - > - if (timestr) { > - fprintf(f, "%s ", timestr); > - } > - > va_start(ap, fmt); > vfprintf(f, fmt, ap); > va_end(ap);
