Bug 236220

Summary:

ZFS vnode deadlock on zfs_mknode

Product:

Base System

Reporter:

ncrogers

Component:

kern

Assignee:

freebsd-fs (Nobody) <fs>

Status:

Closed DUPLICATE

Severity:

Affects Some People

CC:

alexander, andreas.sommer87, cedric, chris, dennis.noordsij, ebay, ipluta, julien, markj, sigsys

Priority:

---

Version:

12.0-RELEASE

Hardware:

Any

OS:

Any

See Also:

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=236480

Attachments:

Description	Flags
procstat + gdb	none
procstat + gdb another system	none
kgdb all threads	none

Description ncrogers 2019-03-04 14:46:30 UTC

Created attachment 202551 [details]
procstat + gdb

Recently a number of my production 12.0 systems have experienced what I can only gather is a ZFS deadlock related to vnodes. It seems similar to the relatively recent FreeBSD-EN-18:18.zfs (ZFS vnode reclaim deadlock) problem. Previously the same systems were running 11.1-RELEASE without problem.

Threads are always stuck with the stack around vn_lock->zfs_root->lookup->namei. When the system is in this state, a simple `ls /` or `ls /tmp` always hangs, but other datasets seem unaffected. I have a fairly straightforward ZFS root setup on a single pool with one SSD. The workload is a ruby/rails/nginx/postgresql backed web application combined with some data warehousing and other periodic tasks.

Sometimes I can remote SSH in, other times that fails because the user shell fails to load, and I can run commands via `ssh ... command`. Sometimes the system is not accessible remotely at all, or it eventually becomes inaccessible if left long enough in this state. I always have to physically reboot the device because the shutdown procedure fails. The network stack (e.g. ping) seems to work completely fine whilst this is going on, until you try to interact with or spawn a process that hits the deadlock.

Like previous similar ZFS deadlock issues, increasing kern.vnodes seems to make the system last longer by up to a few weeks, but is still a bandaid. However, I have yet to witness vnodes usage actually getting close to the maximum.

I haven't had any luck reproducing this reliably, but eventually it happens after a few days or a few weeks... I managed to connect to a system in this state and grab a procstat and get (hopefully) something useful out of kgdb. I will note that although I was able to install debug symbols, I couldn't manage to get the source files onto it for kgdb purposes before I lost SSH access.

Attached is an abbreviated procstat and what I was able to get out of kgdb for an affected thread. Note that the thread backtrace is from a simple `ls` command.

Comment 1 ncrogers 2019-03-04 15:18:35 UTC

avg@freebsd.org pointed out in the freebsd-stable list that one thread is stuck on zfs_znode_alloc, and that is likely the root of the problem. Indeed all the systems I've witnessed this happen to have had one thread stuck on vn_lock -> zfs_znode_alloc. It often seems to be a different application, so I'm still not sure what particular workload is causing this.

For example, the below lines from procstat -kka are from three different systems stuck in a hung / zfs deadlock state.

2329 100515 sh                  -                   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 

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 

1663 100503 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

Comment 2 ncrogers 2019-03-04 20:38:36 UTC

It happened again on a different system. Here is relevant procstat and backtrace of the offending thread and another thread waiting for it.

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)

Comment 3 ncrogers 2019-03-04 20:39:40 UTC

Created attachment 202561 [details]
procstat + gdb another system

Comment 4 ncrogers 2019-03-04 21:02:18 UTC

Created attachment 202562 [details]
kgdb all threads

Comment 5 Andriy Gapon freebsd_committer

2019-03-04 21:44:49 UTC

(In reply to ncrogers from comment #2)
Please print *vp in frame 7 of thread 100527.

Comment 6 ncrogers 2019-03-04 21:53:47 UTC

(In reply to Andriy Gapon from comment #5)
I thought I had that in Comment #2. Here it is again.

(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)

Comment 7 Andriy Gapon freebsd_committer

2019-03-05 10:55:34 UTC

(In reply to ncrogers from comment #6)
Sorry, I missed it in the wall of stack traces.
To mirror what I wrote in the email:
> 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}

lk_lock = 18446744073709551605 = 0xfffffffffffffff5
and that looks like LK_SHARERS_LOCK(-1) | LK_EXCLUSIVE_WAITERS.
I suggest that you try to reproduce the problem with INVARIANTS and INVARIANT_SUPPORT.

Comment 8 ncrogers 2019-03-05 13:18:08 UTC

(In reply to Andriy Gapon from comment #7)
Thanks I will try that. Replicating successfully has been a bit of a waiting game. Any hunches about what may be going on or how I can make it more or less likely to happen?

Comment 9 Andriy Gapon freebsd_committer

2019-03-06 12:47:08 UTC

(In reply to ncrogers from comment #8)
No idea, unfortunately. It might not even be related to ZFS, but some other fs type that you might be using (e.g. nullfs).

Comment 10 ncrogers 2019-03-11 15:02:05 UTC

I finally got a system to panic with INVARIANTS enabled.

panic: solaris assert: dn->dn_type != DMU_OT_NONE, file: /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c, line: 2540

Below is the full panic and backtrace. Let me know if there's something helpful I can provide from kgdb. I also have a second panic but it looks the same.

courtland# kgdb /boot/kernel/kernel /var/crash/vmcore.0
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.

Unread portion of the kernel message buffer:
panic: solaris assert: dn->dn_type != DMU_OT_NONE, file: /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c, line: 2540
cpuid = 1
time = 1552104873
KDB: stack backtrace:
#0 0xffffffff80d3bf77 at kdb_backtrace+0x67
#1 0xffffffff80cf4a53 at vpanic+0x1a3
#2 0xffffffff80cf4833 at panic+0x43
#3 0xffffffff803bbcba at assfail+0x1a
#4 0xffffffff803f094b at dbuf_create+0x9b
#5 0xffffffff803f08a1 at dbuf_create_bonus+0x71
#6 0xffffffff803f8d10 at dmu_bonus_hold+0xb0
#7 0xffffffff804cde29 at zfs_zget+0x69
#8 0xffffffff804bff37 at zfs_get_data+0x67
#9 0xffffffff804d3faf at zil_commit_impl+0x15af
#10 0xffffffff804c73bb at zfs_freebsd_fsync+0xcb
#11 0xffffffff813861be at VOP_FSYNC_APV+0x9e
#12 0xffffffff80dab2d4 at vop_stdfdatasync+0x34
#13 0xffffffff8138a84e at VOP_FDATASYNC_APV+0x9e
#14 0xffffffff80dc7bd3 at kern_fsync+0x1b3
#15 0xffffffff811fc532 at amd64_syscall+0x272
#16 0xffffffff811d65ad at fast_syscall_common+0x101
Uptime: 3d10h28m54s
Dumping 4867 out of 16241 MB:..1%..11%..21%..31%..41%..51%..61%..71%..81%..91%

__curthread () at ./machine/pcpu.h:230
230	./machine/pcpu.h: No such file or directory.
(kgdb) backtrace
#0  __curthread () at ./machine/pcpu.h:230
#1  doadump (textdump=<optimized out>) at /usr/src/sys/kern/kern_shutdown.c:366
#2  0xffffffff80cf468b in kern_reboot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:446
#3  0xffffffff80cf4ab3 in vpanic (fmt=<optimized out>, ap=0xfffffe00b77c54a0)
    at /usr/src/sys/kern/kern_shutdown.c:872
#4  0xffffffff80cf4833 in panic (fmt=<unavailable>) at /usr/src/sys/kern/kern_shutdown.c:799
#5  0xffffffff803bbcba in assfail (a=<unavailable>, f=<unavailable>, l=<unavailable>)
    at /usr/src/sys/cddl/compat/opensolaris/kern/opensolaris_cmn_err.c:81
#6  0xffffffff803f094b in dbuf_create (dn=0xfffff8015f77a770, level=0 '\000', blkid=18446744073709551615, 
    parent=0xfffff80296803c60, blkptr=0x0) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:2540
#7  0xffffffff803f08a1 in dbuf_create_bonus (dn=0xfffff8015f77a770)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:3085
#8  0xffffffff803f8d10 in dmu_bonus_hold (os=<optimized out>, object=<optimized out>, tag=0x0, 
    dbp=0xfffffe00b77c5648) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu.c:345
#9  0xffffffff804cde29 in zfs_zget (zfsvfs=0xfffffe008ea28000, obj_num=33262, zpp=0xfffffe00b77c56c0)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c:1137
#10 0xffffffff804bff37 in zfs_get_data (arg=0xfffffe008ea28000, lr=0xfffffe00a6620300, buf=0x0, 
    lwb=0xfffff8042cf828c0, zio=0xfffff80047eb5000)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:1297
#11 0xffffffff804d3faf in zil_lwb_commit (zilog=<optimized out>, lwb=<optimized out>, itx=<optimized out>)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zil.c:1493
#12 zil_process_commit_list (zilog=<optimized out>)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zil.c:2069
#13 zil_commit_writer (zilog=<optimized out>, zcw=<optimized out>)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zil.c:2201
#14 zil_commit_impl (zilog=<optimized out>, foid=<optimized out>)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zil.c:2712
#15 0xffffffff804c73bb in zfs_fsync (syncflag=0, vp=<optimized out>, cr=<optimized out>, ct=<optimized out>)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:2627
#16 zfs_freebsd_fsync (ap=<optimized out>)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:5079
#17 0xffffffff813861be in VOP_FSYNC_APV (vop=0xffffffff81c64f70 <zfs_vnodeops>, a=0xfffffe00b77c58c0)
    at vnode_if.c:1331
#18 0xffffffff80dab2d4 in VOP_FSYNC (vp=<unavailable>, waitfor=1, td=<optimized out>) at ./vnode_if.h:549
#19 vop_stdfdatasync (ap=<optimized out>) at /usr/src/sys/kern/vfs_default.c:732
#20 0xffffffff8138a84e in VOP_FDATASYNC_APV (vop=0xffffffff81d3b338 <default_vnodeops>, a=0xfffffe00b77c5938)
    at vnode_if.c:4437
#21 0xffffffff80dc7bd3 in VOP_FDATASYNC (vp=<optimized out>, td=<optimized out>) at ./vnode_if.h:1849
#22 kern_fsync (td=0xfffff8000bb96580, fd=<optimized out>, fullsync=false)
    at /usr/src/sys/kern/vfs_syscalls.c:3374
#23 0xffffffff811fc532 in syscallenter (td=0xfffff8000bb96580)
    at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:135
#24 amd64_syscall (td=0xfffff8000bb96580, traced=0) at /usr/src/sys/amd64/amd64/trap.c:1076
#25 <signal handler called>
#26 0x000000080131e8aa in ?? ()
Backtrace stopped: Cannot access memory at address 0x7fffffffd078
(kgdb)

Comment 11 Andriy Gapon freebsd_committer

2019-03-11 21:47:33 UTC

(In reply to ncrogers from comment #10)
To me this looks like a different problem. Probably worth opening a separate bug report.

It would be interesting to see *dn and *parent from frame 6.
Also, it would be interesting to examine object 33262 using zdb -dddd.
You can find out its dataset / filesystem from zfsvfs in frame 9.

Comment 12 ncrogers 2019-03-12 02:35:16 UTC

(In reply to Andriy Gapon from comment #11)

It does seems like it may be a different issue, however definitely started happening after enabling invariants and seems to take about as long as the deadlock issue to manifest.

Here is the requested info:

(kgdb) fr 6
#6  0xffffffff803f094b in dbuf_create (dn=0xfffff8015f77a770, 
    level=0 '\000', blkid=18446744073709551615, 
    parent=0xfffff80296803c60, blkptr=0x0)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dbuf.c:2540
2540		ASSERT(dn->dn_type != DMU_OT_NONE);


(kgdb) print *dn
$2 = {dn_struct_rwlock = {lock_object = {
      lo_name = 0xffffffff814ada70 "dn->dn_struct_rwlock", 
      lo_flags = 40960000, lo_data = 0, lo_witness = 0x0}, 
    sx_lock = 18446735277813228928}, dn_link = {
    list_next = 0xfffff8026c5973d8, list_prev = 0xfffff8018f9cbb48}, 
  dn_objset = 0xfffff8000b72c400, dn_object = 33262, 
  dn_dbuf = 0xfffff80296803c60, dn_handle = 0xfffff802edef9520, 
  dn_phys = 0xfffffe01c6fd1c00, dn_type = DMU_OT_NONE, dn_bonuslen = 168, 
  dn_bonustype = 44 ',', dn_nblkptr = 1 '\001', dn_checksum = 0 '\000', 
  dn_compress = 0 '\000', dn_nlevels = 1 '\001', 
  dn_indblkshift = 17 '\021', dn_datablkshift = 0 '\000', 
  dn_moved = 0 '\000', dn_datablkszsec = 7, dn_datablksz = 3584, 
  dn_maxblkid = 0, dn_next_type = "\000\000\000", 
  dn_num_slots = 1 '\001', dn_next_nblkptr = "\000\000\000", 
  dn_next_nlevels = "\000\000\000", dn_next_indblkshift = "\000\000\000", 
  dn_next_bonustype = "\000\000\000", dn_rm_spillblk = "\000\000\000", 
  dn_next_bonuslen = {0, 0, 0, 0}, dn_next_blksz = {0, 0, 0, 0}, 
  dn_dbufs_count = 0, dn_dirty_link = {{list_next = 0x0, 
      list_prev = 0x0}, {list_next = 0xfffff803bbf774e0, 
      list_prev = 0xfffff8034a965830}, {list_next = 0x0, 
      list_prev = 0x0}, {list_next = 0x0, list_prev = 0x0}}, dn_mtx = {
    lock_object = {lo_name = 0xffffffff81488d05 "dn->dn_mtx", 
      lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
  dn_dirty_records = {{list_size = 344, list_offset = 0, list_head = {
        list_next = 0xfffff8015f77a890, list_prev = 0xfffff8015f77a890}}, 
    {list_size = 344, list_offset = 0, list_head = {
        list_next = 0xfffff8015f77a8b0, list_prev = 0xfffff8015f77a8b0}}, 
    {list_size = 344, list_offset = 0, list_head = {
        list_next = 0xfffff8015f77a8d0, list_prev = 0xfffff8015f77a8d0}}, 
    {list_size = 344, list_offset = 0, list_head = {
        list_next = 0xfffff8015f77a8f0, 
        list_prev = 0xfffff8015f77a8f0}}}, dn_free_ranges = {0x0, 0x0, 
    0x0, 0x0}, dn_allocated_txg = 0, dn_free_txg = 0, 
  dn_assigned_txg = 0, dn_notxholds = {
    cv_description = 0xffffffff814ba0a4 "dn->dn_notxholds", 
    cv_waiters = 0}, dn_dirtyctx = DN_DIRTY_OPEN, 
  dn_dirtyctx_firstset = 0xfffff8038681d070 "\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\360G\305\201\377\377\377\377\336\300\255\336\336\300\255\336\3--Type <RET> for more, q to quit, c to continue without paging--
60G\305\201\377\377\377\377\336\300\255\336\336\300\255\336"..., 
  dn_tx_holds = {rc_mtx = {lock_object = {
        lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, 
        lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, 
    rc_list = {list_size = 40, list_offset = 0, list_head = {
        list_next = 0xfffff8015f77a990, list_prev = 0xfffff8015f77a990}}, 
    rc_removed = {list_size = 40, list_offset = 0, list_head = {
        list_next = 0xfffff8015f77a9b0, list_prev = 0xfffff8015f77a9b0}}, 
    rc_count = 0, rc_removed_count = 0}, dn_holds = {rc_mtx = {
      lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
        lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, 
      sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, 
      list_offset = 0, list_head = {list_next = 0xfffff8015f77aa08, 
        list_prev = 0xfffff8015f77aa08}}, rc_removed = {list_size = 40, 
      list_offset = 0, list_head = {list_next = 0xfffff8015f77aa28, 
        list_prev = 0xfffff8015f77aa28}}, rc_count = 2, 
    rc_removed_count = 0}, dn_dbufs_mtx = {lock_object = {
      lo_name = 0xffffffff814404f1 "dn->dn_dbufs_mtx", 
      lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
  dn_dbufs = {avl_root = 0x0, 
    avl_compar = 0xffffffff80414810 <dbuf_compare>, avl_offset = 288, 
    avl_numnodes = 0, avl_size = 352}, dn_bonus = 0x0, dn_have_spill = 0, 
  dn_zio = 0xfffff8024a314000, dn_oldused = 0, dn_oldflags = 0, 
  dn_olduid = 0, dn_oldgid = 0, dn_newuid = 70, dn_newgid = 70, 
  dn_id_flags = 13, dn_zfetch = {zf_rwlock = {lock_object = {
        lo_name = 0xffffffff813ec741 "zf->zf_rwlock", 
        lo_flags = 40960000, lo_data = 0, lo_witness = 0x0}, 
      sx_lock = 1}, zf_stream = {list_size = 80, list_offset = 64, 
      list_head = {list_next = 0xfffff8015f77ab10, 
        list_prev = 0xfffff8015f77ab10}}, zf_dnode = 0xfffff8015f77a770}}
(kgdb) print *parent
$3 = {db = {db_object = 0, db_offset = 17022976, db_size = 16384, 
    db_data = 0xfffffe01c6fd0000}, db_objset = 0xfffff8000b72c400, 
  db_dnode_handle = 0xfffff8000b72c420, db_parent = 0xfffff800743a9000, 
  db_hash_next = 0x0, db_blkid = 1039, db_blkptr = 0xfffffe017b400780, 
  db_level = 0 '\000', db_mtx = {lock_object = {
      lo_name = 0xffffffff81427def "db->db_mtx", lo_flags = 577830912, 
      lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, db_state = DB_CACHED, 
  db_holds = {rc_mtx = {lock_object = {
        lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, 
        lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, 
    rc_list = {list_size = 40, list_offset = 0, list_head = {
        list_next = 0xfffff80296803d18, list_prev = 0xfffff80296803d18}}, 
    rc_removed = {list_size = 40, list_offset = 0, list_head = {
        list_next = 0xfffff80296803d38, list_prev = 0xfffff80296803d38}}, 
    rc_count = 19, rc_removed_count = 0}, db_buf = 0xfffff80225c1de00, 
  db_changed = {cv_description = 0xffffffff8138c10b "db->db_changed", 
    cv_waiters = 0}, db_data_pending = 0xfffff80449928000, 
  db_last_dirty = 0xfffff80449928000, db_link = {avl_child = {
      0xfffff802abcc6ee0, 0xfffff8030efbfc20}, 
    avl_pcb = 18446735290778607909}, db_cache_link = {list_next = 0x0, 
    list_prev = 0x0}, db_caching_status = DB_NO_CACHE, 
  db_user = 0xfffff802edef9000, db_user_immediate_evict = 0 '\000', 
  db_freed_in_flight = 0 '\000', db_pending_evict = 0 '\000', 
  db_dirtycnt = 1 '\001'}


(kgdb) fr 9
#9  0xffffffff804cde29 in zfs_zget (zfsvfs=0xfffffe008ea28000, obj_num=33262, zpp=0xfffffe00b77c56c0)
    at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c:1137
1137		err = sa_buf_hold(zfsvfs->z_os, obj_num, NULL, &db);


(kgdb) print *zfsvfs
$4 = {z_vfs = 0xfffff800133fd000, z_parent = 0xfffffe008ea28000, z_os = 0xfffff8000b72c400, z_root = 4, z_rootvnode = 0xfffff8001340eb40, 
  z_rootvnodelock = {lock_object = {lo_name = 0xffffffff814594a9 "zfs root vnode lock", lo_flags = 50528256, lo_data = 0, lo_witness = 0x0}, 
    rm_writecpus = {__bits = {0, 0, 0, 0}}, rm_activeReaders = {lh_first = 0x0}, _rm_lock = {_rm_wlock_object = {
        lo_name = 0xffffffff814594a9 "zfs root vnode lock", lo_flags = 16842752, lo_data = 0, lo_witness = 0x0}, _rm_lock_mtx = {lock_object = {
          lo_name = 0xffffffff814594a9 "zfs root vnode lock", lo_flags = 16842752, lo_data = 0, lo_witness = 0x0}, mtx_lock = 0}, _rm_lock_sx = {
        lock_object = {lo_name = 0xffffffff814594a9 "zfs root vnode lock", lo_flags = 16842752, lo_data = 0, lo_witness = 0x0}, sx_lock = 0}}}, 
  z_unlinkedobj = 3, z_max_blksz = 16384, z_fuid_obj = 0, z_fuid_size = 0, z_fuid_idx = {avl_root = 0x0, avl_compar = 0x0, avl_offset = 0, 
    avl_numnodes = 0, avl_size = 0}, z_fuid_domain = {avl_root = 0x0, avl_compar = 0x0, avl_offset = 0, avl_numnodes = 0, avl_size = 0}, 
  z_fuid_lock = {lock_object = {lo_name = 0xffffffff81496098 "zfsvfs->z_fuid_lock", lo_flags = 40960000, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
  z_fuid_loaded = 0, z_fuid_dirty = 0, z_fuid_replay = 0x0, z_log = 0xfffff80003b09800, z_acl_mode = 0, z_acl_inherit = 4, 
  z_case = ZFS_CASE_SENSITIVE, z_utf8 = 0, z_norm = 0, z_atime = 0, z_unmounted = 0, z_teardown_lock = {locks = {{rr_lock = {lock_object = {
            lo_name = 0xffffffff813bcb70 "rrl->rr_lock", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {
          cv_description = 0xffffffff8141c850 "rrl->rr_cv", cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {
              lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, 
          rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea281c0, list_prev = 0xfffffe008ea281c0}}, rc_removed = {
            list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea281e0, list_prev = 0xfffffe008ea281e0}}, rc_count = 1, 
          rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, 
              lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28238, list_prev = 0xfffffe008ea28238}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28258, list_prev = 0xfffffe008ea28258}}, rc_count = 0, rc_removed_count = 0}, rr_writer_wanted = 0, 
        rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", lo_flags = 577830912, lo_data = 0, 
            lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", cv_waiters = 0}, rr_writer = 0x0, 
        rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, 
            sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea282f0, 
              list_prev = 0xfffffe008ea282f0}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28310, 
              list_prev = 0xfffffe008ea28310}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {lock_object = {
              lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, 
          rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28368, list_prev = 0xfffffe008ea28368}}, rc_removed = {
            list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28388, list_prev = 0xfffffe008ea28388}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28420, list_prev = 0xfffffe008ea28420}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28440, list_prev = 0xfffffe008ea28440}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28498, list_prev = 0xfffffe008ea28498}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea284b8, list_prev = 0xfffffe008ea284b8}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28550, list_prev = 0xfffffe008ea28550}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
--Type <RET> for more, q to quit, c to continue without paging--
              list_next = 0xfffffe008ea28570, list_prev = 0xfffffe008ea28570}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea285c8, list_prev = 0xfffffe008ea285c8}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea285e8, list_prev = 0xfffffe008ea285e8}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28680, list_prev = 0xfffffe008ea28680}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea286a0, list_prev = 0xfffffe008ea286a0}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea286f8, list_prev = 0xfffffe008ea286f8}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28718, list_prev = 0xfffffe008ea28718}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea287b0, list_prev = 0xfffffe008ea287b0}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea287d0, list_prev = 0xfffffe008ea287d0}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28828, list_prev = 0xfffffe008ea28828}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28848, list_prev = 0xfffffe008ea28848}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea288e0, list_prev = 0xfffffe008ea288e0}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28900, list_prev = 0xfffffe008ea28900}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28958, list_prev = 0xfffffe008ea28958}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28978, list_prev = 0xfffffe008ea28978}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28a10, list_prev = 0xfffffe008ea28a10}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28a30, list_prev = 0xfffffe008ea28a30}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28a88, list_prev = 0xfffffe008ea28a88}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28aa8, list_prev = 0xfffffe008ea28aa8}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
--Type <RET> for more, q to quit, c to continue without paging--
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28b40, list_prev = 0xfffffe008ea28b40}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28b60, list_prev = 0xfffffe008ea28b60}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28bb8, list_prev = 0xfffffe008ea28bb8}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28bd8, list_prev = 0xfffffe008ea28bd8}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28c70, list_prev = 0xfffffe008ea28c70}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28c90, list_prev = 0xfffffe008ea28c90}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28ce8, list_prev = 0xfffffe008ea28ce8}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28d08, list_prev = 0xfffffe008ea28d08}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28da0, list_prev = 0xfffffe008ea28da0}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28dc0, list_prev = 0xfffffe008ea28dc0}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28e18, list_prev = 0xfffffe008ea28e18}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28e38, list_prev = 0xfffffe008ea28e38}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea28ed0, list_prev = 0xfffffe008ea28ed0}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea28ef0, list_prev = 0xfffffe008ea28ef0}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28f48, list_prev = 0xfffffe008ea28f48}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea28f68, list_prev = 0xfffffe008ea28f68}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea29000, list_prev = 0xfffffe008ea29000}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea29020, list_prev = 0xfffffe008ea29020}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea29078, list_prev = 0xfffffe008ea29078}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea29098, list_prev = 0xfffffe008ea29098}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
--Type <RET> for more, q to quit, c to continue without paging--
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea29130, list_prev = 0xfffffe008ea29130}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea29150, list_prev = 0xfffffe008ea29150}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea291a8, list_prev = 0xfffffe008ea291a8}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea291c8, list_prev = 0xfffffe008ea291c8}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea29260, list_prev = 0xfffffe008ea29260}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea29280, list_prev = 0xfffffe008ea29280}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea292d8, list_prev = 0xfffffe008ea292d8}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea292f8, list_prev = 0xfffffe008ea292f8}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea29390, list_prev = 0xfffffe008ea29390}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea293b0, list_prev = 0xfffffe008ea293b0}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea29408, list_prev = 0xfffffe008ea29408}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea29428, list_prev = 0xfffffe008ea29428}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}, {rr_lock = {lock_object = {lo_name = 0xffffffff813bcb70 "rrl->rr_lock", 
            lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rr_cv = {cv_description = 0xffffffff8141c850 "rrl->rr_cv", 
          cv_waiters = 0}, rr_writer = 0x0, rr_anon_rcount = {rc_mtx = {lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", 
              lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, 
            list_head = {list_next = 0xfffffe008ea294c0, list_prev = 0xfffffe008ea294c0}}, rc_removed = {list_size = 40, list_offset = 0, list_head = {
              list_next = 0xfffffe008ea294e0, list_prev = 0xfffffe008ea294e0}}, rc_count = 0, rc_removed_count = 0}, rr_linked_rcount = {rc_mtx = {
            lock_object = {lo_name = 0xffffffff814893e6 "rc->rc_mtx", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
          rc_tracked = 0, rc_list = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea29538, list_prev = 0xfffffe008ea29538}}, 
          rc_removed = {list_size = 40, list_offset = 0, list_head = {list_next = 0xfffffe008ea29558, list_prev = 0xfffffe008ea29558}}, rc_count = 0, 
          rc_removed_count = 0}, rr_writer_wanted = 0, rr_track_all = 0}}}, z_teardown_inactive_lock = {lock_object = {
      lo_name = 0xffffffff81441592 "zfsvfs->z_teardown_inactive_lock", lo_flags = 40960000, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
  z_all_znodes = {list_size = 272, list_offset = 240, list_head = {list_next = 0xfffff8000ba58420, list_prev = 0xfffff8006add8ca0}}, z_znodes_lock = {
    lock_object = {lo_name = 0xffffffff81489faa "zfsvfs->z_znodes_lock", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1}, 
  z_ctldir = 0xfffff8000ba05400, z_show_ctldir = 0, z_issnap = 0, z_vscan = 0, z_use_fuids = 1, z_replay = 0, z_use_sa = 1, z_use_namecache = 1, 
  z_version = 5, z_shares_dir = 7, z_lock = {lock_object = {lo_name = 0xffffffff8138ce8d "zfsvfs->z_lock", lo_flags = 577830912, lo_data = 0, 
      lo_witness = 0x0}, sx_lock = 1}, z_userquota_obj = 0, z_groupquota_obj = 0, z_replay_eof = 0, z_attr_table = 0xfffff80013351b00, z_hold_mtx = {{
      lock_object = {lo_name = 0xffffffff81429501 "zfsvfs->z_hold_mtx[i]", lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, 
--Type <RET> for more, q to quit, c to continue without paging--
      sx_lock = 1} <repeats 46 times>, {lock_object = {lo_name = 0xffffffff81429501 "zfsvfs->z_hold_mtx[i]", lo_flags = 577830912, lo_data = 0, 
        lo_witness = 0x0}, sx_lock = 18446735277813228928}, {lock_object = {lo_name = 0xffffffff81429501 "zfsvfs->z_hold_mtx[i]", 
        lo_flags = 577830912, lo_data = 0, lo_witness = 0x0}, sx_lock = 1} <repeats 17 times>}, z_unlinked_drain_task = {ta_link = {stqe_next = 0x0}, 
    ta_pending = 0, ta_priority = 0, ta_func = 0xffffffff804bdcd0 <zfsvfs_task_unlinked_drain>, ta_context = 0xfffffe008ea28000}}


(kgdb) print *zfsvfs->z_vfs
$5 = {mnt_mtx = {lock_object = {lo_name = 0xffffffff81393043 "struct mount mtx", lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 0}, 
  mnt_gen = 1, mnt_list = {tqe_next = 0xfffff8001343a000, tqe_prev = 0xfffff800133fe028}, mnt_op = 0xffffffff81c64dc8 <zfs_vfsops>, 
  mnt_vfc = 0xffffffff81c64f18 <zfs_vfsconf>, mnt_vnodecovered = 0xfffff8001340ed20, mnt_syncer = 0xfffff8001340e960, mnt_ref = 896, 
  mnt_nvnodelist = {tqh_first = 0xfffff8001340eb40, tqh_last = 0xfffff80137ee83e0}, mnt_nvnodelistsize = 896, mnt_writeopcount = 0, 
  mnt_kern_flag = 1073742272, mnt_flag = 268439568, mnt_opt = 0xfffff8000ba57e10, mnt_optnew = 0x0, mnt_maxsymlinklen = 0, mnt_stat = {
    f_version = 538182936, f_type = 222, f_flags = 268439568, f_bsize = 512, f_iosize = 16384, f_blocks = 404148032, f_bfree = 390589344, 
    f_bavail = 390589344, f_files = 390593281, f_ffree = 390589344, f_syncwrites = 0, f_asyncwrites = 0, f_syncreads = 0, f_asyncreads = 0, 
    f_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, f_namemax = 255, f_owner = 0, f_fsid = {val = {-901290623, -1775448610}}, 
    f_charspare = '\000' <repeats 79 times>, f_fstypename = "zfs", '\000' <repeats 12 times>, 
    f_mntfromname = "zroot/space/pgsql", '\000' <repeats 1006 times>, f_mntonname = "/space/pgsql", '\000' <repeats 1011 times>}, 
  mnt_cred = 0xfffff800133ef900, mnt_data = 0xfffffe008ea28000, mnt_time = 0, mnt_iosize_max = 65536, mnt_export = 0x0, mnt_label = 0x0, 
  mnt_hashseed = 127686091, mnt_lockref = 0, mnt_secondary_writes = 0, mnt_secondary_accwrites = 0, mnt_susp_owner = 0x0, mnt_gjprovider = 0x0, 
  mnt_listmtx = {lock_object = {lo_name = 0xffffffff8142f7e7 "struct mount vlist mtx", lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, 
    mtx_lock = 0}, mnt_activevnodelist = {tqh_first = 0xfffff802882ebb40, tqh_last = 0xfffff8001340ec00}, mnt_activevnodelistsize = 438, 
  mnt_tmpfreevnodelist = {tqh_first = 0xfffff800244071e0, tqh_last = 0xfffff803c87a82a0}, mnt_tmpfreevnodelistsize = 11, mnt_explock = {
    lock_object = {lo_name = 0xffffffff81469cce "explock", lo_flags = 108199936, lo_data = 0, lo_witness = 0x0}, lk_lock = 1, lk_exslpfail = 0, 
    lk_timo = 0, lk_pri = 96}, mnt_upper_link = {tqe_next = 0x0, tqe_prev = 0x0}, mnt_uppers = {tqh_first = 0x0, tqh_last = 0xfffff800133fdaa8}}
(kgdb) 


courtland# zdb -dddd zroot/space/pgsql 33262
Dataset zroot/space/pgsql [ZPL], ID 184, cr_txg 37, 6.37G, 3905 objects, rootbp DVA[0]=<0:95f64f000:1000> DVA[1]=<0:11e4fbc000:1000> [L0 DMU objset] fletcher4 uncompressed LE contiguous unique double size=800L/800P birth=925624L/925624P fill=3905 cksum=d3563dce4:eed0e01cca3:a72f616c79c87:5770ae867335855

    Object  lvl   iblk   dblk  dsize  dnsize lsize   %full  type
zdb: dmu_bonus_hold(33262) failed, errno 2

Comment 13 ncrogers 2019-03-12 02:47:55 UTC

I created bug #236480.

Comment 14 Julien Cigar 2019-04-01 14:01:04 UTC

I'm also experimenting something similar on 12.0-RELEASE + ZFS, also running PostgreSQL 11 (in jail, with nullfs mounts).

I've seen this on two machines.

The first one is a small HPE Proliant Microserver Gen 8 with 16GB RAM. It started when I upgraded from 10.3 to 12.0, so I don't know if 11.x is affected too. As OP, sometimes I can remote SSH, sometimes not, and a simple ls almost always hangs. A shutdown -r now hangs too after syncing buffers. For some unknow reason the problem didn't occured again (3 months now) since I forced ARC_MAX to 8GB (vfs.zfs.arc_max=8589934592).

The second one is an HPE Proliant DL160Gen9 with 64GB of RAM (freshly installed 12.0-RELEASE). Symptoms are the same as above, with ARC_MAX set to 24GB (vfs.zfs.arc_max=25769803776).

(I'll try to procstat -kk -a next time)

Comment 15 Julien Cigar 2019-04-01 14:30:32 UTC

also I don't know if it's a coincidence or not but on the HPE Proliant DL160Gen9 the problem did not happen anymore until I added a new jail for a new PostgreSQL (9.6) instance (and creating some new ZFS datasets with some nullfs mounts), then the problem occured again two days later.

Comment 16 cedric 2019-04-15 10:10:22 UTC

Are there any news related to this issue? I've a couple of production servers that I want to upgrade to 12.0, but since I use PostgreSQL a lot, I'm scared of this issue...
Thanks

Comment 17 ncrogers 2019-04-15 20:02:40 UTC

(In reply to cedric from comment #16)
The patch in bug #236480 seems to resolve the issue for me, but it's unlikely to be accepted into FreeBSD since the underlying bug originated with a feature in ZFS on Linux (ZoL), which was brought into FreeBSD. However the proper fix in ZoL was much more involved than the patch I mentioned. I'm not sure how to proceed with getting this resolved. Unfortunately the likely way to get more traction with this problem is to have more Postgres+ZFS users upgrade to 12.0 and report their findings.

Comment 18 Julien Cigar 2019-04-17 10:26:42 UTC

(In reply to cedric from comment #16)

I would not upgrade until it gets fixed, I've upgraded 3 dedicated PostgreSQL + ZFS machines to 12.0 and each of them trigger a deadlock after ~ 7-15 days of uptime. 

If you want to help you may upgrade and issue a procstat -kk -a when the problem appears (if you manage to log on the machine which I have never been able to do)

Other than doing fsync / fdatasync a lot I don't think PostgreSQL does anything "special" and it's strange that this problem seems (?) to only manifest when it's installed and running

Comment 19 ipluta 2019-04-17 11:22:52 UTC

(In reply to Julien Cigar from comment #18)
... maybe not so strange. It is not the first time everyone seems happy except a PostgreSQL admin. See this one: https://svnweb.freebsd.org/base?view=revision&revision=253998

Comment 20 Dennis Noordsij 2019-04-28 19:35:52 UTC

As an extra datapoint, I've noticed this exact same problem after upgrading to 12.0-RELEASE in combination with PostgreSQL 11.2

At first I blamed AWS EBS volume hiccups for the stuck-on-access symptoms, but now outside of AWS (KVM based VPS with NAS) I am running into the same problem.

Basic system, a UFS boot partition and a ZFS pool with a root dataset and a database dataset. Dedicated to running PostgreSQL, no other apps running apart from SSH, no jails, etc. Not hitting memory/CPU limits.

Database has recordsize=8k and compression=lz4

It has so far always happened on a sunday/monday, one or twee weeks apart (coincidentally on saturday night a basebackup and an SQL backup are taken which would create some disk/postgresql activity).

Obviously very inconvenient. I can't reproduce it on a dev system (which has a similar hw/sw config but of course not a real usage pattern).

Would appreciate any workarounds or suggestions.

Comment 21 ncrogers 2019-04-29 21:27:38 UTC

(In reply to Dennis Noordsij from comment #20)
Sounds like the same issue I was/am having and others are starting to. In my case, increasing kern.maxvnodes seemed to mask the problem and gave me longer uptime but it eventually happened. So far I have haven't had any problems since applying the patch I attached to bug #236480, however nobody else seems willing to try that so it's still unclear what exactly is going on...

Comment 22 Julien Cigar 2019-04-30 10:40:06 UTC

I have "rolled back" our production server to 11.2 (which has not been a pleasant task BTW) and applied patch from bug #236480 on our 12.0 "dev" machine (a small HPE Microserver) which hasn't deadlocked so far (but it's only 13 days of uptime, and the workload is not the same..)

Comment 23 Dennis Noordsij 2019-04-30 11:45:41 UTC

I'll apply the patch and schedule a maintenance window to reboot the database server tonight.

If the hang happens again (ie this patch does not fix it) I will also downgrade to 11.2, which as Julien describes is painful.

ncrogers if I understand correctly you've been running this patch in production for about 6 weeks now? (on april 1st you said two weeks). Still working fine?

Could you please comment if you do run into anything or have any indication the patch does not (eventually) work?

Safest would be to schedule maintenance and downgrade but it'd be great to get this fixed so I'll try the patch and risk one crash.

Comment 24 ncrogers 2019-04-30 16:18:07 UTC

(In reply to Dennis Noordsij from comment #23)
Yes, I have a few systems that have about a 6 week uptime now after applying the patch, and many more running the same patch with uptimes less than a month because that's about when I started upgrading more systems. It does seem to take up to a few weeks to manifest itself but I feel like I have enough systems running this now that it would have happened.

In my experience it doesn't seem to matter if its a small workload or a huge workload, eventually it strikes. My guess is the problem is unique to something strange with how PostgreSQL handles its WAL but I have no idea what that would be. I have full_page_writes OFF, synchronous_commit OFF, and fsync ON in my postgresql conf. Running PostgreSQL 11.2.

I will definitely report back if I witness a hang/crash. Perhaps it would be useful for someone to open up an issue with PostgreSQL? I am less familiar with their bug reporting process. But given that there is definitively a bug in a feature borrowed  from ZoL that was later fixed in ZoL upstream, it seems like this is more of a FreeBSD problem, so I am not sure if PostgreSQL devs will have much to say other than to perhaps help pinpoint why this is only happening to postgres users?

Comment 25 Dennis Noordsij 2019-05-01 09:33:49 UTC

(In reply to ncrogers from comment #24)

I've updated and will report back if anything happens.

Regarding your comment about workload, I have a dev system running 12.0-RELEASE-p2 that has now been running for 107 days, with a PostgreSQL 11.2 instance with an uptime of 52 days, that I have not seen any problem on. It's the same DB, same kind of ZFS dataset, etc, just a much lighter (dev only) workload.

Comment 26 ncrogers 2019-08-21 17:30:59 UTC


*** This bug has been marked as a duplicate of bug 236480 ***

Comment 27 Julien Cigar 2019-10-07 09:00:35 UTC

I just noticed https://svnweb.freebsd.org/base?view=revision&revision=353176 .. I guess that it's the "proper fix" :) thanks for the work Andriy !