WARNING: suspicious RCU usage - while installing a VM on a CPU listed under nohz_full

[Nitesh Narayan Lal <nitesh@redhat.com>]

[-- Attachment #1.1: Type: text/plain, Size: 6672 bytes --]

Hi,

I have recently come across an RCU trace with the 5.8-rc7 kernel that has the
debug configs enabled while installing a VM on a CPU that is listed under
nohz_full.

Based on some of the initial debugging, my impression is that the issue is
triggered because of the fastpath that is meant to optimize the writes to x2APIC
ICR that eventually leads to a virtual IPI in fixed delivery mode, is getting
invoked from the quiescent state.

Following is the RCU trace dump that I was getting:

[  178.109535] =============================
[  178.114027] WARNING: suspicious RCU usage
[  178.118518] 5.8.0-rc7-upstream-+ #10 Not tainted
[  178.123685] -----------------------------
[  178.128176] arch/x86/kvm/lapic.c:269 suspicious rcu_dereference_check() usage!
[  178.136254]
[  178.136254] other info that might help us debug this:
[  178.136254]
[  178.145205]
[  178.145205] rcu_scheduler_active = 2, debug_locks = 1
[  178.152506] 1 lock held by CPU 0/KVM/2959:
[  178.157091]  #0: ffffc9000717b6f8 (&kvm->arch.apic_map_lock){+.+.}-{3:3}, at:
kvm_recalculate_apic_map+0x8b/0xdd0 [kvm]
[  178.169207]
[  178.169207] stack backtrace:
[  178.174086] CPU: 18 PID: 2959 Comm: CPU 0/KVM Not tainted
5.8.0-rc7-upstream-+ #10
[  178.182539] Hardware name: Dell Inc. PowerEdge R430/0CN7X8, BIOS 2.6.0 10/31/2017
[  178.190895] Call Trace:
[  178.193637]  dump_stack+0x9d/0xe0
[  178.197379]  kvm_recalculate_apic_map+0x8ce/0xdd0 [kvm]
[  178.203259]  ? kvm_lapic_reset+0x832/0xe50 [kvm]
[  178.208459]  kvm_vcpu_reset+0x28/0x7b0 [kvm]
[  178.213270]  kvm_arch_vcpu_create+0x830/0xb70 [kvm]
[  178.218759]  kvm_vm_ioctl+0x11b1/0x1fe0 [kvm]
[  178.223635]  ? mark_lock+0x144/0x19e0
[  178.227757]  ? kvm_unregister_device_ops+0xe0/0xe0 [kvm]
[  178.233698]  ? sched_clock+0x5/0x10
[  178.237597]  ? sched_clock_cpu+0x18/0x1d0
[  178.242087]  ? __lock_acquire+0xcf6/0x5010
[  178.246686]  ? lockdep_hardirqs_on_prepare+0x550/0x550
[  178.252429]  ? lockdep_hardirqs_on_prepare+0x550/0x550
[  178.258177]  ? sched_clock+0x5/0x10
[  178.262074]  ? sched_clock_cpu+0x18/0x1d0
[  178.266556]  ? find_held_lock+0x3a/0x1c0
[  178.270953]  ? ioctl_file_clone+0x120/0x120
[  178.275630]  ? selinux_file_ioctl+0x98/0x570
[  178.280405]  ? selinux_file_mprotect+0x5b0/0x5b0
[  178.285569]  ? rcu_tasks_wait_gp+0x6d1/0xa50
[  178.290342]  ? rcu_read_lock_sched_held+0xe0/0xe0
[  178.295608]  ? __fget_files+0x1f0/0x300
[  178.299912]  ksys_ioctl+0xc0/0x110
[  178.303719]  __x64_sys_ioctl+0x6f/0xb0
[  178.307913]  do_syscall_64+0x51/0xb0
[  178.311913]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  178.317557] RIP: 0033:0x7f6b9700d88b
[  178.321551] Code: 0f 1e fa 48 8b 05 fd 95 2c 00 64 c7 00 26 00 00 00 48 c7 c0
ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0
ff ff 73 018
[  178.342513] RSP: 002b:00007f6b8cbe9668 EFLAGS: 00000246 ORIG_RAX:
0000000000000010
[  178.350967] RAX: ffffffffffffffda RBX: 000055e8162d9000 RCX: 00007f6b9700d88b
[  178.358935] RDX: 0000000000000000 RSI: 000000000000ae41 RDI: 000000000000000e
[  178.366903] RBP: 000055e8162d9000 R08: 000055e8155ec4d0 R09: 000055e8162d9000
[  178.374871] R10: 000055e815d94ee0 R11: 0000000000000246 R12: 000055e8162ad420
[  178.382838] R13: 000055e8162d9000 R14: 00007ffedf043660 R15: 00007f6b8cbe9800
[  182.771858]
[  182.773606] =============================
[  182.778084] WARNING: suspicious RCU usage
[  182.782564] 5.8.0-rc7-upstream-+ #10 Not tainted
[  182.787719] -----------------------------
[  182.792197] arch/x86/include/asm/trace/fpu.h:60 suspicious
rcu_dereference_check() usage!
[  182.801329]
[  182.801329] other info that might help us debug this:
[  182.801329]
[  182.810268]
[  182.810268] RCU used illegally from idle CPU!
[  182.810268] rcu_scheduler_active = 2, debug_locks = 1
[  182.822407] RCU used illegally from extended quiescent state!
[  182.828824] 1 lock held by CPU 0/KVM/2959:
[  182.833397]  #0: ffff88903f8500d0 (&vcpu->mutex){+.+.}-{3:3}, at:
kvm_vcpu_ioctl+0x172/0xb00 [kvm]
[  182.838308]
[  182.838308] stack backtrace:
[  182.838313] CPU: 18 PID: 2959 Comm: CPU 0/KVM Tainted: G        W        
5.8.0-rc7-upstream-+ #10
[  182.838316] Hardware name: Dell Inc. PowerEdge R430/0CN7X8, BIOS 2.6.0 10/31/2017
[  182.838318] Call Trace:
[  182.874318]  dump_stack+0x9d/0xe0
[  182.878024]  switch_fpu_return+0x37c/0x410
[  182.882602]  ? fpu__clear+0x1a0/0x1a0
[  182.886700]  ? rcu_dynticks_eqs_enter+0x15/0x30
[  182.891807]  vcpu_enter_guest+0x1854/0x3df0 [kvm]
[  182.897121]  ? kvm_vcpu_reload_apic_access_page+0x60/0x60 [kvm]
[  182.903738]  ? lock_acquire+0x1ac/0xac0
[  182.908062]  ? kvm_arch_vcpu_ioctl_run+0x1dc/0x13c0 [kvm]
[  182.914107]  ? rcu_read_unlock+0x50/0x50
[  182.918489]  ? rcu_read_lock_sched_held+0xaf/0xe0
[  182.923788]  ? kvm_load_guest_fpu+0x94/0x350 [kvm]
[  182.929177]  ? kvm_load_guest_fpu+0x94/0x350 [kvm]
[  182.934528]  ? __local_bh_enable_ip+0x123/0x1a0
[  182.939635]  kvm_arch_vcpu_ioctl_run+0x310/0x13c0 [kvm]
[  182.945529]  kvm_vcpu_ioctl+0x3ee/0xb00 [kvm]
[  182.950406]  ? sched_clock+0x5/0x10
[  182.954336]  ? kvm_set_memory_region+0x40/0x40 [kvm]
[  182.959897]  ? ioctl_file_clone+0x120/0x120
[  182.964572]  ? selinux_file_ioctl+0x98/0x570
[  182.969347]  ? selinux_file_mprotect+0x5b0/0x5b0
[  182.974507]  ? rcu_tasks_wait_gp+0x710/0xa50
[  182.979280]  ? rcu_read_lock_sched_held+0xe0/0xe0
[  182.984547]  ? __fget_files+0x1f0/0x300
[  182.988852]  ksys_ioctl+0xc0/0x110
[  182.992660]  __x64_sys_ioctl+0x6f/0xb0
[  182.996853]  do_syscall_64+0x51/0xb0
[  183.000849]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  183.006491] RIP: 0033:0x7f6b9700d88b
[  183.010486] Code: 0f 1e fa 48 8b 05 fd 95 2c 00 64 c7 00 26 00 00 00 48 c7 c0
ff ff ff ff c3 66 0f 1f 44 00 00 f3 0f 1e fa b8 10 00 00 00 0f 05 <48> 3d 01 f0
ff ff 73 018
[  183.031446] RSP: 002b:00007f6b8cbe9618 EFLAGS: 00000246 ORIG_RAX:
0000000000000010
[  183.039901] RAX: ffffffffffffffda RBX: 000055e8162d9000 RCX: 00007f6b9700d88b
[  183.047868] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000018
[  183.055826] RBP: 000055e8162d909b R08: 000055e8155ec1d0 R09: 000055e815db1620
[  183.063784] R10: 0000000000000000 R11: 0000000000000246 R12: 000055e8151f6290
[  183.071752] R13: 000055e8155c81c0 R14: 00007ffedf043660 R15: 00007f6b9c163000

Please let me know if any other information is required.

-- 
Nitesh


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 833 bytes --]