Bug 1121955

This bug might be related:
https://bugzilla.redhat.com/show_bug.cgi?id=1105527

It's not totally hang, just take so long for it done.

# time virsh list
 Id    Name                           State
----------------------------------------------------


real	47m15.011s
user	0m0.021s
sys	0m0.016s

Created attachment 919849 [details]
libvirtd log

log collected with:
# journalctl -u libvirtd --since 16:00:00 >/tmp/libvirtd_log

Looks like journald allows libvirtd to log only 9 messages per second and the next message is blocked until the next second. Is it a default installation of systemd or did you touch its configuration? What happens if you use older systemd?

Sigh, the log_level parameter really is such a worthless setting that just causes people pain. It is really only something you want to use when logging to stderr or a plain file

Currently libvirt.c uses this param to set the log level for the journal output

            if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0)

I'd say we should probably restrict that so that the default journal output only at level INFO or higher. If someone really wants to log DEBUG to the journal  they can still set the log_outputs setting.

(In reply to Jiri Denemark from comment #4)
> Looks like journald allows libvirtd to log only 9 messages per second and
> the next message is blocked until the next second. Is it a default
> installation of systemd or did you touch its configuration? What happens if
> you use older systemd?


Yes, it's by default installation of systemd, without change configuration.

This also happen on:
systemd-207-8.el7.x86_64

I'll try to find older systemd later.

Did not find older systemd rhel7 host, tried this with fedora 19 on:

libvirt-1.0.5.1-1.fc19.x86_64
systemd-204-8.fc19.x86_64

and this problem did not happen.

Upstream now doesn't allow debug logging to journald if not specified explicitly via the log_outputs setting:

commit c018efa863a0be46628bc9437fc78dff6d8ee4a2
Author: Peter Krempa <pkrempa>
Date:   Tue Aug 12 16:10:39 2014 +0200

    daemon: Limit default log level to journald to VIR_LOG_INFO
    
    Libvirt is really chatty when the DEBUG log level is enabled. When a
    host uses journald we'd enable debug logging to journald when only
    specifying the debug log level. As journald may employ rate throttling
    this would lock up the daemon until it's able to flush all debug
    messages.
    
    This patch changes the default log level to VIR_LOG_INFO when using the
    default (unconfigured) log output to journald.
    
    To still allow debug logging to journald the user now has to explicitly
    specify journald as a log output with priority 1 in the "log_outputs"
    configuration option. This patch also changes the config file template
    to be explicit about this change and notify the user about the possible
    consequence of debug logging into journald.
    
    Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1121955

commit 7b6228d159578cddf0834336fab3d93b98bc0e96
Author: Peter Krempa <pkrempa>
Date:   Tue Aug 12 16:05:36 2014 +0200

    libvirtd: conf: Mention support for logging into journald
    
    Our docs didn't mention the explicit option to log into journald.

v1.2.7-54-gc018efa

Verify this issue with build libvirt-1.2.8-1.el7.x86_64:

Verify steps:
1. edit libvirtd.conf
# vim /etc/libvirt/libvirtd.conf
...
log_level = 1
...

2. restart libvirtd
# systemctl restart libvirtd

3. run virsh list
# time virsh list
 Id    Name                           State
----------------------------------------------------


real	0m0.013s
user	0m0.008s
sys	0m0.002s
# time virsh list
 Id    Name                           State
----------------------------------------------------


real	0m0.012s
user	0m0.007s
sys	0m0.002s


Virsh command does not take long time here.

Verify this bug with libvirt-1.2.8-9.el7.x86_64；

1.set /etc/libvirt/libvirtd.conf

log_level = 1

also test with set:

log_level = 1
log_outputs="1:journald"

2.restart libvirtd

# service libvirtd restart
Redirecting to /bin/systemctl restart  libvirtd.service

3.check log output in /var/log/message
Nov 27 17:13:52 dhcp-66-71-72 libvirtd: 2014-11-27 09:13:52.876+0000: 15606: info : libvirt version: 1.2.8, package: 9.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2014-11-25-09:14:30, x86-025.build.eng.bos.redhat.com)
Nov 27 17:13:52 dhcp-66-71-72 libvirtd: 2014-11-27 09:13:52.876+0000: 15606: debug : virLogParseOutputs:1105 : outputs=1:journald
Nov 27 17:13:52 dhcp-66-71-72 journal: libvirt version: 1.2.8, package: 9.el7 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2014-11-25-09:14:30, x86-025.build.eng.bos.redhat.com)
Nov 27 17:13:52 dhcp-66-71-72 journal: starting netlink event service with protocol 0
Nov 27 17:13:52 dhcp-66-71-72 journal: starting netlink event service with protocol 15
Nov 27 17:13:52 dhcp-66-71-72 systemd: Started Virtualization daemon.
Nov 27 17:13:52 dhcp-66-71-72 journal: dnsmasq version is 2.66, --bind-dynamic is present, SO_BINDTODEVICE is in use
Nov 27 17:13:52 dhcp-66-71-72 journal: Reloading iptables rules

4.test virsh command
# time virsh list --all
 Id    Name                           State
----------------------------------------------------
 -     crashvm                        shut off
 -     crashvm1                       shut off
 -     iscsi-qcow2                    shut off
 -     qcow                           shut off
 -     qcow2manual                    shut off
 -     r6                             shut off
 -     r6-qcow2                       shut off
 -     r6.5                           shut off
 -     r6test                         shut off
 -     r7-gluster                     shut off
 -     raw                            shut off
 -     test1                          shut off
 -     test2                          shut off
 -     test3                          shut off
 -     test4                          shut off
 -     test5                          shut off


real	0m0.241s
user	0m0.060s
sys	0m0.008s

And check the /etc/libvirt/libvirtd.conf
there is a doc:

#    x:journald
#      output to journald logging system

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2015-0323.html