[PATCH v5 10/24] util: avoid repeated prefix on incremental qemu_log calls

["Daniel P. Berrangé" <berrange@redhat.com>]

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>
---
 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;
+
 /**
  * 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)
     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();
+    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);
+    }
+    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);
-- 
2.52.0