Bug 812654

Summary: libvirt slow respond
Product: [Community] Virtualization Tools Reporter: stalker37 <stalker>
Component: libvirtAssignee: Libvirt Maintainers <libvirt-maint>
Status: CLOSED DEFERRED QA Contact:
Severity: high Docs Contact:
Priority: unspecified    
Version: unspecifiedCC: boris.savelev, crobinso, hzguanqiang, rbalakri, xen-maint
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-03-23 21:14:38 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
libvirtd debug log none

Description stalker37 2012-04-15 18:46:28 UTC
Description of problem:

Libvirt slow responding afterreboot or restart service

Version-Release number of selected component (if applicable):
0.9.11

How reproducible:

reboot server otr rstart libvirtd

Steps to Reproduce:
1. restart service
2. run virsh list or virt-install or some other
3. wait some time (other 20s)
  
Actual results:

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 

Expected results:

time < 5s

Additional info:

cpu core i7, kernel version is 3.3.1

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

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

gdb show

gdb) thread apply all bt

Thread 12 (Thread 0x7fe79b919700 (LWP 9846)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe79b919700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 11 (Thread 0x7fe79b118700 (LWP 9847)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe79b118700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 10 (Thread 0x7fe79a917700 (LWP 9848)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe79a917700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()
---Type <return> to continue, or q <return> to quit---

Thread 9 (Thread 0x7fe79a116700 (LWP 9849)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe79a116700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 8 (Thread 0x7fe799915700 (LWP 9850)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe799915700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 7 (Thread 0x7fe799114700 (LWP 9851)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe799114700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()
---Type <return> to continue, or q <return> to quit---

Thread 6 (Thread 0x7fe798913700 (LWP 9852)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe798913700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 5 (Thread 0x7fe798112700 (LWP 9853)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe798112700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 4 (Thread 0x7fe797911700 (LWP 9854)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe797911700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()
---Type <return> to continue, or q <return> to quit---

Thread 3 (Thread 0x7fe797110700 (LWP 9855)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x000000000050ba1a in virCondWait (c=<value optimized out>, m=<value optimized out>) at util/threads-pthread.c:117
#2  0x000000000050af9b in virThreadPoolWorker (opaque=<value optimized out>) at util/threadpool.c:103
#3  0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#4  0x00007fe79f65f9aa in start_thread (arg=0x7fe797110700) at pthread_create.c:297
#5  0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7fe795157700 (LWP 9856)):
#0  0x00007fe79f1b5703 in __poll (fds=<value optimized out>, nfds=<value optimized out>, timeout=<value optimized out>)
    at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x00000000004f4bc7 in virCommandProcessIO (cmd=0x7fe7900030e0, exitstatus=0x7fe795156b8c) at util/command.c:1742
#2  virCommandRun (cmd=0x7fe7900030e0, exitstatus=0x7fe795156b8c) at util/command.c:1984
#3  0x00000000004f5f54 in virRun (argv=<value optimized out>, status=0x7fe795156b8c) at util/command.c:698
#4  0x0000000000510919 in virFileWaitForDevices () at util/util.c:2611
#5  0x00000000004dc628 in virStorageBackendLogicalRefreshPool (conn=<value optimized out>, pool=0x7fe790007600) at storage/storage_backend_logical.c:588
#6  0x00000000004d45c9 in storageDriverAutostart (driver=<value optimized out>) at storage/storage_driver.c:109
#7  0x00000000004d49c6 in storageDriverStartup (privileged=<value optimized out>) at storage/storage_driver.c:178
#8  0x00007fe79f95c994 in virStateInitialize (privileged=1) at libvirt.c:852
#9  0x0000000000422205 in daemonRunStateInit (opaque=0x7d1e30) at libvirtd.c:1178
#10 0x000000000050b6b6 in virThreadHelper (data=<value optimized out>) at util/threads-pthread.c:161
#11 0x00007fe79f65f9aa in start_thread (arg=0x7fe795157700) at pthread_create.c:297
#12 0x00007fe79f1be14d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#13 0x0000000000000000 in ?? ()

---Type <return> to continue, or q <return> to quit---
Thread 1 (Thread 0x7fe7a20bf840 (LWP 9845)):
#0  0x00007fe79f1b5703 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  0x00007fe79f9b96dd 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

Comment 1 stalker37 2012-04-16 07:39:14 UTC
UPD:
if i undefine pool with pre-defined LVM volume group (on it group exists some other lv) - libvirt respond shortly.

<pool type='logical'>
  <name>LVM_MAIN</name>
  <uuid>a2713bed-ad4a-fb79-83b5-65a9e8f1094e</uuid>
  <capacity>0</capacity>
  <allocation>0</allocation>
  <available>0</available>
  <source>
    <name>LVM_MAIN</name>
    <format type='unknown'/>
  </source>
  <target>
    <path>/dev/LVM_MAIN</path>
    <permissions>
      <mode>0700</mode>
      <owner>-1</owner>
      <group>-1</group>
    </permissions>
  </target>
</pool>

Comment 2 stalker37 2012-04-16 14:00:33 UTC
i8n attach debug log of libvirtd
slow not lvm commands

Comment 3 stalker37 2012-04-16 14:01:29 UTC
Created attachment 577722 [details]
libvirtd debug log

Comment 4 stalker37 2012-04-16 16:28:34 UTC
downgrade kernel to 2.6.32 solve  problem

Comment 5 Cole Robinson 2016-03-23 21:14:38 UTC
The hang on WaitForDevices and the kernel downgrade fix means this must have been some transient kernel breakage