Hello,
kernel test robot noticed "WARNING:bad_unlock_balance_detected" on:
commit: cc69506d19ada63803c37c09ff910217004db1e8 ("KVM: pfncache: simplify locking and make more self-contained")
git://git.infradead.org/users/dwmw2/linux pfncache
in testcase: kernel-selftests
version: kernel-selftests-x86_64-60acb023-1_20230329
with following parameters:
group: kvm
compiler: gcc-12
test machine: 224 threads 2 sockets Intel(R) Xeon(R) Platinum 8480+ (Sapphire Rapids) with 256G memory
(please refer to attached dmesg/kmsg for entire log/backtrace)
If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202402191553.bd17cf2a-oliver.sang@xxxxxxxxx
[ 124.479929][ T5856] WARNING: bad unlock balance detected!
[ 124.487408][ T5856] 6.7.0-rc7-00250-gcc69506d19ad #1 Not tainted
[ 124.495550][ T5856] -------------------------------------
[ 124.503030][ T5856] kvm_clock_test/5856 is trying to release lock (&gpc->refresh_lock) at:
[ 124.513736][ T5856] __kvm_gpc_activate (arch/x86/kvm/../../../virt/kvm/pfncache.c:384) kvm
[ 124.523274][ T5856] but there are no more locks to release!
[ 124.531003][ T5856]
[ 124.531003][ T5856] other info that might help us debug this:
[ 124.542656][ T5856] 2 locks held by kvm_clock_test/5856:
[ 124.550015][ T5856] #0: ff1100406be92470 (&vcpu->mutex){+.+.}-{3:3}, at: kvm_vcpu_ioctl (arch/x86/kvm/../../../virt/kvm/kvm_main.c:4418) kvm
[ 124.562285][ T5856] #1: ffa000003456af10 (&kvm->srcu){.+.+}-{0:0}, at: vcpu_enter_guest+0x19b8/0x3770 kvm
[ 124.575935][ T5856]
[ 124.575935][ T5856] stack backtrace:
[ 124.584919][ T5856] CPU: 207 PID: 5856 Comm: kvm_clock_test Not tainted 6.7.0-rc7-00250-gcc69506d19ad #1
[ 124.596895][ T5856] Call Trace:
[ 124.601723][ T5856] <TASK>
[ 124.606141][ T5856] dump_stack_lvl (lib/dump_stack.c:108)
[ 124.612299][ T5856] __lock_release+0x2eb/0x440
[ 124.619377][ T5856] ? __kvm_gpc_activate (arch/x86/kvm/../../../virt/kvm/pfncache.c:384) kvm
[ 124.626988][ T5856] ? reacquire_held_locks (kernel/locking/lockdep.c:5405)
[ 124.634156][ T5856] ? __mutex_unlock_slowpath (arch/x86/include/asm/atomic64_64.h:109 include/linux/atomic/atomic-arch-fallback.h:4308 include/linux/atomic/atomic-long.h:1499 include/linux/atomic/atomic-instrumented.h:4446 kernel/locking/mutex.c:924)
[ 124.641629][ T5856] ? bit_wait_timeout (kernel/locking/mutex.c:902)
[ 124.648418][ T5856] ? __kvm_gpc_activate (arch/x86/kvm/../../../virt/kvm/pfncache.c:384) kvm
[ 124.656056][ T5856] lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5776)
[ 124.662187][ T5856] __mutex_unlock_slowpath (include/linux/instrumented.h:68 include/linux/atomic/atomic-instrumented.h:3160 kernel/locking/mutex.c:916)
[ 124.669408][ T5856] ? bit_wait_timeout (kernel/locking/mutex.c:902)
[ 124.676233][ T5856] ? __kvm_gpc_refresh (arch/x86/kvm/../../../virt/kvm/pfncache.c:97 arch/x86/kvm/../../../virt/kvm/pfncache.c:328) kvm
[ 124.683867][ T5856] ? lockdep_hardirqs_on_prepare (kernel/locking/lockdep.c:4566)
[ 124.692378][ T5856] __kvm_gpc_activate (arch/x86/kvm/../../../virt/kvm/pfncache.c:384) kvm
[ 124.699751][ T5856] kvm_set_msr_common (arch/x86/kvm/x86.c:4043 arch/x86/kvm/x86.c:4210) kvm
[ 124.707296][ T5856] ? kvm_write_wall_clock+0x180/0x180 kvm
[ 124.716209][ T5856] ? __lock_release+0x111/0x440
[ 124.723338][ T5856] ? kvm_msr_allowed (include/linux/srcu.h:122 include/linux/srcu.h:287 arch/x86/kvm/x86.c:1831) kvm
[ 124.730488][ T5856] vmx_set_msr (arch/x86/kvm/vmx/vmx.c:2448) kvm_intel
[ 124.737687][ T5856] __kvm_set_msr (arch/x86/kvm/x86.c:1845) kvm
[ 124.744439][ T5856] ? kvm_msr_allowed (include/linux/srcu.h:122 include/linux/srcu.h:287 arch/x86/kvm/x86.c:1831) kvm
[ 124.751591][ T5856] ? kvm_emulate_monitor (arch/x86/kvm/x86.c:1845) kvm
[ 124.758933][ T5856] ? lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5776)
[ 124.765024][ T5856] ? kvm_msr_allowed (include/linux/srcu.h:288 arch/x86/kvm/x86.c:1831) kvm
[ 124.772168][ T5856] kvm_emulate_wrmsr (arch/x86/kvm/x86.c:1908 arch/x86/kvm/x86.c:1976 arch/x86/kvm/x86.c:1972 arch/x86/kvm/x86.c:2086) kvm
[ 124.779208][ T5856] vmx_handle_exit (arch/x86/kvm/vmx/vmx.c:6589) kvm_intel
[ 124.786608][ T5856] vcpu_enter_guest+0x1ab2/0x3770 kvm
[ 124.795030][ T5856] ? kvm_check_and_inject_events (arch/x86/kvm/x86.c:10778) kvm
[ 124.803528][ T5856] ? lock_acquire (include/trace/events/lock.h:24 kernel/locking/lockdep.c:5725)
[ 124.809634][ T5856] ? kvm_arch_vcpu_ioctl_run (include/linux/srcu.h:116 include/linux/srcu.h:215 include/linux/kvm_host.h:927 arch/x86/kvm/x86.c:11395) kvm
[ 124.817682][ T5856] ? lock_sync (kernel/locking/lockdep.c:5722)
[ 124.823629][ T5856] ? mark_held_locks (kernel/locking/lockdep.c:4274)
[ 124.829965][ T5856] ? vcpu_run (arch/x86/kvm/x86.c:11258) kvm
[ 124.836441][ T5856] vcpu_run (arch/x86/kvm/x86.c:11258) kvm
[ 124.842720][ T5856] kvm_arch_vcpu_ioctl_run (arch/x86/kvm/x86.c:11484) kvm
[ 124.850583][ T5856] ? lock_release (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5776)
[ 124.856744][ T5856] kvm_vcpu_ioctl (arch/x86/kvm/../../../virt/kvm/kvm_main.c:4442) kvm
[ 124.863640][ T5856] ? kvm_vcpu_kick (arch/x86/kvm/../../../virt/kvm/kvm_main.c:4397) kvm
[ 124.870633][ T5856] __x64_sys_ioctl (fs/ioctl.c:52 fs/ioctl.c:871 fs/ioctl.c:857 fs/ioctl.c:857)
[ 124.877002][ T5856] do_syscall_64 (arch/x86/entry/common.c:52 arch/x86/entry/common.c:83)
[ 124.882981][ T5856] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:129)
[ 124.890633][ T5856] RIP: 0033:0x7f1046845b5b
[ 124.896609][ T5856] Code: 00 48 89 44 24 18 31 c0 48 8d 44 24 60 c7 04 24 10 00 00 00 48 89 44 24 08 48 8d 44 24 20 48 89 44 24 10 b8 10 00 00 00 0f 05 <89> c2 3d 00 f0 ff ff 77 1c 48 8b 44 24 18 64 48 2b 04 25 28 00 00
All code
========
0: 00 48 89 add %cl,-0x77(%rax)
3: 44 24 18 rex.R and $0x18,%al
6: 31 c0 xor %eax,%eax
8: 48 8d 44 24 60 lea 0x60(%rsp),%rax
d: c7 04 24 10 00 00 00 movl $0x10,(%rsp)
14: 48 89 44 24 08 mov %rax,0x8(%rsp)
19: 48 8d 44 24 20 lea 0x20(%rsp),%rax
1e: 48 89 44 24 10 mov %rax,0x10(%rsp)
23: b8 10 00 00 00 mov $0x10,%eax
28: 0f 05 syscall
2a:* 89 c2 mov %eax,%edx <-- trapping instruction
2c: 3d 00 f0 ff ff cmp $0xfffff000,%eax
31: 77 1c ja 0x4f
33: 48 8b 44 24 18 mov 0x18(%rsp),%rax
38: 64 fs
39: 48 rex.W
3a: 2b .byte 0x2b
3b: 04 25 add $0x25,%al
3d: 28 00 sub %al,(%rax)
...
Code starting with the faulting instruction
===========================================
0: 89 c2 mov %eax,%edx
2: 3d 00 f0 ff ff cmp $0xfffff000,%eax
7: 77 1c ja 0x25
9: 48 8b 44 24 18 mov 0x18(%rsp),%rax
e: 64 fs
f: 48 rex.W
10: 2b .byte 0x2b
11: 04 25 add $0x25,%al
13: 28 00 sub %al,(%rax)
...
[ 124.919748][ T5856] RSP: 002b:00007ffed26c1d10 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 124.930292][ T5856] RAX: ffffffffffffffda RBX: 00007f10467456c0 RCX: 00007f1046845b5b
[ 124.940347][ T5856] RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000007
[ 124.950360][ T5856] RBP: 00000000019c2a70 R08: 00007ffed26c1e40 R09: 0000000000000002
[ 124.960375][ T5856] R10: 8c1ed6746cba2bb1 R11: 0000000000000246 R12: 0000000000427220
[ 124.970373][ T5856] R13: 0000000000000000 R14: 00000000019c0490 R15: 000000008030ae7c
[ 124.980364][ T5856] </TASK>
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20240219/202402191553.bd17cf2a-oliver.sang@xxxxxxxxx
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
