Re: [PATCH 2/2] util/log: add timestamp to logs via qemu_log()

[Richard Henderson]

On 8/30/22 04:09, Markus Armbruster wrote:
> Dongli Zhang <dongli.zhang@oracle.com> writes:
>
> > The qemu_log is very helpful for diagnostic. Add the timestamp to the log
> > when it is enabled (e.g., "-msg timestamp=on").
> >
> > While there are many other places that may print to log file, this patch is
> > only for qemu_log(), e.g., the developer may add qemu_log/qemu_log_mask to
> > selected locations to diagnose QEMU issue.
>
> Opinions on the new feature, anyone?
>
> > Cc: Joe Jin <joe.jin@oracle.com>
> > Signed-off-by: Dongli Zhang <dongli.zhang@oracle.com>
> > ---
> > Please let me know if we should use 'error_with_guestname' as well.
> >
> >   util/log.c | 7 +++++++
> >   1 file changed, 7 insertions(+)
> >
> > diff --git a/util/log.c b/util/log.c
> > index d6eb037..f0a081a 100644
> > --- a/util/log.c
> > +++ b/util/log.c
> > @@ -129,8 +129,15 @@ void qemu_log(const char *fmt, ...)
> >   {
> >       FILE *f = qemu_log_trylock();
> >       if (f) {
> > +        gchar *timestr;
> >           va_list ap;
> >   
> > +        if (message_with_timestamp) {
> > +            timestr = real_time_iso8601();
> > +            fprintf(f, "%s ", timestr);
> > +            g_free(timestr);
> > +        }
> > +
> >           va_start(ap, fmt);
> >           vfprintf(f, fmt, ap);
> >           va_end(ap);
>
> This extends -msg timestamp=on to apply to log messages without
> documenting it in -help or anywhere else.  Needs fixing.

I think this is a poor place to add the timestamp.

You'll find that qemu_log is used many times to assemble pieces, e.g.

linux-user/thunk.c:360:            qemu_log("%" PRIu64, tswap64(val));

linux-user/thunk.c:376:                qemu_log("\"");

linux-user/thunk.c:379:                qemu_log("[");

linux-user/thunk.c:384:                    qemu_log(",");

linux-user/thunk.c:391:                qemu_log("\"");

linux-user/thunk.c:393:                qemu_log("]");

linux-user/thunk.c:417:                qemu_log("{");

linux-user/thunk.c:420:                        qemu_log(",");

linux-user/thunk.c:424:                qemu_log("}");


Not the best idea, really, but the replacement for this is to avoid qemu_log 
entirely, and use

    f = qemu_log_trylock();
    if (f) {
        fprintf
        some
        stuff
        qemu_log_unlock(f);
    }

at which point you don't get your timestamp either.  You'd need to explicitly add 
timestamps to individual locations.

It would probably be easier to add timestamps to tracepoints, which are always emitted as 
a unit.


r~