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

[Nikolay Borisov <nborisov@suse.com>]

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>

> 
> All the blocked threads are waiting for a snapshot, which is here:
> 
> 	[42829.412010] btrfs           R  running task        0 11306   6447 0x00000000
> 	[42829.413392] Call Trace:
> 	[42829.413895]  __schedule+0x3d4/0xb70
> 	[42829.414598]  preempt_schedule_common+0x1f/0x30
> 	[42829.415480]  _cond_resched+0x22/0x30
> 	[42829.416198]  wait_for_common_io.constprop.2+0x47/0x1b0
> 	[42829.417212]  ? submit_bio+0x73/0x140
> 	[42829.417932]  wait_for_completion_io+0x18/0x20
> 	[42829.418791]  submit_bio_wait+0x68/0x90
> 	[42829.419546]  blkdev_issue_discard+0x80/0xd0
> 	[42829.420381]  btrfs_issue_discard+0xc7/0x160
> 	[42829.421215]  ? btrfs_issue_discard+0xc7/0x160
> 	[42829.422088]  btrfs_discard_extent+0xcc/0x160
> 	[42829.423191]  btrfs_finish_extent_commit+0x118/0x280
> 	[42829.424310]  btrfs_commit_transaction+0x7f9/0xab0
> 	[42829.425231]  ? wait_woken+0xa0/0xa0
> 	[42829.425907]  btrfs_mksubvol+0x5b4/0x630
> 	[42829.426766]  ? mnt_want_write_file+0x28/0x60
> 	[42829.427597]  btrfs_ioctl_snap_create_transid+0x16b/0x1a0
> 	[42829.428614]  btrfs_ioctl_snap_create_v2+0x125/0x180
> 	[42829.429548]  btrfs_ioctl+0x1351/0x2cb0
> 	[42829.430272]  ? __handle_mm_fault+0x110c/0x1950
> 	[42829.431124]  ? do_raw_spin_unlock+0x4d/0xc0
> 	[42829.431934]  ? _raw_spin_unlock+0x27/0x40
> 	[42829.432704]  ? __handle_mm_fault+0x110c/0x1950
> 	[42829.433556]  ? kvm_sched_clock_read+0x18/0x30
> 	[42829.434437]  do_vfs_ioctl+0xa6/0x6e0
> 	[42829.435345]  ? btrfs_ioctl_get_supported_features+0x30/0x30
> 	[42829.436803]  ? do_vfs_ioctl+0xa6/0x6e0
> 	[42829.437528]  ? up_read+0x1f/0xa0
> 	[42829.438159]  ksys_ioctl+0x75/0x80
> 	[42829.438798]  __x64_sys_ioctl+0x1a/0x20
> 	[42829.439565]  do_syscall_64+0x65/0x1a0
> 	[42829.440510]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> 	[42829.441463] RIP: 0033:0x7f1faa8f5777
> 	[42829.442133] Code: Bad RIP value.
> 	[42829.442736] RSP: 002b:00007ffec1520458 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
> 	[42829.444352] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f1faa8f5777
> 	[42829.445710] RDX: 00007ffec1520498 RSI: 0000000050009417 RDI: 0000000000000003
> 	[42829.447030] RBP: 00005621c22ef260 R08: 0000000000000008 R09: 00007f1faa97fe80
> 	[42829.448372] R10: fffffffffffffa4a R11: 0000000000000202 R12: 00005621c22ef290
> 	[42829.449723] R13: 00005621c22ef290 R14: 0000000000000003 R15: 0000000000000004

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

> 
> Also I just noticed there's sometimes (but not always!) a BUG in
> fs/btrfs/ctree.c just before all the soft lockups start:
> 
> 	[26101.008546] ------------[ cut here ]------------
> 	[26101.016090] kernel BUG at fs/btrfs/ctree.c:1227!
> 	[26101.018285] irq event stamp: 36913
> 	[26101.018287] invalid opcode: 0000 [#1] SMP PTI
> 	[26101.018293] CPU: 1 PID: 4823 Comm: crawl_5268 Not tainted 5.0.16-zb64-9b948ea3083a+ #1
> 	[26101.019115] hardirqs last  enabled at (36913): [<ffffffffbb25b02c>] get_page_from_freelist+0x40c/0x19e0
> 	[26101.019118] hardirqs last disabled at (36912): [<ffffffffbb25af70>] get_page_from_freelist+0x350/0x19e0
> 	[26101.020820] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> 	[26101.022456] softirqs last  enabled at (36478): [<ffffffffbc0003a0>] __do_softirq+0x3a0/0x45a
> 	[26101.022461] softirqs last disabled at (36459): [<ffffffffbb0a9949>] irq_exit+0xe9/0xf0
> 	[26101.024212] RIP: 0010:__tree_mod_log_rewind+0x239/0x240
> 	[26101.039031] 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
> 	[26101.042382] RSP: 0018:ffffb3f401613820 EFLAGS: 00010206
> 	[26101.043512] RAX: ffff9f8068690180 RBX: ffff9f7ebf2ba660 RCX: ffff9f8003b1eb80
> 	[26101.044719] RDX: 000000000000015d RSI: 000000000000007e RDI: 0000018aff0a8000
> 	[26101.046157] RBP: ffffb3f401613850 R08: ffffb3f4016137c8 R09: ffffb3f4016137d0
> 	[26101.047474] R10: 0000000000007af3 R11: 000000000000007e R12: 0000000000000008
> 	[26101.048779] R13: ffff9f7ea7d77d00 R14: 0000000000000a49 R15: ffff9f8068690180
> 	[26101.049939] FS:  00007f9064d7a700(0000) GS:ffff9f80b6000000(0000) knlGS:0000000000000000
> 	[26101.051415] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> 	[26101.052330] CR2: 00007fcc462fd8a0 CR3: 000000020e002006 CR4: 00000000001606e0
> 	[26101.053615] Call Trace:
> 	[26101.054103]  btrfs_search_old_slot+0xfe/0x800
> 	[26101.054900]  resolve_indirect_refs+0x1c5/0x910
> 	[26101.055734]  ? prelim_ref_insert+0x10a/0x320
> 	[26101.056474]  find_parent_nodes+0x443/0x1340
> 	[26101.057153]  btrfs_find_all_roots_safe+0xc5/0x140
> 	[26101.057890]  ? btrfs_inode_flags_to_fsflags+0x90/0x90
> 	[26101.058813]  iterate_extent_inodes+0x198/0x3e0
> 	[26101.059608]  iterate_inodes_from_logical+0xa1/0xd0
> 	[26101.060377]  ? iterate_inodes_from_logical+0xa1/0xd0
> 	[26101.061142]  ? btrfs_inode_flags_to_fsflags+0x90/0x90
> 	[26101.061975]  btrfs_ioctl_logical_to_ino+0xf3/0x1a0
> 	[26101.062710]  btrfs_ioctl+0xcf7/0x2cb0
> 	[26101.063318]  ? __lock_acquire+0x477/0x1b50
> 	[26101.063988]  ? kvm_sched_clock_read+0x18/0x30
> 	[26101.065010]  ? kvm_sched_clock_read+0x18/0x30
> 	[26101.065781]  ? sched_clock+0x9/0x10
> 	[26101.066402]  do_vfs_ioctl+0xa6/0x6e0
> 	[26101.067072]  ? btrfs_ioctl_get_supported_features+0x30/0x30
> 	[26101.068102]  ? do_vfs_ioctl+0xa6/0x6e0
> 	[26101.068765]  ? __fget+0x119/0x200
> 	[26101.069381]  ksys_ioctl+0x75/0x80
> 	[26101.069937]  __x64_sys_ioctl+0x1a/0x20
> 	[26101.070627]  do_syscall_64+0x65/0x1a0
> 	[26101.071299]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
> 	[26101.072125] RIP: 0033:0x7f9067675777
> 	[26101.072732] 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
> 	[26101.075884] RSP: 002b:00007f9064d77458 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
> 	[26101.077193] RAX: ffffffffffffffda RBX: 00007f9064d77780 RCX: 00007f9067675777
> 	[26101.078362] RDX: 00007f9064d77788 RSI: 00000000c038943b RDI: 0000000000000004
> 	[26101.079543] RBP: 0000000001000000 R08: 0000000000000000 R09: 00007f9064d77960
> 	[26101.080837] R10: 0000565444959c40 R11: 0000000000000246 R12: 0000000000000004
> 	[26101.082724] R13: 00007f9064d77788 R14: 00007f9064d77668 R15: 00007f9064d77890
> 	[26101.084083] Modules linked in: mq_deadline bfq dm_cache_smq dm_cache dm_persistent_data snd_pcm crct10dif_pclmul crc32_pclmul dm_bio_prison crc32c_intel ghash_clmulni_intel dm_bufio sr_mod snd_timer cdrom snd sg aesni_intel ppdev joydev aes_x86_64 dm_mod soundcore crypto_simd ide_pci_generic cryptd piix glue_helper psmouse input_leds parport_pc ide_core rtc_cmos pcspkr serio_raw bochs_drm evbug parport evdev floppy i2c_piix4 qemu_fw_cfg ip_tables x_tables ipv6 crc_ccitt autofs4
> 	[26101.091346] ---[ end trace d327561dc44a663d ]---

That looks like genuine bug, first I've ever seen the rewind code
hitting it. The rest that follows doesn't seem relevant.

<snip>

> 
> This doesn't quite match the traces I previously posted.  Maybe the
> storm-of-soft-lockups is a symptom of multiple bugs (at least one which
> happens after a bug in ctree.c and one that happens at other times)?
> I'll run this a few more times and see if different cases come up.
> 
> The one thing that is common to all the storm-of-soft-lockups I've seen
> so far is the involvement of multiple crawl_* threads, and those spend
> ~60% of their time running logical_to_ino.
> 
>> Also do you have this patch on the affected machine:
>>
>> 38e3eebff643 ("btrfs: honor path->skip_locking in backref code") can you
>> try and test with it applied ?
>>
>>
>> <SNIP>