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

[Pavel Butsykin]

On 16.10.2015 10:49, Markus Armbruster wrote:
> "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);
>          }
>      }

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