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

[Pavel Butsykin <pbutsykin@odin.com>]

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.

> Why not simply ctime(&now)?
>

It's just a format like and string is smaller))

>> +    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 },
>>   };