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

Marc Zyngier
2023-01-20T12:00:11Z

On Fri, 20 Jan 2023 05:02:15 +0000,
Shanker Donthineni <sdonthineni@nvidia.com> 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.