On Sep 7, 2023, at 13:07, Alexander Motin <m...@freebsd.org> wrote: > Thanks, Mark. > > On 07.09.2023 15:40, Mark Millard wrote: >> On Sep 7, 2023, at 11:48, Glen Barber <g...@freebsd.org> wrote: >>> On Thu, Sep 07, 2023 at 11:17:22AM -0700, Mark Millard wrote: >>>> When I next have time, should I retry based on a more recent >>>> vintage of main that includes 969071be938c ? >>> >>> Yes, please, if you can. >> As stands, I rebooted that machine into my normal >> enviroment, so the after-crash-with-dump-info >> context is preserved. I'll presume lack of a need >> to preserve that context unless I hear otherwise. >> (But I'll work on this until later today.) >> Even my normal environment predates the commit in >> question by a few commits. So I'll end up doing a >> more general round of updates overall. >> Someone can let me know if there is a preference >> for debug over non-debug for the next test run. > > It is not unknown when some bugs disappear once debugging is enabled due to > different execution timings, but generally debug may to detect the problem > closer to its origin instead of looking on random consequences. I am only > starting to look on this report (unless Pawel or somebody beat me on it), and > don't have additional requests yet, but if you can repeat the same with debug > kernel (in-base ZFS's ZFS_DEBUG setting follows kernel's INVARIANTS), it may > give us some additional information.
So I did a zpool import, rewinding to the checkpoint. (This depends on the questionable zfs doing fully as desired for this. Notably the normal environment has vfs.zfs.bclone_enabled=0 , including when it was doing this activity.) My normal environment reported no problems. Note: the earlier snapshot from my first setup was still in place since it was made just before the original checkpoint used above. However, the rewind did remove the /var/crash/ material that had been added. I did the appropriate zfs mount. I installed a debug kernel and world to the import. Again, no problems reported. I did the appropriate zfs umount. I did the appropriate zpool export. I rebooted with the test media. # sysctl vfs.zfs.bclone_enabled vfs.zfs.bclone_enabled: 1 # zpool trim -w zamd64 # zpool checkpoint zamd64 # uname -apKU FreeBSD amd64-ZFS 15.0-CURRENT FreeBSD 15.0-CURRENT amd64 1500000 #74 main-n265188-117c54a78ccd-dirty: Tue Sep 5 21:29:53 PDT 2023 root@amd64-ZFS:/usr/obj/BUILDs/main-amd64-dbg-clang/usr/main-src/amd64.amd64/sys/GENERIC-DBG amd64 amd64 1500000 1500000 (So, before the 969071be938c vintage, same sources as for my last run but a debug build.) # poudriere bulk -jmain-amd64-bulk_a -a . . . [00:03:23] Building 34214 packages using up to 32 builders [00:03:23] Hit CTRL+t at any time to see build progress and stats [00:03:23] [01] [00:00:00] Builder starting [00:04:19] [01] [00:00:56] Builder started [00:04:20] [01] [00:00:01] Building ports-mgmt/pkg | pkg-1.20.6 [00:05:33] [01] [00:01:14] Finished ports-mgmt/pkg | pkg-1.20.6: Success [00:05:53] [01] [00:00:00] Building print/indexinfo | indexinfo-0.3.1 [00:05:53] [02] [00:00:00] Builder starting . . . [00:05:54] [32] [00:00:00] Builder starting [00:06:11] [01] [00:00:18] Finished print/indexinfo | indexinfo-0.3.1: Success [00:06:12] [01] [00:00:00] Building devel/gettext-runtime | gettext-runtime-0.22_1 [00:08:24] [01] [00:02:12] Finished devel/gettext-runtime | gettext-runtime-0.22_1: Success [00:08:31] [01] [00:00:00] Building devel/libtextstyle | libtextstyle-0.22 [00:10:06] [05] [00:04:13] Builder started [00:10:06] [05] [00:00:00] Building devel/autoconf-switch | autoconf-switch-20220527 [00:10:06] [31] [00:04:12] Builder started [00:10:06] [31] [00:00:00] Building devel/libatomic_ops | libatomic_ops-7.8.0 . . . Crashed again, with 158 *.pkg files in .building/All/ after rebooting. The crash is similar to the non-debug one. No extra output from the debug build. For reference: Unread portion of the kernel message buffer: panic: Solaris(panic): zfs: accessing past end of object 422/10b1c02 (size=2560 access=2560+2560) cpuid = 15 time = 1694127988 KDB: stack backtrace: db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe02e783b5a0 vpanic() at vpanic+0x132/frame 0xfffffe02e783b6d0 panic() at panic+0x43/frame 0xfffffe02e783b730 vcmn_err() at vcmn_err+0xeb/frame 0xfffffe02e783b860 zfs_panic_recover() at zfs_panic_recover+0x59/frame 0xfffffe02e783b8c0 dmu_buf_hold_array_by_dnode() at dmu_buf_hold_array_by_dnode+0xb8/frame 0xfffffe02e783b970 dmu_brt_clone() at dmu_brt_clone+0x61/frame 0xfffffe02e783b9f0 zfs_clone_range() at zfs_clone_range+0xaa3/frame 0xfffffe02e783bbc0 zfs_freebsd_copy_file_range() at zfs_freebsd_copy_file_range+0x18a/frame 0xfffffe02e783bc40 vn_copy_file_range() at vn_copy_file_range+0x114/frame 0xfffffe02e783bce0 kern_copy_file_range() at kern_copy_file_range+0x36c/frame 0xfffffe02e783bdb0 sys_copy_file_range() at sys_copy_file_range+0x78/frame 0xfffffe02e783be00 amd64_syscall() at amd64_syscall+0x14f/frame 0xfffffe02e783bf30 fast_syscall_common() at fast_syscall_common+0xf8/frame 0xfffffe02e783bf30 --- syscall (569, FreeBSD ELF64, copy_file_range), rip = 0xa8a8d32b55a, rsp = 0xa8a8c8fa158, rbp = 0xa8a8c8fa5f0 --- KDB: enter: panic __curthread () at /usr/main-src/sys/amd64/include/pcpu_aux.h:57 57 __asm("movq %%gs:%P1,%0" : "=r" (td) : "n" (offsetof(struct pcpu, (kgdb) #0 __curthread () at /usr/main-src/sys/amd64/include/pcpu_aux.h:57 #1 doadump (textdump=textdump@entry=0) at /usr/main-src/sys/kern/kern_shutdown.c:405 #2 0xffffffff804a505a in db_dump (dummy=<optimized out>, dummy2=<optimized out>, dummy3=<optimized out>, dummy4=<optimized out>) at /usr/main-src/sys/ddb/db_command.c:591 #3 0xffffffff804a4e5d in db_command (last_cmdp=<optimized out>, cmd_table=<optimized out>, dopager=true) at /usr/main-src/sys/ddb/db_command.c:504 #4 0xffffffff804a4b1d in db_command_loop () at /usr/main-src/sys/ddb/db_command.c:551 #5 0xffffffff804a81f6 in db_trap (type=<optimized out>, code=<optimized out>) at /usr/main-src/sys/ddb/db_main.c:268 #6 0xffffffff80bb0793 in kdb_trap (type=type@entry=3, code=code@entry=0, tf=tf@entry=0xfffffe02e783b4e0) at /usr/main-src/sys/kern/subr_kdb.c:790 #7 0xffffffff810623c9 in trap (frame=0xfffffe02e783b4e0) at /usr/main-src/sys/amd64/amd64/trap.c:608 #8 <signal handler called> #9 kdb_enter (why=<optimized out>, msg=<optimized out>) at /usr/main-src/sys/kern/subr_kdb.c:556 #10 0xffffffff80b61b33 in vpanic (fmt=0xffffffff82c3914f "%s%s", ap=ap@entry=0xfffffe02e783b710) at /usr/main-src/sys/kern/kern_shutdown.c:958 #11 0xffffffff80b61913 in panic ( fmt=0xffffffff82369800 <cnputs_mtx> "W\346\025\201\377\377\377\377") at /usr/main-src/sys/kern/kern_shutdown.c:894 #12 0xffffffff8299464b in vcmn_err (ce=<optimized out>, fmt=0xffffffff82c6f791 "zfs: accessing past end of object %llx/%llx (size=%u access=%llu+%llu)", adx=0xfffffe02e783b8a0) at /usr/main-src/sys/contrib/openzfs/module/os/freebsd/spl/spl_cmn_err.c:60 #13 0xffffffff82ab1ab9 in zfs_panic_recover ( fmt=0x12 <error: Cannot access memory at address 0x12>) at /usr/main-src/sys/contrib/openzfs/module/zfs/spa_misc.c:1594 #14 0xffffffff82a10138 in dmu_buf_hold_array_by_dnode (dn=0xfffff80b9edd67f0, offset=offset@entry=2560, length=length@entry=2560, read=read@entry=0, tag=0xffffffff82c1c507, numbufsp=numbufsp@entry=0xfffffe02e783b9bc, dbpp=0xfffffe02e783b9c0, flags=0) at /usr/main-src/sys/contrib/openzfs/module/zfs/dmu.c:543 #15 0xffffffff82a13c91 in dmu_buf_hold_array (os=<optimized out>, object=<optimized out>, read=0, numbufsp=0xfffffe02e783b9bc, dbpp=0xfffffe02e783b9c0, offset=<optimized out>, length=<optimized out>, tag=<optimized out>) at /usr/main-src/sys/contrib/openzfs/module/zfs/dmu.c:654 #16 dmu_brt_clone (os=os@entry=0xfffff8011e989800, object=<optimized out>, offset=offset@entry=2560, length=length@entry=2560, tx=tx@entry=0xfffff81b68d0bb00, bps=bps@entry=0xfffffe04bcc60000, nbps=1, replay=0) at /usr/main-src/sys/contrib/openzfs/module/zfs/dmu.c:2301 #17 0xffffffff82b7e393 in zfs_clone_range (inzp=0xfffff805a65f7000, inoffp=0xfffff805c5e13548, outzp=0xfffff809d42c2cb0, outoffp=0xfffff80134c184f8, lenp=lenp@entry=0xfffffe02e783bc00, cr=0xfffff8041841f700) at /usr/main-src/sys/contrib/openzfs/module/zfs/zfs_vnops.c:1302 #18 0xffffffff829b77ca in zfs_freebsd_copy_file_range (ap=0xfffffe02e783bc58) at /usr/main-src/sys/contrib/openzfs/module/os/freebsd/zfs/zfs_vnops_os.c:6294 #19 0xffffffff80c74694 in VOP_COPY_FILE_RANGE (invp=<optimized out>, inoffp=<optimized out>, outvp=0xffffffff81183b4f, outvp@entry=0xfffffe02e783bce0, outoffp=0xffffffff812265a2, lenp=0x0, lenp@entry=0xfffffe02e783bc70, flags=0, incred=0xfffff8041841f700, outcred=0x0, fsizetd=0xfffffe021b5f4740) at ./vnode_if.h:2385 #20 vn_copy_file_range (invp=invp@entry=0xfffff80435eef8c0, inoffp=inoffp@entry=0xfffff805c5e13548, outvp=0xffffffff81183b4f, outvp@entry=0xfffff80ce8c8ee00, outoffp=0xffffffff812265a2, lenp=0x0, lenp@entry=0xfffffe02e783bd40, flags=flags@entry=0, incred=0xfffff8041841f700, outcred=0xfffff8041841f700, fsize_td=0xfffffe021b5f4740) at /usr/main-src/sys/kern/vfs_vnops.c:3085 #21 0xffffffff80c6f22c in kern_copy_file_range ( td=td@entry=0xfffffe021b5f4740, infd=<optimized out>, inoffp=0xfffff805c5e13548, inoffp@entry=0x0, outfd=<optimized out>, outoffp=0xffffffff812265a2, outoffp@entry=0x0, len=9223372036854775807, flags=0) at /usr/main-src/sys/kern/vfs_syscalls.c:4971 #22 0xffffffff80c6f338 in sys_copy_file_range (td=0xfffffe021b5f4740, uap=0xfffffe021b5f4b40) at /usr/main-src/sys/kern/vfs_syscalls.c:5009 #23 0xffffffff8106323f in syscallenter (td=0xfffffe021b5f4740) at /usr/main-src/sys/amd64/amd64/../../kern/subr_syscall.c:187 #24 amd64_syscall (td=0xfffffe021b5f4740, traced=0) at /usr/main-src/sys/amd64/amd64/trap.c:1197 #25 <signal handler called> #26 0x00000a8a8d32b55a in ?? () Backtrace stopped: Cannot access memory at address 0xa8a8c8fa158 (kgdb) >> Looking at "git: 969071be938c - main", the relevant >> part seems to be just (white space possibly not >> preserved accurately): >> diff --git a/sys/kern/vfs_vnops.c b/sys/kern/vfs_vnops.c >> index 9fb5aee6a023..4e4161ef1a7f 100644 >> --- a/sys/kern/vfs_vnops.c >> +++ b/sys/kern/vfs_vnops.c >> @@ -3076,12 +3076,14 @@ vn_copy_file_range(struct vnode *invp, off_t >> *inoffp, struct vnode *outvp, >> goto out; >> /* >> - * If the two vnode are for the same file system, call >> + * If the two vnodes are for the same file system type, call >> * VOP_COPY_FILE_RANGE(), otherwise call vn_generic_copy_file_range() >> - * which can handle copies across multiple file systems. >> + * which can handle copies across multiple file system types. >> */ >> *lenp = len; >> - if (invp->v_mount == outvp->v_mount) >> + if (invp->v_mount == outvp->v_mount || >> + strcmp(invp->v_mount->mnt_vfc->vfc_name, >> + outvp->v_mount->mnt_vfc->vfc_name) == 0) >> error = VOP_COPY_FILE_RANGE(invp, inoffp, outvp, outoffp, >> lenp, flags, incred, outcred, fsize_td); >> else >> That looks to call VOP_COPY_FILE_RANGE in more contexts and >> vn_generic_copy_file_range in fewer. >> The backtrace I reported involves: VOP_COPY_FILE_RANGE >> So it appears this change is unlikely to invalidate my >> test result, although failure might happen sooner if >> more VOP_COPY_FILE_RANGE calls happen with the newer code. > > Your logic is likely right, but if you have block cloning requests both > within and between datasets, this patch may change the pattern. Though it is > obviously not a fix for the issue. I responded to the commit email only > because it makes no difference while vfs.zfs.bclone_enabled is 0. > >> That in turns means that someone may come up with some >> other change for me to test by the time I get around to >> setting up another test. Let me know if so. > > -- > Alexander Motin === Mark Millard marklmi at yahoo.com