Hi!
I recently came up with an interesting failure in the CI pipeline.
[ 592.704446] WARNING: possible circular locking dependency detected
[ 592.710625] 6.12.0-36.el10.x86_64+debug #1 Not tainted
[ 592.715764] ------------------------------------------------------
[ 592.721946] swapper/19/0 is trying to acquire lock:
[ 592.726823] ff110001b0e64ec0 (&p->pi_lock)\{-.-.}-\{2:2}, at: try_to_wake_up+0xa7/0x15c0
[ 592.734761]
[ 592.734761] but task is already holding lock:
[ 592.740596] ff1100079ec0c058 (&per_cpu(wakeup_vcpus_on_cpu_lock, cpu))\{-...}-\{2:2}, at: pi_wakeup_handler+0x60/0x130 [kvm_intel]
[ 592.752185]
[ 592.752185] which lock already depends on the new lock.
[ 592.752185]
[ 592.760357]
[ 592.760357] the existing dependency chain (in reverse order) is:
[ 592.767837]
[ 592.767837] -> #2 (&per_cpu(wakeup_vcpus_on_cpu_lock, cpu))\{-...}-\{2:2}:
[ 592.776027] __lock_acquire+0xcac/0x1d20
[ 592.780489] lock_acquire.part.0+0x11b/0x360
[ 592.785300] _raw_spin_lock+0x37/0x80
[ 592.789484] pi_enable_wakeup_handler+0x11a/0x5a0 [kvm_intel]
[ 592.795776] vmx_vcpu_pi_put+0x1d3/0x230 [kvm_intel]
[ 592.801282] vmx_vcpu_put+0x12/0x20 [kvm_intel]
[ 592.806360] kvm_arch_vcpu_put+0x494/0x7a0 [kvm]
[ 592.811592] kvm_sched_out+0x161/0x1c0 [kvm]
[ 592.816456] prepare_task_switch+0x36c/0xe20
[ 592.821247] __schedule+0x481/0x1a50
[ 592.825346] schedule+0xd4/0x280
[ 592.829100] kvm_vcpu_block+0xe4/0x1d0 [kvm]
[ 592.833964] kvm_vcpu_halt+0x1a2/0x800 [kvm]
[ 592.838824] vcpu_run+0x53f/0x9e0 [kvm]
[ 592.843263] kvm_arch_vcpu_ioctl_run+0x371/0x1480 [kvm]
[ 592.849078] kvm_vcpu_ioctl+0x45e/0xc70 [kvm]
[ 592.854034] __x64_sys_ioctl+0x12e/0x1a0
[ 592.858481] do_syscall_64+0x92/0x180
[ 592.862685] entry_SYSCALL_64_after_hwframe+0x76/0x7e
[ 592.868276]
[ 592.868276] -> #1 (&rq->__lock)\{-.-.}-\{2:2}:
[ 592.874038] __lock_acquire+0xcac/0x1d20
[ 592.878485] lock_acquire.part.0+0x11b/0x360
[ 592.883277] _raw_spin_lock_nested+0x3b/0x70
[ 592.888069] raw_spin_rq_lock_nested+0x2e/0x130
[ 592.893121] __task_rq_lock+0xdb/0x570
[ 592.897393] wake_up_new_task+0x750/0x1050
[ 592.902014] kernel_clone+0x13e/0x5f0
[ 592.906209] user_mode_thread+0xa4/0xe0
[ 592.910568] rest_init+0x1e/0x1c0
[ 592.914407] start_kernel+0x3ab/0x3b0
[ 592.918592] x86_64_start_reservations+0x24/0x30
[ 592.923732] x86_64_start_kernel+0x9c/0xa0
[ 592.928353] common_startup_64+0x13e/0x141
[ 592.932988]
[ 592.932988] -> #0 (&p->pi_lock)\{-.-.}-\{2:2}:
[ 592.938754] check_prev_add+0x1b7/0x23e0
[ 592.943200] validate_chain+0xa8a/0xf00
[ 592.947557] __lock_acquire+0xcac/0x1d20
[ 592.952005] lock_acquire.part.0+0x11b/0x360
[ 592.956797] _raw_spin_lock_irqsave+0x46/0x90
[ 592.961676] try_to_wake_up+0xa7/0x15c0
[ 592.966035] rcuwait_wake_up+0x80/0x190
[ 592.970396] kvm_vcpu_wake_up+0x19/0xa0 [kvm]
[ 592.975353] pi_wakeup_handler+0xf4/0x130 [kvm_intel]
[ 592.980950] sysvec_kvm_posted_intr_wakeup_ipi+0x9c/0xd0
[ 592.986783] asm_sysvec_kvm_posted_intr_wakeup_ipi+0x1a/0x20
[ 592.992964] finish_task_switch.isra.0+0x228/0x830
[ 592.998275] __schedule+0x7c7/0x1a50
[ 593.002376] schedule_idle+0x59/0x90
[ 593.006477] do_idle+0x155/0x200
[ 593.010244] cpu_startup_entry+0x54/0x60
[ 593.014693] start_secondary+0x212/0x290
[ 593.019138] common_startup_64+0x13e/0x141
[ 593.023758]
[ 593.023758] other info that might help us debug this:
[ 593.023758]
[ 593.031757] Chain exists of:
[ 593.031757] &p->pi_lock --> &rq->__lock --> &per_cpu(wakeup_vcpus_on_cpu_lock, cpu)
[ 593.031757]
[ 593.043932] Possible unsafe locking scenario:
[ 593.043932]
[ 593.049852] CPU0 CPU1
[ 593.054384] ---- ----
[ 593.058918] lock(&per_cpu(wakeup_vcpus_on_cpu_lock, cpu));
[ 593.064576] lock(&rq->__lock);
[ 593.070323] lock(&per_cpu(wakeup_vcpus_on_cpu_lock, cpu));
[ 593.078496] lock(&p->pi_lock);
[ 593.081745]
[ 593.081745] *** DEADLOCK ***
[ 593.081745]
[ 593.087666] 2 locks held by swapper/19/0:
[ 593.091679] #0: ff1100079ec0c058 (&per_cpu(wakeup_vcpus_on_cpu_lock, cpu))\{-...}-\{2:2}, at: pi_wakeup_handler+0x60/0x130 [kvm_intel]
[ 593.103692] #1: ffffffffa9b3eec0 (rcu_read_lock)\{....}-\{1:2}, at: rcuwait_wake_up+0x22/0x190
[ 593.112227]
[ 593.112227] stack backtrace:
[ 593.116590] CPU: 19 UID: 0 PID: 0 Comm: swapper/19 Kdump: loaded Not tainted 6.12.0-36.el10.x86_64+debug #1
[ 593.126338] Hardware name: Dell Inc. PowerEdge R660/0R5JJC, BIOS 2.1.5 03/14/2024
[ 593.133818] Call Trace:
[ 593.136271] <IRQ>
[ 593.138291] dump_stack_lvl+0x6f/0xb0
[ 593.141965] print_circular_bug.cold+0x38/0x48
[ 593.146427] check_noncircular+0x308/0x3f0
[ 593.150545] ? __pfx_check_noncircular+0x10/0x10
[ 593.155180] ? __module_address+0x95/0x240
[ 593.159300] ? alloc_chain_hlocks+0x33b/0x520
[ 593.163675] check_prev_add+0x1b7/0x23e0
[ 593.167620] validate_chain+0xa8a/0xf00
[ 593.171478] ? __pfx_validate_chain+0x10/0x10
[ 593.175850] ? mark_lock+0x78/0x860
[ 593.179360] ? __pfx_lockdep_lock+0x10/0x10
[ 593.183549] __lock_acquire+0xcac/0x1d20
[ 593.187494] ? __pfx_validate_chain+0x10/0x10
[ 593.191867] lock_acquire.part.0+0x11b/0x360
[ 593.196156] ? try_to_wake_up+0xa7/0x15c0
[ 593.200172] ? __pfx_lock_acquire.part.0+0x10/0x10
[ 593.204980] ? rcu_is_watching+0x15/0xb0
[ 593.208907] ? trace_lock_acquire+0x1b9/0x280
[ 593.213265] ? try_to_wake_up+0xa7/0x15c0
[ 593.217294] ? lock_acquire+0x31/0xc0
[ 593.220961] ? try_to_wake_up+0xa7/0x15c0
[ 593.224975] _raw_spin_lock_irqsave+0x46/0x90
[ 593.229351] ? try_to_wake_up+0xa7/0x15c0
[ 593.233362] try_to_wake_up+0xa7/0x15c0
[ 593.237220] ? trace_lock_acquire+0x1b9/0x280
[ 593.241581] ? __pfx_try_to_wake_up+0x10/0x10
[ 593.245958] rcuwait_wake_up+0x80/0x190
[ 593.249816] kvm_vcpu_wake_up+0x19/0xa0 [kvm]
[ 593.254260] pi_wakeup_handler+0xf4/0x130 [kvm_intel]
[ 593.259338] sysvec_kvm_posted_intr_wakeup_ipi+0x9c/0xd0
[ 593.264668] </IRQ>
[ 593.266772] <TASK>
[ 593.268880] asm_sysvec_kvm_posted_intr_wakeup_ipi+0x1a/0x20
[ 593.274557] RIP: 0010:finish_task_switch.isra.0+0x228/0x830
[ 593.280147] Code: 41 ff 4d 00 0f 84 95 03 00 00 81 7d d0 80 00 00 00 0f 84 bd 03 00 00 48 8d 65 d8 5b 41 5c 41 5d 41 5e 41 5f 5d c3 cc cc cc cc <49> 8d be 00 05 00 00 48 b8 00 00 00 00 00 fc ff df
48 89 fa 48 c1
[ 593.298894] RSP: 0018:ffa0000000747cd8 EFLAGS: 00000206
[ 593.304137] RAX: 000000000016e47d RBX: ff1100079ec08e40 RCX: 0000000000000000
[ 593.311269] RDX: 0000000000000000 RSI: ffffffffa82f4140 RDI: ffffffffa85a2fa0
[ 593.318403] RBP: ffa0000000747d18 R08: 0000000000000001 R09: 0000000000000000
[ 593.325534] R10: 0000000000000001 R11: 0000000000000000 R12: ff110001b0e63f80
[ 593.332667] R13: 0000000000000000 R14: ff11000101dabf80 R15: ff1100079ec09e60
[ 593.339803] ? finish_task_switch.isra.0+0x1b9/0x830
[ 593.344785] ? __switch_to+0xc31/0xfa0
[ 593.348537] ? __switch_to_asm+0x3d/0x70
[ 593.352483] __schedule+0x7c7/0x1a50
[ 593.356077] ? __pfx___schedule+0x10/0x10
[ 593.360107] ? __pfx_sched_ttwu_pending+0x10/0x10
[ 593.364829] ? rcu_is_watching+0x15/0xb0
[ 593.368777] schedule_idle+0x59/0x90
[ 593.372370] do_idle+0x155/0x200
[ 593.375605] cpu_startup_entry+0x54/0x60
[ 593.379547] start_secondary+0x212/0x290
[ 593.383483] ? __pfx_start_secondary+0x10/0x10
[ 593.387945] ? startup_64_load_idt+0xc1/0xf0
[ 593.392235] common_startup_64+0x13e/0x141
[ 593.396355] </TASK>
I reproduced the failure upstream as well.
In fact it reproduces well on a Sapphire Rapids system which I use for testing
('Intel(R) Xeon(R) Silver 4410Y')
To reproduce I just need to run the kvm selftests on a lockdep enabled kernel.
If I am not mistaken the following happens:
1. pi_enable_wakeup_handler() is called when the current vCPU is scheduled out
it will then
- *disable interrupts*
- take a per-cpu lock 'wakeup_vcpus_on_cpu_lock' of the *current CPU*
- add the current vCPU to the per-cpu list which is protected by the lock above.
- enable interrupts
2. pi_wakeup_handler (IRQ handler) will also
- take wakeup_vcpus_on_cpu_lock of *current CPU*
- go over the vCPUs in the wakeup_vcpus_on_cpu list of *current CPU*, and kick them.
AFAIK, (1) and (2) can't race with each other and in fact no locking is needed here to prevent
a race.
The lock is required to prevent race with another place with needs access to the 'wakeup_vcpus_on_cpu' list:
(3)
When a sleeping vCPU is waken up it is scheduled to run (e.g. due to the kick above or other reason)
CPU, then *vmx_vcpu_pi_load* will
- disable interrupts (to avoid race with (1))
- take wakeup_vcpus_on_cpu_lock (maybe of a different cpu)
- remove this vCPU from the wakeup_vcpus_on_cpu list of that different CPU
- release the lock and re-enable interrupts.
As far as I see, there is no race, but lockdep doesn't understand this.
It thinks that:
1. pi_enable_wakeup_handler is called from schedule() which holds rq->lock, and it itself takes wakeup_vcpus_on_cpu_lock lock
2. pi_wakeup_handler takes wakeup_vcpus_on_cpu_lock and then calls try_to_wake_up which can eventually take rq->lock
(at the start of the function there is a list of cases when it takes it)
I don't know lockdep well yet, but maybe a lockdep annotation will help,
if we can tell it that there are multiple 'wakeup_vcpus_on_cpu_lock' locks.
What do you think?
Best regards,
Maxim Levitsky
