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

["Denis V. Lunev" <den@openvz.org>]

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)
 
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));
+    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" },
     { 0, NULL, NULL },
 };
 
-- 
2.1.4