svn commit: r326200 - head/sys/kern

Thu Nov 30 05:18:56 UTC 2017

So this is not my bug after all, it just had unfortunate timing with
scheduler changes.

I can't reproduce anything with r326376.

On Tue, Nov 28, 2017 at 9:37 PM, Alan Somers <asomers at freebsd.org> wrote:

> On Sun, Nov 26, 2017 at 11:49 PM, Peter Holm <peter at holm.cc> wrote:
> > 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
>
> I'm seeing a similar panic, at r326314:
>
> panic: spin lock held too long
> cpuid = 3
> time = 1511900768
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame
> 0xfffffe0b58bcef00
> vpanic() at vpanic+0x19c/frame 0xfffffe0b58bcef80
> panic() at panic+0x43/frame 0xfffffe0b58bcefe0
> _mtx_lock_spin_cookie() at _mtx_lock_spin_cookie+0x352/frame
> 0xfffffe0b58bcf050
> __mtx_lock_spin_flags() at __mtx_lock_spin_flags+0xd8/frame
> 0xfffffe0b58bcf090
> smp_targeted_tlb_shootdown() at smp_targeted_tlb_shootdown+0xd7/frame
> 0xfffffe0b58bcf110
> smp_masked_invlpg_range() at smp_masked_invlpg_range+0x50/frame
> 0xfffffe0b58bcf140
> pmap_invalidate_range() at pmap_invalidate_range+0x1f4/frame
> 0xfffffe0b58bcf190
> vm_thread_stack_dispose() at vm_thread_stack_dispose+0x2f/frame
> 0xfffffe0b58bcf1e0
> thread_free() at thread_free+0x39/frame 0xfffffe0b58bcf200
> thread_reap() at thread_reap+0x9e/frame 0xfffffe0b58bcf220
> thread_alloc() at thread_alloc+0xf/frame 0xfffffe0b58bcf240
> kthread_add() at kthread_add+0x43/frame 0xfffffe0b58bcf2e0
> _taskqueue_start_threads() at _taskqueue_start_threads+0xde/frame
> 0xfffffe0b58bcf370
> taskqueue_start_threads() at taskqueue_start_threads+0x3f/frame
> 0xfffffe0b58bcf3d0
> taskq_create_proc() at taskq_create_proc+0x92/frame 0xfffffe0b58bcf400
> spa_activate() at spa_activate+0x372/frame 0xfffffe0b58bcf4a0
> spa_open_common() at spa_open_common+0xd2/frame 0xfffffe0b58bcf510
> spa_get_stats() at spa_get_stats+0x4f/frame 0xfffffe0b58bcf6f0
> zfs_ioc_pool_stats() at zfs_ioc_pool_stats+0x25/frame 0xfffffe0b58bcf730
> zfsdev_ioctl() at zfsdev_ioctl+0x766/frame 0xfffffe0b58bcf7e0
> devfs_ioctl() at devfs_ioctl+0xcb/frame 0xfffffe0b58bcf830
> VOP_IOCTL_APV() at VOP_IOCTL_APV+0xd9/frame 0xfffffe0b58bcf860
> vn_ioctl() at vn_ioctl+0x124/frame 0xfffffe0b58bcf970
> devfs_ioctl_f() at devfs_ioctl_f+0x1f/frame 0xfffffe0b58bcf990
> kern_ioctl() at kern_ioctl+0x2c4/frame 0xfffffe0b58bcf9f0
> sys_ioctl() at sys_ioctl+0x15c/frame 0xfffffe0b58bcfac0
> amd64_syscall() at amd64_syscall+0x79b/frame 0xfffffe0b58bcfbf0
> Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe0b58bcfbf0
>

-- 
Mateusz Guzik <mjguzik gmail.com>