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

Chris Murphy
2021-12-03T18:06:18Z

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