On Tue, Mar 27, 2018 at 03:30:14PM +0300, Mathieu Tarral wrote:
I have installed the following debug symbols:
- libvirt-daemon-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt-daemon-system-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt-clients-dbgsym_3.0.0-4+deb9u3_amd64.deb
- libvirt0-dbgsym_3.0.0-4+deb9u3_amd64.deb
- python3-libvirt-dbgsym_3.0.0-2_amd64.deb
And i was able to reproduce my bug.
In my Python application, i had 2 threads hanging on a libvirt call.
(sorry for the verbosity)
Thread 1:
(gdb) py-bt
Traceback (most recent call first):
<built-in method virDomainGetState of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 2551, in state
ret = libvirtmod.virDomainGetState(self._o, flags)
(gdb) bt
pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x55a1fe420728,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x55a1fe420710,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x55a1fdd798f0, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x55a1fdd798f0) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=108, proc=proc@entry=212, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0f13e0
<xdr_remote_domain_get_state_args>, args=0x7ffd1518cfd0,
ret_filter=0x7f508e0f1410 <xdr_remote_domain_get_state_ret>,
ret=0x7ffd1518cfc8) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=212,
args_filter=0x7f508e0f13e0 <xdr_remote_domain_get_state_args>,
args=0x7ffd1518cfd0 "`k.\376\241U", ret_filter=0x7f508e0f1410
<xdr_remote_domain_get_state_ret>, ret=0x7ffd1518cfc8 "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d7f90 in call (conn=<optimized out>,
ret=0x7ffd1518cfc8 "", ret_filter=<optimized out>, args=0x7ffd1518cfd0
"`k.\376\241U", args_filter=<optimized out>, proc_nr=212, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainGetState (domain=0x55a1fe212da0, state=0x7ffd1518d0a4,
reason=0x7ffd1518d0a8, flags=0) at
../../../src/remote/remote_driver.c:2458
#9 0x00007f508e08e248 in virDomainGetState
(domain=domain@entry=0x55a1fe212da0, state=state@entry=0x7ffd1518d0a4,
reason=reason@entry=0x7ffd1518d0a8, flags=0) at
../../../src/libvirt-domain.c:2495
#10 0x00007f508e466f28 in libvirt_virDomainGetState (self=<optimized
out>, args=<optimized out>) at libvirt-override.c:2539
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
That's pretty much as expected - just remote client waiting for a reply
from the daemon.
And Thread 2:
(gdb) py-bt
<built-in method virDomainIsActive of module object at remote 0x7f508e6b1278>
File "/usr/lib/python3/dist-packages/libvirt.py", line 1340, in isActive
ret = libvirtmod.virDomainIsActive(self._o)
(gdb) bt
Are you sure this isa different thread ? It looks identical to the first
stack trace you give above.
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f508dfe2b86 in virCondWait (c=c@entry=0x7f4ff051fdc8,
m=m@entry=0x55a1fde4d2c0) at ../../../src/util/virthread.c:154
#2 0x00007f508e0f5bbb in virNetClientIO (thiscall=0x7f4ff051fdb0,
client=0x55a1fde4d2b0) at ../../../src/rpc/virnetclient.c:1894
#3 virNetClientSendInternal (client=client@entry=0x55a1fde4d2b0,
msg=msg@entry=0x7f4ff051fa10, expectReply=expectReply@entry=true,
nonBlock=nonBlock@entry=false) at ../../../src/rpc/virnetclient.c:2116
#4 0x00007f508e0f7443 in virNetClientSendWithReply
(client=client@entry=0x55a1fde4d2b0, msg=msg@entry=0x7f4ff051fa10) at
../../../src/rpc/virnetclient.c:2144
#5 0x00007f508e0f7bf2 in virNetClientProgramCall
(prog=prog@entry=0x55a1fdff0f90, client=client@entry=0x55a1fde4d2b0,
serial=serial@entry=107, proc=proc@entry=150, noutfds=noutfds@entry=0,
outfds=outfds@entry=0x0, ninfds=0x0,
infds=0x0, args_filter=0x7f508e0efe70
<xdr_remote_domain_is_active_args>, args=0x7f4fff7fd040,
ret_filter=0x7f508e0efe90 <xdr_remote_domain_is_active_ret>,
ret=0x7f4fff7fd03c) at ../../../src/rpc/virnetclientprogram.c:329
#6 0x00007f508e0cdeb4 in callFull (priv=priv@entry=0x55a1fe5ac460,
flags=flags@entry=0, fdin=fdin@entry=0x0, fdinlen=fdinlen@entry=0,
fdout=fdout@entry=0x0, fdoutlen=fdoutlen@entry=0x0, proc_nr=150,
args_filter=0x7f508e0efe70 <xdr_remote_domain_is_active_args>,
args=0x7f4fff7fd040 "`k.\376\241U", ret_filter=0x7f508e0efe90
<xdr_remote_domain_is_active_ret>, ret=0x7f4fff7fd03c "",
conn=<optimized out>)
at ../../../src/remote/remote_driver.c:6636
#7 0x00007f508e0d71cb in call (conn=<optimized out>,
ret=0x7f4fff7fd03c "", ret_filter=<optimized out>, args=0x7f4fff7fd040
"`k.\376\241U", args_filter=<optimized out>, proc_nr=150, flags=0,
priv=0x55a1fe5ac460)
at ../../../src/remote/remote_driver.c:6658
#8 remoteDomainIsActive (dom=0x55a1fe212da0) at
../../../src/remote/remote_client_bodies.h:2842
#9 0x00007f508e09df03 in virDomainIsActive
(dom=dom@entry=0x55a1fe212da0) at ../../../src/libvirt-domain.c:8467
#10 0x00007f508e46cbd0 in libvirt_virDomainIsActive (self=<optimized
out>, args=<optimized out>) at build/libvirt.c:1288
#11 0x000055a1fb4cb6df in PyCFunction_Call () at ../Objects/methodobject.c:109
Interesting. This is an identical stack trace - so we have 2 python
threads both calling virDomainIsActive(). Nothing wrong with that
per-se - we support multithreaded usage like this.
Curious why it would break.
Can you confirm there are no other threads running libvirt code
in your python app ? Did you have any thread running the libvirt
event loop perhaps ?
So i ran GDB on /usr/sbin/libvirtd to know what was happening:
(gdb) thread all apply bt
Thread 17 (Thread 0x7f241dd40700 (LWP 5100)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x7f24183eeba8,
m=m@entry=0x7f24183eeb80) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071a350) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f241dd40700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 16 (Thread 0x7f241fdfd700 (LWP 3518)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f241fdfd700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 15 (Thread 0x7f24205fe700 (LWP 3517)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071e310) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f24205fe700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 14 (Thread 0x7f2420dff700 (LWP 3516)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2420dff700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 13 (Thread 0x7f2421600700 (LWP 3515)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071e250) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2421600700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 12 (Thread 0x7f2421e01700 (LWP 3514)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x55705073e728,
m=m@entry=0x55705073e700) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705073e4b0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2421e01700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 11 (Thread 0x7f2439e14700 (LWP 3513)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f2439e14700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 10 (Thread 0x7f243a615700 (LWP 3512)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243a615700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 9 (Thread 0x7f243ae16700 (LWP 3511)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b810) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243ae16700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 8 (Thread 0x7f243b617700 (LWP 3510)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243b617700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 7 (Thread 0x7f243be18700 (LWP 3509)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x557050729358,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f2448241694 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243be18700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 6 (Thread 0x7f243c619700 (LWP 3508)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b810) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243c619700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 5 (Thread 0x7f243ce1a700 (LWP 3507)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b8d0) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243ce1a700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 4 (Thread 0x7f243d61b700 (LWP 3506)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071b990) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243d61b700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 3 (Thread 0x7f243de1c700 (LWP 3505)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071ba50) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243de1c700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 2 (Thread 0x7f243e61d700 (LWP 3504)):
#0 pthread_cond_wait@(a)GLIBC_2.3.2 () at
../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1 0x00007f2448240b86 in virCondWait (c=c@entry=0x5570507292b8,
m=m@entry=0x557050729290) at ../../../src/util/virthread.c:154
#2 0x00007f24482416d3 in virThreadPoolWorker
(opaque=opaque@entry=0x55705071bb10) at
../../../src/util/virthreadpool.c:124
#3 0x00007f2448240928 in virThreadHelper (data=<optimized out>) at
../../../src/util/virthread.c:206
#4 0x00007f2444b1a494 in start_thread (arg=0x7f243e61d700) at
pthread_create.c:333
#5 0x00007f244485cacf in clone () at
../sysdeps/unix/sysv/linux/x86_64/clone.S:97
Thread 1 (Thread 0x7f24489f3940 (LWP 3502)):
#0 0x00007f244485367d in poll () at ../sysdeps/unix/syscall-template.S:84
#1 0x00007f24481f304f in poll (__timeout=-1, __nfds=50,
__fds=<optimized out>) at
/usr/include/x86_64-linux-gnu/bits/poll2.h:46
#2 virEventPollRunOnce () at ../../../src/util/vireventpoll.c:641
#3 0x00007f24481f1c21 in virEventRunDefaultImpl () at
../../../src/util/virevent.c:314
#4 0x00007f244835837d in virNetDaemonRun (dmn=0x55705072a330) at
../../../src/rpc/virnetdaemon.c:818
#5 0x000055704f773b87 in main (argc=<optimized out>, argv=<optimized
out>) at ../../../daemon/libvirtd.c:1547
But this doesn't really help me understand why it hangs,
or which threads is processing the client requests that are hanging.
This shows that libvirtd is entirely idle. Thread 1 is the event loop
and waiting for I/O. All the other threads are API workers waiting for
any API call to process. So all completely normal.
Regards,
Daniel
--
|:
https://berrange.com -o-
https://www.flickr.com/photos/dberrange :|
|:
https://libvirt.org -o-
https://fstop138.berrange.com :|
|:
https://entangle-photo.org -o-
https://www.instagram.com/dberrange :|