From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([2001:4830:134:3::10]:58869) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zn3GT-00047W-O5 for qemu-devel@nongnu.org; Fri, 16 Oct 2015 07:33:39 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zn3GR-0003yT-0U for qemu-devel@nongnu.org; Fri, 16 Oct 2015 07:33:37 -0400 Received: from mx1.redhat.com ([209.132.183.28]:42827) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zn3GQ-0003yE-Px for qemu-devel@nongnu.org; Fri, 16 Oct 2015 07:33:34 -0400 From: Markus Armbruster References: <1444894224-9542-1-git-send-email-den@openvz.org> <1444894224-9542-4-git-send-email-den@openvz.org> <87k2qns168.fsf@blackfin.pond.sub.org> <5620C999.5080807@odin.com> Date: Fri, 16 Oct 2015 13:33:31 +0200 In-Reply-To: <5620C999.5080807@odin.com> (Pavel Butsykin's message of "Fri, 16 Oct 2015 12:55:37 +0300") Message-ID: <87si5bf3p0.fsf@blackfin.pond.sub.org> MIME-Version: 1.0 Content-Type: text/plain Subject: Re: [Qemu-devel] [PATCH 3/3] log: adds a timestamp to each log entry List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Pavel Butsykin Cc: "Denis V. Lunev" , Pavel Butsykin , Luiz Capitulino , qemu-devel@nongnu.org, Peter Maydell Pavel Butsykin writes: > On 16.10.2015 10:49, Markus Armbruster wrote: >> "Denis V. Lunev" writes: >> >>> 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-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 >>> Signed-off-by: Denis V. Lunev >>> CC: Markus Armbruster >>> CC: Luiz Capitulino >>> CC: Eric Blake >>> CC: Peter Maydell >>> --- >>> 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. The difference is that casting &tv.tv_sec to time_t * works only when these are essentially the same types. They are in practice; that's why I said "unclean", not "broken". But there's no need for unclean here. >> Why not simply ctime(&now)? >> > > It's just a format like and string is smaller)) I like ISO dates myself, but log files are not a place to be creative. Prepending ctime() to log lines is traditional. Another option is to match -msg timestamp behavior (where we already got creative) and use g_time_val_to_iso8601(). >>> + 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 }, >>> };