Re: storm-of-soft-lockups: spinlocks running on all cores, preventing forward progress (4.14- to 5.0+)

[Zygo Blaxell <ce3g8jdj@umail.furryterror.org>]

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

On Sat, May 18, 2019 at 11:27:46AM +0300, Nikolay Borisov wrote:
> On 18.05.19 г. 7:44 ч., Zygo Blaxell wrote:
> > On Thu, May 16, 2019 at 09:57:01AM +0300, Nikolay Borisov wrote:
> >> On 16.05.19 г. 0:36 ч., Zygo Blaxell wrote:
> >>> "Storm-of-soft-lockups" is a failure mode where btrfs puts all of the
> >>> CPU cores in kernel functions that are unable to make forward progress,
> >>> but also unwilling to release their respective CPU cores.  This is
> >>> usually accompanied by a lot of CPU usage (detectable as either kvm CPU
> >>> usage or just a lot of CPU fan noise) though I don't know if all cores
> >>> are spinning or only some of them.
> >>>
> >>> The kernel console presents a continual stream of "BUG: soft lockup"
> >>> warnings for some days.  None of the call traces change during this time.
> >>> The only way out is to reboot.
> >>>
> >>> You can reproduce this by writing a bunch of data to a filesystem while
> >>> bees is running on all cores.  It takes a few days to occur naturally.
> >>> It can probably be sped up by just doing a bunch of random LOGICAL_INO
> >>> ioctls in a tight loop on each core.
> >>>
> >>> Here's an instance on a 4-CPU VM where CPU#0 is running btrfs-transaction
> >>> (btrfs_try_tree_write_lock) and CPU#1-3 are running the LOGICAL_INO
> >>> ioctl (btrfs_tree_read_lock_atomic):
> >>
> >>
> >> Provide output of all sleeping threads when this occur via
> >>  echo w > /proc/sysrq-trigger.
> > 
> > I fixed my SysRq configuration.  The results are...kind of interesting.
> > I guess the four threads that are running loops on all cores don't count
> > as "blocked"...
> > 
> <snip>
> So you are discards are hung or there is a lost wakeup (which is rather
> unlikely, since this is the block layer). What is the underlying block
> device i.e model/make

Here's another set of soft-lockups, this time with no discard or snapshot.
This one's more interesting--the stuck CPUs are running something that
isn't commit_transaction or LOGICAL_INO.  It's the first time I've
seen that.

First the kernel BUG at fs/btrfs/ctree.c which looks pretty similar to
the last one:

	[20512.078483] kernel BUG at fs/btrfs/ctree.c:1227!
	[20512.079356] invalid opcode: 0000 [#1] SMP PTI
	[20512.080144] CPU: 1 PID: 5662 Comm: crawl_5268 Tainted: G        W         5.0.16-zb64-9b948ea3083a+ #1
	[20512.081397] irq event stamp: 2743290041
	[20512.082303] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
	[20512.082307] RIP: 0010:__tree_mod_log_rewind+0x239/0x240
	[20512.082308] Code: c0 48 89 df 48 89 d6 48 c1 e6 05 48 8d 74 32 65 ba 19 00 00 00 e8 87 02 05 00 e9 88 fe ff ff 49 63 57 2c e9 16 ff ff ff 0f 0b <0f> 0b 0f 1f 44 00 00 0f 1f 44 00 00 55 83 c2 01 48 63 d2 48 89 e5
	[20512.082309] RSP: 0018:ffffa95b80f1b820 EFLAGS: 00010206
	[20512.082311] RAX: ffff9e059aa5a100 RBX: ffff9e04e01496e0 RCX: ffff9e06555dcb81
	[20512.082312] RDX: 00000000000000ce RSI: 000000000000009f RDI: 0000006336410000
	[20512.082312] RBP: ffffa95b80f1b850 R08: ffffa95b80f1b7c8 R09: ffffa95b80f1b7d0
	[20512.082313] R10: 0000000000007b2a R11: 000000000000009f R12: 0000000000000008
	[20512.082314] R13: ffff9e05c9e21c80 R14: 000000000003a09e R15: ffff9e059aa5a100
	[20512.082315] FS:  00007f938be31700(0000) GS:ffff9e06b6000000(0000) knlGS:0000000000000000
	[20512.082316] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
	[20512.082317] CR2: 00007f6dc1f8c519 CR3: 00000001c3d14005 CR4: 00000000001606e0
	[20512.082319] Call Trace:
	[20512.082324]  btrfs_search_old_slot+0xfe/0x800
	[20512.082339]  resolve_indirect_refs+0x1c5/0x910
	[20512.082345]  ? prelim_ref_insert+0x10a/0x320
	[20512.082347]  find_parent_nodes+0x443/0x1340
	[20512.082356]  btrfs_find_all_roots_safe+0xc5/0x140
	[20512.082359]  ? btrfs_inode_flags_to_fsflags+0x90/0x90
	[20512.082361]  iterate_extent_inodes+0x198/0x3e0
	[20512.082367]  iterate_inodes_from_logical+0xa1/0xd0
	[20512.082369]  ? iterate_inodes_from_logical+0xa1/0xd0
	[20512.082370]  ? btrfs_inode_flags_to_fsflags+0x90/0x90
	[20512.082373]  btrfs_ioctl_logical_to_ino+0xf3/0x1a0
	[20512.082376]  btrfs_ioctl+0xcf7/0x2cb0
	[20512.082380]  ? __lock_acquire+0x477/0x1b50
	[20512.082382]  ? kvm_sched_clock_read+0x18/0x30
	[20512.082385]  ? kvm_sched_clock_read+0x18/0x30
	[20512.082387]  ? sched_clock+0x9/0x10
	[20512.082390]  do_vfs_ioctl+0xa6/0x6e0
	[20512.082391]  ? btrfs_ioctl_get_supported_features+0x30/0x30
	[20512.082392]  ? do_vfs_ioctl+0xa6/0x6e0
	[20512.082394]  ? __fget+0x119/0x200
	[20512.082397]  ksys_ioctl+0x75/0x80
	[20512.082399]  __x64_sys_ioctl+0x1a/0x20
	[20512.082402]  do_syscall_64+0x65/0x1a0
	[20512.082405]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[20512.082407] RIP: 0033:0x7f938cf29777
	[20512.082408] Code: 00 00 90 48 8b 05 19 a7 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e9 a6 0c 00 f7 d8 64 89 01 48
	[20512.082409] RSP: 002b:00007f938be2e458 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
	[20512.082410] RAX: ffffffffffffffda RBX: 00007f938be2e780 RCX: 00007f938cf29777
	[20512.082411] RDX: 00007f938be2e788 RSI: 00000000c038943b RDI: 0000000000000003
	[20512.082412] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f938be2e960
	[20512.082412] R10: 000055ad4e628c40 R11: 0000000000000246 R12: 0000000000000003
	[20512.082413] R13: 00007f938be2e788 R14: 00007f938be2e668 R15: 00007f938be2e890
	[20512.082418] Modules linked in: mq_deadline bfq dm_cache_smq dm_cache dm_persistent_data dm_bio_prison dm_bufio crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel ppdev joydev dm_mod snd_pcm aesni_intel aes_x86_64 sr_mod cdrom crypto_simd snd_timer cryptd sg glue_helper snd parport_pc ide_pci_generic parport soundcore piix bochs_drm input_leds ide_core rtc_cmos floppy i2c_piix4 pcspkr psmouse evbug evdev serio_raw qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
	[20512.082464] ---[ end trace 3bcb7e6493f60fe5 ]---
	[20512.082466] RIP: 0010:__tree_mod_log_rewind+0x239/0x240
	[20512.082467] Code: c0 48 89 df 48 89 d6 48 c1 e6 05 48 8d 74 32 65 ba 19 00 00 00 e8 87 02 05 00 e9 88 fe ff ff 49 63 57 2c e9 16 ff ff ff 0f 0b <0f> 0b 0f 1f 44 00 00 0f 1f 44 00 00 55 83 c2 01 48 63 d2 48 89 e5
	[20512.082468] RSP: 0018:ffffa95b80f1b820 EFLAGS: 00010206
	[20512.082469] RAX: ffff9e059aa5a100 RBX: ffff9e04e01496e0 RCX: ffff9e06555dcb81
	[20512.082469] RDX: 00000000000000ce RSI: 000000000000009f RDI: 0000006336410000
	[20512.082470] RBP: ffffa95b80f1b850 R08: ffffa95b80f1b7c8 R09: ffffa95b80f1b7d0
	[20512.082471] R10: 0000000000007b2a R11: 000000000000009f R12: 0000000000000008
	[20512.082472] R13: ffff9e05c9e21c80 R14: 000000000003a09e R15: ffff9e059aa5a100
	[20512.082473] FS:  00007f938be31700(0000) GS:ffff9e06b6000000(0000) knlGS:0000000000000000
	[20512.082473] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
	[20512.082474] CR2: 00007f6dc1f8c519 CR3: 00000001c3d14005 CR4: 00000000001606e0
	[20512.082478] BUG: sleeping function called from invalid context at ./include/linux/percpu-rwsem.h:34
	[20512.082479] in_atomic(): 1, irqs_disabled(): 0, pid: 5662, name: crawl_5268
	[20512.082479] INFO: lockdep is turned off.
	[20512.082481] CPU: 1 PID: 5662 Comm: crawl_5268 Tainted: G      D W         5.0.16-zb64-9b948ea3083a+ #1
	[20512.082482] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
	[20512.082482] Call Trace:
	[20512.082485]  dump_stack+0x86/0xc5
	[20512.082488]  ___might_sleep+0x217/0x240
	[20512.082490]  __might_sleep+0x4a/0x80
	[20512.082494]  exit_signals+0x33/0x250
	[20512.082496]  do_exit+0xb9/0xd70
	[20512.082502]  rewind_stack_do_exit+0x17/0x20
	[20512.082503] RIP: 0033:0x7f938cf29777
	[20512.082504] Code: 00 00 90 48 8b 05 19 a7 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e9 a6 0c 00 f7 d8 64 89 01 48
	[20512.082505] RSP: 002b:00007f938be2e458 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
	[20512.082506] RAX: ffffffffffffffda RBX: 00007f938be2e780 RCX: 00007f938cf29777
	[20512.082507] RDX: 00007f938be2e788 RSI: 00000000c038943b RDI: 0000000000000003
	[20512.082508] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f938be2e960
	[20512.082508] R10: 000055ad4e628c40 R11: 0000000000000246 R12: 0000000000000003
	[20512.082509] R13: 00007f938be2e788 R14: 00007f938be2e668 R15: 00007f938be2e890
	[20512.082514] note: crawl_5268[5662] exited with preempt_count 2
	[20512.214564] hardirqs last  enabled at (2743290041): [<ffffffff922d4758>] kmem_cache_alloc+0x208/0x330
	[20512.216158] hardirqs last disabled at (2743290040): [<ffffffff922d4614>] kmem_cache_alloc+0xc4/0x330
	[20512.217793] softirqs last  enabled at (2743288790): [<ffffffff930003a0>] __do_softirq+0x3a0/0x45a
	[20512.219555] softirqs last disabled at (2743288767): [<ffffffff920a9949>] irq_exit+0xe9/0xf0
	[20536.037778] watchdog: BUG: soft lockup - CPU#2 stuck for 22s! [rsync:5715]
	[20536.042129] watchdog: BUG: soft lockup - CPU#3 stuck for 22s! [btrfs-transacti:4737]
	[20540.028759] watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [crawl_5268:5663]
	[20540.033740] watchdog: BUG: soft lockup - CPU#1 stuck for 22s! [crawl_5268:5664]

Then SysRq-W:

	[53268.006056] sysrq: SysRq : Show Blocked State
	[53268.006780]   task                        PC stack   pid father
	[53268.007927] rsync           D    0  5683   5673 0x00000000
	[53268.008786] Call Trace:
	[53268.009215]  __schedule+0x3d4/0xb70
	[53268.009770]  schedule+0x3d/0x80
	[53268.010313]  btrfs_tree_lock+0x1a5/0x270
	[53268.010984]  ? wait_woken+0xa0/0xa0
	[53268.011560]  btrfs_search_slot+0x75f/0x930
	[53268.012335]  btrfs_lookup_inode+0x3e/0xc0
	[53268.013066]  ? kmem_cache_alloc+0x208/0x330
	[53268.013817]  ? btrfs_alloc_path+0x1a/0x20
	[53268.014552]  __btrfs_update_delayed_inode+0x70/0x210
	[53268.015542]  btrfs_commit_inode_delayed_inode+0x126/0x130
	[53268.016741]  btrfs_evict_inode+0x3c7/0x530
	[53268.017586]  ? dput+0x2a/0x2e0
	[53268.018222]  evict+0xc3/0x1c0
	[53268.018835]  iput+0x1de/0x280
	[53268.019481]  ? dput+0x2a/0x2e0
	[53268.020130]  dentry_unlink_inode+0xc0/0xf0
	[53268.020996]  __dentry_kill+0xd1/0x1b0
	[53268.021767]  dentry_kill+0x55/0x1e0
	[53268.022512]  ? dput+0x2a/0x2e0
	[53268.023168]  dput+0x291/0x2e0
	[53268.023792]  do_renameat2+0x420/0x5b0
	[53268.024667]  __x64_sys_rename+0x20/0x30
	[53268.025583]  do_syscall_64+0x65/0x1a0
	[53268.026501]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.027664] RIP: 0033:0x7f0167fb1947
	[53268.028415] Code: Bad RIP value.
	[53268.029104] RSP: 002b:00007ffd919c7d08 EFLAGS: 00000246 ORIG_RAX: 0000000000000052
	[53268.030731] RAX: ffffffffffffffda RBX: 00007ffd919c9ed0 RCX: 00007f0167fb1947
	[53268.031962] RDX: 0000000000000000 RSI: 00007ffd919c7ed0 RDI: 00007ffd919c9ed0
	[53268.033209] RBP: 00007ffd919c7ed0 R08: 0000000000000000 R09: 0000000000000000
	[53268.034540] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
	[53268.036319] R13: 0000000000000004 R14: 00000000000081a4 R15: 0000000000000001
	[53268.038063] rsync           D    0  6461   6460 0x00000000
	[53268.039405] Call Trace:
	[53268.040102]  __schedule+0x3d4/0xb70
	[53268.040877]  ? sched_clock+0x9/0x10
	[53268.041640]  schedule+0x3d/0x80
	[53268.042301]  io_schedule+0x16/0x40
	[53268.043065]  wait_on_page_bit_killable+0x183/0x290
	[53268.044111]  ? add_to_page_cache_lru+0xd0/0xd0
	[53268.044909]  generic_file_read_iter+0x267/0xb70
	[53268.045688]  __vfs_read+0x124/0x1b0
	[53268.046290]  vfs_read+0xab/0x160
	[53268.046899]  ksys_read+0x5f/0xf0
	[53268.047637]  __x64_sys_read+0x1a/0x20
	[53268.048582]  do_syscall_64+0x65/0x1a0
	[53268.049368]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.050207] RIP: 0033:0x7fa9d031c761
	[53268.050787] Code: Bad RIP value.
	[53268.051318] RSP: 002b:00007ffc5f634ad8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
	[53268.052997] RAX: ffffffffffffffda RBX: 000055a2c9a3cba0 RCX: 00007fa9d031c761
	[53268.054359] RDX: 0000000000003800 RSI: 000055a2c998e9d0 RDI: 0000000000000001
	[53268.056088] RBP: 0000000000003800 R08: fffffffffffffff0 R09: 0000000000b75811
	[53268.057557] R10: 000055a2c998e9d0 R11: 0000000000000246 R12: 0000000000001000
	[53268.058876] R13: 0000000000003800 R14: 0000000000000320 R15: 0000000000001000
	[53268.060583] rsync           D    0  6596   6595 0x00000000
	[53268.061503] Call Trace:
	[53268.061988]  __schedule+0x3d4/0xb70
	[53268.062717]  schedule+0x3d/0x80
	[53268.063693]  io_schedule+0x16/0x40
	[53268.064330]  wait_on_page_bit+0x178/0x270
	[53268.065084]  ? add_to_page_cache_lru+0xd0/0xd0
	[53268.065959]  read_extent_buffer_pages+0x27e/0x350
	[53268.066914]  btree_read_extent_buffer_pages+0xb8/0x1c0
	[53268.067778]  read_tree_block+0x42/0x70
	[53268.068594]  read_block_for_search.isra.11+0x181/0x350
	[53268.069556]  btrfs_search_slot+0x3cf/0x930
	[53268.070318]  btrfs_lookup_extent_info+0xa3/0x450
	[53268.071986]  update_ref_for_cow+0x1a6/0x340
	[53268.073145]  __btrfs_cow_block+0x1ff/0x570
	[53268.074389]  btrfs_cow_block+0xf8/0x230
	[53268.075428]  push_leaf_left+0x11a/0x190
	[53268.077233]  btrfs_del_items+0x27b/0x470
	[53268.078094]  btrfs_truncate_inode_items+0x2ee/0xe70
	[53268.079041]  ? _raw_spin_unlock+0x27/0x40
	[53268.079898]  btrfs_evict_inode+0x455/0x530
	[53268.080898]  ? dput+0x2a/0x2e0
	[53268.081540]  evict+0xc3/0x1c0
	[53268.082183]  iput+0x1de/0x280
	[53268.082853]  ? dput+0x2a/0x2e0
	[53268.084211]  dentry_unlink_inode+0xc0/0xf0
	[53268.084965]  __dentry_kill+0xd1/0x1b0
	[53268.085805]  dentry_kill+0x55/0x1e0
	[53268.086685]  ? dput+0x2a/0x2e0
	[53268.087371]  dput+0x291/0x2e0
	[53268.087973]  do_renameat2+0x420/0x5b0
	[53268.088974]  __x64_sys_rename+0x20/0x30
	[53268.090099]  do_syscall_64+0x65/0x1a0
	[53268.091287]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.092354] RIP: 0033:0x7f17fb432947
	[53268.093487] Code: Bad RIP value.
	[53268.094165] RSP: 002b:00007ffe387435d8 EFLAGS: 00000246 ORIG_RAX: 0000000000000052
	[53268.095777] RAX: ffffffffffffffda RBX: 00007ffe387457a0 RCX: 00007f17fb432947
	[53268.097312] RDX: 0000000000000000 RSI: 00007ffe387437a0 RDI: 00007ffe387457a0
	[53268.098906] RBP: 00007ffe387437a0 R08: 0000000000000000 R09: 0000000000000000
	[53268.100613] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000
	[53268.102466] R13: 0000000000000004 R14: 00000000000081a4 R15: 0000000000000001
	[53268.104454] rsync           D    0  6679   6674 0x00000000
	[53268.105875] Call Trace:
	[53268.106453]  __schedule+0x3d4/0xb70
	[53268.107603]  schedule+0x3d/0x80
	[53268.108404]  io_schedule+0x16/0x40
	[53268.109461]  wait_on_page_bit_killable+0x183/0x290
	[53268.110459]  ? add_to_page_cache_lru+0xd0/0xd0
	[53268.111238]  generic_file_read_iter+0x267/0xb70
	[53268.112123]  __vfs_read+0x124/0x1b0
	[53268.112842]  vfs_read+0xab/0x160
	[53268.113494]  ksys_read+0x5f/0xf0
	[53268.114127]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.116272]  __x64_sys_read+0x1a/0x20
	[53268.116887]  do_syscall_64+0x65/0x1a0
	[53268.117540]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.118364] RIP: 0033:0x7f935866e761
	[53268.119003] Code: 00 f7 27 00 00 00 00 00 00 62 81 01 00 00 00 00 00 00 20 00 00 00 00 00 00 08 28 00 00 00 00 00 00 62 81 01 00 00 00 00 00 00 <20> 00 00 00 00 00 00 2d 28 00 00 00 00 00 00 62 81 01 00 00 00 00
	[53268.124309] RSP: 002b:00007ffd292115f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
	[53268.126193] RAX: ffffffffffffffda RBX: 00005587c16c2ff0 RCX: 00007f935866e761
	[53268.127920] RDX: 0000000000007c00 RSI: 00005587c16c3430 RDI: 0000000000000001
	[53268.129621] RBP: 0000000000007c00 R08: fffffffffffffff0 R09: 0000000005334800
	[53268.132283] R10: 00005587c16c3430 R11: 0000000000000246 R12: 0000000000000400
	[53268.134937] R13: 0000000000007c00 R14: 0000000000000390 R15: 0000000000000400
	[53268.137415] rsync           D    0  7081   7053 0x00000000
	[53268.138587] Call Trace:
	[53268.139507]  __schedule+0x3d4/0xb70
	[53268.141054]  schedule+0x3d/0x80
	[53268.141638]  io_schedule+0x16/0x40
	[53268.142392]  wait_on_page_bit_killable+0x183/0x290
	[53268.143263]  ? add_to_page_cache_lru+0xd0/0xd0
	[53268.144926]  generic_file_read_iter+0x267/0xb70
	[53268.145758]  __vfs_read+0x124/0x1b0
	[53268.146472]  vfs_read+0xab/0x160
	[53268.147252]  ksys_read+0x5f/0xf0
	[53268.148273]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.149682]  __x64_sys_read+0x1a/0x20
	[53268.150565]  do_syscall_64+0x65/0x1a0
	[53268.151428]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.152233] RIP: 0033:0x7ff3a6803761
	[53268.152800] Code: Bad RIP value.
	[53268.153319] RSP: 002b:00007ffefada95e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
	[53268.154919] RAX: ffffffffffffffda RBX: 0000562ccb936cc0 RCX: 00007ff3a6803761
	[53268.156871] RDX: 0000000000002109 RSI: 0000562cc7e2b1c0 RDI: 0000000000000000
	[53268.158322] RBP: 0000000000002109 R08: 0000562cc7e2b1b0 R09: 00007ff3a68d53f0
	[53268.160016] R10: 0000562cc7269010 R11: 0000000000000246 R12: 0000000000000000
	[53268.161736] R13: 0000000000002109 R14: 0000000000000000 R15: 0000000000000000
	[53268.163275] rsync           D    0  8636   8583 0x00000000
	[53268.164188] Call Trace:
	[53268.164688]  __schedule+0x3d4/0xb70
	[53268.165647]  schedule+0x3d/0x80
	[53268.166522]  io_schedule+0x16/0x40
	[53268.167170]  wait_on_page_bit_killable+0x183/0x290
	[53268.168046]  ? add_to_page_cache_lru+0xd0/0xd0
	[53268.168887]  generic_file_read_iter+0x267/0xb70
	[53268.170488]  __vfs_read+0x124/0x1b0
	[53268.171445]  vfs_read+0xab/0x160
	[53268.172233]  ksys_read+0x5f/0xf0
	[53268.172922]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.174115]  __x64_sys_read+0x1a/0x20
	[53268.174922]  do_syscall_64+0x65/0x1a0
	[53268.175769]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.177195] RIP: 0033:0x7ff57017f761
	[53268.178011] Code: Bad RIP value.
	[53268.178730] RSP: 002b:00007ffcbb34b548 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
	[53268.180469] RAX: ffffffffffffffda RBX: 000055e78c7bfc90 RCX: 00007ff57017f761
	[53268.182613] RDX: 00000000000022dd RSI: 000055e78c7b63d0 RDI: 0000000000000000
	[53268.184854] RBP: 00000000000022dd R08: 000055e78c7b63c0 R09: 00007ff570250cd0
	[53268.186508] R10: 000055e78bd77010 R11: 0000000000000246 R12: 0000000000000000
	[53268.189446] R13: 00000000000022dd R14: 0000000000000000 R15: 0000000000000000
	[53268.190635] rsync           D    0 30991   8458 0x00000000
	[53268.192905] Call Trace:
	[53268.193332]  __schedule+0x3d4/0xb70
	[53268.193920]  ? sched_clock+0x9/0x10
	[53268.195564]  schedule+0x3d/0x80
	[53268.196290]  io_schedule+0x16/0x40
	[53268.197067]  wait_on_page_bit_killable+0x183/0x290
	[53268.197895]  ? add_to_page_cache_lru+0xd0/0xd0
	[53268.198875]  generic_file_read_iter+0x267/0xb70
	[53268.199770]  __vfs_read+0x124/0x1b0
	[53268.200515]  vfs_read+0xab/0x160
	[53268.201198]  ksys_read+0x5f/0xf0
	[53268.201755]  __x64_sys_read+0x1a/0x20
	[53268.202561]  do_syscall_64+0x65/0x1a0
	[53268.203364]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53268.204306] RIP: 0033:0x7fcab8c0c761
	[53268.205129] Code: Bad RIP value.
	[53268.205698] RSP: 002b:00007ffe4e709938 EFLAGS: 00000246 ORIG_RAX: 0000000000000000
	[53268.207263] RAX: ffffffffffffffda RBX: 000055cf5c835d70 RCX: 00007fcab8c0c761
	[53268.208588] RDX: 0000000000004400 RSI: 000055cf5a51d7c0 RDI: 0000000000000001
	[53268.209908] RBP: 0000000000004400 R08: 000055cf5a51d7b0 R09: 00007fcab8cde450
	[53268.211376] R10: 000055cf59ded010 R11: 0000000000000246 R12: 0000000000000000
	[53268.214192] R13: 0000000000004400 R14: 0000000000000000 R15: 0000000000000000

Then SysRq-T excerpts for each of the 4 tasks stuck on CPUs:

CPU#0:

	[53274.315728] rsync           R  running task        0  5715   5708 0x80000008
	[53274.316927] Call Trace:
	[53274.317380]  ? trace_hardirqs_on_thunk+0x1a/0x1c
	[53274.318181]  ? retint_kernel+0x10/0x10
	[53274.318820]  ? trace_hardirqs_on_thunk+0x1a/0x1c
	[53274.319646]  ? retint_kernel+0x10/0x10
	[53274.320331]  ? trace_hardirqs_on_thunk+0x1a/0x1c
	[53274.321125]  ? trace_hardirqs_on_caller+0x4a/0x100
	[53274.321924]  ? trace_hardirqs_on_thunk+0x1a/0x1c
	[53274.322716]  ? retint_kernel+0x10/0x10
	[53274.323367]  ? retint_kernel+0x10/0x10
	[53274.324009]  ? __pv_queued_spin_lock_slowpath+0x273/0x2b0
	[53274.324926]  ? __pv_queued_spin_lock_slowpath+0xf7/0x2b0
	[53274.325814]  ? __pv_queued_spin_lock_slowpath+0x273/0x2b0
	[53274.326729]  ? queued_write_lock_slowpath+0x80/0x90
	[53274.327560]  ? do_raw_write_lock+0xae/0xb0
	[53274.328262]  ? _raw_write_lock+0x55/0x70
	[53274.328932]  ? tree_mod_log_insert_key+0xd3/0x150
	[53274.329840]  ? __btrfs_cow_block+0x25d/0x570
	[53274.330810]  ? btrfs_cow_block+0xf8/0x230
	[53274.331688]  ? btrfs_search_slot+0x213/0x930
	[53274.332621]  ? btrfs_lookup_inode+0x3e/0xc0
	[53274.333595]  ? kmem_cache_alloc+0x208/0x330
	[53274.334505]  ? btrfs_alloc_path+0x1a/0x20
	[53274.335385]  ? __btrfs_update_delayed_inode+0x70/0x210
	[53274.336515]  ? btrfs_commit_inode_delayed_inode+0x126/0x130
	[53274.337740]  ? btrfs_evict_inode+0x3c7/0x530
	[53274.338683]  ? dput+0x2a/0x2e0
	[53274.339350]  ? evict+0xc3/0x1c0
	[53274.340056]  ? iput+0x1de/0x280
	[53274.340746]  ? dput+0x2a/0x2e0
	[53274.341456]  ? dentry_unlink_inode+0xc0/0xf0
	[53274.342378]  ? __dentry_kill+0xd1/0x1b0
	[53274.343208]  ? dentry_kill+0x55/0x1e0
	[53274.343932]  ? dput+0x2a/0x2e0
	[53274.344597]  ? dput+0x291/0x2e0
	[53274.345263]  ? __fput+0x12f/0x260
	[53274.345984]  ? ____fput+0xe/0x10
	[53274.346660]  ? task_work_run+0x8f/0xc0
	[53274.347499]  ? exit_to_usermode_loop+0x112/0x120
	[53274.348543]  ? do_syscall_64+0x199/0x1a0
	[53274.349368]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe

CPU#1:

	[53273.449195] btrfs-transacti R  running task        0  4737      2 0x80000008
	[53273.451375] Call Trace:
	[53273.451980]  ? retint_kernel+0x10/0x10
	[53273.452758]  ? trace_hardirqs_on_thunk+0x1a/0x1c
	[53273.453549]  ? trace_hardirqs_on_caller+0x4a/0x100
	[53273.454355]  ? trace_hardirqs_on_thunk+0x1a/0x1c
	[53273.455143]  ? retint_kernel+0x10/0x10
	[53273.455777]  ? kvm_wait+0x86/0x90
	[53273.456368]  ? __pv_queued_spin_lock_slowpath+0x1ed/0x2b0
	[53273.457300]  ? trace_hardirqs_on+0x4c/0x100
	[53273.458008]  ? kvm_wait+0x8b/0x90
	[53273.458577]  ? __pv_queued_spin_lock_slowpath+0x1ed/0x2b0
	[53273.459747]  ? queued_write_lock_slowpath+0x80/0x90
	[53273.460762]  ? do_raw_write_lock+0xae/0xb0
	[53273.461682]  ? _raw_write_lock+0x55/0x70
	[53273.462493]  ? tree_mod_log_insert_key+0xd3/0x150
	[53273.463314]  ? __btrfs_cow_block+0x25d/0x570
	[53273.464040]  ? btrfs_cow_block+0xf8/0x230
	[53273.464718]  ? btrfs_search_slot+0x213/0x930
	[53273.465447]  ? lookup_inline_extent_backref+0x118/0x570
	[53273.466358]  ? mark_held_locks+0x76/0xa0
	[53273.467175]  ? insert_inline_extent_backref+0x51/0xe0
	[53273.468334]  ? rcu_read_lock_sched_held+0x72/0x80
	[53273.469560]  ? __btrfs_inc_extent_ref+0x87/0x220
	[53273.470730]  ? run_delayed_data_ref+0x1c2/0x210
	[53273.471718]  ? run_one_delayed_ref+0x55/0xa0
	[53273.472787]  ? btrfs_run_delayed_refs_for_head+0x17b/0x3b0
	[53273.474200]  ? __btrfs_run_delayed_refs+0x84/0x180
	[53273.475455]  ? btrfs_run_delayed_refs+0x86/0x1e0
	[53273.476684]  ? btrfs_commit_transaction+0x52/0xab0
	[53273.478684]  ? start_transaction+0x93/0x4d0
	[53273.479500]  ? transaction_kthread+0x155/0x190
	[53273.480308]  ? kthread+0x113/0x150
	[53273.480920]  ? btrfs_cleanup_transaction+0x630/0x630
	[53273.481937]  ? kthread_park+0x90/0x90
	[53273.483571]  ? ret_from_fork+0x3a/0x50

CPU#2:

	[53273.814635] crawl_5268      R  running task        0  5663   5650 0x80000008
	[53273.816033] Call Trace:
	[53273.816470]  <IRQ>
	[53273.816840]  sched_show_task+0x198/0x260
	[53273.817546]  show_state_filter+0xa0/0x1a0
	[53273.818276]  sysrq_handle_showstate+0x10/0x20
	[53273.819059]  __handle_sysrq+0x139/0x210
	[53273.819744]  handle_sysrq+0x26/0x30
	[53273.820376]  serial8250_handle_irq.part.16+0xbc/0x100
	[53273.821298]  serial8250_default_handle_irq+0x53/0x60
	[53273.822209]  serial8250_interrupt+0x68/0x100
	[53273.823001]  __handle_irq_event_percpu+0x4e/0x2b0
	[53273.823958]  handle_irq_event_percpu+0x32/0x80
	[53273.824947]  handle_irq_event+0x39/0x60
	[53273.825800]  handle_edge_irq+0xef/0x1c0
	[53273.826554]  handle_irq+0x75/0x120
	[53273.827191]  do_IRQ+0x64/0x130
	[53273.827760]  common_interrupt+0xf/0xf
	[53273.828443]  </IRQ>
	[53273.828841] RIP: 0010:native_safe_halt+0x12/0x20
	[53273.829783] Code: f0 80 48 02 20 48 8b 00 a8 08 0f 84 7b ff ff ff eb bd 90 90 90 90 90 90 55 48 89 e5 e9 07 00 00 00 0f 00 2d b2 ec 43 00 fb f4 <5d> c3 66 90 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 e9 07 00 00
	[53273.834211] RSP: 0018:ffffa95b81107790 EFLAGS: 00000246 ORIG_RAX: ffffffffffffffd6
	[53273.835701] RAX: 0000000000000000 RBX: ffff9e06b5e159d4 RCX: 0000000000000001
	[53273.837608] RDX: ffff9e06aeb2c000 RSI: ffffffff921199ed RDI: ffffffff9207a326
	[53273.839525] RBP: ffffa95b81107790 R08: 0000000000000000 R09: 0000000000000000
	[53273.841170] R10: ffffa95b811077d0 R11: ffff9e069ddfd6b8 R12: 0000000000000246
	[53273.842439] R13: 0000000000000001 R14: ffff9e06b5e159d4 R15: 0000000000000001
	[53273.843995]  ? __pv_queued_spin_lock_slowpath+0x1ed/0x2b0
	[53273.845002]  ? kvm_wait+0x86/0x90
	[53273.845610]  kvm_wait+0x8b/0x90
	[53273.846178]  __pv_queued_spin_lock_slowpath+0x1ed/0x2b0
	[53273.847472]  queued_read_lock_slowpath+0x75/0x80
	[53273.848317]  do_raw_read_lock+0x4b/0x50
	[53273.849013]  _raw_read_lock+0x58/0x70
	[53273.849693]  __tree_mod_log_search+0x2d/0xb0
	[53273.850466]  __tree_mod_log_oldest_root.isra.1+0x4c/0x80
	[53273.851593]  btrfs_old_root_level+0x26/0x80
	[53273.852374]  resolve_indirect_refs+0x2ad/0x910
	[53273.853211]  ? __schedule+0x3dc/0xb70
	[53273.853870]  find_parent_nodes+0x443/0x1340
	[53273.854631]  btrfs_find_all_roots_safe+0xc5/0x140
	[53273.855774]  ? btrfs_inode_flags_to_fsflags+0x90/0x90
	[53273.856908]  iterate_extent_inodes+0x198/0x3e0
	[53273.857766]  iterate_inodes_from_logical+0xa1/0xd0
	[53273.858929]  ? iterate_inodes_from_logical+0xa1/0xd0
	[53273.859939]  ? btrfs_inode_flags_to_fsflags+0x90/0x90
	[53273.860847]  btrfs_ioctl_logical_to_ino+0xf3/0x1a0
	[53273.861741]  btrfs_ioctl+0xcf7/0x2cb0
	[53273.862617]  ? __lock_acquire+0x477/0x1b50
	[53273.863530]  ? kvm_sched_clock_read+0x18/0x30
	[53273.864496]  ? kvm_sched_clock_read+0x18/0x30
	[53273.865335]  ? sched_clock+0x9/0x10
	[53273.866015]  do_vfs_ioctl+0xa6/0x6e0
	[53273.866891]  ? btrfs_ioctl_get_supported_features+0x30/0x30
	[53273.867954]  ? do_vfs_ioctl+0xa6/0x6e0
	[53273.869148]  ? __fget+0x119/0x200
	[53273.869922]  ksys_ioctl+0x75/0x80
	[53273.870649]  __x64_sys_ioctl+0x1a/0x20
	[53273.871450]  do_syscall_64+0x65/0x1a0
	[53273.872351]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
	[53273.873487] RIP: 0033:0x7f938cf29777
	[53273.874154] Code: 00 00 90 48 8b 05 19 a7 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d e9 a6 0c 00 f7 d8 64 89 01 48
	[53273.878117] RSP: 002b:00007f938b62d458 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
	[53273.879542] RAX: ffffffffffffffda RBX: 00007f938b62d780 RCX: 00007f938cf29777
	[53273.881224] RDX: 00007f938b62d788 RSI: 00000000c038943b RDI: 0000000000000003
	[53273.882805] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f938b62d960
	[53273.884519] R10: 000055ad4e628c40 R11: 0000000000000246 R12: 0000000000000003
	[53273.885971] R13: 00007f938b62d788 R14: 00007f938b62d668 R15: 00007f938b62d890

CPU#3:

	[53273.887482] crawl_5268      R  running task        0  5664   5650 0x80000008
	[53273.888778] Call Trace:
	[53273.889807]  ? tree_mod_log_insert_root.isra.2+0x117/0x350
	[53273.890820]  ? __btrfs_cow_block+0x41e/0x570
	[53273.891625]  ? btrfs_cow_block+0xf8/0x230
	[53273.892471]  ? btrfs_search_slot+0x213/0x930
	[53273.893296]  ? kmem_cache_free+0xa4/0x1e0
	[53273.894189]  ? btrfs_lookup_file_extent+0x49/0x60
	[53273.895058]  ? __btrfs_drop_extents+0x183/0xdf0
	[53273.895869]  ? kmem_cache_alloc+0x208/0x330
	[53273.896641]  ? btrfs_alloc_path+0x1a/0x20
	[53273.897371]  ? trace_hardirqs_on+0x4c/0x100
	[53273.898310]  ? btrfs_drop_extents+0x5d/0x90
	[53273.899096]  ? btrfs_clone+0x845/0xcf0
	[53273.899938]  ? btrfs_extent_same_range+0x5b/0xd0
	[53273.901203]  ? btrfs_remap_file_range+0x218/0x380
	[53273.902585]  ? vfs_dedupe_file_range_one+0x111/0x170
	[53273.903996]  ? vfs_dedupe_file_range+0x157/0x1f0
	[53273.904850]  ? do_vfs_ioctl+0x27f/0x6e0
	[53273.905655]  ? __fget+0x119/0x200
	[53273.906918]  ? ksys_ioctl+0x75/0x80
	[53273.907699]  ? __x64_sys_ioctl+0x1a/0x20
	[53273.908428]  ? do_syscall_64+0x65/0x1a0
	[53273.909175]  ? entry_SYSCALL_64_after_hwframe+0x49/0xbe

> >>
> >> <SNIP>

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]