Hi Evan,
Does this IOC load any other EPICS drivers or device support at all (other than the standard ones that come with Base)? Your configuration with multiple callback threads is unusual, and a lot of device/driver support might not
have been written or tested with the thought that there could more than one such callback in mind, so any such support code might be contributing to this issue.
- Andrew
Hi Michael,
Please see:
https://gist.github.com/daykin/6ab54c10e46d119785a89f3cf88d424c (debugger output)
Driver code is here:
https://github.com/frib-bim/caen-blm-software
-----Original Message-----
From: Michael Davidsaver <mdavidsaver at gmail.com>
Sent: Thursday, August 5, 2021 11:14 AM
To: Daykin, Evan <daykin at frib.msu.edu>
Cc: tech-talk at aps.anl.gov; Mark Rivers <rivers at cars.uchicago.edu>; Johnson, Andrew N. <anj at anl.gov>
Subject: Re: cbLow consumption randomly stopping
[EXTERNAL] This email originated from outside of FRIB
Even,
... Should I file a bug report in base? ...
This is almost certainly a driver bug, with nothing to fix in Base.
... If so, is there any other info you'd like me to add before submitting?
The output of "thread apply all backtrace" from GDB when an IOC is "stuck".
On 8/4/21 12:33 PM, Daykin, Evan wrote:
Hello again,
Just reviving this thread as I was able to do some more digging, but still no solution. Some more data points:
The PICO module is not stopping. debugPICO PICO<n> 5 spams output like always.
In bugged state, cbLow threads are stopped in FUTEX_WAIT_PRIVATE for some reason, but I'm having trouble figuring out why. If I run strace -fp <pid> and search for the LWP ID's associated with cbLow-1...cbLow-8, I get exactly
one hit for each cbLow thread:
I don't think that 'strace' is going to help you here. All this is says is that 'cbLow' is
waiting on some condition (epicsMutex or epicsEvent). This happens normally all the time.
'strace' doesn't provide enough context to distinguish normal vs. erroneous operation.
It might be better for you to focus on trying to investigate how to trigger the issue
on demand. Personally, I find these sort of issues much easier to troubleshoot when I don't
have to wait hours or days between iterations.
1669 futex(0x55a511f78924, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
OTOH, during normal operation, I see what I'd expect:
21864 futex(0x55cc299855f0, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
...
21864 <... futex resumed> )
21864 futex(0x55cc299855f0, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
Andrew, I saw you'd mentioned it could be in the callback subsystem. Should I file a bug report in base? If so, is there any other info you'd like me to add before submitting?
Have a nice day,
Evan
-----Original Message-----
From: Daykin, Evan
Sent: Tuesday, June 15, 2021 5:30 PM
To: Michael Davidsaver <mdavidsaver at gmail.com>; Mark Rivers <rivers at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov
Subject: RE: cbLow consumption randomly stopping
The issue just happened again on another device. So as promised, here is the github mirror:
https://github.com/frib-bim/caen-blm-software
And some more debug information - epicsMutexShowAll 1, info threads, thread apply all bt:
https://gist.github.com/daykin/6ab54c10e46d119785a89f3cf88d424c
Cheers,
Evan
-----Original Message-----
From: Michael Davidsaver <mdavidsaver at gmail.com>
Sent: Tuesday, June 8, 2021 3:31 PM
To: Daykin, Evan <daykin at frib.msu.edu>; Mark Rivers <rivers at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov
Subject: Re: cbLow consumption randomly stopping
[EXTERNAL] This email originated from outside of FRIB
On 6/8/21 12:19 PM, Daykin, Evan wrote:
, if you think there is a deadlock, I would suggest attaching GDB to a running IOC process and capture all the stack.
So should I run `bt full` on the cbLow thread?
I should have written "... all of the stacks". So all threads, or "thread apply all backtrace".
-----Original Message-----
From: Michael Davidsaver <mdavidsaver at gmail.com>
Sent: Tuesday, June 8, 2021 2:20 PM
To: Daykin, Evan <daykin at frib.msu.edu>; Mark Rivers <rivers at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov
Subject: Re: cbLow consumption randomly stopping
[EXTERNAL] This email originated from outside of FRIB
On 6/8/21 11:03 AM, Daykin, Evan via Tech-talk wrote:
...
Is the driver or device support using asyn? If so, what version?
No, it seems to be using epicspci/devlib2 to communicate with hardware.
I think this driver was one that I did back in 2017.
@Andrew, Mark hardware access is partly through a Linux driver [1], and partly
through MMIO for a custom register range. The Linux driver is public, but the
EPICS driver was FRIB internal. (it would be nice if this could be public as well)
@Evan, if you think there is a deadlock, I would suggest attaching GDB to a running
IOC process and capture all the stack.
Looking back, I also added a per-device logging mask (a la asyn). cf. "debugPico()"
at the IOC shell.
All cbLow threads show same backtrace.
These threads are expected to be in epicsEventWait() when idling.
So this by itself does not indicate a deadlock.
[1] https://github.com/CAENels/amc-pico8-driver and/or https://github.com/mdavidsaver/amc-pico8-driver
@Andrew, here is some output from attaching gdb:
(gdb) info threads
Id Target Id Frame
1 Thread 0x7fd5a60a5c80 (LWP 22198) "st.cmd" 0x00007fd5a9d62151 in __pselect (nfds=1, readfds=0x7fff0eb98db0, writefds=0x0, exceptfds=0x0, timeout=<optimized out>, sigmask=<optimized out>) at ../sysdeps/unix/sysv/linux/pselect.c:69
2 Thread 0x7fd5a5899700 (LWP 22200) "errlog" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d2538054) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
3 Thread 0x7fd5a5818700 (LWP 22202) "Reader" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d2612600) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
4 Thread 0x7fd5a5797700 (LWP 22203) "capture" __GI___libc_read (nbytes=176, buf=0x7fd598000b20, fd=9) at ../sysdeps/unix/sysv/linux/read.c:26
5 Thread 0x7fd5a5716700 (LWP 22204) "Reader" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d26144d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
6 Thread 0x7fd5a5695700 (LWP 22205) "capture" __GI___libc_read (nbytes=176, buf=0x7fd59c000b20, fd=13) at ../sysdeps/unix/sysv/linux/read.c:26
7 Thread 0x7fd5a5614700 (LWP 22206) "Reader" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d26163c0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
8 Thread 0x7fd5a5593700 (LWP 22207) "capture" __GI___libc_read (nbytes=176, buf=0x7fd590000b20, fd=17) at ../sysdeps/unix/sysv/linux/read.c:26
9 Thread 0x7fd5a5512700 (LWP 22208) "Reader" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d2618350) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
10 Thread 0x7fd5a5491700 (LWP 22209) "capture" __GI___libc_read (nbytes=176, buf=0x7fd594000b20, fd=21) at ../sysdeps/unix/sysv/linux/read.c:26
11 Thread 0x7fd5a5410700 (LWP 22217) "taskwd" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd5a540fcf0, expected=0, futex_word=0x55c1d2e56e00) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
12 Thread 0x7fd5a538f700 (LWP 22218) "timerQueue" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd5a538ecc0, expected=0, futex_word=0x55c1d2619b74) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
* 13 Thread 0x7fd5a609a700 (LWP 22219) "cbLow-0" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
14 Thread 0x7fd5a528e700 (LWP 22220) "cbLow-1" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
15 Thread 0x7fd5a508d700 (LWP 22221) "cbLow-2" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
16 Thread 0x7fd5a4e8c700 (LWP 22222) "cbLow-3" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
17 Thread 0x7fd5a4c8b700 (LWP 22223) "cbLow-4" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
18 Thread 0x7fd5a4a8a700 (LWP 22224) "cbLow-5" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
19 Thread 0x7fd5a4889700 (LWP 22225) "cbLow-6" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
20 Thread 0x7fd5a4688700 (LWP 22226) "cbLow-7" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
21 Thread 0x7fd5a4487700 (LWP 22227) "cbMedium" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d31ed8c0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
22 Thread 0x7fd5a4286700 (LWP 22228) "cbHigh" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d31edac0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
23 Thread 0x7fd567fff700 (LWP 22229) "dbCaLink" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d31edeb4) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
24 Thread 0x7fd567dfe700 (LWP 22230) "timerQueue" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd567dfdcc0, expected=0, futex_word=0x55c1d31eef44) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
25 Thread 0x7fd55095c700 (LWP 22233) "scanOnce" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d3883b80) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
26 Thread 0x7fd55075b700 (LWP 22234) "scan-10" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd55075acd0, expected=0, futex_word=0x55c1d3883360) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
27 Thread 0x7fd55055a700 (LWP 22235) "scan-5" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd550559cd0, expected=0, futex_word=0x55c1d38834a0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
28 Thread 0x7fd550359700 (LWP 22236) "scan-2" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd550358cd0, expected=0, futex_word=0x55c1d38835e0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
29 Thread 0x7fd543fff700 (LWP 22237) "scan-1" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd543ffecd0, expected=0, futex_word=0x55c1d3883720) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
30 Thread 0x7fd543dfe700 (LWP 22238) "scan-0.5" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd543dfdcd0, expected=0, futex_word=0x55c1d3883860) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
31 Thread 0x7fd543bfd700 (LWP 22239) "scan-0.2" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd543bfccd0, expected=0, futex_word=0x55c1d38839a0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
32 Thread 0x7fd5439fc700 (LWP 22240) "scan-0.1" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd5439fbcd0, expected=0, futex_word=0x55c1d3883ae0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
33 Thread 0x7fd5437fb700 (LWP 22241) "asCaTask" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d3927c70) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
34 Thread 0x7fd5435fa700 (LWP 22242) "ipToAsciiProxy" futex_wait_cancelable (private=0, expected=0, futex_word=0x7fd52c00fa34) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
35 Thread 0x7fd56418c700 (LWP 22243) "timerQueue" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd56418bcc0, expected=0, futex_word=0x7fd52c010224) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
36 Thread 0x7fd550158700 (LWP 22244) "CAC-UDP" 0x00007fd5a9d6b742 in __libc_recvfrom (fd=26, buf=0x7fd52c0127d8, len=65551, flags=0, addr=..., addrlen=0x7fd550157ca8) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
37 Thread 0x7fd5433f9700 (LWP 22245) "CAC-TCP-recv" __libc_recv (flags=0, len=16384, buf=0x7fd54307b04c, fd=28) at ../sysdeps/unix/sysv/linux/recv.c:28
38 Thread 0x7fd5431f8700 (LWP 22246) "CAC-TCP-send" futex_wait_cancelable (private=0, expected=0, futex_word=0x7fd52000e830) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
39 Thread 0x7fd543076700 (LWP 22256) "CAS-TCP" 0x00007fd5a9d6b437 in __libc_accept (fd=29, addr=..., len=0x7fd543075cec) at ../sysdeps/unix/sysv/linux/accept.c:26
40 Thread 0x7fd542f75700 (LWP 22257) "CAS-UDP" 0x00007fd5a9d6b742 in __libc_recvfrom (fd=30, buf=0x7fd50c001a50, len=65551, flags=0, addr=..., addrlen=0x7fd542f74ce8) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
41 Thread 0x7fd542e74700 (LWP 22258) "CAS-beacon" 0x00007fd5a9d37720 in __GI___nanosleep (requested_time=0x7fd542e73c50, remaining=0x7fd542e73c60) at ../sysdeps/unix/sysv/linux/nanosleep.c:28
42 Thread 0x7fd542df3700 (LWP 22259) "CAC-event" futex_wait_cancelable (private=0, expected=0, futex_word=0x7fd56008ccd0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
43 Thread 0x7fd542cf2700 (LWP 22260) "logRestart" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd542cf1d30, expected=0, futex_word=0x55c1d39310d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
44 Thread 0x7fd542c71700 (LWP 22261) "caPutLog" futex_wait_cancelable (private=0, expected=0, futex_word=0x7fd4f8000b90) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
45 Thread 0x7fd542bf0700 (LWP 22262) "logRestart" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd542befd30, expected=0, futex_word=0x55c1d393f270) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
46 Thread 0x7fd542b6f700 (LWP 22263) "save_restore" futex_abstimed_wait_cancelable (private=0, abstime=0x7fd542b6e880, expected=0, futex_word=0x7fd4fc0204e0) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
47 Thread 0x7fd54296e700 (LWP 22264) "reccaster-etcd" 0x00007fd5a9d37720 in __GI___nanosleep (requested_time=0x7fd54296dc40, remaining=0x7fd54296dc50) at ../sysdeps/unix/sysv/linux/nanosleep.c:28
48 Thread 0x7fd5428ed700 (LWP 22265) "recEtcdConsumer" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d61a30d0) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
49 Thread 0x7fd54286c700 (LWP 22266) "recEtcdConsumer" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d61a3380) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
50 Thread 0x7fd5427eb700 (LWP 22267) "recEtcdConsumer" futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d61a3630) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
-----
(gdb) thread 13
[Switching to thread 13 (Thread 0x7fd5a609a700 (LWP 22219))]
#0 futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
88
../sysdeps/unix/sysv/linux/futex-internal.h: No such file or directory.
------------
(gdb) bt
#0 futex_wait_cancelable (private=0, expected=0, futex_word=0x55c1d321ba40) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#1 __pthread_cond_wait_common (abstime=0x0, mutex=0x55c1d321b9f0, cond=0x55c1d321ba18) at pthread_cond_wait.c:502
#2 __pthread_cond_wait (cond=0x55c1d321ba18, mutex=0x55c1d321b9f0) at pthread_cond_wait.c:655
#3 0x00007fd5a9f3051b in epicsEventWait () from /lib/x86_64-linux-gnu/libCom.so.3.15.8
#4 0x00007fd5a9f28c99 in epicsEventMustWait () from /lib/x86_64-linux-gnu/libCom.so.3.15.8
#5 0x00007fd5a9f9c251 in ?? () from /lib/x86_64-linux-gnu/libdbCore.so.3.15.8
#6 0x00007fd5a9f2da7b in ?? () from /lib/x86_64-linux-gnu/libCom.so.3.15.8
#7 0x00007fd5a98e9fa3 in start_thread (arg=<optimized out>) at pthread_create.c:486
#8 0x00007fd5a9d6a4cf in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
All cbLow threads show same backtrace.
Thanks for the help,
Evan
-----Original Message-----
From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: Tuesday, June 8, 2021 1:27 PM
To: Daykin, Evan <daykin at frib.msu.edu>
Cc: tech-talk at aps.anl.gov
Subject: Re: cbLow consumption randomly stopping
[EXTERNAL] This email originated from outside of FRIB One possibility is that the thread the pulls the message out of the queue has locked up for some reason.One possibility is a deadlock. When this happens you could try typingepicsMutexShowAll
1several times. If the same mutexes are locked each time you type that, then there is likely a deadlock.What OS is this?What version of EPICS base?Is the driver or device support using asyn? If so, what version?Mark________________________________From: Tech-talk
<tech-talk-bounces at aps.anl.gov> on behalf of Daykin, Evan via Tech-talk <tech-talk at aps.anl.gov>Sent: Tuesday, June 8, 2021 12:10 PMTo: EPICS tech-talkSubject: cbLow consumption randomly stoppingHello tech-talk,We have an IOC repeatedly locking up with the
infamous "cbLow ring buffer full" message. The IOC consumes data from our CAEN Pico-8 card via an EPICS driver at 100Hz (about 1200-1215 events per second total) , and at some point on the order of hours to days, seems to stop consuming callbacks from the
queue. I wrote a script to track this, and it seems to all be happening in one shot. Below is some data I captured from the last time this happened. Before this, everything was happy for about 4 hours, but sometimes it takes up to a week for this to happen.TimeHigh-waterItems
in qQ capacity%Oflws6/7/2021 19:22:4013012000006/7/2021 19:22:4113012000006/7/2021 19:22:4213012000006/7/2021 19:22:4413012000006/7/2021 19:22:45571571120004.806/7/2021 19:22:46177817781200014.806/7/2021 19:22:47299129911200024.906/7/2021 19:22:4842044204120003506/7/2021
19:22:4954065406120004506/7/2021 19:22:50661966191200055.206/7/2021 19:22:51783478341200065.306/7/2021 19:22:52904890481200075.406/7/2021 19:22:5310249102491200085.406/7/2021 19:22:5411462114621200095.506/7/2021 19:22:5612000120001200010016/7/2021 19:22:581200012000120001001Has
anyone else experienced this? If so, what is the remedy? I can't seem to correlate it to anything unusual happening in the OS/kernel.Thanks,Evan
--
Complexity comes for free, simplicity you have to work for.
|