New Comment on Issue #github

[pcp:master] New Comment on Issue #118 reported pmDestroyContext: pthread_mutex_destroy(c_lock) failed: Device or resource busy, failed second try as well ( https://github.com/performancecopilot/pcp/issues/118 )
By fche ( https://github.com/fche ) :

Similar phenomenon observed in pmmgr stock 3.11.5. Intermittently, during the multithreaded phase where each thread opens a brief pmNewContext to a hypothetical address, we have recently started getting *hangs* . This seems to occur when a particular target host dies. I happen to have a box that disconnect/reconnects every few minutes on my network, so error-handling parts of pmmgr/libpcp get probably more of a workout than for a normal site.

Anyway, the observed situation is a hang of the pmmgr process:

(gdb) bt #0 0x00007f29a96ae6bd in pthread_join (threadid=139812543633152, thread_return=0x0) at pthread_join.c:90 #1 0x00005654f23ae60b in pmmgr_job_spec:parallel_do (this= , num_threads= , fn=0x5654f23b0f60 , data=0x7ffd1394b600) at pmmgr.cxx:653 #2 0x00005654f23b1854 in pmmgr_job_spec:poll (this=0x5654f33b4c70) at pmmgr.cxx:721 #3 0x00005654f23a4729 in main (argc= , argv= ) at pmmgr.cxx:1791

A few threads are alive, one looks suspicious:

(gdb) info thread Id Target Id Frame * 1 Thread 0x7f29a9c848c0 (LWP 17870) "pmmgr" 0x00005654f23ae60b in pmmgr_job_spec:parallel_do (this= , num_threads= , fn=0x5654f23b0f60 , data=0x7ffd1394b600) at pmmgr.cxx:653 2 Thread 0x7f28a4ff9700 (LWP 21746) "pmmgr" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135 3 Thread 0x7f28a57fa700 (LWP 21747) "pmmgr" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135 4 Thread 0x7f28a67fc700 (LWP 21749) "pmmgr" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135 5 Thread 0x7f28a7fff700 (LWP 21751) "pmmgr" __lll_lock_wait () at ../sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135 6 Thread 0x7f28a77fe700 (LWP 21752) "pmmgr" 0x00007f29a96b610f in __libc_recv (fd=fd@entry=11, buf=buf@entry=0x7f29700090ac, n=n@entry=12, flags=flags@entry=0) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:28 (gdb) thread 6 [Switching to thread 6 (Thread 0x7f28a77fe700 (LWP 21752))] #0 0x00007f29a96b610f in __libc_recv (fd=fd@entry=11, buf=buf@entry=0x7f29700090ac, n=n@entry=12, flags=flags@entry=0) at ../sysdeps/unix/sysv/linux/x86_64/recv.c:28 28 return SYSCALL_CANCEL (recvfrom, fd, buf, n, flags, NULL, NULL); (gdb) l 23 Returns the number read or -1 for errors. */ 24 25 ssize_t 26 __libc_recv (int fd, void *buf, size_t n, int flags) 27 { 28 return SYSCALL_CANCEL (recvfrom, fd, buf, n, flags, NULL, NULL); 29 } 30 31 weak_alias (__libc_recv, __recv) 32 libc_hidden_weak (__recv) (gdb) p fd $2 = 11

But what's fd 11?

sudo lsof -p 17870 [...] pmmgr 17870 pcp 3u IPv4 28309694 0t0 TCP very.local:34448->very.localpmcd (ESTABLISHED) pmmgr 17870 pcp 4u IPv4 28305018 0t0 TCP very.local:40486->very.localpmcd (ESTABLISHED) pmmgr 17870 pcp 6u IPv4 28303567 0t0 TCP very.elastic.org:42912->dhcp10.elastic.orgpmcd (ESTABLISHED) pmmgr 17870 pcp 10u sock 0,8 0t0 28313674 protocol: TCP

Whoa, no record of fd-11. It has already been closed, maybe by another thread connecting to the same IP address (via another host name?), and having recovered from the failure. Let's resume.

(gdb) q % tail -NNN pmmgr.log [Sat Oct 15 02:1203] pmmgr(17870) Warning: auxconnect.c:__pmCreateSocket(11) __pmSetSockOpt TCP_NODELAY: Bad file descriptor [Sat Oct 15 02:1203] pmmgr(17870) Error: auxconnect.c:__pmConnectTo cannot set FNDELAY - fcntl(11,F_SETFL,0xffffffff) failed: Bad file descriptor [Sat Oct 15 02:1303] pmmgr(17870) Warning: auxconnect.c:__pmCreateSocket(8) __pmSetSockOpt TCP_NODELAY: Bad file descriptor [Sat Oct 15 02:1303] pmmgr(17870) Error: auxconnect.c:__pmCreateIPv6Socket IPV6 is not supported [Sat Oct 15 02:1303] pmmgr(17870) Error: auxconnect.c:__pmCreateIPv6Socket IPV6 is not supported [Sat Oct 15 02:1404] pmmgr(17870) Warning: auxconnect.c:__pmCreateSocket(11) __pmSetSockOpt TCP_NODELAY: Bad file descriptor [Sat Oct 15 02:1404] pmmgr(17870) Error: __pmGetPDU: fd=11 illegal PDU len=1 in hdr [Thu Oct 20 15:0011] pmmgr(17870) Error: __pmGetPDU: fd=11 data read: len=-1: Bad file descriptor [Thu Oct 20 15:0011] pmmgr(17870) Error: __pmGetPDU: PDU hdr: len=0x18 type=0x700d from=0x0 [Thu Oct 20 15:0011] pmmgr(17870) Error: __pmCloseChannelbyContext: fd=11 context=6 expected PDU_PMNS_IDS received: IPC protocol failure [Thu Oct 20 15:0024] pmmgr(17870) Error: __pmCloseChannelbyContext: fd=6 context=3 expected PDU_PMNS_IDS received: Timeout waiting for a response from PMCD pmDestroyContext: pthread_mutex_destroy(c_lock) failed: Device or resource busy pmDestroyContext: pthread_mutex_destroy(c_lock) failed second try: Device or resource busy

There is the bad c_lock error message again.

ISTM there is a recent regression in the multithreading and/or error-handling code in libpcp, probably associated with sharing sockets between contexts.