Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Fri, 20 Jan 2023 12:00:01 +0000
Message-ID: <86r0vpmn5q.wl-maz@kernel.org>
From:   Marc Zyngier <maz@kernel.org>
To:     Shanker Donthineni <sdonthineni@nvidia.com>
Cc:     James Morse <james.morse@arm.com>,
        Catalin Marinas <catalin.marinas@arm.com>,
        Will Deacon <will@kernel.org>,
        linux-arm-kernel@lists.infradead.org, kvmarm@lists.linux.dev,
        linux-kernel@vger.kernel.org, Vikram Sethi <vsethi@nvidia.com>,
        Zenghui Yu <yuzenghui@huawei.com>,
        Oliver Upton <oliver.upton@linux.dev>,
        Suzuki K Poulose <suzuki.poulose@arm.com>,
        Ard Biesheuvel <ardb@kernel.org>
Subject: Re: [PATCH] KVM: arm64: vgic: Fix soft lockup during VM teardown
In-Reply-To: <b3bf3a46-410b-a756-dfd9-ee74d5dc31e0@nvidia.com>
References: <20230118022348.4137094-1-sdonthineni@nvidia.com>
        <863588njmt.wl-maz@kernel.org>
        <28061ceb-a7ce-0aca-a97d-8227dcfe6800@nvidia.com>
        <87bkmvdmna.wl-maz@kernel.org>
        <2e0c971a-0199-ff0d-c13c-d007d9f03122@nvidia.com>
        <86wn5imxm9.wl-maz@kernel.org>
        <b3bf3a46-410b-a756-dfd9-ee74d5dc31e0@nvidia.com>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI-EPG/1.14.7 (Harue)
 FLIM-LB/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL-LB/10.8 EasyPG/1.0.0 Emacs/28.2
 (aarch64-unknown-linux-gnu) MULE/6.0 (HANACHIRUSATO)
MIME-Version: 1.0 (generated by SEMI-EPG 1.14.7 - "Harue")
Content-Type: text/plain; charset=US-ASCII
Precedence: bulk

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.