Pavel Butsykin <pbutsy...@odin.com> writes:
> On 16.10.2015 10:49, Markus Armbruster wrote:
>> "Denis V. Lunev" <d...@openvz.org> writes:
>>
>>> From: Pavel Butsykin <pbutsy...@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 <pbutsy...@virtuozzo.com>
>>> Signed-off-by: Denis V. Lunev <d...@openvz.org>
>>> CC: Markus Armbruster <arm...@redhat.com>
>>> CC: Luiz Capitulino <lcapitul...@redhat.com>
>>> CC: Eric Blake <ebl...@redhat.com>
>>> CC: Peter Maydell <peter.mayd...@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 },
>>> };
