[Qemu-devel] [PATCH 9/9] 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-19T08:52:57.859786Z QAPI event: { "timestamp":{"seconds":
        1445244777, "microseconds": 859721}, "event": "RESUME" }
2015-10-19T08:53:03.524088Z QMP event: new connection established
2015-10-19T08:53:11.816711Z QMP command request: {
        "execute": "qmp_capabilities" }
2015-10-19T08:53:11.816791Z QMP command response: { "return": {}}

Using timestamp for qemu_log_vprintf(), log_cpu_state() it is not advisable,
because that will lead to previously unexpected results.
Excessive conclusions timestamps for all that use qemu_log_vprintf:
    qemu_log("qemu: fatal: ");
    qemu_log_vprintf(fmt, ap2);
    ...
The distortion of the output format for log_cpu_state:
    qemu_log_mask(CPU_LOG_INT, "SMM: enter\n");
    log_cpu_state_mask(CPU_LOG_INT, CPU(cpu), CPU_DUMP_CCOP);
    ...
In all variants qemu_log invoked as the design and the timestamp will
be present.

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: Stefan Hajnoczi <stefanha@redhat.com>
CC: Paolo Bonzini <pbonzini@redhat.com>
CC: Markus Armbruster <armbru@redhat.com>
---
 include/qemu/log.h |  5 ++++-
 util/log.c         | 26 ++++++++++++++++++++++++++
 2 files changed, 30 insertions(+), 1 deletion(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 0c7a564..5fe1962 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -45,6 +45,7 @@ static inline bool qemu_log_separate(void)
 #define LOG_QMP            (1 << 16)
 #define LOG_HMP            (1 << 17)
 #define LOG_QAPI           (1 << 18)
+#define LOG_TIME           (1 << 19)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
@@ -55,6 +56,8 @@ static inline bool qemu_loglevel_mask(int mask)
 
 /* Logging functions: */
 
+void qemu_do_log(const char *fmt, ...) GCC_FMT_ATTR(1, 2);
+
 /* main logging function
  */
 #define qemu_log(...)                          \
@@ -79,7 +82,7 @@ qemu_log_vprintf(const char *fmt, va_list va)
 #define qemu_log_mask(mask, ...)                                \
     do {                                                        \
         if ((qemu_loglevel & (mask)) && qemu_log_enabled()) {   \
-           fprintf(qemu_logfile, __VA_ARGS__);                  \
+           qemu_do_log(__VA_ARGS__);                            \
         }                                                       \
     } while (0)
 
diff --git a/util/log.c b/util/log.c
index 572f005..fb562c1 100644
--- a/util/log.c
+++ b/util/log.c
@@ -28,6 +28,30 @@ int qemu_loglevel;
 static int log_append = 0;
 
 
+static void qemu_log_time(void)
+{
+    GTimeVal tv;
+    gchar *timestr;
+
+    g_get_current_time(&tv);
+
+    timestr = g_time_val_to_iso8601(&tv);
+    fprintf(qemu_logfile, "%s ", timestr);
+    g_free(timestr);
+}
+
+void qemu_do_log(const char *fmt, ...)
+{
+    va_list ap;
+
+    if (qemu_loglevel & LOG_TIME) {
+        qemu_log_time();
+    }
+    va_start(ap, fmt);
+    vfprintf(qemu_logfile, fmt, ap);
+    va_end(ap);
+}
+
 /* enable or disable low levels log */
 void do_qemu_set_log(int log_flags, bool use_own_buffers)
 {
@@ -137,6 +161,8 @@ const QEMULogItem qemu_log_items[] = {
       "log the HMP commands and events" },
     { LOG_QAPI, "qapi",
       "log the QAPI events"},
+    { LOG_TIME, "time",
+      "add a timestamp to each log entry" },
     { 0, NULL, NULL },
 };
 
-- 
2.5.0