From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from eggs.gnu.org ([2001:4830:134:3::10]:49015) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zn1kG-0001EK-7G for qemu-devel@nongnu.org; Fri, 16 Oct 2015 05:56:17 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1Zn1kD-0003A8-0O for qemu-devel@nongnu.org; Fri, 16 Oct 2015 05:56:16 -0400 Received: from mx2.parallels.com ([199.115.105.18]:57948) by eggs.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1Zn1kC-0003A3-No for qemu-devel@nongnu.org; Fri, 16 Oct 2015 05:56:12 -0400 Message-ID: <5620C999.5080807@odin.com> Date: Fri, 16 Oct 2015 12:55:37 +0300 From: Pavel Butsykin MIME-Version: 1.0 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> In-Reply-To: <87k2qns168.fsf@blackfin.pond.sub.org> Content-Type: text/plain; charset="windows-1252"; format=flowed Content-Transfer-Encoding: 7bit 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: Markus Armbruster , "Denis V. Lunev" Cc: Peter Maydell , Luiz Capitulino , qemu-devel@nongnu.org, Pavel Butsykin 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. > 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 }, >> };