Date: Thu, 31 Aug 2023 21:18:30 -0500 From: Kyle Evans <kevans@FreeBSD.org> To: Alexander Motin <mav@FreeBSD.org>, Gleb Smirnoff <glebius@freebsd.org>, Martin Matuska <mm@freebsd.org> Cc: src-committers@freebsd.org, dev-commits-src-all@freebsd.org, dev-commits-src-main@freebsd.org Subject: Re: git: 315ee00fa961 - main - zfs: merge openzfs/zfs@804414aad Message-ID: <a9a0b8b4-b47b-b629-37b6-1c18c8736859@FreeBSD.org> In-Reply-To: <c09c92df-90f5-8c94-4125-9e33262bc686@FreeBSD.org> References: <202308270509.37R596B5048298@gitrepo.freebsd.org> <ZO_aOaf-eGiCMCKy@cell.glebi.us> <c09c92df-90f5-8c94-4125-9e33262bc686@FreeBSD.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On 8/30/23 20:01, Alexander Motin wrote:
> On 30.08.2023 20:09, Gleb Smirnoff wrote:
>> Hi Martin,
>>
>> we hit this panic with this update:
>>
>> panic: VERIFY(avl_is_empty(&lwb->lwb_vdev_tree)) failed
>>
>> cpuid = 8
>> time = 1693432004
>> KDB: stack backtrace:
>> db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame
>> 0xfffffe09519aa800
>> vpanic() at vpanic+0x132/frame 0xfffffe09519aa930
>> spl_panic() at spl_panic+0x3a/frame 0xfffffe09519aa990
>> zil_free_lwb() at zil_free_lwb+0x1de/frame 0xfffffe09519aa9c0
>> zil_sync() at zil_sync+0x3cb/frame 0xfffffe09519aaaa0
>> [Wed Aug 30 21:46:44 2023]dmu_objset_sync() at
>> dmu_objset_sync+0x51b/frame 0xfffffe09519aab70
>> dsl_pool_sync() at dsl_pool_sync+0x11d/frame 0xfffffe09519aabf0
>> spa_sync() at spa_sync+0xc68/frame 0xfffffe09519aae20
>> txg_sync_thread() at txg_sync_thread+0x2eb/frame 0xfffffe09519aaef0
>> fork_exit() at fork_exit+0x82/frame 0xfffffe09519aaf30
>> fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe09519aaf30
>> --- trap 0x26d90a2f, rip = 0xbba54c81b25fd8d4, rsp =
>> 0xff60c2f6f9874bcd, rbp = 0x37940e3e9793bd40 --
>>
>> I have two cores dumped for this panic.
>>
>> Our previous version is based on
>> 9c0a2d522f3a18fc795a7dd6266d2be2aff4b084, which
>> I guess has the most recent ZFS merge openzfs/zfs@009d3288d.
>>
> Hi Gleb,
>
> It is the first time I see a panic like this. I'll think about it
> tomorrow. But I'd appreciate any information on what is your workload
> and what are you doing related to ZIL (O_SYNC, fsync(), sync=always,
> etc) to trigger it? What is your pool configuration?
>
Hello!
Probably not related, but I seem to have hit a use-after-free in ZIL
bits; is this something you're interested in? Backtrace is:
#17 zio_nowait (zio=0xdeadc0dedeadc0de) at
/usr/src.kbsd/sys/contrib/openzfs/module/zfs/zio.c:2367
#18 0xffff00000160720c in zil_lwb_write_issue
(zilog=zilog@entry=0xffffa00021631800, lwb=0xffffa00933d34c40)
at /usr/src.kbsd/sys/contrib/openzfs/module/zfs/zil.c:1935
--Type <RET> for more, q to quit, c to continue without paging--
#19 0xffff0000016031c0 in zil_commit_writer (zilog=0xffffa00021631800,
zcw=0xffffa000fb01e140) at
/usr/src.kbsd/sys/contrib/openzfs/module/zfs/zil.c:2985
#20 zil_commit_impl (zilog=0xffffa00021631800, foid=<optimized out>) at
/usr/src.kbsd/sys/contrib/openzfs/module/zfs/zil.c:3489
#21 0xffff000001602f44 in zil_commit (zilog=<optimized out>,
foid=<optimized out>) at
/usr/src.kbsd/sys/contrib/openzfs/module/zfs/zil.c:3452
#22 0xffff0000015fdac8 in zfs_fsync (zp=0xffffa007e27b23a0,
syncflag=<optimized out>, cr=<optimized out>) at
/usr/src.kbsd/sys/contrib/openzfs/module/zfs/zfs_vnops.c:75
#23 0xffff00000056a864 in VOP_FSYNC (vp=0xffffa001d2003000, waitfor=1,
td=0xffff00015aa94620) at ./vnode_if.h:763
#24 kern_fsync (td=0xffff00015aa94620, fd=<optimized out>,
fullsync=true) at /usr/src.kbsd/sys/kern/vfs_syscalls.c:3556
#25 0xffff000000800630 in syscallenter (td=0xffff00015aa94620) at
/usr/src.kbsd/sys/arm64/arm64/../../kern/subr_syscall.c:187
#26 svc_handler (td=0xffff00015aa94620, frame=<optimized out>) at
/usr/src.kbsd/sys/arm64/arm64/trap.c:198
#27 do_el0_sync (td=0xffff00015aa94620, frame=<optimized out>) at
/usr/src.kbsd/sys/arm64/arm64/trap.c:625
If I pop up to the zil_lwb_write_issue frame:
(kgdb) print *lwb
$4 = {lwb_zilog = 0xdeadc0dedeadc0de, lwb_blk = {blk_dva = {{dva_word =
{16045693110842147038, 16045693110842147038}}, {dva_word =
{16045693110842147038, 16045693110842147038}}, {dva_word =
{16045693110842147038,
16045693110842147038}}}, blk_prop = 16045693110842147038,
blk_pad = {16045693110842147038, 16045693110842147038}, blk_phys_birth =
16045693110842147038, blk_birth = 16045693110842147038,
blk_fill = 16045693110842147038, blk_cksum = {zc_word =
{16045693110842147038, 16045693110842147038, 16045693110842147038,
16045693110842147038}}}, lwb_slim = 3735929054, lwb_slog = 3735929054,
lwb_error = -559038242,
lwb_nmax = -559038242, lwb_nused = -559038242, lwb_nfilled =
-559038242, lwb_sz = -559038242, lwb_state = 3735929054, lwb_buf =
0xdeadc0dedeadc0de <error: Cannot access memory at address
0xdeadc0dedeadc0de>,
lwb_child_zio = 0xdeadc0dedeadc0de, lwb_write_zio =
0xdeadc0dedeadc0de, lwb_root_zio = 0xdeadc0dedeadc0de,
lwb_issued_timestamp = -2401050962867404578, lwb_issued_txg =
16045693110842147038,
lwb_alloc_txg = 16045693110842147038, lwb_max_txg =
16045693110842147038, lwb_node = {list_next = 0xdeadc0dedeadc0de,
list_prev = 0xdeadc0dedeadc0de}, lwb_issue_node = {list_next =
0xdeadc0dedeadc0de,
list_prev = 0xdeadc0dedeadc0de}, lwb_itxs = {list_size =
16045693110842147038, list_offset = 16045693110842147038, list_head =
{list_next = 0xdeadc0dedeadc0de, list_prev = 0xdeadc0dedeadc0de}},
lwb_waiters = {
list_size = 16045693110842147038, list_offset =
16045693110842147038, list_head = {list_next = 0xdeadc0dedeadc0de,
list_prev = 0xdeadc0dedeadc0de}}, lwb_vdev_tree = {avl_root =
0xdeadc0dedeadc0de,
avl_compar = 0xdeadc0dedeadc0de, avl_offset = 16045693110842147038,
avl_numnodes = 16045693110842147038}, lwb_vdev_lock = {lock_object = {
lo_name = 0xdeadc0dedeadc0de <error: Cannot access memory at
address 0xdeadc0dedeadc0de>, lo_flags = 3735929054, lo_data =
3735929054, lo_witness = 0xdeadc0dedeadc0de}, sx_lock =
16045693110842147038}}
It seems to have clearly been stomped on by uma trashing. Encountered
while running a pkgbase build, I think while it was in the packaging
phase. I note in particular in that frame:
(kgdb) p/x lwb->lwb_issued_timestamp
$4 = 0xdeadc0dedeadc0de
So I guess it was freed sometime during one of the previous two
zio_nowait() calls.
Thanks,
Kyle Evans
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?a9a0b8b4-b47b-b629-37b6-1c18c8736859>