Bug 219187

Summary:	kernel BUG at fs/btrfs/ordered-data.c:983! with kernel 6.10.5
Product:	File System	Reporter:	Paulo Dias (paulo.miguel.dias)
Component:	btrfs	Assignee:	BTRFS virtual assignee (fs_btrfs)
Status:	NEW ---
Severity:	normal	CC:	fdmanana, seifert
Priority:	P3
Hardware:	All
OS:	Linux
Kernel Version:		Subsystem:
Regression:	No	Bisected commit-id:

Description Paulo Dias 2024-08-21 12:46:31 UTC

while running kvm and heavy disk usage i get this kernel dump:

Aug 21 11:46:43 kerberos kernel: assertion failed: inode_is_locked(&inode->vfs_inode), in fs/btrfs/ordered-data.c:983
Aug 21 11:46:43 kerberos kernel: ------------[ cut here ]------------
Aug 21 11:46:43 kerberos kernel: kernel BUG at fs/btrfs/ordered-data.c:983!
Aug 21 11:46:43 kerberos kernel: Oops: invalid opcode: 0000 [#1] PREEMPT SMP PTI
Aug 21 11:46:43 kerberos kernel: CPU: 9 PID: 5072 Comm: worker Tainted: G     U     OE      6.10.5-1-default #1 openSUSE Tumbleweed 69f48d427608e1c09e60ea24c6c55e2ca1b049e8
Aug 21 11:46:43 kerberos kernel: Hardware name: Acer Predator PH315-52/Covini_CFS, BIOS V1.12 07/28/2020
Aug 21 11:46:43 kerberos kernel: RIP: 0010:btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs]
Aug 21 11:46:43 kerberos kernel: Code: 50 d6 86 c0 e8 79 03 f3 db 0f 0b b9 d7 03 00 00 48 c7 c2 b0 48 86 c0 48 c7 c6 40 d8 86 c0 48 c7 c7 50 d6 86 c0 e8 58 03 f3 db <0f> 0b b9 e2 03 00 00 48 c7 c2 b0 48 86 c0 48 c7 c6 68 d8 86 c0 48
Aug 21 11:46:43 kerberos kernel: RSP: 0018:ffff9e4a03dcfc78 EFLAGS: 00010246
Aug 21 11:46:43 kerberos kernel: RAX: 0000000000000054 RBX: ffff9078a9868e98 RCX: 0000000000000000
Aug 21 11:46:43 kerberos kernel: RDX: 0000000000000000 RSI: ffff907dce4a7800 RDI: ffff907dce4a7800
Aug 21 11:46:43 kerberos kernel: RBP: ffff907805518800 R08: 0000000000000000 R09: ffff9e4a03dcfb38
Aug 21 11:46:43 kerberos kernel: R10: ffff9e4a03dcfb30 R11: 0000000000000003 R12: ffff907684ae7800
Aug 21 11:46:43 kerberos kernel: R13: 0000000000000001 R14: ffff90774646b600 R15: 0000000000000000
Aug 21 11:46:43 kerberos kernel: FS:  00007f04b96006c0(0000) GS:ffff907dce480000(0000) knlGS:0000000000000000
Aug 21 11:46:43 kerberos kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 21 11:46:43 kerberos kernel: CR2: 00007f32acbfc000 CR3: 00000001fd4fa005 CR4: 00000000003726f0
Aug 21 11:46:43 kerberos kernel: Call Trace:
Aug 21 11:46:43 kerberos kernel:  <TASK>
Aug 21 11:46:43 kerberos kernel:  ? __die_body.cold+0x14/0x24
Aug 21 11:46:43 kerberos kernel:  ? die+0x2e/0x50
Aug 21 11:46:43 kerberos kernel:  ? do_trap+0xca/0x110
Aug 21 11:46:43 kerberos kernel:  ? do_error_trap+0x6a/0x90
Aug 21 11:46:43 kerberos kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 21 11:46:43 kerberos kernel:  ? exc_invalid_op+0x50/0x70
Aug 21 11:46:43 kerberos kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 21 11:46:43 kerberos kernel:  ? asm_exc_invalid_op+0x1a/0x20
Aug 21 11:46:43 kerberos kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 21 11:46:43 kerberos kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 21 11:46:43 kerberos kernel:  btrfs_sync_file+0x21a/0x4d0 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 21 11:46:43 kerberos kernel:  ? __seccomp_filter+0x31d/0x4f0
Aug 21 11:46:43 kerberos kernel:  __x64_sys_fdatasync+0x4f/0x90
Aug 21 11:46:43 kerberos kernel:  do_syscall_64+0x82/0x160
Aug 21 11:46:43 kerberos kernel:  ? do_futex+0xcb/0x190
Aug 21 11:46:43 kerberos kernel:  ? __x64_sys_futex+0x10e/0x1d0
Aug 21 11:46:43 kerberos kernel:  ? switch_fpu_return+0x4f/0xd0
Aug 21 11:46:43 kerberos kernel:  ? syscall_exit_to_user_mode+0x72/0x220
Aug 21 11:46:43 kerberos kernel:  ? do_syscall_64+0x8e/0x160
Aug 21 11:46:43 kerberos kernel:  ? syscall_exit_to_user_mode+0x72/0x220
Aug 21 11:46:43 kerberos kernel:  ? do_syscall_64+0x8e/0x160
Aug 21 11:46:43 kerberos kernel:  ? syscall_exit_to_user_mode+0x72/0x220
Aug 21 11:46:43 kerberos kernel:  ? do_syscall_64+0x8e/0x160
Aug 21 11:46:43 kerberos kernel:  ? syscall_exit_to_user_mode+0x72/0x220
Aug 21 11:46:43 kerberos kernel:  ? do_syscall_64+0x8e/0x160
Aug 21 11:46:43 kerberos kernel:  entry_SYSCALL_64_after_hwframe+0x76/0x7e
Aug 21 11:46:43 kerberos kernel: RIP: 0033:0x7f04c310911a
Aug 21 11:46:43 kerberos kernel: Code: 00 00 0f 05 48 3d 00 f0 ff ff 77 44 c3 0f 1f 00 48 83 ec 18 89 7c 24 0c e8 c1 58 f8 ff 8b 7c 24 0c 89 c2 b8 4b 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 36 89 d7 89 44 24 0c e8 31 59 f8 ff 8b 44 24
Aug 21 11:46:43 kerberos kernel: RSP: 002b:00007f04b95ff590 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
Aug 21 11:46:43 kerberos kernel: RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f04c310911a
Aug 21 11:46:43 kerberos kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000010
Aug 21 11:46:43 kerberos kernel: RBP: 0000558cee4cafc0 R08: 0000000000000000 R09: 0000558cee252634
Aug 21 11:46:43 kerberos kernel: R10: 0000000000000000 R11: 0000000000000293 R12: 0000558cee2525a0
Aug 21 11:46:43 kerberos kernel: R13: 0000558ce6ad4b11 R14: 00007fffe955eeb0 R15: 00007f04b8e00000
Aug 21 11:46:43 kerberos kernel:  </TASK>
Aug 21 11:46:43 kerberos kernel: Modules linked in: vhost_net vhost vhost_iotlb tap tun nft_masq nft_ct nft_reject_ipv4 nf_reject_ipv4 nft_reject nft_chain_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 nf_tables bridge stp llc uhid rfcomm snd_seq_dummy snd_hrtimer snd_seq snd_seq_device ccm facer(OE) af_packet nvi>
Aug 21 11:46:43 kerberos kernel:  x86_pkg_temp_thermal snd_hda_codec_generic btbcm intel_powerclamp snd_compress btmtk snd_hda_scodec_component coretemp cfg80211 snd_pcm_dmaengine bluetooth uvcvideo snd_hda_intel iTCO_wdt snd_intel_dspcfg intel_pmc_bxt platform_profile videobuf2_vmalloc snd_intel_sdw_acpi iTCO_vendor_supp>
Aug 21 11:46:43 kerberos kernel:  pmt_telemetry acpi_pad pmt_class tiny_power_button nvme_fabrics fuse loop dm_mod efi_pstore configfs nfnetlink dmi_sysfs ip_tables x_tables i915 ahci crct10dif_pclmul crc32_pclmul libahci polyval_clmulni polyval_generic gf128mul libata ghash_clmulni_intel sha512_ssse3 hid_multitouch sha25>
Aug 21 11:46:43 kerberos kernel: ---[ end trace 0000000000000000 ]---
Aug 21 11:46:43 kerberos kernel: RIP: 0010:btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs]
Aug 21 11:46:43 kerberos kernel: Code: 50 d6 86 c0 e8 79 03 f3 db 0f 0b b9 d7 03 00 00 48 c7 c2 b0 48 86 c0 48 c7 c6 40 d8 86 c0 48 c7 c7 50 d6 86 c0 e8 58 03 f3 db <0f> 0b b9 e2 03 00 00 48 c7 c2 b0 48 86 c0 48 c7 c6 68 d8 86 c0 48
Aug 21 11:46:43 kerberos kernel: RSP: 0018:ffff9e4a03dcfc78 EFLAGS: 00010246
Aug 21 11:46:43 kerberos kernel: RAX: 0000000000000054 RBX: ffff9078a9868e98 RCX: 0000000000000000
Aug 21 11:46:43 kerberos kernel: RDX: 0000000000000000 RSI: ffff907dce4a7800 RDI: ffff907dce4a7800
Aug 21 11:46:43 kerberos kernel: RBP: ffff907805518800 R08: 0000000000000000 R09: ffff9e4a03dcfb38
Aug 21 11:46:43 kerberos kernel: R10: ffff9e4a03dcfb30 R11: 0000000000000003 R12: ffff907684ae7800
Aug 21 11:46:43 kerberos kernel: R13: 0000000000000001 R14: ffff90774646b600 R15: 0000000000000000
Aug 21 11:46:43 kerberos kernel: FS:  00007f04b96006c0(0000) GS:ffff907dce480000(0000) knlGS:0000000000000000
Aug 21 11:46:43 kerberos kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 21 11:46:43 kerberos kernel: CR2: 00007f32acbfc000 CR3: 00000001fd4fa005 CR4: 00000000003726f0

qemu image is NOT using CoW (chattr +C), no issue with kernel 6.10.4

Comment 1 Filipe David Manana 2024-08-29 15:18:46 UTC

So this is the same issue as reported later at: https://bugzilla.kernel.org/show_bug.cgi?id=219199

Working on a fix for it, I think I know what's happening.
I'll let you known when a patch is available for testing.
Thanks.

Comment 2 Ales Seifert 2024-08-30 00:52:36 UTC

Probably same issue crashing our database server last few days:

Aug 30 09:10:17 isp1 kernel: assertion failed: inode_is_locked(&inode->vfs_inode), in fs/btrfs/ordered-data.c:983
Aug 30 09:10:17 isp1 kernel: ------------[ cut here ]------------
Aug 30 09:10:17 isp1 kernel: kernel BUG at fs/btrfs/ordered-data.c:983!
Aug 30 09:10:17 isp1 kernel: Oops: invalid opcode: 0000 [#1] PREEMPT SMP PTI
Aug 30 09:10:17 isp1 kernel: CPU: 11 PID: 9764 Comm: mariadbd Not tainted 6.10.5-1-default #1 openSUSE Tumbleweed 69f48d427608e1c09e60ea24c6c55e2ca1b049e8
Aug 30 09:10:17 isp1 kernel: Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./E3C246D4I-2T, BIOS L2.23A 12/13/2022
Aug 30 09:10:17 isp1 kernel: RIP: 0010:btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs]
Aug 30 09:10:17 isp1 kernel: Code: 50 c6 6b c0 e8 79 13 8e f1 0f 0b b9 d7 03 00 00 48 c7 c2 b0 38 6b c0 48 c7 c6 40 c8 6b c0 48 c7 c7 50 c6 6b c0 e8 58 13 8e f1 <0f> 0b b9 e2 03 00 00 48 c7 c2 b0 38 6b c0 48 c7 c6 68 c8 6b c0 48
Aug 30 09:10:17 isp1 kernel: RSP: 0018:ffffafff858a7a80 EFLAGS: 00010246
Aug 30 09:10:17 isp1 kernel: RAX: 0000000000000054 RBX: ffff92b0765c9728 RCX: 0000000000000000
Aug 30 09:10:17 isp1 kernel: RDX: 0000000000000000 RSI: ffff92ceaeda7800 RDI: ffff92ceaeda7800
Aug 30 09:10:17 isp1 kernel: RBP: ffff92afc6917d00 R08: 0000000000000000 R09: ffffafff858a7880
Aug 30 09:10:17 isp1 kernel: R10: ffffafff858a7878 R11: 0000000000000003 R12: ffff92afc7dc8000
Aug 30 09:10:17 isp1 kernel: R13: 0000000000000001 R14: ffff92b07654c9c0 R15: 0000000000000000
Aug 30 09:10:17 isp1 kernel: FS:  00007f55d72006c0(0000) GS:ffff92ceaed80000(0000) knlGS:0000000000000000
Aug 30 09:10:17 isp1 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 30 09:10:17 isp1 kernel: CR2: 00007f2565600000 CR3: 000000020dbf2004 CR4: 00000000003706f0
Aug 30 09:10:17 isp1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 30 09:10:17 isp1 kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
Aug 30 09:10:17 isp1 kernel: Call Trace:
Aug 30 09:10:17 isp1 kernel:  <TASK>
Aug 30 09:10:17 isp1 kernel:  ? __die_body.cold+0x14/0x24
Aug 30 09:10:17 isp1 kernel:  ? die+0x2e/0x50
Aug 30 09:10:17 isp1 kernel:  ? do_trap+0xca/0x110
Aug 30 09:10:17 isp1 kernel:  ? do_error_trap+0x6a/0x90
Aug 30 09:10:17 isp1 kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 30 09:10:17 isp1 kernel:  ? exc_invalid_op+0x50/0x70
Aug 30 09:10:17 isp1 kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 30 09:10:17 isp1 kernel:  ? asm_exc_invalid_op+0x1a/0x20
Aug 30 09:10:17 isp1 kernel:  ? btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 30 09:10:17 isp1 kernel:  btrfs_sync_file+0x21a/0x4d0 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 30 09:10:17 isp1 kernel:  ? __seccomp_filter+0x31d/0x4f0
Aug 30 09:10:17 isp1 kernel:  __x64_sys_fdatasync+0x4f/0x90
Aug 30 09:10:17 isp1 kernel:  do_syscall_64+0x82/0x160
Aug 30 09:10:17 isp1 kernel:  ? file_check_and_advance_wb_err+0x32/0xd0
Aug 30 09:10:17 isp1 kernel:  ? btrfs_sync_file+0x160/0x4d0 [btrfs bb26272d49b4cdc847cf3f7faadd459b62caee9a]
Aug 30 09:10:17 isp1 kernel:  ? __rseq_handle_notify_resume+0xa8/0x4d0
Aug 30 09:10:17 isp1 kernel:  ? switch_fpu_return+0x4f/0xd0
Aug 30 09:10:17 isp1 kernel:  ? syscall_exit_to_user_mode+0x72/0x220
Aug 30 09:10:17 isp1 kernel:  ? do_syscall_64+0x8e/0x160
Aug 30 09:10:17 isp1 kernel:  ? futex_wake+0x159/0x190
Aug 30 09:10:17 isp1 kernel:  ? do_futex+0x125/0x190
Aug 30 09:10:17 isp1 kernel:  ? __x64_sys_futex+0x10e/0x1d0
Aug 30 09:10:17 isp1 kernel:  ? syscall_exit_to_user_mode+0x72/0x220
Aug 30 09:10:17 isp1 kernel:  ? do_syscall_64+0x8e/0x160
Aug 30 09:10:17 isp1 kernel:  ? ktime_get+0x38/0xd0
Aug 30 09:10:17 isp1 kernel:  ? lapic_next_deadline+0x2c/0x40
Aug 30 09:10:17 isp1 kernel:  ? clockevents_program_event+0x8a/0xf0
Aug 30 09:10:17 isp1 kernel:  ? hrtimer_interrupt+0x123/0x210
Aug 30 09:10:17 isp1 kernel:  ? __sysvec_apic_timer_interrupt+0x55/0x100
Aug 30 09:10:17 isp1 kernel:  ? __irq_exit_rcu+0x38/0xb0
Aug 30 09:10:17 isp1 kernel:  entry_SYSCALL_64_after_hwframe+0x76/0x7e
Aug 30 09:10:17 isp1 kernel: RIP: 0033:0x7f56f571e77c
Aug 30 09:10:17 isp1 kernel: Code: 0f 05 48 3d 00 f0 ff ff 77 3c c3 0f 1f 00 55 48 89 e5 48 83 ec 10 89 7d fc e8 d0 9d f7 ff 8b 7d fc 89 c2 b8 4b 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 2c 89 d7 89 45 fc e8 32 9e f7 ff 8b 45 fc c9
Aug 30 09:10:17 isp1 kernel: RSP: 002b:00007f55d71ffa00 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
Aug 30 09:10:17 isp1 kernel: RAX: ffffffffffffffda RBX: 000055d7c5ee78b8 RCX: 00007f56f571e77c
Aug 30 09:10:17 isp1 kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000000000000000e
Aug 30 09:10:17 isp1 kernel: RBP: 00007f55d71ffa10 R08: 000055d7c5dc9030 R09: 0000000000000000
Aug 30 09:10:17 isp1 kernel: R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000001
Aug 30 09:10:17 isp1 kernel: R13: 000000000000000e R14: 000055d7c5ee7768 R15: 000000000000000e
Aug 30 09:10:17 isp1 kernel:  </TASK>
Aug 30 09:10:17 isp1 kernel: Modules linked in: veth xt_nat xt_tcpudp xt_conntrack xt_MASQUERADE nf_conntrack_netlink xfrm_user xt_addrtype nft_compat af_packet wireguard libchacha20poly1305 chacha_x86_64 poly1305_x86_64 curve25519_x86_64 libcurve25519_generic libchacha ip6_udp_tunnel udp_tunnel nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib n>
Aug 30 09:10:17 isp1 kernel:  ipmi_msghandler intel_pmc_core intel_vsec pmt_telemetry pmt_class acpi_tad acpi_pad button configfs fuse loop dm_mod efi_pstore dmi_sysfs ip_tables x_tables usbhid uas usb_storage crct10dif_pclmul crc32_pclmul polyval_clmulni polyval_generic gf128mul ghash_clmulni_intel ahci sha512_ssse3 libahci sha256_ssse3 sha1_>
Aug 30 09:10:17 isp1 kernel: ---[ end trace 0000000000000000 ]---
Aug 30 09:10:17 isp1 kernel: RIP: 0010:btrfs_get_ordered_extents_for_logging.cold+0x1f/0x42 [btrfs]
Aug 30 09:10:17 isp1 kernel: Code: 50 c6 6b c0 e8 79 13 8e f1 0f 0b b9 d7 03 00 00 48 c7 c2 b0 38 6b c0 48 c7 c6 40 c8 6b c0 48 c7 c7 50 c6 6b c0 e8 58 13 8e f1 <0f> 0b b9 e2 03 00 00 48 c7 c2 b0 38 6b c0 48 c7 c6 68 c8 6b c0 48
Aug 30 09:10:17 isp1 kernel: RSP: 0018:ffffafff858a7a80 EFLAGS: 00010246
Aug 30 09:10:17 isp1 kernel: RAX: 0000000000000054 RBX: ffff92b0765c9728 RCX: 0000000000000000
Aug 30 09:10:17 isp1 kernel: RDX: 0000000000000000 RSI: ffff92ceaeda7800 RDI: ffff92ceaeda7800
Aug 30 09:10:17 isp1 kernel: RBP: ffff92afc6917d00 R08: 0000000000000000 R09: ffffafff858a7880
Aug 30 09:10:17 isp1 kernel: R10: ffffafff858a7878 R11: 0000000000000003 R12: ffff92afc7dc8000
Aug 30 09:10:17 isp1 kernel: R13: 0000000000000001 R14: ffff92b07654c9c0 R15: 0000000000000000
Aug 30 09:10:17 isp1 kernel: FS:  00007f55d72006c0(0000) GS:ffff92ceaed80000(0000) knlGS:0000000000000000
Aug 30 09:10:17 isp1 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 30 09:10:17 isp1 kernel: CR2: 00007f2565600000 CR3: 000000020dbf2004 CR4: 00000000003706f0
Aug 30 09:10:18 isp1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Aug 30 09:10:18 isp1 kernel: DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400

Comment 3 Filipe David Manana 2024-08-30 10:11:12 UTC

Here's the fix:

https://lore.kernel.org/linux-btrfs/717029440fe379747b9548a9c91eb7801bc5a813.1724972507.git.fdmanana@suse.com/

That applies only against 6.11-rc releases. For a version that applies to the latest 6.10 stable release (6.10.7):

https://gist.githubusercontent.com/fdmanana/e032236302bf5e65fb9728fca98c5eb0/raw/456f1c2c30c338964085d6ba016dcf330aa10fb4/gistfile1.txt