On Wed, Jul 13, 2022 at 4:15 AM Chao Yu chao@kernel.org wrote:
On 2022/7/13 7:22, Matteo Croce wrote:
On Fri, 6 May 2022 09:33:06 +0800 Chao Yu chao@kernel.org wrote:
As Yanming reported in bugzilla:
https://bugzilla.kernel.org/show_bug.cgi?id=215916
The kernel message is shown below:
kernel BUG at fs/f2fs/segment.c:2560! Call Trace: allocate_segment_by_default+0x228/0x440 f2fs_allocate_data_block+0x13d1/0x31f0 do_write_page+0x18d/0x710 f2fs_outplace_write_data+0x151/0x250 f2fs_do_write_data_page+0xef9/0x1980 move_data_page+0x6af/0xbc0 do_garbage_collect+0x312f/0x46f0 f2fs_gc+0x6b0/0x3bc0 f2fs_balance_fs+0x921/0x2260 f2fs_write_single_data_page+0x16be/0x2370 f2fs_write_cache_pages+0x428/0xd00 f2fs_write_data_pages+0x96e/0xd50 do_writepages+0x168/0x550 __writeback_single_inode+0x9f/0x870 writeback_sb_inodes+0x47d/0xb20 __writeback_inodes_wb+0xb2/0x200 wb_writeback+0x4bd/0x660 wb_workfn+0x5f3/0xab0 process_one_work+0x79f/0x13e0 worker_thread+0x89/0xf60 kthread+0x26a/0x300 ret_from_fork+0x22/0x30 RIP: 0010:new_curseg+0xe8d/0x15f0
The root cause is: ckpt.valid_block_count is inconsistent with SIT table, stat info indicates filesystem has free blocks, but SIT table indicates filesystem has no free segment.
So that during garbage colloection, it triggers panic when LFS allocator fails to find free segment.
This patch tries to fix this issue by checking consistency in between ckpt.valid_block_count and block accounted from SIT.
Cc: stable@vger.kernel.org Reported-by: Ming Yan yanming@tju.edu.cn Signed-off-by: Chao Yu chao.yu@oppo.com
v4:
- fix to set data/node type correctly. fs/f2fs/segment.c | 37 ++++++++++++++++++++++++++----------- 1 file changed, 26 insertions(+), 11 deletions(-)
diff --git a/fs/f2fs/segment.c b/fs/f2fs/segment.c index 3a3e2cec2ac4..4735d477059d 100644 --- a/fs/f2fs/segment.c +++ b/fs/f2fs/segment.c @@ -4461,7 +4461,8 @@ static int build_sit_entries(struct f2fs_sb_info *sbi) unsigned int i, start, end; unsigned int readed, start_blk = 0; int err = 0;
- block_t total_node_blocks = 0;
block_t sit_valid_blocks[2] = {0, 0};
int type;
do { readed = f2fs_ra_meta_pages(sbi, start_blk,
BIO_MAX_VECS, @@ -4486,8 +4487,9 @@ static int build_sit_entries(struct f2fs_sb_info *sbi) if (err) return err; seg_info_from_raw_sit(se, &sit);
if (IS_NODESEG(se->type))total_node_blocks +=se->valid_blocks; +
type = IS_NODESEG(se->type) ? NODE : DATA;sit_valid_blocks[type] += se->valid_blocks; if (f2fs_block_unit_discard(sbi)) { /* build discard map only one time */@@ -4527,15 +4529,17 @@ static int build_sit_entries(struct f2fs_sb_info *sbi) sit = sit_in_journal(journal, i);
old_valid_blocks = se->valid_blocks;
if (IS_NODESEG(se->type))total_node_blocks -= old_valid_blocks;
type = IS_NODESEG(se->type) ? NODE : DATA;sit_valid_blocks[type] -= old_valid_blocks; err = check_block_count(sbi, start, &sit); if (err) break; seg_info_from_raw_sit(se, &sit);
if (IS_NODESEG(se->type))total_node_blocks += se->valid_blocks;
type = IS_NODESEG(se->type) ? NODE : DATA;sit_valid_blocks[type] += se->valid_blocks; if (f2fs_block_unit_discard(sbi)) { if (is_set_ckpt_flags(sbi, CP_TRIMMED_FLAG)){ @@ -4557,13 +4561,24 @@ static int build_sit_entries(struct f2fs_sb_info *sbi) } up_read(&curseg->journal_rwsem);
- if (!err && total_node_blocks != valid_node_count(sbi)) {
- if (err)
return err;- if (sit_valid_blocks[NODE] != valid_node_count(sbi)) { f2fs_err(sbi, "SIT is corrupted node# %u vs %u",
total_node_blocks, valid_node_count(sbi));err = -EFSCORRUPTED;
sit_valid_blocks[NODE],valid_node_count(sbi));
return -EFSCORRUPTED;
- return err;
- if (sit_valid_blocks[DATA] + sit_valid_blocks[NODE] >
valid_user_blocks(sbi)) {f2fs_err(sbi, "SIT is corrupted data# %u %u vs %u",sit_valid_blocks[DATA],sit_valid_blocks[NODE],
valid_user_blocks(sbi));return -EFSCORRUPTED;}
return 0; }
static void init_free_segmap(struct f2fs_sb_info *sbi)
Hi all,
I'm experiencing this with kernel 5.18.5:
Hi Matteo,
It looks in your attached log there is no similar stack as below?
kernel BUG at fs/f2fs/segment.c:2560! Call Trace: allocate_segment_by_default+0x228/0x440 f2fs_allocate_data_block+0x13d1/0x31f0 do_write_page+0x18d/0x710
Could you please check cpu usage when the bug reproduces?
Thanks,
Hi,
This happens when the bug happens:
PID USER PR NI S %CPU %MEM TIME+ COMMAND 398 root 20 0 R 100,0 0,0 2:05.80 f2fs_gc-179:130
[1774085.200363] rcu: INFO: rcu_sched self-detected stall on CPU [1774085.206139] rcu: 1-....: (2099 ticks this GP) idle=a7f/1/0x4000000000000000 softirq=6435692/6435692 fqs=977 [1774085.216272] (t=2101 jiffies g=30461565 q=289) [1774085.216276] Task dump for CPU 1: [1774085.216278] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774085.216285] Call trace: [1774085.216287] dump_backtrace.part.0+0xb4/0xc0 [1774085.216299] show_stack+0x14/0x30 [1774085.216304] sched_show_task+0x130/0x160 [1774085.216309] dump_cpu_task+0x40/0x4c [1774085.216313] rcu_dump_cpu_stacks+0xec/0x130 [1774085.216317] rcu_sched_clock_irq+0x8f8/0xaa0 [1774085.216321] update_process_times+0x98/0x180 [1774085.216324] tick_sched_timer+0x54/0xd0 [1774085.216329] __hrtimer_run_queues+0x134/0x2d0 [1774085.216333] hrtimer_interrupt+0x110/0x2c0 [1774085.216336] arch_timer_handler_phys+0x28/0x40 [1774085.216342] handle_percpu_devid_irq+0x84/0x1c0 [1774085.216348] generic_handle_domain_irq+0x28/0x40 [1774085.216352] gic_handle_irq+0x58/0x80 [1774085.216357] call_on_irq_stack+0x2c/0x3c [1774085.216360] do_interrupt_handler+0x78/0x84 [1774085.216364] el1_interrupt+0x30/0x50 [1774085.216368] el1h_64_irq_handler+0x14/0x20 [1774085.216371] el1h_64_irq+0x64/0x68 [1774085.216374] __filemap_get_folio+0xa0/0x3b0 [1774085.216378] pagecache_get_page+0x18/0x70 [1774085.216383] grab_cache_page_write_begin+0x20/0x30 [1774085.216388] f2fs_get_read_data_page+0x3c/0x480 [1774085.216392] f2fs_get_lock_data_page+0x3c/0x260 [1774085.216395] move_data_page+0x34/0x530 [1774085.216398] do_garbage_collect+0xc54/0x12e0 [1774085.216401] f2fs_gc+0x3b4/0x800 [1774085.216404] gc_thread_func+0x4c8/0x640 [1774085.216407] kthread+0xd0/0xe0 [1774085.216411] ret_from_fork+0x10/0x20 [1774115.558533] rcu: INFO: rcu_sched self-detected stall on CPU [1774115.564309] rcu: 1-....: (2099 ticks this GP) idle=be7/1/0x4000000000000000 softirq=6435694/6435694 fqs=1016 [1774115.574528] (t=2101 jiffies g=30461569 q=847) [1774115.574532] Task dump for CPU 1: [1774115.574534] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774115.574541] Call trace: [1774115.574543] dump_backtrace.part.0+0xb4/0xc0 [1774115.574555] show_stack+0x14/0x30 [1774115.574559] sched_show_task+0x130/0x160 [1774115.574564] dump_cpu_task+0x40/0x4c [1774115.574569] rcu_dump_cpu_stacks+0xec/0x130 [1774115.574572] rcu_sched_clock_irq+0x8f8/0xaa0 [1774115.574576] update_process_times+0x98/0x180 [1774115.574580] tick_sched_timer+0x54/0xd0 [1774115.574584] __hrtimer_run_queues+0x134/0x2d0 [1774115.574587] hrtimer_interrupt+0x110/0x2c0 [1774115.574590] arch_timer_handler_phys+0x28/0x40 [1774115.574596] handle_percpu_devid_irq+0x84/0x1c0 [1774115.574603] generic_handle_domain_irq+0x28/0x40 [1774115.574606] gic_handle_irq+0x58/0x80 [1774115.574611] call_on_irq_stack+0x2c/0x3c [1774115.574615] do_interrupt_handler+0x78/0x84 [1774115.574618] el1_interrupt+0x30/0x50 [1774115.574623] el1h_64_irq_handler+0x14/0x20 [1774115.574626] el1h_64_irq+0x64/0x68 [1774115.574629] f2fs_is_valid_blkaddr+0x184/0x310 [1774115.574633] f2fs_get_read_data_page+0x80/0x480 [1774115.574637] f2fs_get_lock_data_page+0x3c/0x260 [1774115.574640] move_data_page+0x34/0x530 [1774115.574643] do_garbage_collect+0xc54/0x12e0 [1774115.574646] f2fs_gc+0x3b4/0x800 [1774115.574649] gc_thread_func+0x4c8/0x640 [1774115.574652] kthread+0xd0/0xe0 [1774115.574655] ret_from_fork+0x10/0x20 [1774178.604732] rcu: INFO: rcu_sched self-detected stall on CPU [1774178.610507] rcu: 1-....: (8404 ticks this GP) idle=be7/1/0x4000000000000000 softirq=6435694/6435694 fqs=3918 [1774178.620727] (t=8406 jiffies g=30461569 q=2117) [1774178.620730] Task dump for CPU 1: [1774178.620732] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774178.620739] Call trace: [1774178.620741] dump_backtrace.part.0+0xb4/0xc0 [1774178.620750] show_stack+0x14/0x30 [1774178.620754] sched_show_task+0x130/0x160 [1774178.620762] dump_cpu_task+0x40/0x4c [1774178.620766] rcu_dump_cpu_stacks+0xec/0x130 [1774178.620769] rcu_sched_clock_irq+0x8f8/0xaa0 [1774178.620774] update_process_times+0x98/0x180 [1774178.620777] tick_sched_timer+0x54/0xd0 [1774178.620781] __hrtimer_run_queues+0x134/0x2d0 [1774178.620785] hrtimer_interrupt+0x110/0x2c0 [1774178.620788] arch_timer_handler_phys+0x28/0x40 [1774178.620793] handle_percpu_devid_irq+0x84/0x1c0 [1774178.620798] generic_handle_domain_irq+0x28/0x40 [1774178.620801] gic_handle_irq+0x58/0x80 [1774178.620806] call_on_irq_stack+0x2c/0x3c [1774178.620810] do_interrupt_handler+0x78/0x84 [1774178.620813] el1_interrupt+0x30/0x50 [1774178.620818] el1h_64_irq_handler+0x14/0x20 [1774178.620821] el1h_64_irq+0x64/0x68 [1774178.620823] f2fs_lookup_extent_cache+0x18c/0x310 [1774178.620828] f2fs_get_read_data_page+0x54/0x480 [1774178.620832] f2fs_get_lock_data_page+0x3c/0x260 [1774178.620835] move_data_page+0x34/0x530 [1774178.620838] do_garbage_collect+0xc54/0x12e0 [1774178.620842] f2fs_gc+0x3b4/0x800 [1774178.620844] gc_thread_func+0x4c8/0x640 [1774178.620848] kthread+0xd0/0xe0 [1774178.620851] ret_from_fork+0x10/0x20 [1774260.049828] rcu: INFO: rcu_sched self-detected stall on CPU [1774260.055605] rcu: 0-....: (2099 ticks this GP) idle=915/1/0x4000000000000000 softirq=6031130/6031130 fqs=1015 [1774260.065826] (t=2101 jiffies g=30461577 q=931) [1774260.065830] Task dump for CPU 0: [1774260.065832] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774260.065839] Call trace: [1774260.065841] dump_backtrace.part.0+0xb4/0xc0 [1774260.065854] show_stack+0x14/0x30 [1774260.065858] sched_show_task+0x130/0x160 [1774260.065863] dump_cpu_task+0x40/0x4c [1774260.065868] rcu_dump_cpu_stacks+0xec/0x130 [1774260.065871] rcu_sched_clock_irq+0x8f8/0xaa0 [1774260.065875] update_process_times+0x98/0x180 [1774260.065879] tick_sched_timer+0x54/0xd0 [1774260.065883] __hrtimer_run_queues+0x134/0x2d0 [1774260.065887] hrtimer_interrupt+0x110/0x2c0 [1774260.065890] arch_timer_handler_phys+0x28/0x40 [1774260.065896] handle_percpu_devid_irq+0x84/0x1c0 [1774260.065901] generic_handle_domain_irq+0x28/0x40 [1774260.065904] gic_handle_irq+0x58/0x80 [1774260.065909] call_on_irq_stack+0x2c/0x3c [1774260.065913] do_interrupt_handler+0x78/0x84 [1774260.065916] el1_interrupt+0x30/0x50 [1774260.065922] el1h_64_irq_handler+0x14/0x20 [1774260.065925] el1h_64_irq+0x64/0x68 [1774260.065928] folio_wait_stable+0x8/0x30 [1774260.065933] pagecache_get_page+0x18/0x70 [1774260.065938] grab_cache_page_write_begin+0x20/0x30 [1774260.065943] f2fs_get_read_data_page+0x3c/0x480 [1774260.065947] f2fs_get_lock_data_page+0x3c/0x260 [1774260.065950] move_data_page+0x34/0x530 [1774260.065954] do_garbage_collect+0xc54/0x12e0 [1774260.065957] f2fs_gc+0x3b4/0x800 [1774260.065960] gc_thread_func+0x4c8/0x640 [1774260.065963] kthread+0xd0/0xe0 [1774260.065966] ret_from_fork+0x10/0x20 [1774323.086033] rcu: INFO: rcu_sched self-detected stall on CPU [1774323.091808] rcu: 0-....: (8403 ticks this GP) idle=915/1/0x4000000000000000 softirq=6031130/6031130 fqs=4088 [1774323.102028] (t=8405 jiffies g=30461577 q=1422) [1774323.102031] Task dump for CPU 0: [1774323.102033] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774323.102040] Call trace: [1774323.102042] dump_backtrace.part.0+0xb4/0xc0 [1774323.102052] show_stack+0x14/0x30 [1774323.102055] sched_show_task+0x130/0x160 [1774323.102060] dump_cpu_task+0x40/0x4c [1774323.102065] rcu_dump_cpu_stacks+0xec/0x130 [1774323.102068] rcu_sched_clock_irq+0x8f8/0xaa0 [1774323.102073] update_process_times+0x98/0x180 [1774323.102076] tick_sched_timer+0x54/0xd0 [1774323.102080] __hrtimer_run_queues+0x134/0x2d0 [1774323.102084] hrtimer_interrupt+0x110/0x2c0 [1774323.102087] arch_timer_handler_phys+0x28/0x40 [1774323.102092] handle_percpu_devid_irq+0x84/0x1c0 [1774323.102097] generic_handle_domain_irq+0x28/0x40 [1774323.102100] gic_handle_irq+0x58/0x80 [1774323.102105] call_on_irq_stack+0x2c/0x3c [1774323.102109] do_interrupt_handler+0x78/0x84 [1774323.102112] el1_interrupt+0x30/0x50 [1774323.102118] el1h_64_irq_handler+0x14/0x20 [1774323.102120] el1h_64_irq+0x64/0x68 [1774323.102123] folio_unlock+0x8/0x40 [1774323.102127] f2fs_get_lock_data_page+0xf4/0x260 [1774323.102131] move_data_page+0x34/0x530 [1774323.102135] do_garbage_collect+0xc54/0x12e0 [1774323.102138] f2fs_gc+0x3b4/0x800 [1774323.102141] gc_thread_func+0x4c8/0x640 [1774323.102144] kthread+0xd0/0xe0 [1774323.102147] ret_from_fork+0x10/0x20 [1774386.122242] rcu: INFO: rcu_sched self-detected stall on CPU [1774386.128015] rcu: 0-....: (14707 ticks this GP) idle=915/1/0x4000000000000000 softirq=6031130/6031130 fqs=7133 [1774386.138322] (t=14709 jiffies g=30461577 q=1895) [1774386.138325] Task dump for CPU 0: [1774386.138327] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774386.138334] Call trace: [1774386.138335] dump_backtrace.part.0+0xb4/0xc0 [1774386.138345] show_stack+0x14/0x30 [1774386.138349] sched_show_task+0x130/0x160 [1774386.138354] dump_cpu_task+0x40/0x4c [1774386.138358] rcu_dump_cpu_stacks+0xec/0x130 [1774386.138361] rcu_sched_clock_irq+0x8f8/0xaa0 [1774386.138365] update_process_times+0x98/0x180 [1774386.138369] tick_sched_timer+0x54/0xd0 [1774386.138373] __hrtimer_run_queues+0x134/0x2d0 [1774386.138376] hrtimer_interrupt+0x110/0x2c0 [1774386.138380] arch_timer_handler_phys+0x28/0x40 [1774386.138384] handle_percpu_devid_irq+0x84/0x1c0 [1774386.138389] generic_handle_domain_irq+0x28/0x40 [1774386.138393] gic_handle_irq+0x58/0x80 [1774386.138397] call_on_irq_stack+0x2c/0x3c [1774386.138401] do_interrupt_handler+0x78/0x84 [1774386.138405] el1_interrupt+0x30/0x50 [1774386.138410] el1h_64_irq_handler+0x14/0x20 [1774386.138413] el1h_64_irq+0x64/0x68 [1774386.138416] f2fs_lookup_extent_cache+0x18c/0x310 [1774386.138420] f2fs_get_read_data_page+0x54/0x480 [1774386.138424] f2fs_get_lock_data_page+0x3c/0x260 [1774386.138427] move_data_page+0x34/0x530 [1774386.138431] do_garbage_collect+0xc54/0x12e0 [1774386.138434] f2fs_gc+0x3b4/0x800 [1774386.138437] gc_thread_func+0x4c8/0x640 [1774386.138440] kthread+0xd0/0xe0 [1774386.138443] ret_from_fork+0x10/0x20 [1774449.158452] rcu: INFO: rcu_sched self-detected stall on CPU [1774449.164226] rcu: 0-....: (21011 ticks this GP) idle=915/1/0x4000000000000000 softirq=6031130/6031130 fqs=10163 [1774449.174619] (t=21013 jiffies g=30461577 q=2392) [1774449.174622] Task dump for CPU 0: [1774449.174624] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774449.174630] Call trace: [1774449.174632] dump_backtrace.part.0+0xb4/0xc0 [1774449.174641] show_stack+0x14/0x30 [1774449.174645] sched_show_task+0x130/0x160 [1774449.174650] dump_cpu_task+0x40/0x4c [1774449.174654] rcu_dump_cpu_stacks+0xec/0x130 [1774449.174657] rcu_sched_clock_irq+0x8f8/0xaa0 [1774449.174661] update_process_times+0x98/0x180 [1774449.174664] tick_sched_timer+0x54/0xd0 [1774449.174668] __hrtimer_run_queues+0x134/0x2d0 [1774449.174672] hrtimer_interrupt+0x110/0x2c0 [1774449.174675] arch_timer_handler_phys+0x28/0x40 [1774449.174680] handle_percpu_devid_irq+0x84/0x1c0 [1774449.174685] generic_handle_domain_irq+0x28/0x40 [1774449.174688] gic_handle_irq+0x58/0x80 [1774449.174693] call_on_irq_stack+0x2c/0x3c [1774449.174696] do_interrupt_handler+0x78/0x84 [1774449.174700] el1_interrupt+0x30/0x50 [1774449.174705] el1h_64_irq_handler+0x14/0x20 [1774449.174708] el1h_64_irq+0x64/0x68 [1774449.174711] __filemap_get_folio+0x20/0x3b0 [1774449.174715] pagecache_get_page+0x18/0x70 [1774449.174720] grab_cache_page_write_begin+0x20/0x30 [1774449.174725] f2fs_get_read_data_page+0x3c/0x480 [1774449.174729] f2fs_get_lock_data_page+0x3c/0x260 [1774449.174732] move_data_page+0x34/0x530 [1774449.174735] do_garbage_collect+0xc54/0x12e0 [1774449.174738] f2fs_gc+0x3b4/0x800 [1774449.174741] gc_thread_func+0x4c8/0x640 [1774449.174744] kthread+0xd0/0xe0 [1774449.174748] ret_from_fork+0x10/0x20 [1774512.194663] rcu: INFO: rcu_sched self-detected stall on CPU [1774512.200436] rcu: 0-....: (27315 ticks this GP) idle=915/1/0x4000000000000000 softirq=6031130/6031130 fqs=13122 [1774512.210828] (t=27317 jiffies g=30461577 q=2781) [1774512.210831] Task dump for CPU 0: [1774512.210834] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774512.210841] Call trace: [1774512.210842] dump_backtrace.part.0+0xb4/0xc0 [1774512.210852] show_stack+0x14/0x30 [1774512.210856] sched_show_task+0x130/0x160 [1774512.210860] dump_cpu_task+0x40/0x4c [1774512.210864] rcu_dump_cpu_stacks+0xec/0x130 [1774512.210868] rcu_sched_clock_irq+0x8f8/0xaa0 [1774512.210872] update_process_times+0x98/0x180 [1774512.210875] tick_sched_timer+0x54/0xd0 [1774512.210879] __hrtimer_run_queues+0x134/0x2d0 [1774512.210882] hrtimer_interrupt+0x110/0x2c0 [1774512.210886] arch_timer_handler_phys+0x28/0x40 [1774512.210891] handle_percpu_devid_irq+0x84/0x1c0 [1774512.210896] generic_handle_domain_irq+0x28/0x40 [1774512.210899] gic_handle_irq+0x58/0x80 [1774512.210904] call_on_irq_stack+0x2c/0x3c [1774512.210907] do_interrupt_handler+0x78/0x84 [1774512.210911] el1_interrupt+0x30/0x50 [1774512.210916] el1h_64_irq_handler+0x14/0x20 [1774512.210918] el1h_64_irq+0x64/0x68 [1774512.210921] __filemap_get_folio+0x8c/0x3b0 [1774512.210925] pagecache_get_page+0x18/0x70 [1774512.210930] grab_cache_page_write_begin+0x20/0x30 [1774512.210935] f2fs_get_read_data_page+0x3c/0x480 [1774512.210939] f2fs_get_lock_data_page+0x3c/0x260 [1774512.210942] move_data_page+0x34/0x530 [1774512.210945] do_garbage_collect+0xc54/0x12e0 [1774512.210948] f2fs_gc+0x3b4/0x800 [1774512.210951] gc_thread_func+0x4c8/0x640 [1774512.210954] kthread+0xd0/0xe0 [1774512.210957] ret_from_fork+0x10/0x20 [1774560.785116] INFO: task f2fs_ckpt-179:1:401 blocked for more than 404 seconds. [1774560.792572] Not tainted 5.18.5-matteo #107 [1774560.797401] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [1774560.805445] task:f2fs_ckpt-179:1 state:D stack: 0 pid: 401 ppid: 2 flags:0x00000008 [1774560.805453] Call trace: [1774560.805456] __switch_to+0xc0/0x100 [1774560.805465] __schedule+0x258/0x620 [1774560.805469] schedule+0x44/0xb0 [1774560.805472] rwsem_down_write_slowpath+0x314/0x5a0 [1774560.805478] down_write+0x44/0x50 [1774560.805482] __checkpoint_and_complete_reqs+0x6c/0x1c0 [1774560.805487] issue_checkpoint_thread+0x34/0xc0 [1774560.805490] kthread+0xd0/0xe0 [1774560.805494] ret_from_fork+0x10/0x20 [1774560.805504] INFO: task NetworkManager:1061 blocked for more than 404 seconds. [1774560.812854] Not tainted 5.18.5-matteo #107 [1774560.817667] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [1774560.825708] task:NetworkManager state:D stack: 0 pid: 1061 ppid: 1 flags:0x00000000 [1774560.825714] Call trace: [1774560.825716] __switch_to+0xc0/0x100 [1774560.825720] __schedule+0x258/0x620 [1774560.825723] schedule+0x44/0xb0 [1774560.825726] schedule_timeout+0x114/0x150 [1774560.825730] __wait_for_common+0xc8/0x200 [1774560.825733] wait_for_completion+0x1c/0x30 [1774560.825736] f2fs_issue_checkpoint+0xd0/0x190 [1774560.825740] f2fs_sync_fs+0x48/0xd0 [1774560.825745] f2fs_do_sync_file+0x178/0x8a0 [1774560.825749] f2fs_sync_file+0x28/0x40 [1774560.825753] vfs_fsync_range+0x30/0x80 [1774560.825758] do_fsync+0x38/0x80 [1774560.825762] __arm64_sys_fsync+0x14/0x20 [1774560.825767] invoke_syscall.constprop.0+0x4c/0xe0 [1774560.825771] do_el0_svc+0x40/0xd0 [1774560.825775] el0_svc+0x14/0x50 [1774560.825779] el0t_64_sync_handler+0xa8/0xb0 [1774560.825782] el0t_64_sync+0x148/0x14c [1774560.825803] INFO: task kworker/u8:4:335638 blocked for more than 404 seconds. [1774560.833149] Not tainted 5.18.5-matteo #107 [1774560.837962] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [1774560.846002] task:kworker/u8:4 state:D stack: 0 pid:335638 ppid: 2 flags:0x00000008 [1774560.846009] Workqueue: writeback wb_workfn (flush-179:128) [1774560.846016] Call trace: [1774560.846017] __switch_to+0xc0/0x100 [1774560.846021] __schedule+0x258/0x620 [1774560.846024] schedule+0x44/0xb0 [1774560.846027] schedule_timeout+0x114/0x150 [1774560.846031] __wait_for_common+0xc8/0x200 [1774560.846034] wait_for_completion+0x1c/0x30 [1774560.846037] f2fs_issue_checkpoint+0xd0/0x190 [1774560.846040] f2fs_sync_fs+0x48/0xd0 [1774560.846044] f2fs_balance_fs_bg+0x114/0x2b0 [1774560.846048] f2fs_write_node_pages+0x38/0x1f0 [1774560.846053] do_writepages+0x68/0x1e0 [1774560.846058] __writeback_single_inode+0x3c/0x3c0 [1774560.846062] writeback_sb_inodes+0x230/0x520 [1774560.846065] __writeback_inodes_wb+0x50/0x130 [1774560.846069] wb_writeback+0x244/0x340 [1774560.846073] wb_workfn+0x308/0x560 [1774560.846077] process_one_work+0x1dc/0x420 [1774560.846081] worker_thread+0x170/0x4c0 [1774560.846084] kthread+0xd0/0xe0 [1774560.846086] ret_from_fork+0x10/0x20 [1774623.467979] rcu: INFO: rcu_sched self-detected stall on CPU [1774623.473755] rcu: 0-....: (2099 ticks this GP) idle=643/1/0x4000000000000000 softirq=6031246/6031247 fqs=1028 [1774623.483976] (t=2101 jiffies g=30461613 q=633) [1774623.483979] Task dump for CPU 0: [1774623.483982] task:f2fs_gc-179:130 state:R running task stack: 0 pid: 400 ppid: 2 flags:0x0000000a [1774623.483989] Call trace: [1774623.483991] dump_backtrace.part.0+0xb4/0xc0 [1774623.484003] show_stack+0x14/0x30 [1774623.484007] sched_show_task+0x130/0x160 [1774623.484013] dump_cpu_task+0x40/0x4c [1774623.484018] rcu_dump_cpu_stacks+0xec/0x130 [1774623.484021] rcu_sched_clock_irq+0x8f8/0xaa0 [1774623.484025] update_process_times+0x98/0x180 [1774623.484028] tick_sched_timer+0x54/0xd0 [1774623.484033] __hrtimer_run_queues+0x134/0x2d0 [1774623.484036] hrtimer_interrupt+0x110/0x2c0 [1774623.484040] arch_timer_handler_phys+0x28/0x40 [1774623.484045] handle_percpu_devid_irq+0x84/0x1c0 [1774623.484050] generic_handle_domain_irq+0x28/0x40 [1774623.484054] gic_handle_irq+0x58/0x80 [1774623.484059] call_on_irq_stack+0x2c/0x3c [1774623.484062] do_interrupt_handler+0x78/0x84 [1774623.484066] el1_interrupt+0x30/0x50 [1774623.484071] el1h_64_irq_handler+0x14/0x20 [1774623.484074] el1h_64_irq+0x64/0x68 [1774623.484077] folio_unlock+0x18/0x40 [1774623.484081] f2fs_get_lock_data_page+0xf4/0x260 [1774623.484085] move_data_page+0x34/0x530 [1774623.484089] do_garbage_collect+0xc54/0x12e0 [1774623.484092] f2fs_gc+0x3b4/0x800 [1774623.484095] gc_thread_func+0x4c8/0x640 [1774623.484098] kthread+0xd0/0xe0 [1774623.484101] ret_from_fork+0x10/0x20
root@macchiatobin:~# uname -a Linux macchiatobin 5.18.5-matteo #107 SMP Fri Jun 17 17:58:26 CEST 2022 aarch64 GNU/Linux
-- per aspera ad upstream