ZFS deadlock in zfs_lookup/zfs_dirent_lock on head r271170
Bryan Drewery
bdrewery at FreeBSD.org
Fri Sep 19 20:36:08 UTC 2014
On 9/19/2014 11:46 AM, Bryan Drewery wrote:
> rename is: https://people.freebsd.org/~bdrewery/rename.c
>
> All files are in the same mountpoint.
>
>> # ps uaxwww|egrep "(rm|rename)"
>> root 96901 0.0 0.0 12300 1948 2 D+ 11:01AM 0:00.00 rm -rf /poudriere/data/.m/exp-head-commit-test-devel/ref/.p/cleaning/deps/py27-PasteScript-1.7.5_2
>> root 96903 0.0 0.0 8196 1912 2 D+ 11:01AM 0:00.00 rename /poudriere/data/.m/exp-head-commit-test-devel/ref/.p/deps/py27-PasteDeploy-1.5.0_1 /poudriere/data/.m/exp-head-commit-test-devel/ref/.p/cleaning/deps/py27-PasteDeploy-1.5.0_1
>> root 3720 0.0 0.0 8196 1912 3 D+ 11:05AM 0:00.00 ./rename /poudriere/data/.m/exp-head-commit-test-devel/ref/.p/deps/py27-PasteDeploy-1.5.0_1 /poudriere/data/.m/exp-head-commit-test-devel/ref/.p/cleaning/deps/py27-PasteDeploy-1.5.0_1
>>
>> # procstat -kka|egrep "(96901|96903|3720)"
>> 3720 100969 rename - mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 _cv_wait+0x1da zfs_dirent_lock+0x212 zfs_dirlook+0x1b0 zfs_lookup+0x223 zfs_freebsd_lookup+0x91 VOP_CACHEDLOOKUP_APV+0xf1 vfs_cache_lookup+0xd6 VOP_LOOKUP_APV+0xf1 lookup+0x5ad namei+0x4e4 kern_renameat+0x95 filemon_wrapper_rename+0x19 amd64_syscall+0x25a Xfast_syscall+0xfb
>> 96901 101213 rm - mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 sleeplk+0x14a __lockmgr_args+0x862 vop_stdlock+0x3c VOP_LOCK1_APV+0xfc _vn_lock+0xaa zfs_lookup+0x462 zfs_freebsd_lookup+0x91 VOP_CACHEDLOOKUP_APV+0xf1 vfs_cache_lookup+0xd6 VOP_LOOKUP_APV+0xf1 lookup+0x5ad namei+0x4e4 kern_statat_vnhook+0xae sys_fstatat+0x2c amd64_syscall+0x25a
>> 96903 101290 rename - mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 sleeplk+0x14a __lockmgr_args+0xea1 vop_stdlock+0x3c VOP_LOCK1_APV+0xfc _vn_lock+0xaa vputx+0x232 zfs_rename_unlock+0x78 zfs_freebsd_rename+0xfbb VOP_RENAME_APV+0xfc kern_renameat+0x3ef filemon_wrapper_rename+0x19 amd64_syscall+0x25a Xfast_syscall+0xfb
>>
>> # procstat -kka|grep zfs
>> 0 100698 kernel zfs_vn_rele_task mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 _sleep+0x366 taskqueue_thread_loop+0xc8 fork_exit+0x84 fork_trampoline+0xe
>> 3 100159 zfskern arc_reclaim_thre mi_switch+0x179 sleepq_switch+0x152 sleepq_timedwait+0x43 _cv_timedwait_sbt+0x200 arc_reclaim_thread+0x2de fork_exit+0x84 fork_trampoline+0xe
>> 3 100160 zfskern l2arc_feed_threa mi_switch+0x179 sleepq_switch+0x152 sleepq_timedwait+0x43 _cv_timedwait_sbt+0x200 l2arc_feed_thread+0x1d8 fork_exit+0x84 fork_trampoline+0xe
>> 3 100681 zfskern trim zroot mi_switch+0x179 sleepq_switch+0x152 sleepq_timedwait+0x43 _cv_timedwait_sbt+0x200 trim_thread+0x9e fork_exit+0x84 fork_trampoline+0xe
>> 3 100715 zfskern txg_thread_enter mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 _cv_wait+0x1da txg_thread_wait+0x9b txg_quiesce_thread+0x420 fork_exit+0x84 fork_trampoline+0xe
>> 3 100716 zfskern txg_thread_enter mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 _cv_wait+0x1da zio_wait+0x9b dsl_pool_sync+0x35c spa_sync+0x530 txg_sync_thread+0x24d fork_exit+0x84 fork_trampoline+0xe
>> 3720 100969 rename - mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 _cv_wait+0x1da zfs_dirent_lock+0x212 zfs_dirlook+0x1b0 zfs_lookup+0x223 zfs_freebsd_lookup+0x91 VOP_CACHEDLOOKUP_APV+0xf1 vfs_cache_lookup+0xd6 VOP_LOOKUP_APV+0xf1 lookup+0x5ad namei+0x4e4 kern_renameat+0x95 filemon_wrapper_rename+0x19 amd64_syscall+0x25a Xfast_syscall+0xfb
>> 96901 101213 rm - mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 sleeplk+0x14a __lockmgr_args+0x862 vop_stdlock+0x3c VOP_LOCK1_APV+0xfc _vn_lock+0xaa zfs_lookup+0x462 zfs_freebsd_lookup+0x91 VOP_CACHEDLOOKUP_APV+0xf1 vfs_cache_lookup+0xd6 VOP_LOOKUP_APV+0xf1 lookup+0x5ad namei+0x4e4 kern_statat_vnhook+0xae sys_fstatat+0x2c amd64_syscall+0x25a
>> 96903 101290 rename - mi_switch+0x179 sleepq_switch+0x152 sleepq_wait+0x43 sleeplk+0x14a __lockmgr_args+0xea1 vop_stdlock+0x3c VOP_LOCK1_APV+0xfc _vn_lock+0xaa vputx+0x232 zfs_rename_unlock+0x78 zfs_freebsd_rename+0xfbb VOP_RENAME_APV+0xfc kern_renameat+0x3ef filemon_wrapper_rename+0x19 amd64_syscall+0x25a Xfast_syscall+0xfb
>
>
>
PID 96903 / TID 101290: zfs_rename takes dirent_lock. It then calls
zfs_rename_lock, which then is stuck in vrele()
PID 3720 / TID 100969: zfs_dirlook waits on zfs_dirent_lock.
PID 96901 I think can be ignored, it was fallout and ran 4 minutes after
the deadlock.
Some info from gdb the vnode stuck in vrele() follows. I'm not sure
where to look from here due to it being 'SHARED' with no pid/tid owning it.
> (kgdb) backtrace
> #0 sched_switch (td=0xfffff80834e36490, newtd=<value optimized out>, flags=<value optimized out>) at /usr/src/sys/kern/sched_ule.c:1932
> #1 0xffffffff80929379 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:493
> #2 0xffffffff80966af2 in sleepq_switch (wchan=<value optimized out>, pri=<value optimized out>) at /usr/src/sys/kern/subr_sleepqueue.c:552
> #3 0xffffffff80966953 in sleepq_wait (wchan=0xfffff8090c3259a0, pri=96) at /usr/src/sys/kern/subr_sleepqueue.c:631
> #4 0xffffffff808fdf3a in sleeplk (lk=<value optimized out>, flags=<value optimized out>, ilk=<value optimized out>, wmesg=<value optimized out>, pri=<value optimized out>,
> timo=<value optimized out>) at /usr/src/sys/kern/kern_lock.c:225
> #5 0xffffffff808fd601 in __lockmgr_args (lk=0xfffff8090c3259a0, flags=<value optimized out>, ilk=0xfffff8090c3259d0, wmesg=<value optimized out>, pri=<value optimized out>,
> timo=<value optimized out>, file=0xffffffff80fcd0e8 "/usr/src/sys/kern/vfs_subr.c", line=2248) at /usr/src/sys/kern/kern_lock.c:939
> #6 0xffffffff809be27c in vop_stdlock (ap=<value optimized out>) at lockmgr.h:98
> #7 0xffffffff80e5b75c in VOP_LOCK1_APV (vop=<value optimized out>, a=<value optimized out>) at vnode_if.c:2082
> #8 0xffffffff809ddbca in _vn_lock (vp=0xfffff8090c325938, flags=<value optimized out>, file=0xffffffff80fcd0e8 "/usr/src/sys/kern/vfs_subr.c", line=2248) at vnode_if.h:859
> #9 0xffffffff809ce662 in vputx (vp=0xfffff8090c325938, func=1) at /usr/src/sys/kern/vfs_subr.c:2248
> #10 0xffffffff81e99b28 in zfs_rename_unlock (zlpp=0xfffffe12484b8758) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:3630
> #11 0xffffffff81e969bb in zfs_freebsd_rename (ap=<value optimized out>) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:4067
> #12 0xffffffff80e5ac1c in VOP_RENAME_APV (vop=<value optimized out>, a=<value optimized out>) at vnode_if.c:1544
> #13 0xffffffff809dadcf in kern_renameat (td=<value optimized out>, oldfd=<value optimized out>, old=<value optimized out>, newfd=<value optimized out>, new=<value optimized out>,
> pathseg=<value optimized out>) at vnode_if.h:636
> #14 0xffffffff820c5ab9 in filemon_wrapper_rename (td=0x0, uap=0xfffffe12484b8b80) at filemon_wrapper.c:326
> #15 0xffffffff80d38b6a in amd64_syscall (td=0xfffff80834e36490, traced=0) at subr_syscall.c:133
> #16 0xffffffff80d1a44b in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:390
> #17 0x000000080088df9a in ?? ()
> Previous frame inner to this frame (corrupt stack?)
> (kgdb) vprint 0xfffff8090c325938
> 0xfffff8090c325938: tag zfs, type VDIR
> usecount 1, writecount 0, refcount 2 mountedhere 0x0
> flags ()
> lock type zfs: SHARED (count 2) with exclusive waiters pending
> mount /poudriere/data/.m/exp-head-commit-test-devel/ref from zroot/poudriere/jails/exp-head-commit-test-devel-ref
> (kgdb) p *(struct vnode*)0xfffff8090c325938
> $22 = {v_tag = 0xffffffff81f0f8ff "zfs", v_op = 0xffffffff81f24b50, v_data = 0xfffff809b8612a10, v_mount = 0xfffff8014c262660, v_nmntvnodes = {tqe_next = 0xfffff8095e9aa760,
> tqe_prev = 0xfffff80aa43d7780}, v_un = {vu_mount = 0x0, vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, le_prev = 0x0}, v_cache_src = {
> lh_first = 0x0}, v_cache_dst = {tqh_first = 0xfffff80ac9c35310, tqh_last = 0xfffff80ac9c35330}, v_cache_dd = 0xfffff80ac9c35310, v_lock = {lock_object = {
> lo_name = 0xffffffff81f0f8ff "zfs", lo_flags = 117112832, lo_data = 0, lo_witness = 0xfffffe0000b28780}, lk_lock = 21, lk_exslpfail = 0, lk_timo = 51, lk_pri = 96}, v_interlock = {
> lock_object = {lo_name = 0xffffffff80fc4bc6 "vnode interlock", lo_flags = 16973824, lo_data = 0, lo_witness = 0xfffffe0000b1e500}, mtx_lock = 4}, v_vnlock = 0xfffff8090c3259a0,
> v_actfreelist = {tqe_next = 0xfffff80a5421f1d8, tqe_prev = 0xfffff8095e9aa820}, v_bufobj = {bo_lock = {lock_object = {lo_name = 0xffffffff80fcd144 "bufobj interlock",
> lo_flags = 86179840, lo_data = 0, lo_witness = 0xfffffe0000b26580}, rw_lock = 1}, bo_ops = 0xffffffff814ab900, bo_object = 0x0, bo_synclist = {le_next = 0x0, le_prev = 0x0},
> bo_private = 0xfffff8090c325938, __bo_vnode = 0xfffff8090c325938, bo_clean = {bv_hd = {tqh_first = 0x0, tqh_last = 0xfffff8090c325a58}, bv_root = {pt_root = 0}, bv_cnt = 0},
> bo_dirty = {bv_hd = {tqh_first = 0x0, tqh_last = 0xfffff8090c325a78}, bv_root = {pt_root = 0}, bv_cnt = 0}, bo_numoutput = 0, bo_flag = 0, bo_bsize = 131072}, v_pollinfo = 0x0,
> v_label = 0x0, v_lockf = 0x0, v_rl = {rl_waiters = {tqh_first = 0x0, tqh_last = 0xfffff8090c325ac0}, rl_currdep = 0x0}, v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0,
> v_holdcnt = 2, v_usecount = 1, v_iflag = 512, v_vflag = 0, v_writecount = 0, v_hash = 151794265, v_type = VDIR}
--
Regards,
Bryan Drewery
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 488 bytes
Desc: OpenPGP digital signature
URL: <http://lists.freebsd.org/pipermail/freebsd-fs/attachments/20140919/5e95485a/attachment.sig>
More information about the freebsd-fs
mailing list