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;
  }