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

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

[Tomasz Chmielewski]

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

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

[Johannes Thumshirn]

On 03/12/2021 00:23, Tomasz Chmielewski wrote:
> 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.
> 

Hi,

We're currently working on a similar hang with btrfs on zoned 
block devices. Which brings me to the question, are you seeing this issues
on a zoned device, like an SMR drive, or on a regular device?

Thanks,
	Johannes

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

[Tomasz Chmielewski]

On 2021-12-03 09:09, Johannes Thumshirn wrote:
> On 03/12/2021 00:23, Tomasz Chmielewski wrote:
>> 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.
>> 
> 
> Hi,
> 
> We're currently working on a similar hang with btrfs on zoned
> block devices. Which brings me to the question, are you seeing this 
> issues
> on a zoned device, like an SMR drive, or on a regular device?

It's a regular HDD.


Tomasz

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

[Chris Murphy]

I just did a Fedora Rawhide installation in a VM which has kernel
5.16.0-0.rc3.20211201git58e1100fdc59.25.fc36.x86_64

The installation depends on loop mounted squashfs image as the source,
and rsync as the copy mechanism. In top I see quite a few high CPU
btrfs-delalloc as well, more than expected. I'll redo the installation
and see if there were any deadlock warnings or anything like that, and
if not I'll grab sysrq+t during the heavier btrfs CPU usage.

The guest uses virtio drives; and the host uses NVMe.

--
Chris Murphy

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

[Chris Murphy]

On Fri, Dec 3, 2021 at 12:23 PM Chris Murphy <lists@colorremedies.com> wrote:
>
> I just did a Fedora Rawhide installation in a VM which has kernel
> 5.16.0-0.rc3.20211201git58e1100fdc59.25.fc36.x86_64
>
> The installation depends on loop mounted squashfs image as the source,
> and rsync as the copy mechanism. In top I see quite a few high CPU
> btrfs-delalloc as well, more than expected. I'll redo the installation
> and see if there were any deadlock warnings or anything like that, and
> if not I'll grab sysrq+t during the heavier btrfs CPU usage.
>
> The guest uses virtio drives; and the host uses NVMe.

On second glance, it's mostly btrfs-endio-write that's hitting 50%+
CPU on occasion, but no kernel warnings. sysrq+w caught this:

[ 1864.688477] EXT4-fs (vda2): mounted filesystem with ordered data
mode. Opts: (null). Quota mode: none.
[ 2002.412681] sysrq: Show Blocked State
[ 2002.412939] task:rsync           state:D stack:12856 pid: 3360
ppid:  3358 flags:0x00004000
[ 2002.412957] Call Trace:
[ 2002.412960]  <TASK>
[ 2002.412968]  __schedule+0x3f8/0x1500
[ 2002.412976]  ? lock_is_held_type+0xea/0x140
[ 2002.412984]  ? kvm_sched_clock_read+0x14/0x40
[ 2002.412999]  schedule+0x4e/0xc0
[ 2002.413004]  io_schedule+0x47/0x70
[ 2002.413007]  folio_wait_bit_common+0x14a/0x400
[ 2002.413024]  ? folio_unlock+0x50/0x50
[ 2002.413034]  filemap_get_pages+0x733/0x800
[ 2002.413047]  ? lock_is_held_type+0xea/0x140
[ 2002.413107]  filemap_read+0xb8/0x3f0
[ 2002.413113]  ? sched_clock_cpu+0xb/0xc0
[ 2002.413122]  ? lock_release+0x151/0x460
[ 2002.413133]  ? _copy_to_user+0x63/0x80
[ 2002.413143]  ? lock_is_held_type+0xea/0x140
[ 2002.413156]  new_sync_read+0x108/0x180
[ 2002.413175]  vfs_read+0x125/0x1c0
[ 2002.413184]  ksys_read+0x58/0xd0
[ 2002.413192]  do_syscall_64+0x38/0x90
[ 2002.413199]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 2002.413626] RIP: 0033:0x7f728b42d622
[ 2002.413631] RSP: 002b:00007ffc166df488 EFLAGS: 00000246 ORIG_RAX:
0000000000000000
[ 2002.413636] RAX: ffffffffffffffda RBX: 000055ba4417f9b0 RCX: 00007f728b42d622
[ 2002.413639] RDX: 0000000000012633 RSI: 000055ba44155990 RDI: 0000000000000003
[ 2002.413642] RBP: 0000000000012633 R08: 0000000000000000 R09: 0000000000000000
[ 2002.413644] R10: 0000000004000000 R11: 0000000000000246 R12: 0000000000000000
[ 2002.413647] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000012633
[ 2002.413671]  </TASK>
[ 2163.803113] kworker/dying (7) used greatest stack depth: 11536 bytes left




-- 
Chris Murphy