panic: corrupted memory in l2arc

[glebius]

System information

FreeBSD 15-CURRENT @ d6e457328d0e
OpenZFS @ 41e55b476bcf
zfs-2.2.99-184-FreeBSD_g41e55b476
zfs-kmod-2.2.99-184-FreeBSD_g41e55b476

Describe the problem you're observing

Got kernel panic running kernel with INVARIANTS enabled. The panic happened during nightly job run, which induces find /. The filesystem has zvols on it and pool configuration has L2ARC.

#7  <signal handler called>
#8  0xffffffff8041b0a5 in buf_hash_find (spa=9365292975275091231, bp=0xfffffe025ed99650, lockp=0xfffffe025ed99598)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:1025
#9  0xffffffff804185eb in arc_read (pio=0xfffffe02b3910600, spa=0xfffffe022ed8c000, bp=0xfffffe025ed99650, 
    done=0xffffffff80462850 <dbuf_read_done>, private=0xfffff8001a0ca7f8, priority=ZIO_PRIORITY_SYNC_READ, zio_flags=128, 
    arc_flags=0xfffffe025ed996dc, zb=0xfffffe025ed996e0) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:5512
#10 0xffffffff804512d5 in dbuf_read_impl (db=0xfffff8001a0ca7f8, zio=0xfffffe02b3910600, flags=30, dblt=DLT_PARENT, tag=0xffffffff81177b83)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dbuf.c:1658
#11 0xffffffff8044f9bd in dbuf_read (db=0xfffff8001a0ca7f8, zio=0xfffffe02b3910600, flags=30)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dbuf.c:1817
#12 0xffffffff804731d8 in dmu_buf_hold_array_by_dnode (dn=0xfffff80a1cc287f0, offset=96128983040, length=32768, read=1, tag=0xffffffff8119becb, 
    numbufsp=0xfffffe025ed9990c, dbpp=0xfffffe025ed99910, flags=0) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dmu.c:598
#13 0xffffffff804744bb in dmu_read_impl (dn=0xfffff80a1cc287f0, offset=96128983040, size=32768, buf=0xfffffe00d472c200, flags=0)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dmu.c:1069
#14 0xffffffff80474369 in dmu_read (os=0xfffff80a1ff92000, object=1, offset=96128983040, size=32768, buf=0xfffffe00d472c200, flags=0)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dmu.c:1106
#15 0xffffffff803eba1a in zvol_geom_bio_strategy (bp=0xfffff800021b62f0)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/os/freebsd/zfs/zvol_os.c:747
#16 0xffffffff803e907a in zvol_geom_bio_start (bp=0xfffff800021b62f0) at /usr/src/FreeBSD/sys/contrib/openzfs/module/os/freebsd/zfs/zvol_os.c:576
#17 0xffffffff80b61e5d in g_io_request (bp=0xfffff800021b62f0, cp=0xfffff8000336b880) at /usr/src/FreeBSD/sys/geom/geom_io.c:587
#18 0xffffffff80b5ba12 in g_dev_strategy (bp=0xfffff804639922f0) at /usr/src/FreeBSD/sys/geom/geom_dev.c:803
#19 0xffffffff80c1d576 in physio (dev=0xfffff8000311fc00, uio=0xfffffe025ed99da0, ioflag=0) at /usr/src/FreeBSD/sys/kern/kern_physio.c:175
#20 0xffffffff80a5fd71 in devfs_read_f (fp=0xfffff8002d5c4730, uio=0xfffffe025ed99da0, cred=0xfffff80a202bca00, flags=1, td=0xfffff808d6d9a740)
    at /usr/src/FreeBSD/sys/fs/devfs/devfs_vnops.c:1415
#21 0xffffffff80cf2cdb in fo_read (fp=0xfffff8002d5c4730, uio=0xfffffe025ed99da0, active_cred=0xfffff80a202bca00, flags=1, td=0xfffff808d6d9a740)
    at /usr/src/FreeBSD/sys/sys/file.h:342
#22 0xffffffff80cee2c9 in dofileread (td=0xfffff808d6d9a740, fd=7, fp=0xfffff8002d5c4730, auio=0xfffffe025ed99da0, offset=96128983040, flags=1)
    at /usr/src/FreeBSD/sys/kern/sys_generic.c:367
#23 0xffffffff80cee124 in kern_preadv (td=0xfffff808d6d9a740, fd=7, auio=0xfffffe025ed99da0, offset=96128983040)
    at /usr/src/FreeBSD/sys/kern/sys_generic.c:333
#24 0xffffffff80cee049 in kern_pread (td=0xfffff808d6d9a740, fd=7, buf=0x3660cbe00200, nbyte=32768, offset=96128983040)
    at /usr/src/FreeBSD/sys/kern/sys_generic.c:242
#25 0xffffffff80cedfb7 in sys_pread (td=0xfffff808d6d9a740, uap=0xfffff808d6d9ab40) at /usr/src/FreeBSD/sys/kern/sys_generic.c:224
#26 0xffffffff8109ca74 in syscallenter (td=0xfffff808d6d9a740) at /usr/src/FreeBSD/sys/amd64/amd64/../../kern/subr_syscall.c:188
#27 0xffffffff8109c215 in amd64_syscall (td=0xfffff808d6d9a740, traced=0) at /usr/src/FreeBSD/sys/amd64/amd64/trap.c:1194
(kgdb) frame 8
#8  0xffffffff8041b0a5 in buf_hash_find (spa=9365292975275091231, bp=0xfffffe025ed99650, lockp=0xfffffe025ed99598)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:1025
1025                    if (HDR_EQUAL(spa, dva, birth, hdr)) {

The second hdr in the chain is corrupted:

(kgdb) p *buf_hash_table.ht_table[idx]->b_hash_next
$103 = {b_dva = {dva_word = {18439988536828035042, 18440551503961587687}}, b_birth = 18440270024689582052, 
  b_type = (ARC_BUFC_NUMTYPES | unknown: 0xffe5ffe0), b_complevel = 227 '\343', b_reserved1 = 255 '\377', b_reserved2 = 65511, 
  b_hash_next = 0xffeaffe5ffe9ffe2, 
  b_flags = (ARC_FLAG_NOWAIT | ARC_FLAG_UNCACHED | ARC_FLAG_PRESCIENT_PREFETCH | ARC_FLAG_IN_HASH_TABLE | ARC_FLAG_IO_IN_PROGRESS | ARC_FLAG_IO_ERROR | ARC_FLAG_INDIRECT | ARC_FLAG_PRIO_ASYNC_READ | ARC_FLAG_L2_WRITING | ARC_FLAG_L2_EVICTED | ARC_FLAG_L2_WRITE_HEAD | ARC_FLAG_PROTECTED | ARC_FLAG_HAS_L2HDR | ARC_FLAG_SHARED_DATA | ARC_FLAG_CACHED_ONLY | ARC_FLAG_NO_BUF | ARC_FLAG_COMPRESS_0 | ARC_FLAG_COMPRESS_1 | ARC_FLAG_COMPRESS_2 | ARC_FLAG_COMPRESS_3 | ARC_FLAG_COMPRESS_4 | ARC_FLAG_COMPRESS_5 | ARC_FLAG_COMPRESS_6 | unknown: 0x80000000), b_psize = 65503, b_lsize = 65507, 
  b_spa = 18438299686967377885, b_l2hdr = {b_dev = 0xffe5ffe1ffdfffdd, b_daddr = 18441395950366097377, b_hits = 4293722085, 
    b_arcs_state = 4293722088, b_l2node = {list_next = 0xffebffe7ffebffe6, list_prev = 0xffe8ffe3ffebffe6}}, b_l1hdr = {

The memory points at a valid location in the hdr_l2only_cache zone, which is marked as allocated in the UMA slab metadata. It is 3rd item in the slab. It appears that first five entries in the slab are all trashed with similar pattern. Starting with sixth's entry the slab items aren't corrupted.

(kgdb) set $keg = hdr_l2only_cache->kc_zone->uz_keg
(kgdb) set $slabmem = (arc_buf_hdr_t *)((uintptr_t)buf_hash_table.ht_table[idx]->b_hash_next & ~4095)
(kgdb) p *(arc_buf_hdr_t *)((uintptr_t)$slabmem + $keg->uk_rsize * 4)
$111 = {b_dva = {dva_word = {18437455227677179862, 18438581149058924505}}, b_birth = 18440551508256030688, 
  b_type = (ARC_BUFC_NUMTYPES | unknown: 0xffebffe4), b_complevel = 230 '\346', b_reserved1 = 255 '\377', b_reserved2 = 65516, 
  b_hash_next = 0xfff0ffeafff2ffee, 
  b_flags = (ARC_FLAG_WAIT | ARC_FLAG_NOWAIT | ARC_FLAG_PREFETCH | ARC_FLAG_UNCACHED | ARC_FLAG_PRESCIENT_PREFETCH | ARC_FLAG_IN_HASH_TABLE | ARC_FLAG_IO_IN_PROGRESS | ARC_FLAG_IO_ERROR | ARC_FLAG_INDIRECT | ARC_FLAG_PRIO_ASYNC_READ | ARC_FLAG_L2_WRITING | ARC_FLAG_L2_EVICTED | ARC_FLAG_L2_WRITE_HEAD | ARC_FLAG_PROTECTED | ARC_FLAG_HAS_L1HDR | ARC_FLAG_HAS_L2HDR | ARC_FLAG_SHARED_DATA | ARC_FLAG_CACHED_ONLY | ARC_FLAG_NO_BUF | ARC_FLAG_COMPRESS_0 | ARC_FLAG_COMPRESS_1 | ARC_FLAG_COMPRESS_2 | ARC_FLAG_COMPRESS_3 | ARC_FLAG_COMPRESS_4 | ARC_FLAG_COMPRESS_5 | ARC_FLAG_COMPRESS_6 | unknown: 0x80000000), b_psize = 65511, b_lsize = 65514, b_spa = 18439144116193001445, b_l2hdr = {b_dev = 0xffe1ffdaffe4ffde, 
    b_daddr = 18439988528237772766, b_hits = 4293394399, b_arcs_state = 4293722086, b_l2node = {list_next = 0xffedffe9ffebffe7, 
      list_prev = 0xffefffe8ffedffe9}}, b_l1hdr = 
(kgdb) p *(arc_buf_hdr_t *)((uintptr_t)$slabmem + $keg->uk_rsize * 5)
$112 = {b_dva = {dva_word = {18441114466800369646, 18439707079031193570}}, b_birth = 18439144116192477152, 
  b_type = (ARC_BUFC_METADATA | ARC_BUFC_NUMTYPES | unknown: 0xffe4ffdc), b_complevel = 230 '\346', b_reserved1 = 255 '\377', 
  b_reserved2 = 65509, b_hash_next = 0x0, 
  b_flags = (ARC_FLAG_IN_HASH_TABLE | ARC_FLAG_HAS_L2HDR | ARC_FLAG_COMPRESSED_ARC | ARC_FLAG_COMPRESS_1), b_psize = 16, b_lsize = 16, 
  b_spa = 9365292975275091231, b_l2hdr = {b_dev = 0xfffffe022fd35000, b_daddr = 172890644480, b_hits = 0, b_arcs_state = ARC_STATE_MRU, 
    b_l2node = {list_next = 0xfffff800400c01d0, list_prev = 0xfffff800400c0290}}, b_l1hdr =

I have core file saved and can provide more data.

[glebius]

One more panic. Different trace, but again smashed entry in the hdr hash.

#7  <signal handler called>
#8  0xffffffff8041b0a5 in buf_hash_find (spa=10619825782056584190, bp=0xfffffe0274d882e0, lockp=0xfffffe025ef13630)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:1025
#9  0xffffffff8041e9a6 in arc_freed (spa=0xfffffe025e6ce000, bp=0xfffffe0274d882e0) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:6117
#10 0xffffffff8064816a in zio_free_sync (pio=0x0, spa=0xfffffe025e6ce000, txg=40797312, bp=0xfffffe0274d882e0, flags=0)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/zio.c:1336
#11 0xffffffff80647ecd in zio_free (spa=0xfffffe025e6ce000, txg=40797312, bp=0xfffffe0274d882e0)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/zio.c:1316
#12 0xffffffff80509888 in dsl_free (dp=0xfffff8000c68b000, txg=40797312, bp=0xfffffe0274d882e0)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dsl_scan.c:1413
#13 0xffffffff804d7a7f in dsl_dataset_block_kill (ds=0xfffff8098b278000, bp=0xfffffe0274d882e0, tx=0xfffff805626e4b00, async=1)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dsl_dataset.c:292
#14 0xffffffff80467e1e in dbuf_write_done (zio=0xfffffe0274d88140, buf=0xfffff8055e5ec840, vdb=0xfffff8055aff9330)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/dbuf.c:4797
#15 0xffffffff80424ff9 in arc_write_done (zio=0xfffffe0274d88140) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:6620
#16 0xffffffff8065a2d4 in zio_done (zio=0xfffffe0274d88140) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/zio.c:4957
#17 0xffffffff8064adef in __zio_execute (zio=0xfffffe0274d88140) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/zio.c:2315
#18 zio_execute (zio=0xfffffe033534bc80) at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/zio.c:2226
#19 0xffffffff80363fb8 in taskq_run_ent (arg=0xfffffe033534c078, pending=1)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/os/freebsd/spl/spl_taskq.c:394
#20 0xffffffff80cd9972 in taskqueue_run_locked (queue=0xfffff8001b2c2100) at /usr/src/FreeBSD/sys/kern/subr_taskqueue.c:512
#21 0xffffffff80cdad2d in taskqueue_thread_loop (arg=0xfffff80003231f80) at /usr/src/FreeBSD/sys/kern/subr_taskqueue.c:824
#22 0xffffffff80be1b3a in fork_exit (callout=0xffffffff80cdac80 <taskqueue_thread_loop>, arg=0xfffff80003231f80, frame=0xfffffe025ef13f40)
    at /usr/src/FreeBSD/sys/kern/kern_fork.c:1160
(kgdb) frame 8
#8  0xffffffff8041b0a5 in buf_hash_find (spa=10619825782056584190, bp=0xfffffe0274d882e0, lockp=0xfffffe025ef13630)
    at /usr/src/FreeBSD/sys/contrib/openzfs/module/zfs/arc.c:1025
1025                    if (HDR_EQUAL(spa, dva, birth, hdr)) {
(kgdb) p buf_hash_table.ht_table[idx]
$1 = (arc_buf_hdr_t *) 0xfffff800400800c0
(kgdb) p *buf_hash_table.ht_table[idx]
$2 = {b_dva = {dva_word = {18440270076228993002, 18439988596957511661}}, b_birth = 18439707117685768170, 
  b_type = (ARC_BUFC_METADATA | unknown: 0xffedfff4), b_complevel = 242 '\362', b_reserved1 = 255 '\377', b_reserved2 = 65517, 
  b_hash_next = 0xffecfff2ffedfff4, 
  b_flags = (ARC_FLAG_NOWAIT | ARC_FLAG_L2CACHE | ARC_FLAG_UNCACHED | ARC_FLAG_PRESCIENT_PREFETCH | ARC_FLAG_IN_HASH_TABLE | ARC_FLAG_IO_IN_PROGRESS | ARC_FLAG_IO_ERROR | ARC_FLAG_INDIRECT | ARC_FLAG_PRIO_ASYNC_READ | ARC_FLAG_L2_WRITING | ARC_FLAG_L2_EVICTED | ARC_FLAG_L2_WRITE_HEAD | ARC_FLAG_PROTECTED | ARC_FLAG_NOAUTH | ARC_FLAG_BUFC_METADATA | ARC_FLAG_HAS_L2HDR | ARC_FLAG_SHARED_DATA | ARC_FLAG_CACHED_ONLY | ARC_FLAG_NO_BUF | ARC_FLAG_COMPRESS_0 | ARC_FLAG_COMPRESS_1 | ARC_FLAG_COMPRESS_2 | ARC_FLAG_COMPRESS_3 | ARC_FLAG_COMPRESS_4 | ARC_FLAG_COMPRESS_5 | ARC_FLAG_COMPRESS_6 | unknown: 0x80000000), b_psize = 65518, b_lsize = 65513, b_spa = 18439707104801193967, b_l2hdr = {b_dev = 0xffe6ffeaffe6ffec, 
    b_daddr = 18438862671280668650, b_hits = 4293197800, b_arcs_state = 4293132265, b_l2node = {list_next = 0xffe4ffe8ffe5ffe7, 
      list_prev = 0xffedfff0ffeafff0}}, b_l1hdr = 

[glebius]

I got third panic. Again different trace, but zvol is involved. Again buf is thrashed and again entire beginning of the slab containing bufs is thrashed.

[Kitt3120]

Similar to the other issues that are popping up on here the past days. ZFS 2.2.x is kinda broken atm. I am also waiting for a fix and had to shut down almost all of my services on my server to prevent a possible pool corruption.

[grahamperrin]

FreeBSD 15-CURRENT @ d6e457328d0e

• freebsd/freebsd-src@d6e457328d0e (2023-11-07)

Please share outputs from:

• uname -aKU
• sysctl vfs.zfs.bclone_enabled
• grep -i zfs /boot/loader.conf | grep -v \# | sort
• grep -i zfs /etc/rc.conf | grep -v \# | sort

OpenZFS @ 41e55b476bcf
zfs-2.2.99-184-FreeBSD_g41e55b476
zfs-kmod-2.2.99-184-FreeBSD_g41e55b476

Here, superior ZFS:

% zfs version
zfs-2.2.99-197-FreeBSD_g9198de8f1
zfs-kmod-2.2.99-197-FreeBSD_g9198de8f1
% uname -aKU
FreeBSD mowa219-gjp4-8570p-freebsd 15.0-CURRENT FreeBSD 15.0-CURRENT #3 main-n266317-f5b3e686292b-dirty: Thu Nov  9 12:49:29 GMT 2023     grahamperrin@mowa219-gjp4-8570p-freebsd:/usr/obj/usr/src/amd64.amd64/sys/GENERIC-NODEBUG amd64 1500003 1500001
% sysctl vfs.zfs.bclone_enabled
vfs.zfs.bclone_enabled: 1
% sudo sysctl vfs.zfs.bclone_enabled=0
grahamperrin's password:
vfs.zfs.bclone_enabled: 1 -> 0
% grep -i zfs /boot/loader.conf | grep -v \# | sort
openzfs_load="NO"
vfs.zfs.debug=1
zfs_load="YES"
% grep -i zfs /etc/rc.conf | grep -v \# | sort
zfs_enable="YES"
zfsd_enable="YES"
zfskeys_enable="YES"
% 

… The filesystem has zvols on it and pool configuration has L2ARC. …

Here:

• L2ARC (three USB flash drives)
• I'm not aware of having a zvol.

[glebius]

>sysctl vfs.zfs.bclone_enabled
vfs.zfs.bclone_enabled: 1
>grep -i zfs /boot/loader.conf | grep -v \# | sort
vfs.root.mountfrom="zfs:zroot/ROOT/default"
grep -i zfs /etc/rc.conf | grep -v \# | sort
zfs_enable="YES"

Right now I'm trying to bisect staying on the same FreeBSD main revision, but bisecting only the openzfs subtree merge. That requires some git gymnastics but is possible. Right now revision 05a7348 seems to be good, but I need to wait at least 24 hours to be sure.

Your revision is definitely ahead of mine, so may be the bug is gone ;|

[KungFuJesus]

The comment about this being bisected to the zvol_threading commit seems to have been deleted. Did you conclude that was actually a dead end / coincidence?

[glebius]

The previous bisect point (assumed to be good) paniced after ~ 24 hours, proving the statement wrong. It is really hard to bisect this, since sometimes it takes minutes to panic and sometimes > 24 hours.

[KungFuJesus]

Ahh, well that at least makes sense, it didn't seem like zvol_threading would have anything to do with where your panics were. Still panic free with bclone_enabled=0, I hope?

[glebius]

No, running with vfs.zfs.bclone_enabled=1. Bisecting. Now running at 799e09f

[glebius]

I also got a second machine with very similar configuration and work profile. Now updating it to bleeding edge FreeBSD/OpenZFS to check if any of the later commits have fixed the problem.

[glebius]

This time my bisecting brought me to dbe839a. It paniced within an hour and previous revision was stable for over 24 hours.

[KungFuJesus]

I'm not sure how helpful the bisect is when BRT is enabled. Though the stack smashing being hit at the DMU might be unique here (other users don't likely have debug assertions on in their ZFS modules).

[glebius]

After more than 24 hours a revision marked as good panic. So pointing to dbe839a was again incorrect. @amotin gave me a patch that loops over entire hash and verifies it again and again the l2arc_feed_thread. Now I'm restarting the bisect from scratch with addition of this patch to speed up crash discovery.