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>