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@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