From patchwork Mon Mar 14 11:21:41 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Denis V. Lunev" X-Patchwork-Id: 8578531 Return-Path: X-Original-To: patchwork-qemu-devel@patchwork.kernel.org Delivered-To: patchwork-parsemail@patchwork1.web.kernel.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.136]) by patchwork1.web.kernel.org (Postfix) with ESMTP id A67749F294 for ; Mon, 14 Mar 2016 11:24:22 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id B6C962041D for ; Mon, 14 Mar 2016 11:24:21 +0000 (UTC) Received: from lists.gnu.org (lists.gnu.org [208.118.235.17]) (using TLSv1 with cipher AES256-SHA (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id D1A7B2041C for ; Mon, 14 Mar 2016 11:24:20 +0000 (UTC) Received: from localhost ([::1]:40193 helo=lists.gnu.org) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1afQbk-0004jz-69 for patchwork-qemu-devel@patchwork.kernel.org; Mon, 14 Mar 2016 07:24:20 -0400 Received: from eggs.gnu.org ([2001:4830:134:3::10]:39535) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1afQZb-00018u-Ns for qemu-devel@nongnu.org; Mon, 14 Mar 2016 07:22:11 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1afQZY-0003Nn-5s for qemu-devel@nongnu.org; Mon, 14 Mar 2016 07:22:07 -0400 Received: from mailhub.sw.ru ([195.214.232.25]:13135 helo=relay.sw.ru) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1afQZX-0003Iw-I6 for qemu-devel@nongnu.org; Mon, 14 Mar 2016 07:22:03 -0400 Received: from hades.sw.ru ([10.30.8.132]) by relay.sw.ru (8.13.4/8.13.4) with ESMTP id u2EBLf9A003660; Mon, 14 Mar 2016 14:21:59 +0300 (MSK) From: "Denis V. Lunev" To: Date: Mon, 14 Mar 2016 14:21:41 +0300 Message-Id: <1457954501-26528-10-git-send-email-den@openvz.org> X-Mailer: git-send-email 2.5.0 In-Reply-To: <1457954501-26528-1-git-send-email-den@openvz.org> References: <1457954501-26528-1-git-send-email-den@openvz.org> X-detected-operating-system: by eggs.gnu.org: OpenBSD 3.x X-Received-From: 195.214.232.25 Cc: Pavel Butsykin , Markus Armbruster , qemu-devel@nongnu.org, Stefan Hajnoczi , Paolo Bonzini , "Denis V. Lunev" Subject: [Qemu-devel] [PATCH 9/9] log: adds a timestamp to each log entry X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+patchwork-qemu-devel=patchwork.kernel.org@nongnu.org Sender: qemu-devel-bounces+patchwork-qemu-devel=patchwork.kernel.org@nongnu.org X-Spam-Status: No, score=-6.9 required=5.0 tests=BAYES_00, RCVD_IN_DNSWL_HI, UNPARSEABLE_RELAY autolearn=unavailable version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mail.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP From: Pavel Butsykin 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 Signed-off-by: Denis V. Lunev CC: Stefan Hajnoczi CC: Paolo Bonzini CC: Markus Armbruster --- 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 }, };