panic: System call lstat returning with 1 locks held

[Scot Hetzel]

Previous message sent prematurely.

On 1/18/08, Scot Hetzel <swhetzel at gmail.com> wrote:
> On 1/17/08, Pawel Jakub Dawidek <pjd at freebsd.org> wrote:
> > On Wed, Jan 16, 2008 at 08:10:03PM -0600, Scot Hetzel wrote:
> > > The local CVS repository is on a ZFS filesystem.  Is anyone seeing
> > > this problem on a UFS filesystem?
> >
> > WITNESS won't work on ZFS' lock by default. Please add:
> >
> > CFLAGS+=-DDEBUG
> >
> > to sys/modules/zfs/Makefile and recompile zfs kernel module. DEBUG
> > define tells ZFS not to add NOWITNESS flag at lock initialization time.
> >
>
> I rebuilt the zfs module as suggested.
>
> When I reboot, I am now seeing 4 different lock order reversals related to ZFS:
>
> 1. This lock order reversal occurs most often:
>
> lock order reversal:
>  1st 0xffffff0001b95838 dr->dt.di.dr_mtx (dr->dt.di.dr_mtx) @
> /usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/dbuf.c:1866
>  2nd 0xffffff00017531c0 db->db_mtx (db->db_mtx) @
> /usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/dbuf.c:1888
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> witness_checkorder() at witness_checkorder+0x606
> _sx_xlock() at _sx_xlock+0x52
> dbuf_sync_list() at dbuf_sync_list+0x215
> dbuf_sync_list() at dbuf_sync_list+0x194
> dnode_sync() at dnode_sync+0x385
> dmu_objset_sync() at dmu_objset_sync+0x116
> dsl_pool_sync() at dsl_pool_sync+0x153
> spa_sync() at spa_sync+0x39e
> txg_sync_thread() at txg_sync_thread+0x17d
> fork_exit() at fork_exit+0x12a
> fork_trampoline() at fork_trampoline+0xe
> --- trap 0, rip = 0, rsp = 0xffffffffd72a3d30, rbp = 0 ---
>
> 2. This lock order reversal is similar to the one above:
>
> lock order reversal:
>  1st 0xffffff0001b00d38 dr->dt.di.dr_mtx (dr->dt.di.dr_mtx) @
> /usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/dbuf.c:1866
>  2nd 0xffffff0001a27760 db->db_mtx (db->db_mtx) @
> /usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/dbuf.c:1837
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> witness_checkorder() at witness_checkorder+0x606
> _sx_xlock() at _sx_xlock+0x52
> dbuf_sync_list() at dbuf_sync_list+0xaf
> dbuf_sync_list() at dbuf_sync_list+0x194
> dnode_sync() at dnode_sync+0x385
> dmu_objset_sync() at dmu_objset_sync+0x116
> dsl_pool_sync() at dsl_pool_sync+0x72
> spa_sync() at spa_sync+0x39e
> txg_sync_thread() at txg_sync_thread+0x17d
> fork_exit() at fork_exit+0x12a
> fork_trampoline() at fork_trampoline+0xe
> --- trap 0, rip = 0, rsp = 0xffffffffd72a3d30, rbp = 0 ---
>
3. lock order reversal related to the write syscall

lock order reversal:
1st 0xffffff00269f6500 dn->dn_mtx (dn->dn_mtx) @
/usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/dnode.c:874
2nd 0xffffff0026338d38 dr->dt.di.dr_mtx (dr->dt.di.dr_mtx) @
/usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/dnode.c:875
KDB: Stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
witness_check_order() at witness_check_order+0x606
_sx_lock() at _sx_lock+0x52
dnode_new_blkid() at dnode_new_blkid+0x15b
dbuf_dirty() at dbuf_dirty+0x7dc
dmu_write_uio() at dmu_write_uio+0x167
zfs_freebsd_write() at zfs_freebsd_write+0x9b4
VOP_WRITE_APV() at VOP_WRITE_APV+0x131
vn_write() at vn_write+0x24f
dofilewrite() at dofilewrite+0x85
kern_writev() at kern_writev+0x60
write() at write+0x54
syscall() at syscall+0x1ce
Xfast_syscall() at Xfast_syscall+0xab
--- syscall (4, FreeBSD ELF64, write), rip = 0x8009f623c, rsp =
0x7729d0, rbp = 0x772a18 ---

4. lock order reversal related to the lstat syscall

lock order reversal:
1st 0xffffff0001578058 zfsvfs->z_um_lock (zfsvfs->z_um_lock) @
/usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:2949
2nd 0xffffff001725cd0 tx->tx_sync_lock (tx->tx_sync_lock) @
/usr/src/sys/modules/zfs/../../contrib/opensolaris/uts/common/fs/zfs/txg.c:414
KDB: Stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
witness_check_order() at witness_check_order+0x606
_sx_lock() at _sx_lock+0x52
txg_wait_open() at txg_wait_open+0x34
dmu_tx_assign() at dmu_tx_assign+0x2a5
zfs_inactive() at zfs_inactive+0x21f
zfs_freebsd_inactive() at zfs_freebsd_inactive+0x18
VOP_INACTIVE_APV() at VOP_INACTIVE_APV+0xb5
vinactive() at vinactive+0x90
vput() at vput+0x24d
namei() at namei+0x29a
kern_lstat() at kern_lstat+0x5e
lstat() at lstat+0x2a
syscall() at syscall+0x1ce
Xfast_syscall() at Xfast_syscall+0xab
--- syscall (190, FreeBSD ELF64, lstat), rip = 0x8009e87ec, rsp =
0x72f1d0, rbp = 0x72f2a8 ---

The panic didn't occur after lock order reversal 4, instead it occured
after the system had displayed lock order reversal 2.

hp010# /usr/local/etc/cvsup/update.sh &
hp010# tail -f /var/log/cvsup.log
:
<lock order reversal 1>
:
<lock order reversal 3>
:
<lock order reversal 1>
<lock order reversal 2>
:
<lock order reversal 4>
:
<lock order reversal 1>
<lock order reversal 2>
Edit CVSROOT-ports/modules,v
:
:
Edit ports/audio/sonata/pkg-plist,v
panic: System call lstat returning with 1 locks held
cpuid = 0
KDB: enter: panic
[ thread pid 996 tid 10011 ]
stopped at kdb_enter+0x3d: movq $0,0x4ad188(%rip)
db> show lockedvnods
Locked vnodes
db>

Scot