Re: ZFS deadlock in 14
- Reply: Cy Schubert : "Re: ZFS deadlock in 14"
- Reply: Dag-Erling_Smørgrav : "Re: ZFS deadlock in 14"
- In reply to: Dag-Erling_Smørgrav : "ZFS deadlock in 14"
- Go to: [ bottom of page ] [ top of archives ] [ this month ]
Date: Sat, 12 Aug 2023 14:11:10 UTC
Dag-Erling Smørgrav <des@FreeBSD.org> writes:
> At some point between 42d088299c (4 May) and f0c9703301 (26 June), a
> deadlock was introduced in ZFS.
Trying to narrow this range down, I did not get a deadlock with
4e8d558c9d1c (10 June) but I did with b7198dcfc039 (16 June), albeit
after building ~1800 packages. This is surprising since we have a
report of this or a very similar deadlock occurring with a kernel from 8
June (https://bugs.freebsd.org/271945). Perhaps I should try
4e8d558c9d1c again.
Here's the complete kgdb session showing, once again, a zfs rollback
stuck waiting for the txg to sync:
Reading symbols from /boot/GENERIC/kernel...
Reading symbols from /usr/lib/debug//boot/GENERIC/kernel.debug...
Unread portion of the kernel message buffer:
panic: deadlres_td_sleep_q: possible deadlock detected for 0xfffffe03567a01e0 (sh), blocked for 180242 ticks
cpuid = 17
time = 1691802362
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe021507ce00
vpanic() at vpanic+0x150/frame 0xfffffe021507ce50
panic() at panic+0x43/frame 0xfffffe021507ceb0
deadlkres() at deadlkres+0x350/frame 0xfffffe021507cef0
fork_exit() at fork_exit+0x80/frame 0xfffffe021507cf30
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe021507cf30
--- trap 0xdeadc0de, rip = 0xdeadc0dedeadc0de, rsp = 0xdeadc0dedeadc0de, rbp = 0xdeadc0dedeadc0de ---
KDB: enter: panic
__curthread () at /usr/src/sys/amd64/include/pcpu_aux.h:59
59 __asm("movq %%gs:%P1,%0" : "=r" (td) : "n" (offsetof(struct pcpu,
(kgdb) tid 0xfffffe03567a01e0
(kgdb) bt
#0 sched_switch (td=td@entry=0xfffffe03567a01e0, flags=flags@entry=259) at /usr/src/sys/kern/sched_ule.c:2299
#1 0xffffffff80b5fbd4 in mi_switch (flags=flags@entry=259) at /usr/src/sys/kern/kern_synch.c:550
#2 0xffffffff80bb1257 in sleepq_switch (wchan=0xfffff80b139e4770, wchan@entry=0xffffffff8113878f, pri=pri@entry=64) at /usr/src/sys/kern/subr_sleepqueue.c:609
#3 0xffffffff80bb112e in sleepq_wait (wchan=<unavailable>, pri=<unavailable>) at /usr/src/sys/kern/subr_sleepqueue.c:660
#4 0xffffffff80b21d6f in sleeplk (lk=lk@entry=0xfffff80b139e4770, flags=flags@entry=2122752, ilk=ilk@entry=0x0, wmesg=wmesg@entry=0xffffffff8113878f "tmpfs", pri=<optimized out>, pri@entry=64, timo=timo@entry=6, queue=1) at /usr/src/sys/kern/kern_lock.c:310
#5 0xffffffff80b1fd9f in lockmgr_slock_hard (lk=0xfffff80b139e4770, flags=2122752, ilk=<optimized out>, file=0xffffffff81296919 "/usr/src/sys/kern/vfs_lookup.c", line=1012, lwa=0x0) at /usr/src/sys/kern/kern_lock.c:705
#6 0xffffffff80c5e444 in VOP_LOCK1 (vp=0xfffff80b139e4700, flags=2106368, file=0xffffffff81296919 "/usr/src/sys/kern/vfs_lookup.c", line=1012) at ./vnode_if.h:1120
#7 _vn_lock (vp=0xfffff80b139e4700, flags=2106368, file=<unavailable>, line=<unavailable>) at /usr/src/sys/kern/vfs_vnops.c:1808
#8 0xffffffff80c36eae in vfs_lookup (ndp=ndp@entry=0xfffffe03c63a6bd8) at /usr/src/sys/kern/vfs_lookup.c:1010
#9 0xffffffff80c36291 in namei (ndp=ndp@entry=0xfffffe03c63a6bd8) at /usr/src/sys/kern/vfs_lookup.c:689
#10 0xffffffff80c5681f in kern_statat (td=0xfffffe03567a01e0, td@entry=<unavailable>, flag=<optimized out>, fd=-100, path=0x1032a8685a15 <error: Cannot access memory at address 0x1032a8685a15>, pathseg=pathseg@entry=UIO_USERSPACE, sbp=sbp@entry=0xfffffe03c63a6d18)
at /usr/src/sys/kern/vfs_syscalls.c:2441
#11 0xffffffff80c56f17 in sys_fstatat (td=<unavailable>, td@entry=<error reading variable: value is not available>, uap=0xfffffe03567a05e0, uap@entry=<error reading variable: value is not available>) at /usr/src/sys/kern/vfs_syscalls.c:2419
#12 0xffffffff8104d8e0 in syscallenter (td=<optimized out>) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:190
#13 amd64_syscall (td=0xfffffe03567a01e0, traced=0) at /usr/src/sys/amd64/amd64/trap.c:1199
#14 <signal handler called>
#15 0x0000103acaf3b03a in ?? ()
Backtrace stopped: Cannot access memory at address 0x103ac929af28
(kgdb) f 5
#5 0xffffffff80b1fd9f in lockmgr_slock_hard (lk=0xfffff80b139e4770, flags=2122752, ilk=<optimized out>, file=0xffffffff81296919 "/usr/src/sys/kern/vfs_lookup.c", line=1012, lwa=0x0) at /usr/src/sys/kern/kern_lock.c:705
705 error = sleeplk(lk, flags, ilk, iwmesg, ipri, itimo,
(kgdb) p (struct thread *)(lk->lk_lock & ~0x1f)
$1 = (struct thread *) 0xfffffe02ddae0e40
(kgdb) tid 0xfffffe02ddae0e40
(kgdb) bt
#0 sched_switch (td=td@entry=0xfffffe02ddae0e40, flags=flags@entry=259) at /usr/src/sys/kern/sched_ule.c:2299
#1 0xffffffff80b5fbd4 in mi_switch (flags=flags@entry=259) at /usr/src/sys/kern/kern_synch.c:550
#2 0xffffffff80bb1257 in sleepq_switch (wchan=wchan@entry=0xfffff81ab3c81154, pri=87, pri@entry=-1278734048) at /usr/src/sys/kern/subr_sleepqueue.c:609
#3 0xffffffff80bb112e in sleepq_wait (wchan=<unavailable>, pri=<unavailable>) at /usr/src/sys/kern/subr_sleepqueue.c:660
#4 0xffffffff80b5f11d in _sleep (ident=0xfffff81ab3c81154, lock=0xfffff81ab3c81120, priority=87, wmesg=0xffffffff82239fba "zfs teardown inactive", sbt=0, pr=0, flags=256) at /usr/src/sys/kern/kern_synch.c:225
#5 0xffffffff80b4b640 in rms_rlock_fallback (rms=rms@entry=0xfffff81ab3c81120) at /usr/src/sys/kern/kern_rmlock.c:1015
#6 0xffffffff80b4b51c in rms_rlock (rms=<unavailable>, rms@entry=0xfffff81ab3c81120) at /usr/src/sys/kern/kern_rmlock.c:1036
#7 0xffffffff81faff5c in zfs_freebsd_reclaim (ap=<optimized out>) at /usr/src/sys/contrib/openzfs/module/os/freebsd/zfs/zfs_vnops_os.c:5164
#8 0xffffffff811215e4 in VOP_RECLAIM_APV (vop=0xffffffff822e61a0 <zfs_vnodeops>, a=a@entry=0xfffffe02fb2118a0) at vnode_if.c:2180
#9 0xffffffff80c47d54 in VOP_RECLAIM (vp=0xfffff80912340000) at ./vnode_if.h:1084
#10 vgonel (vp=vp@entry=0xfffff80912340000) at /usr/src/sys/kern/vfs_subr.c:4143
#11 0xffffffff80c436f2 in vtryrecycle (vp=0xfffff80912340000) at /usr/src/sys/kern/vfs_subr.c:1693
#12 vnlru_free_impl (count=count@entry=1, mnt_op=mnt_op@entry=0x0, mvp=0xfffff8010945da00) at /usr/src/sys/kern/vfs_subr.c:1344
#13 0xffffffff80c4dd83 in vnlru_free_locked (count=1) at /usr/src/sys/kern/vfs_subr.c:1357
#14 vn_alloc_hard (mp=mp@entry=0xfffffe0314140000) at /usr/src/sys/kern/vfs_subr.c:1744
#15 0xffffffff80c43db1 in vn_alloc (mp=0xfffffe0314140000) at /usr/src/sys/amd64/include/atomic.h:375
#16 getnewvnode (tag=0xffffffff8113878f "tmpfs", mp=0xfffffe0314140000, vops=0xffffffff816b7a70 <tmpfs_vnodeop_entries>, vpp=vpp@entry=0xfffffe02fb211a30) at /usr/src/sys/kern/vfs_subr.c:1810
#17 0xffffffff80a7b27c in tmpfs_alloc_vp (mp=0xfffffe0314140000, node=node@entry=0xfffff81924deabc8, lkflag=lkflag@entry=524288, vpp=0xfffffe02fb211cf0) at /usr/src/sys/fs/tmpfs/tmpfs_subr.c:1027
#18 0xffffffff80a7b985 in tmpfs_alloc_file (dvp=dvp@entry=0xfffff80b139e4700, vpp=<unavailable>, vpp@entry=0xfffffe02fb211cf0, vap=<optimized out>, cnp=cnp@entry=0xfffffe02fb211d18, target=target@entry=0x0) at /usr/src/sys/fs/tmpfs/tmpfs_subr.c:1203
#19 0xffffffff80a74d28 in tmpfs_create (v=<optimized out>) at /usr/src/sys/fs/tmpfs/tmpfs_vnops.c:271
#20 0xffffffff8111eb99 in VOP_CREATE_APV (vop=0xffffffff816b7a70 <tmpfs_vnodeop_entries>, a=a@entry=0xfffffe02fb211be0) at vnode_if.c:244
#21 0xffffffff80c5d94c in VOP_CREATE (dvp=<unavailable>, vpp=0xfffffe02fb211cf0, cnp=0xfffffe02fb211d18, vap=0xfffffe02fb211b20) at ./vnode_if.h:133
#22 vn_open_cred (ndp=ndp@entry=0xfffffe02fb211c98, flagp=flagp@entry=0xfffffe02fb211da4, cmode=cmode@entry=420, vn_open_flags=vn_open_flags@entry=16, cred=0xfffff8010978bc00, fp=0xfffff804f42cff00) at /usr/src/sys/kern/vfs_vnops.c:287
#23 0xffffffff80c53f43 in kern_openat (td=0xfffffe02ddae0e40, td@entry=<unavailable>, fd=fd@entry=-100, path=0x8222f799b <error: Cannot access memory at address 0x8222f799b>, pathseg=pathseg@entry=UIO_USERSPACE, flags=1538, mode=<optimized out>)
at /usr/src/sys/kern/vfs_syscalls.c:1167
#24 0xffffffff80c53cad in sys_open (td=td@entry=<unavailable>, uap=uap@entry=<unavailable>) at /usr/src/sys/kern/vfs_syscalls.c:1095
#25 0xffffffff82b18365 in filemon_wrapper_open (td=<unavailable>, td@entry=<error reading variable: value is not available>, uap=<unavailable>, uap@entry=<error reading variable: value is not available>) at /usr/src/sys/dev/filemon/filemon_wrapper.c:220
#26 0xffffffff8104d8e0 in syscallenter (td=<optimized out>) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:190
#27 amd64_syscall (td=0xfffffe02ddae0e40, traced=0) at /usr/src/sys/amd64/amd64/trap.c:1199
#28 <signal handler called>
#29 0x0000000829c8227a in ?? ()
Backtrace stopped: Cannot access memory at address 0x8222f6868
(kgdb) f 7
#7 0xffffffff81faff5c in zfs_freebsd_reclaim (ap=<optimized out>) at /usr/src/sys/contrib/openzfs/module/os/freebsd/zfs/zfs_vnops_os.c:5164
5164 ZFS_TEARDOWN_INACTIVE_ENTER_READ(zfsvfs);
(kgdb) p zp->z_zfsvfs->z_teardown_inactive_lock->owner
$2 = (struct thread *) 0xfffffe0314249020
(kgdb) tid 0xfffffe0314249020
(kgdb) bt
#0 sched_switch (td=td@entry=0xfffffe0314249020, flags=flags@entry=259) at /usr/src/sys/kern/sched_ule.c:2299
#1 0xffffffff80b5fbd4 in mi_switch (flags=flags@entry=259) at /usr/src/sys/kern/kern_synch.c:550
#2 0xffffffff80bb1257 in sleepq_switch (wchan=wchan@entry=0xfffff80108fe1540, pri=0, pri@entry=150869200) at /usr/src/sys/kern/subr_sleepqueue.c:609
#3 0xffffffff80bb112e in sleepq_wait (wchan=<unavailable>, wchan@entry=0xfffff80108fe1540, pri=<unavailable>, pri@entry=0) at /usr/src/sys/kern/subr_sleepqueue.c:660
#4 0xffffffff80ade224 in _cv_wait (cvp=0xfffff80108fe1540, lock=0xfffff80108fe14d0) at /usr/src/sys/kern/kern_condvar.c:146
#5 0xffffffff820b383b in txg_wait_synced_impl (dp=0xfffff80108fe1000, txg=8751529, txg@entry=0, wait_sig=wait_sig@entry=0) at /usr/src/sys/contrib/openzfs/module/zfs/txg.c:726
#6 0xffffffff820b31eb in txg_wait_synced (dp=<unavailable>, txg=<unavailable>, txg@entry=0) at /usr/src/sys/contrib/openzfs/module/zfs/txg.c:736
#7 0xffffffff81fa5fc5 in zfsvfs_teardown (zfsvfs=0xfffff81ab3c81000, unmounting=unmounting@entry=0) at /usr/src/sys/contrib/openzfs/module/os/freebsd/zfs/zfs_vfsops.c:1661
#8 0xffffffff81fa5db9 in zfs_suspend_fs (zfsvfs=<unavailable>) at /usr/src/sys/contrib/openzfs/module/os/freebsd/zfs/zfs_vfsops.c:1954
#9 0xffffffff821680ff in zfs_ioc_rollback (fsname=0xfffffe0301913000 "zroot-default-ref/03", fsname@entry=<error reading variable: value is not available>, innvl=<unavailable>, innvl@entry=<error reading variable: value is not available>,
outnvl=0xfffff81601748640, outnvl@entry=<error reading variable: value is not available>) at /usr/src/sys/contrib/openzfs/module/zfs/zfs_ioctl.c:4401
#10 0xffffffff82163836 in zfsdev_ioctl_common (vecnum=vecnum@entry=25, zc=zc@entry=0xfffffe0301913000, flag=flag@entry=0) at /usr/src/sys/contrib/openzfs/module/zfs/zfs_ioctl.c:7798
#11 0xffffffff81f969aa in zfsdev_ioctl (dev=<optimized out>, zcmd=<unavailable>, zcmd@entry=<error reading variable: value is not available>, arg=0xfffffe02fd546d50 "\017", arg@entry=<error reading variable: value is not available>, flag=<optimized out>, td=<optimized out>)
at /usr/src/sys/contrib/openzfs/module/os/freebsd/zfs/kmod_core.c:168
#12 0xffffffff809dc9cc in devfs_ioctl (ap=0xfffffe02fd546c40) at /usr/src/sys/fs/devfs/devfs_vnops.c:935
#13 0xffffffff80c5cac0 in vn_ioctl (fp=0xfffff81e9207f0a0, com=<optimized out>, data=0xfffffe02fd546d50, active_cred=0xfffff8026a65a900, td=<unavailable>) at /usr/src/sys/kern/vfs_vnops.c:1697
#14 0xffffffff809dd07e in devfs_ioctl_f (fp=<unavailable>, fp@entry=<error reading variable: value is not available>, com=<unavailable>, com@entry=<error reading variable: value is not available>, data=<unavailable>, data@entry=<error reading variable: value is not available>,
cred=<unavailable>, cred@entry=<error reading variable: value is not available>, td=<unavailable>, td@entry=<error reading variable: value is not available>) at /usr/src/sys/fs/devfs/devfs_vnops.c:866
#15 0xffffffff80bca1ce in fo_ioctl (fp=0xfffff81e9207f0a0, com=3222821401, data=<unavailable>, active_cred=<unavailable>, td=<optimized out>) at /usr/src/sys/sys/file.h:367
#16 kern_ioctl (td=td@entry=0xfffffe0314249020, fd=<optimized out>, com=com@entry=3222821401, data=<unavailable>, data@entry=0xfffffe02fd546d50 "\017") at /usr/src/sys/kern/sys_generic.c:807
#17 0xffffffff80bc9f64 in sys_ioctl (td=0xfffffe0314249020, td@entry=<error reading variable: value is not available>, uap=0xfffffe0314249420, uap@entry=<error reading variable: value is not available>) at /usr/src/sys/kern/sys_generic.c:715
#18 0xffffffff8104d8e0 in syscallenter (td=<optimized out>) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:190
#19 amd64_syscall (td=0xfffffe0314249020, traced=0) at /usr/src/sys/amd64/amd64/trap.c:1199
#20 <signal handler called>
#21 0x000005c8e125953a in ?? ()
Backtrace stopped: Cannot access memory at address 0x5c8d89c8018
DES
--
Dag-Erling Smørgrav - des@FreeBSD.org