Date: Mon, 4 Mar 2019 15:35:46 -0500 From: Nick Rogers <ncrogers@gmail.com> To: Andriy Gapon <avg@freebsd.org> Cc: FreeBSD STABLE <freebsd-stable@freebsd.org> Subject: Re: 12.0-RELEASE zfs/vnode deadlock issue Message-ID: <CAKOb=YYkuH=8Q94wi=q_zB%2BMS%2BNWXr5Q3_VRarYS5zTz%2BSPfUw@mail.gmail.com> In-Reply-To: <233f3723-a78e-91db-ebe6-9e13c1c9b50d@FreeBSD.org> References: <CAKOb=YaLSPPRrLWGPbcDt0tKqS2h3mT2dLo92aK3r-8O%2B3SHTw@mail.gmail.com> <233f3723-a78e-91db-ebe6-9e13c1c9b50d@FreeBSD.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On Sat, Mar 2, 2019 at 12:48 PM Andriy Gapon <avg@freebsd.org> wrote:
> On 01/03/2019 17:00, Nick Rogers wrote:
> > 36704 101146 perl - mi_switch+0xe1
> > sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_xlock_hard+0x19c
> VOP_LOCK1_APV+0x7e
> > _vn_lock+0x40 zfs_znode_alloc+0x434 zfs_mknode+0xa9d
> > zfs_freebsd_create+0x512 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9
> > kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101
>
> I suspect that this thread is a root cause of the problem.
> In this place, the vnode should be freshly created and not visible to
> anything
> but the current thread. So, vn_lock() should always immediately succeed.
> I
> cannot understand how the vnode lock could be held by another thread.
>
It happened again. I tried to get a backtrace from the offending thread and
one of the others waiting for it. At the moment I have access to this
particular system in its bad state and can leave it like this for as long
as possible, so let me know if there's something else useful I can get out
of the debugger.
courtland# procstat -kka | grep zfs
0 100140 kernel zfsvfs mi_switch+0xe1
sleepq_wait+0x2c _sleep+0x237 taskqueue_thread_loop+0xf1 fork_exit+0x83
fork_trampoline+0xe
0 100424 kernel zfs_vn_rele_taskq mi_switch+0xe1
sleepq_wait+0x2c _sleep+0x237 taskqueue_thread_loop+0xf1 fork_exit+0x83
fork_trampoline+0xe
23 100119 zfskern arc_reclaim_thread mi_switch+0xe1
sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a arc_reclaim_thread+0x146
fork_exit+0x83 fork_trampoline+0xe
23 100120 zfskern arc_dnlc_evicts_thr mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 arc_dnlc_evicts_thread+0x16f fork_exit+0x83
fork_trampoline+0xe
23 100122 zfskern dbuf_evict_thread mi_switch+0xe1
sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a dbuf_evict_thread+0x1c8
fork_exit+0x83 fork_trampoline+0xe
23 100139 zfskern l2arc_feed_thread mi_switch+0xe1
sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a l2arc_feed_thread+0x219
fork_exit+0x83 fork_trampoline+0xe
23 100405 zfskern trim zroot mi_switch+0xe1
sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a trim_thread+0x11f
fork_exit+0x83 fork_trampoline+0xe
23 100441 zfskern txg_thread_enter mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 txg_quiesce+0x21b txg_quiesce_thread+0x11b
fork_exit+0x83 fork_trampoline+0xe
23 100442 zfskern txg_thread_enter mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 txg_sync_thread+0x13b fork_exit+0x83
fork_trampoline+0xe
23 100443 zfskern solthread 0xfffffff mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 zthr_procedure+0xcc fork_exit+0x83
fork_trampoline+0xe
23 100444 zfskern solthread 0xfffffff mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 zthr_procedure+0xcc fork_exit+0x83
fork_trampoline+0xe
7476 100751 postgres - mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 dmu_tx_wait+0x2eb dmu_tx_assign+0x48
zfs_freebsd_create+0x4c8 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9
kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101
7480 100527 postgres - mi_switch+0xe1
sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_xlock_hard+0x19c VOP_LOCK1_APV+0x7e
_vn_lock+0x40 zfs_znode_alloc+0x434 zfs_mknode+0xa9d
zfs_freebsd_create+0x512 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9
kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101
46101 100471 postgres - mi_switch+0xe1
sleepq_wait+0x2c _cv_wait+0x152 dmu_tx_wait+0x2eb dmu_tx_assign+0x48
zfs_freebsd_create+0x4c8 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9
kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101
52625 100488 perl - mi_switch+0xe1
sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e
_vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77
sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101
52675 100643 csh - mi_switch+0xe1
sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e
_vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77
sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101
52826 100562 ls - mi_switch+0xe1
sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e
_vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77
sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101
52889 100641 bash - mi_switch+0xe1
sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e
_vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77
sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101
courtland# kgdb
GNU gdb (GDB) 8.2.1 [GDB v8.2.1 for FreeBSD]
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html
>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-portbld-freebsd12.0".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /boot/kernel/kernel...Reading symbols from
/usr/lib/debug//boot/kernel/kernel.debug...done.
done.
<signal handler called>
(kgdb) tid 100471
(kgdb) bt
#0 sched_switch (td=0xfffff8001196c580, newtd=0xfffff8000354f580,
flags=<optimized out>) at /usr/src/sys/kern/sched_ule.c:2112
#1 0xffffffff80d0e0a1 in mi_switch (flags=<optimized out>, newtd=0x0) at
/usr/src/sys/kern/kern_synch.c:439
#2 0xffffffff80d5c80c in sleepq_wait (wchan=<unavailable>,
pri=<unavailable>) at /usr/src/sys/kern/subr_sleepqueue.c:692
#3 0xffffffff80c9ca52 in _cv_wait (cvp=0xfffff80011354d28,
lock=0xfffff80011354c50) at /usr/src/sys/kern/kern_condvar.c:146
#4 0xffffffff80403dfb in dmu_tx_wait (tx=0xfffff8037afd1c00) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu_tx.c:1090
#5 0xffffffff80403748 in dmu_tx_assign (tx=0xfffff8037afd1c00, txg_how=1)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu_tx.c:1032
#6 0xffffffff804a4ce8 in zfs_create (excl=0, mode=0, dvp=<optimized out>,
name=<optimized out>, vap=<optimized out>, vpp=<optimized out>,
cr=<optimized out>, td=<optimized out>) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:1875
#7 zfs_freebsd_create (ap=0xfffffe008e25a790) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:4996
#8 0xffffffff813aaa68 in VOP_CREATE_APV (vop=<optimized out>,
a=0xfffffe008e25a790) at vnode_if.c:263
#9 0xffffffff80de20f9 in VOP_CREATE (dvp=<unavailable>,
vpp=0xfffffe008e25a888, cnp=<optimized out>, vap=0x18000000001) at
./vnode_if.h:109
#10 vn_open_cred (ndp=0xfffffe008e25a828, flagp=0xfffffe008e25a954,
cmode=<optimized out>, vn_open_flags=<optimized out>,
cred=0xfffff8002b529b00, fp=0xfffff80359185aa0) at
/usr/src/sys/kern/vfs_vnops.c:243
#11 0xffffffff80dda74c in kern_openat (td=0xfffff8001196c580, fd=-100,
path=0x88d3a0f70 <error: Cannot access memory at address 0x88d3a0f70>,
pathseg=UIO_USERSPACE, flags=2563, mode=<optimized out>) at
/usr/src/sys/kern/vfs_syscalls.c:1082
#12 0xffffffff81222449 in syscallenter (td=<optimized out>) at
/usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:135
#13 amd64_syscall (td=0xfffff8001196c580, traced=0) at
/usr/src/sys/amd64/amd64/trap.c:1076
#14 <signal handler called>
#15 0x000000080131e82a in ?? ()
Backtrace stopped: Cannot access memory at address 0x7fffffffb4c8
(kgdb) tid 100527
(kgdb) bt
#0 sched_switch (td=0xfffff8026af9d580, newtd=0xfffff80003551000,
flags=<optimized out>) at /usr/src/sys/kern/sched_ule.c:2112
#1 0xffffffff80d0e0a1 in mi_switch (flags=<optimized out>, newtd=0x0) at
/usr/src/sys/kern/kern_synch.c:439
#2 0xffffffff80d5c80c in sleepq_wait (wchan=<unavailable>,
pri=<unavailable>) at /usr/src/sys/kern/subr_sleepqueue.c:692
#3 0xffffffff80cd9105 in sleeplk (lk=0xfffff802f256c248, flags=<optimized
out>, ilk=<optimized out>, wmesg=<optimized out>, pri=<optimized out>,
timo=51, queue=0) at /usr/src/sys/kern/kern_lock.c:300
#4 0xffffffff80cd819c in lockmgr_xlock_hard (lk=0xfffff802f256c248,
flags=525312, ilk=0xfffff802f256c278, file=<optimized out>, line=<optimized
out>, lwa=<optimized out>) at /usr/src/sys/kern/kern_lock.c:822
#5 0xffffffff813acc5e in VOP_LOCK1_APV (vop=<optimized out>,
a=0xfffffe008e36b280) at vnode_if.c:2087
#6 0xffffffff80de2820 in VOP_LOCK1 (vp=0xfffff802f256c1e0, flags=525312,
file=0xffffffff813c47d0
"/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c",
line=730) at ./vnode_if.h:859
#7 _vn_lock (vp=0xfffff802f256c1e0, flags=525312, file=0xffffffff813c47d0
"/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c",
line=730) at /usr/src/sys/kern/vfs_vnops.c:1533
#8 0xffffffff804ae1f4 in zfs_znode_alloc (zfsvfs=<optimized out>,
db=<optimized out>, blksz=0, obj_type=<optimized out>, hdl=<optimized out>)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c:730
#9 0xffffffff804adc0d in zfs_mknode (dzp=0xfffff802f461f440,
vap=0xfffffe008e36b6e0, tx=<optimized out>, cr=0xfffff8002b529b00,
flag=<optimized out>, zpp=0xfffffe008e36b638, acl_ids=0xfffffe008e36b5f8)
at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c:988
#10 0xffffffff804a4d32 in zfs_create (excl=0, mode=0, dvp=<optimized out>,
name=<optimized out>, vap=<optimized out>, vpp=<optimized out>,
cr=<optimized out>, td=<optimized out>) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:1883
#11 zfs_freebsd_create (ap=0xfffffe008e36b790) at
/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:4996
#12 0xffffffff813aaa68 in VOP_CREATE_APV (vop=<optimized out>,
a=0xfffffe008e36b790) at vnode_if.c:263
#13 0xffffffff80de20f9 in VOP_CREATE (dvp=<unavailable>,
vpp=0xfffffe008e36b888, cnp=<optimized out>, vap=0x18000000001) at
./vnode_if.h:109
#14 vn_open_cred (ndp=0xfffffe008e36b828, flagp=0xfffffe008e36b954,
cmode=<optimized out>, vn_open_flags=<optimized out>,
cred=0xfffff8002b529b00, fp=0xfffff8026d933d70) at
/usr/src/sys/kern/vfs_vnops.c:243
#15 0xffffffff80dda74c in kern_openat (td=0xfffff8026af9d580, fd=-100,
path=0x7fffffffc630 <error: Cannot access memory at address
0x7fffffffc630>, pathseg=UIO_USERSPACE, flags=1538, mode=<optimized out>)
at /usr/src/sys/kern/vfs_syscalls.c:1082
#16 0xffffffff81222449 in syscallenter (td=<optimized out>) at
/usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:135
#17 amd64_syscall (td=0xfffff8026af9d580, traced=0) at
/usr/src/sys/amd64/amd64/trap.c:1076
#18 <signal handler called>
#19 0x000000080138b4fa in ?? ()
Backtrace stopped: Cannot access memory at address 0x7fffffffc138
(kgdb) fr 7
#7 _vn_lock (vp=0xfffff802f256c1e0, flags=525312, file=0xffffffff813c47d0
"/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c",
line=730) at /usr/src/sys/kern/vfs_vnops.c:1533
warning: Source file is more recent than executable.
1533 error = VOP_LOCK1(vp, flags, file, line);
(kgdb) print *vp
$1 = {v_tag = 0xffffffff8144af45 "zfs", v_op = 0xffffffff81c64fd0
<zfs_vnodeops>, v_data = 0xfffff802608c3440, v_mount = 0x0, v_nmntvnodes =
{tqe_next = 0xfffff8037a047000, tqe_prev = 0xfffff802f23feb60},
{v_mountedhere = 0x0, v_unpcb = 0x0, v_rdev = 0x0, v_fifoinfo = 0x0},
v_hashlist = {le_next = 0x0, le_prev = 0x0}, v_cache_src = {
lh_first = 0x0}, v_cache_dst = {tqh_first = 0x0, tqh_last =
0xfffff802f256c230}, v_cache_dd = 0x0, v_lock = {lock_object = {lo_name =
0xffffffff8144af45 "zfs", lo_flags = 117112840, lo_data = 0, lo_witness =
0x0}, lk_lock = 18446744073709551605, lk_exslpfail = 0, lk_timo = 51,
lk_pri = 96}, v_interlock = {lock_object = {
lo_name = 0xffffffff814e4508 "vnode interlock", lo_flags = 16973824,
lo_data = 0, lo_witness = 0x0}, mtx_lock = 0}, v_vnlock =
0xfffff802f256c248, v_actfreelist = {tqe_next = 0xfffff8037a047000,
tqe_prev = 0xfffff80011333a38}, v_bufobj = {bo_lock = {lock_object =
{lo_name = 0xffffffff814a9e5f "bufobj interlock", lo_flags = 86179840,
lo_data = 0, lo_witness = 0x0}, rw_lock = 1}, bo_ops =
0xffffffff81d38600 <buf_ops_bio>, bo_object = 0x0, bo_synclist = {le_next =
0x0, le_prev = 0x0}, bo_private = 0xfffff802f256c1e0, bo_clean = {bv_hd =
{tqh_first = 0x0, tqh_last = 0xfffff802f256c2f8}, bv_root = {pt_root = 0},
bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0,
tqh_last = 0xfffff802f256c318}, bv_root = {pt_root = 0}, bv_cnt =
0}, bo_numoutput = 0, bo_flag = 0, bo_domain = 1, bo_bsize = 16384},
v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0, v_rl = {rl_waiters =
{tqh_first = 0x0, tqh_last = 0xfffff802f256c368}, rl_currdep = 0x0},
v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0,
v_holdcnt = 1, v_usecount = 1, v_iflag = 0, v_vflag = 0, v_mflag = 0,
v_writecount = 0, v_hash = 49436353, v_type = VREG}
(kgdb)
> --
> Andriy Gapon
>
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?CAKOb=YYkuH=8Q94wi=q_zB%2BMS%2BNWXr5Q3_VRarYS5zTz%2BSPfUw>