[Qemu-devel] [PATCH 0/3] QEMU logging improvements

[Qemu-devel] [PATCH 0/3] QEMU logging improvements

[Denis V. Lunev]

The following is done:
- QMP/HMP events are now logged
- timestamp is added to the log message
- arguments of qemu_log/qemu_log_mask are not calculated now if the log
  is disabled

These patches are sent in the hope that it is not too late for QEMU 2.5.

Logging subsystem in QEMU looks rudimentary to me and should be definitely
improved, f.e. log on stalled NFS could ruin the system completely. Anyway,
it is too late for this at the moment.

Signed-off-by: Denis V. Lunev <den@openvz.org>
CC: Pavel Butsykin <pbutsykin@virtuozzo.com>
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>

[Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Denis V. Lunev]

The patch is intended to avoid to perform any operation including
calculation of log function arguments when the log is not enabled due to
various reasons.

Functions qemu_log and qemu_log_mask are replaced with variadic macros.
Unfortunately the code is not C99 compatible and we can not use
portable __VA_ARGS__ way. There are a lot of warnings in the other
places with --std=c99. Thus the only way to achive the result is to use
args.. GCC extension.

Format checking performed by compiler will not suffer by this patch. It
will be done inside in fprintf arguments checking.

Signed-off-by: Denis V. Lunev <den@openvz.org>
Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
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 | 17 ++++++++++++++---
 qemu-log.c         | 21 ---------------------
 2 files changed, 14 insertions(+), 24 deletions(-)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index f880e66..57b8c96 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
 
 /* main logging function
  */
-void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
+#define qemu_log(args...)                   \
+    do {                                    \
+        if (!qemu_log_enabled()) {          \
+            break;                          \
+        }                                   \
+        fprintf(qemu_logfile, args);        \
+    } while (0)
 
 /* vfprintf-like logging function
  */
@@ -67,8 +73,13 @@ qemu_log_vprintf(const char *fmt, va_list va)
 
 /* log only if a bit is set on the current loglevel mask
  */
-void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
-
+#define qemu_log_mask(mask, args...)        \
+    do {                                    \
+        if (!qemu_loglevel_mask(mask)) {    \
+            break;                          \
+        }                                   \
+        qemu_log(args);                     \
+    } while (0)
 
 /* Special cases: */
 
diff --git a/qemu-log.c b/qemu-log.c
index 13f3813..e6d2b3f 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -25,27 +25,6 @@ FILE *qemu_logfile;
 int qemu_loglevel;
 static int log_append = 0;
 
-void qemu_log(const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    if (qemu_logfile) {
-        vfprintf(qemu_logfile, fmt, ap);
-    }
-    va_end(ap);
-}
-
-void qemu_log_mask(int mask, const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    if ((qemu_loglevel & mask) && qemu_logfile) {
-        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)
-- 
2.1.4

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Alex Bennée]

Denis V. Lunev <den@openvz.org> writes:

> The patch is intended to avoid to perform any operation including
> calculation of log function arguments when the log is not enabled due to
> various reasons.
>
> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
> Unfortunately the code is not C99 compatible and we can not use
> portable __VA_ARGS__ way. There are a lot of warnings in the other
> places with --std=c99. Thus the only way to achive the result is to use
> args.. GCC extension.
>
> Format checking performed by compiler will not suffer by this patch. It
> will be done inside in fprintf arguments checking.
>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> 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 | 17 ++++++++++++++---
>  qemu-log.c         | 21 ---------------------
>  2 files changed, 14 insertions(+), 24 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index f880e66..57b8c96 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>  
>  /* main logging function
>   */
> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
> +#define qemu_log(args...)                   \
> +    do {                                    \
> +        if (!qemu_log_enabled()) {          \
> +            break;                          \
> +        }                                   \
> +        fprintf(qemu_logfile, args);        \
> +    } while (0)
>

I've had one of Peter's patches in my logging improvements queue for a
while although it uses a slightly different form which I prefer:

-/* log only if a bit is set on the current loglevel mask
+/* log only if a bit is set on the current loglevel mask:
+ * @mask: bit to check in the mask
+ * @fmt: printf-style format string
+ * @args: optional arguments for format string
  */
-void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
-
+#define qemu_log_mask(MASK, FMT, ...)                   \
+    do {                                                \
+        if (unlikely(qemu_loglevel_mask(MASK))) {       \
+            qemu_log(FMT, ## __VA_ARGS__);              \
+        }                                               \

See the message:

qemu-log: Avoid function call for disabled qemu_log_mask logging

>  /* vfprintf-like logging function
>   */
> @@ -67,8 +73,13 @@ qemu_log_vprintf(const char *fmt, va_list va)
>  
>  /* log only if a bit is set on the current loglevel mask
>   */
> -void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
> -
> +#define qemu_log_mask(mask, args...)        \
> +    do {                                    \
> +        if (!qemu_loglevel_mask(mask)) {    \
> +            break;                          \
> +        }                                   \
> +        qemu_log(args);                     \
> +    } while (0)
>  
>  /* Special cases: */
>  
> diff --git a/qemu-log.c b/qemu-log.c
> index 13f3813..e6d2b3f 100644
> --- a/qemu-log.c
> +++ b/qemu-log.c
> @@ -25,27 +25,6 @@ FILE *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
>  
> -void qemu_log(const char *fmt, ...)
> -{
> -    va_list ap;
> -
> -    va_start(ap, fmt);
> -    if (qemu_logfile) {
> -        vfprintf(qemu_logfile, fmt, ap);
> -    }
> -    va_end(ap);
> -}
> -
> -void qemu_log_mask(int mask, const char *fmt, ...)
> -{
> -    va_list ap;
> -
> -    va_start(ap, fmt);
> -    if ((qemu_loglevel & mask) && qemu_logfile) {
> -        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)

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Denis V. Lunev]

On 10/15/2015 08:23 PM, Alex Bennée wrote:
> Denis V. Lunev <den@openvz.org> writes:
>
>> The patch is intended to avoid to perform any operation including
>> calculation of log function arguments when the log is not enabled due to
>> various reasons.
>>
>> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
>> Unfortunately the code is not C99 compatible and we can not use
>> portable __VA_ARGS__ way. There are a lot of warnings in the other
>> places with --std=c99. Thus the only way to achive the result is to use
>> args.. GCC extension.
>>
>> Format checking performed by compiler will not suffer by this patch. It
>> will be done inside in fprintf arguments checking.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>> 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 | 17 ++++++++++++++---
>>   qemu-log.c         | 21 ---------------------
>>   2 files changed, 14 insertions(+), 24 deletions(-)
>>
>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>> index f880e66..57b8c96 100644
>> --- a/include/qemu/log.h
>> +++ b/include/qemu/log.h
>> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>>   
>>   /* main logging function
>>    */
>> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>> +#define qemu_log(args...)                   \
>> +    do {                                    \
>> +        if (!qemu_log_enabled()) {          \
>> +            break;                          \
>> +        }                                   \
>> +        fprintf(qemu_logfile, args);        \
>> +    } while (0)
>>
> I've had one of Peter's patches in my logging improvements queue for a
> while although it uses a slightly different form which I prefer:
>
> -/* log only if a bit is set on the current loglevel mask
> +/* log only if a bit is set on the current loglevel mask:
> + * @mask: bit to check in the mask
> + * @fmt: printf-style format string
> + * @args: optional arguments for format string
>    */
> -void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
> -
> +#define qemu_log_mask(MASK, FMT, ...)                   \
> +    do {                                                \
> +        if (unlikely(qemu_loglevel_mask(MASK))) {       \
> +            qemu_log(FMT, ## __VA_ARGS__);              \
> +        }                                               \
>
> See the message:
>
> qemu-log: Avoid function call for disabled qemu_log_mask logging

as far as I can see that patch is one year old at least
and my version is slightly better, it does the same for
qemu_log.

The difference is that old patch has unlikely() hint and does not
contain break.

I can revert the condition and add the hint in a couple
of minutes if this will increase the chance to get
both things merged. We should have both functions
as macros.

Will you accept that?

Den

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Alex Bennée]

Denis V. Lunev <den@openvz.org> writes:

> On 10/15/2015 08:23 PM, Alex Bennée wrote:
>> Denis V. Lunev <den@openvz.org> writes:
>>
>>> The patch is intended to avoid to perform any operation including
>>> calculation of log function arguments when the log is not enabled due to
>>> various reasons.
>>>
>>> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
>>> Unfortunately the code is not C99 compatible and we can not use
>>> portable __VA_ARGS__ way. There are a lot of warnings in the other
>>> places with --std=c99. Thus the only way to achive the result is to use
>>> args.. GCC extension.
>>>
>>> Format checking performed by compiler will not suffer by this patch. It
>>> will be done inside in fprintf arguments checking.
>>>
>>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>> 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 | 17 ++++++++++++++---
>>>   qemu-log.c         | 21 ---------------------
>>>   2 files changed, 14 insertions(+), 24 deletions(-)
>>>
>>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>>> index f880e66..57b8c96 100644
>>> --- a/include/qemu/log.h
>>> +++ b/include/qemu/log.h
>>> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>>>   
>>>   /* main logging function
>>>    */
>>> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>>> +#define qemu_log(args...)                   \
>>> +    do {                                    \
>>> +        if (!qemu_log_enabled()) {          \
>>> +            break;                          \
>>> +        }                                   \
>>> +        fprintf(qemu_logfile, args);        \
>>> +    } while (0)
>>>
>> I've had one of Peter's patches in my logging improvements queue for a
>> while although it uses a slightly different form which I prefer:
>>
>> -/* log only if a bit is set on the current loglevel mask
>> +/* log only if a bit is set on the current loglevel mask:
>> + * @mask: bit to check in the mask
>> + * @fmt: printf-style format string
>> + * @args: optional arguments for format string
>>    */
>> -void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
>> -
>> +#define qemu_log_mask(MASK, FMT, ...)                   \
>> +    do {                                                \
>> +        if (unlikely(qemu_loglevel_mask(MASK))) {       \
>> +            qemu_log(FMT, ## __VA_ARGS__);              \
>> +        }                                               \
>>
>> See the message:
>>
>> qemu-log: Avoid function call for disabled qemu_log_mask logging
>
> as far as I can see that patch is one year old at least
> and my version is slightly better, it does the same for
> qemu_log.

Yeah it has been sitting in my queue for a while as part of a larger
series. I haven't been pushing it because the demand for the other
changes isn't super high.

Yes it would be better to do both qemu_log and qemu_log_mask.

> The difference is that old patch has unlikely() hint and does not
> contain break.

I'm not sure what the break form brings. It's personal preference I
guess but to me it is more natural to wrap things inside the condition
then use break to skip out of a block.

> I can revert the condition and add the hint in a couple
> of minutes if this will increase the chance to get
> both things merged. We should have both functions
> as macros.
>
> Will you accept that?

I'll certainly review the next submission. I also suggest you CC
qemu-trivial once you have collected all your r-b and a-b/s-o-b tags.

>
> Den

-- 
Alex Bennée

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Markus Armbruster]

"Denis V. Lunev" <den@openvz.org> writes:

> The patch is intended to avoid to perform any operation including
> calculation of log function arguments when the log is not enabled due to
> various reasons.
>
> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
> Unfortunately the code is not C99 compatible and we can not use
> portable __VA_ARGS__ way. There are a lot of warnings in the other
> places with --std=c99. Thus the only way to achive the result is to use
> args.. GCC extension.

Really?  We use __VA_ARGS__ all over the place, why won't it work here?

> Format checking performed by compiler will not suffer by this patch. It
> will be done inside in fprintf arguments checking.
>
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
> 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 | 17 ++++++++++++++---
>  qemu-log.c         | 21 ---------------------
>  2 files changed, 14 insertions(+), 24 deletions(-)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index f880e66..57b8c96 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>  
>  /* main logging function
>   */
> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
> +#define qemu_log(args...)                   \
> +    do {                                    \
> +        if (!qemu_log_enabled()) {          \
> +            break;                          \
> +        }                                   \
> +        fprintf(qemu_logfile, args);        \
> +    } while (0)

Feels stilted.  Like Alex's, I'd prefer something like

    #define qemu_log(fmt, ...)				\
        do {                                                \
            if (unlikely(qemu_log_enabled())) {		\
                fprintf(qemu_logfile, fmt, ## __VA_ARGS__);	\
            }						\
        } while (0)

I'm no fan of hiding qemu_logfile in qemu_log_enabled(), then using it
directly to print to it, but that's a different conversation.

However, we already have

    static inline void GCC_FMT_ATTR(1, 0)
    qemu_log_vprintf(const char *fmt, va_list va)
    {
        if (qemu_logfile) {
            vfprintf(qemu_logfile, fmt, va);
        }
    }

Wouldn't static inline work for qemu_log(), too?

>  /* vfprintf-like logging function
>   */
> @@ -67,8 +73,13 @@ qemu_log_vprintf(const char *fmt, va_list va)
>  
>  /* log only if a bit is set on the current loglevel mask
>   */
> -void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
> -
> +#define qemu_log_mask(mask, args...)        \
> +    do {                                    \
> +        if (!qemu_loglevel_mask(mask)) {    \
> +            break;                          \
> +        }                                   \
> +        qemu_log(args);                     \
> +    } while (0)
>  
>  /* Special cases: */
>  
> diff --git a/qemu-log.c b/qemu-log.c
> index 13f3813..e6d2b3f 100644
> --- a/qemu-log.c
> +++ b/qemu-log.c
> @@ -25,27 +25,6 @@ FILE *qemu_logfile;
>  int qemu_loglevel;
>  static int log_append = 0;
>  
> -void qemu_log(const char *fmt, ...)
> -{
> -    va_list ap;
> -
> -    va_start(ap, fmt);
> -    if (qemu_logfile) {
> -        vfprintf(qemu_logfile, fmt, ap);
> -    }
> -    va_end(ap);
> -}
> -
> -void qemu_log_mask(int mask, const char *fmt, ...)
> -{
> -    va_list ap;
> -
> -    va_start(ap, fmt);
> -    if ((qemu_loglevel & mask) && qemu_logfile) {
> -        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)

I support the general approach to inline the "is logging on" test
somehow.

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Denis V. Lunev]

On 10/16/2015 10:17 AM, Markus Armbruster wrote:
> "Denis V. Lunev" <den@openvz.org> writes:
>
>> The patch is intended to avoid to perform any operation including
>> calculation of log function arguments when the log is not enabled due to
>> various reasons.
>>
>> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
>> Unfortunately the code is not C99 compatible and we can not use
>> portable __VA_ARGS__ way. There are a lot of warnings in the other
>> places with --std=c99. Thus the only way to achive the result is to use
>> args.. GCC extension.
> Really?  We use __VA_ARGS__ all over the place, why won't it work here?

I have received warning like this
   "__VA_ARGS__ can only appear in the expansion of a C99 variadic macro"
with intermediate version of the patch.

At the moment (with the current version) the replacement to __VA_ARGS__
works. Something strange has been happen. This syntax is definitely
better for me.

Will change.

>> Format checking performed by compiler will not suffer by this patch. It
>> will be done inside in fprintf arguments checking.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>> 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 | 17 ++++++++++++++---
>>   qemu-log.c         | 21 ---------------------
>>   2 files changed, 14 insertions(+), 24 deletions(-)
>>
>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>> index f880e66..57b8c96 100644
>> --- a/include/qemu/log.h
>> +++ b/include/qemu/log.h
>> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>>   
>>   /* main logging function
>>    */
>> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>> +#define qemu_log(args...)                   \
>> +    do {                                    \
>> +        if (!qemu_log_enabled()) {          \
>> +            break;                          \
>> +        }                                   \
>> +        fprintf(qemu_logfile, args);        \
>> +    } while (0)
> Feels stilted.  Like Alex's, I'd prefer something like
>
>      #define qemu_log(fmt, ...)				\
>          do {                                                \
>              if (unlikely(qemu_log_enabled())) {		\
>                  fprintf(qemu_logfile, fmt, ## __VA_ARGS__);	\
>              }						\
>          } while (0)
>
> I'm no fan of hiding qemu_logfile in qemu_log_enabled(), then using it
> directly to print to it, but that's a different conversation.
actually I am fine with any approach :) as there is no difference to me.
In general, this was taken from another project where I have
had more code below if. This is just an option to reduce indentation
to a meaningful piece of the code.

> However, we already have
>
>      static inline void GCC_FMT_ATTR(1, 0)
>      qemu_log_vprintf(const char *fmt, va_list va)
>      {
>          if (qemu_logfile) {
>              vfprintf(qemu_logfile, fmt, va);
>          }
>      }
>
> Wouldn't static inline work for qemu_log(), too?

AFAIK no and the problem is that this could be compiler
specific.

irbis ~ $ cat 1.c
#include <stdio.h>

int f()
{
     return 1;
}

static inline int test(int a, int b)
{
     if (a == 1) {
         printf("%d\n", b);
     }
}

int main()
{
     test(2, f());
     return 0;
}
irbis ~ $

000000000040056b <main>:
   40056b:    55                       push   %rbp
   40056c:    48 89 e5                 mov    %rsp,%rbp
   40056f:    b8 00 00 00 00           mov    $0x0,%eax
   400574:    e8 bd ff ff ff           callq  400536 <f>
   400579:    89 c6                    mov    %eax,%esi
   40057b:    bf 02 00 00 00           mov    $0x2,%edi
   400580:    e8 bc ff ff ff           callq  400541 <test>
   400585:    b8 00 00 00 00           mov    $0x0,%eax
   40058a:    5d                       pop    %rbp
   40058b:    c3                       retq
   40058c:    0f 1f 40 00              nopl   0x0(%rax)


as you can see here f() is called before calling to test()

Thus I feel that this inline should be replaced too ;)

>>   /* vfprintf-like logging function
>>    */
>> @@ -67,8 +73,13 @@ qemu_log_vprintf(const char *fmt, va_list va)
>>   
>>   /* log only if a bit is set on the current loglevel mask
>>    */
>> -void GCC_FMT_ATTR(2, 3) qemu_log_mask(int mask, const char *fmt, ...);
>> -
>> +#define qemu_log_mask(mask, args...)        \
>> +    do {                                    \
>> +        if (!qemu_loglevel_mask(mask)) {    \
>> +            break;                          \
>> +        }                                   \
>> +        qemu_log(args);                     \
>> +    } while (0)
>>   
>>   /* Special cases: */
>>   
>> diff --git a/qemu-log.c b/qemu-log.c
>> index 13f3813..e6d2b3f 100644
>> --- a/qemu-log.c
>> +++ b/qemu-log.c
>> @@ -25,27 +25,6 @@ FILE *qemu_logfile;
>>   int qemu_loglevel;
>>   static int log_append = 0;
>>   
>> -void qemu_log(const char *fmt, ...)
>> -{
>> -    va_list ap;
>> -
>> -    va_start(ap, fmt);
>> -    if (qemu_logfile) {
>> -        vfprintf(qemu_logfile, fmt, ap);
>> -    }
>> -    va_end(ap);
>> -}
>> -
>> -void qemu_log_mask(int mask, const char *fmt, ...)
>> -{
>> -    va_list ap;
>> -
>> -    va_start(ap, fmt);
>> -    if ((qemu_loglevel & mask) && qemu_logfile) {
>> -        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)
> I support the general approach to inline the "is logging on" test
> somehow.

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Markus Armbruster]

"Denis V. Lunev" <den@openvz.org> writes:

> On 10/16/2015 10:17 AM, Markus Armbruster wrote:
>> "Denis V. Lunev" <den@openvz.org> writes:
>>
>>> The patch is intended to avoid to perform any operation including
>>> calculation of log function arguments when the log is not enabled due to
>>> various reasons.
>>>
>>> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
>>> Unfortunately the code is not C99 compatible and we can not use
>>> portable __VA_ARGS__ way. There are a lot of warnings in the other
>>> places with --std=c99. Thus the only way to achive the result is to use
>>> args.. GCC extension.
>> Really?  We use __VA_ARGS__ all over the place, why won't it work here?
>
> I have received warning like this
>   "__VA_ARGS__ can only appear in the expansion of a C99 variadic macro"
> with intermediate version of the patch.
>
> At the moment (with the current version) the replacement to __VA_ARGS__
> works. Something strange has been happen. This syntax is definitely
> better for me.
>
> Will change.
>
>>> Format checking performed by compiler will not suffer by this patch. It
>>> will be done inside in fprintf arguments checking.
>>>
>>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>> 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 | 17 ++++++++++++++---
>>>   qemu-log.c         | 21 ---------------------
>>>   2 files changed, 14 insertions(+), 24 deletions(-)
>>>
>>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>>> index f880e66..57b8c96 100644
>>> --- a/include/qemu/log.h
>>> +++ b/include/qemu/log.h
>>> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>>>     /* main logging function
>>>    */
>>> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>>> +#define qemu_log(args...)                   \
>>> +    do {                                    \
>>> +        if (!qemu_log_enabled()) {          \
>>> +            break;                          \
>>> +        }                                   \
>>> +        fprintf(qemu_logfile, args);        \
>>> +    } while (0)
>> Feels stilted.  Like Alex's, I'd prefer something like
>>
>>      #define qemu_log(fmt, ...)				\
>>          do {                                                \
>>              if (unlikely(qemu_log_enabled())) {		\
>>                  fprintf(qemu_logfile, fmt, ## __VA_ARGS__);	\
>>              }						\
>>          } while (0)
>>
>> I'm no fan of hiding qemu_logfile in qemu_log_enabled(), then using it
>> directly to print to it, but that's a different conversation.
> actually I am fine with any approach :) as there is no difference to me.
> In general, this was taken from another project where I have
> had more code below if. This is just an option to reduce indentation
> to a meaningful piece of the code.
>
>> However, we already have
>>
>>      static inline void GCC_FMT_ATTR(1, 0)
>>      qemu_log_vprintf(const char *fmt, va_list va)
>>      {
>>          if (qemu_logfile) {
>>              vfprintf(qemu_logfile, fmt, va);
>>          }
>>      }
>>
>> Wouldn't static inline work for qemu_log(), too?
>
> AFAIK no and the problem is that this could be compiler
> specific.
>
> irbis ~ $ cat 1.c
> #include <stdio.h>
>
> int f()
> {
>     return 1;
> }
>
> static inline int test(int a, int b)
> {
>     if (a == 1) {
>         printf("%d\n", b);
>     }
> }
>
> int main()
> {
>     test(2, f());
>     return 0;
> }
> irbis ~ $
>
> 000000000040056b <main>:
>   40056b:    55                       push   %rbp
>   40056c:    48 89 e5                 mov    %rsp,%rbp
>   40056f:    b8 00 00 00 00           mov    $0x0,%eax
>   400574:    e8 bd ff ff ff           callq  400536 <f>
>   400579:    89 c6                    mov    %eax,%esi
>   40057b:    bf 02 00 00 00           mov    $0x2,%edi
>   400580:    e8 bc ff ff ff           callq  400541 <test>
>   400585:    b8 00 00 00 00           mov    $0x0,%eax
>   40058a:    5d                       pop    %rbp
>   40058b:    c3                       retq
>   40058c:    0f 1f 40 00              nopl   0x0(%rax)
>
>
> as you can see here f() is called before calling to test()
>
> Thus I feel that this inline should be replaced too ;)

Well, what did you expect?  You asked the compiler to inline test(), and
it inlined test().  You didn't ask it to inline f(), and it didn't
inline f().

[...]

Re: [Qemu-devel] [PATCH 1/3] log: improve performance of qemu_log and qemu_log_mask if disabled

[Denis V. Lunev]

On 10/16/2015 02:02 PM, Markus Armbruster wrote:
> "Denis V. Lunev" <den@openvz.org> writes:
>
>> On 10/16/2015 10:17 AM, Markus Armbruster wrote:
>>> "Denis V. Lunev" <den@openvz.org> writes:
>>>
>>>> The patch is intended to avoid to perform any operation including
>>>> calculation of log function arguments when the log is not enabled due to
>>>> various reasons.
>>>>
>>>> Functions qemu_log and qemu_log_mask are replaced with variadic macros.
>>>> Unfortunately the code is not C99 compatible and we can not use
>>>> portable __VA_ARGS__ way. There are a lot of warnings in the other
>>>> places with --std=c99. Thus the only way to achive the result is to use
>>>> args.. GCC extension.
>>> Really?  We use __VA_ARGS__ all over the place, why won't it work here?
>> I have received warning like this
>>    "__VA_ARGS__ can only appear in the expansion of a C99 variadic macro"
>> with intermediate version of the patch.
>>
>> At the moment (with the current version) the replacement to __VA_ARGS__
>> works. Something strange has been happen. This syntax is definitely
>> better for me.
>>
>> Will change.
>>
>>>> Format checking performed by compiler will not suffer by this patch. It
>>>> will be done inside in fprintf arguments checking.
>>>>
>>>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>>>> Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>> 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 | 17 ++++++++++++++---
>>>>    qemu-log.c         | 21 ---------------------
>>>>    2 files changed, 14 insertions(+), 24 deletions(-)
>>>>
>>>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>>>> index f880e66..57b8c96 100644
>>>> --- a/include/qemu/log.h
>>>> +++ b/include/qemu/log.h
>>>> @@ -53,7 +53,13 @@ static inline bool qemu_loglevel_mask(int mask)
>>>>      /* main logging function
>>>>     */
>>>> -void GCC_FMT_ATTR(1, 2) qemu_log(const char *fmt, ...);
>>>> +#define qemu_log(args...)                   \
>>>> +    do {                                    \
>>>> +        if (!qemu_log_enabled()) {          \
>>>> +            break;                          \
>>>> +        }                                   \
>>>> +        fprintf(qemu_logfile, args);        \
>>>> +    } while (0)
>>> Feels stilted.  Like Alex's, I'd prefer something like
>>>
>>>       #define qemu_log(fmt, ...)				\
>>>           do {                                                \
>>>               if (unlikely(qemu_log_enabled())) {		\
>>>                   fprintf(qemu_logfile, fmt, ## __VA_ARGS__);	\
>>>               }						\
>>>           } while (0)
>>>
>>> I'm no fan of hiding qemu_logfile in qemu_log_enabled(), then using it
>>> directly to print to it, but that's a different conversation.
>> actually I am fine with any approach :) as there is no difference to me.
>> In general, this was taken from another project where I have
>> had more code below if. This is just an option to reduce indentation
>> to a meaningful piece of the code.
>>
>>> However, we already have
>>>
>>>       static inline void GCC_FMT_ATTR(1, 0)
>>>       qemu_log_vprintf(const char *fmt, va_list va)
>>>       {
>>>           if (qemu_logfile) {
>>>               vfprintf(qemu_logfile, fmt, va);
>>>           }
>>>       }
>>>
>>> Wouldn't static inline work for qemu_log(), too?
>> AFAIK no and the problem is that this could be compiler
>> specific.
>>
>> irbis ~ $ cat 1.c
>> #include <stdio.h>
>>
>> int f()
>> {
>>      return 1;
>> }
>>
>> static inline int test(int a, int b)
>> {
>>      if (a == 1) {
>>          printf("%d\n", b);
>>      }
>> }
>>
>> int main()
>> {
>>      test(2, f());
>>      return 0;
>> }
>> irbis ~ $
>>
>> 000000000040056b <main>:
>>    40056b:    55                       push   %rbp
>>    40056c:    48 89 e5                 mov    %rsp,%rbp
>>    40056f:    b8 00 00 00 00           mov    $0x0,%eax
>>    400574:    e8 bd ff ff ff           callq  400536 <f>
>>    400579:    89 c6                    mov    %eax,%esi
>>    40057b:    bf 02 00 00 00           mov    $0x2,%edi
>>    400580:    e8 bc ff ff ff           callq  400541 <test>
>>    400585:    b8 00 00 00 00           mov    $0x0,%eax
>>    40058a:    5d                       pop    %rbp
>>    40058b:    c3                       retq
>>    40058c:    0f 1f 40 00              nopl   0x0(%rax)
>>
>>
>> as you can see here f() is called before calling to test()
>>
>> Thus I feel that this inline should be replaced too ;)
> Well, what did you expect?  You asked the compiler to inline test(), and
> it inlined test().  You didn't ask it to inline f(), and it didn't
> inline f().
>
> [...]
you have asked whether 'static inline' will help
to avoid arguments evaluation. This does not happen,
compiler has not inlined inline function, (call test)
is here and arguments have been calculated.

For me this means that macros are better than
inline functions for logging functions. I do not
want to bother about interesting side-effects.

No log - no parameter evaluation under all
conditions.

Den

[Qemu-devel] [PATCH 2/3] log: report hmp/qmp command and qmp event

[Denis V. Lunev]

From: Pavel Butsykin <pbutsykin@virtuozzo.com>

This log would be very welcome for long-term diagnostics of the system
in the production. This log is at least necessary to understand what
has been happened on the system and to identify issues at higher-level
subsystems (libvirt, etc).

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 |  1 +
 monitor.c          | 18 ++++++++++++++++++
 qemu-log.c         |  1 +
 3 files changed, 20 insertions(+)

diff --git a/include/qemu/log.h b/include/qemu/log.h
index 57b8c96..ba86606 100644
--- a/include/qemu/log.h
+++ b/include/qemu/log.h
@@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
 #define LOG_UNIMP          (1 << 10)
 #define LOG_GUEST_ERROR    (1 << 11)
 #define CPU_LOG_MMU        (1 << 12)
+#define LOG_CMD            (1 << 13)
 
 /* Returns true if a bit is set in the current loglevel mask
  */
diff --git a/monitor.c b/monitor.c
index 4f1ba2f..71810bb 100644
--- a/monitor.c
+++ b/monitor.c
@@ -434,6 +434,12 @@ static void monitor_protocol_emitter(Monitor *mon, QObject *data,
     }
 
     monitor_json_emitter(mon, QOBJECT(qmp));
+    if (qemu_loglevel_mask(LOG_CMD)) {
+        QString *output_json = qobject_to_json_pretty(QOBJECT(qmp));
+        qemu_log("qmp response:\n%s\n", output_json->string);
+        QDECREF(output_json);
+    }
+
     QDECREF(qmp);
 }
 
@@ -474,6 +480,11 @@ monitor_qapi_event_queue(QAPIEvent event, QDict *data, Error **errp)
                                        evstate->last,
                                        now);
 
+    if (qemu_loglevel_mask(LOG_CMD)) {
+        QString *output_json = qobject_to_json_pretty(QOBJECT(data));
+        qemu_log("qmp event:\n%s\n", output_json->string);
+        QDECREF(output_json);
+    }
     /* Rate limit of 0 indicates no throttling */
     qemu_mutex_lock(&monitor_lock);
     if (!evstate->rate) {
@@ -2848,6 +2859,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
     QDict *qdict;
     const mon_cmd_t *cmd;
 
+    qemu_log_mask(LOG_CMD, "hmp request:\n%s\n", cmdline);
+
     cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
     if (!cmd) {
         return;
@@ -3823,6 +3836,11 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
         goto err_out;
     }
 
+    if (qemu_loglevel_mask(LOG_CMD)) {
+        QString *output_json = output_json = qobject_to_json_pretty(obj);
+        qemu_log("qmp request:\n%s\n", output_json->string);
+        QDECREF(output_json);
+    }
     input = qmp_check_input_obj(obj, &local_err);
     if (!input) {
         qobject_decref(obj);
diff --git a/qemu-log.c b/qemu-log.c
index e6d2b3f..ba7b34c 100644
--- a/qemu-log.c
+++ b/qemu-log.c
@@ -98,6 +98,7 @@ 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" },
     { 0, NULL, NULL },
 };
 
-- 
2.1.4

Re: [Qemu-devel] [PATCH 2/3] log: report hmp/qmp command and qmp event

[Markus Armbruster]

"Denis V. Lunev" <den@openvz.org> writes:

> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>
> This log would be very welcome for long-term diagnostics of the system
> in the production. This log is at least necessary to understand what
> has been happened on the system and to identify issues at higher-level
> subsystems (libvirt, etc).
>
> 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 |  1 +
>  monitor.c          | 18 ++++++++++++++++++
>  qemu-log.c         |  1 +
>  3 files changed, 20 insertions(+)
>
> diff --git a/include/qemu/log.h b/include/qemu/log.h
> index 57b8c96..ba86606 100644
> --- a/include/qemu/log.h
> +++ b/include/qemu/log.h
> @@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
>  #define LOG_UNIMP          (1 << 10)
>  #define LOG_GUEST_ERROR    (1 << 11)
>  #define CPU_LOG_MMU        (1 << 12)
> +#define LOG_CMD            (1 << 13)
>  
>  /* Returns true if a bit is set in the current loglevel mask
>   */
> diff --git a/monitor.c b/monitor.c
> index 4f1ba2f..71810bb 100644
> --- a/monitor.c
> +++ b/monitor.c
> @@ -434,6 +434,12 @@ static void monitor_protocol_emitter(Monitor *mon, QObject *data,
>      }
>  
>      monitor_json_emitter(mon, QOBJECT(qmp));
> +    if (qemu_loglevel_mask(LOG_CMD)) {
> +        QString *output_json = qobject_to_json_pretty(QOBJECT(qmp));
> +        qemu_log("qmp response:\n%s\n", output_json->string);
> +        QDECREF(output_json);
> +    }
> +

Uh, _pretty makes this multiple lines.  Is this appropriate for the log
file?  Finding log message boundaries goes from regular to
context-free...

Nitpick: we generally spell it QMP.

>      QDECREF(qmp);
>  }
>  
> @@ -474,6 +480,11 @@ monitor_qapi_event_queue(QAPIEvent event, QDict *data, Error **errp)
>                                         evstate->last,
>                                         now);
>  
> +    if (qemu_loglevel_mask(LOG_CMD)) {
> +        QString *output_json = qobject_to_json_pretty(QOBJECT(data));
> +        qemu_log("qmp event:\n%s\n", output_json->string);
> +        QDECREF(output_json);
> +    }

This does *not* log QMP events (the ones put on the wire), it logs
*QAPI* events, which may or may not put on the wire due to rate
limiting.

Are you sure we don't want to rate-limit log messages?

If you really want to log QAPI events rather than QMP events, you get to
explain why in the commit message, and you get to document the
difference between the log and the actual wire.

But I suspect you merely put this in the wrong place :)

>      /* Rate limit of 0 indicates no throttling */
>      qemu_mutex_lock(&monitor_lock);
>      if (!evstate->rate) {

Not logged: the QMP greeting.  If you want to log QMP, log all of QMP.

You can either put the logging of the transmit direction in
monitor_json_emitter(), or you put it in each of its callers.

> @@ -2848,6 +2859,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>      QDict *qdict;
>      const mon_cmd_t *cmd;
>  
> +    qemu_log_mask(LOG_CMD, "hmp request:\n%s\n", cmdline);
> +
>      cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>      if (!cmd) {
>          return;
> @@ -3823,6 +3836,11 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>          goto err_out;
>      }
>  
> +    if (qemu_loglevel_mask(LOG_CMD)) {
> +        QString *output_json = output_json = qobject_to_json_pretty(obj);
> +        qemu_log("qmp request:\n%s\n", output_json->string);
> +        QDECREF(output_json);
> +    }
>      input = qmp_check_input_obj(obj, &local_err);
>      if (!input) {
>          qobject_decref(obj);

Nitpick: QMP calls this a command, not a request.

> diff --git a/qemu-log.c b/qemu-log.c
> index e6d2b3f..ba7b34c 100644
> --- a/qemu-log.c
> +++ b/qemu-log.c
> @@ -98,6 +98,7 @@ 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" },
>      { 0, NULL, NULL },
>  };

I can't quite see the use case for logging HMP, but since you wrote it,
I assume you got one.

Regardless, separate flags and patches for QMP and HMP, please.

Re: [Qemu-devel] [PATCH 2/3] log: report hmp/qmp command and qmp event

[Pavel Butsykin]

On 16.10.2015 10:34, Markus Armbruster wrote:
> "Denis V. Lunev" <den@openvz.org> writes:
>
>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>
>> This log would be very welcome for long-term diagnostics of the system
>> in the production. This log is at least necessary to understand what
>> has been happened on the system and to identify issues at higher-level
>> subsystems (libvirt, etc).
>>
>> 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 |  1 +
>>   monitor.c          | 18 ++++++++++++++++++
>>   qemu-log.c         |  1 +
>>   3 files changed, 20 insertions(+)
>>
>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>> index 57b8c96..ba86606 100644
>> --- a/include/qemu/log.h
>> +++ b/include/qemu/log.h
>> @@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
>>   #define LOG_UNIMP          (1 << 10)
>>   #define LOG_GUEST_ERROR    (1 << 11)
>>   #define CPU_LOG_MMU        (1 << 12)
>> +#define LOG_CMD            (1 << 13)
>>
>>   /* Returns true if a bit is set in the current loglevel mask
>>    */
>> diff --git a/monitor.c b/monitor.c
>> index 4f1ba2f..71810bb 100644
>> --- a/monitor.c
>> +++ b/monitor.c
>> @@ -434,6 +434,12 @@ static void monitor_protocol_emitter(Monitor *mon, QObject *data,
>>       }
>>
>>       monitor_json_emitter(mon, QOBJECT(qmp));
>> +    if (qemu_loglevel_mask(LOG_CMD)) {
>> +        QString *output_json = qobject_to_json_pretty(QOBJECT(qmp));
>> +        qemu_log("qmp response:\n%s\n", output_json->string);
>> +        QDECREF(output_json);
>> +    }
>> +
>
> Uh, _pretty makes this multiple lines.  Is this appropriate for the log
> file?  Finding log message boundaries goes from regular to
> context-free...
>
I think so much more convenient to read the log, for example:
qmp requested:
{
     "execute": "query-block"
}
qmp responsed:
{
     "return": [
         {
             "io-status": "ok",
             "device": "drive-virtio-disk0",
             "locked": false,
             "removable": false,
             "inserted": {
                 "iops_rd": 0,
                 "detect_zeroes": "off",
                 "image": {
                     "snapshots": [
                         {
                             "vm-clock-nsec": 235120743,
                             "name": "snap4",
                             "date-sec": 1444402741,
                             "date-nsec": 246561000,
                             "vm-clock-sec": 42,
                             "id": "2",
                             "vm-state-size": 247252333
                         },
...

if we just use qobject_to_json(), it will be a long string, which may be 
difficult to understand.

> Nitpick: we generally spell it QMP.
>
Ok.

>>       QDECREF(qmp);
>>   }
>>
>> @@ -474,6 +480,11 @@ monitor_qapi_event_queue(QAPIEvent event, QDict *data, Error **errp)
>>                                          evstate->last,
>>                                          now);
>>
>> +    if (qemu_loglevel_mask(LOG_CMD)) {
>> +        QString *output_json = qobject_to_json_pretty(QOBJECT(data));
>> +        qemu_log("qmp event:\n%s\n", output_json->string);
>> +        QDECREF(output_json);
>> +    }
>
> This does *not* log QMP events (the ones put on the wire), it logs
> *QAPI* events, which may or may not put on the wire due to rate
> limiting.
>
> Are you sure we don't want to rate-limit log messages?
>
> If you really want to log QAPI events rather than QMP events, you get to
> explain why in the commit message, and you get to document the
> difference between the log and the actual wire.
>
> But I suspect you merely put this in the wrong place :)
>
>>       /* Rate limit of 0 indicates no throttling */
>>       qemu_mutex_lock(&monitor_lock);
>>       if (!evstate->rate) {
>
> Not logged: the QMP greeting.  If you want to log QMP, log all of QMP.
>
> You can either put the logging of the transmit direction in
> monitor_json_emitter(), or you put it in each of its callers.
>
I agree, just missed this point. In this case, we are interested in 
logging QAPI and QMP events. For QAPI events point logging can be put in 
monitor_qapi_event_emit(), it should solve the problem with rate-limit. 
For QMP(and monitor_json_emitter) more suitable put it in each of its 
callers, because it is not known what is this call(it the request, 
response or event).

>> @@ -2848,6 +2859,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>>       QDict *qdict;
>>       const mon_cmd_t *cmd;
>>
>> +    qemu_log_mask(LOG_CMD, "hmp request:\n%s\n", cmdline);
>> +
>>       cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>>       if (!cmd) {
>>           return;
>> @@ -3823,6 +3836,11 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>>           goto err_out;
>>       }
>>
>> +    if (qemu_loglevel_mask(LOG_CMD)) {
>> +        QString *output_json = output_json = qobject_to_json_pretty(obj);
>> +        qemu_log("qmp request:\n%s\n", output_json->string);
>> +        QDECREF(output_json);
>> +    }
>>       input = qmp_check_input_obj(obj, &local_err);
>>       if (!input) {
>>           qobject_decref(obj);
>
> Nitpick: QMP calls this a command, not a request.
>
It is understood that the request came to execute the command.

>> diff --git a/qemu-log.c b/qemu-log.c
>> index e6d2b3f..ba7b34c 100644
>> --- a/qemu-log.c
>> +++ b/qemu-log.c
>> @@ -98,6 +98,7 @@ 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" },
>>       { 0, NULL, NULL },
>>   };
>
> I can't quite see the use case for logging HMP, but since you wrote it,
> I assume you got one.
>
> Regardless, separate flags and patches for QMP and HMP, please.
>
Ok.

Re: [Qemu-devel] [PATCH 2/3] log: report hmp/qmp command and qmp event

[Markus Armbruster]

Pavel Butsykin <pbutsykin@odin.com> writes:

> On 16.10.2015 10:34, Markus Armbruster wrote:
>> "Denis V. Lunev" <den@openvz.org> writes:
>>
>>> From: Pavel Butsykin <pbutsykin@virtuozzo.com>
>>>
>>> This log would be very welcome for long-term diagnostics of the system
>>> in the production. This log is at least necessary to understand what
>>> has been happened on the system and to identify issues at higher-level
>>> subsystems (libvirt, etc).
>>>
>>> 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 |  1 +
>>>   monitor.c          | 18 ++++++++++++++++++
>>>   qemu-log.c         |  1 +
>>>   3 files changed, 20 insertions(+)
>>>
>>> diff --git a/include/qemu/log.h b/include/qemu/log.h
>>> index 57b8c96..ba86606 100644
>>> --- a/include/qemu/log.h
>>> +++ b/include/qemu/log.h
>>> @@ -41,6 +41,7 @@ static inline bool qemu_log_enabled(void)
>>>   #define LOG_UNIMP          (1 << 10)
>>>   #define LOG_GUEST_ERROR    (1 << 11)
>>>   #define CPU_LOG_MMU        (1 << 12)
>>> +#define LOG_CMD            (1 << 13)
>>>
>>>   /* Returns true if a bit is set in the current loglevel mask
>>>    */
>>> diff --git a/monitor.c b/monitor.c
>>> index 4f1ba2f..71810bb 100644
>>> --- a/monitor.c
>>> +++ b/monitor.c
>>> @@ -434,6 +434,12 @@ static void monitor_protocol_emitter(Monitor *mon, QObject *data,
>>>       }
>>>
>>>       monitor_json_emitter(mon, QOBJECT(qmp));
>>> +    if (qemu_loglevel_mask(LOG_CMD)) {
>>> +        QString *output_json = qobject_to_json_pretty(QOBJECT(qmp));
>>> +        qemu_log("qmp response:\n%s\n", output_json->string);
>>> +        QDECREF(output_json);
>>> +    }
>>> +
>>
>> Uh, _pretty makes this multiple lines.  Is this appropriate for the log
>> file?  Finding log message boundaries goes from regular to
>> context-free...
>>
> I think so much more convenient to read the log, for example:
> qmp requested:
> {
>     "execute": "query-block"
> }
> qmp responsed:
> {
>     "return": [
>         {
>             "io-status": "ok",
>             "device": "drive-virtio-disk0",
>             "locked": false,
>             "removable": false,
>             "inserted": {
>                 "iops_rd": 0,
>                 "detect_zeroes": "off",
>                 "image": {
>                     "snapshots": [
>                         {
>                             "vm-clock-nsec": 235120743,
>                             "name": "snap4",
>                             "date-sec": 1444402741,
>                             "date-nsec": 246561000,
>                             "vm-clock-sec": 42,
>                             "id": "2",
>                             "vm-state-size": 247252333
>                         },
> ...
>
> if we just use qobject_to_json(), it will be a long string, which may
> be difficult to understand.

Log files should be utterly trivial to parse.  That means a rigid
format.

The traditional format is one line per entry, prefixed with a timestamp.

Extracting JSON from such lines and feeding it to a pretty-printer is
bothersome, but it's at least feasible.

Reliably finding log message boundaries in a log file without rules on
message format generally isn't.

I'm not sure how the log.h interface is currently used.  Are there any
rules, or is it a "barf whatever text you like to the log file" thing?

If there are rules, we should stick to them.

If there are none, I'd seriously consider giving up on this log file and
create a new one that's actually parseable.

See also "What's the intended use of log.h logging?"

>> Nitpick: we generally spell it QMP.
>>
> Ok.
>
>>>       QDECREF(qmp);
>>>   }
>>>
>>> @@ -474,6 +480,11 @@ monitor_qapi_event_queue(QAPIEvent event, QDict *data, Error **errp)
>>>                                          evstate->last,
>>>                                          now);
>>>
>>> +    if (qemu_loglevel_mask(LOG_CMD)) {
>>> +        QString *output_json = qobject_to_json_pretty(QOBJECT(data));
>>> +        qemu_log("qmp event:\n%s\n", output_json->string);
>>> +        QDECREF(output_json);
>>> +    }
>>
>> This does *not* log QMP events (the ones put on the wire), it logs
>> *QAPI* events, which may or may not put on the wire due to rate
>> limiting.
>>
>> Are you sure we don't want to rate-limit log messages?
>>
>> If you really want to log QAPI events rather than QMP events, you get to
>> explain why in the commit message, and you get to document the
>> difference between the log and the actual wire.
>>
>> But I suspect you merely put this in the wrong place :)
>>
>>>       /* Rate limit of 0 indicates no throttling */
>>>       qemu_mutex_lock(&monitor_lock);
>>>       if (!evstate->rate) {
>>
>> Not logged: the QMP greeting.  If you want to log QMP, log all of QMP.
>>
>> You can either put the logging of the transmit direction in
>> monitor_json_emitter(), or you put it in each of its callers.
>>
> I agree, just missed this point. In this case, we are interested in
> logging QAPI and QMP events. For QAPI events point logging can be put
> in monitor_qapi_event_emit(), it should solve the problem with
> rate-limit. For QMP(and monitor_json_emitter) more suitable put it in
> each of its callers, because it is not known what is this call(it the
> request, response or event).
>
>>> @@ -2848,6 +2859,8 @@ static void handle_hmp_command(Monitor *mon, const char *cmdline)
>>>       QDict *qdict;
>>>       const mon_cmd_t *cmd;
>>>
>>> +    qemu_log_mask(LOG_CMD, "hmp request:\n%s\n", cmdline);
>>> +
>>>       cmd = monitor_parse_command(mon, &cmdline, mon->cmd_table);
>>>       if (!cmd) {
>>>           return;
>>> @@ -3823,6 +3836,11 @@ static void handle_qmp_command(JSONMessageParser *parser, QList *tokens)
>>>           goto err_out;
>>>       }
>>>
>>> +    if (qemu_loglevel_mask(LOG_CMD)) {
>>> +        QString *output_json = output_json = qobject_to_json_pretty(obj);
>>> +        qemu_log("qmp request:\n%s\n", output_json->string);
>>> +        QDECREF(output_json);
>>> +    }
>>>       input = qmp_check_input_obj(obj, &local_err);
>>>       if (!input) {
>>>           qobject_decref(obj);
>>
>> Nitpick: QMP calls this a command, not a request.
>>
> It is understood that the request came to execute the command.

It's just terminology, but I like *consistent* terminology.
docs/qmp-spec.txt calls it a command, not a request.

>>> diff --git a/qemu-log.c b/qemu-log.c
>>> index e6d2b3f..ba7b34c 100644
>>> --- a/qemu-log.c
>>> +++ b/qemu-log.c
>>> @@ -98,6 +98,7 @@ 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" },
>>>       { 0, NULL, NULL },
>>>   };
>>
>> I can't quite see the use case for logging HMP, but since you wrote it,
>> I assume you got one.
>>
>> Regardless, separate flags and patches for QMP and HMP, please.
>>
> Ok.

[Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Markus Armbruster]

We have a couple of related features, and I'd like to get some clarity
on how exactly they should be used.

1. Tracing

   Documented in docs/tracing.txt.

   Each trace event can be individually controlled with -trace and with
   monitor command trace-event.  Wildcards work.  Monitor command "info
   trace-event" shows their status.

   Supports a wealth of tracing backends: nop (compiles out tracing
   completely), stderr (prints trace to stderr), "simple", "ftrace",
   "dtrace", ...  Range from "trivially easy" to "complex power tool".

2. Ad hoc printing

   We have 108 files with some #define DPRINTF(), and probably some more
   sailing under different flags.  The ones that aren't useless should
   probably be tracepoints.

3. "qemu/log.h" logging

   Sports a "mask", where each bit enables a certain set of log
   messages.  Control the mask with "-d item,..."  Try "-d help" to see
   acceptable items.

   Logs to stderr by default, can be redirected with "-D <logfile>".

   Odd for a log file: no timestamp, but proposed "[PATCH 3/3] log: adds
   a timestamp to each log entry" adds one.

   Log message format is unclear.

   There are no locks beyond the one provided by stdio, and log entries
   appear to be build with multiple calls in places.  I suspect logging
   from more than one thread can mess up the log.

   Currently defined items are:

    const QEMULogItem qemu_log_items[] = {
        { CPU_LOG_TB_OUT_ASM, "out_asm",
          "show generated host assembly code for each compiled TB" },
        { CPU_LOG_TB_IN_ASM, "in_asm",
          "show target assembly code for each compiled TB" },
        { CPU_LOG_TB_OP, "op",
          "show micro ops for each compiled TB" },
        { CPU_LOG_TB_OP_OPT, "op_opt",
          "show micro ops (x86 only: before eflags optimization) and\n"
          "after liveness analysis" },
        { CPU_LOG_INT, "int",
          "show interrupts/exceptions in short format" },
        { CPU_LOG_EXEC, "exec",
          "show trace before each executed TB (lots of logs)" },
        { CPU_LOG_TB_CPU, "cpu",
          "show CPU state before block translation" },
        { CPU_LOG_MMU, "mmu",
          "log MMU-related activities" },
        { CPU_LOG_PCALL, "pcall",
          "x86 only: show protected mode far calls/returns/exceptions" },
        { CPU_LOG_RESET, "cpu_reset",
          "show CPU state before CPU resets" },
        { CPU_LOG_IOPORT, "ioport",
          "show all i/o ports accesses" },
        { LOG_UNIMP, "unimp",
          "log unimplemented functionality" },
        { LOG_GUEST_ERROR, "guest_errors",
          "log when the guest OS does something invalid (eg accessing a\n"
          "non-existent register)" },
        { 0, NULL, NULL },
    };

   Looks like this is basically TCG with a couple of random LOG_UNIMP
   and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
   QEMU log in its current state.

   Should some of these items be tracepoints instead?

   Do we want a general purpose QEMU log?
   
   If yes, should this TCG-ish log become the general purpose QEMU log?

   I'm asking because "[PATCH 2/3] log: report hmp/qmp command and qmp
   event" proposes to log QMP traffic here.  I understand the need for
   logging QMP traffic, but I'm not sure it fits here.

4. Error messages with timestamps

   "-msg timestamp" adds timestamps to the error messages that use the
   proper error reporting interfaces.

   I suspect this is basically a poor work-around for not having a log
   file.

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 16/10/2015 14:33, Markus Armbruster wrote:
>    Looks like this is basically TCG with a couple of random LOG_UNIMP
>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>    QEMU log in its current state.

I think these could become error_report.

Some others (e.g. LOG_IOPORT) can be removed.

LOG_MMU seems to be mostly a ppc thing, could also become a tracepoint.
 Likewise for LOG_PCALL and perhaps LOG_INT.

However, we should at the same time add some functionality to enable
tracepoints more easily, and perhaps enable the stderr tracing backend
by default upstream (downstream can enable stderr+stap; or if they care
a lot about performance disable stderr in favor of stap only).

Paolo

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 16 October 2015 at 13:48, Paolo Bonzini <pbonzini@redhat.com> wrote:
>
>
> On 16/10/2015 14:33, Markus Armbruster wrote:
>>    Looks like this is basically TCG with a couple of random LOG_UNIMP
>>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>>    QEMU log in its current state.
>
> I think these could become error_report.

No; it's important not to print these unless the user really
asked for them (especially the GUEST_ERROR) kind. Otherwise it's
(potentially quite a lot of) unnecessary noise.

> Some others (e.g. LOG_IOPORT) can be removed.
>
> LOG_MMU seems to be mostly a ppc thing, could also become a tracepoint.
>  Likewise for LOG_PCALL and perhaps LOG_INT.

It's also very useful to be able to enable whole *classes* of
tracing (like "tell me whenever my guest OS does something dumb");
does the tracepoint code have any support for this?

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 16/10/2015 14:54, Peter Maydell wrote:
> On 16 October 2015 at 13:48, Paolo Bonzini <pbonzini@redhat.com> wrote:
>>
>>
>> On 16/10/2015 14:33, Markus Armbruster wrote:
>>>    Looks like this is basically TCG with a couple of random LOG_UNIMP
>>>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>>>    QEMU log in its current state.
>>
>> I think these could become error_report.
> 
> No; it's important not to print these unless the user really
> asked for them (especially the GUEST_ERROR) kind. Otherwise it's
> (potentially quite a lot of) unnecessary noise.

I guess it depends then.  If the unimplemented feature is in all
likelihood a showstopper (e.g. setend) it should be unconditionally
enabled, I think.

>> Some others (e.g. LOG_IOPORT) can be removed.
>>
>> LOG_MMU seems to be mostly a ppc thing, could also become a tracepoint.
>>  Likewise for LOG_PCALL and perhaps LOG_INT.
> 
> It's also very useful to be able to enable whole *classes* of
> tracing (like "tell me whenever my guest OS does something dumb");
> does the tracepoint code have any support for this?

That's part of what I mentioned in my message ("add some functionality
to enable tracepoints more easily").  It would be great to have
something like "-d trace:scsi_*" on the command line, integrated with
qemu-log.

So perhaps the place of qemu-log is as a replacement for the stderr
tracing backend?

Paolo

Re: [Qemu-devel] What's the intended use of log.h logging?

[Denis V. Lunev]

On 10/16/2015 04:00 PM, Paolo Bonzini wrote:
>
> On 16/10/2015 14:54, Peter Maydell wrote:
>> On 16 October 2015 at 13:48, Paolo Bonzini <pbonzini@redhat.com> wrote:
>>>
>>> On 16/10/2015 14:33, Markus Armbruster wrote:
>>>>     Looks like this is basically TCG with a couple of random LOG_UNIMP
>>>>     and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>>>>     QEMU log in its current state.
>>> I think these could become error_report.
>> No; it's important not to print these unless the user really
>> asked for them (especially the GUEST_ERROR) kind. Otherwise it's
>> (potentially quite a lot of) unnecessary noise.
> I guess it depends then.  If the unimplemented feature is in all
> likelihood a showstopper (e.g. setend) it should be unconditionally
> enabled, I think.
>
>>> Some others (e.g. LOG_IOPORT) can be removed.
>>>
>>> LOG_MMU seems to be mostly a ppc thing, could also become a tracepoint.
>>>   Likewise for LOG_PCALL and perhaps LOG_INT.
>> It's also very useful to be able to enable whole *classes* of
>> tracing (like "tell me whenever my guest OS does something dumb");
>> does the tracepoint code have any support for this?
> That's part of what I mentioned in my message ("add some functionality
> to enable tracepoints more easily").  It would be great to have
> something like "-d trace:scsi_*" on the command line, integrated with
> qemu-log.
>
> So perhaps the place of qemu-log is as a replacement for the stderr
> tracing backend?
>
> Paolo

The motivation for the patchset is simple. These messages will be quite
useful to understand how things are going. We do not think about
automatic parsing of that logs at all. They should be human-readable
for us to understand the problem.

In general, we should have "normal" locking engine.

Here I mean a non-blocking facility, which should allow to place
arbitrary log message preserving order of that message in
which events have been happen. In general, this is possible
through lockless ring-buffer and a flush thread. Yes, messages
could be lost if this is noted to the log.

I am a bit old-fashioned with this approach, sorry. This information
is at least necessary to guess what operations were performed
with a VM from outside using conventional interfaces.

Thus my approach to the topic is simple. I'd like to put minimal
information at the moment using current API for 2.5 and expect
this merged if possible,

For 2.6 we will replace the engine with one I have described above.
 From my point of view this work should not start new sub-system
but slowly evolve current one.

All bits here a a bit technical without much usage details, but
this is something which should be discussed. With an effective
backend (which does not contradict to the current implementation)
more could be allowed to be logged.

Tracepoints, in general, are designated for the debugging.
Logging is something for post-ship analysis from the customer
report and speaking about [commercially] supported product
running in _production_ you will not be able either to access
customer's host or even customer's network.

Den

Re: [Qemu-devel] What's the intended use of log.h logging?

[Daniel P. Berrange]

On Fri, Oct 16, 2015 at 01:54:40PM +0100, Peter Maydell wrote:
> On 16 October 2015 at 13:48, Paolo Bonzini <pbonzini@redhat.com> wrote:
> >
> >
> > On 16/10/2015 14:33, Markus Armbruster wrote:
> >>    Looks like this is basically TCG with a couple of random LOG_UNIMP
> >>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
> >>    QEMU log in its current state.
> >
> > I think these could become error_report.
> 
> No; it's important not to print these unless the user really
> asked for them (especially the GUEST_ERROR) kind. Otherwise it's
> (potentially quite a lot of) unnecessary noise.
> 
> > Some others (e.g. LOG_IOPORT) can be removed.
> >
> > LOG_MMU seems to be mostly a ppc thing, could also become a tracepoint.
> >  Likewise for LOG_PCALL and perhaps LOG_INT.
> 
> It's also very useful to be able to enable whole *classes* of
> tracing (like "tell me whenever my guest OS does something dumb");
> does the tracepoint code have any support for this?

You can use globs in tracepoint names you want to enable. So if the
tracepoints have structured / well considerd name prefixes, you can
enable classses at once.


Regards,
Daniel
-- 
|: http://berrange.com      -o-    http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org              -o-             http://virt-manager.org :|
|: http://autobuild.org       -o-         http://search.cpan.org/~danberr/ :|
|: http://entangle-photo.org       -o-       http://live.gnome.org/gtk-vnc :|

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 16 October 2015 at 14:26, Daniel P. Berrange <berrange@redhat.com> wrote:
>> It's also very useful to be able to enable whole *classes* of
>> tracing (like "tell me whenever my guest OS does something dumb");
>> does the tracepoint code have any support for this?
>
> You can use globs in tracepoint names you want to enable. So if the
> tracepoints have structured / well considerd name prefixes, you can
> enable classses at once.

...but in practice we don't really do that very much, and we
don't have documented lists of classes which we support either.
Guessing what might be a plausible glob of tracepoint names to
enable seems like a definite step back from the formalized
logging categories we have currently.

-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 16/10/2015 15:29, Peter Maydell wrote:
>> > You can use globs in tracepoint names you want to enable. So if the
>> > tracepoints have structured / well considerd name prefixes, you can
>> > enable classses at once.
> ...but in practice we don't really do that very much, and we
> don't have documented lists of classes which we support either.
> Guessing what might be a plausible glob of tracepoint names to
> enable seems like a definite step back from the formalized
> logging categories we have currently.

We could add "-d trace:help" to list valid tracepoint names.

Paolo

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 16 October 2015 at 14:30, Paolo Bonzini <pbonzini@redhat.com> wrote:
>
>
> On 16/10/2015 15:29, Peter Maydell wrote:
>>> > You can use globs in tracepoint names you want to enable. So if the
>>> > tracepoints have structured / well considerd name prefixes, you can
>>> > enable classses at once.
>> ...but in practice we don't really do that very much, and we
>> don't have documented lists of classes which we support either.
>> Guessing what might be a plausible glob of tracepoint names to
>> enable seems like a definite step back from the formalized
>> logging categories we have currently.
>
> We could add "-d trace:help" to list valid tracepoint names.

I think people are mostly going to care about categories
(eg "enable tracing for device X", or "enable tracing for
all unimplemented features", or "enable a medium level of
debug tracing for device Y".

If we want to get there we need to define standards for
naming tracepoints and enforce them somehow
(subsystem_category_level_tracepointname ?)

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 16/10/2015 15:36, Peter Maydell wrote:
>> We could add "-d trace:help" to list valid tracepoint names.
> 
> I think people are mostly going to care about categories
> (eg "enable tracing for device X", or "enable tracing for
> all unimplemented features", or "enable a medium level of
> debug tracing for device Y".

I hadn't thought about levels, but honestly when I use KVM tracing (which
is often measured in tens of megabytes per run) I don't care.  I just
get a .xz file from the person who reported the bug, with all the events,
and use less/grep on it.

> If we want to get there we need to define standards for
> naming tracepoints and enforce them somehow
> (subsystem_category_level_tracepointname ?)

We're surprisingly good at naming tracepoints.  Only 13 files
do not have a common prefix for their tracepoints, conflicts are rare,
and only a few files could arguably improve their naming:

hw/usb/desc.c                    usb_desc, usb_set, usb_clear                             !!
hw/vfio/platform.c               vfio_platform (except for one)                           !!
migration/savevm.c               savevm, qemu_loadvm, vmstate, qemu_announce_self_iter    !!
target-s390x/mmu_helper.c        (none)                                                   !!
target-sparc/int32_helper.c      int_helper                                               !!
target-sparc/int64_helper.c      int_helper                                               !!
target-sparc/mmu_helper.c        mmu_helper                                               !!
target-sparc/win_helper.c        win_helper                                               !!
xen-hvm.c                        handle_ioreq, cpu_ioreq, xen                             !!

Globbing should suffice, IMHO.

Full list of prefixes under my signature.

Paolo

audio/alsaaudio.c                alsa
audio/ossaudio.c                 oss
balloon.c                        virtio_balloon
block/backup.c                   backup
block.c                          bdrv
block/commit.c                   commit
blockdev.c                       qmp_block
block/mirror.c                   mirror
block/qcow2-cache.c              qcow2
block/qcow2-cluster.c            qcow2
block/qcow2.c                    qcow2
block/qed.c                      qed
block/qed-l2-cache.c             qed
block/qed-table.c                qed
block/raw-posix.c                paio_submit
block/stream.c                   stream
cpu-exec.c                       exec_tb
crypto/tlscredsanon.c            qcrypto_tls_creds_anon
crypto/tlscreds.c                qcrypto_tls_creds
crypto/tlscredsx509.c            qcrypto_tls_creds_x509
crypto/tlssession.c              qcrypto_tls_session
dma-helpers.c                    dma
hw/9pfs/virtio-9p.c              v9fs
hw/acpi/memory_hotplug.c         mhp_acpi
hw/arm/virt-acpi-build.c         virt_acpi
hw/audio/cs4231.c                cs4231
hw/audio/milkymist-ac97.c        milkymist_ac97
hw/block/dataplane/virtio-blk.c  virtio_blk_data_plane
hw/block/hd-geometry.c           hd_geometry
hw/block/virtio-blk.c            virtio_blk
hw/char/escc.c                   escc
hw/char/grlib_apbuart.c          grlib_apbuart
hw/char/lm32_juart.c             lm32_juart
hw/char/lm32_uart.c              lm32_uart
hw/char/milkymist-uart.c         milkymist_uart
hw/char/virtio-console.c         virtio_console
hw/char/virtio-serial-bus.c      virtio_serial
hw/display/g364fb.c              g364fb
hw/display/jazz_led.c            jazz_led
hw/display/milkymist-tmu2.c      milkymist_tmu2
hw/display/milkymist-vgafb.c     milkymist_vgafb_memory
hw/display/qxl.c                 qxl
hw/display/qxl-render.c          qxl_render
hw/display/virtio-gpu.c          virtio_gpu
hw/display/vmware_vga.c          vmware
hw/display/xenfb.c               xenfb
hw/dma/i8257.c                   i8257
hw/dma/rc4030.c                  rc4030, jazzio
hw/dma/sparc32_dma.c             sparc32, espdma, ledma
hw/dma/sun4m_iommu.c             sun4m_iommu
hw/i386/pc.c                     mhp_pc_dimm
hw/i386/xen/xen_platform.c       xen
hw/i386/xen/xen_pvdevice.c       xen_pv_mmio
hw/input/milkymist-softusb.c     milkymist_softusb
hw/input/ps2.c                   ps2
hw/intc/apic.c                   apic
hw/intc/apic_common.c            cpu, apic
hw/intc/grlib_irqmp.c            grlib_irqmp
hw/intc/lm32_pic.c               lm32_pic
hw/intc/s390_flic_kvm.c          flic
hw/intc/slavio_intctl.c          slavio
hw/intc/xics.c                   xics
hw/isa/pc87312.c                 pc87312
hw/misc/eccmemctl.c              ecc
hw/misc/milkymist-hpdmc.c        milkymist_hpdmc_memory
hw/misc/milkymist-pfpu.c         milkymist_pfpu
hw/misc/slavio_misc.c            slavio
hw/net/lance.c                   lance
hw/net/milkymist-minimac2.c      milkymist_minimac2
hw/net/mipsnet.c                 mipsnet
hw/net/opencores_eth.c           open_eth
hw/net/pcnet.c                   pcnet
hw/net/pcnet-pci.c               pcnet
hw/nvram/ds1225y.c               nvram
hw/nvram/fw_cfg.c                fw_cfg
hw/pci/pci.c                     pci_update_mappings
hw/pci/pci_host.c                pci_cfg
hw/ppc/ppc.c                     ppc
hw/ppc/spapr.c                   spapr_cas
hw/ppc/spapr_hcall.c             spapr_cas
hw/ppc/spapr_iommu.c             spapr_iommu
hw/ppc/spapr_pci.c               spapr_pci
hw/s390x/css.c                   css
hw/s390x/virtio-ccw.c            virtio_ccw
hw/scsi/esp.c                    esp
hw/scsi/esp-pci.c                esp_pci
hw/scsi/megasas.c                megasas
hw/scsi/scsi-bus.c               scsi_req, scsi
hw/scsi/vmw_pvscsi.c             pvscsi
hw/sd/milkymist-memcard.c        milkymist_memcard_memory
hw/sparc/leon3.c                 leon3
hw/sparc/sun4m.c                 sun4m_cpu
hw/timer/grlib_gptimer.c         grlib_gptimer
hw/timer/lm32_timer.c            lm32_timer
hw/timer/milkymist-sysctl.c      milkymist_sysctl
hw/timer/slavio_timer.c          slavio
hw/usb/bus.c                     usb_port
hw/usb/core.c                    usb_packet_state
hw/usb/dev-hub.c                 usb_hub
hw/usb/dev-mtp.c                 usb_mtp
hw/usb/dev-uas.c                 usb_uas
hw/usb/hcd-ehci.c                usb_ehci
hw/usb/hcd-ohci.c                usb_ohci
hw/usb/hcd-uhci.c                usb_uhci
hw/usb/hcd-xhci.c                usb_xhci
hw/usb/host-libusb.c             usb_host
hw/vfio/pci.c                    vfio
hw/vfio/pci-quirks.              vfio_quirk
hw/vfio/vfio-common.c            vfio
hw/virtio/dataplane/vring.c      vring
hw/virtio/virtio.c               virtio, virtqueue
hw/virtio/virtio-rng.c           virtio_rng
ioport.c                         cpu
kvm-all.c                        kvm
memory.c                         memory_region_ops
migration.c                      migration, migrate
migration/ram.c                  migration
migration/rdma.c                 qemu_rdma, rdma
monitor.c                        monitor_protocol
qemu-coroutine.c                 qemu_coroutine
qemu-coroutine-lock.c            qemu_co
qemu-file.c                      qemu_file
qom/object.c                     object
spice-qemu-char.c                spice_vmc
target-ppc/kvm.c                 kvm
target-s390x/cpu.c               cpu
target-s390x/ioinst.c            ioinst
target-s390x/kvm.c               kvm
thread-pool.c                    thread_pool
translate-all.c                  translate
ui/console.c                     displaychangelistener, displaysurface, console
ui/gtk.c                         gd
ui/input.c                       input
ui/spice-display.c               qemu_spice
ui/vnc.c                         vnc_key
util/hbitmap.c                   hbitmap
vl.c                             qemu_system
vmstate.c                        vmstate
xen-mapcache.c                   xen

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 16 October 2015 at 15:17, Paolo Bonzini <pbonzini@redhat.com> wrote:
> On 16/10/2015 15:36, Peter Maydell wrote:
>>> We could add "-d trace:help" to list valid tracepoint names.
>>
>> I think people are mostly going to care about categories
>> (eg "enable tracing for device X", or "enable tracing for
>> all unimplemented features", or "enable a medium level of
>> debug tracing for device Y".
>
> I hadn't thought about levels, but honestly when I use KVM tracing (which
> is often measured in tens of megabytes per run) I don't care.

In a lot of cases, especially with the TCG logging, not enabling
voluminous tracing is really important because if you turn it all
on then the system is way too slow (and can behave differently
as a result), and generates gigabytes of trace output. (-d exec
and -d cpu will do this, for instance.)

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 16/10/2015 16:31, Peter Maydell wrote:
> > I hadn't thought about levels, but honestly when I use KVM tracing (which
> > is often measured in tens of megabytes per run) I don't care.
>
> In a lot of cases, especially with the TCG logging, not enabling
> voluminous tracing is really important because if you turn it all
> on then the system is way too slow (and can behave differently
> as a result), and generates gigabytes of trace output. (-d exec
> and -d cpu will do this, for instance.)

Yes, but device models are going to generate orders of magnitude smaller
traces than the CPU.  Since I'm not proposing to drop -d together, but
rather to integrate tracing with it, we can cross that river when we
reach it.

Paolo

Re: [Qemu-devel] What's the intended use of log.h logging?

[Markus Armbruster]

Peter Maydell <peter.maydell@linaro.org> writes:

> On 16 October 2015 at 15:17, Paolo Bonzini <pbonzini@redhat.com> wrote:
>> On 16/10/2015 15:36, Peter Maydell wrote:
>>>> We could add "-d trace:help" to list valid tracepoint names.
>>>
>>> I think people are mostly going to care about categories
>>> (eg "enable tracing for device X", or "enable tracing for
>>> all unimplemented features", or "enable a medium level of
>>> debug tracing for device Y".
>>
>> I hadn't thought about levels, but honestly when I use KVM tracing (which
>> is often measured in tens of megabytes per run) I don't care.
>
> In a lot of cases, especially with the TCG logging, not enabling
> voluminous tracing is really important because if you turn it all
> on then the system is way too slow (and can behave differently
> as a result), and generates gigabytes of trace output. (-d exec
> and -d cpu will do this, for instance.)

This is at least as much an argument for use of tracing as against it.
Tracing is a lot more flexible than log.h, and with the right backend,
it's much more efficient, too.

If the appropriate trace patterns turn out to be too hard to remember,
we can provide canned trace patterns with names that are easy to
remember.

-d could become sugar for a suitable trace patterns.

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 19/10/2015 15:17, Markus Armbruster wrote:
> This is at least as much an argument for use of tracing as against it.
> Tracing is a lot more flexible than log.h, and with the right backend,
> it's much more efficient, too.
> 
> If the appropriate trace patterns turn out to be too hard to remember,
> we can provide canned trace patterns with names that are easy to
> remember.
> 
> -d could become sugar for a suitable trace patterns.

I think that's putting the cart a bit before the horse, since "-d" is
currently not related to tracing at all. :)

Paolo

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 19 October 2015 at 14:17, Markus Armbruster <armbru@redhat.com> wrote:
> Peter Maydell <peter.maydell@linaro.org> writes:
>> In a lot of cases, especially with the TCG logging, not enabling
>> voluminous tracing is really important because if you turn it all
>> on then the system is way too slow (and can behave differently
>> as a result), and generates gigabytes of trace output. (-d exec
>> and -d cpu will do this, for instance.)
>
> This is at least as much an argument for use of tracing as against it.
> Tracing is a lot more flexible than log.h, and with the right backend,
> it's much more efficient, too.
>
> If the appropriate trace patterns turn out to be too hard to remember,
> we can provide canned trace patterns with names that are easy to
> remember.
>
> -d could become sugar for a suitable trace patterns.

I don't object to the use of tracing under the hood, as long as
the user-facing experience remains as good as what we have for -d
at the moment (in terms of it being always present, working the
same for everybody, easily discoverable and simple to use).

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Peter Maydell]

On 16 October 2015 at 13:33, Markus Armbruster <armbru@redhat.com> wrote:
> We have a couple of related features, and I'd like to get some clarity
> on how exactly they should be used.
>
> 1. Tracing
>
>    Documented in docs/tracing.txt.
>
>    Each trace event can be individually controlled with -trace and with
>    monitor command trace-event.  Wildcards work.  Monitor command "info
>    trace-event" shows their status.
>
>    Supports a wealth of tracing backends: nop (compiles out tracing
>    completely), stderr (prints trace to stderr), "simple", "ftrace",
>    "dtrace", ...  Range from "trivially easy" to "complex power tool".

The major problem with this is it is a compile time choice
(especially the choice of backend), and our default backend
is 'nop'.

> 2. Ad hoc printing
>
>    We have 108 files with some #define DPRINTF(), and probably some more
>    sailing under different flags.  The ones that aren't useless should
>    probably be tracepoints.
>
> 3. "qemu/log.h" logging
>
>    Sports a "mask", where each bit enables a certain set of log
>    messages.  Control the mask with "-d item,..."  Try "-d help" to see
>    acceptable items.
>
>    Logs to stderr by default, can be redirected with "-D <logfile>".

This, though it is a bit ad-hoc, always exists, always behaves the
same way, and doesn't require anybody to rebuild QEMU to enable
tracing.

I think having a more consistent approach to logging would be great,
though.

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging?

[Markus Armbruster]

Peter Maydell <peter.maydell@linaro.org> writes:

> On 16 October 2015 at 13:33, Markus Armbruster <armbru@redhat.com> wrote:
>> We have a couple of related features, and I'd like to get some clarity
>> on how exactly they should be used.
>>
>> 1. Tracing
>>
>>    Documented in docs/tracing.txt.
>>
>>    Each trace event can be individually controlled with -trace and with
>>    monitor command trace-event.  Wildcards work.  Monitor command "info
>>    trace-event" shows their status.
>>
>>    Supports a wealth of tracing backends: nop (compiles out tracing
>>    completely), stderr (prints trace to stderr), "simple", "ftrace",
>>    "dtrace", ...  Range from "trivially easy" to "complex power tool".
>
> The major problem with this is it is a compile time choice
> (especially the choice of backend), and our default backend
> is 'nop'.

I think the default is / has become wrong.  Easy enough to fix.

Let's compare log.h and tracing.

Both let you control stuff on the command line and in the monitor.

log.h's unit of control is a mask bit, which controls a canned group of
related messages.

Tracing's unit of control is the individual message.  To control a group
of messages, use globbing.  As long as we use sane names, this is
strictly more powerful than canned group.  When you don't need the
power, globbing can be harder to use than canned group with sensible
names.

log.h can log to stderr, log to a file, or not log at all (default).

Tracing's capabilities depend on a compile time choice:

* You can pick multiple backends.  They're all simultaneously active.
  If we want to support enabling configured backends selectively at
  runtime, that shouldn't be hard.

* If you compile out tracing (configure only backend 'nop'), you can't
  trace.  That's a feature.

* If you pick 'stderr', you can trace to stderr.  Turning it into a
  backend that could alternatively trace to a file (-trace file=FNAME)
  would be easy.  Picking just 'stderr' would be feature-equivalent to
  log.h then.

>> 2. Ad hoc printing
>>
>>    We have 108 files with some #define DPRINTF(), and probably some more
>>    sailing under different flags.  The ones that aren't useless should
>>    probably be tracepoints.
>>
>> 3. "qemu/log.h" logging
>>
>>    Sports a "mask", where each bit enables a certain set of log
>>    messages.  Control the mask with "-d item,..."  Try "-d help" to see
>>    acceptable items.
>>
>>    Logs to stderr by default, can be redirected with "-D <logfile>".
>
> This, though it is a bit ad-hoc, always exists, always behaves the
> same way, and doesn't require anybody to rebuild QEMU to enable
> tracing.

"Always exists" and "doesn't require rebuild" are the same.

For me, "exists unless you compiled it out" would be a (minor)
improvement over "always exists".  That's how tracing will be once we
fix the default backend.

"Always behaves the same way" I interpret as complaint about tracing
user interface complexity.  Flexibility breeds complexity, and when you
don't need the former, you don't want the latter.

While that's a valid argument for a simpler user interface, it's hardly
one for having two separate subsystems!  Pretty sure we could provide
the existing log.h user interface as sugar for tracing if we wanted.

> I think having a more consistent approach to logging would be great,
> though.

Points I'd like to make:

1. Logging is not tracing.  Logging logs events interesting for the
user.  Tracing logs code execution.  It's a debugging aid.  The two
overlap to a degree, but they're not the same.

2. The current use of log.h seems closer to tracing than to logging.

3. I figure our tracing needs could be served by the tracing subsystem
with a few improvements.  The few things log.h can do that tracing can't
yet do should be easy enough to add.  Why have two separate subsystems
then?

4. Logging would be useful, but I feel it shouldn't be shoehorned into
log.h.

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 19 October 2015 at 15:29, Markus Armbruster <armbru@redhat.com> wrote:
> Points I'd like to make:
>
> 1. Logging is not tracing.  Logging logs events interesting for the
> user.  Tracing logs code execution.  It's a debugging aid.  The two
> overlap to a degree, but they're not the same.

In the case of QEMU, the event the user is often interested in
is (guest) code execution...

> 2. The current use of log.h seems closer to tracing than to logging.

Maybe. It gets a fair amount of use for "figure out what my
guest is doing" questions.

> 3. I figure our tracing needs could be served by the tracing subsystem
> with a few improvements.  The few things log.h can do that tracing can't
> yet do should be easy enough to add.  Why have two separate subsystems
> then?

I just feel that the logging subsystem is very simple and easy
to use. The tracing subsystem is far from easy to comprehend.
I'm apprehensive that in the name of simplification we'll end up
deleting the easy to use logging without making the tracing
as easy for end users to use.

> 4. Logging would be useful, but I feel it shouldn't be shoehorned into
> log.h.

The log.h code is definitely intended for our end users to run.
It's true that at the moment we log the things that are easy
to log rather than having the flexibility to log the things
end users would ideally like; but the solution to that is to
improve the logging...

In particular, ideally the logging should allow you to debug or
instrument your guest program without having to care about QEMU's
internals particularly. LOG_UNIMP and LOG_GUEST_ERROR are moving
in that direction.

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging?

[Dr. David Alan Gilbert]

* Peter Maydell (peter.maydell@linaro.org) wrote:
> On 19 October 2015 at 15:29, Markus Armbruster <armbru@redhat.com> wrote:
> > Points I'd like to make:
> >
> > 1. Logging is not tracing.  Logging logs events interesting for the
> > user.  Tracing logs code execution.  It's a debugging aid.  The two
> > overlap to a degree, but they're not the same.
> 
> In the case of QEMU, the event the user is often interested in
> is (guest) code execution...
> 
> > 2. The current use of log.h seems closer to tracing than to logging.
> 
> Maybe. It gets a fair amount of use for "figure out what my
> guest is doing" questions.
> 
> > 3. I figure our tracing needs could be served by the tracing subsystem
> > with a few improvements.  The few things log.h can do that tracing can't
> > yet do should be easy enough to add.  Why have two separate subsystems
> > then?
> 
> I just feel that the logging subsystem is very simple and easy
> to use. The tracing subsystem is far from easy to comprehend.
> I'm apprehensive that in the name of simplification we'll end up
> deleting the easy to use logging without making the tracing
> as easy for end users to use.

When I first looked at it, I thought the same way, but then
I found the stderr mode, and it's really very easy.

Dave

> > 4. Logging would be useful, but I feel it shouldn't be shoehorned into
> > log.h.
> 
> The log.h code is definitely intended for our end users to run.
> It's true that at the moment we log the things that are easy
> to log rather than having the flexibility to log the things
> end users would ideally like; but the solution to that is to
> improve the logging...
> 
> In particular, ideally the logging should allow you to debug or
> instrument your guest program without having to care about QEMU's
> internals particularly. LOG_UNIMP and LOG_GUEST_ERROR are moving
> in that direction.
> 
> thanks
> -- PMM
> 
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [Qemu-devel] What's the intended use of log.h logging?

[Dr. David Alan Gilbert]

* Markus Armbruster (armbru@redhat.com) wrote:
> Peter Maydell <peter.maydell@linaro.org> writes:
> 
> > On 16 October 2015 at 13:33, Markus Armbruster <armbru@redhat.com> wrote:
> >> We have a couple of related features, and I'd like to get some clarity
> >> on how exactly they should be used.
> >>
> >> 1. Tracing
> >>
> >>    Documented in docs/tracing.txt.
> >>
> >>    Each trace event can be individually controlled with -trace and with
> >>    monitor command trace-event.  Wildcards work.  Monitor command "info
> >>    trace-event" shows their status.
> >>
> >>    Supports a wealth of tracing backends: nop (compiles out tracing
> >>    completely), stderr (prints trace to stderr), "simple", "ftrace",
> >>    "dtrace", ...  Range from "trivially easy" to "complex power tool".
> >
> > The major problem with this is it is a compile time choice
> > (especially the choice of backend), and our default backend
> > is 'nop'.
> 
> I think the default is / has become wrong.  Easy enough to fix.
> 
> Let's compare log.h and tracing.
> 
> Both let you control stuff on the command line and in the monitor.
> 
> log.h's unit of control is a mask bit, which controls a canned group of
> related messages.
> 
> Tracing's unit of control is the individual message.  To control a group
> of messages, use globbing.  As long as we use sane names, this is
> strictly more powerful than canned group.  When you don't need the
> power, globbing can be harder to use than canned group with sensible
> names.

Hmm; I don't thinking globbing actually works that well here;
the naming scheme for tracing is a bit difficult since it's based
on function name, and the things you might want to trace a particular
behaviour are typically scattered a bit.
Having said that, the 'canned group' can be solved by some premade
cans of trace elements, although it would be nice to generate
those automatically.

> log.h can log to stderr, log to a file, or not log at all (default).
> 
> Tracing's capabilities depend on a compile time choice:
> 
> * You can pick multiple backends.  They're all simultaneously active.
>   If we want to support enabling configured backends selectively at
>   runtime, that shouldn't be hard.
> 
> * If you compile out tracing (configure only backend 'nop'), you can't
>   trace.  That's a feature.
> 
> * If you pick 'stderr', you can trace to stderr.  Turning it into a
>   backend that could alternatively trace to a file (-trace file=FNAME)
>   would be easy.  Picking just 'stderr' would be feature-equivalent to
>   log.h then.

Yes, that would be useful.

TBH the biggest problem I have with tracing is the flat name space and
the way it's all in one trace-events file/one header.  The names start
getting long/non-obvious quickly, and if you use them in lots of your
patches then bisecting gets really slow since every change causes 
recompilation of the entire code base due to the changed trace header.
I started looking at trying to split trace-events but it's non-trivial
since it's going to need to build multiple trace enums.

Dave
--
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: [Qemu-devel] What's the intended use of log.h logging?

[Kevin Wolf]

Am 19.10.2015 um 16:29 hat Markus Armbruster geschrieben:
> Points I'd like to make:
> 
> 1. Logging is not tracing.  Logging logs events interesting for the
> user.  Tracing logs code execution.  It's a debugging aid.  The two
> overlap to a degree, but they're not the same.

It's hard to draw a line here because qemu is a tool for debugging
guests. So yes, we're logging code execution, which you call tracing.
It's still output meant for the user. I've been using -d often enough,
and you can easily check that I'm not a regular TCG developer. My goal
was debugging the guest, not qemu.

(By the way, it's a shame that -d int doesn't work with KVM.)

> 2. The current use of log.h seems closer to tracing than to logging.
> 
> 3. I figure our tracing needs could be served by the tracing subsystem
> with a few improvements.  The few things log.h can do that tracing can't
> yet do should be easy enough to add.  Why have two separate subsystems
> then?

I'm not objecting to this as long as the currently supported logging
doesn't get worse.

One important point for me is that our logging gives me nicely formatted
messages, for example register dumps. I'm trying to imagine this being
printed through our existing tracing functions - the horror. It would be
like using QMP query-* commands instead of HMP info, simply not made for
human readers.

Kevin

Re: [Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Alex Bennée]

Markus Armbruster <armbru@redhat.com> writes:

> We have a couple of related features, and I'd like to get some clarity
> on how exactly they should be used.

FWIW this is how I view them.

>
> 1. Tracing
>
>    Documented in docs/tracing.txt.
>
>    Each trace event can be individually controlled with -trace and with
>    monitor command trace-event.  Wildcards work.  Monitor command "info
>    trace-event" shows their status.
>
>    Supports a wealth of tracing backends: nop (compiles out tracing
>    completely), stderr (prints trace to stderr), "simple", "ftrace",
>    "dtrace", ...  Range from "trivially easy" to "complex power tool".

While not enabled by default this is the sort of thing that can be
enabled by distros to enable non-invasive tracing of complex behaviour
and performance bottle-necks. Ignoring nop/stderr backends the others
can be used when your looking as system-wide behaviour and interactions
between QEMU, KVM and the kernel.

>
> 2. Ad hoc printing
>
>    We have 108 files with some #define DPRINTF(), and probably some more
>    sailing under different flags.  The ones that aren't useless should
>    probably be tracepoints.

These are basically debug crutches for individual files that are
currently in development or particularly tricky bits of code that
the relevant developer would enable when debugging.

>
> 3. "qemu/log.h" logging
>
>    Sports a "mask", where each bit enables a certain set of log
>    messages.  Control the mask with "-d item,..."  Try "-d help" to see
>    acceptable items.
>
>    Logs to stderr by default, can be redirected with "-D <logfile>".
>
>    Odd for a log file: no timestamp, but proposed "[PATCH 3/3] log: adds
>    a timestamp to each log entry" adds one.
>
>    Log message format is unclear.
>
>    There are no locks beyond the one provided by stdio, and log entries
>    appear to be build with multiple calls in places.  I suspect logging
>    from more than one thread can mess up the log.

As you note bellow most of these are TCG related and currently unlikely
to race with each other due to TCG being single threaded (for now ;-)

>    Currently defined items are:
>
>     const QEMULogItem qemu_log_items[] = {
>         { CPU_LOG_TB_OUT_ASM, "out_asm",
>           "show generated host assembly code for each compiled TB" },
>         { CPU_LOG_TB_IN_ASM, "in_asm",
>           "show target assembly code for each compiled TB" },
>         { CPU_LOG_TB_OP, "op",
>           "show micro ops for each compiled TB" },
>         { CPU_LOG_TB_OP_OPT, "op_opt",
>           "show micro ops (x86 only: before eflags optimization) and\n"
>           "after liveness analysis" },
>         { CPU_LOG_INT, "int",
>           "show interrupts/exceptions in short format" },
>         { CPU_LOG_EXEC, "exec",
>           "show trace before each executed TB (lots of logs)" },
>         { CPU_LOG_TB_CPU, "cpu",
>           "show CPU state before block translation" },
>         { CPU_LOG_MMU, "mmu",
>           "log MMU-related activities" },
>         { CPU_LOG_PCALL, "pcall",
>           "x86 only: show protected mode far calls/returns/exceptions" },
>         { CPU_LOG_RESET, "cpu_reset",
>           "show CPU state before CPU resets" },
>         { CPU_LOG_IOPORT, "ioport",
>           "show all i/o ports accesses" },
>         { LOG_UNIMP, "unimp",
>           "log unimplemented functionality" },
>         { LOG_GUEST_ERROR, "guest_errors",
>           "log when the guest OS does something invalid (eg accessing a\n"
>           "non-existent register)" },
>         { 0, NULL, NULL },
>     };
>
>    Looks like this is basically TCG with a couple of random LOG_UNIMP
>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>    QEMU log in its current state.

However it is useful when users find broken TCG stuff and you want a log
of what happened. Having said that I'm not sure how often that happens
because any non-trivial stuff generates huge logs.

It is the logging I use the most though.

>    Should some of these items be tracepoints instead?

IMHO no because stitching together tracepoints with the log file would
be a pain.

>    Do we want a general purpose QEMU log?

It depends. If you are talking about a standardised log style thing then
maybe but all the current TCG reporting is very specialised and often
over multiple lines.

To my mind a general purpose log should be fairly quiet and just log
extraordinary events (maybe via syslog). The sort of stuff that would be
useful for a user to report when tailing a log before something went
wrong.

>    
>    If yes, should this TCG-ish log become the general purpose QEMU log?
>
>    I'm asking because "[PATCH 2/3] log: report hmp/qmp command and qmp
>    event" proposes to log QMP traffic here.  I understand the need for
>    logging QMP traffic, but I'm not sure it fits here.

Yeah I'm unsure about this as well. To my mind as the QMP is a whole
separate API I'd be tempted to log it separately. 

> 4. Error messages with timestamps
>
>    "-msg timestamp" adds timestamps to the error messages that use the
>    proper error reporting interfaces.
>
>    I suspect this is basically a poor work-around for not having a log
>    file.

Aren't these meant to be user visible errors? "I died because of X"?

-- 
Alex Bennée

Re: [Qemu-devel] What's the intended use of log.h logging?

[Markus Armbruster]

Alex Bennée <alex.bennee@linaro.org> writes:

> Markus Armbruster <armbru@redhat.com> writes:
>
>> We have a couple of related features, and I'd like to get some clarity
>> on how exactly they should be used.
>
> FWIW this is how I view them.
>
>>
>> 1. Tracing
>>
>>    Documented in docs/tracing.txt.
>>
>>    Each trace event can be individually controlled with -trace and with
>>    monitor command trace-event.  Wildcards work.  Monitor command "info
>>    trace-event" shows their status.
>>
>>    Supports a wealth of tracing backends: nop (compiles out tracing
>>    completely), stderr (prints trace to stderr), "simple", "ftrace",
>>    "dtrace", ...  Range from "trivially easy" to "complex power tool".
>
> While not enabled by default this is the sort of thing that can be
> enabled by distros to enable non-invasive tracing of complex behaviour
> and performance bottle-necks. Ignoring nop/stderr backends the others
> can be used when your looking as system-wide behaviour and interactions
> between QEMU, KVM and the kernel.
>
>>
>> 2. Ad hoc printing
>>
>>    We have 108 files with some #define DPRINTF(), and probably some more
>>    sailing under different flags.  The ones that aren't useless should
>>    probably be tracepoints.
>
> These are basically debug crutches for individual files that are
> currently in development or particularly tricky bits of code that
> the relevant developer would enable when debugging.

Modern code should probably use tracing for this purpose except where
its (small!) overhead can't be tolerated.

>> 3. "qemu/log.h" logging
>>
>>    Sports a "mask", where each bit enables a certain set of log
>>    messages.  Control the mask with "-d item,..."  Try "-d help" to see
>>    acceptable items.
>>
>>    Logs to stderr by default, can be redirected with "-D <logfile>".
>>
>>    Odd for a log file: no timestamp, but proposed "[PATCH 3/3] log: adds
>>    a timestamp to each log entry" adds one.
>>
>>    Log message format is unclear.
>>
>>    There are no locks beyond the one provided by stdio, and log entries
>>    appear to be build with multiple calls in places.  I suspect logging
>>    from more than one thread can mess up the log.
>
> As you note bellow most of these are TCG related and currently unlikely
> to race with each other due to TCG being single threaded (for now ;-)

Argument against proliferation to subsystems that can run in other
threads.

>>    Currently defined items are:
>>
>>     const QEMULogItem qemu_log_items[] = {
>>         { CPU_LOG_TB_OUT_ASM, "out_asm",
>>           "show generated host assembly code for each compiled TB" },
>>         { CPU_LOG_TB_IN_ASM, "in_asm",
>>           "show target assembly code for each compiled TB" },
>>         { CPU_LOG_TB_OP, "op",
>>           "show micro ops for each compiled TB" },
>>         { CPU_LOG_TB_OP_OPT, "op_opt",
>>           "show micro ops (x86 only: before eflags optimization) and\n"
>>           "after liveness analysis" },
>>         { CPU_LOG_INT, "int",
>>           "show interrupts/exceptions in short format" },
>>         { CPU_LOG_EXEC, "exec",
>>           "show trace before each executed TB (lots of logs)" },
>>         { CPU_LOG_TB_CPU, "cpu",
>>           "show CPU state before block translation" },
>>         { CPU_LOG_MMU, "mmu",
>>           "log MMU-related activities" },
>>         { CPU_LOG_PCALL, "pcall",
>>           "x86 only: show protected mode far calls/returns/exceptions" },
>>         { CPU_LOG_RESET, "cpu_reset",
>>           "show CPU state before CPU resets" },
>>         { CPU_LOG_IOPORT, "ioport",
>>           "show all i/o ports accesses" },
>>         { LOG_UNIMP, "unimp",
>>           "log unimplemented functionality" },
>>         { LOG_GUEST_ERROR, "guest_errors",
>>           "log when the guest OS does something invalid (eg accessing a\n"
>>           "non-existent register)" },
>>         { 0, NULL, NULL },
>>     };
>>
>>    Looks like this is basically TCG with a couple of random LOG_UNIMP
>>    and LOG_GUEST_ERROR thrown in.  It's definitely not a general purpose
>>    QEMU log in its current state.
>
> However it is useful when users find broken TCG stuff and you want a log
> of what happened. Having said that I'm not sure how often that happens
> because any non-trivial stuff generates huge logs.
>
> It is the logging I use the most though.
>
>>    Should some of these items be tracepoints instead?
>
> IMHO no because stitching together tracepoints with the log file would
> be a pain.

Should *all* of them use tracepoints?

If not, sufficiently fine-grained timestamps could reduce the pain.

Alternatively, we could have a "trace to text file" backend that uses
the same file as log.h.

>>    Do we want a general purpose QEMU log?
>
> It depends. If you are talking about a standardised log style thing then
> maybe but all the current TCG reporting is very specialised and often
> over multiple lines.

My current understanding of the TCG reporting is that it's a debugging
aid, not a log for users.

> To my mind a general purpose log should be fairly quiet and just log
> extraordinary events (maybe via syslog). The sort of stuff that would be
> useful for a user to report when tailing a log before something went
> wrong.

Yes.

>>    
>>    If yes, should this TCG-ish log become the general purpose QEMU log?
>>
>>    I'm asking because "[PATCH 2/3] log: report hmp/qmp command and qmp
>>    event" proposes to log QMP traffic here.  I understand the need for
>>    logging QMP traffic, but I'm not sure it fits here.
>
> Yeah I'm unsure about this as well. To my mind as the QMP is a whole
> separate API I'd be tempted to log it separately. 
>
>> 4. Error messages with timestamps
>>
>>    "-msg timestamp" adds timestamps to the error messages that use the
>>    proper error reporting interfaces.
>>
>>    I suspect this is basically a poor work-around for not having a log
>>    file.
>
> Aren't these meant to be user visible errors? "I died because of X"?

If we had a general purpose log, then errors would also go there, and
get timestamped there like everything else.  No real need to optionally
timestamp them on stderr then.

Re: [Qemu-devel] What's the intended use of log.h logging?

[Peter Maydell]

On 19 October 2015 at 15:52, Markus Armbruster <armbru@redhat.com> wrote:
> My current understanding of the TCG reporting is that it's a debugging
> aid, not a log for users.

It is in my view an aid for users to debug their guest code.
(Sometimes it turns out that the problem is "a QEMU bug resulted
in our doing the wrong thing for a valid guest", but very often
the problem is "the guest code was buggy and QEMU correctly
handled it as it crashed or went into an infinite loop". Being
able to look at logs of what got executed is very handy in
demonstrating this.)

-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Stefan Hajnoczi]

Two useful aspects for observability:

1. Logging

Error messages, rate-limited warnings, and important troubleshooting
information for users.

Audience: Users, system administrators, developers

2. Tracing

Internal state changes and events for performance analysis.

Audience: Developers


DPRINTF() falls under both #1 and #2.  Care needs to be taken to
separate the logging from the tracing when converting DPRINTF().

Side note: we don't have effect "once only" or rate-limiting built into
error_report().  Guest-triggerable errors or warnings should be limited
to prevent log flooding.

It would be nice to unify TCG's "qemu log" and error_report() into a
single logging mechanism that is thread-safe and has rate-limiting.

Stefan

Re: [Qemu-devel] What's the intended use of log.h logging?

[Denis V. Lunev]

On 10/21/2015 01:41 PM, Stefan Hajnoczi wrote:
> Two useful aspects for observability:
>
> 1. Logging
>
> Error messages, rate-limited warnings, and important troubleshooting
> information for users.
>
> Audience: Users, system administrators, developers
>
> 2. Tracing
>
> Internal state changes and events for performance analysis.
>
> Audience: Developers
>
>
> DPRINTF() falls under both #1 and #2.  Care needs to be taken to
> separate the logging from the tracing when converting DPRINTF().
>
> Side note: we don't have effect "once only" or rate-limiting built into
> error_report().  Guest-triggerable errors or warnings should be limited
> to prevent log flooding.
>
> It would be nice to unify TCG's "qemu log" and error_report() into a
> single logging mechanism that is thread-safe and has rate-limiting.
>
> Stefan
Sounds very good to me.

Short and simple.

Den

Re: [Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Peter Maydell]

On 21 October 2015 at 11:41, Stefan Hajnoczi <stefanha@redhat.com> wrote:
> DPRINTF() falls under both #1 and #2.  Care needs to be taken to
> separate the logging from the tracing when converting DPRINTF().
>
> Side note: we don't have effect "once only" or rate-limiting built into
> error_report().  Guest-triggerable errors or warnings should be limited
> to prevent log flooding.
>
> It would be nice to unify TCG's "qemu log" and error_report() into a
> single logging mechanism that is thread-safe and has rate-limiting.

As long as you can disable the rate-limiting: for almost all
of the use cases for the qemu-log code you really don't want
to have it drop logging messages.

thanks
-- PMM

Re: [Qemu-devel] What's the intended use of log.h logging? (was: [PATCH 2/3] log: report hmp/qmp command and qmp event)

[Stefan Hajnoczi]

On Wed, Oct 21, 2015 at 01:22:22PM +0100, Peter Maydell wrote:
> On 21 October 2015 at 11:41, Stefan Hajnoczi <stefanha@redhat.com> wrote:
> > DPRINTF() falls under both #1 and #2.  Care needs to be taken to
> > separate the logging from the tracing when converting DPRINTF().
> >
> > Side note: we don't have effect "once only" or rate-limiting built into
> > error_report().  Guest-triggerable errors or warnings should be limited
> > to prevent log flooding.
> >
> > It would be nice to unify TCG's "qemu log" and error_report() into a
> > single logging mechanism that is thread-safe and has rate-limiting.
> 
> As long as you can disable the rate-limiting: for almost all
> of the use cases for the qemu-log code you really don't want
> to have it drop logging messages.

In the Linux kernel there are a few primitives:

printk() - plain old printf
printk_once() - uses a static bool for once-only semantics,
                modulo races between CPUs
printk_ratelimited() - time-based rate-limiting

(And if you need to configure the ratelimit threshold, you can use the
underlying __ratelimit() function.)

The same could work for QEMU.  Existing "qemu log" stuff is mostly
printk().  Any messages that are not errors or warnings don't need
rate-limiting because they shouldn't be enabled by default (and when you
do want them for troubleshooting, then rate-limiting gets in the way).

Stefan

Re: [Qemu-devel] What's the intended use of log.h logging?

[Paolo Bonzini]

On 22/10/2015 14:26, Stefan Hajnoczi wrote:
> printk() - plain old printf
> printk_once() - uses a static bool for once-only semantics,
>                 modulo races between CPUs
> printk_ratelimited() - time-based rate-limiting
> 
> (And if you need to configure the ratelimit threshold, you can use the
> underlying __ratelimit() function.)
> 
> The same could work for QEMU.  Existing "qemu log" stuff is mostly
> printk().  Any messages that are not errors or warnings don't need
> rate-limiting because they shouldn't be enabled by default (and when you
> do want them for troubleshooting, then rate-limiting gets in the way).

Actually, most of the "qemu log" stuff is TCG tracing.

UNIMP and GUEST_ERROR are not tracing, and could indeed go to stderr
with a rate-limiter (with a "-msg ratelimit=no" option).

I agree with you about DPRINTF being sometimes tracing and sometimes
logging.

I'm planning to integrate the stderr tracing backend with qemu log.  I
think this is the most pressing need, and I think I can have some
patches ready for comments on Monday.  It depends on whether I'll decide
to play with QEMU or LEGO Digital Designer on the way to Seoul.

Second, we can integrate qemu log with "-msg timestamp=yes" and add the
above rate-limiting functionality.

Paolo

[Qemu-devel] [PATCH 3/3] log: adds a timestamp to each log entry

[Denis V. Lunev]

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)
 
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 },
 };
 
-- 
2.1.4

Re: [Qemu-devel] [PATCH 3/3] log: adds a timestamp to each log entry

[Markus Armbruster]

"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 },
>  };

Re: [Qemu-devel] [PATCH 3/3] log: adds a timestamp to each log entry

[Pavel Butsykin]

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 },
>>   };

Re: [Qemu-devel] [PATCH 3/3] log: adds a timestamp to each log entry

[Markus Armbruster]

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 },
>>>   };

Re: [Qemu-devel] [PATCH 0/3] QEMU logging improvements

[Kashyap Chamarthy]

On Thu, Oct 15, 2015 at 10:30:21AM +0300, Denis V. Lunev wrote:
> The following is done:
> - QMP/HMP events are now logged

I applied this patch series locally, and tried to test it the below way:

Launch a minimal QEMU instance:

  $ /home/kashyapc/build/build-qemu-upstream/x86_64-softmmu/qemu-system-x86_64 \
   -nographic                      \
   -nodefconfig                    \
   -nodefaults                     \
   -m 2048                         \
   -cpu SandyBridge                \
   -device virtio-scsi-pci,id=scsi \
   -device virtio-serial-pci       \
   -drive file=./cirros.qcow2,if=virtio,cache=writeback \
   -serial stdio \
   -D ./output-of-qemu.txt \
   -qmp unix:./qmp-sock,server
    
And, issued QMP commands via `qmp-shell`:

  $ ./qmp-shell /export/qmp-sock
  Welcome to the QMP low-level shell!
  Connected to QEMU 2.4.50
  (QEMU)
  (QEMU) query-status
  {"return": {"status": "running", "singlestep": false, "running": true}}
  (QEMU)
  (QEMU) blockdev-snapshot-internal-sync device=virtio0 name=snapshot1
  {"return": {}}

As we can see, the QMP commands gets successfully invoked, but nothing
gets logged to the output-of-qemu.txt file.  Maybe because everything is
logged onto my stdout of qmp-shell?

A couple of related questions:

  - Is the way I supplied '-D' option correct?  If so, why the
    output-of-qemu.txt file does not get created?  _Should_ it?

  - If I `touch output-of-qemu.txt`, then re-try issuing QMP commmands
    from 'qmp-shell', still, nothing gets logged to it.  Probably
    because only stderr is supposed to get logged to '-D logfile'?

Do I have to turn on any other special knob to take advantage of
LOG_CMD/LOG_TIME flags mentioned in your patch[1]?

I'm pretty sure I'm missing something. . .

[1] http://lists.nongnu.org/archive/html/qemu-devel/2015-10/msg03316.html

> - timestamp is added to the log message
> - arguments of qemu_log/qemu_log_mask are not calculated now if the log
>   is disabled
> 
> These patches are sent in the hope that it is not too late for QEMU 2.5.
> 
> Logging subsystem in QEMU looks rudimentary to me and should be definitely
> improved, f.e. log on stalled NFS could ruin the system completely. Anyway,
> it is too late for this at the moment.
> 
> Signed-off-by: Denis V. Lunev <den@openvz.org>
> CC: Pavel Butsykin <pbutsykin@virtuozzo.com>
> 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>
> 
> 

-- 
/kashyap

Re: [Qemu-devel] [PATCH 0/3] QEMU logging improvements

[Pavel Butsykin]

On 15.10.2015 17:49, Kashyap Chamarthy wrote:
> On Thu, Oct 15, 2015 at 10:30:21AM +0300, Denis V. Lunev wrote:
>> The following is done:
>> - QMP/HMP events are now logged
>
> I applied this patch series locally, and tried to test it the below way:
>
> Launch a minimal QEMU instance:
>
>    $ /home/kashyapc/build/build-qemu-upstream/x86_64-softmmu/qemu-system-x86_64 \
>     -nographic                      \
>     -nodefconfig                    \
>     -nodefaults                     \
>     -m 2048                         \
>     -cpu SandyBridge                \
>     -device virtio-scsi-pci,id=scsi \
>     -device virtio-serial-pci       \
>     -drive file=./cirros.qcow2,if=virtio,cache=writeback \
>     -serial stdio \
>     -D ./output-of-qemu.txt \
>     -qmp unix:./qmp-sock,server
>
> And, issued QMP commands via `qmp-shell`:
>
>    $ ./qmp-shell /export/qmp-sock
>    Welcome to the QMP low-level shell!
>    Connected to QEMU 2.4.50
>    (QEMU)
>    (QEMU) query-status
>    {"return": {"status": "running", "singlestep": false, "running": true}}
>    (QEMU)
>    (QEMU) blockdev-snapshot-internal-sync device=virtio0 name=snapshot1
>    {"return": {}}
>
> As we can see, the QMP commands gets successfully invoked, but nothing
> gets logged to the output-of-qemu.txt file.  Maybe because everything is
> logged onto my stdout of qmp-shell?
>
> A couple of related questions:
>
>    - Is the way I supplied '-D' option correct?  If so, why the
>      output-of-qemu.txt file does not get created?  _Should_ it?
>
>    - If I `touch output-of-qemu.txt`, then re-try issuing QMP commmands
>      from 'qmp-shell', still, nothing gets logged to it.  Probably
>      because only stderr is supposed to get logged to '-D logfile'?
>
> Do I have to turn on any other special knob to take advantage of
> LOG_CMD/LOG_TIME flags mentioned in your patch[1]?
>
> I'm pretty sure I'm missing something. . .
>
> [1] http://lists.nongnu.org/archive/html/qemu-devel/2015-10/msg03316.html
>
>> - timestamp is added to the log message
>> - arguments of qemu_log/qemu_log_mask are not calculated now if the log
>>    is disabled
>>
>> These patches are sent in the hope that it is not too late for QEMU 2.5.
>>
>> Logging subsystem in QEMU looks rudimentary to me and should be definitely
>> improved, f.e. log on stalled NFS could ruin the system completely. Anyway,
>> it is too late for this at the moment.
>>
>> Signed-off-by: Denis V. Lunev <den@openvz.org>
>> CC: Pavel Butsykin <pbutsykin@virtuozzo.com>
>> 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>
>>
>>
>

You forgot to specify the mask: -d cmd,time

qemu$ qemu-system-x86_64 -h|grep log
...
-d item1,...    enable logging of specified items (use '-d help' for a 
list of log items)
-D logfile      output log to logfile (default stderr)

So it should work:
     $ 
/home/kashyapc/build/build-qemu-upstream/x86_64-softmmu/qemu-system-x86_64 \
      -nographic                      \
      -nodefconfig                    \
      -nodefaults                     \
      -m 2048                         \
      -cpu SandyBridge                \
      -device virtio-scsi-pci,id=scsi \
      -device virtio-serial-pci       \
      -drive file=./cirros.qcow2,if=virtio,cache=writeback \
      -serial stdio \
      -D ./output-of-qemu.txt \
      -d cmd,time \
      -qmp unix:./qmp-sock,server

Re: [Qemu-devel] [PATCH 0/3] QEMU logging improvements

[Kashyap Chamarthy]

On Thu, Oct 15, 2015 at 06:18:31PM +0300, Pavel Butsykin wrote:
> 
> On 15.10.2015 17:49, Kashyap Chamarthy wrote:
> >On Thu, Oct 15, 2015 at 10:30:21AM +0300, Denis V. Lunev wrote:
> >>The following is done:
> >>- QMP/HMP events are now logged
> >
> >I applied this patch series locally, and tried to test it the below way:
> >
> >Launch a minimal QEMU instance:
> >
> >   $ /home/kashyapc/build/build-qemu-upstream/x86_64-softmmu/qemu-system-x86_64 \
> >    -nographic                      \
> >    -nodefconfig                    \
> >    -nodefaults                     \
> >    -m 2048                         \
> >    -cpu SandyBridge                \
> >    -device virtio-scsi-pci,id=scsi \
> >    -device virtio-serial-pci       \
> >    -drive file=./cirros.qcow2,if=virtio,cache=writeback \
> >    -serial stdio \
> >    -D ./output-of-qemu.txt \
> >    -qmp unix:./qmp-sock,server
> >
> >And, issued QMP commands via `qmp-shell`:
> >
> >   $ ./qmp-shell /export/qmp-sock
> >   Welcome to the QMP low-level shell!
> >   Connected to QEMU 2.4.50
> >   (QEMU)
> >   (QEMU) query-status
> >   {"return": {"status": "running", "singlestep": false, "running": true}}
> >   (QEMU)
> >   (QEMU) blockdev-snapshot-internal-sync device=virtio0 name=snapshot1
> >   {"return": {}}

[. . .]

> You forgot to specify the mask: -d cmd,time
> 
> qemu$ qemu-system-x86_64 -h|grep log
> ...
> -d item1,...    enable logging of specified items (use '-d help' for a list
> of log items)

Ah, my bad.  Thanks for pointing it out, Pavel.

> -D logfile      output log to logfile (default stderr)
> 
> So it should work:
>     $
> /home/kashyapc/build/build-qemu-upstream/x86_64-softmmu/qemu-system-x86_64 \
>      -nographic                      \
>      -nodefconfig                    \
>      -nodefaults                     \
>      -m 2048                         \
>      -cpu SandyBridge                \
>      -device virtio-scsi-pci,id=scsi \
>      -device virtio-serial-pci       \
>      -drive file=./cirros.qcow2,if=virtio,cache=writeback \
>      -serial stdio \
>      -D ./output-of-qemu.txt \
>      -d cmd,time \
>      -qmp unix:./qmp-sock,server
> 

Yep, '-d cmd,time' perfectly logs the QMP requests/response, on stdio,
when I invoke QMP commands from a different shell:


    $ ./qemu-system-x86_64 \
    [. . .]
    2015-10-15 17:38:58.474 qmp request:
    {
        "execute": "blockdev-snapshot-internal-sync",
        "arguments": {
            "name": "snapshot2",
            "device": "virtio0"
        }
    }
    2015-10-15 17:38:58.488 qmp response:
    {
        "return": {
        }
    }
    2015-10-15 17:39:25.743 qmp request:
    {
        "execute": "quit",
        "arguments": {
        }
    }
    2015-10-15 17:39:25.743 qmp response:
    {
        "return": {
        }
    }
    2015-10-15 17:39:25.744 qmp event:
    {
        "timestamp": {
            "seconds": 1444923565,
            "microseconds": 744211
        },
        "event": "SHUTDOWN"
    }


    * * *

Also, Stefan Hajnoczi pointed out on IRC that: "-D is mainly a TCG
thing.  There are plenty of fprintf(stderr) calls in QEMU".  So, the
stderr might not be affected by it.


-- 
/kashyap

Re: [Qemu-devel] [PATCH 0/3] QEMU logging improvements

[Markus Armbruster]

"Denis V. Lunev" <den@openvz.org> writes:

> The following is done:
> - QMP/HMP events are now logged
> - timestamp is added to the log message
> - arguments of qemu_log/qemu_log_mask are not calculated now if the log
>   is disabled
>
> These patches are sent in the hope that it is not too late for QEMU 2.5.
>
> Logging subsystem in QEMU looks rudimentary to me and should be definitely
> improved, f.e. log on stalled NFS could ruin the system completely. Anyway,
> it is too late for this at the moment.

Logging QMP traffic makes sense to me.

However, I don't think logging QMP/HMP traffic to the existing -D
logfile is a good idea, because in its current state, that logfile is
mostly for TCG tracing.

Regardless, this series has led to a fruitful (I think) discussion of
logging and tracing ("What's the intended use of log.h logging?"), and
then to Paolo's "[PATCH 0/9] simplify usage of tracepoints, and connect
them to logging".  Let's see where this leads us, and how much we can
still do for 2.5.