Re: [libvirt] [PATCH 1/7] Reduce performance overhead of the global log buffer
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(a)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
Attachments:
- signature.asc (application/pgp-signature — 604 bytes)