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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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@@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 :|