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

["Denis V. Lunev" <den@openvz.org>]

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.