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

[Markus Armbruster]

"Denis V. Lunev" <address@hidden> writes:

> From: Pavel Butsykin <address@hidden>
>
> 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 <address@hidden>
> Signed-off-by: Denis V. Lunev <address@hidden>
> CC: Markus Armbruster <address@hidden>
> CC: Luiz Capitulino <address@hidden>
> CC: Eric Blake <address@hidden>
> CC: Peter Maydell <address@hidden>
> ---
>  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);
        }
    }

You don't add a timestamp to qemu_log_vprintf(), log_cpu_state(), ...
Intentional?

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

Why not simply ctime(&now)?

> +    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.

>      { 0, NULL, NULL },
>  };