| Message ID | 1444894224-9542-4-git-send-email-den@openvz.org |
|---|---|
| State | New |
| Headers | show |
"Denis V. Lunev" <den@openvz.org> writes: > 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) 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); } } You don't add a timestamp to qemu_log_vprintf(), log_cpu_state(), ... Intentional? > > 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)); Why not simply ctime(&now)? > + 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. > { 0, NULL, NULL }, > };
On 16.10.2015 10:49, Markus Armbruster wrote: > "Denis V. Lunev" <den@openvz.org> writes: > >> 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) > > 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 }, >> };
Pavel Butsykin <pbutsykin@odin.com> writes: > On 16.10.2015 10:49, Markus Armbruster wrote: >> "Denis V. Lunev" <den@openvz.org> writes: >> >>> 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) >> >> 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 }, >>> };
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 }, };