[libvirt] [PATCH 0/2] qemu: Don't log partial buffer reads from qemu monitor
I was debugging a case where 200 snapshots of a disk would result in a VERY long reconnect time after libvirtd restart when debug logging was enabled. I've figured out that qemu responds with 9MiB of json after calling "query-named-block-nodes" and this resulted in > 26 GiB of libvirtd debug log just to process the message. I'll report the qemu flaw separately. Peter Krempa (2): util: probe: Add quiet versions of the "PROBE" macro qemu: monitor: Decrease logging verbosity src/qemu/qemu_monitor.c | 4 ++-- src/qemu/qemu_monitor_json.c | 3 +++ src/util/virprobe.h | 8 ++++++++ 3 files changed, 13 insertions(+), 2 deletions(-) -- 2.15.0
PROBE macro adds a loging entry, when used in places seeing a lot of traffic this can cause a significant slowdown. --- src/util/virprobe.h | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/util/virprobe.h b/src/util/virprobe.h index 1baec98f78..88cda2104f 100644 --- a/src/util/virprobe.h +++ b/src/util/virprobe.h @@ -90,11 +90,19 @@ PROBE_EXPAND(LIBVIRT_ ## NAME, \ VIR_ADD_CASTS(__VA_ARGS__)); \ } + +# define PROBE_QUIET(NAME, FMT, ...) \ + if (LIBVIRT_ ## NAME ## _ENABLED()) { \ + PROBE_EXPAND(LIBVIRT_ ## NAME, \ + VIR_ADD_CASTS(__VA_ARGS__)); \ + } # else # define PROBE(NAME, FMT, ...) \ VIR_INFO_INT(&virLogSelf, \ __FILE__, __LINE__, __func__, \ #NAME ": " FMT, __VA_ARGS__); + +# define PROBE_QUIET(NAME, FMT, ...) # endif #endif /* __VIR_PROBE_H__ */ -- 2.15.0
On 12/21/2017 05:16 AM, Peter Krempa wrote:
PROBE macro adds a loging entry, when used in places seeing a lot of
s/loging/logging/
traffic this can cause a significant slowdown. --- src/util/virprobe.h | 8 ++++++++ 1 file changed, 8 insertions(+)
-- Eric Blake, Principal Software Engineer Red Hat, Inc. +1-919-301-3266 Virtualization: qemu.org | libvirt.org
The PROBE macro used in qemuMonitorIOProcess and the VIR_DEBUG message in qemuMonitorJSONIOProcess create a lot of logging churn when debug logging is enabled during monitor communication. The messages logged from the PROBE macro are rather useless since they are reporting the partial state of receiving the reply from qemu. The actuall full reply is still logged in qemuMonitorJSONIOProcessLine once the full message is received. --- src/qemu/qemu_monitor.c | 4 ++-- src/qemu/qemu_monitor_json.c | 3 +++ 2 files changed, 5 insertions(+), 2 deletions(-) diff --git a/src/qemu/qemu_monitor.c b/src/qemu/qemu_monitor.c index 4db12c512a..046caf001c 100644 --- a/src/qemu/qemu_monitor.c +++ b/src/qemu/qemu_monitor.c @@ -435,8 +435,8 @@ qemuMonitorIOProcess(qemuMonitorPtr mon) # endif #endif - PROBE(QEMU_MONITOR_IO_PROCESS, - "mon=%p buf=%s len=%zu", mon, mon->buffer, mon->bufferOffset); + PROBE_QUIET(QEMU_MONITOR_IO_PROCESS, "mon=%p buf=%s len=%zu", + mon, mon->buffer, mon->bufferOffset); if (mon->json) len = qemuMonitorJSONIOProcess(mon, diff --git a/src/qemu/qemu_monitor_json.c b/src/qemu/qemu_monitor_json.c index e45868b01f..ea1b8e1f5f 100644 --- a/src/qemu/qemu_monitor_json.c +++ b/src/qemu/qemu_monitor_json.c @@ -259,7 +259,10 @@ int qemuMonitorJSONIOProcess(qemuMonitorPtr mon, } } +#if DEBUG_IO VIR_DEBUG("Total used %d bytes out of %zd available in buffer", used, len); +#endif + return used; } -- 2.15.0
On 12/21/2017 05:16 AM, Peter Krempa wrote:
The PROBE macro used in qemuMonitorIOProcess and the VIR_DEBUG message in qemuMonitorJSONIOProcess create a lot of logging churn when debug logging is enabled during monitor communication.
The messages logged from the PROBE macro are rather useless since they are reporting the partial state of receiving the reply from qemu. The actuall full reply is still logged in qemuMonitorJSONIOProcessLine once
s/actuall/actual/
the full message is received. --- src/qemu/qemu_monitor.c | 4 ++-- src/qemu/qemu_monitor_json.c | 3 +++ 2 files changed, 5 insertions(+), 2 deletions(-)
-- Eric Blake, Principal Software Engineer Red Hat, Inc. +1-919-301-3266 Virtualization: qemu.org | libvirt.org
On Thu, Dec 21, 2017 at 12:16:50PM +0100, Peter Krempa wrote:
I was debugging a case where 200 snapshots of a disk would result in a VERY long reconnect time after libvirtd restart when debug logging was enabled.
I've figured out that qemu responds with 9MiB of json after calling "query-named-block-nodes" and this resulted in > 26 GiB of libvirtd debug log just to process the message.
I'll report the qemu flaw separately.
Peter Krempa (2): util: probe: Add quiet versions of the "PROBE" macro qemu: monitor: Decrease logging verbosity
src/qemu/qemu_monitor.c | 4 ++-- src/qemu/qemu_monitor_json.c | 3 +++ src/util/virprobe.h | 8 ++++++++ 3 files changed, 13 insertions(+), 2 deletions(-)
ACK series with the typos fixed. Jan
participants (3)
-
Eric Blake -
Ján Tomko -
Peter Krempa