[libvirt] libvirt slow responding after restart of service

Sunday, 15 April 2012


after service libvirtd restarted has go slow responding 
(virsh,virt-install and some other tools)
lsof /var/run/libvirt/libvirt-sock-ro and attach strace to this $PID 
always show

futex(0x7d1f84, FUTEX_WAIT_PRIVATE, 3, NULL) = -1 EAGAIN (Resource 
temporarily unavailable)
futex(0x7d1f84, FUTEX_WAIT_PRIVATE, 5, NULL <detached ...>

in starce of any threds (strace -p $PID -ff -o /opt/virtdebug.log)

gdb show only
(gdb) bt
#0  0x00007f938c1e3703 in __poll (fds=<value optimized out>, nfds=<value 
optimized out>, timeout=<value optimized out>)
     at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x00000000004fadd0 in virEventPollRunOnce () at util/event_poll.c:620
#2  0x00000000004f99e5 in virEventRunDefaultImpl () at util/event.c:247
#3  0x00007f938c9e76dd in virNetServerRun (srv=0x7d1e30) at 
rpc/virnetserver.c:736
#4  0x0000000000423f2c in main (argc=<value optimized out>, argv=<value 
optimized out>) at libvirtd.c:1609


LIBVIRT_DEFAULT_URI=qemu:///system time virsh -r list
  ID    Имя                         Статус
----------------------------------------------------
  1     debian6.0                      работает

0.00user 0.00system 0:28.29elapsed 0%CPU (0avgtext+0avgdata 
21520maxresident)k
0inputs+0outputs (0major+1809minor)pagefaults 0swaps

and with LIBVIRT_DEBUG=1
LIBVIRT_DEBUG=1 LIBVIRT_DEFAULT_URI=qemu:///system time virsh -r list
2012-04-14 21:21:45.185+0000: 21338: info : libvirt version: 0.9.11, 
package: alt3M60P1
2012-04-14 21:21:45.185+0000: 21338: debug : virInitialize:414 : 
register drivers
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb22e8e0 name=Test
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering Test as driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNetworkDriver:592 : registering Test as network driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterInterfaceDriver:625 : registering Test as interface driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterStorageDriver:658 : registering Test as storage driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterDeviceMonitor:691 : registering Test as device driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterSecretDriver:724 
: registering Test as secret driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNWFilterDriver:757 : registering Test as network filter driver 0
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb22fe20 name=Xen
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering Xen as driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb230de0 name=OPENVZ
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering OPENVZ as driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb231300 name=VMWARE
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering VMWARE as driver 3
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb2306c0 name=PHYP
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering PHYP as driver 4
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterStorageDriver:658 : registering PHYP as storage driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterInterfaceDriver:625 : registering PHYP as interface driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : vboxRegister:137 : 
VBoxCGlueInit failed, using dummy driver
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb231820 name=VBOX
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering VBOX as driver 5
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNetworkDriver:592 : registering VBOX as network driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterStorageDriver:658 : registering VBOX as storage driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb234800 name=ESX
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering ESX as driver 6
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterInterfaceDriver:625 : registering ESX as interface driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNetworkDriver:592 : registering ESX as network driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterStorageDriver:658 : registering ESX as storage driver 3
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterDeviceMonitor:691 : registering ESX as device driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterSecretDriver:724 
: registering ESX as secret driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNWFilterDriver:757 : registering ESX as network filter driver 1
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:775 : 
driver=0x7f16fb22f1c0 name=remote
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterDriver:799 : 
registering remote as driver 7
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNetworkDriver:592 : registering remote as network driver 3
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterInterfaceDriver:625 : registering remote as interface driver 3
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterStorageDriver:658 : registering remote as storage driver 4
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterDeviceMonitor:691 : registering remote as device driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : virRegisterSecretDriver:724 
: registering remote as secret driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : 
virRegisterNWFilterDriver:757 : registering remote as network filter 
driver 2
2012-04-14 21:21:45.185+0000: 21338: debug : 
virEventRegisterDefaultImpl:204 : registering default event implementation
2012-04-14 21:21:45.185+0000: 21338: debug : virEventPollAddHandle:116 : 
Used 0 handle slots, adding at least 10 more
2012-04-14 21:21:45.185+0000: 21338: debug : 
virEventPollInterruptLocked:702 : Skip interrupt, 0 0
2012-04-14 21:21:45.185+0000: 21338: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=1 fd=4 events=1 cb=0x7f16fad71670 op
2012-04-14 21:21:45.185+0000: 21338: debug : virEventRegisterImpl:177 : 
addHandle=0x7f16fad72260 updateHandle=0x7f16fad72130 
removeHandle=imeout=0x7f16fad71c50 updateTimeout=0x7f16fad71e20 
removeTimeout=0x7f16fad71f50
2012-04-14 21:21:45.185+0000: 21338: debug : virConnectOpenAuth:1455 : 
name=(null), auth=0x7f16fb22e860, flags=1
2012-04-14 21:21:45.186+0000: 21339: debug : virEventRunDefaultImpl:244 
: running default event implementation
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:542 : Found 0 out of 0 timeout slots used, 
releasing 0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=0 w=1, f=4 e=1 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:325 : Calculate expiry of 0 timers
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:619 : 
EVENT_POLL_RUN: nhandles=1 timeout=-1
2012-04-14 21:21:45.186+0000: 21338: debug : 
virConnectGetDefaultURI:1105 : Using LIBVIRT_DEFAULT_URI 'qemu:///system'
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1182 : name 
"qemu:///system" to URI components:
   scheme qemu
   server (null)
   user (null)
   port 0
   path /system

2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 0 (Test) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 0 
Test returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 1 (Xen) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 1 Xen 
returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 2 (OPENVZ) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 2 
OPENVZ returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 3 (VMWARE) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 3 
VMWARE returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 4 (PHYP) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 4 
PHYP returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 5 (VBOX) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 5 
VBOX returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 6 (ESX) ...
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1232 : driver 6 ESX 
returned DECLINED
2012-04-14 21:21:45.186+0000: 21338: debug : do_open:1226 : trying 
driver 7 (remote) ...
2012-04-14 21:21:45.186+0000: 21338: debug : doRemoteOpen:542 : 
proceeding with name = qemu:///system
2012-04-14 21:21:45.186+0000: 21338: debug : doRemoteOpen:552 : 
Connecting with transport 1
2012-04-14 21:21:45.186+0000: 21338: debug : doRemoteOpen:599 : 
Proceeding with sockname /var/run/libvirt/libvirt-sock-ro
2012-04-14 21:21:45.186+0000: 21338: debug : virNetSocketNew:119 : 
localAddr=0x7fff75e552a0 remoteAddr=0x7fff75e55210 fd=6 errfd
2012-04-14 21:21:45.186+0000: 21338: debug : virNetSocketNew:179 : 
RPC_SOCKET_NEW: sock=0x680f90 refs=1 fd=6 errfd=-1 pid=0 
localAddr=127.=127.0.0.1;0
2012-04-14 21:21:45.186+0000: 21338: debug : virNetSocketRef:709 : 
RPC_SOCKET_REF: sock=0x680f90 refs=2
2012-04-14 21:21:45.186+0000: 21338: debug : 
virEventPollInterruptLocked:706 : Interrupting
2012-04-14 21:21:45.186+0000: 21338: debug : virEventPollAddHandle:141 : 
EVENT_POLL_ADD_HANDLE: watch=2 fd=6 events=1 cb=0x7f16fae700b0 
op7f16fae707f0
2012-04-14 21:21:45.186+0000: 21338: debug : virKeepAliveNew:244 : 
client=0x7f16fb283010, interval=-1, count=0
2012-04-14 21:21:45.186+0000: 21338: debug : virEventPollAddTimeout:225 
: Used 0 timeout slots, adding at least 10 more
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:630 : 
Poll got 1 event(s)
2012-04-14 21:21:45.186+0000: 21338: debug : 
virEventPollInterruptLocked:706 : Interrupting
2012-04-14 21:21:45.186+0000: 21338: debug : virEventPollAddTimeout:248 
: EVENT_POLL_ADD_TIMEOUT: timer=1 frequency=-1 cb=0x7f16fae6c180 
ox7f16fae6c3a0
2012-04-14 21:21:45.186+0000: 21338: debug : virKeepAliveNew:277 : 
RPC_KEEPALIVE_NEW: ka=0x680870 client=0x7f16fb283010 refs=2
2012-04-14 21:21:45.186+0000: 21338: debug : virNetClientNew:324 : 
RPC_CLIENT_NEW: client=0x7f16fb283010 refs=3 sock=0x680f9
2012-04-14 21:21:45.186+0000: 21338: debug : doRemoteOpen:684 : Trying 
authentication
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchTimeouts:415 : Dispatch 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:460 : Dispatch 1
2012-04-14 21:21:45.186+0000: 21338: debug : virNetMessageNew:48 : 
msg=0x7f16f43fb010 tracked=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:474 : i=0 w=1
2012-04-14 21:21:45.186+0000: 21338: debug : 
virNetMessageEncodePayload:351 : Encode length as 28
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 
events=1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 2
2012-04-14 21:21:45.186+0000: 21339: debug : virEventRunDefaultImpl:244 
: running default event implementation
2012-04-14 21:21:45.186+0000: 21338: debug : 
virNetClientSendInternal:1675 : RPC_CLIENT_MSG_TX_QUEUE: 
client=0x7f16fb283010 len=28 prog=53=66 type=0 status=0 serial=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 2
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=0 w=1, f=4 e=1 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=1 w=2, f=6 e=1 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:325 : Calculate expiry of 1 timers
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:619 : 
EVENT_POLL_RUN: nhandles=2 timeout=-1
2012-04-14 21:21:45.186+0000: 21338: debug : virNetClientIO:1533 : 
Outgoing message prog=536903814 version=1 serial=0 proc=66 type=0 lengt
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:630 : 
Poll got 1 event(s)
2012-04-14 21:21:45.186+0000: 21338: debug : virNetClientIO:1591 : We 
have the buck 0x6822d0 0x6822d0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchTimeouts:415 : Dispatch 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:460 : Dispatch 2
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:474 : i=0 w=1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 
events=1
2012-04-14 21:21:45.186+0000: 21338: debug : 
virEventPollUpdateHandle:151 : EVENT_POLL_UPDATE_HANDLE: watch=2 events=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:474 : i=1 w=2
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 2
2012-04-14 21:21:45.186+0000: 21339: debug : virEventRunDefaultImpl:244 
: running default event implementation
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 2
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=0 w=1, f=4 e=1 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=1 w=2, f=6 e=1 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:325 : Calculate expiry of 1 timers
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:619 : 
EVENT_POLL_RUN: nhandles=2 timeout=-1
2012-04-14 21:21:45.186+0000: 21338: debug : 
virEventPollInterruptLocked:706 : Interrupting
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:630 : 
Poll got 1 event(s)
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchTimeouts:415 : Dispatch 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:460 : Dispatch 2
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:474 : i=0 w=1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollDispatchHandles:488 : EVENT_POLL_DISPATCH_HANDLE: watch=1 
events=1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 2
2012-04-14 21:21:45.186+0000: 21339: debug : virEventRunDefaultImpl:244 
: running default event implementation
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupTimeouts:506 : Cleanup 1
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCleanupHandles:554 : Cleanup 2
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=0 w=1, f=4 e=1 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollMakePollFDs:383 
: Prepare n=1 w=2, f=6 e=0 d=0
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:325 : Calculate expiry of 1 timers
2012-04-14 21:21:45.186+0000: 21339: debug : 
virEventPollCalculateTimeout:351 : Timeout at 0 due in -1 ms
2012-04-14 21:21:45.186+0000: 21339: debug : virEventPollRunOnce:619 : 
EVENT_POLL_RUN: nhandles=1 timeout=-1

uname -a
Linux f37.local 3.3.1-std-def-alt1 #1 SMP Tue Apr 10 13:27:26 UTC 2012 
x86_64 GNU/Linux

libvirtd --version
libvirtd (libvirt) 0.9.11

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

2007

2006

2005

[libvirt] libvirt slow responding after restart of service