[libvirt] [PATCH 1/7] Reduce performance overhead of the global log buffer

[Eric Blake]

On 03/03/2014 12:18 PM, Daniel P. Berrange wrote:
> With the vast number of log debug statements in the code, the
> logging framework has a measurable performance impact on libvirt
> code, particularly in the daemon event loop.
> 
> The global log buffer records every single log message triggered
> whether anyone cares to see them or not. This makes it impossible
> to eliminate the overhead of printf format expansions in any of
> the logging code. It is possible to disable the global log buffer
> in libvirtd itself, but this doesn't help client side library
> code. Also even if disabled by the config file, the existance of

s/existance/existence/

> the feature makes other performance improvements in the logging
> layer impossible.
> 
> Instead of logging every single message to the global buffer, only
> log messages that pass the log filters. This if libvirtd is set
> to have log_filters="1:libvirt 1:qemu" the global log buffer will
> only get filled with those messages instead of everything. This
> reduces the performance burden, as well as improving the signal
> to noise ratio of the log buffer.

For reproducible errors, this is fine - we simply tell a person to
reproduce the crash with the filters that we think are relevant to the
crash.  For hard-to-reproduce errors, it means an initial report might
no longer contain the vital clue - but then again, if we have such a low
signal-to-noise ratio, the vital clue may have been flushed out of the
circular log by virtue of the amount of other verbose logging, and is
hard to locate anyways.  So I'm okay with this patch.

> 
> As a quick benchmark, a demo program that registers 500 file
> descriptors with the event loop (eg equiv of 500 QEMU monitor
> commands), creates pending read I/O on every FD, and then runs
> virEventRunDefaultImpl() took 1 minute 40 seconds todo 51200

s/todo/to do/

> iterations with nearly all the time shown against the logging
> code. After this optimization it only takes 4.6 seconds.
> 
> Signed-off-by: Daniel P. Berrange <berrange at redhat.com>
> ---
>  src/util/virlog.c | 6 +-----
>  1 file changed, 1 insertion(+), 5 deletions(-)
> 
> diff --git a/src/util/virlog.c b/src/util/virlog.c
> index 68af0f3..e9bd61b 100644
> --- a/src/util/virlog.c
> +++ b/src/util/virlog.c
> @@ -833,7 +833,7 @@ virLogVMessage(virLogSource source,
>          emit = false;
>      }
>  
> -    if (!emit && ((virLogBuffer == NULL) || (virLogSize <= 0)))
> +    if (!emit)
>          goto cleanup;

This skips the printf() overhead.

>  
>      /*
> @@ -862,11 +862,7 @@ virLogVMessage(virLogSource source,
>      virLogStr(timestamp);
>      virLogStr(": ");
>      virLogStr(msg);
> -    virLogUnlock();
> -    if (!emit)
> -        goto cleanup;
>  
> -    virLogLock();

Why were we unlocking and relocking anyways?  Less overhead than above,
but also a reasonable change.

ACK.

-- 
Eric Blake   eblake redhat com    +1-919-301-3266
Libvirt virtualization library http://libvirt.org

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 604 bytes
Desc: OpenPGP digital signature
URL: <http://listman.redhat.com/archives/libvir-list/attachments/20140304/2d098dd6/attachment-0001.sig>