6.4 and 6.9 btrfs blocked and btrfs_work_helper workqueue lockup, is it an IO bug/hang though?

Marc MERLIN
2024-02-19T06:23:37Z

I've seen this with both 6.4.9 and 6.6.9 and had to sysrq reboot both
times to recover.
I'm trying to see if it's a hang of my raid card.

That's the more recent hang with 6.6.9:

The one with 6.4.9 is longer, so I put it here: https://pastebin.com/xz11JXWM

Here's the 6.6.9 one here. Can someone help me confirm that at least
this one is likely not btrfs' fault but just underlying I/O hang?

If so, idoes the 6.4.9 match the same symptom, or is it a different issue?

Thanks,
Marc

135577.600958] INFO: task md12_raid1:1276 blocked for more than 120 seconds.
[135577.621963] Not tainted 6.6.9-amd64-volpre-sysrq-20240101 #19
[135577.641401] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135577.665522] task:md12_raid1 state:D stack:0 pid:1276 ppid:2 flags:0x00004000
[135577.691381] Call Trace:
[135577.699494] <TASK>
[135577.706627] __schedule+0x6af/0x702
[135577.717853] schedule+0x8b/0xbd
[135577.727933] md_super_wait+0x5d/0x9c
[135577.739287] ? __pfx_autoremove_wake_function+0x40/0x40
[135577.755602] write_sb_page+0x242/0x25d
[135577.767482] md_update_sb+0x4c1/0x679
[135577.779072] md_check_recovery+0x276/0x484
[135577.791965] raid1d+0x46/0x10db
[135577.802178] ? raw_spin_rq_unlock_irq+0x5/0x10
[135577.816122] ? finish_task_switch.isra.0+0x129/0x202
[135577.831629] ? __schedule+0x6b7/0x702
[135577.843292] ? lock_timer_base+0x38/0x5f
[135577.855662] ? schedule+0x8b/0xbd
[135577.866222] ? __list_add+0x12/0x2f
[135577.877341] ? _raw_spin_unlock_irqrestore+0xe/0x2e
[135577.892618] md_thread+0x113/0x140
[135577.903553] ? __pfx_autoremove_wake_function+0x40/0x40
[135577.920016] ? __pfx_md_thread+0x40/0x40
[135577.932413] kthread+0xe8/0xf0
[135577.942221] ? __pfx_kthread+0x40/0x40
[135577.954084] ret_from_fork+0x24/0x36
[135577.965583] ? __pfx_kthread+0x40/0x40
[135577.977475] ret_from_fork_asm+0x1b/0x80
[135577.989877] </TASK>
[135577.997078] INFO: task md13_raid1:1278 blocked for more than 121 seconds.
[135578.018044] Not tainted 6.6.9-amd64-volpre-sysrq-20240101 #19
[135578.037405] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135578.061454] task:md13_raid1 state:D stack:0 pid:1278 ppid:2 flags:0x00004000
[135578.087065] Call Trace:
[135578.094972] <TASK>
[135578.102074] __schedule+0x6af/0x702
[135578.113302] schedule+0x8b/0xbd
[135578.123297] md_super_wait+0x5d/0x9c
[135578.134757] ? __pfx_autoremove_wake_function+0x40/0x40
[135578.151023] write_sb_page+0x242/0x25d
[135578.162869] md_update_sb+0x4c1/0x679
[135578.174470] md_check_recovery+0x276/0x484
[135578.187342] raid1d+0x46/0x10db
[135578.197352] ? raw_spin_rq_unlock_irq+0x5/0x10
[135578.211262] ? finish_task_switch.isra.0+0x129/0x202
[135578.226731] ? __schedule+0x6b7/0x702
[135578.238278] ? lock_timer_base+0x38/0x5f
[135578.250688] ? _raw_spin_unlock_irqrestore+0xe/0x2e
[135578.265933] ? __try_to_del_timer_sync+0x64/0x8b
[135578.280350] ? __timer_delete_sync+0x2e/0x3d
[135578.293706] ? __list_add+0x12/0x2f
[135578.304886] ? _raw_spin_unlock_irqrestore+0xe/0x2e
[135578.320238] md_thread+0x113/0x140
[135578.331038] ? __pfx_autoremove_wake_function+0x40/0x40
[135578.347265] ? __pfx_md_thread+0x40/0x40
[135578.359599] kthread+0xe8/0xf0
[135578.369323] ? __pfx_kthread+0x40/0x40
[135578.381272] ret_from_fork+0x24/0x36
[135578.392702] ? __pfx_kthread+0x40/0x40
[135578.404534] ret_from_fork_asm+0x1b/0x80
[135578.416877] </TASK>
[135578.424012] INFO: task dmcrypt_write/2:2017 blocked for more than 121 seconds.
[135578.446256] Not tainted 6.6.9-amd64-volpre-sysrq-20240101 #19
[135578.465619] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135578.489691] task:dmcrypt_write/2 state:D stack:0 pid:2017 ppid:2 flags:0x00004000
[135578.515301] Call Trace:
[135578.523384] <TASK>
[135578.530433] __schedule+0x6af/0x702
[135578.541490] schedule+0x8b/0xbd
[135578.551650] md_write_start+0x160/0x1a7
[135578.563748] ? __pfx_autoremove_wake_function+0x40/0x40
[135578.579993] raid1_make_request+0x89/0x880
[135578.592962] ? sugov_update_single_freq+0x20/0x106
[135578.607926] ? update_load_avg+0x372/0x39b
[135578.620814] ? get_sd_balance_interval+0xf/0x3d
[135578.635156] md_handle_request+0x126/0x16d
[135578.648040] ? __pfx_dmcrypt_write+0x40/0x40 [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135578.674973] ? _raw_spin_unlock+0xa/0x1d
[135578.687325] ? raw_spin_rq_unlock_irq+0x5/0x10
[135578.701386] ? finish_task_switch.isra.0+0x129/0x202
[135578.716851] __submit_bio+0x63/0x89
[135578.728043] submit_bio_noacct_nocheck+0x181/0x258
[135578.743026] ? __pfx_dmcrypt_write+0x40/0x40 [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135578.769994] dmcrypt_write+0xd1/0xfd [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135578.794848] kthread+0xe8/0xf0
[135578.804612] ? __pfx_kthread+0x40/0x40
[135578.816438] ret_from_fork+0x24/0x36
[135578.827741] ? __pfx_kthread+0x40/0x40
[135578.839744] ret_from_fork_asm+0x1b/0x80
[135578.852280] </TASK>
[135578.859445] INFO: task btrfs-transacti:2415 blocked for more than 122 seconds.
[135578.881710] Not tainted 6.6.9-amd64-volpre-sysrq-20240101 #19
[135578.901270] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135578.925345] task:btrfs-transacti state:D stack:0 pid:2415 ppid:2 flags:0x00004000
[135578.950996] Call Trace:
[135578.958960] <TASK>
[135578.965902] __schedule+0x6af/0x702
[135578.976995] schedule+0x8b/0xbd
[135578.987195] io_schedule+0x12/0x38
[135578.998015] folio_wait_bit_common+0x157/0x202
[135579.011950] ? __pfx_wake_page_function+0x40/0x40
[135579.026658] folio_wait_writeback+0x30/0x38
[135579.039897] __filemap_fdatawait_range+0x74/0xbf
[135579.054353] ? __update_freelist_fast+0x17/0x1e
[135579.068568] ? __clear_extent_bit+0x323/0x338
[135579.082257] filemap_fdatawait_range+0xf/0x19
[135579.096112] __btrfs_wait_marked_extents.isra.0+0x98/0xf3
[135579.113089] btrfs_write_and_wait_transaction+0x5d/0xbf
[135579.129372] btrfs_commit_transaction+0x67c/0xa62
[135579.144094] ? start_transaction+0x3f7/0x463
[135579.157540] transaction_kthread+0x105/0x17a
[135579.170970] ? __pfx_transaction_kthread+0x40/0x40
[135579.185951] kthread+0xe8/0xf0
[135579.195732] ? __pfx_kthread+0x40/0x40
[135579.207593] ret_from_fork+0x24/0x36
[135579.218942] ? __pfx_kthread+0x40/0x40
[135579.230778] ret_from_fork_asm+0x1b/0x80
[135579.243146] </TASK>
[135579.250316] INFO: task dmcrypt_write/2:5016 blocked for more than 122 seconds.
[135579.272593] Not tainted 6.6.9-amd64-volpre-sysrq-20240101 #19
[135579.291991] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135579.316244] task:dmcrypt_write/2 state:D stack:0 pid:5016 ppid:2 flags:0x00004000
[135579.341930] Call Trace:
[135579.349929] <TASK>
[135579.356826] __schedule+0x6af/0x702
[135579.367910] schedule+0x8b/0xbd
[135579.377939] md_write_start+0x160/0x1a7
[135579.390216] ? __pfx_autoremove_wake_function+0x40/0x40
[135579.406491] raid1_make_request+0x89/0x880
[135579.419401] ? update_cfs_rq_load_avg+0x176/0x189
[135579.434131] ? update_load_avg+0x46/0x39b
[135579.446738] ? get_sd_balance_interval+0xf/0x3d
[135579.461129] md_handle_request+0x126/0x16d
[135579.474037] ? __pfx_dmcrypt_write+0x40/0x40 [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135579.500975] ? _raw_spin_unlock+0xa/0x1d
[135579.513370] ? raw_spin_rq_unlock_irq+0x5/0x10
[135579.527308] ? finish_task_switch.isra.0+0x129/0x202
[135579.542831] __submit_bio+0x63/0x89
[135579.553918] submit_bio_noacct_nocheck+0x181/0x258
[135579.568943] ? __pfx_dmcrypt_write+0x40/0x40 [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135579.595885] dmcrypt_write+0xd1/0xfd [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135579.620760] kthread+0xe8/0xf0
[135579.630682] ? __pfx_kthread+0x40/0x40
[135579.642699] ret_from_fork+0x24/0x36
[135579.654188] ? __pfx_kthread+0x40/0x40
[135579.666045] ret_from_fork_asm+0x1b/0x80
[135579.678418] </TASK>
[135579.685606] INFO: task dmcrypt_write/2:5286 blocked for more than 122 seconds.
[135579.707870] Not tainted 6.6.9-amd64-volpre-sysrq-20240101 #19
[135579.727445] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[135579.751591] task:dmcrypt_write/2 state:D stack:0 pid:5286 ppid:2 flags:0x00004000
[135579.777266] Call Trace:
[135579.785223] <TASK>
[135579.792124] __schedule+0x6af/0x702
[135579.803200] ? __pfx_wbt_inflight_cb+0x40/0x40
[135579.817139] ? __pfx_wbt_cleanup_cb+0x40/0x40
[135579.830818] schedule+0x8b/0xbd
[135579.840951] io_schedule+0x12/0x38
[135579.851745] rq_qos_wait+0xe8/0x126
[135579.862795] ? __pfx_rq_qos_wake_function+0x40/0x40
[135579.878021] ? __pfx_wbt_inflight_cb+0x40/0x40
[135579.891951] wbt_wait+0x95/0xe4
[135579.902022] __rq_qos_throttle+0x23/0x33
[135579.914398] blk_mq_submit_bio+0x2b6/0x4dd
[135579.927273] __submit_bio+0x29/0x89
[135579.938356] submit_bio_noacct_nocheck+0x121/0x258
[135579.953357] ? __pfx_dmcrypt_write+0x40/0x40 [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135579.980432] dmcrypt_write+0xd1/0xfd [dm_crypt 721219ef82f7f7c3ecde59f70e81b621d3b8f858]
[135580.005323] kthread+0xe8/0xf0
[135580.015088] ? __pfx_kthread+0x40/0x40
[135580.026929] ret_from_fork+0x24/0x36
[135580.038259] ? __pfx_kthread+0x40/0x40
[135580.050266] ret_from_fork_asm+0x1b/0x80
[135580.062628] </TASK>
[135580.069774] Future hung task reports are suppressed, see sysctl kernel.hung_task_warnings