diff mbox series

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

Message ID 20220829100622.1554-2-dongli.zhang@oracle.com (mailing list archive)
State New, archived
Headers show
Series [1/2] error-report: make real_time_iso8601() non-static | expand

Commit Message

Dongli Zhang Aug. 29, 2022, 10:06 a.m. UTC
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.

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(+)

Comments

Markus Armbruster Aug. 30, 2022, 11:09 a.m. UTC | #1
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.
Richard Henderson Aug. 30, 2022, 3:31 p.m. UTC | #2
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~
Dongli Zhang Sept. 1, 2022, 4:17 a.m. UTC | #3
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~
>
diff mbox series

Patch

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