Re: [PATCH v6 12/27] 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)

Real code needs to check @f or risk crashing.  Shouldn't we show that
here?

>  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.

qemu_log_trylock()'s lock is recursive.  Worth a comment?  Not sure.

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

Reviewed-by: Markus Armbruster <armbru@redhat.com>