lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <ece36eb1-253a-8ec6-c183-309c10bb35d5@redhat.com>
Date:   Tue, 28 Jul 2020 10:39:49 -0400
From:   Nitesh Narayan Lal <nitesh@...hat.com>
To:     linux-kernel@...r.kernel.org, KVM list <kvm@...r.kernel.org>,
        wanpengli@...cent.com, Paolo Bonzini <pbonzini@...hat.com>,
        sean.j.christopherson@...el.com, vkuznets@...hat.com,
        liran.alon@...cle.com, "frederic@...nel.org" <frederic@...nel.org>,
        tglx@...utronix.de, Juri Lelli <juri.lelli@...hat.com>
Subject: WARNING: suspicious RCU usage - while installing a VM on a CPU listed
 under nohz_full

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



Download attachment "signature.asc" of type "application/pgp-signature" (834 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ