| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <b3bf3a46-410b-a756-dfd9-ee74d5dc31e0@nvidia.com>
Date: Thu, 19 Jan 2023 23:02:15 -0600
From: Shanker Donthineni <sdonthineni@...dia.com>
To: Marc Zyngier <maz@...nel.org>
Cc: James Morse <james.morse@....com>,
Catalin Marinas <catalin.marinas@....com>,
Will Deacon <will@...nel.org>,
linux-arm-kernel@...ts.infradead.org, kvmarm@...ts.linux.dev,
linux-kernel@...r.kernel.org, Vikram Sethi <vsethi@...dia.com>,
Zenghui Yu <yuzenghui@...wei.com>,
Oliver Upton <oliver.upton@...ux.dev>,
Suzuki K Poulose <suzuki.poulose@....com>,
Ard Biesheuvel <ardb@...nel.org>
Subject: Re: [PATCH] KVM: arm64: vgic: Fix soft lockup during VM teardown
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(),
Time State
-----------------------
[277.684981] VM created
[278.158511] Started executing GICv4 init code
[545.092580] VGIC save/pending called
[545.099561] set IRQD_IRQ_INPROGRESS
[545.099562] clr IRQD_IRQ_INPROGRESS & irqd_set_activated() ---> same/close time
[545.163250] kvm_vm_release() called
Software:
Linux kernel: 6.2.0-rc4
QEMU: 7.1.0
Debug patch:
diff --git a/arch/arm64/kvm/vgic/vgic-kvm-device.c b/arch/arm64/kvm/vgic/vgic-kvm-device.c
index edeac2380591..da922ac72dc6 100644
--- a/arch/arm64/kvm/vgic/vgic-kvm-device.c
+++ b/arch/arm64/kvm/vgic/vgic-kvm-device.c
@@ -260,6 +260,7 @@ static int vgic_set_common_attr(struct kvm_device *dev,
mutex_unlock(&dev->kvm->lock);
return -EBUSY;
}
+ pr_err("%s(%d) called kvm=%px\n",__func__,__LINE__,dev->kvm);
r = vgic_v3_save_pending_tables(dev->kvm);
unlock_all_vcpus(dev->kvm);
mutex_unlock(&dev->kvm->lock);
diff --git a/arch/arm64/kvm/vgic/vgic-v3.c b/arch/arm64/kvm/vgic/vgic-v3.c
index 2074521d4a8c..91b53646f7ec 100644
--- a/arch/arm64/kvm/vgic/vgic-v3.c
+++ b/arch/arm64/kvm/vgic/vgic-v3.c
@@ -394,6 +394,7 @@ int vgic_v3_save_pending_tables(struct kvm *kvm)
* and enabling of the doorbells have already been done.
*/
if (kvm_vgic_global_state.has_gicv4_1) {
+ pr_err("%s(%d) called kvm=%px \n",__func__,__LINE__,kvm);
unmap_all_vpes(dist);
vlpi_avail = true;
}
@@ -443,8 +444,10 @@ int vgic_v3_save_pending_tables(struct kvm *kvm)
}
out:
- if (vlpi_avail)
+ if (vlpi_avail) {
+ pr_err("%s(%d) called kvm=%px \n",__func__,__LINE__,kvm);
map_all_vpes(dist);
+ }
diff --git a/arch/arm64/kvm/vgic/vgic-v4.c b/arch/arm64/kvm/vgic/vgic-v4.c
index ad06ba6c9b00..71d234844acd 100644
--- a/arch/arm64/kvm/vgic/vgic-v4.c
+++ b/arch/arm64/kvm/vgic/vgic-v4.c
@@ -264,10 +264,14 @@ int vgic_v4_init(struct kvm *kvm)
dist->its_vm.vpes = NULL;
return ret;
}
+ pr_err("%s(%d) called kvm=%px doorbell=%d(%d)\n", __func__, __LINE__, kvm, dist->its_vm.vpes[0]->irq, nr_vcpus);
kvm_for_each_vcpu(i, vcpu, kvm) {
int irq = dist->its_vm.vpes[i]->irq;
unsigned long irq_flags = DB_IRQ_FLAGS;
+ struct irq_desc *desc = irq_to_desc(irq);
+
+ desc->irq_data.dbgdata = kvm;
/*
* Don't automatically enable the doorbell, as we're
@@ -316,6 +320,8 @@ void vgic_v4_teardown(struct kvm *kvm)
if (!its_vm->vpes)
return;
+ pr_err("%s(%d) started kvm=%px doorbell=%d(%d)\n", __func__, __LINE__, kvm, its_vm->vpes[0]->irq, its_vm->nr_vpes);
+
for (i = 0; i < its_vm->nr_vpes; i++) {
struct kvm_vcpu *vcpu = kvm_get_vcpu(kvm, i);
int irq = its_vm->vpes[i]->irq;
@@ -324,6 +330,7 @@ void vgic_v4_teardown(struct kvm *kvm)
free_irq(irq, vcpu);
}
+ pr_err("%s(%d) finished kvm=%px doorbell=%d(%d)\n", __func__, __LINE__, kvm, its_vm->vpes[0]->irq, its_vm->nr_vpes);
its_free_vcpu_irqs(its_vm);
kfree(its_vm->vpes);
its_vm->nr_vpes = 0;
diff --git a/include/linux/irq.h b/include/linux/irq.h
index c3eb89606c2b..3e3d6ae8d59f 100644
--- a/include/linux/irq.h
+++ b/include/linux/irq.h
@@ -187,6 +187,8 @@ struct irq_data {
struct irq_data *parent_data;
#endif
void *chip_data;
+ unsigned long dbgtime[2];
+ void *dbgdata;
};
/*
@@ -390,12 +392,35 @@ static inline bool irqd_is_activated(struct irq_data *d)
static inline void irqd_set_activated(struct irq_data *d)
{
- __irqd_to_state(d) |= IRQD_ACTIVATED;
+ atomic_t *state = (atomic_t *)(&__irqd_to_state(d));
+ unsigned int new, old = __irqd_to_state(d);
+
+ new = atomic_xchg(state, old | IRQD_ACTIVATED);
+
+ if ((old ^ new) & IRQD_IRQ_INPROGRESS) {
+ pr_err("%s: CPU%u IRQ%u lost IRQD_IRQ_INPROGRESS old=0x%x new=0x%x, expected=0x%x kvm=%px\n",
+ __func__, raw_smp_processor_id(), d->irq,
+ old, old | IRQD_ACTIVATED, new | IRQD_ACTIVATED, d->dbgdata);
+ pr_err("%s: IRQD_IRQ_INPROGRESS set time [%5lu.%06u] \n", __func__, d->dbgtime[0], do_div(d->dbgtime[0], 1000000000)/1000);
+ pr_err("%s: IRQD_IRQ_INPROGRESS clr time [%5lu.%06u] \n", __func__, d->dbgtime[1], do_div(d->dbgtime[1], 1000000000)/1000);
+ }
+
}
static inline void irqd_clr_activated(struct irq_data *d)
{
- __irqd_to_state(d) &= ~IRQD_ACTIVATED;
+ atomic_t *state = (atomic_t *)(&__irqd_to_state(d));
+ unsigned int new, old = __irqd_to_state(d);
+
+ new = atomic_xchg(state, old & ~IRQD_ACTIVATED);
+
+ if ((old ^ new) & IRQD_IRQ_INPROGRESS) {
+ pr_err("%s: CPU%u IRQ%u lost IRQD_IRQ_INPROGRESS old=0x%x new=0x%x, expected=0x%x kvm=%px\n",
+ __func__, raw_smp_processor_id(), d->irq,
+ old, old & ~IRQD_ACTIVATED, new & ~IRQD_ACTIVATED, d->dbgdata);
+ pr_err("%s: IRQD_IRQ_INPROGRESS set time [%5lu.%06u] \n", __func__, d->dbgtime[0], do_div(d->dbgtime[0], 1000000000)/1000);
+ pr_err("%s: IRQD_IRQ_INPROGRESS clr time [%5lu.%06u] \n", __func__, d->dbgtime[1], do_div(d->dbgtime[1], 1000000000)/1000);
+ }
}
static inline bool irqd_is_started(struct irq_data *d)
diff --git a/kernel/irq/handle.c b/kernel/irq/handle.c
index 9489f93b3db3..5891ec27ae93 100644
--- a/kernel/irq/handle.c
+++ b/kernel/irq/handle.c
@@ -205,12 +205,14 @@ irqreturn_t handle_irq_event(struct irq_desc *desc)
desc->istate &= ~IRQS_PENDING;
irqd_set(&desc->irq_data, IRQD_IRQ_INPROGRESS);
+ desc->irq_data.dbgtime[0] = sched_clock();
raw_spin_unlock(&desc->lock);
ret = handle_irq_event_percpu(desc);
raw_spin_lock(&desc->lock);
irqd_clear(&desc->irq_data, IRQD_IRQ_INPROGRESS);
+ desc->irq_data.dbgtime[1] = sched_clock();
return ret;
}
diff --git a/virt/kvm/kvm_main.c b/virt/kvm/kvm_main.c
index 9c60384b5ae0..0fbf17ea3adb 100644
--- a/virt/kvm/kvm_main.c
+++ b/virt/kvm/kvm_main.c
@@ -1233,6 +1233,7 @@ static struct kvm *kvm_create_vm(unsigned long type, const char *fdname)
preempt_notifier_inc();
kvm_init_pm_notifier(kvm);
+ pr_err("%s(%d) called kvm=%px\n",__func__,__LINE__,kvm);
return kvm;
out_err:
@@ -1370,6 +1371,7 @@ static int kvm_vm_release(struct inode *inode, struct file *filp)
{
struct kvm *kvm = filp->private_data;
+ pr_err("%s(%d) called kvm=%px\n",__func__,__LINE__, kvm);
kvm_irqfd_release(kvm);
kvm_put_kvm(kvm);
return ret;
}
View attachment "gicv4-debug.txt" of type "text/plain" (124523 bytes)
Powered by blists - more mailing lists