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

[Markus Armbruster <armbru@redhat.com>]

Daniel P. Berrangé <berrange@redhat.com> 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 <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;

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);