Hi Slawa,
On 9/26/16 7:22 PM, Slawa Olhovchenkov wrote:> On Mon, Sep 26, 2016 at 11:33:12AM +0200, Julien Charbon wrote:
>> On 9/25/16 2:46 PM, Slawa Olhovchenkov wrote:
>>> On Fri, Sep 23, 2016 at 11:01:43PM +0300, Slawa Olhovchenkov wrote:
>>>>> On 9/21/16 9:51 PM, Slawa Olhovchenkov wrote:
>>>>>> On Wed, Sep 21, 2016 at 09:11:24AM +0200, Julien
Charbon wrote:
>>>>>>> You can also use Dtrace and lockstat (especially
with the lockstat -s
>>>>>>> option):
>>>>>>>
>>>>>>>
https://wiki.freebsd.org/DTrace/One-Liners#Kernel_Locks
>>>>>>>
https://www.freebsd.org/cgi/man.cgi?query=lockstat&manpath=FreeBSD+11.0-RELEASE
>>>>>>>
>>>>>>> But I am less familiar with Dtrace/lockstat tools.
>>>>>>
>>>>>> I am still use old kernel and got lockdown again.
>>>>>> Try using lockstat (I am save more output), interesting
may be next:
>>>>>>
>>>>>> R/W writer spin on writer: 190019 events in 1.070
seconds (177571 events/sec)
>>>>>>
>>>>>>
-------------------------------------------------------------------------------
>>>>>> Count indv cuml rcnt nsec Lock
Caller
>>>>>> 140839 74% 74% 0.00 24659 tcpinp
tcp_tw_2msl_scan+0xc6
>>>>>>
>>>>>> nsec ------ Time Distribution ------ count
Stack
>>>>>> 4096 | 913
tcp_twstart+0xa3
>>>>>> 8192 |@@@@@@@@@@@@ 58191
tcp_do_segment+0x201f
>>>>>> 16384 |@@@@@@ 29594
tcp_input+0xe1c
>>>>>> 32768 |@@@@ 23447
ip_input+0x15f
>>>>>> 65536 |@@@ 16197
>>>>>> 131072 |@ 8674
>>>>>> 262144 | 3358
>>>>>> 524288 | 456
>>>>>> 1048576 | 9
>>>>>>
-------------------------------------------------------------------------------
>>>>>> Count indv cuml rcnt nsec Lock
Caller
>>>>>> 49180 26% 100% 0.00 15929 tcpinp
tcp_tw_2msl_scan+0xc6
>>>>>>
>>>>>> nsec ------ Time Distribution ------ count
Stack
>>>>>> 4096 | 157
pfslowtimo+0x54
>>>>>> 8192 |@@@@@@@@@@@@@@@ 24796
softclock_call_cc+0x179
>>>>>> 16384 |@@@@@@ 11223
softclock+0x44
>>>>>> 32768 |@@@@ 7426
intr_event_execute_handlers+0x95
>>>>>> 65536 |@@ 3918
>>>>>> 131072 | 1363
>>>>>> 262144 | 278
>>>>>> 524288 | 19
>>>>>>
-------------------------------------------------------------------------------
>>>>>
>>>>> This is interesting, it seems that you have two call paths
competing
>>>>> for INP locks here:
>>>>>
>>>>> - pfslowtimo()/tcp_tw_2msl_scan(reuse=0) and
>>>>>
>>>>> - tcp_input()/tcp_twstart()/tcp_tw_2msl_scan(reuse=1)
>>>>
>>>> My current hypothesis:
>>>>
>>>> nginx do write() (or may be close()?) to socket, kernel lock
>>>> first inp in V_twq_2msl, happen callout for pfslowtimo() on the
same
>>>> CPU core and tcp_tw_2msl_scan infinity locked on same inp.
>>>>
>>>> In this case you modification can't help, before next try
we need some
>>>> like yeld().
>>>
>>> Or may be locks leaks.
>>> Or both.
>>
>> You are totally right, pfslowtimo()/tcp_tw_2msl_scan(reuse=0) is
>> infinitely blocked on INP_WLOCK() by "something" (that could
be related
>> to write()).
>>
>> As I reached my limit of debugging without WITNESS, could you share
>> your /etc/sysctl.conf, /boot/loader.conf files? And any specific
>> configuration you have (like having a Nginx workers affinity, Nginx
>> special options, etc.). Like that I can try to reproduce it on
releng/11.0.
>
> Some more traces from ddb:
>
> Tracing command intr pid 12 tid 100103 td 0xfffff8012508ea00
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe2020ea8330
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe2020ea8360
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe2020ea83a0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe2020ea8420
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe2020ea8460
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe2020ea8490
> tcp_do_segment() at 0xffffffff80610226 = tcp_do_segment+0x1666/frame
0xfffffe2020ea8590
> tcp_input() at 0xffffffff8060e17c = tcp_input+0xe1c/frame
0xfffffe2020ea86e0
> ip_input() at 0xffffffff805a087f = ip_input+0x15f/frame 0xfffffe2020ea8740
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020ea87a0
> ether_demux() at 0xffffffff80575b3a = ether_demux+0x12a/frame
0xfffffe2020ea87d0
> ether_nh_input() at 0xffffffff80576792 = ether_nh_input+0x322/frame
0xfffffe2020ea8830
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020ea8890
> ether_input() at 0xffffffff80575db6 = ether_input+0x26/frame
0xfffffe2020ea88b0
> ixgbe_rxeof() at 0xffffffff813df36b = ixgbe_rxeof+0x7ab/frame
0xfffffe2020ea8990
> ixgbe_msix_que() at 0xffffffff813da57c = ixgbe_msix_que+0x8c/frame
0xfffffe2020ea89e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe2020ea8a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe2020ea8a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe2020ea8ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe2020ea8ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100105 td 0xfffff8012508e000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe2020eb2330
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe2020eb2360
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe2020eb23a0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe2020eb2420
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe2020eb2460
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe2020eb2490
> tcp_do_segment() at 0xffffffff80610226 = tcp_do_segment+0x1666/frame
0xfffffe2020eb2590
> tcp_input() at 0xffffffff8060e17c = tcp_input+0xe1c/frame
0xfffffe2020eb26e0
> ip_input() at 0xffffffff805a087f = ip_input+0x15f/frame 0xfffffe2020eb2740
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020eb27a0
> ether_demux() at 0xffffffff80575b3a = ether_demux+0x12a/frame
0xfffffe2020eb27d0
> ether_nh_input() at 0xffffffff80576792 = ether_nh_input+0x322/frame
0xfffffe2020eb2830
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020eb2890
> ether_input() at 0xffffffff80575db6 = ether_input+0x26/frame
0xfffffe2020eb28b0
> ixgbe_rxeof() at 0xffffffff813df36b = ixgbe_rxeof+0x7ab/frame
0xfffffe2020eb2990
> ixgbe_msix_que() at 0xffffffff813da57c = ixgbe_msix_que+0x8c/frame
0xfffffe2020eb29e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe2020eb2a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe2020eb2a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe2020eb2ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe2020eb2ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100107 td 0xfffff8012508d500
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe2020ebc2b0
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe2020ebc2e0
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe2020ebc320
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe2020ebc3a0
> soalloc() at 0xffffffff8051b914 = soalloc+0x1b4/frame 0xfffffe2020ebc3f0
> sonewconn() at 0xffffffff8051bb9f = sonewconn+0xbf/frame 0xfffffe2020ebc430
> syncache_expand() at 0xffffffff8061b85b = syncache_expand+0x78b/frame
0xfffffe2020ebc590
> tcp_input() at 0xffffffff8060e10e = tcp_input+0xdae/frame
0xfffffe2020ebc6e0
> ip_input() at 0xffffffff805a087f = ip_input+0x15f/frame 0xfffffe2020ebc740
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020ebc7a0
> ether_demux() at 0xffffffff80575b3a = ether_demux+0x12a/frame
0xfffffe2020ebc7d0
> ether_nh_input() at 0xffffffff80576792 = ether_nh_input+0x322/frame
0xfffffe2020ebc830
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020ebc890
> ether_input() at 0xffffffff80575db6 = ether_input+0x26/frame
0xfffffe2020ebc8b0
> ixgbe_rxeof() at 0xffffffff813df36b = ixgbe_rxeof+0x7ab/frame
0xfffffe2020ebc990
> ixgbe_msix_que() at 0xffffffff813da57c = ixgbe_msix_que+0x8c/frame
0xfffffe2020ebc9e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe2020ebca20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe2020ebca70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe2020ebcab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe2020ebcab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100111 td 0xfffff801250a2000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe2020f302f0
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe2020f30320
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe2020f30360
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe2020f303e0
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe2020f30420
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe2020f30450
> tcp_twstart() at 0xffffffff8061f0e7 = tcp_twstart+0x2b7/frame
0xfffffe2020f30490
> tcp_do_segment() at 0xffffffff80610bdf = tcp_do_segment+0x201f/frame
0xfffffe2020f30590
> tcp_input() at 0xffffffff8060e17c = tcp_input+0xe1c/frame
0xfffffe2020f306e0
> ip_input() at 0xffffffff805a087f = ip_input+0x15f/frame 0xfffffe2020f30740
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020f307a0
> ether_demux() at 0xffffffff80575b3a = ether_demux+0x12a/frame
0xfffffe2020f307d0
> ether_nh_input() at 0xffffffff80576792 = ether_nh_input+0x322/frame
0xfffffe2020f30830
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020f30890
> ether_input() at 0xffffffff80575db6 = ether_input+0x26/frame
0xfffffe2020f308b0
> ixgbe_rxeof() at 0xffffffff813df36b = ixgbe_rxeof+0x7ab/frame
0xfffffe2020f30990
> ixgbe_msix_que() at 0xffffffff813da57c = ixgbe_msix_que+0x8c/frame
0xfffffe2020f309e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe2020f30a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe2020f30a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe2020f30ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe2020f30ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100113 td 0xfffff801250a1500
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe2020f3a2f0
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe2020f3a320
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe2020f3a360
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe2020f3a3e0
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe2020f3a420
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe2020f3a450
> tcp_twstart() at 0xffffffff8061f0e7 = tcp_twstart+0x2b7/frame
0xfffffe2020f3a490
> tcp_do_segment() at 0xffffffff80610bdf = tcp_do_segment+0x201f/frame
0xfffffe2020f3a590
> tcp_input() at 0xffffffff8060e17c = tcp_input+0xe1c/frame
0xfffffe2020f3a6e0
> ip_input() at 0xffffffff805a087f = ip_input+0x15f/frame 0xfffffe2020f3a740
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020f3a7a0
> ether_demux() at 0xffffffff80575b3a = ether_demux+0x12a/frame
0xfffffe2020f3a7d0
> ether_nh_input() at 0xffffffff80576792 = ether_nh_input+0x322/frame
0xfffffe2020f3a830
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020f3a890
> ether_input() at 0xffffffff80575db6 = ether_input+0x26/frame
0xfffffe2020f3a8b0
> ixgbe_rxeof() at 0xffffffff813df36b = ixgbe_rxeof+0x7ab/frame
0xfffffe2020f3a990
> ixgbe_msix_que() at 0xffffffff813da57c = ixgbe_msix_que+0x8c/frame
0xfffffe2020f3a9e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe2020f3aa20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe2020f3aa70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe2020f3aab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe2020f3aab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100115 td 0xfffff801250a0a00
> cpustop_handler() at 0xffffffff80775998 = cpustop_handler+0x28/frame
0xfffffe1f9e182cf0
> ipi_nmi_handler() at 0xffffffff8077595a = ipi_nmi_handler+0x4a/frame
0xfffffe1f9e182d10
> trap() at 0xffffffff806e2e4a = trap+0x3a/frame 0xfffffe1f9e182f20
> nmi_calltrap() at 0xffffffff806cb413 = nmi_calltrap+0x8/frame
0xfffffe1f9e182f20
> --- trap 0x13, rip = 0xffffffff8059b9f9, rsp = 0xfffffe2020f44420, rbp =
0xfffffe2020f44420 ---
> in_pcbref() at 0xffffffff8059b9f9 = in_pcbref+0x9/frame 0xfffffe2020f44420
> tcp_tw_2msl_scan() at 0xffffffff8061f1a3 = tcp_tw_2msl_scan+0x73/frame
0xfffffe2020f44450
> tcp_twstart() at 0xffffffff8061eed3 = tcp_twstart+0xa3/frame
0xfffffe2020f44490
> tcp_do_segment() at 0xffffffff80610bdf = tcp_do_segment+0x201f/frame
0xfffffe2020f44590
> tcp_input() at 0xffffffff8060e17c = tcp_input+0xe1c/frame
0xfffffe2020f446e0
> ip_input() at 0xffffffff805a087f = ip_input+0x15f/frame 0xfffffe2020f44740
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020f447a0
> ether_demux() at 0xffffffff80575b3a = ether_demux+0x12a/frame
0xfffffe2020f447d0
> ether_nh_input() at 0xffffffff80576792 = ether_nh_input+0x322/frame
0xfffffe2020f44830
> netisr_dispatch_src() at 0xffffffff80583db5 =
netisr_dispatch_src+0xa5/frame 0xfffffe2020f44890
> ether_input() at 0xffffffff80575db6 = ether_input+0x26/frame
0xfffffe2020f448b0
> ixgbe_rxeof() at 0xffffffff813df36b = ixgbe_rxeof+0x7ab/frame
0xfffffe2020f44990
> ixgbe_msix_que() at 0xffffffff813da57c = ixgbe_msix_que+0x8c/frame
0xfffffe2020f449e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe2020f44a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe2020f44a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe2020f44ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe2020f44ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command ps pid 37011 tid 101992 td 0xfffff80144378000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe20224367b0
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe20224367e0
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe2022436820
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe20224368a0
> soalloc() at 0xffffffff8051b914 = soalloc+0x1b4/frame 0xfffffe20224368f0
> socreate() at 0xffffffff8051b617 = socreate+0xa7/frame 0xfffffe2022436940
> sys_socket() at 0xffffffff8052144d = sys_socket+0xed/frame
0xfffffe20224369a0
> amd64_syscall() at 0xffffffff806e4051 = amd64_syscall+0x2c1/frame
0xfffffe2022436ab0
> Xfast_syscall() at 0xffffffff806cb2bb = Xfast_syscall+0xfb/frame
0xfffffe2022436ab0
> --- syscall (97, FreeBSD ELF64, sys_socket), rip = 0x8011c413a, rsp =
0x7fffffffc748, rbp = 0x7fffffffc770 ---
>
> Tracing command cron pid 37008 tid 102228 td 0xfffff801a4090000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe20228d67b0
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe20228d67e0
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe20228d6820
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe20228d68a0
> soalloc() at 0xffffffff8051b914 = soalloc+0x1b4/frame 0xfffffe20228d68f0
> socreate() at 0xffffffff8051b617 = socreate+0xa7/frame 0xfffffe20228d6940
> sys_socket() at 0xffffffff8052144d = sys_socket+0xed/frame
0xfffffe20228d69a0
> amd64_syscall() at 0xffffffff806e4051 = amd64_syscall+0x2c1/frame
0xfffffe20228d6ab0
> Xfast_syscall() at 0xffffffff806cb2bb = Xfast_syscall+0xfb/frame
0xfffffe20228d6ab0
> --- syscall (97, FreeBSD ELF64, sys_socket), rip = 0x800d8c13a, rsp =
0x7fffffffd658, rbp = 0x7fffffffd6f0 ---
>
> [many likes]
>
> Tracing command intr pid 12 tid 100015 td 0xfffff8011422b000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1cf760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1cf790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1cf7d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1cf850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1cf890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1cf8c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1cf8f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1cf9c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1cf9e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1cfa20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1cfa70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1cfab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1cfab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100016 td 0xfffff8011422aa00
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1d4760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1d4790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1d47d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1d4850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1d4890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1d48c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1d48f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1d49c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1d49e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1d4a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1d4a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1d4ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1d4ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100017 td 0xfffff8011422a500
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1d9760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1d9790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1d97d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1d9850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1d9890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1d98c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1d98f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1d99c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1d99e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1d9a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1d9a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1d9ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1d9ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100018 td 0xfffff8011422a000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1de760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1de790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1de7d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1de850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1de890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1de8c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1de8f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1de9c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1de9e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1dea20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1dea70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1deab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1deab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100019 td 0xfffff8011424da00
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1e3760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1e3790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1e37d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1e3850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1e3890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1e38c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1e38f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1e39c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1e39e0
> intr_event_execute_handlers() at 0xffffffff8046c605 = intr_event_execute--
7:zsh -- time-stamp -- Sep/26/16 20:00:13 --
> -- 7:zsh -- time-stamp -- Sep/26/16 20:00:13 --
> _handlers+0x95/frame 0xfffffe1f9e1e3a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1e3a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1e3ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1e3ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100020 td 0xfffff8011424d500
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1e8760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1e8790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1e87d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1e8850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1e8890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1e88c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1e88f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1e89c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1e89e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1e8a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1e8a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1e8ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1e8ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100021 td 0xfffff8011424d000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1ed760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1ed790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1ed7d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1ed850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1ed890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1ed8c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1ed8f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1ed9c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1ed9e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1eda20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1eda70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1edab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1edab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100022 td 0xfffff8011424ca00
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1f2760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1f2790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1f27d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1f2850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1f2890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1f28c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1f28f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1f29c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1f29e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1f2a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1f2a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1f2ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1f2ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100023 td 0xfffff8011424c500
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1f7760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1f7790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1f77d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1f7850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1f7890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1f78c0
> tcp_timer_rexmt() at 0xffffffff8061e454 = tcp_timer_rexmt+0x114/frame
0xfffffe1f9e1f78f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1f79c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1f79e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1f7a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1f7a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1f7ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1f7ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100024 td 0xfffff8011424c000
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe1f9e1fc760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe1f9e1fc790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe1f9e1fc7d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe1f9e1fc850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe1f9e1fc890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe1f9e1fc8c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe1f9e1fc8f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe1f9e1fc9c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe1f9e1fc9e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe1f9e1fca20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe1f9e1fca70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe1f9e1fcab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe1f9e1fcab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100025 td 0xfffff8011424ba00
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe0000382760
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe0000382790
> turnstile_wait() at 0xffffffff804ef177 = turnstile_wait+0x2a7/frame
0xfffffe00003827d0
> __mtx_lock_sleep() at 0xffffffff80484d9d = __mtx_lock_sleep+0x13d/frame
0xfffffe0000382850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe0000382890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe00003828c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe00003828f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe00003829c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe00003829e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe0000382a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe0000382a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe0000382ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe0000382ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
>
> Tracing command intr pid 12 tid 100026 td 0xfffff8011424b500
> sched_switch() at 0xffffffff804c956d = sched_switch+0x6ad/frame
0xfffffe00003876f0
> mi_switch() at 0xffffffff804a8d92 = mi_switch+0xd2/frame 0xfffffe0000387720
> critical_exit() at 0xffffffff804a6bee = critical_exit+0x7e/frame
0xfffffe0000387740
> ipi_bitmap_handler() at 0xffffffff80775629 = ipi_bitmap_handler+0x79/frame
0xfffffe0000387780
> Xipi_intr_bitmap_handler() at 0xffffffff806cc15e =
Xipi_intr_bitmap_handler+0x8e/frame 0xfffffe0000387780
> --- interrupt, rip = 0xffffffff80484c1f, rsp = 0xfffffe0000387850, rbp =
0xfffffe0000387850 ---
> __mtx_lock_flags() at 0xffffffff80484c1f = __mtx_lock_flags+0x2f/frame
0xfffffe0000387850
> sodealloc() at 0xffffffff8051b992 = sodealloc+0x32/frame 0xfffffe0000387890
> tcp_close() at 0xffffffff80618150 = tcp_close+0xd0/frame 0xfffffe00003878c0
> tcp_timer_2msl() at 0xffffffff8061dda3 = tcp_timer_2msl+0x1f3/frame
0xfffffe00003878f0
> softclock_call_cc() at 0xffffffff804b4ca9 = softclock_call_cc+0x179/frame
0xfffffe00003879c0
> softclock() at 0xffffffff804b5034 = softclock+0x44/frame 0xfffffe00003879e0
> intr_event_execute_handlers() at 0xffffffff8046c605 =
intr_event_execute_handlers+0x95/frame 0xfffffe0000387a20
> ithread_loop() at 0xffffffff8046cc26 = ithread_loop+0xa6/frame
0xfffffe0000387a70
> fork_exit() at 0xffffffff8046a211 = fork_exit+0x71/frame 0xfffffe0000387ab0
> fork_trampoline() at 0xffffffff806cb50e = fork_trampoline+0xe/frame
0xfffffe0000387ab0
> --- trap 0, rip = 0, rsp = 0, rbp = 0 ---
Nice stack traces, all threads are blocked in sodealloc() or soalloc()
and if you look at how mtx_lock(&so_global_mtx) and
mtx_unlock(&so_global_mtx) are used, it is hard to think about a
scenario that can lead to this state.
I am still trying to reproduce your issue, without success so far.
--
Julien
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 496 bytes
Desc: OpenPGP digital signature
URL:
<http://lists.freebsd.org/pipermail/freebsd-stable/attachments/20160928/ad00348b/attachment.sig>