On 04/29/2017 04:38 AM, Stefano Ricci wrote:> 2017-04-28 14:33 GMT+02:00 Michal Privoznik <mprivozn@redhat.com>: >> On 04/27/2017 04:31 PM, Stefano Ricci wrote: >>> Here is the backtrace of the libvirt process just started >> >> [Just a side note, you shouldn't top post on technical lists. Gmail >> sucks at this.] >> >>> >>> https://pastebin.com/R66myzFp >> >> Looks like libvirtd is trying to spawn /usr/bin/qemu-system-x86_64 but >> it takes ages to init. In the debug logs you might see the actual >> command line that libvirt tries to execute. You can try running it by >> hand and see if it takes about the same time. If so, then it's a qemu bug. >> >> http://wiki.libvirt.org/page/DebugLogs >> >> Michal > > The line that comes from the libvirt log is as follows: > LC_ALL=C PATH=/bin:/usr/bin:/sbin:/usr/sbin HOME=/ USER=root > /usr/bin/qemu-system-x86_64 -S -no-user-config -nodefaults -nographic > -M none -qmp unix:/var/lib/libvirt/qemu/capabilities.monitor.sock,server,nowait > -pidfile /var/lib/libvirt/qemu/capabilities.pidfile -daemonize > Before I run the command manually I added the -D parameter to write > the qemu process stderr in a log file. > Once the command is executed, the log file is blank then error-free > and the process seems to respond correctly. > I have connected with the following command: nc -U > /var/lib/libvirt/qemu/capabilities.monitor.sock > and this is an extract of qemu output to my requests: > {"QMP": {"version": {"qemu": {"micro": 1, "minor": 8, "major": 2}, > "package": ""}, "capabilities": []}} > { "execute": "qmp_capabilities" } > {"return": {}} > { "execute": "query-commands" } > {"return": [{"name": "xen-set-global-dirty-log"}, {"name": > "xen-save-devices-state"}, {"name": "xen-load-devices-state"}, > {"name": "x-colo-lost-heartbeat"}, {"name": > "x-blockdev-remove-medium"}, {"name": "x-blockdev-insert-medium"}, > {"name": "x-blockdev-del"}, {"name": "x-blockdev-change"}, {"name": > "transaction"}, {"name": "trace-event-set-state"}, {"name": > "trace-event-get-state"}, {"name": "system_wakeup"}, {"name": > "system_reset"}, {"name": "system_powerdown"}, {"name": "stop"}, > {"name": "set_password"}, {"name": "set_link"}, {"name": "send-key"}, > {"name": "screendump"}, {"name": "rtc-reset-reinjection"}, {"name": > "ringbuf-write"}, {"name": "ringbuf-read"}, {"name": "remove-fd"}, > {"name": "quit"}, {"name": "query-vnc-servers"}, {"name": > "query-vnc"}, {"name": "query-version"}, {"name": "query-uuid"}, > {"name": "query-tpm-types"}, {"name": "query-tpm-models"}, {"name": > "query-tpm"}, {"name": "query-target"}, {"name": "query-status"}, > {"name": "query-spice"}, {"name": "query-rx-filter"}, {"name": > "query-rocker-ports"}, {"name": "query-rocker-of-dpa-groups"}, > {"name": "query-rocker-of-dpa-flows"}, {"name": "query-rocker"}, > {"name": "query-pci"}, {"name": "query-named-block-nodes"}, {"name": > "query-name"}, {"name": "query-migrate-parameters"}, {"name": > "query-migrate-capabilities"}, {"name": "query-migrate-cache-size"}, > {"name": "query-migrate"}, {"name": "query-mice"}, {"name": > "query-memory-devices"}, {"name": "query-memdev"}, {"name": > "query-machines"}, {"name": "query-kvm"}, {"name": "query-iothreads"}, > {"name": "query-hotpluggable-cpus"}, {"name": "query-fdsets"}, > {"name": "query-events"}, {"name": > "query-dump-guest-memory-capability"}, {"name": "query-dump"}, > {"name": "query-cpus"}, {"name": "query-cpu-definitions"}, {"name": > "query-commands"}, {"name": "query-command-line-options"}, {"name": > "query-chardev-backends"}, {"name": "query-chardev"}, {"name": > "query-blockstats"}, {"name": "query-block-jobs"}, {"name": > "query-block"}, {"name": "query-balloon"}, {"name": > "query-acpi-ospm-status"}, {"name": "qom-set"}, {"name": > "qom-list-types"}, {"name": "qom-list"}, {"name": "qom-get"}, {"name": > "qmp_capabilities"}, {"name": "pmemsave"}, {"name": "object-del"}, > {"name": "object-add"}, {"name": "netdev_del"} ....... > So it would not look like a qemu bug.Well, this does not prove that qemu replies to all commands issued by libvirt. For that we would need debug logs as referred to above. BTW: The stack trace looks a bit old (the line number do not match with the current git HEAD) - what's the release you're running and does the problem occur with the current git HEAD too? Michal
2017-04-29 7:24 GMT+02:00 Michal Privoznik <mprivozn@redhat.com>:> On 04/29/2017 04:38 AM, Stefano Ricci wrote: >> 2017-04-28 14:33 GMT+02:00 Michal Privoznik <mprivozn@redhat.com>: >>> On 04/27/2017 04:31 PM, Stefano Ricci wrote: >>>> Here is the backtrace of the libvirt process just started >>> >>> [Just a side note, you shouldn't top post on technical lists. Gmail >>> sucks at this.] >>> >>>> >>>> https://pastebin.com/R66myzFp >>> >>> Looks like libvirtd is trying to spawn /usr/bin/qemu-system-x86_64 but >>> it takes ages to init. In the debug logs you might see the actual >>> command line that libvirt tries to execute. You can try running it by >>> hand and see if it takes about the same time. If so, then it's a qemu bug. >>> >>> http://wiki.libvirt.org/page/DebugLogs >>> >>> Michal >> >> The line that comes from the libvirt log is as follows: >> LC_ALL=C PATH=/bin:/usr/bin:/sbin:/usr/sbin HOME=/ USER=root >> /usr/bin/qemu-system-x86_64 -S -no-user-config -nodefaults -nographic >> -M none -qmp unix:/var/lib/libvirt/qemu/capabilities.monitor.sock,server,nowait >> -pidfile /var/lib/libvirt/qemu/capabilities.pidfile -daemonize >> Before I run the command manually I added the -D parameter to write >> the qemu process stderr in a log file. >> Once the command is executed, the log file is blank then error-free >> and the process seems to respond correctly. >> I have connected with the following command: nc -U >> /var/lib/libvirt/qemu/capabilities.monitor.sock >> and this is an extract of qemu output to my requests: >> {"QMP": {"version": {"qemu": {"micro": 1, "minor": 8, "major": 2}, >> "package": ""}, "capabilities": []}} >> { "execute": "qmp_capabilities" } >> {"return": {}} >> { "execute": "query-commands" } >> {"return": [{"name": "xen-set-global-dirty-log"}, {"name": >> "xen-save-devices-state"}, {"name": "xen-load-devices-state"}, >> {"name": "x-colo-lost-heartbeat"}, {"name": >> "x-blockdev-remove-medium"}, {"name": "x-blockdev-insert-medium"}, >> {"name": "x-blockdev-del"}, {"name": "x-blockdev-change"}, {"name": >> "transaction"}, {"name": "trace-event-set-state"}, {"name": >> "trace-event-get-state"}, {"name": "system_wakeup"}, {"name": >> "system_reset"}, {"name": "system_powerdown"}, {"name": "stop"}, >> {"name": "set_password"}, {"name": "set_link"}, {"name": "send-key"}, >> {"name": "screendump"}, {"name": "rtc-reset-reinjection"}, {"name": >> "ringbuf-write"}, {"name": "ringbuf-read"}, {"name": "remove-fd"}, >> {"name": "quit"}, {"name": "query-vnc-servers"}, {"name": >> "query-vnc"}, {"name": "query-version"}, {"name": "query-uuid"}, >> {"name": "query-tpm-types"}, {"name": "query-tpm-models"}, {"name": >> "query-tpm"}, {"name": "query-target"}, {"name": "query-status"}, >> {"name": "query-spice"}, {"name": "query-rx-filter"}, {"name": >> "query-rocker-ports"}, {"name": "query-rocker-of-dpa-groups"}, >> {"name": "query-rocker-of-dpa-flows"}, {"name": "query-rocker"}, >> {"name": "query-pci"}, {"name": "query-named-block-nodes"}, {"name": >> "query-name"}, {"name": "query-migrate-parameters"}, {"name": >> "query-migrate-capabilities"}, {"name": "query-migrate-cache-size"}, >> {"name": "query-migrate"}, {"name": "query-mice"}, {"name": >> "query-memory-devices"}, {"name": "query-memdev"}, {"name": >> "query-machines"}, {"name": "query-kvm"}, {"name": "query-iothreads"}, >> {"name": "query-hotpluggable-cpus"}, {"name": "query-fdsets"}, >> {"name": "query-events"}, {"name": >> "query-dump-guest-memory-capability"}, {"name": "query-dump"}, >> {"name": "query-cpus"}, {"name": "query-cpu-definitions"}, {"name": >> "query-commands"}, {"name": "query-command-line-options"}, {"name": >> "query-chardev-backends"}, {"name": "query-chardev"}, {"name": >> "query-blockstats"}, {"name": "query-block-jobs"}, {"name": >> "query-block"}, {"name": "query-balloon"}, {"name": >> "query-acpi-ospm-status"}, {"name": "qom-set"}, {"name": >> "qom-list-types"}, {"name": "qom-list"}, {"name": "qom-get"}, {"name": >> "qmp_capabilities"}, {"name": "pmemsave"}, {"name": "object-del"}, >> {"name": "object-add"}, {"name": "netdev_del"} ....... >> So it would not look like a qemu bug. > > Well, this does not prove that qemu replies to all commands issued by > libvirt. For that we would need debug logs as referred to above. > > BTW: The stack trace looks a bit old (the line number do not match with > the current git HEAD) - what's the release you're running and does the > problem occur with the current git HEAD too? > > MichalThe version used for backtrace is 3.2.0, now I have also tried the current downloaded with git but the problem is always present. This is the current version log file, set as shown on the DebugLogs page: https://drive.google.com/open?id=0By9lwQyveHENdEt4aEtZcUV3ZEU Stefano
On 04/30/2017 07:12 PM, Stefano Ricci wrote:> > The version used for backtrace is 3.2.0, now I have also tried the > current downloaded with git but the problem is always present. > This is the current version log file, set as shown on the DebugLogs page: > > https://drive.google.com/open?id=0By9lwQyveHENdEt4aEtZcUV3ZEUCouple of my findings: 2017-04-30 16:19:34.894+0000: 870: debug : virDriverLoadModuleFile:49 : Load module file '/usr/lib/libvirt/storage-backend/libvirt_storage_backend_rbd.so' 2017-04-30 16:19:35.324+0000: 870: debug : virDriverLoadModuleFunc:71 : Lookup function 'virStorageBackendRBDRegister' it takes nearly .5s to load libvirt_storage_backend_rbd.so But apart from that there is nothing unusual in the logs. So how do you observe the hang? How long it is anyway - assuming it goes away after some time. Or does it hang indefinitely? BTW: is this all the debug messages you have? Because in there, the last line is how libvirtd starts qemu-system-x86_64 in order to fetch its capabilities. I'd expect libvirt setting qmp_capabilities on the monitor at least. Michal