Circular lockdep in kvm_reset_vcpu() ?

Circular lockdep in kvm_reset_vcpu() ?

[Jeremy Linton]

Hi,

I saw this pop yesterday:

[   78.333360] ======================================================
[   78.339541] WARNING: possible circular locking dependency detected
[   78.345721] 6.2.0-rc7+ #19 Not tainted
[   78.349470] ------------------------------------------------------
[   78.355647] qemu-system-aar/859 is trying to acquire lock:
[   78.361130] ffff5aa69269eba0 (&host_kvm->lock){+.+.}-{3:3}, at: 
kvm_reset_vcpu+0x34/0x274
[   78.369344]
[   78.369344] but task is already holding lock:
[   78.375182] ffff5aa68768c0b8 (&vcpu->mutex){+.+.}-{3:3}, at: 
kvm_vcpu_ioctl+0x8c/0xba0
[   78.383133]
[   78.383133] which lock already depends on the new lock.
[   78.383133]
[   78.391318]
[   78.391318] the existing dependency chain (in reverse order) is:
[   78.398811]
[   78.398811] -> #1 (&vcpu->mutex){+.+.}-{3:3}:
[   78.404682]        __lock_acquire+0x480/0x9c0
[   78.409068]        lock_acquire.part.0+0xf0/0x240
[   78.413806]        lock_acquire+0xa8/0x204
[   78.417934]        __mutex_lock+0xac/0x460
[   78.422053]        mutex_lock_nested+0x34/0x40
[   78.426517]        kvm_vm_ioctl_create_vcpu+0x17c/0x474
[   78.431768]        kvm_vm_ioctl+0x67c/0xb00
[   78.435966]        __arm64_sys_ioctl+0xb4/0x100
[   78.440516]        invoke_syscall+0x78/0xfc
[   78.444714]        el0_svc_common.constprop.0+0x68/0x124
[   78.450044]        do_el0_svc+0x34/0x4c
[   78.453892]        el0_svc+0x50/0x140
[   78.457571]        el0t_64_sync_handler+0xf4/0x120
[   78.462381]        el0t_64_sync+0x194/0x198
[   78.466580]
[   78.466580] -> #0 (&host_kvm->lock){+.+.}-{3:3}:
[   78.472714]        check_prev_add+0xa4/0x8d4
[   78.477005]        validate_chain+0x420/0x590
[   78.481381]        __lock_acquire+0x480/0x9c0
[   78.485759]        lock_acquire.part.0+0xf0/0x240
[   78.490483]        lock_acquire+0xa8/0x204
[   78.494598]        __mutex_lock+0xac/0x460
[   78.498711]        mutex_lock_nested+0x34/0x40
[   78.503171]        kvm_reset_vcpu+0x34/0x274
[   78.507461]        kvm_vcpu_set_target+0x10c/0x154
[   78.512274]        kvm_arch_vcpu_ioctl_vcpu_init+0x20/0xf0
[   78.517782]        kvm_arch_vcpu_ioctl+0x398/0x550
[   78.522595]        kvm_vcpu_ioctl+0x5f8/0xba0
[   78.526973]        __arm64_sys_ioctl+0xb4/0x100
[   78.531522]        invoke_syscall+0x78/0xfc
[   78.535719]        el0_svc_common.constprop.0+0x68/0x124
[   78.541048]        do_el0_svc+0x34/0x4c
[   78.544897]        el0_svc+0x50/0x140
[   78.548574]        el0t_64_sync_handler+0xf4/0x120
[   78.553384]        el0t_64_sync+0x194/0x198
[   78.557581]
[   78.557581] other info that might help us debug this:
[   78.557581]
[   78.565606]  Possible unsafe locking scenario:
[   78.565606]
[   78.571541]        CPU0                    CPU1
[   78.576080]        ----                    ----
[   78.580606]   lock(&vcpu->mutex);
[   78.583922]                                lock(&host_kvm->lock);
[   78.590017]                                lock(&vcpu->mutex);
[   78.595851]   lock(&host_kvm->lock);
[   78.599426]
[   78.599426]  *** DEADLOCK ***
[   78.599426]
[   78.605344] 1 lock held by qemu-system-aar/859:
[   78.609873]  #0: ffff5aa68768c0b8 (&vcpu->mutex){+.+.}-{3:3}, at: 
kvm_vcpu_ioctl+0x8c/0xba0
[   78.618245]
[   78.618245] stack backtrace:
[   78.622599] CPU: 1 PID: 859 Comm: qemu-system-aar Not tainted 
6.2.0-rc7+ #19
[   78.629650] Hardware name: Raspberry Pi Foundation Raspberry Pi 4 
Model B/Raspberry Pi 4 Model B, BIOS EDK2-DEV 11/07/2022
[   78.640696] Call trace:
[   78.643137]  dump_backtrace+0xe8/0x140
[   78.646885]  show_stack+0x20/0x30
[   78.650197]  dump_stack_lvl+0x88/0xb4
[   78.653858]  dump_stack+0x18/0x34
[   78.657171]  print_circular_bug+0x1f8/0x200
[   78.661355]  check_noncircular+0x13c/0x150
[   78.665451]  check_prev_add+0xa4/0x8d4
[   78.669199]  validate_chain+0x420/0x590
[   78.673035]  __lock_acquire+0x480/0x9c0
[   78.676871]  lock_acquire.part.0+0xf0/0x240
[   78.681055]  lock_acquire+0xa8/0x204
[   78.684629]  __mutex_lock+0xac/0x460
[   78.688203]  mutex_lock_nested+0x34/0x40
[   78.692124]  kvm_reset_vcpu+0x34/0x274
[   78.695873]  kvm_vcpu_set_target+0x10c/0x154
[   78.700144]  kvm_arch_vcpu_ioctl_vcpu_init+0x20/0xf0
[   78.705110]  kvm_arch_vcpu_ioctl+0x398/0x550
[   78.709380]  kvm_vcpu_ioctl+0x5f8/0xba0
[   78.713217]  __arm64_sys_ioctl+0xb4/0x100
[   78.717225]  invoke_syscall+0x78/0xfc
[   78.720885]  el0_svc_common.constprop.0+0x68/0x124
[   78.725674]  do_el0_svc+0x34/0x4c
[   78.728986]  el0_svc+0x50/0x140
[   78.732126]  el0t_64_sync_handler+0xf4/0x120
[   78.736395]  el0t_64_sync+0x194/0x198


It appears to be triggered by the new commit 42a90008f890a ('KVM: Ensure 
lockdep knows about kvm->lock vs. vcpu->mutex ordering rule') which is 
detecting the vcpu lock grabbed by kvm_vcpu_ioctl() and then the kvm 
mutext grabbed by kvm_reset_vcpu().

This is 6.2rc7 configured for fedora-debug and qemu on the rpi4.

Thanks,

Re: Circular lockdep in kvm_reset_vcpu() ?

[Oliver Upton]

Hi Jeremy,

On Fri, Feb 10, 2023 at 11:46:36AM -0600, Jeremy Linton wrote:
> Hi,
> 
> I saw this pop yesterday:

You and me both actually! Shame on me, I spoke off-list about this with
Marc in passing. Thanks for sending along the report.

> [   78.333360] ======================================================
> [   78.339541] WARNING: possible circular locking dependency detected
> [   78.345721] 6.2.0-rc7+ #19 Not tainted
> [   78.349470] ------------------------------------------------------
> [   78.355647] qemu-system-aar/859 is trying to acquire lock:
> [   78.361130] ffff5aa69269eba0 (&host_kvm->lock){+.+.}-{3:3}, at:
> kvm_reset_vcpu+0x34/0x274
> [   78.369344]
> [   78.369344] but task is already holding lock:
> [   78.375182] ffff5aa68768c0b8 (&vcpu->mutex){+.+.}-{3:3}, at:
> kvm_vcpu_ioctl+0x8c/0xba0

[...]

> It appears to be triggered by the new commit 42a90008f890a ('KVM: Ensure
> lockdep knows about kvm->lock vs. vcpu->mutex ordering rule') which is
> detecting the vcpu lock grabbed by kvm_vcpu_ioctl() and then the kvm mutext
> grabbed by kvm_reset_vcpu().

Right, this commit gave lockdep what it needed to smack us on the head
for getting the locking wrong in the arm64 side.

As gross as it might be, the right direction is likely to have our own
lock in kvm_arch that we can acquire while holding the vcpu mutex. I'll
throw a patch at the list once I get done testing it.

-- 
Thanks,
Oliver

Re: Circular lockdep in kvm_reset_vcpu() ?

[Cristian Marussi]

On Sat, Feb 11, 2023 at 12:56:41AM +0000, Oliver Upton wrote:
> Hi Jeremy,
> 

Hi,

> On Fri, Feb 10, 2023 at 11:46:36AM -0600, Jeremy Linton wrote:
> > Hi,
> > 
> > I saw this pop yesterday:
> 
> You and me both actually! Shame on me, I spoke off-list about this with
> Marc in passing. Thanks for sending along the report.
> 
> > [   78.333360] ======================================================
> > [   78.339541] WARNING: possible circular locking dependency detected
> > [   78.345721] 6.2.0-rc7+ #19 Not tainted
> > [   78.349470] ------------------------------------------------------
> > [   78.355647] qemu-system-aar/859 is trying to acquire lock:
> > [   78.361130] ffff5aa69269eba0 (&host_kvm->lock){+.+.}-{3:3}, at:
> > kvm_reset_vcpu+0x34/0x274
> > [   78.369344]
> > [   78.369344] but task is already holding lock:
> > [   78.375182] ffff5aa68768c0b8 (&vcpu->mutex){+.+.}-{3:3}, at:
> > kvm_vcpu_ioctl+0x8c/0xba0
> 
> [...]
> 
> > It appears to be triggered by the new commit 42a90008f890a ('KVM: Ensure
> > lockdep knows about kvm->lock vs. vcpu->mutex ordering rule') which is
> > detecting the vcpu lock grabbed by kvm_vcpu_ioctl() and then the kvm mutext
> > grabbed by kvm_reset_vcpu().
> 
> Right, this commit gave lockdep what it needed to smack us on the head
> for getting the locking wrong in the arm64 side.
> 
> As gross as it might be, the right direction is likely to have our own
> lock in kvm_arch that we can acquire while holding the vcpu mutex. I'll
> throw a patch at the list once I get done testing it.
> 

I just hit this using a v6.3-rc2 and a mainline kvmtool.

In my case, though, the guest does not even boot if I use more than 1 vcpu, which
I suppose triggers effectively the reported possible deadlock, i.e.:

root/lkvm_master run -c 4 -m 4096 -k /root/Image_guest -d /root/disk_debian_buster_guest.img -p "loglevel=8"
  # lkvm run -k /root/Image_guest -m 4096 -c 4 --name guest-288
....<HANGS FOREVER>

Thanks,
Cristian

Re: Circular lockdep in kvm_reset_vcpu() ?

[Marc Zyngier]

On 2023-03-13 10:09, Cristian Marussi wrote:
> On Sat, Feb 11, 2023 at 12:56:41AM +0000, Oliver Upton wrote:
>> Hi Jeremy,
>> 
> 
> Hi,
> 
>> On Fri, Feb 10, 2023 at 11:46:36AM -0600, Jeremy Linton wrote:
>> > Hi,
>> >
>> > I saw this pop yesterday:
>> 
>> You and me both actually! Shame on me, I spoke off-list about this 
>> with
>> Marc in passing. Thanks for sending along the report.
>> 
>> > [   78.333360] ======================================================
>> > [   78.339541] WARNING: possible circular locking dependency detected
>> > [   78.345721] 6.2.0-rc7+ #19 Not tainted
>> > [   78.349470] ------------------------------------------------------
>> > [   78.355647] qemu-system-aar/859 is trying to acquire lock:
>> > [   78.361130] ffff5aa69269eba0 (&host_kvm->lock){+.+.}-{3:3}, at:
>> > kvm_reset_vcpu+0x34/0x274
>> > [   78.369344]
>> > [   78.369344] but task is already holding lock:
>> > [   78.375182] ffff5aa68768c0b8 (&vcpu->mutex){+.+.}-{3:3}, at:
>> > kvm_vcpu_ioctl+0x8c/0xba0
>> 
>> [...]
>> 
>> > It appears to be triggered by the new commit 42a90008f890a ('KVM: Ensure
>> > lockdep knows about kvm->lock vs. vcpu->mutex ordering rule') which is
>> > detecting the vcpu lock grabbed by kvm_vcpu_ioctl() and then the kvm mutext
>> > grabbed by kvm_reset_vcpu().
>> 
>> Right, this commit gave lockdep what it needed to smack us on the head
>> for getting the locking wrong in the arm64 side.
>> 
>> As gross as it might be, the right direction is likely to have our own
>> lock in kvm_arch that we can acquire while holding the vcpu mutex. 
>> I'll
>> throw a patch at the list once I get done testing it.
>> 
> 
> I just hit this using a v6.3-rc2 and a mainline kvmtool.
> 
> In my case, though, the guest does not even boot if I use more than 1
> vcpu, which
> I suppose triggers effectively the reported possible deadlock, i.e.:
> 
> root/lkvm_master run -c 4 -m 4096 -k /root/Image_guest -d
> /root/disk_debian_buster_guest.img -p "loglevel=8"
>   # lkvm run -k /root/Image_guest -m 4096 -c 4 --name guest-288
> ....<HANGS FOREVER>

Pass earlycon to the guest for a start.

I seriously doubt someone has actually seen a deadlock, because
the issue has been there for at least the past 7 years...

And -rc2 works just fine here.

         M.
-- 
Who you jivin' with that Cosmik Debris?

Re: Circular lockdep in kvm_reset_vcpu() ?

[Cristian Marussi]

On Mon, Mar 13, 2023 at 02:09:55PM +0000, Marc Zyngier wrote:
> On 2023-03-13 10:09, Cristian Marussi wrote:
> > On Sat, Feb 11, 2023 at 12:56:41AM +0000, Oliver Upton wrote:
> > > Hi Jeremy,
> > > 
> > 
> > Hi,
> > 
> > > On Fri, Feb 10, 2023 at 11:46:36AM -0600, Jeremy Linton wrote:
> > > > Hi,
> > > >
> > > > I saw this pop yesterday:
> > > 
> > > You and me both actually! Shame on me, I spoke off-list about this
> > > with
> > > Marc in passing. Thanks for sending along the report.
> > > 
> > > > [   78.333360] ======================================================
> > > > [   78.339541] WARNING: possible circular locking dependency detected
> > > > [   78.345721] 6.2.0-rc7+ #19 Not tainted
> > > > [   78.349470] ------------------------------------------------------
> > > > [   78.355647] qemu-system-aar/859 is trying to acquire lock:
> > > > [   78.361130] ffff5aa69269eba0 (&host_kvm->lock){+.+.}-{3:3}, at:
> > > > kvm_reset_vcpu+0x34/0x274
> > > > [   78.369344]
> > > > [   78.369344] but task is already holding lock:
> > > > [   78.375182] ffff5aa68768c0b8 (&vcpu->mutex){+.+.}-{3:3}, at:
> > > > kvm_vcpu_ioctl+0x8c/0xba0
> > > 
> > > [...]
> > > 
> > > > It appears to be triggered by the new commit 42a90008f890a ('KVM: Ensure
> > > > lockdep knows about kvm->lock vs. vcpu->mutex ordering rule') which is
> > > > detecting the vcpu lock grabbed by kvm_vcpu_ioctl() and then the kvm mutext
> > > > grabbed by kvm_reset_vcpu().
> > > 
> > > Right, this commit gave lockdep what it needed to smack us on the head
> > > for getting the locking wrong in the arm64 side.
> > > 
> > > As gross as it might be, the right direction is likely to have our own
> > > lock in kvm_arch that we can acquire while holding the vcpu mutex.
> > > I'll
> > > throw a patch at the list once I get done testing it.
> > > 
> > 
> > I just hit this using a v6.3-rc2 and a mainline kvmtool.
> > 
> > In my case, though, the guest does not even boot if I use more than 1
> > vcpu, which
> > I suppose triggers effectively the reported possible deadlock, i.e.:
> > 
> > root/lkvm_master run -c 4 -m 4096 -k /root/Image_guest -d
> > /root/disk_debian_buster_guest.img -p "loglevel=8"
> >   # lkvm run -k /root/Image_guest -m 4096 -c 4 --name guest-288
> > ....<HANGS FOREVER>
> 
> Pass earlycon to the guest for a start.
> 
> I seriously doubt someone has actually seen a deadlock, because
> the issue has been there for at least the past 7 years...
> 
> And -rc2 works just fine here.

Thanks, I'll dig deeper what's going on un my setup.
Cristian

Re: Circular lockdep in kvm_reset_vcpu() ?

[Marc Zyngier]

On 2023-03-13 18:20, Cristian Marussi wrote:
> On Mon, Mar 13, 2023 at 02:09:55PM +0000, Marc Zyngier wrote:

>> And -rc2 works just fine here.
> 
> Thanks, I'll dig deeper what's going on un my setup.

Actually, you really want this patch[1] which is on its
way to Linus.

It could explain the issue you're seeing with SMP.

         M.

[1] 
https://git.kernel.org/pub/scm/linux/kernel/git/kvmarm/kvmarm.git/commit/?h=fixes&id=47053904e18282af4525a02e3e0f519f014fc7f9
-- 
Jazz is not dead. It just smells funny...

Re: Circular lockdep in kvm_reset_vcpu() ?

[Cristian Marussi]

On Tue, Mar 14, 2023 at 09:28:25AM +0000, Marc Zyngier wrote:
> On 2023-03-13 18:20, Cristian Marussi wrote:
> > On Mon, Mar 13, 2023 at 02:09:55PM +0000, Marc Zyngier wrote:
> 
> > > And -rc2 works just fine here.
> > 
> > Thanks, I'll dig deeper what's going on un my setup.
> 
> Actually, you really want this patch[1] which is on its
> way to Linus.
> 
> It could explain the issue you're seeing with SMP.

Hi Marc,

thanks this just solves for me on JUNO with guest SMP.

Indeed with earlycon on JUNO with SMP I was seeing, beside a lot of
workqueue lockup that finally hanged the guest, some puzzling
'time-traveling' stamps that seemed to align more with the host time
than the guest.

    [    0.509305] thermal_sys: Registered thermal governor 'step_wise'
    [    0.509327] thermal_sys: Registered thermal governor 'power_allocator'
    [  282.404523] audit: type=2000 audit(0.372:1): state=initialized audit_enabled=0 res=1
    [    0.526380] cpuidle: using governor menu
    [    0.530378] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
    [    0.536241] ASID allocator initialised with 65536 entries
    [    0.547455] Serial: AMBA PL011 UART driver
    [    0.563267] Callback from call_rcu_tasks() invoked.
    [  282.463816] KASLR disabled due to lack of seed
    [  282.470356] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages
    [  282.476182] HugeTLB: 0 KiB vmemmap can be freed for a 1.00 GiB page
    ....
    .....
    [  345.799753] io scheduler bfq registered
    [  126.753573] watchdog: BUG: soft lockup - CPU#0 stuck for 118s! [kworker/u4:0:9]
    [  126.759801] Modules linked in:
    [  126.762397] irq event stamp: 713

Thanks a lot for the help.
Cristian

Re: Circular lockdep in kvm_reset_vcpu() ?

[Marc Zyngier]

On 2023-03-14 11:04, Cristian Marussi wrote:
> On Tue, Mar 14, 2023 at 09:28:25AM +0000, Marc Zyngier wrote:
>> On 2023-03-13 18:20, Cristian Marussi wrote:
>> > On Mon, Mar 13, 2023 at 02:09:55PM +0000, Marc Zyngier wrote:
>> 
>> > > And -rc2 works just fine here.
>> >
>> > Thanks, I'll dig deeper what's going on un my setup.
>> 
>> Actually, you really want this patch[1] which is on its
>> way to Linus.
>> 
>> It could explain the issue you're seeing with SMP.
> 
> Hi Marc,
> 
> thanks this just solves for me on JUNO with guest SMP.
> 
> Indeed with earlycon on JUNO with SMP I was seeing, beside a lot of
> workqueue lockup that finally hanged the guest, some puzzling
> 'time-traveling' stamps that seemed to align more with the host time
> than the guest.

Yeah, my bad. Thankfully, Paolo just pulled the fix, and it should
make it into -rc3 (fingers crossed).

         M.
-- 
Jazz is not dead. It just smells funny...