Re: Linux RAID with btrfs stuck and consume 100 % CPU

[Vojtech Myslivec <vojtech@xmyslivec.cz>]

[-- Attachment #1: Type: text/plain, Size: 2898 bytes --]

Hi again,

On 20. 08. 20 0:58, Chris Murphy wrote:
> The problem here I think is that /proc/pid/stack is empty. You might
> have to hammer on it a bunch of times to get a stack. I can't tell if
> the sysrq+w is enough information to conclusively tell if this is
> strictly an md problem or if there's something else going on.
> 
> But I do see in the sysrq+w evidence of a Btrfs snapshot happening,
> which will result in a flush of the file system. Since the mdadm raid
> journal is on two SSDs which should be fast enough to accept the
> metadata changes before actually doing the flush.

We were lucky to dump some stacks yesterday, when the issue happened again.


In `sysrq.log`, there is an dmesg/kern.log output of

    echo w > /proc/sysrq-trigger

command, when `md1_raid6` started to consume 100% CPU and all
btrfs-snapshot-related commands stuck in the *disk sleep* state.

We had issued sysrq+w command several times and I have included all
unique tasks appeared there.


In `stack_md1_reclaim.txt`, `stack_btrfs-transacti.txt` and
`stack_btrfs*.txt`, there are outputs of

    cat /proc/<pid>/stack

of given processes during the same time. The output is still the same
when we issued this command several times.


In `stack_md1_raid6-[0-3].txt`, there are outputs of the same command
where pid is `md1_raid6` process id. We issued that several time and the
output differs a bit sometimes. If I get it right, differs only in
instruction offset of given functions. I include all the combinations we
encounter for case it matters.

We have dumped stack of this process in a while-true cycle just after we
perform a manual "unstuck" workaround (I described this action in the
first e-mail). I can send it to the mailing list as well if needed.



I hope these outputs include what you, Song, requested on July the 30th
(and I hope it's ok to continue in this thread)

On 30. 07. 20 8:45, Song Liu wrote:
>> On Jul 29, 2020, at 2:06 PM, Guoqing Jiang wrote:
>>
>> Hi,
>>
>> On 7/22/20 10:47 PM, Vojtech Myslivec wrote:
>>> 1. What should be the cause of this problem?
>>
>> Just a quick glance based on the stacks which you attached, I guess
>> it could be a deadlock issue of raid5 cache super write.
>>
>> Maybe the commit 8e018c21da3f ("raid5-cache: fix a deadlock in
>> superblock write") didn't fix the problem completely.  Cc Song.
>>
>> And I am curious why md thread is not waked if mddev_trylock fails,
>> you can give it a try but I can't promise it helps ...
>
> Thanks Guoqing!
>
> I am not sure whether we hit the mddev_trylock() failure. Looks like
> the md1_raid6 thread is already running at 100%.
>
> A few questions:
>
> 1. I see wbt_wait in the stack trace. Are we using write back
>    throttling here?
> 2. Could you please get the /proc/<pid>/stack for <pid> of md1_raid6?
>    We may want to sample it multiple times.
>
> Thanks,
> Song


Thanks,
Vojtech and Michal

[-- Attachment #2: stack_md1_raid6-0.txt --]
[-- Type: text/plain, Size: 266 bytes --]

[<0>] ops_run_io+0x40/0xd80 [raid456]
[<0>] handle_stripe+0xc32/0x2230 [raid456]
[<0>] handle_active_stripes.isra.71+0x3b8/0x590 [raid456]
[<0>] raid5d+0x392/0x5b0 [raid456]
[<0>] md_thread+0x94/0x150 [md_mod]
[<0>] kthread+0x112/0x130
[<0>] ret_from_fork+0x22/0x40

[-- Attachment #3: stack_md1_raid6-1.txt --]
[-- Type: text/plain, Size: 266 bytes --]

[<0>] ops_run_io+0x40/0xd80 [raid456]
[<0>] handle_stripe+0x136/0x2230 [raid456]
[<0>] handle_active_stripes.isra.71+0x3b8/0x590 [raid456]
[<0>] raid5d+0x392/0x5b0 [raid456]
[<0>] md_thread+0x94/0x150 [md_mod]
[<0>] kthread+0x112/0x130
[<0>] ret_from_fork+0x22/0x40

[-- Attachment #4: stack_md1_raid6-2.txt --]
[-- Type: text/plain, Size: 266 bytes --]

[<0>] ops_run_io+0x40/0xd80 [raid456]
[<0>] handle_stripe+0xc32/0x2230 [raid456]
[<0>] handle_active_stripes.isra.71+0x485/0x590 [raid456]
[<0>] raid5d+0x392/0x5b0 [raid456]
[<0>] md_thread+0x94/0x150 [md_mod]
[<0>] kthread+0x112/0x130
[<0>] ret_from_fork+0x22/0x40

[-- Attachment #5: stack_md1_raid6-3.txt --]
[-- Type: text/plain, Size: 266 bytes --]

[<0>] ops_run_io+0x40/0xd80 [raid456]
[<0>] handle_stripe+0x136/0x2230 [raid456]
[<0>] handle_active_stripes.isra.71+0x420/0x590 [raid456]
[<0>] raid5d+0x392/0x5b0 [raid456]
[<0>] md_thread+0x94/0x150 [md_mod]
[<0>] kthread+0x112/0x130
[<0>] ret_from_fork+0x22/0x40

[-- Attachment #6: stack_md1_reclaim.txt --]
[-- Type: text/plain, Size: 375 bytes --]

[<0>] rq_qos_wait+0xfa/0x170
[<0>] wbt_wait+0x98/0xe0
[<0>] __rq_qos_throttle+0x23/0x30
[<0>] blk_mq_make_request+0x12a/0x5d0
[<0>] generic_make_request+0xcf/0x310
[<0>] submit_bio+0x42/0x1c0
[<0>] md_update_sb.part.71+0x3c0/0x8f0 [md_mod]
[<0>] r5l_do_reclaim+0x32a/0x3b0 [raid456]
[<0>] md_thread+0x94/0x150 [md_mod]
[<0>] kthread+0x112/0x130
[<0>] ret_from_fork+0x22/0x40

[-- Attachment #7: stack_btrfs-transacti.txt --]
[-- Type: text/plain, Size: 395 bytes --]

[<0>] wait_on_page_bit+0x15c/0x230
[<0>] __filemap_fdatawait_range+0x89/0xf0
[<0>] filemap_fdatawait_range+0xe/0x20
[<0>] __btrfs_wait_marked_extents.isra.19+0xc2/0x100 [btrfs]
[<0>] btrfs_write_and_wait_transaction.isra.23+0x67/0xd0 [btrfs]
[<0>] btrfs_commit_transaction+0x755/0xa50 [btrfs]
[<0>] transaction_kthread+0x144/0x170 [btrfs]
[<0>] kthread+0x112/0x130
[<0>] ret_from_fork+0x22/0x40

[-- Attachment #8: stack_btrfs32445.txt --]
[-- Type: text/plain, Size: 165 bytes --]

[<0>] do_wait+0x1c7/0x230
[<0>] kernel_wait4+0xa6/0x140
[<0>] __do_sys_wait4+0x83/0x90
[<0>] do_syscall_64+0x52/0x170
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

[-- Attachment #9: stack_btrfs32277.txt --]
[-- Type: text/plain, Size: 319 bytes --]

[<0>] rwsem_down_write_slowpath+0x329/0x4e0
[<0>] btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[<0>] btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[<0>] btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[<0>] ksys_ioctl+0x86/0xc0
[<0>] __x64_sys_ioctl+0x16/0x20
[<0>] do_syscall_64+0x52/0x170
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

[-- Attachment #10: stack_btrfs31357.txt --]
[-- Type: text/plain, Size: 319 bytes --]

[<0>] rwsem_down_write_slowpath+0x329/0x4e0
[<0>] btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[<0>] btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[<0>] btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[<0>] ksys_ioctl+0x86/0xc0
[<0>] __x64_sys_ioctl+0x16/0x20
[<0>] do_syscall_64+0x52/0x170
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

[-- Attachment #11: stack_btrfs31094.txt --]
[-- Type: text/plain, Size: 319 bytes --]

[<0>] rwsem_down_write_slowpath+0x329/0x4e0
[<0>] btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[<0>] btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[<0>] btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[<0>] ksys_ioctl+0x86/0xc0
[<0>] __x64_sys_ioctl+0x16/0x20
[<0>] do_syscall_64+0x52/0x170
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

[-- Attachment #12: stack_btrfs30168.txt --]
[-- Type: text/plain, Size: 411 bytes --]

[<0>] wait_for_commit+0x58/0x80 [btrfs]
[<0>] btrfs_commit_transaction+0x169/0xa50 [btrfs]
[<0>] btrfs_mksubvol+0x2e9/0x450 [btrfs]
[<0>] __btrfs_ioctl_snap_create+0x167/0x170 [btrfs]
[<0>] btrfs_ioctl_snap_create_v2+0xc5/0xe0 [btrfs]
[<0>] btrfs_ioctl+0xf61/0x2ef0 [btrfs]
[<0>] ksys_ioctl+0x86/0xc0
[<0>] __x64_sys_ioctl+0x16/0x20
[<0>] do_syscall_64+0x52/0x170
[<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9

[-- Attachment #13: sysrq.log --]
[-- Type: text/x-log, Size: 20285 bytes --]

[Tue Aug 25 16:41:16 2020] sysrq: Show Blocked State
[Tue Aug 25 16:41:16 2020]   task                        PC stack   pid father

[Tue Aug 25 16:41:16 2020] md1_reclaim     D    0   806      2 0x80004000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  ? __switch_to_asm+0x34/0x70
[Tue Aug 25 16:41:16 2020]  ? __switch_to_asm+0x34/0x70
[Tue Aug 25 16:41:16 2020]  ? wbt_exit+0x30/0x30
[Tue Aug 25 16:41:16 2020]  ? __wbt_done+0x30/0x30
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  io_schedule+0x12/0x40
[Tue Aug 25 16:41:16 2020]  rq_qos_wait+0xfa/0x170
[Tue Aug 25 16:41:16 2020]  ? __switch_to_asm+0x34/0x70
[Tue Aug 25 16:41:16 2020]  ? karma_partition+0x1e0/0x1e0
[Tue Aug 25 16:41:16 2020]  ? wbt_exit+0x30/0x30
[Tue Aug 25 16:41:16 2020]  wbt_wait+0x98/0xe0
[Tue Aug 25 16:41:16 2020]  __rq_qos_throttle+0x23/0x30
[Tue Aug 25 16:41:16 2020]  blk_mq_make_request+0x12a/0x5d0
[Tue Aug 25 16:41:16 2020]  generic_make_request+0xcf/0x310
[Tue Aug 25 16:41:16 2020]  submit_bio+0x42/0x1c0
[Tue Aug 25 16:41:16 2020]  ? md_super_write.part.70+0x98/0x120 [md_mod]
[Tue Aug 25 16:41:16 2020]  md_update_sb.part.71+0x3c0/0x8f0 [md_mod]
[Tue Aug 25 16:41:16 2020]  r5l_do_reclaim+0x32a/0x3b0 [raid456]
[Tue Aug 25 16:41:16 2020]  ? schedule_timeout+0x162/0x340
[Tue Aug 25 16:41:16 2020]  ? prepare_to_wait_event+0xb6/0x140
[Tue Aug 25 16:41:16 2020]  ? md_register_thread+0xd0/0xd0 [md_mod]
[Tue Aug 25 16:41:16 2020]  md_thread+0x94/0x150 [md_mod]
[Tue Aug 25 16:41:16 2020]  ? finish_wait+0x80/0x80
[Tue Aug 25 16:41:16 2020]  kthread+0x112/0x130
[Tue Aug 25 16:41:16 2020]  ? kthread_park+0x80/0x80
[Tue Aug 25 16:41:16 2020]  ret_from_fork+0x22/0x40

[Tue Aug 25 16:41:16 2020] btrfs-transacti D    0   893      2 0x80004000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  io_schedule+0x12/0x40
[Tue Aug 25 16:41:16 2020]  wait_on_page_bit+0x15c/0x230
[Tue Aug 25 16:41:16 2020]  ? file_fdatawait_range+0x20/0x20
[Tue Aug 25 16:41:16 2020]  __filemap_fdatawait_range+0x89/0xf0
[Tue Aug 25 16:41:16 2020]  filemap_fdatawait_range+0xe/0x20
[Tue Aug 25 16:41:16 2020]  __btrfs_wait_marked_extents.isra.19+0xc2/0x100 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_write_and_wait_transaction.isra.23+0x67/0xd0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_commit_transaction+0x755/0xa50 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? start_transaction+0xd5/0x540 [btrfs]
[Tue Aug 25 16:41:16 2020]  transaction_kthread+0x144/0x170 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? btrfs_cleanup_transaction+0x590/0x590 [btrfs]
[Tue Aug 25 16:41:16 2020]  kthread+0x112/0x130
[Tue Aug 25 16:41:16 2020]  ? kthread_park+0x80/0x80
[Tue Aug 25 16:41:16 2020]  ret_from_fork+0x22/0x40

[Tue Aug 25 16:41:16 2020] btrfs           D    0 30168  30162 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  wait_for_commit+0x58/0x80 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? finish_wait+0x80/0x80
[Tue Aug 25 16:41:16 2020]  btrfs_commit_transaction+0x169/0xa50 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? btrfs_record_root_in_trans+0x56/0x60 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? start_transaction+0xd5/0x540 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_mksubvol+0x2e9/0x450 [btrfs]
[Tue Aug 25 16:41:16 2020]  __btrfs_ioctl_snap_create+0x167/0x170 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_create_v2+0xc5/0xe0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xf61/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f273259b427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffe48178418 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f273259b427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffe48178458 RSI: 0000000050009417 RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 00005637741dc260 R08: 0000000000000008 R09: 0000000035322d38
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000206 R12: 00005637741dc2b0
[Tue Aug 25 16:41:16 2020] R13: 00005637741dc2b0 R14: 0000000000000003 R15: 0000000000000004

[Tue Aug 25 16:41:16 2020] btrfs           D    0 31094  31088 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7ff3fa6a3427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffe92fc4058 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007ff3fa6a3427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffe92fc4090 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 000055b4e34ab2ca R09: 00007ff3fa72de80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000202 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffe92fc4090 R15: 000055b4e34ab2ca

[Tue Aug 25 16:41:16 2020] btrfs           D    0 31357  31351 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f9c14290427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007fff4c9f8ed8 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f9c14290427
[Tue Aug 25 16:41:16 2020] RDX: 00007fff4c9f8f10 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 000055ea83aa82c8 R09: 00007f9c1431ae80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000206 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007fff4c9f8f10 R15: 000055ea83aa82c8

[Tue Aug 25 16:41:16 2020] btrfs           D    0 32277  32271 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f0b35736427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007fff96ad7c48 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f0b35736427
[Tue Aug 25 16:41:16 2020] RDX: 00007fff96ad7c80 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 000055e2598b62c8 R09: 00007f0b357c0e80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000206 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007fff96ad7c80 R15: 000055e2598b62c8

[Tue Aug 25 16:41:16 2020] btrfs           D    0 32451  32445 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f0517ff8427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffc862d3c98 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f0517ff8427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffc862d3cd0 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 0000555d6d7872ca R09: 00007f0518082e80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000202 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffc862d3cd0 R15: 0000555d6d7872ca

[Tue Aug 25 16:41:16 2020] btrfs           D    0   596    590 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7ffa2b954427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffc88d95748 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007ffa2b954427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffc88d95780 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 0000558d2b97f2c8 R09: 00007ffa2b9dee80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000206 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffc88d95780 R15: 0000558d2b97f2c8

[Tue Aug 25 16:41:16 2020] btrfs           D    0   792    786 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f74f06d2427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007fffbb878738 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f74f06d2427
[Tue Aug 25 16:41:16 2020] RDX: 00007fffbb878770 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 000055f062e442c7 R09: 00007f74f075ce80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000202 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007fffbb878770 R15: 000055f062e442c7

[Tue Aug 25 16:41:16 2020] btrfs           D    0   833    827 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f65fee13427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffc45aa0508 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f65fee13427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffc45aa0540 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 000055d819de32c6 R09: 00007f65fee9de80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000202 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffc45aa0540 R15: 000055d819de32c6

[Tue Aug 25 16:41:16 2020] btrfs           D    0 10542  10515 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f48b0d4a427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffdf1ab4fd8 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f48b0d4a427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffdf1ab5010 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 00005631cce8a2c8 R09: 00007f48b0dd4e80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000206 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffdf1ab5010 R15: 00005631cce8a2c8

[Tue Aug 25 16:41:16 2020] btrfs           D    0  1667   1661 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f759eff1427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffcc4fb06c8 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f759eff1427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffcc4fb0700 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 00005584f7c5a2ca R09: 00007f759f07be80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000202 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffcc4fb0700 R15: 00005584f7c5a2ca

[Tue Aug 25 16:41:16 2020] btrfs           D    0  2473   2467 0x00000000
[Tue Aug 25 16:41:16 2020] Call Trace:
[Tue Aug 25 16:41:16 2020]  __schedule+0x2dd/0x710
[Tue Aug 25 16:41:16 2020]  schedule+0x40/0xb0
[Tue Aug 25 16:41:16 2020]  rwsem_down_write_slowpath+0x329/0x4e0
[Tue Aug 25 16:41:16 2020]  ? kmem_cache_alloc_trace+0x15e/0x230
[Tue Aug 25 16:41:16 2020]  btrfs_delete_subvolume+0x90/0x5f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? d_lookup+0x25/0x50
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl_snap_destroy+0x5b3/0x6f0 [btrfs]
[Tue Aug 25 16:41:16 2020]  btrfs_ioctl+0xa5f/0x2ef0 [btrfs]
[Tue Aug 25 16:41:16 2020]  ? ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  ksys_ioctl+0x86/0xc0
[Tue Aug 25 16:41:16 2020]  __x64_sys_ioctl+0x16/0x20
[Tue Aug 25 16:41:16 2020]  do_syscall_64+0x52/0x170
[Tue Aug 25 16:41:16 2020]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Tue Aug 25 16:41:16 2020] RIP: 0033:0x7f278ea1a427
[Tue Aug 25 16:41:16 2020] Code: Bad RIP value.
[Tue Aug 25 16:41:16 2020] RSP: 002b:00007ffd784d5318 EFLAGS: 00000206 ORIG_RAX: 0000000000000010
[Tue Aug 25 16:41:16 2020] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f278ea1a427
[Tue Aug 25 16:41:16 2020] RDX: 00007ffd784d5350 RSI: 000000005000940f RDI: 0000000000000003
[Tue Aug 25 16:41:16 2020] RBP: 0000000000000000 R08: 000055b8f4d412de R09: 00007f278eaa4e80
[Tue Aug 25 16:41:16 2020] R10: fffffffffffffb66 R11: 0000000000000206 R12: 0000000000000003
[Tue Aug 25 16:41:16 2020] R13: 0000000000000003 R14: 00007ffd784d5350 R15: 000055b8f4d412de