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

[Dongli Zhang]

Hi Markus and Richard,

Thank you very much for the feedback. I agree this is not a good solution. I
will look for alternatives to add timestamp.

Thank you very much!

Dongli Zhang

On 8/30/22 8:31 AM, Richard Henderson wrote:
> 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~
>