Re: [PATCH] KVM: arm64: vgic: Fix soft lockup during VM teardown

[Marc Zyngier]

On Fri, 20 Jan 2023 05:02:15 +0000,
Shanker Donthineni <sdonthineni@xxxxxxxxxx> wrote:
> 
> [1  <text/plain; UTF-8 (7bit)>]
> Hi Marc,
> 
> On 1/19/23 08:01, Marc Zyngier wrote:
> >> On 1/19/23 01:11, Marc Zyngier wrote:
> >>> So you can see the VM being torn down while the vgic save sequence is
> >>> still in progress?
> >>> 
> >>> If you can actually see that, then this is a much bigger bug than the
> >>> simple race you are describing, and we're missing a reference on the
> >>> kvm structure. This would be a*MAJOR*  bug.
> >>> 
> >> How do we know vGIC save sequence is in progress while VM is being
> >> teardown?  I'm launching/terminating ~32 VMs in a loop to reproduce
> >> the issue.
> > Errr...*you*  know when you are issuing the save ioctl, right? You
> > also know when you are terminating the VM (closing its fd or killing
> > the VMM).
> > 
> 
> Added debug statements to trace the code patch, and tagged each log message
> with 'struct kvm *'. Attached the complete kernel log messages including
> debug messages.
> 
> All 32 VMs launched, time 258s to 291s
>  [  258.519837] kvm_create_vm(1236) called kvm=ffff8000303e0000  --> 1st VM
>  ...
>  [  291.801179] kvm_create_vm(1236) called kvm=ffff800057a60000   --> 32nd VM
> 
> Test script inside VM issues poweroff command after sleeping 200sec.
> 
> Working case kvm=ffff8000303e0000:
> 
>  $ cat gicv4-debug.txt | grep ffff8000303e0000
>   [  258.519837] kvm_create_vm(1236) called kvm=ffff8000303e0000
>   [  258.667101] vgic_v4_init(267) called kvm=ffff8000303e0000 doorbell=140(64)
>   [  517.942167] vgic_set_common_attr(263) called kvm=ffff8000303e0000
>   [  517.948415] vgic_v3_save_pending_tables(397) called kvm=ffff8000303e0000
>   [  517.955602] vgic_v3_save_pending_tables(448) called kvm=ffff8000303e0000
>   [  518.099696] kvm_vm_release(1374) called kvm=ffff8000303e0000
>   [  518.126833] vgic_v4_teardown(323) started kvm=ffff8000303e0000 doorbell=140(64)
>   [  518.134677] vgic_v4_teardown(333) finished kvm=ffff8000303e0000 doorbell=140(64)
> 
> Not working case kvm=ffff80001e0a0000:
> 
>  $ cat gicv4-debug.txt | grep ffff80001e0a0000
>   [  277.684981] kvm_create_vm(1236) called kvm=ffff80001e0a0000
>   [  278.158511] vgic_v4_init(267) called kvm=ffff80001e0a0000 doorbell=20812(64)
>   [  545.079117] vgic_set_common_attr(263) called kvm=ffff80001e0a0000
>   [  545.085358] vgic_v3_save_pending_tables(397) called kvm=ffff80001e0a0000
>   [  545.092580] vgic_v3_save_pending_tables(448) called kvm=ffff80001e0a0000
>   [  545.099562] irq: irqd_set_activated: CPU49 IRQ20821 lost IRQD_IRQ_INPROGRESS old=0x10401400 new=0x10401600, expected=0x10441600 kvm=ffff80001e0a0000^M
>   [  545.113177] irq: irqd_set_activated: IRQD_IRQ_INPROGRESS set time [545.099561]^M
>   [  545.121454] irq: irqd_set_activated: IRQD_IRQ_INPROGRESS clr time [545.099562]^M
>   [  545.129755] irq: irqd_set_activated: CPU49 IRQ20826 lost IRQD_IRQ_INPROGRESS old=0x10441400 new=0x10441600, expected=0x10401600 kvm=ffff80001e0a0000^M
>   [  545.143365] irq: irqd_set_activated: IRQD_IRQ_INPROGRESS set time [545.129754]^M
>   [  545.151654] irq: irqd_set_activated: IRQD_IRQ_INPROGRESS clr time [545.129755]^M
>   [  545.163250] kvm_vm_release(1374) called kvm=ffff80001e0a0000
>   [  545.169204] vgic_v4_teardown(323) started kvm=ffff80001e0a0000 doorbell=20812(64)
> 
> IRQD_IRQ_INPROGRESS is corrupted before calling kvm_vm_release(),

You keep missing my point. Yes, we have established the interrupt race
and have a way to fix it, let's move on...

What I am asking agin is: is there any overlap between any vgic ioctl
and the teardown of the VM? Do you ever see kvm_vm_release() being
called before kvm_device_release()?

Because that's the overlap I've been talking all along.

	M.

-- 
Without deviation from the norm, progress is not possible.