Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné <roger.pau@xxxxxxxxxx>]

On Fri, Nov 27, 2020 at 02:59:29PM +0100, Manuel Bouyer wrote:
> On Fri, Nov 27, 2020 at 02:40:22PM +0100, Jan Beulich wrote:
> > On 27.11.2020 14:31, Manuel Bouyer wrote:
> > > On Fri, Nov 27, 2020 at 02:18:54PM +0100, Jan Beulich wrote:
> > >> On 27.11.2020 14:13, Manuel Bouyer wrote:
> > >>> On Fri, Nov 27, 2020 at 12:29:35PM +0100, Jan Beulich wrote:
> > >>>> On 27.11.2020 11:59, Roger Pau Monné wrote:
> > >>>>> --- a/xen/arch/x86/hvm/irq.c
> > >>>>> +++ b/xen/arch/x86/hvm/irq.c
> > >>>>> @@ -187,6 +187,10 @@ void hvm_gsi_assert(struct domain *d, unsigned 
> > >>>>> int gsi)
> > >>>>>       * to know if the GSI is pending or not.
> > >>>>>       */
> > >>>>>      spin_lock(&d->arch.hvm.irq_lock);
> > >>>>> +    if ( gsi == TRACK_IRQ )
> > >>>>> +        debugtrace_printk("hvm_gsi_assert irq %u trig %u assert 
> > >>>>> count %u\n",
> > >>>>> +                          gsi, trig, hvm_irq->gsi_assert_count[gsi]);
> > >>>>
> > >>>> This produces
> > >>>>
> > >>>> 81961 hvm_gsi_assert irq 34 trig 1 assert count 1
> > >>>>
> > >>>> Since the logging occurs ahead of the call to assert_gsi(), it
> > >>>> means we don't signal anything to Dom0, because according to our
> > >>>> records there's still an IRQ in flight. Unfortunately we only
> > >>>> see the tail of the trace, so it's not possible to tell how / when
> > >>>> we got into this state.
> > >>>>
> > >>>> Manuel - is this the only patch you have in place? Or did you keep
> > >>>> any prior ones? Iirc there once was one where Roger also suppressed
> > >>>> some de-assert call.
> > >>>
> > >>> Yes, I have some of the previous patches (otherwise Xen panics).
> > >>> Attached is the diffs I currently have 
> > >>
> > >> I think you want to delete the hunk dropping the call to
> > >> hvm_gsi_deassert() from pt_irq_time_out(). Iirc it was that
> > >> addition which changed the behavior to just a single IRQ ever
> > >> making it into Dom0. And it ought to be only the change to
> > >> msix_write() which is needed to avoid the panic.
> > > 
> > > yes, I did keep the hvm_gsi_deassert() patch because I expected it
> > > to make things easier, as it allows to interract with Xen without changing
> > > interrupt states.
> > 
> > Right, but then we'd need to see the beginning of the trace,
> > rather than it starting at (in this case) about 95,000. Yet ...
> > 
> > > I removed it, here's a new trace
> > > 
> > > http://www-soc.lip6.fr/~bouyer/xen-log12.txt
> > 
> > ... hmm, odd - no change at all:
> > 
> > 95572 hvm_gsi_assert irq 34 trig 1 assert count 1
> 
> But I can confirm that now, entering ^A^A^A gets interrupt going in again

I think there are some weird things with dpci interrupts that I'm
trying to understand. I have a patch now that will panic when the
buffer is full, so we will hopefully be able to see the whole trace of
events. There will be no need for you to press the 'T' key now, the
system will panic when the buffer is full.

Note this patch also removes the deassert done in pt_irq_time_out.

Thanks, Roger.
---8<---
diff --git a/xen/arch/x86/hvm/irq.c b/xen/arch/x86/hvm/irq.c
index 38ac5fb6c7..9db3dcc957 100644
--- a/xen/arch/x86/hvm/irq.c
+++ b/xen/arch/x86/hvm/irq.c
@@ -187,6 +187,10 @@ void hvm_gsi_assert(struct domain *d, unsigned int gsi)
      * to know if the GSI is pending or not.
      */
     spin_lock(&d->arch.hvm.irq_lock);
+    if ( gsi == TRACK_IRQ )
+        debugtrace_printk("hvm_gsi_assert irq %u trig %u assert count %u\n",
+                          gsi, trig, hvm_irq->gsi_assert_count[gsi]);
+
     if ( trig == VIOAPIC_EDGE_TRIG || !hvm_irq->gsi_assert_count[gsi] )
     {
         if ( trig == VIOAPIC_LEVEL_TRIG )
diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..e6748e0649 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -257,7 +257,11 @@ static void vioapic_write_redirent(
         vlapic_adjust_i8259_target(d);
     }
     else if ( ent.fields.trig_mode == VIOAPIC_EDGE_TRIG )
+    {
+        if ( gsi == TRACK_IRQ )
+            debugtrace_printk("vIO-APIC set edge trigger irq %u\n", gsi);
         pent->fields.remote_irr = 0;
+    }
     else if ( !ent.fields.mask &&
               !ent.fields.remote_irr &&
               hvm_irq->gsi_assert_count[idx] )
@@ -278,6 +282,10 @@ static void vioapic_write_redirent(
          */
         int ret = vioapic_hwdom_map_gsi(gsi, ent.fields.trig_mode,
                                         ent.fields.polarity);
+
+        if ( gsi == TRACK_IRQ )
+            debugtrace_printk("vIO-APIC UNMASK irq %u\n", gsi);
+
         if ( ret )
         {
             gprintk(XENLOG_ERR,
@@ -285,6 +293,9 @@ static void vioapic_write_redirent(
             unmasked = 0;
         }
     }
+    else if ( is_hardware_domain(d) && gsi == TRACK_IRQ )
+        debugtrace_printk("vIO-APIC MASK irq %u\n", gsi);
+
 
     if ( gsi == 0 || unmasked )
         pt_may_unmask_irq(d, NULL);
@@ -405,6 +416,10 @@ static void vioapic_deliver(struct hvm_vioapic *vioapic, 
unsigned int pin)
 
     ASSERT(spin_is_locked(&d->arch.hvm.irq_lock));
 
+    if ( irq == TRACK_IRQ )
+            debugtrace_printk("vIO-APIC deliver irq %u vector %u\n",
+                              irq, vector);
+
     HVM_DBG_LOG(DBG_LEVEL_IOAPIC,
                 "dest=%x dest_mode=%x delivery_mode=%x "
                 "vector=%x trig_mode=%x",
diff --git a/xen/arch/x86/io_apic.c b/xen/arch/x86/io_apic.c
index 49bd778484..db7167eb4b 100644
--- a/xen/arch/x86/io_apic.c
+++ b/xen/arch/x86/io_apic.c
@@ -1641,6 +1641,9 @@ static void mask_and_ack_level_ioapic_irq(struct irq_desc 
*desc)
     unsigned long v;
     int i;
 
+    if ( desc->irq == TRACK_IRQ )
+        debugtrace_printk("ACK irq %u\n", desc->irq);
+
     irq_complete_move(desc);
 
     if ( !directed_eoi_enabled )
@@ -1688,6 +1691,9 @@ static void mask_and_ack_level_ioapic_irq(struct irq_desc 
*desc)
 
 static void end_level_ioapic_irq_old(struct irq_desc *desc, u8 vector)
 {
+    if ( desc->irq == TRACK_IRQ )
+        debugtrace_printk("END irq %u\n", desc->irq);
+
     if ( directed_eoi_enabled )
     {
         if ( !(desc->status & (IRQ_DISABLED|IRQ_MOVE_PENDING)) )
diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index 8d1f9a9fc6..ec52e44cb7 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -1109,6 +1109,10 @@ static void irq_guest_eoi_timer_fn(void *data)
     unsigned int i, irq = desc - irq_desc;
     irq_guest_action_t *action;
 
+    if ( desc->irq == TRACK_IRQ )
+        debugtrace_printk("irq_guest_eoi_timer_fn irq %u status %x\n",
+                          desc->irq, desc->status);
+
     spin_lock_irq(&desc->lock);
     
     if ( !(desc->status & IRQ_GUEST) )
@@ -1118,6 +1122,10 @@ static void irq_guest_eoi_timer_fn(void *data)
 
     ASSERT(action->ack_type != ACKTYPE_NONE);
 
+    if ( desc->irq == TRACK_IRQ )
+        debugtrace_printk("ack_type %u in_flight %u\n",
+                          action->ack_type, action->in_flight);
+
     /*
      * Is no IRQ in flight at all, or another instance of this timer already
      * running? Skip everything to avoid forcing an EOI early.
@@ -1837,6 +1845,12 @@ static void do_IRQ_guest(struct irq_desc *desc, unsigned 
int vector)
     unsigned int        i;
     struct pending_eoi *peoi = this_cpu(pending_eoi);
 
+    if ( desc->irq == TRACK_IRQ )
+        debugtrace_printk("do_IRQ_guest irq %u nr_guests %u ack_type %u 
in_flight %u\n",
+                          desc->irq, action->nr_guests, action->ack_type,
+                          action->in_flight);
+
+
     if ( unlikely(!action->nr_guests) )
     {
         /* An interrupt may slip through while freeing an ACKTYPE_EOI irq. */
diff --git a/xen/common/debugtrace.c b/xen/common/debugtrace.c
index f3794b9453..b22c09297d 100644
--- a/xen/common/debugtrace.c
+++ b/xen/common/debugtrace.c
@@ -130,14 +130,14 @@ static void debugtrace_toggle(void)
 
 void debugtrace_dump(void)
 {
-    unsigned long flags;
+    //unsigned long flags;
 
     watchdog_disable();
-    spin_lock_irqsave(&debugtrace_lock, flags);
+    //spin_lock_irqsave(&debugtrace_lock, flags);
 
     debugtrace_dump_worker();
 
-    spin_unlock_irqrestore(&debugtrace_lock, flags);
+    //spin_unlock_irqrestore(&debugtrace_lock, flags);
     watchdog_enable();
 }
 
@@ -152,7 +152,10 @@ static void debugtrace_add_to_buf(char *buf)
     {
         data->buf[data->prd++] = *p;
         if ( data->prd == debugtrace_bytes )
+        {
+            panic("END of buffer\n");
             data->prd = 0;
+        }
     }
 }
 
diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..c8fefc2648 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -174,7 +174,10 @@ static void pt_irq_time_out(void *data)
          * In the identity mapped case the EOI can also be done now, this way
          * the iteration over the list of domain pirqs is avoided.
          */
-        hvm_gsi_deassert(irq_map->dom, dpci_pirq(irq_map)->pirq);
+        if ( dpci_pirq(irq_map)->pirq == TRACK_IRQ )
+            debugtrace_printk("pt_irq_time_out irq %u\n",
+                              dpci_pirq(irq_map)->pirq);
+        //hvm_gsi_deassert(irq_map->dom, dpci_pirq(irq_map)->pirq);
         irq_map->flags |= HVM_IRQ_DPCI_EOI_LATCH;
         pt_irq_guest_eoi(irq_map->dom, irq_map, NULL);
         spin_unlock(&irq_map->dom->event_lock);
@@ -828,6 +831,9 @@ int hvm_do_IRQ_dpci(struct domain *d, struct pirq *pirq)
          !pirq_dpci || !(pirq_dpci->flags & HVM_IRQ_DPCI_MAPPED) )
         return 0;
 
+    if ( pirq->pirq == TRACK_IRQ )
+        debugtrace_printk("hvm_do_IRQ_dpci irq %u\n", pirq->pirq);
+
     pirq_dpci->masked = 1;
     raise_softirq_for(pirq_dpci);
     return 1;
@@ -1010,6 +1016,9 @@ void hvm_dpci_eoi(struct domain *d, unsigned int 
guest_gsi,
     if ( !is_iommu_enabled(d) )
         return;
 
+    if ( guest_gsi == TRACK_IRQ )
+        debugtrace_printk("hvm_dpci_eoi irq %u\n", guest_gsi);
+
     if ( is_hardware_domain(d) )
     {
         spin_lock(&d->event_lock);
diff --git a/xen/include/xen/irq.h b/xen/include/xen/irq.h
index 43d567fe44..91579c33b9 100644
--- a/xen/include/xen/irq.h
+++ b/xen/include/xen/irq.h
@@ -174,4 +174,6 @@ unsigned int arch_hwdom_irqs(domid_t);
 void arch_evtchn_bind_pirq(struct domain *, int pirq);
 #endif
 
+#define TRACK_IRQ 34
+
 #endif /* __XEN_IRQ_H__ */