Re: [Qemu-devel] [PATCH 3/3] log: adds a timestamp to each log entry

[Markus Armbruster <armbru@redhat.com>]

Pavel Butsykin <pbutsykin@odin.com> writes:

> On 16.10.2015 10:49, Markus Armbruster wrote:
>> "Denis V. Lunev" <den@openvz.org> writes:
>>
>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>
>>> This patch is written as an addition to the previous one with logging of
>>> QPM commands. This information (the moment of the event) is very useful
>>> to match guest problems with actions performing by management software.
>>>
>>> example:
>>> 2015-10-14 17:15:25.644 qmp event:
>>> {
>>>      "timestamp": {
>>>          "seconds": 1444832125,
>>>          "microseconds": 644854
>>>      },
>>>      "event": "RESUME"
>>> }
>>> 2015-10-14 17:15:35.823 hmp request:
>>> info registers
>>> 2015-10-14 17:15:46.936 hmp request:
>>> q
>>> 2015-10-14 17:15:46.936 qmp event:
>>> {
>>>      "timestamp": {
>>>          "seconds": 1444832146,
>>>          "microseconds": 936214
>>>      },
>>>      "event": "SHUTDOWN"
>>> }
>>>
>>> This patch is not perfect as messages from different threads could
>>> interleave but this is not a big deal, timestamps are nearly the
>>> same.
>>>
>>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>>> CC: Markus Armbruster <armbru@redhat.com>
>>> CC: Luiz Capitulino <lcapitulino@redhat.com>
>>> CC: Eric Blake <eblake@redhat.com>
>>> CC: Peter Maydell <peter.maydell@linaro.org>
>>> ---
>>>   include/qemu/log.h |  9 +++++++++
>>>   qemu-log.c         | 17 ++++++++++++++++-
>>>   2 files changed, 25 insertions(+), 1 deletion(-)
>>>
>>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>>> index ba86606..285636a 100644
>>> --- a/include/qemu/log.h
>>> +++ b/include/qemu/log.h
>>> @@ -42,6 +42,7 @@ static inline bool qemu_log_enabled(void)
>>>   #define LOG_GUEST_ERROR    (1 << 11)
>>>   #define CPU_LOG_MMU        (1 << 12)
>>>   #define LOG_CMD            (1 << 13)
>>> +#define LOG_TIME           (1 << 14)
>>>
>>>   /* Returns true if a bit is set in the current loglevel mask
>>>    */
>>> @@ -52,6 +53,11 @@ static inline bool qemu_loglevel_mask(int mask)
>>>
>>>   /* Logging functions: */
>>>
>>> +
>>> +/* timestamp logging function
>>> +*/
>>> +void qemu_log_time(void);
>>> +
>>>   /* main logging function
>>>    */
>>>   #define qemu_log(args...)                   \
>>> @@ -59,6 +65,9 @@ static inline bool qemu_loglevel_mask(int mask)
>>>           if (!qemu_log_enabled()) {          \
>>>               break;                          \
>>>           }                                   \
>>> +        if (qemu_loglevel & LOG_TIME) {     \
>>> +            qemu_log_time();                \
>>> +        }                                   \
>>>           fprintf(qemu_logfile, args);        \
>>>       } while (0)
>>
>> Since this is no longer just a simple fprintf(), you should keep the
>> actual logging out of line, like this:
>>
>>      static inline void qemu_log(const char *fmt, ...)
>>      {
>>          va_list ap;
>>
>>          if (qemu_log_enabled()) {
>>              va_start(ap, fmt);
>>              qemu_do_log(fmt, ap);
>>              va_end(ap);
>>          }
>>      }
>>
>
> Ok.
>
>> You don't add a timestamp to qemu_log_vprintf(), log_cpu_state(), ...
>> Intentional?
>>
>
> Will add in the next version of the patch.
>
>>>
>>> diff --git a/qemu-log.c b/qemu-log.c
>>> index ba7b34c..6a8ca71 100644
>>> --- a/qemu-log.c
>>> +++ b/qemu-log.c
>>> @@ -25,6 +25,18 @@ FILE *qemu_logfile;
>>>   int qemu_loglevel;
>>>   static int log_append = 0;
>>>
>>> +void qemu_log_time(void)
>>> +{
>>> +    qemu_timeval tv;
>>> +    char timestr[32];
>>> +
>>> +    qemu_gettimeofday(&tv);
>>> +
>>> +    /* cast below needed for OpenBSD where tv_sec is still 'long' */
>>> +    strftime(timestr, sizeof(timestr), "%F %T",
>>> +             localtime((const time_t *)&tv.tv_sec));
>>
>> The pointer cast is unnecessarily unclean.  The clean version is
>>
>>      time_t now = tv.tv_sec;
>>      strftime(timestr, sizeof(timestr), "%F %T", localtime(&now));
>>
>
> I don't think that's a big difference but one less variable.

The difference is that casting &tv.tv_sec to time_t * works only when
these are essentially the same types.  They are in practice; that's why
I said "unclean", not "broken".  But there's no need for unclean here.

>> Why not simply ctime(&now)?
>>
>
> It's just a format like and string is smaller))

I like ISO dates myself, but log files are not a place to be creative.
Prepending ctime() to log lines is traditional.  Another option is to
match -msg timestamp behavior (where we already got creative) and use
g_time_val_to_iso8601().

>>> +    fprintf(qemu_logfile, "%s.%03lu ", timestr, tv.tv_usec / 1000);
>>> +}
>>>
>>>   /* enable or disable low levels log */
>>>   void do_qemu_set_log(int log_flags, bool use_own_buffers)
>>> @@ -98,7 +110,10 @@ const QEMULogItem qemu_log_items[] = {
>>>       { LOG_GUEST_ERROR, "guest_errors",
>>>         "log when the guest OS does something invalid (eg accessing a\n"
>>>         "non-existent register)" },
>>> -    { LOG_CMD, "cmd", "log the hmp/qmp commands execution" },
>>> +    { LOG_CMD, "cmd",
>>> +      "log the hmp/qmp commands execution" },
>>> +    { LOG_TIME, "time",
>>> +      "adds a timestamp to each log entry" },
>>
>> Make that "add a timestamp", for consistency with the other help texts.
>>
>
> Ok.
>>>       { 0, NULL, NULL },
>>>   };