Re: [linus:master] [xfs] 304a68b9c6: WARNING:at_fs/iomap/buffered-io.c:#iomap_write_delalloc_release
From: Yujie Liu
Date: Thu Mar 02 2023 - 03:42:01 EST
On Wed, Mar 01, 2023 at 09:11:07AM +1100, Dave Chinner wrote:
> On Tue, Feb 28, 2023 at 04:40:01PM +0800, kernel test robot wrote:
> > Greeting,
> >
> > FYI, we noticed WARNING:at_fs/iomap/buffered-io.c:#iomap_write_delalloc_release due to commit (built with gcc-11):
> >
> > commit: 304a68b9c63bbfc1f6e159d68e8892fc54a06067 ("xfs: use iomap_valid method to detect stale cached iomaps")
> > https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master
> >
> > [test failed on linux-next/master 058f4df42121baadbb8a980c06011e912784dbd2]
> > in testcase: xfstests
> > version: xfstests-i386-5a5e419-1_20220926
> > with following parameters:
> >
> > disk: 4HDD
> > fs: xfs
> > test: generic-group-32
>
> Which fstest was running at the time this warning was thrown?
It is fstests generic/648 running at that time.
> >
> > test-description: xfstests is a regression test suite for xfs and other files ystems.
> > test-url: git://git.kernel.org/pub/scm/fs/xfs/xfstests-dev.git
> >
> > on test machine: 8 threads Intel(R) Core(TM) i7-6700 CPU @ 3.40GHz (Skylake) with 28G memory
> >
> > caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
> >
> >
> > [ 78.565703][ T59] ------------[ cut here ]------------
> > [ 78.570983][ T59] WARNING: CPU: 4 PID: 59 at fs/iomap/buffered-io.c:984 iomap_write_delalloc_release (buffered-io.c:?)
>
> Well, that's useless without the function offset or line number to
> tell us what warning in that function triggered.
>
> > [ 78.581265][ T59] Modules linked in: loop(E) dm_flakey(E) xfs(E) dm_mod(E) intel_rapl_msr(E) intel_rapl_common(E) btrfs(E) blake2b_generic(E) xor(E) raid6_pq(E) zstd_compress(E) x86_pkg_temp_thermal(E) libcrc32c(E) intel_powerclamp(E) crc32c_generic(E) coretemp(E) sd_mod(E) t10_pi(E) ipmi_devintf(E) kvm_intel(E) ipmi_msghandler(E) i915(E) crc64_rocksoft_generic(E) kvm(E) irqbypass(E) crc64_rocksoft(E) crc64(E) drm_buddy(E) crc32_pclmul(E) crc32c_intel(E) aesni_intel(E) crypto_simd(E) drm_display_helper(E) cryptd(E) cec(E) mei_wdt(E) wmi_bmof(E) rapl(E) ahci(E) evdev(E) ttm(E) xhci_pci(E) intel_cstate(E) xhci_hcd(E) libahci(E) i2c_i801(E) mei_me(E) drm_kms_helper(E) syscopyarea(E) intel_uncore(E) usbcore(E) i2c_smbus(E) sysfillrect(E) libata(E) mei(E) sysimgblt(E) intel_pch_thermal(E) fb_sys_fops(E) usb_common(E) video(E) fan(E) thermal(E) wmi(E) acpi_pad(E) button(E) fuse(E) drm(E) configfs(E) autofs4(E)
> > [ 78.661092][ T59] CPU: 4 PID: 59 Comm: kworker/u16:2 Tainted: G E 6.1.0-rc4-00008-g304a68b9c63b #1
>
> This looks like a broken kernel install. Why are all the modules
> tainted?
Sorry, this seems to be a bug when we built the modules. We are still
investigating it and will fix it once we find the root cause.
> > [ 78.671542][ T59] Hardware name: Dell Inc. OptiPlex 7040/0Y7WYT, BIOS 1.2.8 01/26/2016
> > [ 78.679578][ T59] Workqueue: loop0 loop_rootcg_workfn [loop]
> > [ 78.685393][ T59] EIP: iomap_write_delalloc_release (buffered-io.c:?)
> > [ 78.691449][ T59] Code: e8 cf 94 ed ff f0 ff 4b 1c 74 45 8b 45 e0 8b 40 20 83 c0 10 e8 ab 93 d8 ff 8d 65 f4 89 f0 5b 5e 5f 5d c3 0f 0b e9 f9 fd ff ff <0f> 0b e9 e0 fd ff ff 0f 0b 8b 45 cc 8b 4d f0 8b 55 d0 39 c8 89 d0
> > All code
> > ========
> > 0: e8 cf 94 ed ff callq 0xffffffffffed94d4
> > 5: f0 ff 4b 1c lock decl 0x1c(%rbx)
> > 9: 74 45 je 0x50
> > b: 8b 45 e0 mov -0x20(%rbp),%eax
> > e: 8b 40 20 mov 0x20(%rax),%eax
> > 11: 83 c0 10 add $0x10,%eax
> > 14: e8 ab 93 d8 ff callq 0xffffffffffd893c4
> > 19: 8d 65 f4 lea -0xc(%rbp),%esp
> > 1c: 89 f0 mov %esi,%eax
> > 1e: 5b pop %rbx
> > 1f: 5e pop %rsi
> > 20: 5f pop %rdi
> > 21: 5d pop %rbp
> > 22: c3 retq
> > 23: 0f 0b ud2
> > 25: e9 f9 fd ff ff jmpq 0xfffffffffffffe23
> > 2a:* 0f 0b ud2 <-- trapping instruction
> > 2c: e9 e0 fd ff ff jmpq 0xfffffffffffffe11
> > 31: 0f 0b ud2
> > 33: 8b 45 cc mov -0x34(%rbp),%eax
> > 36: 8b 4d f0 mov -0x10(%rbp),%ecx
> > 39: 8b 55 d0 mov -0x30(%rbp),%edx
> > 3c: 39 c8 cmp %ecx,%eax
> > 3e: 89 d0 mov %edx,%eax
> >
> > Code starting with the faulting instruction
> > ===========================================
> > 0: 0f 0b ud2
> > 2: e9 e0 fd ff ff jmpq 0xfffffffffffffde7
> > 7: 0f 0b ud2
> > 9: 8b 45 cc mov -0x34(%rbp),%eax
> > c: 8b 4d f0 mov -0x10(%rbp),%ecx
> > f: 8b 55 d0 mov -0x30(%rbp),%edx
> > 12: 39 c8 cmp %ecx,%eax
> > 14: 89 d0 mov %edx,%eax
> > [ 78.710792][ T59] EAX: 2335a000 EBX: 00000004 ECX: fffffffc EDX: 00000004
> > [ 78.717707][ T59] ESI: 2335b000 EDI: 00000000 EBP: c3187c24 ESP: c3187bf0
> > [ 78.724624][ T59] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010297
> > [ 78.732056][ T59] CR0: 80050033 CR2: b7da00b0 CR3: 02350000 CR4: 003506f0
> > [ 78.738971][ T59] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> > [ 78.745887][ T59] DR6: fffe0ff0 DR7: 00000400
> > [ 78.750389][ T59] Call Trace:
> > [ 78.753508][ T59] iomap_file_buffered_write_punch_delalloc (??:?)
> > [ 78.760183][ T59] ? xfs_buffered_write_iomap_end (xfs_iomap.c:?) xfs
> > [ 78.766541][ T59] xfs_buffered_write_iomap_end (xfs_iomap.c:?) xfs
>
> What's with all the broken/missing function offsets and
> file/line numbers in the stack trace?
>
> Please fix your tooling - this report isn't useful with all the
> offset/line number information being broken like this
Sorry for missing the offsets and numbers. The binutils version was
outdated in our environment and failed to parse symbols correctly in
latest kernels. We've upgraded binutils and here is the new decoded
stacktrace:
[ 70.647665][ T1431] run fstests generic/648 at 2023-02-28 01:01:42
[ 71.823863][ T6673] XFS (sda4): Mounting V5 Filesystem
[ 71.883835][ T6673] XFS (sda4): Ending clean mount
[ 71.889345][ T6673] xfs filesystem being mounted at /fs/scratch supports timestamps until 2038 (0x7fffffff)
[ 71.942655][ T6686] XFS (sda4): Unmounting Filesystem
[ 72.055909][ T6718] loop: module verification failed: signature and/or required key missing - tainting kernel
[ 72.066111][ T6718] calling loop_init+0x0/0x1000 [ loop] @ 6718
[ 72.073700][ T6718] loop: module loaded
[ 72.077534][ T6718] initcall loop_init+0x0/0x1000 [ loop] returned 0 after 5536 usecs
[ 73.097330][ T6767] XFS (dm-0): Mounting V5 Filesystem
[ 73.261204][ T6767] XFS (dm-0): Ending clean mount
[ 73.267558][ T6767] xfs filesystem being mounted at /fs/scratch supports timestamps until 2038 (0x7fffffff)
[ 73.335169][ T6801] loop0: detected capacity change from 0 to 138745493
[ 73.374666][ T6801] XFS (loop0): Mounting V5 Filesystem
[ 73.382659][ T6801] XFS (loop0): Ending clean mount
[ 73.387588][ T6801] xfs filesystem being mounted at /tmp/6480.mount supports timestamps until 2038 (0x7fffffff)
[ 74.446227][ T3540] Buffer I/O error on dev dm-1, logical block 52428784, async page read
[ 74.457497][ T66] dm-0: writeback error on inode 131, offset 131072, sector 78144
[ 74.457500][ T66] dm-0: writeback error on inode 131, offset 262144, sector 74928
[ 74.459752][ T3540] Buffer I/O error on dev dm-0, logical block 52428784, async page read
[ 74.465109][ T66] dm-0: writeback error on inode 131, offset 2228224, sector 78400
[ 74.480852][ T66] dm-0: writeback error on inode 131, offset 3969024, sector 78504
[ 74.488596][ T66] dm-0: writeback error on inode 131, offset 4005888, sector 78576
[ 74.496292][ T66] dm-0: writeback error on inode 131, offset 4063232, sector 192
[ 74.496418][ C3] I/O error, dev loop0, sector 69373014 op 0x1:(WRITE) flags 0x9800 phys_seg 1 prio class 2
[ 74.521346][ T144] XFS (loop0): log I/O error -5
[ 74.526022][ T144] XFS (loop0): Filesystem has been shut down due to log error (0x2).
[ 74.533882][ T144] XFS (loop0): Please unmount the filesystem and rectify the problem(s).
[ 74.542294][ T67] dm-0: writeback error on inode 131, offset 53279154176, sector 78688
[ 74.542299][ C3] I/O error, dev loop0, sector 0 op 0x1:(WRITE) flags 0x800 phys_seg 0 prio class 2
[ 75.364416][ T6868] XFS (loop0): Unmounting Filesystem
[ 75.370061][ T164] XFS (dm-0): log I/O error -5
[ 75.374652][ T164] XFS (dm-0): Filesystem has been shut down due to log error (0x2).
[ 75.382433][ T164] XFS (dm-0): Please unmount the filesystem and rectify the problem(s).
[ 75.390581][ C6] I/O error, dev loop0, sector 0 op 0x1:(WRITE) flags 0x800 phys_seg 0 prio class 2
[ 76.403161][ T6876] XFS (dm-0): Unmounting Filesystem
[ 76.554265][ T6888] XFS (dm-0): Mounting V5 Filesystem
[ 76.602707][ T6888] XFS (dm-0): Starting recovery (logdev: internal)
[ 76.678261][ T6888] XFS (dm-0): Ending recovery (logdev: internal)
[ 76.705011][ T6888] xfs filesystem being mounted at /fs/scratch supports timestamps until 2038 (0x7fffffff)
[ 76.720823][ T6905] loop0: detected capacity change from 0 to 138745493
[ 76.765868][ T6905] XFS (loop0): Mounting V5 Filesystem
[ 76.811151][ T6905] XFS (loop0): Starting recovery (logdev: internal)
[ 76.820611][ T6905] XFS (loop0): Ending recovery (logdev: internal)
[ 76.826950][ T6905] xfs filesystem being mounted at /tmp/6480.mount supports timestamps until 2038 (0x7fffffff)
[ 78.565703][ T59] ------------[ cut here ]------------
[ 78.570983][ T59] WARNING: CPU: 4 PID: 59 at fs/iomap/buffered-io.c:984 iomap_write_delalloc_release (fs/iomap/buffered-io.c:984 (discriminator 1))
[ 78.581265][ T59] Modules linked in: loop(E) dm_flakey(E) xfs(E) dm_mod(E) intel_rapl_msr(E) intel_rapl_common(E) btrfs(E) blake2b_generic(E) xor(E) raid6_pq(E) zstd_compress(E) x86_pkg_temp_thermal(E) libcrc32c(E) intel_powerclamp(E) crc32c_generic(E) coretemp(E) sd_mod(E) t10_pi(E) ipmi_devintf(E) kvm_intel(E) ipmi_msghandler(E) i915(E) crc64_rocksoft_generic(E) kvm(E) irqbypass(E) crc64_rocksoft(E) crc64(E) drm_buddy(E) crc32_pclmul(E) crc32c_intel(E) aesni_intel(E) crypto_simd(E) drm_display_helper(E) cryptd(E) cec(E) mei_wdt(E) wmi_bmof(E) rapl(E) ahci(E) evdev(E) ttm(E) xhci_pci(E) intel_cstate(E) xhci_hcd(E) libahci(E) i2c_i801(E) mei_me(E) drm_kms_helper(E) syscopyarea(E) intel_uncore(E) usbcore(E) i2c_smbus(E) sysfillrect(E) libata(E) mei(E) sysimgblt(E) intel_pch_thermal(E) fb_sys_fops(E) usb_common(E) video(E) fan(E) thermal(E) wmi(E) acpi_pad(E) button(E) fuse(E) drm(E) configfs(E) autofs4(E)
[ 78.661092][ T59] CPU: 4 PID: 59 Comm: kworker/u16:2 Tainted: G E 6.1.0-rc4-00008-g304a68b9c63b #1
[ 78.671542][ T59] Hardware name: Dell Inc. OptiPlex 7040/0Y7WYT, BIOS 1.2.8 01/26/2016
[ 78.679578][ T59] Workqueue: loop0 loop_rootcg_workfn [ loop]
[ 78.685393][ T59] EIP: iomap_write_delalloc_release (fs/iomap/buffered-io.c:984 (discriminator 1))
[ 78.691449][ T59] Code: e8 cf 94 ed ff f0 ff 4b 1c 74 45 8b 45 e0 8b 40 20 83 c0 10 e8 ab 93 d8 ff 8d 65 f4 89 f0 5b 5e 5f 5d c3 0f 0b e9 f9 fd ff ff <0f> 0b e9 e0 fd ff ff 0f 0b 8b 45 cc 8b 4d f0 8b 55 d0 39 c8 89 d0
All code
========
0: e8 cf 94 ed ff call 0xffffffffffed94d4
5: f0 ff 4b 1c lock decl 0x1c(%rbx)
9: 74 45 je 0x50
b: 8b 45 e0 mov -0x20(%rbp),%eax
e: 8b 40 20 mov 0x20(%rax),%eax
11: 83 c0 10 add $0x10,%eax
14: e8 ab 93 d8 ff call 0xffffffffffd893c4
19: 8d 65 f4 lea -0xc(%rbp),%esp
1c: 89 f0 mov %esi,%eax
1e: 5b pop %rbx
1f: 5e pop %rsi
20: 5f pop %rdi
21: 5d pop %rbp
22: c3 ret
23: 0f 0b ud2
25: e9 f9 fd ff ff jmp 0xfffffffffffffe23
2a:* 0f 0b ud2 <-- trapping instruction
2c: e9 e0 fd ff ff jmp 0xfffffffffffffe11
31: 0f 0b ud2
33: 8b 45 cc mov -0x34(%rbp),%eax
36: 8b 4d f0 mov -0x10(%rbp),%ecx
39: 8b 55 d0 mov -0x30(%rbp),%edx
3c: 39 c8 cmp %ecx,%eax
3e: 89 d0 mov %edx,%eax
Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: e9 e0 fd ff ff jmp 0xfffffffffffffde7
7: 0f 0b ud2
9: 8b 45 cc mov -0x34(%rbp),%eax
c: 8b 4d f0 mov -0x10(%rbp),%ecx
f: 8b 55 d0 mov -0x30(%rbp),%edx
12: 39 c8 cmp %ecx,%eax
14: 89 d0 mov %edx,%eax
[ 78.710792][ T59] EAX: 2335a000 EBX: 00000004 ECX: fffffffc EDX: 00000004
[ 78.717707][ T59] ESI: 2335b000 EDI: 00000000 EBP: c3187c24 ESP: c3187bf0
[ 78.724624][ T59] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00010297
[ 78.732056][ T59] CR0: 80050033 CR2: b7da00b0 CR3: 02350000 CR4: 003506f0
[ 78.738971][ T59] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 78.745887][ T59] DR6: fffe0ff0 DR7: 00000400
[ 78.750389][ T59] Call Trace:
[ 78.753508][ T59] iomap_file_buffered_write_punch_delalloc (fs/iomap/buffered-io.c:1078)
[ 78.760183][ T59] ? xfs_buffered_write_iomap_end (fs/xfs/xfs_iomap.c:1175) xfs
[ 78.766541][ T59] xfs_buffered_write_iomap_end (fs/xfs/xfs_iomap.c:1204) xfs
[ 78.772720][ T59] ? xfs_buffered_write_iomap_end (fs/xfs/xfs_iomap.c:1175) xfs
[ 78.779078][ T59] ? xfs_alert_fsblock_zero (fs/xfs/xfs_iomap.c:1188) xfs
[ 78.784893][ T59] iomap_iter (fs/iomap/iter.c:82)
[ 78.788960][ T59] iomap_file_buffered_write (fs/iomap/buffered-io.c:850)
[ 78.794323][ T59] xfs_file_buffered_write (fs/xfs/xfs_file.c:726) xfs
[ 78.800191][ T59] ? __update_load_avg_se (kernel/sched/pelt.c:77 kernel/sched/pelt.c:135 kernel/sched/pelt.c:226 kernel/sched/pelt.c:308)
[ 78.805382][ T59] xfs_file_write_iter (fs/xfs/xfs_file.c:803) xfs
[ 78.810864][ T59] ? apparmor_file_permission (security/apparmor/include/cred.h:122 security/apparmor/lsm.c:496 security/apparmor/lsm.c:509)
[ 78.816314][ T59] do_iter_readv_writev (include/linux/fs.h:2191 fs/read_write.c:735)
[ 78.821246][ T59] do_iter_write (fs/read_write.c:861)
[ 78.825572][ T59] ? xfs_file_buffered_write (fs/xfs/xfs_file.c:773) xfs
[ 78.831676][ T59] vfs_iter_write (fs/read_write.c:902)
[ 78.836017][ T59] lo_write_simple+0x5f/0x290 loop
[ 78.841733][ T59] loop_process_work (drivers/block/loop.c:495 drivers/block/loop.c:1864 drivers/block/loop.c:1899) loop
[ 78.847111][ T59] ? wb_workfn (include/linux/jump_label.h:207 (discriminator 1) include/linux/jump_label.h:207 (discriminator 1) include/trace/events/writeback.h:395 (discriminator 1) fs/fs-writeback.c:2228 (discriminator 1))
[ 78.851287][ T59] ? try_to_wake_up (kernel/sched/core.c:4196)
[ 78.855887][ T59] ? __switch_to_asm (arch/x86/entry/entry_32.S:708)
[ 78.860483][ T59] loop_rootcg_workfn (drivers/block/loop.c:1931) loop
[ 78.865772][ T59] process_one_work (kernel/workqueue.c:2294)
[ 78.870450][ T59] worker_thread (include/linux/list.h:292 kernel/workqueue.c:2437)
[ 78.874866][ T59] kthread (kernel/kthread.c:376)
[ 78.878591][ T59] ? process_one_work (kernel/workqueue.c:2379)
[ 78.883438][ T59] ? kthread_complete_and_exit (kernel/kthread.c:331)
[ 78.888887][ T59] ret_from_fork (arch/x86/entry/entry_32.S:770)
[ 78.893130][ T59] ---[ end trace 0000000000000000 ]---
--
Best Regards,
Yujie