kworker/u32:5+btrfs-delalloc using 100% CPU

Tomasz Chmielewski
2021-12-02T23:23:31Z

On two of my servers running Linux 5.15.5 I can observe
kworker/u32:5+btrfs-delalloc process using 100% CPU.

The servers receive files with rsync and I suspect that because of that
process using 100% CPU, the speed is very slow, less than 1 MB/s over a
gigabit network.

echo w > /proc/sysrq-trigger produces the following:

[566889.534346] sysrq: Show Blocked State
[566889.534615] task:kworker/u32:1 state:D stack: 0 pid:19498 ppid:
2 flags:0x00004000
[566889.534619] Workqueue: writeback wb_workfn (flush-btrfs-1)
[566889.534625] Call Trace:
[566889.534626] <TASK>
[566889.534628] __schedule+0x21a/0x530
[566889.534631] schedule+0x4e/0xb0
[566889.534632] io_schedule+0x46/0x70
[566889.534633] wait_on_page_bit_common+0x10c/0x3d0
[566889.534636] ? filemap_invalidate_unlock_two+0x40/0x40
[566889.534638] __lock_page+0x4c/0x50
[566889.534640] extent_write_cache_pages+0x377/0x4a0 [btrfs]
[566889.534680] extent_writepages+0x92/0x130 [btrfs]
[566889.534706] btrfs_writepages+0xe/0x10 [btrfs]
[566889.534728] do_writepages+0xda/0x200
[566889.534731] __writeback_single_inode+0x44/0x290
[566889.534733] writeback_sb_inodes+0x223/0x4d0
[566889.534736] __writeback_inodes_wb+0x56/0xf0
[566889.534737] wb_writeback+0x1cc/0x290
[566889.534739] wb_do_writeback+0x1fc/0x280
[566889.534741] wb_workfn+0x77/0x250
[566889.534743] ? psi_task_switch+0x1c8/0x1e0
[566889.534745] ? finish_task_switch.isra.0+0xa7/0x260
[566889.534747] process_one_work+0x229/0x3d0
[566889.534749] worker_thread+0x53/0x420
[566889.534751] kthread+0x11e/0x140
[566889.534753] ? process_one_work+0x3d0/0x3d0
[566889.534755] ? set_kthread_struct+0x50/0x50
[566889.534757] ret_from_fork+0x22/0x30
[566889.534760] </TASK>
[566889.534765] task:btrfs state:D stack: 0 pid:22657 ppid:
22651 flags:0x00000000
[566889.534767] Call Trace:
[566889.534767] <TASK>
[566889.534768] __schedule+0x21a/0x530
[566889.534769] schedule+0x4e/0xb0
[566889.534770] schedule_timeout+0x87/0x140
[566889.534773] ? __bpf_trace_tick_stop+0x10/0x10
[566889.534775] io_schedule_timeout+0x51/0x80
[566889.534776] balance_dirty_pages+0x344/0xe70
[566889.534778] ? __mod_lruvec_state+0x37/0x40
[566889.534781] balance_dirty_pages_ratelimited+0x300/0x3d0
[566889.534783] btrfs_buffered_write+0x59a/0x850 [btrfs]
[566889.534809] btrfs_file_write_iter+0x76/0x130 [btrfs]
[566889.534834] new_sync_write+0x117/0x1a0
[566889.534837] vfs_write+0x1cd/0x260
[566889.534838] __x64_sys_pwrite64+0x92/0xc0
[566889.534840] do_syscall_64+0x5c/0xc0
[566889.534842] ? do_syscall_64+0x69/0xc0
[566889.534844] ? exit_to_user_mode_prepare+0x37/0xb0
[566889.534846] ? syscall_exit_to_user_mode+0x27/0x50
[566889.534848] ? __x64_sys_read+0x19/0x20
[566889.534849] ? do_syscall_64+0x69/0xc0
[566889.534851] ? syscall_exit_to_user_mode+0x27/0x50
[566889.534852] ? do_syscall_64+0x69/0xc0
[566889.534854] ? do_syscall_64+0x69/0xc0
[566889.534856] ? do_syscall_64+0x69/0xc0
[566889.534858] ? do_syscall_64+0x69/0xc0
[566889.534860] ? asm_sysvec_apic_timer_interrupt+0xa/0x20
[566889.534862] entry_SYSCALL_64_after_hwframe+0x44/0xae
[566889.534864] RIP: 0033:0x7fb894d57cda
[566889.534866] RSP: 002b:00007ffc3620af08 EFLAGS: 00000246 ORIG_RAX:
0000000000000012
[566889.534868] RAX: ffffffffffffffda RBX: 000000000000c000 RCX:
00007fb894d57cda
[566889.534869] RDX: 000000000000c000 RSI: 00007ffc3620c095 RDI:
0000000000000006
[566889.534869] RBP: 0000562681ae59e0 R08: 0000000000000000 R09:
0000000000000093
[566889.534870] R10: 000000000fca4000 R11: 0000000000000246 R12:
0000000000000000
[566889.534871] R13: 00007ffc3621e198 R14: 000000000fca4000 R15:
00007ffc3620c095
[566889.534872] </TASK>
[566889.534878] task:rsync state:D stack: 0 pid:43786 ppid:
43782 flags:0x00004000
[566889.534880] Call Trace:
[566889.534880] <TASK>
[566889.534881] __schedule+0x21a/0x530
[566889.534882] schedule+0x4e/0xb0
[566889.534883] schedule_timeout+0x87/0x140
[566889.534885] ? free_extent_state+0x4a/0x90 [btrfs]
[566889.534912] ? __bpf_trace_tick_stop+0x10/0x10
[566889.534913] io_schedule_timeout+0x51/0x80
[566889.534914] balance_dirty_pages+0x344/0xe70
[566889.534916] ? __mod_lruvec_state+0x37/0x40
[566889.534919] balance_dirty_pages_ratelimited+0x300/0x3d0
[566889.534921] btrfs_buffered_write+0x59a/0x850 [btrfs]
[566889.534947] btrfs_file_write_iter+0x76/0x130 [btrfs]
[566889.534972] new_sync_write+0x117/0x1a0
[566889.534974] vfs_write+0x1cd/0x260
[566889.534975] ksys_write+0x67/0xe0
[566889.534977] __x64_sys_write+0x19/0x20
[566889.534978] do_syscall_64+0x5c/0xc0
[566889.534980] ? ksys_read+0xb1/0xe0
[566889.534981] ? exit_to_user_mode_prepare+0x37/0xb0
[566889.534983] ? syscall_exit_to_user_mode+0x27/0x50
[566889.534984] ? __x64_sys_read+0x19/0x20
[566889.534985] ? do_syscall_64+0x69/0xc0
[566889.534987] ? __x64_sys_select+0x21/0x30
[566889.534989] ? do_syscall_64+0x69/0xc0
[566889.534991] ? do_syscall_64+0x69/0xc0
[566889.534993] ? asm_common_interrupt+0x8/0x40
[566889.534995] entry_SYSCALL_64_after_hwframe+0x44/0xae
[566889.534997] RIP: 0033:0x7f12f22e81e7
[566889.534998] RSP: 002b:00007ffd870af8c8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[566889.534999] RAX: ffffffffffffffda RBX: 00005654bb3b64d0 RCX:
00007f12f22e81e7
[566889.535000] RDX: 0000000000040000 RSI: 00005654bb3b64d0 RDI:
0000000000000004
[566889.535001] RBP: 0000000000000004 R08: 00000000000041e1 R09:
00005654bb3a9ff1
[566889.535002] R10: 000000005f0494dd R11: 0000000000000246 R12:
0000000000040000
[566889.535002] R13: 00005654bb3a6480 R14: 0000000000003b71 R15:
00007ffd870af9a8
[566889.535004] </TASK>

Tomasz Chmielewski