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
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:?)
[ 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 (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
[ 78.772720][ T59] ? xfs_buffered_write_iomap_end (xfs_iomap.c:?) xfs
[ 78.779078][ T59] ? xfs_alert_fsblock_zero (xfs_iomap.c:?) xfs
[ 78.784893][ T59] iomap_iter (??:?)
[ 78.788960][ T59] iomap_file_buffered_write (??:?)
[ 78.794323][ T59] xfs_file_buffered_write (xfs_file.c:?) xfs
[ 78.800191][ T59] ? __update_load_avg_se (??:?)
[ 78.805382][ T59] xfs_file_write_iter (xfs_file.c:?) xfs
[ 78.810864][ T59] ? apparmor_file_permission (lsm.c:?)
[ 78.816314][ T59] do_iter_readv_writev (read_write.c:?)
[ 78.821246][ T59] do_iter_write (read_write.c:?)
[ 78.825572][ T59] ? xfs_file_buffered_write (xfs_file.c:?) xfs
[ 78.831676][ T59] vfs_iter_write (??:?)
[ 78.836017][ T59] lo_write_simple+0x5f/0x290 loop
[ 78.841733][ T59] loop_process_work (loop.c:?) loop
[ 78.847111][ T59] ? wb_workfn (??:?)
[ 78.851287][ T59] ? try_to_wake_up (core.c:?)
[ 78.855887][ T59] ? __switch_to_asm (??:?)
[ 78.860483][ T59] loop_rootcg_workfn (loop.c:?) loop
[ 78.865772][ T59] process_one_work (workqueue.c:?)
[ 78.870450][ T59] worker_thread (workqueue.c:?)
[ 78.874866][ T59] kthread (kthread.c:?)
[ 78.878591][ T59] ? process_one_work (workqueue.c:?)
[ 78.883438][ T59] ? kthread_complete_and_exit (kthread.c:?)
[ 78.888887][ T59] ret_from_fork (??:?)
[ 78.893130][ T59] ---[ end trace 0000000000000000 ]---
If you fix the issue, kindly add following tag
| Reported-by: kernel test robot <[email protected]>
| Link: https://lore.kernel.org/oe-lkp/[email protected]
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
sudo bin/lkp install job.yaml # job file is attached in this email
bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
sudo bin/lkp run generated-yaml-file
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests
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?
>
> 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?
> [ 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
Cheers,
Dave.
--
Dave Chinner
[email protected]
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
On Thu, Mar 02, 2023 at 04:39:03PM +0800, Yujie Liu wrote:
> 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.
Ok.
Can you add this patch and see if it fixes the problem?
https://lore.kernel.org/linux-xfs/[email protected]/
> [ 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))
Ok, that is:
WARN_ON_ONCE(start_byte < punch_start_byte);
Which I can't immediately see how that happens. This is a 32-bit
i386 kernel which we largely don't test or support, so maybe there's
32/64 bit variable size change problem somewhere in the code path
being executed.
> [ 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]
Ok, so this is happening while writing to the loopback image file
which is racing with cloning and removing the clone of the image
file.
Looking at the rest of the trace, IO to the entire loopback file
hung, but this warning doesn't explain that happening either.
I'll try to reproduce it, but I don't actually have an i386 test
environment here (I haven't tested i386 at all the last 5-6
years!) so it might be a while before I can get to testing this
specific environment.
Do you see it reproduce on any other architecture, of just this one?
-Dave.
--
Dave Chinner
[email protected]
On Fri, Mar 03, 2023 at 09:21:22AM +1100, Dave Chinner wrote:
> On Thu, Mar 02, 2023 at 04:39:03PM +0800, Yujie Liu wrote:
> > 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.
>
> Ok.
>
> Can you add this patch and see if it fixes the problem?
>
> https://lore.kernel.org/linux-xfs/[email protected]/
We applied this patch on commit 304a68b9c63b and tested it, but cannot
fix the problem.
=========================================================================================
compiler/disk/fs/kconfig/rootfs/tbox_group/test/testcase:
gcc-11/4HDD/xfs/i386-debian-10.3-func/debian-11.1-i386-20220923.cgz/lkp-skl-d01/generic-group-32/xfstests
commit:
d7b64041164c ("iomap: write iomap validity checks")
304a68b9c63b ("xfs: use iomap_valid method to detect stale cached iomaps")
e5a7d5f824ad ("xfs: fix off-by-one-block in xfs_discard_folio()")
d7b64041164ca177 304a68b9c63bbfc1f6e159d68e8 e5a7d5f824ad7409f85e2665d11
---------------- --------------------------- ---------------------------
fail:runs %reproduction fail:runs %reproduction fail:runs
| | | | |
:6 50% 3:3 100% 3:3 dmesg.EIP:iomap_write_delalloc_release
:6 50% 3:3 100% 3:3 dmesg.WARNING:at_fs/iomap/buffered-io.c:#iomap_write_delalloc_release
> > [ 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))
>
> Ok, that is:
>
> WARN_ON_ONCE(start_byte < punch_start_byte);
>
> Which I can't immediately see how that happens. This is a 32-bit
> i386 kernel which we largely don't test or support, so maybe there's
> 32/64 bit variable size change problem somewhere in the code path
> being executed.
>
> > [ 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]
>
> Ok, so this is happening while writing to the loopback image file
> which is racing with cloning and removing the clone of the image
> file.
>
> Looking at the rest of the trace, IO to the entire loopback file
> hung, but this warning doesn't explain that happening either.
>
> I'll try to reproduce it, but I don't actually have an i386 test
> environment here (I haven't tested i386 at all the last 5-6
> years!) so it might be a while before I can get to testing this
> specific environment.
>
> Do you see it reproduce on any other architecture, of just this one?
It can be reproduced on i386, but not on x86_64. Sorry that we don't
have machines of other architectures in the robot infrastructure.
=========================================================================================
commit/compiler/disk/fs/kconfig/rootfs/tbox_group/test/testcase:
304a68b9c63bbfc1f6e159d68e8892fc54a06067/gcc-11/4HDD/xfs/x86_64-rhel-8.3-func/debian-11.1-x86_64-20220510.cgz/lkp-skl-d01/generic-group-32/xfstests
commit/compiler/disk/fs/kconfig/rootfs/tbox_group/test/testcase:
304a68b9c63bbfc1f6e159d68e8892fc54a06067/gcc-11/4HDD/xfs/i386-debian-10.3-func/debian-11.1-i386-20220923.cgz/lkp-skl-d01/generic-group-32/xfstests
kconfig:
x86_64-rhel-8.3-func
i386-debian-10.3-func
x86_64-rhel-8.3-func i386-debian-10.3-func
---------------- ---------------------------
fail:runs %reproduction fail:runs
| | |
:3 100% 3:3 dmesg.EIP:iomap_write_delalloc_release
:3 100% 3:3 dmesg.WARNING:at_fs/iomap/buffered-io.c:#iomap_write_delalloc_release
--
Best Regards,
Yujie