svn commit: r326200 - head/sys/kern

[Peter Holm]

On Sun, Nov 26, 2017 at 10:11:21PM +0100, Mateusz Guzik wrote:
> On Sun, Nov 26, 2017 at 7:49 AM, Peter Holm <peter at holm.cc> wrote:
> 
> > On Sat, Nov 25, 2017 at 08:49:27PM +0000, Mateusz Guzik wrote:
> > > Author: mjg
> > > Date: Sat Nov 25 20:49:27 2017
> > > New Revision: 326200
> > > URL: https://svnweb.freebsd.org/changeset/base/326200
> > >
> > > Log:
> > >   Add the missing lockstat check for thread lock.
> > >
> > > Modified:
> > >   head/sys/kern/kern_mutex.c
> > >
> > > Modified: head/sys/kern/kern_mutex.c
> > > ============================================================
> > ==================
> > > --- head/sys/kern/kern_mutex.c        Sat Nov 25 20:37:13 2017
> > (r326199)
> >
> > Hi Mateusz,
> >
> > Could this be yours?
> >
> > spin lock 0xffffffff81ddc100 (turnstile chain) held by 0xfffff80014e57000
> > (tid 100277) too long
> > panic: spin lock held too long
> > cpuid = 20
> > time = 1511677687
> > KDB: stack backtrace:
> > db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame
> > 0xfffffe104f86ea40
> > vpanic() at vpanic+0x268/frame 0xfffffe104f86eb10
> > kproc_shutdown() at kproc_shutdown/frame 0xfffffe104f86eb70
> > _mtx_lock_spin_failed() at _mtx_lock_spin_failed+0x87/frame
> > 0xfffffe104f86eba0
> > _mtx_lock_spin_cookie() at _mtx_lock_spin_cookie+0x4ba/frame
> > 0xfffffe104f86ed10
> > __mtx_lock_spin_flags() at __mtx_lock_spin_flags+0x21f/frame
> > 0xfffffe104f86edb0
> > turnstile_trywait() at turnstile_trywait+0x32/frame 0xfffffe104f86edd0
> > __rw_rlock_hard() at __rw_rlock_hard+0x118/frame 0xfffffe104f86ee60
> > __rw_rlock_int() at __rw_rlock_int+0xd5/frame 0xfffffe104f86ee90
> > getblk() at getblk+0xdb/frame 0xfffffe104f86ef40
> > breadn_flags() at breadn_flags+0x6e/frame 0xfffffe104f86eff0
> > ffs_getcg() at ffs_getcg+0x20d/frame 0xfffffe104f86f0d0
> > ffs_nodealloccg() at ffs_nodealloccg+0xd0/frame 0xfffffe104f86f210
> > ffs_hashalloc() at ffs_hashalloc+0xb7/frame 0xfffffe104f86f290
> > ffs_valloc() at ffs_valloc+0x1c1/frame 0xfffffe104f86f390
> > ufs_makeinode() at ufs_makeinode+0xba/frame 0xfffffe104f86f520
> > ufs_create() at ufs_create+0x34/frame 0xfffffe104f86f540
> > VOP_CREATE_APV() at VOP_CREATE_APV+0x241/frame 0xfffffe104f86f5c0
> > VOP_CREATE() at VOP_CREATE+0x59/frame 0xfffffe104f86f620
> > vn_open_cred() at vn_open_cred+0x311/frame 0xfffffe104f86f770
> > vn_open() at vn_open+0x4c/frame 0xfffffe104f86f7b0
> > kern_openat() at kern_openat+0x212/frame 0xfffffe104f86f920
> > syscallenter() at syscallenter+0x4e4/frame 0xfffffe104f86f9f0
> > amd64_syscall() at amd64_syscall+0x4d/frame 0xfffffe104f86fab0
> >
> > https://people.freebsd.org/~pho/stress/log/mateusz004.txt
> >
> > - Peter
> >
> 
> Fixed in r326237.
> 

Yes, that fixed the issue reported.
After some more tests I got this one:

20171127 01:19:57 all (31/561): mkfifo2c.sh
spin lock 0xffffffff81edace0 (smp rendezvous) held by 0xfffff80d2ae31000 (tid 100529) too long
panic: spin lock held too long
cpuid = 14
time = 1511742163
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe105096c0b0
vpanic() at vpanic+0x19c/frame 0xfffffe105096c130
panic() at panic+0x43/frame 0xfffffe105096c190
_mtx_lock_spin_cookie() at _mtx_lock_spin_cookie+0x352/frame 0xfffffe105096c200
__mtx_lock_spin_flags() at __mtx_lock_spin_flags+0xd8/frame 0xfffffe105096c240
smp_targeted_tlb_shootdown() at smp_targeted_tlb_shootdown+0xd7/frame 0xfffffe105096c2c0
smp_masked_invlpg_range() at smp_masked_invlpg_range+0x50/frame 0xfffffe105096c2f0
pmap_invalidate_range() at pmap_invalidate_range+0x1f4/frame 0xfffffe105096c340
allocbuf() at allocbuf+0x107/frame 0xfffffe105096c3b0
brelse() at brelse+0x219/frame 0xfffffe105096c400
trunc_dependencies() at trunc_dependencies+0x745/frame 0xfffffe105096c4a0
softdep_setup_freeblocks() at softdep_setup_freeblocks+0x7b4/frame 0xfffffe105096c510
ffs_truncate() at ffs_truncate+0x6b8/frame 0xfffffe105096c700
ufs_inactive() at ufs_inactive+0x1cb/frame 0xfffffe105096c740
VOP_INACTIVE_APV() at VOP_INACTIVE_APV+0xfd/frame 0xfffffe105096c770
vinactive() at vinactive+0xe3/frame 0xfffffe105096c7c0
vputx() at vputx+0x31e/frame 0xfffffe105096c820
kern_rmdirat() at kern_rmdirat+0x1c9/frame 0xfffffe105096c980
amd64_syscall() at amd64_syscall+0x7ab/frame 0xfffffe105096cab0

Not so much more info here, I'm afraid:
https://people.freebsd.org/~pho/stress/log/mateusz005.txt

-- 
Peter