From: Filipe Manana <fdmanana@kernel.org>
To: Chris Murphy <lists@colorremedies.com>
Cc: Btrfs BTRFS <linux-btrfs@vger.kernel.org>,
Josef Bacik <josef@toxicpanda.com>
Subject: Re: 5.16.0-0.rc5, btrfs-transacti:9822 blocked, write time tree block corruption, parent transid verify failed, error in free_log_tree, forced ro
Date: Tue, 14 Dec 2021 11:37:08 +0000 [thread overview]
Message-ID: <YbiB5K2xeN2tomkz@debian9.Home> (raw)
In-Reply-To: <CAJCQCtT+RSzpUjbMq+UfzNUMe1X5+1G+DnAGbHC=OZ=iRS24jg@mail.gmail.com>
On Mon, Dec 13, 2021 at 09:58:41PM -0500, Chris Murphy wrote:
> This is a regression, I never encountered it running rc4, and running
> rc5 for just about 5 hours ran into a hang after logging out of the
> desktop and back in...
>
> I let it hang for a while (few minutes) then dropped to a tty and did
> a reboot. Fortunately journald did capture quite a lot more than I saw
> before the reboot. Following reboot (used 5.15.7), btrfs has no
> complaints. Mounts and boots fine, so the write time tree checker may
> have prevented corruption.
>
> Full dmesg here:
> https://drive.google.com/file/d/1arn0_wVbbK0RiI1sKLnXuqpPjW2mHdFu/view?usp=sharing
>
> Inline excerpted from the first blocked task messages...
>
> Dec 13 21:42:47 kernel: INFO: task btrfs-transacti:9822 blocked for
> more than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:btrfs-transacti state:D stack:14920 pid:
> 9822 ppid: 2 flags:0x00004000
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x2d/0x60
> Dec 13 21:42:47 kernel: ? lockdep_hardirqs_on+0x7e/0x100
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x3e/0x60
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: wait_current_trans+0xad/0x110
> Dec 13 21:42:47 kernel: ? do_wait_intr_irq+0xb0/0xb0
> Dec 13 21:42:47 kernel: start_transaction+0x365/0x6a0
> Dec 13 21:42:47 kernel: transaction_kthread+0xa7/0x1a0
> Dec 13 21:42:47 kernel: ? btrfs_cleanup_transaction.isra.0+0x640/0x640
> Dec 13 21:42:47 kernel: kthread+0x17a/0x1a0
> Dec 13 21:42:47 kernel: ? set_kthread_struct+0x40/0x40
> Dec 13 21:42:47 kernel: ret_from_fork+0x1f/0x30
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task Cache2 I/O:10810 blocked for more
> than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:Cache2 I/O state:D stack:12680
> pid:10810 ppid: 9889 flags:0x00000004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x2d/0x60
> Dec 13 21:42:47 kernel: ? lockdep_hardirqs_on+0x7e/0x100
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x3e/0x60
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: wait_current_trans+0xad/0x110
> Dec 13 21:42:47 kernel: ? do_wait_intr_irq+0xb0/0xb0
> Dec 13 21:42:47 kernel: start_transaction+0x3dc/0x6a0
> Dec 13 21:42:47 kernel: btrfs_unlink+0x32/0x110
> Dec 13 21:42:47 kernel: vfs_unlink+0x110/0x230
> Dec 13 21:42:47 kernel: do_unlinkat+0x18c/0x2b0
> Dec 13 21:42:47 kernel: __x64_sys_unlink+0x3e/0x60
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df1fdb
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc939748e8 EFLAGS: 00000206
> ORIG_RAX: 0000000000000057
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 00007fbc6af4c500
> RCX: 00007fbcb3df1fdb
> Dec 13 21:42:47 kernel: RDX: 0000000000000000 RSI: 00007fbc6d144d08
> RDI: 00007fbc6d144d08
> Dec 13 21:42:47 kernel: RBP: 0000000000000000 R08: 0000000000000000
> R09: 000000000000000a
> Dec 13 21:42:47 kernel: R10: 0000000000000100 R11: 0000000000000206
> R12: 0000000000000000
> Dec 13 21:42:47 kernel: R13: 00007fbc6c8e78e0 R14: 00007fbc6c8e78e0
> R15: 00007fbc6d1259c0
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task BgIOThr~Pool #1:10821 blocked for
> more than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:BgIOThr~Pool #1 state:D stack:11784
> pid:10821 ppid: 9889 flags:0x00000004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x2d/0x60
> Dec 13 21:42:47 kernel: ? lockdep_hardirqs_on+0x7e/0x100
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x3e/0x60
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: wait_current_trans+0xad/0x110
> Dec 13 21:42:47 kernel: ? do_wait_intr_irq+0xb0/0xb0
> Dec 13 21:42:47 kernel: start_transaction+0x3dc/0x6a0
> Dec 13 21:42:47 kernel: btrfs_create+0x4c/0x200
> Dec 13 21:42:47 kernel: ? d_splice_alias+0x16e/0x490
> Dec 13 21:42:47 kernel: lookup_open.isra.0+0x534/0x670
> Dec 13 21:42:47 kernel: ? __wake_up_common_lock+0x52/0x90
> Dec 13 21:42:47 kernel: path_openat+0x2aa/0xa20
> Dec 13 21:42:47 kernel: do_filp_open+0x9f/0x130
> Dec 13 21:42:47 kernel: ? lock_release+0x151/0x460
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock+0x29/0x40
> Dec 13 21:42:47 kernel: ? alloc_fd+0x12f/0x1f0
> Dec 13 21:42:47 kernel: do_sys_openat2+0x7a/0x140
> Dec 13 21:42:47 kernel: __x64_sys_openat+0x45/0x70
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df0524
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc92ebc130 EFLAGS: 00000293
> ORIG_RAX: 0000000000000101
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 0000000000000008
> RCX: 00007fbcb3df0524
> Dec 13 21:42:47 kernel: RDX: 0000000000000241 RSI: 00007fbc6baaf608
> RDI: 00000000ffffff9c
> Dec 13 21:42:47 kernel: RBP: 00007fbc6baaf608 R08: 0000000000000000
> R09: 0000000000000004
> Dec 13 21:42:47 kernel: R10: 00000000000001b6 R11: 0000000000000293
> R12: 0000000000000241
> Dec 13 21:42:47 kernel: R13: 00000000000001b6 R14: 00007fbc92ebd580
> R15: 00007fbc66a9a000
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task glean.dispatche:10872 blocked for
> more than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:glean.dispatche state:D stack:13032
> pid:10872 ppid: 9889 flags:0x00000004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x2d/0x60
> Dec 13 21:42:47 kernel: ? lockdep_hardirqs_on+0x7e/0x100
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x3e/0x60
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: wait_current_trans+0xad/0x110
> Dec 13 21:42:47 kernel: ? do_wait_intr_irq+0xb0/0xb0
> Dec 13 21:42:47 kernel: start_transaction+0x3dc/0x6a0
> Dec 13 21:42:47 kernel: btrfs_setattr+0x165/0x6e0
> Dec 13 21:42:47 kernel: notify_change+0x346/0x4e0
> Dec 13 21:42:47 kernel: ? do_truncate+0x6d/0xb0
> Dec 13 21:42:47 kernel: do_truncate+0x6d/0xb0
> Dec 13 21:42:47 kernel: path_openat+0x8a8/0xa20
> Dec 13 21:42:47 kernel: do_filp_open+0x9f/0x130
> Dec 13 21:42:47 kernel: ? lock_release+0x151/0x460
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock+0x29/0x40
> Dec 13 21:42:47 kernel: ? alloc_fd+0x12f/0x1f0
> Dec 13 21:42:47 kernel: do_sys_openat2+0x7a/0x140
> Dec 13 21:42:47 kernel: __x64_sys_openat+0x45/0x70
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df0524
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc7b9fe5d0 EFLAGS: 00000293
> ORIG_RAX: 0000000000000101
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 00007fbc656beb00
> RCX: 00007fbcb3df0524
> Dec 13 21:42:47 kernel: RDX: 0000000000080241 RSI: 00007fbc656bebe0
> RDI: 00000000ffffff9c
> Dec 13 21:42:47 kernel: RBP: 00007fbc656bebe0 R08: 0000000000000000
> R09: 06d4bfcacf505cb2
> Dec 13 21:42:47 kernel: R10: 00000000000001b6 R11: 0000000000000293
> R12: 0000000000080241
> Dec 13 21:42:47 kernel: R13: 00007fbc7b9fe6f8 R14: 0000000000000000
> R15: 00000000000001b6
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task QuotaManager IO:10873 blocked for
> more than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:QuotaManager IO state:D stack:12360
> pid:10873 ppid: 9889 flags:0x00000004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? mark_held_locks+0x50/0x80
> Dec 13 21:42:47 kernel: ? __down_read_common+0x168/0x4f0
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: __down_read_common+0x328/0x4f0
> Dec 13 21:42:47 kernel: ? down_read+0xbe/0x130
> Dec 13 21:42:47 kernel: down_read+0xbe/0x130
> Dec 13 21:42:47 kernel: walk_component+0x10c/0x190
> Dec 13 21:42:47 kernel: path_lookupat+0x6e/0x1c0
> Dec 13 21:42:47 kernel: filename_lookup+0xbc/0x1a0
> Dec 13 21:42:47 kernel: ? __check_object_size+0x152/0x190
> Dec 13 21:42:47 kernel: ? strncpy_from_user+0x53/0x180
> Dec 13 21:42:47 kernel: user_path_at_empty+0x3a/0x50
> Dec 13 21:42:47 kernel: do_faccessat+0x6e/0x260
> Dec 13 21:42:47 kernel: ? syscall_enter_from_user_mode+0x21/0x70
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df08bb
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc823fe618 EFLAGS: 00000246
> ORIG_RAX: 0000000000000015
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 00007fbc6a8710e0
> RCX: 00007fbcb3df08bb
> Dec 13 21:42:47 kernel: RDX: 0000000000000139 RSI: 0000000000000000
> RDI: 00007fbc6a824a88
> Dec 13 21:42:47 kernel: RBP: 00007fbc823fe647 R08: 00007fbcb3b00258
> R09: 0000000000000004
> Dec 13 21:42:47 kernel: R10: 0000000000000038 R11: 0000000000000246
> R12: 00007fbc823fe6a8
> Dec 13 21:42:47 kernel: R13: 00007fbc823fe700 R14: 00007fbc823fe780
> R15: 00007fbc6a8114b0
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task StreamTrans #5:10874 blocked for
> more than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:StreamTrans #5 state:D stack:13464
> pid:10874 ppid: 9889 flags:0x00004004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? lock_release+0x151/0x460
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: btrfs_sync_log+0x150/0xc20
> Dec 13 21:42:47 kernel: ? do_wait_intr_irq+0xb0/0xb0
> Dec 13 21:42:47 kernel: ? lock_is_held_type+0xea/0x140
> Dec 13 21:42:47 kernel: ? dput+0x20/0x480
> Dec 13 21:42:47 kernel: ? find_held_lock+0x32/0x90
> Dec 13 21:42:47 kernel: ? __lock_acquire+0x3b3/0x1e00
> Dec 13 21:42:47 kernel: ? reacquire_held_locks+0xe6/0x200
> Dec 13 21:42:47 kernel: ? btrfs_sync_file+0x327/0x5a0
> Dec 13 21:42:47 kernel: ? lock_is_held_type+0xea/0x140
> Dec 13 21:42:47 kernel: ? lock_release+0x151/0x460
> Dec 13 21:42:47 kernel: btrfs_sync_file+0x40c/0x5a0
> Dec 13 21:42:47 kernel: __x64_sys_fsync+0x33/0x60
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df71db
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc823bd7e0 EFLAGS: 00000293
> ORIG_RAX: 000000000000004a
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 00007fbc736e5f20
> RCX: 00007fbcb3df71db
> Dec 13 21:42:47 kernel: RDX: 0000000000000000 RSI: 00007fbc6a8ab000
> RDI: 0000000000000078
> Dec 13 21:42:47 kernel: RBP: 00007fbc6a815430 R08: 0000000000000000
> R09: fffffffffffffff0
> Dec 13 21:42:47 kernel: R10: 0000000000000010 R11: 0000000000000293
> R12: 00000000000000ca
> Dec 13 21:42:47 kernel: R13: 00007fbcaeaafa78 R14: 00007fbcaeaafa48
> R15: 00007fbc736f8bc8
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task DOM Worker:10876 blocked for more
> than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:DOM Worker state:D stack:14416
> pid:10876 ppid: 9889 flags:0x00000004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x2d/0x60
> Dec 13 21:42:47 kernel: ? lockdep_hardirqs_on+0x7e/0x100
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock_irqrestore+0x3e/0x60
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: wait_current_trans+0xad/0x110
> Dec 13 21:42:47 kernel: ? do_wait_intr_irq+0xb0/0xb0
> Dec 13 21:42:47 kernel: start_transaction+0x3dc/0x6a0
> Dec 13 21:42:47 kernel: btrfs_create+0x4c/0x200
> Dec 13 21:42:47 kernel: ? d_splice_alias+0x16e/0x490
> Dec 13 21:42:47 kernel: lookup_open.isra.0+0x534/0x670
> Dec 13 21:42:47 kernel: ? __wake_up_common_lock+0x52/0x90
> Dec 13 21:42:47 kernel: path_openat+0x2aa/0xa20
> Dec 13 21:42:47 kernel: do_filp_open+0x9f/0x130
> Dec 13 21:42:47 kernel: ? lock_release+0x151/0x460
> Dec 13 21:42:47 kernel: ? _raw_spin_unlock+0x29/0x40
> Dec 13 21:42:47 kernel: ? alloc_fd+0x12f/0x1f0
> Dec 13 21:42:47 kernel: do_sys_openat2+0x7a/0x140
> Dec 13 21:42:47 kernel: __x64_sys_openat+0x45/0x70
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df0524
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc79afbd60 EFLAGS: 00000293
> ORIG_RAX: 0000000000000101
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 00007fbc6c7ac200
> RCX: 00007fbcb3df0524
> Dec 13 21:42:47 kernel: RDX: 0000000000000641 RSI: 00007fbc6c7c7340
> RDI: 00000000ffffff9c
> Dec 13 21:42:47 kernel: RBP: 00007fbc6c7c7340 R08: 0000000000000000
> R09: 00007fbc6c7c7340
> Dec 13 21:42:47 kernel: R10: 0000000000000180 R11: 0000000000000293
> R12: 0000000000000641
> Dec 13 21:42:47 kernel: R13: 00007fbc79afbe80 R14: 00007fbc757c9a98
> R15: 0000000000000003
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task IndexedDB #1:10877 blocked for more
> than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:IndexedDB #1 state:D stack:12344
> pid:10877 ppid: 9889 flags:0x00000004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? mark_held_locks+0x50/0x80
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: rwsem_down_write_slowpath+0x227/0x6b0
> Dec 13 21:42:47 kernel: down_write_nested+0xb3/0x120
> Dec 13 21:42:47 kernel: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: __x64_sys_unlink+0x3e/0x60
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df1fdb
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc90a973e8 EFLAGS: 00000246
> ORIG_RAX: 0000000000000057
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 0000000000000000
> RCX: 00007fbcb3df1fdb
> Dec 13 21:42:47 kernel: RDX: 0000000000000000 RSI: 00007fbc7cdf0b63
> RDI: 00007fbc7cdf0b63
> Dec 13 21:42:47 kernel: RBP: 00007fbc7cdf0b63 R08: 00007fbcb3b00418
> R09: 0000000000000005
> Dec 13 21:42:47 kernel: R10: 0000000000000037 R11: 0000000000000246
> R12: 00007fbc7cdf0b63
> Dec 13 21:42:47 kernel: R13: 0000000000000000 R14: 00007fbcb31fd7d8
> R15: 0000000000000000
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task IndexedDB #3:10926 blocked for more
> than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:IndexedDB #3 state:D stack:14088
> pid:10926 ppid: 9889 flags:0x00004004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? mark_held_locks+0x50/0x80
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: rwsem_down_write_slowpath+0x227/0x6b0
> Dec 13 21:42:47 kernel: down_write_nested+0xb3/0x120
> Dec 13 21:42:47 kernel: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: __x64_sys_unlink+0x3e/0x60
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df1fdb
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc774e43e8 EFLAGS: 00000246
> ORIG_RAX: 0000000000000057
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 0000000000000000
> RCX: 00007fbcb3df1fdb
> Dec 13 21:42:47 kernel: RDX: 0000000000000000 RSI: 00007fbc75b05851
> RDI: 00007fbc75b05851
> Dec 13 21:42:47 kernel: RBP: 00007fbc75b05851 R08: 00007fbcb3b00418
> R09: 0000000000000005
> Dec 13 21:42:47 kernel: R10: 0000000000000037 R11: 0000000000000246
> R12: 00007fbc75b05851
> Dec 13 21:42:47 kernel: R13: 0000000000000000 R14: 00007fbcb31fd7d8
> R15: 0000000000000000
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel: INFO: task IndexedDB #4:10927 blocked for more
> than 122 seconds.
> Dec 13 21:42:47 kernel: Tainted: G W --------- ---
> 5.16.0-0.rc5.35.fc36.x86_64+debug #1
> Dec 13 21:42:47 kernel: "echo 0 >
> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Dec 13 21:42:47 kernel: task:IndexedDB #4 state:D stack:13928
> pid:10927 ppid: 9889 flags:0x00004004
> Dec 13 21:42:47 kernel: Call Trace:
> Dec 13 21:42:47 kernel: <TASK>
> Dec 13 21:42:47 kernel: __schedule+0x3f8/0x1500
> Dec 13 21:42:47 kernel: ? mark_held_locks+0x50/0x80
> Dec 13 21:42:47 kernel: schedule+0x4e/0xc0
> Dec 13 21:42:47 kernel: rwsem_down_write_slowpath+0x227/0x6b0
> Dec 13 21:42:47 kernel: down_write_nested+0xb3/0x120
> Dec 13 21:42:47 kernel: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: __x64_sys_unlink+0x3e/0x60
> Dec 13 21:42:47 kernel: do_syscall_64+0x38/0x90
> Dec 13 21:42:47 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
> Dec 13 21:42:47 kernel: RIP: 0033:0x7fbcb3df1fdb
> Dec 13 21:42:47 kernel: RSP: 002b:00007fbc774a33e8 EFLAGS: 00000246
> ORIG_RAX: 0000000000000057
> Dec 13 21:42:47 kernel: RAX: ffffffffffffffda RBX: 0000000000000000
> RCX: 00007fbcb3df1fdb
> Dec 13 21:42:47 kernel: RDX: 0000000000000000 RSI: 00007fbc75b0676f
> RDI: 00007fbc75b0676f
> Dec 13 21:42:47 kernel: RBP: 00007fbc75b0676f R08: 00007fbcb3b00418
> R09: 0000000000000005
> Dec 13 21:42:47 kernel: R10: 0000000000000037 R11: 0000000000000246
> R12: 00007fbc75b0676f
> Dec 13 21:42:47 kernel: R13: 0000000000000000 R14: 00007fbcb31fd7d8
> R15: 0000000000000000
> Dec 13 21:42:47 kernel: </TASK>
> Dec 13 21:42:47 kernel:
> Showing all locks held in the system:
> Dec 13 21:42:47 kernel: 1 lock held by khungtaskd/56:
> Dec 13 21:42:47 kernel: #0: ffffffffa01915e0
> (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x15/0x16b
> Dec 13 21:42:47 kernel: 4 locks held by systemd-journal/593:
> Dec 13 21:42:47 kernel: 1 lock held by btrfs-transacti/9822:
> Dec 13 21:42:47 kernel: #0: ffff971463ab4840
> (&fs_info->transaction_kthread_mutex){+.+.}-{3:3}, at:
> transaction_kthread+0x56/0x1a0
> Dec 13 21:42:47 kernel: 3 locks held by Permission/10806:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: path_openat+0x9fb/0xa20
> Dec 13 21:42:47 kernel: #1: ffff97156085e9d8
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: path_openat+0x296/0xa20
> Dec 13 21:42:47 kernel: #2: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_create+0x4c/0x200
> Dec 13 21:42:47 kernel: 4 locks held by Cache2 I/O/10810:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: do_unlinkat+0x95/0x2b0
> Dec 13 21:42:47 kernel: #1: ffff971561909068
> (&type->i_mutex_dir_key#6/1){+.+.}-{3:3}, at: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: #2: ffff971535328678
> (&sb->s_type->i_mutex_key#14){++++}-{3:3}, at: vfs_unlink+0x48/0x230
> Dec 13 21:42:47 kernel: #3: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_unlink+0x32/0x110
> Dec 13 21:42:47 kernel: 3 locks held by BgIOThr~Pool #1/10821:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: path_openat+0x9fb/0xa20
> Dec 13 21:42:47 kernel: #1: ffff97153534dfe8
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: path_openat+0x296/0xa20
> Dec 13 21:42:47 kernel: #2: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_create+0x4c/0x200
> Dec 13 21:42:47 kernel: 3 locks held by glean.dispatche/10872:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: path_openat+0x813/0xa20
> Dec 13 21:42:47 kernel: #1: ffff97144eed2448
> (&sb->s_type->i_mutex_key#14){++++}-{3:3}, at: do_truncate+0x5d/0xb0
> Dec 13 21:42:47 kernel: #2: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_setattr+0x165/0x6e0
> Dec 13 21:42:47 kernel: 1 lock held by QuotaManager IO/10873:
> Dec 13 21:42:47 kernel: #0: ffff9715d4d73828
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: walk_component+0x10c/0x190
> Dec 13 21:42:47 kernel: 1 lock held by StreamTrans #5/10874:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_sync_file+0x327/0x5a0
> Dec 13 21:42:47 kernel: 3 locks held by DOM Worker/10876:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: path_openat+0x9fb/0xa20
> Dec 13 21:42:47 kernel: #1: ffff97150121a448
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: path_openat+0x296/0xa20
> Dec 13 21:42:47 kernel: #2: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_create+0x4c/0x200
> Dec 13 21:42:47 kernel: 2 locks held by IndexedDB #1/10877:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: do_unlinkat+0x95/0x2b0
> Dec 13 21:42:47 kernel: #1: ffff9715d4d73828
> (&type->i_mutex_dir_key#6/1){+.+.}-{3:3}, at: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: 4 locks held by IndexedDB #2/10878:
> Dec 13 21:42:47 kernel: 2 locks held by IndexedDB #3/10926:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: do_unlinkat+0x95/0x2b0
> Dec 13 21:42:47 kernel: #1: ffff9715d4d73828
> (&type->i_mutex_dir_key#6/1){+.+.}-{3:3}, at: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: 2 locks held by IndexedDB #4/10927:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: do_unlinkat+0x95/0x2b0
> Dec 13 21:42:47 kernel: #1: ffff9715d4d73828
> (&type->i_mutex_dir_key#6/1){+.+.}-{3:3}, at: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: 4 locks held by Backgro~Pool #2/10932:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: do_unlinkat+0x95/0x2b0
> Dec 13 21:42:47 kernel: #1: ffff971506b34218
> (&type->i_mutex_dir_key#6/1){+.+.}-{3:3}, at: do_unlinkat+0x106/0x2b0
> Dec 13 21:42:47 kernel: #2: ffff971506b35fe8
> (&sb->s_type->i_mutex_key#14){++++}-{3:3}, at: vfs_unlink+0x48/0x230
> Dec 13 21:42:47 kernel: #3: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_unlink+0x32/0x110
> Dec 13 21:42:47 kernel: 1 lock held by SaveScripts/11059:
> Dec 13 21:42:47 kernel: #0: ffff97153534dfe8
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: walk_component+0x10c/0x190
> Dec 13 21:42:47 kernel: 1 lock held by Classif~ Update/11066:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_sync_file+0x327/0x5a0
> Dec 13 21:42:47 kernel: 1 lock held by mozStorage #5/11358:
> Dec 13 21:42:47 kernel: #0: ffff97156085e9d8
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: walk_component+0x10c/0x190
> Dec 13 21:42:47 kernel: 3 locks held by gvfsd-metadata/11304:
> Dec 13 21:42:47 kernel: #0: ffff971601d0f498
> (sb_writers#14){.+.+}-{0:0}, at: path_openat+0x9fb/0xa20
> Dec 13 21:42:47 kernel: #1: ffff97155e064c08
> (&type->i_mutex_dir_key#6){++++}-{3:3}, at: path_openat+0x296/0xa20
> Dec 13 21:42:47 kernel: #2: ffff971601d0f6b8
> (sb_internal){.+.+}-{0:0}, at: btrfs_create+0x4c/0x200
> Dec 13 21:42:47 kernel:
> Dec 13 21:42:47 kernel: =============================================
> Dec 13 21:44:50 kernel: BTRFS critical (device dm-0): corrupt leaf:
> root=18446744073709551610 block=118444032 slot=21, bad key order, prev
> (704687 84 4146773349) current (704687 84 1063561078)
That's the problem. Everything else above can be ignored.
It was introduced in 5.16-rc1.
I've sent the fix a few minutes ago. It's at:
https://patchwork.kernel.org/project/linux-btrfs/patch/024e44a8e8d1fa7e15eb91c6891bd229b2b4210d.1639481280.git.fdmanana@suse.com/
Thanks.
> Dec 13 21:44:50 kernel: BTRFS info (device dm-0): leaf 118444032 gen
> 91449 total ptrs 39 free space 546 owner 18446744073709551610
> Dec 13 21:44:50 kernel: item 0 key (704687 1 0) itemoff 3835
> itemsize 160
> Dec 13 21:44:50 kernel: inode generation 35532 size
> 1026 mode 40755
> Dec 13 21:44:50 kernel: item 1 key (704687 12 704685) itemoff
> 3822 itemsize 13
> Dec 13 21:44:50 kernel: item 2 key (704687 24 3817753667)
> itemoff 3736 itemsize 86
> Dec 13 21:44:50 kernel: item 3 key (704687 60 0) itemoff 3728 itemsize 8
> Dec 13 21:44:50 kernel: item 4 key (704687 72 0) itemoff 3720 itemsize 8
> Dec 13 21:44:50 kernel: item 5 key (704687 84 140445108)
> itemoff 3666 itemsize 54
> Dec 13 21:44:50 kernel: dir oid 704793 type 1
> Dec 13 21:44:50 kernel: item 6 key (704687 84 298800632)
> itemoff 3599 itemsize 67
> Dec 13 21:44:50 kernel: dir oid 707849 type 2
> Dec 13 21:44:50 kernel: item 7 key (704687 84 476147658)
> itemoff 3532 itemsize 67
> Dec 13 21:44:50 kernel: dir oid 707901 type 2
> Dec 13 21:44:50 kernel: item 8 key (704687 84 633818382)
> itemoff 3471 itemsize 61
> Dec 13 21:44:50 kernel: dir oid 704694 type 2
> Dec 13 21:44:50 kernel: item 9 key (704687 84 654256665)
> itemoff 3403 itemsize 68
> Dec 13 21:44:50 kernel: dir oid 707841 type 1
> Dec 13 21:44:50 kernel: item 10 key (704687 84 995843418)
> itemoff 3331 itemsize 72
> Dec 13 21:44:50 kernel: dir oid 2167736 type 1
> Dec 13 21:44:50 kernel: item 11 key (704687 84 1063561078)
> itemoff 3278 itemsize 53
> Dec 13 21:44:50 kernel: dir oid 704799 type 2
> Dec 13 21:44:50 kernel: item 12 key (704687 84 1101156010)
> itemoff 3225 itemsize 53
> Dec 13 21:44:50 kernel: dir oid 704696 type 1
> Dec 13 21:44:50 kernel: item 13 key (704687 84 2521936574)
> itemoff 3173 itemsize 52
> Dec 13 21:44:50 kernel: dir oid 704704 type 2
> Dec 13 21:44:50 kernel: item 14 key (704687 84 2618368432)
> itemoff 3112 itemsize 61
> Dec 13 21:44:50 kernel: dir oid 704738 type 1
> Dec 13 21:44:50 kernel: item 15 key (704687 84 2676316190)
> itemoff 3046 itemsize 66
> Dec 13 21:44:50 kernel: dir oid 2167729 type 1
> Dec 13 21:44:50 kernel: item 16 key (704687 84 3319104192)
> itemoff 2986 itemsize 60
> Dec 13 21:44:50 kernel: dir oid 704745 type 2
> Dec 13 21:44:50 kernel: item 17 key (704687 84 3908046265)
> itemoff 2929 itemsize 57
> Dec 13 21:44:50 kernel: dir oid 2167734 type 1
> Dec 13 21:44:50 kernel: item 18 key (704687 84 3945713089)
> itemoff 2857 itemsize 72
> Dec 13 21:44:50 kernel: dir oid 2167730 type 1
> Dec 13 21:44:50 kernel: item 19 key (704687 84 4077169308)
> itemoff 2795 itemsize 62
> Dec 13 21:44:50 kernel: dir oid 704688 type 1
> Dec 13 21:44:50 kernel: item 20 key (704687 84 4146773349)
> itemoff 2727 itemsize 68
> Dec 13 21:44:50 kernel: dir oid 707892 type 1
> Dec 13 21:44:50 kernel: item 21 key (704687 84 1063561078)
> itemoff 2674 itemsize 53
> Dec 13 21:44:50 kernel: dir oid 704799 type 2
> Dec 13 21:44:50 kernel: item 22 key (704687 96 2) itemoff 2612
> itemsize 62
> Dec 13 21:44:50 kernel: item 23 key (704687 96 6) itemoff 2551
> itemsize 61
> Dec 13 21:44:50 kernel: item 24 key (704687 96 7) itemoff 2498
> itemsize 53
> Dec 13 21:44:50 kernel: item 25 key (704687 96 12) itemoff
> 2446 itemsize 52
> Dec 13 21:44:50 kernel: item 26 key (704687 96 14) itemoff
> 2385 itemsize 61
> Dec 13 21:44:50 kernel: item 27 key (704687 96 18) itemoff
> 2325 itemsize 60
> Dec 13 21:44:50 kernel: item 28 key (704687 96 24) itemoff
> 2271 itemsize 54
> Dec 13 21:44:50 kernel: item 29 key (704687 96 28) itemoff
> 2218 itemsize 53
> Dec 13 21:44:50 kernel: item 30 key (704687 96 62) itemoff
> 2150 itemsize 68
> Dec 13 21:44:50 kernel: item 31 key (704687 96 66) itemoff
> 2083 itemsize 67
> Dec 13 21:44:50 kernel: item 32 key (704687 96 75) itemoff
> 2015 itemsize 68
> Dec 13 21:44:50 kernel: item 33 key (704687 96 79) itemoff
> 1948 itemsize 67
> Dec 13 21:44:50 kernel: item 34 key (704687 96 82) itemoff
> 1882 itemsize 66
> Dec 13 21:44:50 kernel: item 35 key (704687 96 83) itemoff
> 1810 itemsize 72
> Dec 13 21:44:50 kernel: item 36 key (704687 96 85) itemoff
> 1753 itemsize 57
> Dec 13 21:44:50 kernel: item 37 key (704687 96 87) itemoff
> 1681 itemsize 72
> Dec 13 21:44:50 kernel: item 38 key (704694 1 0) itemoff 1521
> itemsize 160
> Dec 13 21:44:50 kernel: inode generation 35534 size 30
> mode 40755
> Dec 13 21:44:50 kernel: BTRFS error (device dm-0): block=118444032
> write time tree block corruption detected
> Dec 13 21:44:50 kernel: BTRFS error (device dm-0): parent transid
> verify failed on 118444032 wanted 91449 found 91446
> Dec 13 21:44:50 kernel: BTRFS error (device dm-0): parent transid
> verify failed on 118444032 wanted 91449 found 91446
> Dec 13 21:44:50 kernel: BTRFS: error (device dm-0) in
> free_log_tree:3434: errno=-5 IO failure
> Dec 13 21:44:50 kernel: BTRFS info (device dm-0): forced readonly
> Dec 13 21:44:50 kernel: BTRFS warning (device dm-0): Skipping commit
> of aborted transaction.
> Dec 13 21:44:50 kernel: BTRFS: error (device dm-0) in
> cleanup_transaction:1945: errno=-5 IO failure
>
>
>
> --
> Chris Murphy
prev parent reply other threads:[~2021-12-14 11:37 UTC|newest]
Thread overview: 3+ messages / expand[flat|nested] mbox.gz Atom feed top
2021-12-14 2:58 5.16.0-0.rc5, btrfs-transacti:9822 blocked, write time tree block corruption, parent transid verify failed, error in free_log_tree, forced ro Chris Murphy
2021-12-14 3:14 ` Chris Murphy
2021-12-14 11:37 ` Filipe Manana [this message]
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=YbiB5K2xeN2tomkz@debian9.Home \
--to=fdmanana@kernel.org \
--cc=josef@toxicpanda.com \
--cc=linux-btrfs@vger.kernel.org \
--cc=lists@colorremedies.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox