NetBSD dom0 PVH: hardware interrupts stalls

NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

Hello,
so, after fixing an issue in the NetBSD kernel, related to PV clock
interrupts, I'm back with physical interrupts issues.
At some point in the initialisation, the dom0 kernel stops receiving
interrupts for its disks controller. The disk controller is:
[   1.0000030] mfii0 at pci6 dev 0 function 0: "PERC H740P Adapter ", firmware 51.13.0-3485, 8192MB cache
(XEN) d0: bind: m_gsi=34 g_gsi=34
[   1.0000030] allocated pic ioapic2 type level pin 2 level 6 to cpu0 slot 2 idt entry 103
[   1.0000030] mfii0: interrupting at ioapic2 pin 2

entering the NetBSD kenrel debugger and looking at interrupt counters,
I see that some interrupts did trigger on ioapic2 pin 2, as well as for
some other hardware controllers.
I did print the controller's status when the command times out, and
the controller says that there is an interrupt pending. So I guess that
the command was executed, but the dom0 kernel didn't get interupted.

At this point I can't say if other hardware controller interripts are
working (because of the lockdown I don't have physical access
to the hardware).

What's strange is that some Xen console activity seems to be enough to
resume interrupt activity. Hitting ^A 3 times is enough to get some progess
on the dom0's disk controller, and hitting 'v' is usually enough to
get the dom0 multiuser. Once there the systems looks stable, I can log
in from network. But I/O may stall again on reboot, maybe because the
dom0 kenrel is back using synchronous console output.

Any idea what to look at from here ?

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 17, 2020 at 04:09:49PM +0100, Manuel Bouyer wrote:
> Hello,
> so, after fixing an issue in the NetBSD kernel, related to PV clock
> interrupts, I'm back with physical interrupts issues.
> At some point in the initialisation, the dom0 kernel stops receiving
> interrupts for its disks controller. The disk controller is:
> [   1.0000030] mfii0 at pci6 dev 0 function 0: "PERC H740P Adapter ", firmware 51.13.0-3485, 8192MB cache
> (XEN) d0: bind: m_gsi=34 g_gsi=34
> [   1.0000030] allocated pic ioapic2 type level pin 2 level 6 to cpu0 slot 2 idt entry 103
> [   1.0000030] mfii0: interrupting at ioapic2 pin 2
> 
> entering the NetBSD kenrel debugger and looking at interrupt counters,
> I see that some interrupts did trigger on ioapic2 pin 2, as well as for
> some other hardware controllers.
> I did print the controller's status when the command times out, and
> the controller says that there is an interrupt pending. So I guess that
> the command was executed, but the dom0 kernel didn't get interupted.
> 
> At this point I can't say if other hardware controller interripts are
> working (because of the lockdown I don't have physical access
> to the hardware).
> 
> What's strange is that some Xen console activity seems to be enough to
> resume interrupt activity. Hitting ^A 3 times is enough to get some progess
> on the dom0's disk controller, and hitting 'v' is usually enough to
> get the dom0 multiuser. Once there the systems looks stable, I can log
> in from network. But I/O may stall again on reboot, maybe because the
> dom0 kenrel is back using synchronous console output.

Hm, certainly weird.

> Any idea what to look at from here ?

I have attached a patch below that will dump the vIO-APIC info as part
of the 'i' debug key output, can you paste the whole output of the 'i'
debug key when the system stalls?

Can you assert that you properly EOI the vectors on the local APIC? (I
don't have a patch to dump the emulated lapic ISR right now, but could
provide one if needed).

Roger.
---8<---
diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..fd0d75db80 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -30,6 +30,7 @@
 #include <xen/lib.h>
 #include <xen/errno.h>
 #include <xen/sched.h>
+#include <xen/softirq.h>
 #include <xen/nospec.h>
 #include <public/hvm/ioreq.h>
 #include <asm/hvm/io.h>
@@ -720,3 +721,34 @@ void vioapic_deinit(struct domain *d)
 
     vioapic_free(d, d->arch.hvm.nr_vioapics);
 }
+
+void vioapic_dump(void)
+{
+    const struct domain *d = hardware_domain;
+    unsigned int i;
+
+    if ( !has_vioapic(d) )
+        return;
+
+    printk("vIO-APIC dom%u state:\n", d->domain_id);
+    for ( i = 0; i < d->arch.hvm.nr_vioapics; i++ )
+    {
+        const struct hvm_vioapic *vioapic = domain_vioapic(d, i);
+        unsigned int j;
+
+        for ( j = 0; j < vioapic->nr_pins; j++ )
+        {
+            const union vioapic_redir_entry *ent = &vioapic->redirtbl[j];
+
+            printk("ioapic %u pin %u gsi %u vector %#x\n"
+                   "  delivery mode %u dest mode %u delivery status %u\n"
+                   "  polarity %u IRR %u trig mode %u mask %u dest id %u\n",
+                   i, j, vioapic->base_gsi + j, ent->fields.vector,
+                   ent->fields.delivery_mode, ent->fields.dest_mode,
+                   ent->fields.delivery_status, ent->fields.polarity,
+                   ent->fields.remote_irr, ent->fields.trig_mode,
+                   ent->fields.mask, ent->fields.dest_id);
+            process_pending_softirqs();
+        }
+    }
+}
diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index 8d1f9a9fc6..bd208efc58 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -24,6 +24,7 @@
 #include <asm/msi.h>
 #include <asm/current.h>
 #include <asm/flushtlb.h>
+#include <asm/hvm/vioapic.h>
 #include <asm/mach-generic/mach_apic.h>
 #include <irq_vectors.h>
 #include <public/physdev.h>
@@ -441,8 +442,15 @@ int __init init_irq_data(void)
     set_bit(HYPERCALL_VECTOR, used_vectors);
 #endif
     
-    /* IRQ_MOVE_CLEANUP_VECTOR used for clean up vectors */
-    set_bit(IRQ_MOVE_CLEANUP_VECTOR, used_vectors);
+    /*
+     * Mark vectors up to the cleanup one as used, to prevent an infinite loop
+     * in irq_move_cleanup_interrupt.
+     */
+    BUILD_BUG_ON(IRQ_MOVE_CLEANUP_VECTOR < FIRST_DYNAMIC_VECTOR);
+    for ( vector = FIRST_DYNAMIC_VECTOR;
+          vector <= IRQ_MOVE_CLEANUP_VECTOR;
+          vector++ )
+        set_bit(vector, used_vectors);
 
     return 0;
 }
@@ -727,10 +735,6 @@ void irq_move_cleanup_interrupt(struct cpu_user_regs *regs)
 {
     unsigned vector, me;
 
-    /* This interrupt should not nest inside others. */
-    BUILD_BUG_ON(APIC_PRIO_CLASS(IRQ_MOVE_CLEANUP_VECTOR) !=
-                 APIC_PRIO_CLASS(FIRST_DYNAMIC_VECTOR));
-
     ack_APIC_irq();
 
     me = smp_processor_id();
@@ -764,6 +768,8 @@ void irq_move_cleanup_interrupt(struct cpu_user_regs *regs)
              cpumask_test_cpu(me, desc->arch.cpu_mask) )
             goto unlock;
 
+        BUG_ON(vector <= IRQ_MOVE_CLEANUP_VECTOR);
+
         irr = apic_read(APIC_IRR + (vector / 32 * 0x10));
         /*
          * Check if the vector that needs to be cleanedup is
@@ -2524,6 +2530,7 @@ static void dump_irqs(unsigned char key)
             printk("   %#02x -> %ps()\n", i, direct_apic_vector[i]);
 
     dump_ioapic_irq_info();
+    vioapic_dump();
 }
 
 static int __init setup_dump_irqs(void)
diff --git a/xen/include/asm-x86/hvm/vioapic.h b/xen/include/asm-x86/hvm/vioapic.h
index d6f4e12d54..8a3ad18b20 100644
--- a/xen/include/asm-x86/hvm/vioapic.h
+++ b/xen/include/asm-x86/hvm/vioapic.h
@@ -70,4 +70,6 @@ int vioapic_get_mask(const struct domain *d, unsigned int gsi);
 int vioapic_get_vector(const struct domain *d, unsigned int gsi);
 int vioapic_get_trigger_mode(const struct domain *d, unsigned int gsi);
 
+void vioapic_dump(void);
+
 #endif /* __ASM_X86_HVM_VIOAPIC_H__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

[-- Attachment #1: Type: text/plain, Size: 1071 bytes --]

On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> [...]
> 
> I have attached a patch below that will dump the vIO-APIC info as part
> of the 'i' debug key output, can you paste the whole output of the 'i'
> debug key when the system stalls?

see attached file. Note that the kernel did unstall while 'i' output was
being printed, so it is mixed with some NetBSD kernel output.
The idt entry of the 'ioapic2 pin2' interrupt is 103 on CPU 0.

I also put the whole sequence at
http://www-soc.lip6.fr/~bouyer/xen-log3.txt

You'll see that I did hit 'i' 2 times to get the NetBSD kernel to boot
multiuser.

> 
> Can you assert that you properly EOI the vectors on the local APIC? (I
> don't have a patch to dump the emulated lapic ISR right now, but could
> provide one if needed).

Reading the code, I think it's OK (assuming I properly understood what
you mean too). Wouldn't it cause problems on real hardware too
if the vectors were not EOI'd ?

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

[-- Attachment #2: i.txt --]
[-- Type: text/plain, Size: 22044 bytes --]

(XEN) IRQ information:
(XEN)    IRQ:   0 vec:f0 IO-APIC-edge    status=000 aff:{0}/{0} arch/x86/time.c#timer_interrupt()
(XEN)    IRQ:   1 vec:70 IO-APIC-edge    status=006 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:   3 vec:f1 IO-APIC-edge    status=000 aff:{0-15}/{0-15} drivers/char/ns16550.c#ns16550_interrupt()
(XEN)    IRQ:   4 vec:78 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:   5 vec:88 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:   6 vec:90 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:   7 vec:98 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:   8 vec:a0 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:   9 vec:a8 IO-APIC-level   status=010 aff:{0}/{0} in-flight=0 d0:  9(-M-)
(XEN)    IRQ:  10 vec:b0 IO-APIC-edge    status=006 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:  11 vec:b8 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:  12 vec:c0 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:  13 vec:c8 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:  14 vec:d0 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:  15 vec:d8 IO-APIC-edge    status=002 aff:{0}/{0} mapped, unbound
(XEN)    IRQ:  16 vec:49 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=0 d0: 16(-M-)
(XEN)    IRQ:  34 vec:51 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
(XEN)    IRQ: 104 vec:30 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 105 vec:38 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 106 vec:40 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 107 vec:48 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 108 vec:50 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 109 vec:58 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 110 vec:60 DMA_MSI         status=000 aff:{0-223}/{0} drivers/passthrough/vtd/iommu.c#iommu_page_fault()
(XEN)    IRQ: 111 vec:68 DMA_MSI         status=000 aff:{0-223}/{0} [drivers/passthrough/vtd/iommu.c#iommu_page_fault()
 (XEN)    IRQ: 112 vec:e0 PCI-MSI         status=030 aff:{0}/{0-7}  in-flight=0 5d0:1143(-M-)
0(XEN)    IRQ: 113 vec:e8 PCI-MSI         status=010 aff:{0}/{0-7} .in-flight=0 3d0:1142(-M-)
5(XEN)    IRQ: 114 vec:31 PCI-MSI         status=030 aff:{0}/{0-7} 7in-flight=0 6d0:1141(-M-)
0(XEN)    IRQ: 115 vec:39 PCI-MSI/-X      status=030 aff:{0}/{0-7} 3in-flight=0 8d0:1140(-M-)
](XEN)    IRQ: 116 vec:41 PCI-MSI/-X      status=030 aff:{0}/{0-7}  in-flight=0 md0:1139(-M-)
f(XEN)    IRQ: 117 vec:8e PCI-MSI/-X      status=030 aff:{0}/{0-7} iin-flight=0 id0:1138(-M-)
0(XEN)    IRQ: 118 vec:96 PCI-MSI/-X      status=030 aff:{0}/{0-7} :in-flight=0  d0:1137(-M-)
c(XEN)    IRQ: 119 vec:9e PCI-MSI/-X      status=030 aff:{0}/{0-7} min-flight=0 dd0:1136(-M-)
 (XEN)    IRQ: 120 vec:a6 PCI-MSI/-X      status=030 aff:{0}/{0-7} ain-flight=0 bd0:1135(-M-)
o(XEN)    IRQ: 121 vec:ae PCI-MSI/-X      status=030 aff:{0}/{0-7} rin-flight=0 td0:1134(-M-)
e(XEN)    IRQ: 122 vec:b6 PCI-MSI/-X      status=030 aff:{0}/{0-7} din-flight=0  d0:1133(-M-)
c(XEN)    IRQ: 123 vec:be PCI-MSI/-X      status=030 aff:{0}/{0-7} cin-flight=0 bd0:1132(-M-)
 (XEN)    IRQ: 124 vec:c6 PCI-MSI/-X      status=030 aff:{0}/{0-7} 0in-flight=0 xd0:1131(-M-)
f(XEN)    IRQ: 125 vec:ce PCI-MSI/-X      status=030 aff:{0}/{0-7} fin-flight=0 fd0:1130(-M-)
f(XEN)    IRQ: 126 vec:d6 PCI-MSI/-X      status=030 aff:{0}/{0-7} 8in-flight=0 cd0:1129(-M-)
8(XEN)    IRQ: 127 vec:de PCI-MSI/-X      status=030 aff:{0}/{0-7} 0in-flight=0 0d0:1128(-M-)
2(XEN)    IRQ: 128 vec:e6 PCI-MSI/-X      status=030 aff:{0}/{0-7} 7in-flight=0 bd0:1127(-M-)
7(XEN)    IRQ: 129 vec:ee PCI-MSI/-X      status=030 aff:{0}/{0-7} din-flight=0 6d0:1126(-M-)
0(XEN)    IRQ: 130 vec:37 PCI-MSI/-X      status=030 aff:{0}/{0-7} in-flight=0 
d0:1125(-M-)
[(XEN)    IRQ: 131 vec:3f PCI-MSI/-X      status=030 aff:{0}/{0-7}  in-flight=0  d0:1124(-M-)
5(XEN)    IRQ: 132 vec:47 PCI-MSI/-X      status=030 aff:{0}/{0-7} 0in-flight=0 .d0:1123(-M-)
6(XEN)    IRQ: 133 vec:4f PCI-MSI/-X      status=030 aff:{0}/{0-7} 8in-flight=0 9d0:1122(-M-)
2(XEN)    IRQ: 134 vec:76 PCI-MSI/-X      status=030 aff:{0}/{0-7} 7in-flight=0 2d0:1121(-M-)
3(XEN)    IRQ: 135 vec:7e PCI-MSI/-X      status=030 aff:{0}/{0-7} ]in-flight=0  d0:1120(-M-)
m(XEN)    IRQ: 136 vec:86 PCI-MSI/-X      status=030 aff:{0}/{0-7} fin-flight=0 id0:1119(-M-)
i(XEN)    IRQ: 137 vec:57 PCI-MSI/-X      status=030 aff:{0}/{0-7} 0in-flight=0 :d0:1118(-M-)
 (XEN)    IRQ: 138 vec:5f PCI-MSI/-X      status=030 aff:{0}/{0-7} nin-flight=0 od0:1117(-M-)
r(XEN)    IRQ: 139 vec:67 PCI-MSI/-X      status=030 aff:{0}/{0-7} min-flight=0 ad0:1116(-M-)
l(XEN)    IRQ: 140 vec:6f PCI-MSI/-X      status=030 aff:{0}/{0-7}  in-flight=0 sd0:1115(-M-)
t(XEN)    IRQ: 141 vec:77 PCI-MSI/-X      status=030 aff:{0}/{0-7} ain-flight=0 td0:1114(-M-)
e(XEN)    IRQ: 142 vec:7f PCI-MSI/-X      status=030 aff:{0}/{0-7}  in-flight=0 od0:1113(-M-)
n(XEN)    IRQ: 143 vec:87 PCI-MSI/-X      status=030 aff:{0}/{0-7}  in-flight=0 'd0:1112(-M-)
m(XEN)    IRQ: 144 vec:8f PCI-MSI/-X      status=030 aff:{0}/{0-7} fin-flight=0 id0:1111(-M-)
i(XEN)    IRQ: 145 vec:97 PCI-MSI/-X      status=030 aff:{0}/{0-7} 0in-flight=0 :d0:1110(-M-)
0(XEN)    IRQ: 146 vec:9f PCI-MSI/-X      status=030 aff:{0}/{0-7} 'in-flight=0  d0:1109(-M-)
((XEN)    IRQ: 147 vec:a7 PCI-MSI/-X      status=030 aff:{0}/{0-7} oin-flight=0 nd0:1108(-M-)
l(XEN)    IRQ: 148 vec:af PCI-MSI/-X      status=030 aff:{0}/{0-7} iin-flight=0 nd0:1107(-M-)
e(XEN)    IRQ: 149 vec:b7 PCI-MSI/-X      status=030 aff:{0}/{0-7} )in-flight=0 d0:1106(-M-)

(XEN)    IRQ: 150 vec:bf PCI-MSI/-X      status=030 aff:{0}/{0-7} [in-flight=0  d0:1105(-M-)
 (XEN) Direct vector information:
5(XEN)    0x22 -> irq_move_cleanup_interrupt()
0(XEN)    0xf2 -> arch/x86/cpu/mcheck/mce_intel.c#cmci_interrupt()
.(XEN)    0xf3 -> arch/x86/cpu/mcheck/mce_intel.c#intel_thermal_interrupt()
7(XEN)    0xf4 -> arch/x86/hvm/vmx/vmx.c#pi_notification_interrupt()
1(XEN)    0xf9 -> pmu_apic_interrupt()
3(XEN)    0xfa -> apic_timer_interrupt()
8(XEN)    0xfb -> call_function_interrupt()
3(XEN)    0xfc -> event_check_interrupt()
7(XEN)    0xfd -> invalidate_interrupt()
3(XEN)    0xfe -> error_interrupt()
](XEN)    0xff -> spurious_interrupt()
 (XEN) IO-APIC interrupt information:
s(XEN)     IRQ  0 Vec240:
d(XEN)       Apic 0x00, Pin  2: 0vec=f0 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
:(XEN)     IRQ  1 Vec112:
 (XEN)       Apic 0x00, Pin  1: fvec=70 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
a(XEN)     IRQ  3 Vec241:
b(XEN)       Apic 0x00, Pin  3: rvec=f1 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00015555
i(XEN)     IRQ  4 Vec120:
c(XEN)       Apic 0x00, Pin  4: avec=78 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
t(XEN)     IRQ  5 Vec136:
i(XEN)       Apic 0x00, Pin  5: nvec=88 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
g(XEN)     IRQ  6 Vec144:
 (XEN)       Apic 0x00, Pin  6: avec=90 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
 (XEN)     IRQ  7 Vec152:
g(XEN)       Apic 0x00, Pin  7: evec=98 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
o(XEN)     IRQ  8 Vec160:
m(XEN)       Apic 0x00, Pin  8: evec=a0 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
t(XEN)     IRQ  9 Vec168:
r(XEN)       Apic 0x00, Pin  9: yvec=a8 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=L mask=0 dest_id:00000001
(XEN)     IRQ 10 Vec176:
(XEN)       Apic 0x00, Pin 10: 
vec=b0 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=1 dest_id:00000001
(XEN)     IRQ 11 Vec184:
(XEN)       Apic 0x00, Pin 11: vec=b8 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
[(XEN)     IRQ 12 Vec192:
 (XEN)       Apic 0x00, Pin 12:  vec=c0 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
5(XEN)     IRQ 13 Vec200:
1(XEN)       Apic 0x00, Pin 13: .vec=c8 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
3(XEN)     IRQ 14 Vec208:
9(XEN)       Apic 0x00, Pin 14: 3vec=d0 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
9(XEN)     IRQ 15 Vec216:
1(XEN)       Apic 0x00, Pin 15: 0vec=d8 delivery=LoPri dest=L status=0 polarity=0 irr=0 trig=E mask=0 dest_id:00000001
2(XEN)     IRQ 16 Vec 73:
](XEN)       Apic 0x00, Pin 16:  vec=49 delivery=LoPri dest=L status=0 polarity=1 irr=0 trig=L mask=0 dest_id:00000001
s(XEN)     IRQ 34 Vec 81:
d(XEN)       Apic 0x02, Pin  2: 0vec=51 delivery=LoPri dest=L status=0 polarity=1 irr=0 trig=L mask=0 dest_id:00000001
:(XEN) vIO-APIC dom0 state:
 (XEN) ioapic 0 pin 0 gsi 0 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
G(XEN) ioapic 0 pin 1 gsi 1 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
P(XEN) ioapic 0 pin 2 gsi 2 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
T(XEN) ioapic 0 pin 3 gsi 3 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 0 pin 4 gsi 4 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
G(XEN) ioapic 0 pin 5 gsi 5 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
U(XEN) ioapic 0 pin 6 gsi 6 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
I(XEN) ioapic 0 pin 7 gsi 7 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
D(XEN) ioapic 0 pin 8 gsi 8 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
:(XEN) ioapic 0 pin 9 gsi 9 vector 0x60
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 1 mask 0 dest id 0
 (XEN) ioapic 0 pin 10 gsi 10 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
4(XEN) ioapic 0 pin 11 gsi 11 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
c(XEN) ioapic 0 pin 12 gsi 12 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
d(XEN) ioapic 0 pin 13 gsi 13 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 0 pin 14 gsi 14 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
a(XEN) ioapic 0 pin 15 gsi 15 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
8(XEN) ioapic 0 pin 16 gsi 16 vector 0x66
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 0 dest id 0
9(XEN) ioapic 0 pin 17 gsi 17 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
7(XEN) ioapic 0 pin 18 gsi 18 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
-(XEN) ioapic 0 pin 19 gsi 19 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
b(XEN) ioapic 0 pin 20 gsi 20 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
5(XEN) ioapic 0 pin 21 gsi 21 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
9(XEN) ioapic 0 pin 22 gsi 22 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
1(XEN) ioapic 0 pin 23 gsi 23 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
-(XEN) ioapic 1 pin 0 gsi 24 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
4(XEN) ioapic 1 pin 1 gsi 25 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
5(XEN) ioapic 1 pin 2 gsi 26 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
c(XEN) ioapic 1 pin 3 gsi 27 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
5(XEN) ioapic 1 pin 4 gsi 28 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
-(XEN) ioapic 1 pin 5 gsi 29 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
8(XEN) ioapic 1 pin 6 gsi 30 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
6(XEN) ioapic 1 pin 7 gsi 31 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
7(XEN) ioapic 2 pin 0 gsi 32 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
9(XEN) ioapic 2 pin 1 gsi 33 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
-(XEN) ioapic 2 pin 2 gsi 34 vector 0x67
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 0 dest id 0
f(XEN) ioapic 2 pin 3 gsi 35 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
2(XEN) ioapic 2 pin 4 gsi 36 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
d(XEN) ioapic 2 pin 5 gsi 37 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
4(XEN) ioapic 2 pin 6 gsi 38 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
b(XEN) ioapic 2 pin 7 gsi 39 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
c(XEN) ioapic 3 pin 0 gsi 40 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 3 pin 1 gsi 41 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
d(XEN) ioapic 3 pin 2 gsi 42 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
8(XEN) ioapic 3 pin 3 gsi 43 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
3(XEN) ioapic 3 pin 4 gsi 44 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
c(XEN) ioapic 3 pin 5 gsi 45 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
8(XEN) ioapic 3 pin 6 gsi 46 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
(XEN) ioapic 3 pin 7 gsi 47 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0

(XEN) ioapic 4 pin 0 gsi 48 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
[(XEN) ioapic 4 pin 1 gsi 49 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 4 pin 2 gsi 50 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 4 pin 3 gsi 51 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
5(XEN) ioapic 4 pin 4 gsi 52 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
1(XEN) ioapic 4 pin 5 gsi 53 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
.(XEN) ioapic 4 pin 6 gsi 54 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
8(XEN) ioapic 4 pin 7 gsi 55 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
1(XEN) ioapic 5 pin 0 gsi 72 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 5 pin 1 gsi 73 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
3(XEN) ioapic 5 pin 2 gsi 74 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 5 pin 3 gsi 75 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
7(XEN) ioapic 5 pin 4 gsi 76 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
4(XEN) ioapic 5 pin 5 gsi 77 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
](XEN) ioapic 5 pin 6 gsi 78 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 5 pin 7 gsi 79 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
d(XEN) ioapic 6 pin 0 gsi 80 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
k(XEN) ioapic 6 pin 1 gsi 81 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 6 pin 2 gsi 82 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 6 pin 3 gsi 83 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
a(XEN) ioapic 6 pin 4 gsi 84 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
t(XEN) ioapic 6 pin 5 gsi 85 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 6 pin 6 gsi 86 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
s(XEN) ioapic 6 pin 7 gsi 87 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
d(XEN) ioapic 7 pin 0 gsi 88 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 7 pin 1 gsi 89 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
:(XEN) ioapic 7 pin 2 gsi 90 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 7 pin 3 gsi 91 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
"(XEN) ioapic 7 pin 4 gsi 92 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
r(XEN) ioapic 7 pin 5 gsi 93 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
o(XEN) ioapic 7 pin 6 gsi 94 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
o(XEN) ioapic 7 pin 7 gsi 95 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
t(XEN) ioapic 8 pin 0 gsi 96 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
"(XEN) ioapic 8 pin 1 gsi 97 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
,(XEN) ioapic 8 pin 2 gsi 98 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
 (XEN) ioapic 8 pin 3 gsi 99 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
1(XEN) ioapic 8 pin 4 gsi 100 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
0(XEN) ioapic 8 pin 5 gsi 101 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
2(XEN) ioapic 8 pin 6 gsi 102 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0
4(XEN) ioapic 8 pin 7 gsi 103 vector 0
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 0 IRR 0 trig mode 0 mask 1 dest id 0

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 17, 2020 at 05:40:33PM +0100, Manuel Bouyer wrote:
> On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> > [...]
> > 
> > I have attached a patch below that will dump the vIO-APIC info as part
> > of the 'i' debug key output, can you paste the whole output of the 'i'
> > debug key when the system stalls?
> 
> see attached file. Note that the kernel did unstall while 'i' output was
> being printed, so it is mixed with some NetBSD kernel output.
> The idt entry of the 'ioapic2 pin2' interrupt is 103 on CPU 0.
> 
> I also put the whole sequence at
> http://www-soc.lip6.fr/~bouyer/xen-log3.txt

On one of the instances the pin shows up as masked, but I'm not sure
if that's relevant since later it shows up as unmasked. Might just be
part of how NetBSD handles such interrupts.

So taking a look at the information dumped:

(XEN)     IRQ 34 Vec 81:
(XEN)       Apic 0x02, Pin  2: 5vec=51 delivery=LoPri dest=L status=1 polarity=1 irr=1 trig=L mask=0 dest_id:00000001
(XEN) ioapic 2 pin 2 gsi 34 vector 0x67
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 1 dest id 0
[...]
(XEN)     IRQ 34 Vec 81:
(XEN)       Apic 0x02, Pin  2: 0vec=51 delivery=LoPri dest=L status=0 polarity=1 irr=0 trig=L mask=0 dest_id:00000001
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 0 dest id 0

The state between the physical IO-APIC and the emulated one seems
consistent at least.

On a maybe unrelated question, how do you setup the event channel
callback, is it using HVM_PARAM_CALLBACK_IRQ and
HVM_PARAM_CALLBACK_TYPE_VECTOR?

Are you EOI'ing such vector on the local APIC when servicing the
interrupt?

> You'll see that I did hit 'i' 2 times to get the NetBSD kernel to boot
> multiuser.
> 
> > 
> > Can you assert that you properly EOI the vectors on the local APIC? (I
> > don't have a patch to dump the emulated lapic ISR right now, but could
> > provide one if needed).
> 
> Reading the code, I think it's OK (assuming I properly understood what
> you mean too). Wouldn't it cause problems on real hardware too
> if the vectors were not EOI'd ?

Yes it should, just wasn't sure whether NetBSD would use the same
handler code when running under Xen.

I was mostly asking because Xen has a weird semantic with the vector
callback when using HVM_PARAM_CALLBACK_IRQ, see above.

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 17.11.2020 17:40, Manuel Bouyer wrote:
> On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
>> [...]
>>
>> I have attached a patch below that will dump the vIO-APIC info as part
>> of the 'i' debug key output, can you paste the whole output of the 'i'
>> debug key when the system stalls?
> 
> see attached file. Note that the kernel did unstall while 'i' output was
> being printed, so it is mixed with some NetBSD kernel output.

Could you try to run Xen's serial port without use of any IRQ
(i.e. in "polling" mode), in an attempt to avoid this unstalling
(which is likely to render the resulting output at least in part
meaningless)?

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Wed, Nov 18, 2020 at 09:57:38AM +0100, Roger Pau Monné wrote:
> On Tue, Nov 17, 2020 at 05:40:33PM +0100, Manuel Bouyer wrote:
> > On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> > > [...]
> > > 
> > > I have attached a patch below that will dump the vIO-APIC info as part
> > > of the 'i' debug key output, can you paste the whole output of the 'i'
> > > debug key when the system stalls?
> > 
> > see attached file. Note that the kernel did unstall while 'i' output was
> > being printed, so it is mixed with some NetBSD kernel output.
> > The idt entry of the 'ioapic2 pin2' interrupt is 103 on CPU 0.
> > 
> > I also put the whole sequence at
> > http://www-soc.lip6.fr/~bouyer/xen-log3.txt
> 
> On one of the instances the pin shows up as masked, but I'm not sure
> if that's relevant since later it shows up as unmasked. Might just be
> part of how NetBSD handles such interrupts.

Yes, NetBSD can mask an interrupt source if the interrupts needs to be delayed.
It will be unmasked once the interrupt has been handled.

Would it be possible that Xen misses an unmask write, or fails to
call the vector if the interrupt is again pending at the time of the
unmask ?


> [...]
> On a maybe unrelated question, how do you setup the event channel
> callback, is it using HVM_PARAM_CALLBACK_IRQ and
> HVM_PARAM_CALLBACK_TYPE_VECTOR?

Yes, the code is at
https://github.com/NetBSD/src/blob/f9a54eaecfb47bce597f72f6cae8861f4d486eb4/sys/arch/xen/xen/hypervisor.c#L457

> 
> Are you EOI'ing such vector on the local APIC when servicing the
> interrupt?

I think it's OK. the code is at
https://github.com/NetBSD/src/blob/f9a54eaecfb47bce597f72f6cae8861f4d486eb4/sys/arch/amd64/amd64/vector.S#L770

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Wed, Nov 18, 2020 at 10:16:17AM +0100, Jan Beulich wrote:
> On 17.11.2020 17:40, Manuel Bouyer wrote:
> > On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> >> [...]
> >>
> >> I have attached a patch below that will dump the vIO-APIC info as part
> >> of the 'i' debug key output, can you paste the whole output of the 'i'
> >> debug key when the system stalls?
> > 
> > see attached file. Note that the kernel did unstall while 'i' output was
> > being printed, so it is mixed with some NetBSD kernel output.
> 
> Could you try to run Xen's serial port without use of any IRQ
> (i.e. in "polling" mode), in an attempt to avoid this unstalling
> (which is likely to render the resulting output at least in part
> meaningless)?

It there a boot line option for that ?

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 18.11.2020 10:28, Manuel Bouyer wrote:
> On Wed, Nov 18, 2020 at 10:16:17AM +0100, Jan Beulich wrote:
>> On 17.11.2020 17:40, Manuel Bouyer wrote:
>>> On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
>>>> [...]
>>>>
>>>> I have attached a patch below that will dump the vIO-APIC info as part
>>>> of the 'i' debug key output, can you paste the whole output of the 'i'
>>>> debug key when the system stalls?
>>>
>>> see attached file. Note that the kernel did unstall while 'i' output was
>>> being printed, so it is mixed with some NetBSD kernel output.
>>
>> Could you try to run Xen's serial port without use of any IRQ
>> (i.e. in "polling" mode), in an attempt to avoid this unstalling
>> (which is likely to render the resulting output at least in part
>> meaningless)?
> 
> It there a boot line option for that ?

Yes, com<N>= has a field for this:

### com1
### com2
> `= <baud>[/<base-baud>][,[DPS][,[<io-base>|pci|amt][,[<irq>|msi][,[<port-bdf>][,[<bridge-bdf>]]]]]]`

with

* `<irq>` is the IRQ number to use, or `0` to use the UART in poll
  mode only, or `msi` to set up a Message Signaled Interrupt.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Wed, Nov 18, 2020 at 10:24:25AM +0100, Manuel Bouyer wrote:
> On Wed, Nov 18, 2020 at 09:57:38AM +0100, Roger Pau Monné wrote:
> > On Tue, Nov 17, 2020 at 05:40:33PM +0100, Manuel Bouyer wrote:
> > > On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> > > > [...]
> > > > 
> > > > I have attached a patch below that will dump the vIO-APIC info as part
> > > > of the 'i' debug key output, can you paste the whole output of the 'i'
> > > > debug key when the system stalls?
> > > 
> > > see attached file. Note that the kernel did unstall while 'i' output was
> > > being printed, so it is mixed with some NetBSD kernel output.
> > > The idt entry of the 'ioapic2 pin2' interrupt is 103 on CPU 0.
> > > 
> > > I also put the whole sequence at
> > > http://www-soc.lip6.fr/~bouyer/xen-log3.txt
> > 
> > On one of the instances the pin shows up as masked, but I'm not sure
> > if that's relevant since later it shows up as unmasked. Might just be
> > part of how NetBSD handles such interrupts.
> 
> Yes, NetBSD can mask an interrupt source if the interrupts needs to be delayed.
> It will be unmasked once the interrupt has been handled.

Yes, I think that's roughly the same model that FreeBSD uses for
level IO-APIC interrupts: mask it until the handlers have been run.

> Would it be possible that Xen misses an unmask write, or fails to
> call the vector if the interrupt is again pending at the time of the
> unmask ?

Well, it should work properly, but we cannot discard anything.

> > [...]
> > On a maybe unrelated question, how do you setup the event channel
> > callback, is it using HVM_PARAM_CALLBACK_IRQ and
> > HVM_PARAM_CALLBACK_TYPE_VECTOR?
> 
> Yes, the code is at
> https://github.com/NetBSD/src/blob/f9a54eaecfb47bce597f72f6cae8861f4d486eb4/sys/arch/xen/xen/hypervisor.c#L457
> 
> > 
> > Are you EOI'ing such vector on the local APIC when servicing the
> > interrupt?
> 
> I think it's OK. the code is at
> https://github.com/NetBSD/src/blob/f9a54eaecfb47bce597f72f6cae8861f4d486eb4/sys/arch/amd64/amd64/vector.S#L770

Yes, it's fine as you also have support for the newly per-CPU vector
callback which does require an EOI.

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Wed, Nov 18, 2020 at 10:43:27AM +0100, Jan Beulich wrote:
> On 18.11.2020 10:28, Manuel Bouyer wrote:
> > On Wed, Nov 18, 2020 at 10:16:17AM +0100, Jan Beulich wrote:
> >> On 17.11.2020 17:40, Manuel Bouyer wrote:
> >>> On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> >>>> [...]
> >>>>
> >>>> I have attached a patch below that will dump the vIO-APIC info as part
> >>>> of the 'i' debug key output, can you paste the whole output of the 'i'
> >>>> debug key when the system stalls?
> >>>
> >>> see attached file. Note that the kernel did unstall while 'i' output was
> >>> being printed, so it is mixed with some NetBSD kernel output.
> >>
> >> Could you try to run Xen's serial port without use of any IRQ
> >> (i.e. in "polling" mode), in an attempt to avoid this unstalling
> >> (which is likely to render the resulting output at least in part
> >> meaningless)?
> > 
> > It there a boot line option for that ?
> 
> Yes, com<N>= has a field for this:
> 
> ### com1
> ### com2
> > `= <baud>[/<base-baud>][,[DPS][,[<io-base>|pci|amt][,[<irq>|msi][,[<port-bdf>][,[<bridge-bdf>]]]]]]`
> 
> with
> 
> * `<irq>` is the IRQ number to use, or `0` to use the UART in poll
>   mode only, or `msi` to set up a Message Signaled Interrupt.

thanks.
This marginally changes the boot behavior (the kenrel hangs a little bit
earlier) but switching the console input to Xen is enough to get some
interrupt, and hitting 'i' causes again the boot to complete.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 18.11.2020 11:14, Manuel Bouyer wrote:
> On Wed, Nov 18, 2020 at 10:43:27AM +0100, Jan Beulich wrote:
>> On 18.11.2020 10:28, Manuel Bouyer wrote:
>>> On Wed, Nov 18, 2020 at 10:16:17AM +0100, Jan Beulich wrote:
>>>> On 17.11.2020 17:40, Manuel Bouyer wrote:
>>>>> On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
>>>>>> [...]
>>>>>>
>>>>>> I have attached a patch below that will dump the vIO-APIC info as part
>>>>>> of the 'i' debug key output, can you paste the whole output of the 'i'
>>>>>> debug key when the system stalls?
>>>>>
>>>>> see attached file. Note that the kernel did unstall while 'i' output was
>>>>> being printed, so it is mixed with some NetBSD kernel output.
>>>>
>>>> Could you try to run Xen's serial port without use of any IRQ
>>>> (i.e. in "polling" mode), in an attempt to avoid this unstalling
>>>> (which is likely to render the resulting output at least in part
>>>> meaningless)?
>>>
>>> It there a boot line option for that ?
>>
>> Yes, com<N>= has a field for this:
>>
>> ### com1
>> ### com2
>>> `= <baud>[/<base-baud>][,[DPS][,[<io-base>|pci|amt][,[<irq>|msi][,[<port-bdf>][,[<bridge-bdf>]]]]]]`
>>
>> with
>>
>> * `<irq>` is the IRQ number to use, or `0` to use the UART in poll
>>   mode only, or `msi` to set up a Message Signaled Interrupt.
> 
> thanks.
> This marginally changes the boot behavior (the kenrel hangs a little bit
> earlier) but switching the console input to Xen is enough to get some
> interrupt, and hitting 'i' causes again the boot to complete.

That's unfortunate for the purposes here, but thanks for trying.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Wed, Nov 18, 2020 at 11:00:25AM +0100, Roger Pau Monné wrote:
> On Wed, Nov 18, 2020 at 10:24:25AM +0100, Manuel Bouyer wrote:
> > On Wed, Nov 18, 2020 at 09:57:38AM +0100, Roger Pau Monné wrote:
> > > On Tue, Nov 17, 2020 at 05:40:33PM +0100, Manuel Bouyer wrote:
> > > > On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> > > > > [...]
> > > > > 
> > > > > I have attached a patch below that will dump the vIO-APIC info as part
> > > > > of the 'i' debug key output, can you paste the whole output of the 'i'
> > > > > debug key when the system stalls?
> > > > 
> > > > see attached file. Note that the kernel did unstall while 'i' output was
> > > > being printed, so it is mixed with some NetBSD kernel output.
> > > > The idt entry of the 'ioapic2 pin2' interrupt is 103 on CPU 0.
> > > > 
> > > > I also put the whole sequence at
> > > > http://www-soc.lip6.fr/~bouyer/xen-log3.txt
> > > 
> > > On one of the instances the pin shows up as masked, but I'm not sure
> > > if that's relevant since later it shows up as unmasked. Might just be
> > > part of how NetBSD handles such interrupts.
> > 
> > Yes, NetBSD can mask an interrupt source if the interrupts needs to be delayed.
> > It will be unmasked once the interrupt has been handled.
> 
> Yes, I think that's roughly the same model that FreeBSD uses for
> level IO-APIC interrupts: mask it until the handlers have been run.
> 
> > Would it be possible that Xen misses an unmask write, or fails to
> > call the vector if the interrupt is again pending at the time of the
> > unmask ?
> 
> Well, it should work properly, but we cannot discard anything.

I did some more instrumentation from the NetBSD kernel, including dumping
the iopic2 pin2 register.

At the time of the command timeout, the register value is 0x0000a067,
which, if I understant it properly, menas that there's no interrupt
pending (bit IOAPIC_REDLO_RIRR, 0x00004000, is not set).
From the NetBSD ddb, I can dump this register multiple times, waiting
several seconds, etc .., it doens't change).
Now if I call ioapic_dump_raw() from the debugger, which triggers some
XEN printf:
db{0}> call ioapic_dump_raw^M
Register dump of ioapic0^M
[ 203.5489060] 00 08000000 00170011 08000000(XEN) vioapic.c:124:d0v0 apic_mem_re
adl:undefined ioregsel 3
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
 00000000^M
[ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
 00000000^M
[ 203.5489060] 10 00010000 00000000 00010000 00000000 00010000 00000000 00010000 00000000^M
[...]
[ 203.5489060] Register dump of ioapic2^M
[ 203.5489060] 00 0a000000 00070011 0a000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 3
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
 00000000^M
[ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
 00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
 00000000^M
[ 203.5489060] 10 00010000 00000000 00010000 00000000 0000e067 00000000 00010000 00000000^M

then the register switches to 0000e067, with the IOAPIC_REDLO_RIRR bit set.
From here, if I continue from ddb, the dom0 boots.

I can get the same effect by just doing ^A^A^A so my guess is that it's
not accessing the iopic's register which changes the IOAPIC_REDLO_RIRR bit,
but the XEN printf. Also, from NetBSD, using a dump fuinction which
doesn't access undefined registers - and so doesn't trigger XEN printfs -
doens't change the IOAPIC_REDLO_RIRR bit either.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Wed, Nov 18, 2020 at 01:14:03PM +0100, Manuel Bouyer wrote:
> On Wed, Nov 18, 2020 at 11:00:25AM +0100, Roger Pau Monné wrote:
> > On Wed, Nov 18, 2020 at 10:24:25AM +0100, Manuel Bouyer wrote:
> > > On Wed, Nov 18, 2020 at 09:57:38AM +0100, Roger Pau Monné wrote:
> > > > On Tue, Nov 17, 2020 at 05:40:33PM +0100, Manuel Bouyer wrote:
> > > > > On Tue, Nov 17, 2020 at 04:58:07PM +0100, Roger Pau Monné wrote:
> > > > > > [...]
> > > > > > 
> > > > > > I have attached a patch below that will dump the vIO-APIC info as part
> > > > > > of the 'i' debug key output, can you paste the whole output of the 'i'
> > > > > > debug key when the system stalls?
> > > > > 
> > > > > see attached file. Note that the kernel did unstall while 'i' output was
> > > > > being printed, so it is mixed with some NetBSD kernel output.
> > > > > The idt entry of the 'ioapic2 pin2' interrupt is 103 on CPU 0.
> > > > > 
> > > > > I also put the whole sequence at
> > > > > http://www-soc.lip6.fr/~bouyer/xen-log3.txt
> > > > 
> > > > On one of the instances the pin shows up as masked, but I'm not sure
> > > > if that's relevant since later it shows up as unmasked. Might just be
> > > > part of how NetBSD handles such interrupts.
> > > 
> > > Yes, NetBSD can mask an interrupt source if the interrupts needs to be delayed.
> > > It will be unmasked once the interrupt has been handled.
> > 
> > Yes, I think that's roughly the same model that FreeBSD uses for
> > level IO-APIC interrupts: mask it until the handlers have been run.
> > 
> > > Would it be possible that Xen misses an unmask write, or fails to
> > > call the vector if the interrupt is again pending at the time of the
> > > unmask ?
> > 
> > Well, it should work properly, but we cannot discard anything.
> 
> I did some more instrumentation from the NetBSD kernel, including dumping
> the iopic2 pin2 register.
> 
> At the time of the command timeout, the register value is 0x0000a067,
> which, if I understant it properly, menas that there's no interrupt
> pending (bit IOAPIC_REDLO_RIRR, 0x00004000, is not set).
> From the NetBSD ddb, I can dump this register multiple times, waiting
> several seconds, etc .., it doens't change).
> Now if I call ioapic_dump_raw() from the debugger, which triggers some
> XEN printf:
> db{0}> call ioapic_dump_raw^M
> Register dump of ioapic0^M
> [ 203.5489060] 00 08000000 00170011 08000000(XEN) vioapic.c:124:d0v0 apic_mem_re
> adl:undefined ioregsel 3
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
>  00000000^M
> [ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
>  00000000^M
> [ 203.5489060] 10 00010000 00000000 00010000 00000000 00010000 00000000 00010000 00000000^M
> [...]
> [ 203.5489060] Register dump of ioapic2^M
> [ 203.5489060] 00 0a000000 00070011 0a000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 3
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
>  00000000^M
> [ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
>  00000000^M
> [ 203.5489060] 10 00010000 00000000 00010000 00000000 0000e067 00000000 00010000 00000000^M
> 
> then the register switches to 0000e067, with the IOAPIC_REDLO_RIRR bit set.
> From here, if I continue from ddb, the dom0 boots.
> 
> I can get the same effect by just doing ^A^A^A so my guess is that it's
> not accessing the iopic's register which changes the IOAPIC_REDLO_RIRR bit,
> but the XEN printf. Also, from NetBSD, using a dump fuinction which
> doesn't access undefined registers - and so doesn't trigger XEN printfs -
> doens't change the IOAPIC_REDLO_RIRR bit either.

I'm thinking about further ways to debug this. I see that all active
IO-APIC pins are routed to vCPU0, but does it make a difference if you
boot with dom0_max_vcpus=1 on the Xen command line? (thus limiting
NertBSD dom0 to a single CPU)

I can also prepare a patch that will periodically dump the same stuff
as the 'i' debug key without you having to press anything, but I'm not
sure if it would help much.

Also, does the system work fine when you reach multiuser, or it also
randomly freezes and requires further poking?

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 18.11.2020 15:39, Roger Pau Monné wrote:
> On Wed, Nov 18, 2020 at 01:14:03PM +0100, Manuel Bouyer wrote:
>> I did some more instrumentation from the NetBSD kernel, including dumping
>> the iopic2 pin2 register.
>>
>> At the time of the command timeout, the register value is 0x0000a067,
>> which, if I understant it properly, menas that there's no interrupt
>> pending (bit IOAPIC_REDLO_RIRR, 0x00004000, is not set).
>> From the NetBSD ddb, I can dump this register multiple times, waiting
>> several seconds, etc .., it doens't change).
>> Now if I call ioapic_dump_raw() from the debugger, which triggers some
>> XEN printf:
>> db{0}> call ioapic_dump_raw^M
>> Register dump of ioapic0^M
>> [ 203.5489060] 00 08000000 00170011 08000000(XEN) vioapic.c:124:d0v0 apic_mem_re
>> adl:undefined ioregsel 3
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
>>  00000000^M
>> [ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
>>  00000000^M
>> [ 203.5489060] 10 00010000 00000000 00010000 00000000 00010000 00000000 00010000 00000000^M
>> [...]
>> [ 203.5489060] Register dump of ioapic2^M
>> [ 203.5489060] 00 0a000000 00070011 0a000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 3
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
>>  00000000^M
>> [ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
>>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
>>  00000000^M
>> [ 203.5489060] 10 00010000 00000000 00010000 00000000 0000e067 00000000 00010000 00000000^M
>>
>> then the register switches to 0000e067, with the IOAPIC_REDLO_RIRR bit set.
>> From here, if I continue from ddb, the dom0 boots.
>>
>> I can get the same effect by just doing ^A^A^A so my guess is that it's
>> not accessing the iopic's register which changes the IOAPIC_REDLO_RIRR bit,
>> but the XEN printf. Also, from NetBSD, using a dump fuinction which
>> doesn't access undefined registers - and so doesn't trigger XEN printfs -
>> doens't change the IOAPIC_REDLO_RIRR bit either.
> 
> I'm thinking about further ways to debug this. I see that all active
> IO-APIC pins are routed to vCPU0, but does it make a difference if you
> boot with dom0_max_vcpus=1 on the Xen command line? (thus limiting
> NertBSD dom0 to a single CPU)

I too have been pondering possible approaches. One thing I thought might
help is accompany all places setting remote_irr (and calling
vioapic_deliver()) with a conditional log message, turning on the
condition immediately before the first "undefined ioregsel" gets logged.
(And turn it off again once the last RTE was read in sequence, just to
avoid spamming the console.) From Manuel's description above, there has
to be something that sets the bit and causes the delivery _without_ any
active action by the guest (i.e. neither EOI nor RTE write) and
_without_ any new instance of the IRQ appearing. I have some vague hope
that knowing how we end up making the system make progress again may
also help understand how it got stuck.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Wed, Nov 18, 2020 at 03:39:28PM +0100, Roger Pau Monné wrote:
> > [...]
> > I can get the same effect by just doing ^A^A^A so my guess is that it's
> > not accessing the iopic's register which changes the IOAPIC_REDLO_RIRR bit,
> > but the XEN printf. Also, from NetBSD, using a dump fuinction which
> > doesn't access undefined registers - and so doesn't trigger XEN printfs -
> > doens't change the IOAPIC_REDLO_RIRR bit either.
> 
> I'm thinking about further ways to debug this. I see that all active
> IO-APIC pins are routed to vCPU0, but does it make a difference if you
> boot with dom0_max_vcpus=1 on the Xen command line? (thus limiting
> NertBSD dom0 to a single CPU)

No, the same issue happens

> 
> I can also prepare a patch that will periodically dump the same stuff
> as the 'i' debug key without you having to press anything, but I'm not
> sure if it would help much.

I think the key is to read all the interresting stuff before printing,
as it seems that printing to console is what change states.

> 
> Also, does the system work fine when you reach multiuser, or it also
> randomly freezes and requires further poking?

I let it run overnight, with some cron jobs firing and it didn't wedge.
I guess that once the kernel autoconf is done, the window in which
the interrupt is masked at the ioapic level is much shorter, making the
problem much less likely to happen.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

[-- Attachment #1: Type: text/plain, Size: 5267 bytes --]

On Wed, Nov 18, 2020 at 03:59:44PM +0100, Jan Beulich wrote:
> On 18.11.2020 15:39, Roger Pau Monné wrote:
> > On Wed, Nov 18, 2020 at 01:14:03PM +0100, Manuel Bouyer wrote:
> >> I did some more instrumentation from the NetBSD kernel, including dumping
> >> the iopic2 pin2 register.
> >>
> >> At the time of the command timeout, the register value is 0x0000a067,
> >> which, if I understant it properly, menas that there's no interrupt
> >> pending (bit IOAPIC_REDLO_RIRR, 0x00004000, is not set).
> >> From the NetBSD ddb, I can dump this register multiple times, waiting
> >> several seconds, etc .., it doens't change).
> >> Now if I call ioapic_dump_raw() from the debugger, which triggers some
> >> XEN printf:
> >> db{0}> call ioapic_dump_raw^M
> >> Register dump of ioapic0^M
> >> [ 203.5489060] 00 08000000 00170011 08000000(XEN) vioapic.c:124:d0v0 apic_mem_re
> >> adl:undefined ioregsel 3
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
> >>  00000000^M
> >> [ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
> >>  00000000^M
> >> [ 203.5489060] 10 00010000 00000000 00010000 00000000 00010000 00000000 00010000 00000000^M
> >> [...]
> >> [ 203.5489060] Register dump of ioapic2^M
> >> [ 203.5489060] 00 0a000000 00070011 0a000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 3
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 4
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 5
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 6
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 7
> >>  00000000^M
> >> [ 203.5489060] 08(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 8
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel 9
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel a
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel b
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel c
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel d
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel e
> >>  00000000(XEN) vioapic.c:124:d0v0 apic_mem_readl:undefined ioregsel f
> >>  00000000^M
> >> [ 203.5489060] 10 00010000 00000000 00010000 00000000 0000e067 00000000 00010000 00000000^M
> >>
> >> then the register switches to 0000e067, with the IOAPIC_REDLO_RIRR bit set.
> >> From here, if I continue from ddb, the dom0 boots.
> >>
> >> I can get the same effect by just doing ^A^A^A so my guess is that it's
> >> not accessing the iopic's register which changes the IOAPIC_REDLO_RIRR bit,
> >> but the XEN printf. Also, from NetBSD, using a dump fuinction which
> >> doesn't access undefined registers - and so doesn't trigger XEN printfs -
> >> doens't change the IOAPIC_REDLO_RIRR bit either.
> > 
> > I'm thinking about further ways to debug this. I see that all active
> > IO-APIC pins are routed to vCPU0, but does it make a difference if you
> > boot with dom0_max_vcpus=1 on the Xen command line? (thus limiting
> > NertBSD dom0 to a single CPU)
> 
> I too have been pondering possible approaches. One thing I thought might
> help is accompany all places setting remote_irr (and calling
> vioapic_deliver()) with a conditional log message, turning on the
> condition immediately before the first "undefined ioregsel" gets logged.
> (And turn it off again once the last RTE was read in sequence, just to
> avoid spamming the console.) From Manuel's description above, there has
> to be something that sets the bit and causes the delivery _without_ any
> active action by the guest (i.e. neither EOI nor RTE write) and
> _without_ any new instance of the IRQ appearing. I have some vague hope
> that knowing how we end up making the system make progress again may
> also help understand how it got stuck.

I've got two different debug patches for you to try. I'm attaching both
to this email but I think we should start with Jan's suggestion
(conditional_print.patch). That patch will only print extra messages
between the ioregsel 3 ... ioregsel f existing debug messages, you
will have to trigger this from NetBSD by using ioapic_dump_raw AFAICT.

The other patch (verbose_intr.patch) adds some messages related to
interrupts, but I'm afraid it's likely to interfere with the issue we
are trying to debug, since it will add a lot of extra printk's (and
likely flood your console).

Thanks, Roger.

[-- Attachment #2: conditional_print.patch --]
[-- Type: text/plain, Size: 2002 bytes --]

From 9f1cf4f5f4f143be2d9e87d1b2f4c4cf4c286b69 Mon Sep 17 00:00:00 2001
From: Roger Pau Monne <roger.pau@citrix.com>
Date: Thu, 19 Nov 2020 14:11:43 +0100
Subject: [PATCH]

---
 xen/arch/x86/hvm/vioapic.c | 20 ++++++++++++++++++--
 1 file changed, 18 insertions(+), 2 deletions(-)

diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..9c0423b26e 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -43,7 +43,13 @@
 /* HACK: Route IRQ0 only to VCPU0 to prevent time jumps. */
 #define IRQ0_SPECIAL_ROUTING 1
 
-static void vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int irq);
+static void _vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int irq);
+
+static bool __read_mostly print;
+#define vioapic_deliver(vioapic, irq) ({\
+    if ( print && irq == 34 ) \
+        printk("%s:%d:%s: vioapic_deliver\n", __FILE__, __LINE__, __func__); \
+    _vioapic_deliver(vioapic, irq); })
 
 static struct hvm_vioapic *addr_vioapic(const struct domain *d,
                                         unsigned long addr)
@@ -119,6 +125,16 @@ static uint32_t vioapic_read_indirect(const struct hvm_vioapic *vioapic)
 
         if ( redir_index >= vioapic->nr_pins )
         {
+            switch ( vioapic->ioregsel )
+            {
+            case 3:
+                print = true;
+                break;
+
+            case 0xf:
+                print = false;
+                break;
+            }
             gdprintk(XENLOG_WARNING, "apic_mem_readl:undefined ioregsel %x\n",
                      vioapic->ioregsel);
             break;
@@ -391,7 +407,7 @@ static void ioapic_inj_irq(
     vlapic_set_irq(target, vector, trig_mode);
 }
 
-static void vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int pin)
+static void _vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int pin)
 {
     uint16_t dest = vioapic->redirtbl[pin].fields.dest_id;
     uint8_t dest_mode = vioapic->redirtbl[pin].fields.dest_mode;
-- 
2.29.2


[-- Attachment #3: verbose_intr.patch --]
[-- Type: text/plain, Size: 2950 bytes --]

From 381eebe51657a3b3101dc80880fa3350dcfb1e23 Mon Sep 17 00:00:00 2001
From: Roger Pau Monne <roger.pau@citrix.com>
Date: Thu, 19 Nov 2020 10:45:00 +0100
Subject: [PATCH]

---
 xen/arch/x86/hvm/vioapic.c   | 9 +++++++++
 xen/arch/x86/irq.c           | 3 +++
 xen/drivers/passthrough/io.c | 3 +++
 xen/include/asm-x86/irq.h    | 2 ++
 4 files changed, 17 insertions(+)

diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..1702434f0d 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -235,6 +235,10 @@ static void vioapic_write_redirent(
     pent = &vioapic->redirtbl[idx];
     ent  = *pent;
 
+    if ( gsi == TRACK_IRQ )
+        printk("vioapic write %s word %d val %#x current %#lx\n",
+               top_word ? "top" : "low", val, ent.bits);
+
     if ( top_word )
     {
         /* Contains only the dest_id. */
@@ -410,6 +414,9 @@ static void vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int pin)
                 "vector=%x trig_mode=%x",
                 dest, dest_mode, delivery_mode, vector, trig_mode);
 
+    if ( irq == TRACK_IRQ )
+        printk("vioapic inject vector %#x\n", vector);
+
     switch ( delivery_mode )
     {
     case dest_LowestPrio:
@@ -517,6 +524,8 @@ void vioapic_update_EOI(struct domain *d, u8 vector)
                 continue;
 
             ent->fields.remote_irr = 0;
+            if ( vioapic->base_gsi + pin == TRACK_IRQ )
+                printk("vioapic EOI\n");
 
             if ( is_iommu_enabled(d) )
             {
diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index 8d1f9a9fc6..34f50a24ea 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -1837,6 +1837,9 @@ 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 )
+        printk("do_IRQ_guest\n");
+
     if ( unlikely(!action->nr_guests) )
     {
         /* An interrupt may slip through while freeing an ACKTYPE_EOI irq. */
diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..ddbda10593 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -997,6 +997,9 @@ static void hvm_gsi_eoi(struct domain *d, unsigned int gsi,
     if ( !pirq_dpci(pirq) )
         return;
 
+    if ( gsi == TRACK_IRQ )
+        printk("dpci EOI\n");
+
     hvm_gsi_deassert(d, gsi);
     hvm_pirq_eoi(pirq, ent);
 }
diff --git a/xen/include/asm-x86/irq.h b/xen/include/asm-x86/irq.h
index 7c825e9d9c..bb450e5e59 100644
--- a/xen/include/asm-x86/irq.h
+++ b/xen/include/asm-x86/irq.h
@@ -218,4 +218,6 @@ int allocate_and_map_gsi_pirq(struct domain *d, int index, int *pirq_p);
 int allocate_and_map_msi_pirq(struct domain *d, int index, int *pirq_p,
                               int type, struct msi_info *msi);
 
+#define TRACK_IRQ 34
+
 #endif /* _ASM_HW_IRQ_H */
-- 
2.29.2

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Thu, Nov 19, 2020 at 03:19:15PM +0100, Roger Pau Monné wrote:
> I've got two different debug patches for you to try. I'm attaching both
> to this email but I think we should start with Jan's suggestion
> (conditional_print.patch). That patch will only print extra messages
> between the ioregsel 3 ... ioregsel f existing debug messages, you
> will have to trigger this from NetBSD by using ioapic_dump_raw AFAICT.

thanks. I didn't see any change in behavior or XEN output with this
patch (especially the vioapic_deliver string doesn't show up in the
logs).

> 
> The other patch (verbose_intr.patch) adds some messages related to
> interrupts, but I'm afraid it's likely to interfere with the issue we
> are trying to debug, since it will add a lot of extra printk's (and
> likely flood your console).

with this one, the console is indeed flooded, and the dom0 boots without
problem.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Thu, Nov 19, 2020 at 04:57:18PM +0100, Manuel Bouyer wrote:
> On Thu, Nov 19, 2020 at 03:19:15PM +0100, Roger Pau Monné wrote:
> > I've got two different debug patches for you to try. I'm attaching both
> > to this email but I think we should start with Jan's suggestion
> > (conditional_print.patch). That patch will only print extra messages
> > between the ioregsel 3 ... ioregsel f existing debug messages, you
> > will have to trigger this from NetBSD by using ioapic_dump_raw AFAICT.
> 
> thanks. I didn't see any change in behavior or XEN output with this
> patch (especially the vioapic_deliver string doesn't show up in the
> logs).

I tried forcing print to 1, and I still don't see "vioapic_deliver" on the
console. I changed the patch to:
#define vioapic_deliver(vioapic, irq) ({\ 
    if ( /* print && irq == 34 */ 1 ) \
        printk("%s:%d:%s: vioapic_deliver %d\n", __FILE__, __LINE__, __func__, i
rq); \
    _vioapic_deliver(vioapic, irq); })

and got:
[  13.8853432] ioapic2: pin2 0x0000a067 0x00000000^M
[  13.8853432] mfii0: cmd timeout ccb 0xffff9780023b7d60 status 0x40000008^M
(XEN) *** Serial input to Xen (type 'CTRL-a' three times to switch input)
(XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
[  17.0001093] mfii0: cmd aborted ccb 0xffff9780023b7d60^M
(XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
[  17.0217772] config_pending_decr: scsibus0 0^M
(XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
[  17.(XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
0417095] config_finalize 2185^M

So I guess that the interrupt delivery on XEN output is
vioapic.c:511

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Thu, Nov 19, 2020 at 05:57:34PM +0100, Manuel Bouyer wrote:
> On Thu, Nov 19, 2020 at 04:57:18PM +0100, Manuel Bouyer wrote:
> > On Thu, Nov 19, 2020 at 03:19:15PM +0100, Roger Pau Monné wrote:
> > > I've got two different debug patches for you to try. I'm attaching both
> > > to this email but I think we should start with Jan's suggestion
> > > (conditional_print.patch). That patch will only print extra messages
> > > between the ioregsel 3 ... ioregsel f existing debug messages, you
> > > will have to trigger this from NetBSD by using ioapic_dump_raw AFAICT.
> > 
> > thanks. I didn't see any change in behavior or XEN output with this
> > patch (especially the vioapic_deliver string doesn't show up in the
> > logs).
> 
> I tried forcing print to 1, and I still don't see "vioapic_deliver" on the
> console. I changed the patch to:
> #define vioapic_deliver(vioapic, irq) ({\ 
>     if ( /* print && irq == 34 */ 1 ) \
>         printk("%s:%d:%s: vioapic_deliver %d\n", __FILE__, __LINE__, __func__, i
> rq); \
>     _vioapic_deliver(vioapic, irq); })
> 
> and got:
> [  13.8853432] ioapic2: pin2 0x0000a067 0x00000000^M
> [  13.8853432] mfii0: cmd timeout ccb 0xffff9780023b7d60 status 0x40000008^M
> (XEN) *** Serial input to Xen (type 'CTRL-a' three times to switch input)
> (XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
> [  17.0001093] mfii0: cmd aborted ccb 0xffff9780023b7d60^M
> (XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
> [  17.0217772] config_pending_decr: scsibus0 0^M
> (XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
> [  17.(XEN) vioapic.c:511:vioapic_irq_positive_edge: vioapic_deliver 2
> 0417095] config_finalize 2185^M
> 
> So I guess that the interrupt delivery on XEN output is
> vioapic.c:511

I added an ASSERT() after the printf to ket a stack trace, and got:
db{0}> call ioapic_dump_raw^M
Register dump of ioapic0^M
[  13.0193374] 00 08000000 00170011 08000000(XEN) vioapic.c:141:d0v0 apic_mem_readl:undefined ioregsel 3
(XEN) vioapic.c:512:vioapic_irq_positive_edge: vioapic_deliver 2
(XEN) Assertion '!print' failed at vioapic.c:512
(XEN) ----[ Xen-4.15-unstable  x86_64  debug=y   Tainted:   C   ]----
(XEN) CPU:    0
(XEN) RIP:    e008:[<ffff82d0402c4164>] vioapic_irq_positive_edge+0x14e/0x150
(XEN) RFLAGS: 0000000000010202   CONTEXT: hypervisor (d0v0)
(XEN) rax: ffff82d0405c806c   rbx: ffff830836650580   rcx: 0000000000000000
(XEN) rdx: ffff8300688bffff   rsi: 000000000000000a   rdi: ffff82d0404b36b8
(XEN) rbp: ffff8300688bfde0   rsp: ffff8300688bfdc0   r8:  0000000000000004
(XEN) r9:  0000000000000032   r10: 0000000000000000   r11: 00000000fffffffd
(XEN) r12: ffff8308366dc000   r13: 0000000000000022   r14: ffff8308366dc31c
(XEN) r15: ffff8308366d1d80   cr0: 0000000080050033   cr4: 00000000003526e0
(XEN) cr3: 00000008366c9000   cr2: 0000000000000000
(XEN) fsb: 0000000000000000   gsb: 0000000000000000   gss: 0000000000000000
(XEN) ds: 0000   es: 0000   fs: 0000   gs: 0000   ss: 0000   cs: e008
(XEN) Xen code around <ffff82d0402c4164> (vioapic_irq_positive_edge+0x14e/0x150):
(XEN)  3d 10 be 1d 00 00 74 c2 <0f> 0b 55 48 89 e5 41 57 41 56 41 55 41 54 53 48
(XEN) Xen stack trace from rsp=ffff8300688bfdc0:
(XEN)    0000000200000086 ffff8308366dc000 0000000000000022 0000000000000000
(XEN)    ffff8300688bfe08 ffff82d0402bcc33 ffff8308366dc000 0000000000000022
(XEN)    0000000000000001 ffff8300688bfe40 ffff82d0402bd18f ffff830835a7eb98
(XEN)    ffff8308366dc000 ffff830835a7eb40 ffff8300688bfe68 0100100100100100
(XEN)    ffff8300688bfea0 ffff82d04026f6e1 ffff830835a7eb30 ffff8308366dc0f4
(XEN)    ffff830835a7eb40 ffff8300688bfe68 ffff8300688bfe68 ffff82d0405cec80
(XEN)    ffffffffffffffff ffff82d0405cec80 0000000000000000 ffff82d0405d6c80
(XEN)    ffff8300688bfed8 ffff82d04022b6fa ffff83083663f000 ffff83083663f000
(XEN)    0000000000000000 0000000000000000 0000000a7c62165b ffff8300688bfee8
(XEN)    ffff82d04022b798 ffff8300688bfe08 ffff82d0402a4bcb 0000000000000000
(XEN)    0000000000000206 ffff8316da86e61c ffff8316da86e600 ffff938031fd47c0
(XEN)    0000000000000003 0000000000000400 ff889e8da08f928a 0000000000000000
(XEN)    0000000000000002 0000000000000100 000000000000b86e ffff93803237f010
(XEN)    0000000000000000 ffff8316da86e61c 0000beef0000beef ffffffff80555918
(XEN)    000000bf0000beef 0000000000000046 ffff938031fd4790 000000000000beef
(XEN)    000000000000beef 000000000000beef 000000000000beef 000000000000beef
(XEN)    0000e01000000000 ffff83083663f000 0000000000000000 00000000003526e0
(XEN)    0000000000000000 0000000000000000 0000060100000001 0000000000000000
(XEN) Xen call trace:
(XEN)    [<ffff82d0402c4164>] R vioapic_irq_positive_edge+0x14e/0x150
(XEN)    [<ffff82d0402bcc33>] F arch/x86/hvm/irq.c#assert_gsi+0x5e/0x7b
(XEN)    [<ffff82d0402bd18f>] F hvm_gsi_assert+0x62/0x77
(XEN)    [<ffff82d04026f6e1>] F drivers/passthrough/io.c#dpci_softirq+0x261/0x29e
(XEN)    [<ffff82d04022b6fa>] F common/softirq.c#__do_softirq+0x8a/0xbf
(XEN)    [<ffff82d04022b798>] F do_softirq+0x13/0x15
(XEN)    [<ffff82d0402a4bcb>] F vmx_asm_do_vmentry+0x2b/0x30
(XEN) 
(XEN) 
(XEN) ****************************************
(XEN) Panic on CPU 0:
(XEN) Assertion '!print' failed at vioapic.c:512
(XEN) ****************************************


hope this helps ...

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 19.11.2020 18:57, Manuel Bouyer wrote:
> I added an ASSERT() after the printf to ket a stack trace, and got:
> db{0}> call ioapic_dump_raw^M
> Register dump of ioapic0^M
> [  13.0193374] 00 08000000 00170011 08000000(XEN) vioapic.c:141:d0v0 apic_mem_readl:undefined ioregsel 3
> (XEN) vioapic.c:512:vioapic_irq_positive_edge: vioapic_deliver 2
> (XEN) Assertion '!print' failed at vioapic.c:512
> (XEN) ----[ Xen-4.15-unstable  x86_64  debug=y   Tainted:   C   ]----
> (XEN) CPU:    0
> (XEN) RIP:    e008:[<ffff82d0402c4164>] vioapic_irq_positive_edge+0x14e/0x150
> (XEN) RFLAGS: 0000000000010202   CONTEXT: hypervisor (d0v0)
> (XEN) rax: ffff82d0405c806c   rbx: ffff830836650580   rcx: 0000000000000000
> (XEN) rdx: ffff8300688bffff   rsi: 000000000000000a   rdi: ffff82d0404b36b8
> (XEN) rbp: ffff8300688bfde0   rsp: ffff8300688bfdc0   r8:  0000000000000004
> (XEN) r9:  0000000000000032   r10: 0000000000000000   r11: 00000000fffffffd
> (XEN) r12: ffff8308366dc000   r13: 0000000000000022   r14: ffff8308366dc31c
> (XEN) r15: ffff8308366d1d80   cr0: 0000000080050033   cr4: 00000000003526e0
> (XEN) cr3: 00000008366c9000   cr2: 0000000000000000
> (XEN) fsb: 0000000000000000   gsb: 0000000000000000   gss: 0000000000000000
> (XEN) ds: 0000   es: 0000   fs: 0000   gs: 0000   ss: 0000   cs: e008
> (XEN) Xen code around <ffff82d0402c4164> (vioapic_irq_positive_edge+0x14e/0x150):
> (XEN)  3d 10 be 1d 00 00 74 c2 <0f> 0b 55 48 89 e5 41 57 41 56 41 55 41 54 53 48
> (XEN) Xen stack trace from rsp=ffff8300688bfdc0:
> (XEN)    0000000200000086 ffff8308366dc000 0000000000000022 0000000000000000
> (XEN)    ffff8300688bfe08 ffff82d0402bcc33 ffff8308366dc000 0000000000000022
> (XEN)    0000000000000001 ffff8300688bfe40 ffff82d0402bd18f ffff830835a7eb98
> (XEN)    ffff8308366dc000 ffff830835a7eb40 ffff8300688bfe68 0100100100100100
> (XEN)    ffff8300688bfea0 ffff82d04026f6e1 ffff830835a7eb30 ffff8308366dc0f4
> (XEN)    ffff830835a7eb40 ffff8300688bfe68 ffff8300688bfe68 ffff82d0405cec80
> (XEN)    ffffffffffffffff ffff82d0405cec80 0000000000000000 ffff82d0405d6c80
> (XEN)    ffff8300688bfed8 ffff82d04022b6fa ffff83083663f000 ffff83083663f000
> (XEN)    0000000000000000 0000000000000000 0000000a7c62165b ffff8300688bfee8
> (XEN)    ffff82d04022b798 ffff8300688bfe08 ffff82d0402a4bcb 0000000000000000
> (XEN)    0000000000000206 ffff8316da86e61c ffff8316da86e600 ffff938031fd47c0
> (XEN)    0000000000000003 0000000000000400 ff889e8da08f928a 0000000000000000
> (XEN)    0000000000000002 0000000000000100 000000000000b86e ffff93803237f010
> (XEN)    0000000000000000 ffff8316da86e61c 0000beef0000beef ffffffff80555918
> (XEN)    000000bf0000beef 0000000000000046 ffff938031fd4790 000000000000beef
> (XEN)    000000000000beef 000000000000beef 000000000000beef 000000000000beef
> (XEN)    0000e01000000000 ffff83083663f000 0000000000000000 00000000003526e0
> (XEN)    0000000000000000 0000000000000000 0000060100000001 0000000000000000
> (XEN) Xen call trace:
> (XEN)    [<ffff82d0402c4164>] R vioapic_irq_positive_edge+0x14e/0x150
> (XEN)    [<ffff82d0402bcc33>] F arch/x86/hvm/irq.c#assert_gsi+0x5e/0x7b
> (XEN)    [<ffff82d0402bd18f>] F hvm_gsi_assert+0x62/0x77
> (XEN)    [<ffff82d04026f6e1>] F drivers/passthrough/io.c#dpci_softirq+0x261/0x29e
> (XEN)    [<ffff82d04022b6fa>] F common/softirq.c#__do_softirq+0x8a/0xbf
> (XEN)    [<ffff82d04022b798>] F do_softirq+0x13/0x15
> (XEN)    [<ffff82d0402a4bcb>] F vmx_asm_do_vmentry+0x2b/0x30
> (XEN) 
> (XEN) 
> (XEN) ****************************************
> (XEN) Panic on CPU 0:
> (XEN) Assertion '!print' failed at vioapic.c:512
> (XEN) ****************************************

Right, this was the expected path after what you've sent prior to this.
Which turned my attention back to the 'i' debug key output you had sent
the other day. There we have

(XEN)    IRQ:  34 vec:51 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)

i.e. at that point we're waiting for Dom0 to signal it's done handling
the IRQ. There is, however, a timer associated with this. Yet that's
actually to prevent the system getting stuck, i.e. the "in-flight"
state ought to clear 1ms later (when that timer expires), and hence
ought to be pretty unlikely to catch when non-zero _and_ something's
actually stuck.

So for the softirq to get Dom0 out of its stuck state, there has got to
be yet some other event. Nevertheless it may be worthwhile
instrumenting irq_guest_eoi_timer_fn() to prove we actually take this
path, i.e. Xen is trying to "clean up" after Dom0 taking too long to
service an IRQ. In normal operation this path shouldn't be taken, so I
wouldn't exclude something got broken in that logic. (Orthogonal to
this it may also be worth seeing whether increasing the timeout would
actually help things. This wouldn't be a solution, but another data
point hinting something's wrong on this code path.)

Roger, I'm also somewhat puzzled by the trailing (-MM): Is PVH using
event channels for delivering pIRQ-s? I thought that's purely vIO-APIC
and vMSI? I wonder whether we misleadingly dump info from evtchn 0
here, in which case only the 2nd of the M-s would be meaningful (and
would be in line with non-zero in-flight).

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Fri, Nov 20, 2020 at 09:09:51AM +0100, Jan Beulich wrote:
> On 19.11.2020 18:57, Manuel Bouyer wrote:
> > I added an ASSERT() after the printf to ket a stack trace, and got:
> > db{0}> call ioapic_dump_raw^M
> > Register dump of ioapic0^M
> > [  13.0193374] 00 08000000 00170011 08000000(XEN) vioapic.c:141:d0v0 apic_mem_readl:undefined ioregsel 3
> > (XEN) vioapic.c:512:vioapic_irq_positive_edge: vioapic_deliver 2
> > (XEN) Assertion '!print' failed at vioapic.c:512
> > (XEN) ----[ Xen-4.15-unstable  x86_64  debug=y   Tainted:   C   ]----
> > (XEN) CPU:    0
> > (XEN) RIP:    e008:[<ffff82d0402c4164>] vioapic_irq_positive_edge+0x14e/0x150
> > (XEN) RFLAGS: 0000000000010202   CONTEXT: hypervisor (d0v0)
> > (XEN) rax: ffff82d0405c806c   rbx: ffff830836650580   rcx: 0000000000000000
> > (XEN) rdx: ffff8300688bffff   rsi: 000000000000000a   rdi: ffff82d0404b36b8
> > (XEN) rbp: ffff8300688bfde0   rsp: ffff8300688bfdc0   r8:  0000000000000004
> > (XEN) r9:  0000000000000032   r10: 0000000000000000   r11: 00000000fffffffd
> > (XEN) r12: ffff8308366dc000   r13: 0000000000000022   r14: ffff8308366dc31c
> > (XEN) r15: ffff8308366d1d80   cr0: 0000000080050033   cr4: 00000000003526e0
> > (XEN) cr3: 00000008366c9000   cr2: 0000000000000000
> > (XEN) fsb: 0000000000000000   gsb: 0000000000000000   gss: 0000000000000000
> > (XEN) ds: 0000   es: 0000   fs: 0000   gs: 0000   ss: 0000   cs: e008
> > (XEN) Xen code around <ffff82d0402c4164> (vioapic_irq_positive_edge+0x14e/0x150):
> > (XEN)  3d 10 be 1d 00 00 74 c2 <0f> 0b 55 48 89 e5 41 57 41 56 41 55 41 54 53 48
> > (XEN) Xen stack trace from rsp=ffff8300688bfdc0:
> > (XEN)    0000000200000086 ffff8308366dc000 0000000000000022 0000000000000000
> > (XEN)    ffff8300688bfe08 ffff82d0402bcc33 ffff8308366dc000 0000000000000022
> > (XEN)    0000000000000001 ffff8300688bfe40 ffff82d0402bd18f ffff830835a7eb98
> > (XEN)    ffff8308366dc000 ffff830835a7eb40 ffff8300688bfe68 0100100100100100
> > (XEN)    ffff8300688bfea0 ffff82d04026f6e1 ffff830835a7eb30 ffff8308366dc0f4
> > (XEN)    ffff830835a7eb40 ffff8300688bfe68 ffff8300688bfe68 ffff82d0405cec80
> > (XEN)    ffffffffffffffff ffff82d0405cec80 0000000000000000 ffff82d0405d6c80
> > (XEN)    ffff8300688bfed8 ffff82d04022b6fa ffff83083663f000 ffff83083663f000
> > (XEN)    0000000000000000 0000000000000000 0000000a7c62165b ffff8300688bfee8
> > (XEN)    ffff82d04022b798 ffff8300688bfe08 ffff82d0402a4bcb 0000000000000000
> > (XEN)    0000000000000206 ffff8316da86e61c ffff8316da86e600 ffff938031fd47c0
> > (XEN)    0000000000000003 0000000000000400 ff889e8da08f928a 0000000000000000
> > (XEN)    0000000000000002 0000000000000100 000000000000b86e ffff93803237f010
> > (XEN)    0000000000000000 ffff8316da86e61c 0000beef0000beef ffffffff80555918
> > (XEN)    000000bf0000beef 0000000000000046 ffff938031fd4790 000000000000beef
> > (XEN)    000000000000beef 000000000000beef 000000000000beef 000000000000beef
> > (XEN)    0000e01000000000 ffff83083663f000 0000000000000000 00000000003526e0
> > (XEN)    0000000000000000 0000000000000000 0000060100000001 0000000000000000
> > (XEN) Xen call trace:
> > (XEN)    [<ffff82d0402c4164>] R vioapic_irq_positive_edge+0x14e/0x150
> > (XEN)    [<ffff82d0402bcc33>] F arch/x86/hvm/irq.c#assert_gsi+0x5e/0x7b
> > (XEN)    [<ffff82d0402bd18f>] F hvm_gsi_assert+0x62/0x77
> > (XEN)    [<ffff82d04026f6e1>] F drivers/passthrough/io.c#dpci_softirq+0x261/0x29e
> > (XEN)    [<ffff82d04022b6fa>] F common/softirq.c#__do_softirq+0x8a/0xbf
> > (XEN)    [<ffff82d04022b798>] F do_softirq+0x13/0x15
> > (XEN)    [<ffff82d0402a4bcb>] F vmx_asm_do_vmentry+0x2b/0x30
> > (XEN) 
> > (XEN) 
> > (XEN) ****************************************
> > (XEN) Panic on CPU 0:
> > (XEN) Assertion '!print' failed at vioapic.c:512
> > (XEN) ****************************************
> 
> Right, this was the expected path after what you've sent prior to this.
> Which turned my attention back to the 'i' debug key output you had sent
> the other day. There we have
> 
> (XEN)    IRQ:  34 vec:51 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
> 
> i.e. at that point we're waiting for Dom0 to signal it's done handling
> the IRQ. There is, however, a timer associated with this. Yet that's
> actually to prevent the system getting stuck, i.e. the "in-flight"
> state ought to clear 1ms later (when that timer expires), and hence
> ought to be pretty unlikely to catch when non-zero _and_ something's
> actually stuck.

I somehow assumed the interrupt was in-flight because the printing to
the Xen console caused one to be injected, and thus dom0 didn't had
time to Ack it yet.

> 
> So for the softirq to get Dom0 out of its stuck state, there has got to
> be yet some other event. Nevertheless it may be worthwhile
> instrumenting irq_guest_eoi_timer_fn() to prove we actually take this
> path, i.e. Xen is trying to "clean up" after Dom0 taking too long to
> service an IRQ. In normal operation this path shouldn't be taken, so I
> wouldn't exclude something got broken in that logic. (Orthogonal to
> this it may also be worth seeing whether increasing the timeout would
> actually help things. This wouldn't be a solution, but another data
> point hinting something's wrong on this code path.)
> 
> Roger, I'm also somewhat puzzled by the trailing (-MM): Is PVH using
> event channels for delivering pIRQ-s?

No, it's always using emulated interrupt controllers. I explicitly
disabled HVM PIRQ for PVH.

> I thought that's purely vIO-APIC
> and vMSI? I wonder whether we misleadingly dump info from evtchn 0
> here, in which case only the 2nd of the M-s would be meaningful (and
> would be in line with non-zero in-flight).

Likely - will have to look closer but there's no event channel
associated with a PIRQ on PVH dom0. I will send a patch to fix dump_irqs.

Maybe we should track interrupt EOI, and see when the interrupt gets
EOI'ed. Will see if I can find some time later to prepare another
debug patch.

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 20, 2020 at 09:28:55AM +0100, Roger Pau Monné wrote:
> > i.e. at that point we're waiting for Dom0 to signal it's done handling
> > the IRQ. There is, however, a timer associated with this. Yet that's
> > actually to prevent the system getting stuck, i.e. the "in-flight"
> > state ought to clear 1ms later (when that timer expires), and hence
> > ought to be pretty unlikely to catch when non-zero _and_ something's
> > actually stuck.
> 
> I somehow assumed the interrupt was in-flight because the printing to
> the Xen console caused one to be injected, and thus dom0 didn't had
> time to Ack it yet.

What does Xen consider to be an ACK from the dom0 ?
AFAIK we have EOI only for LAPIC interrupts.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 20.11.2020 09:28, Roger Pau Monné wrote:
> On Fri, Nov 20, 2020 at 09:09:51AM +0100, Jan Beulich wrote:
>> On 19.11.2020 18:57, Manuel Bouyer wrote:
>>> I added an ASSERT() after the printf to ket a stack trace, and got:
>>> db{0}> call ioapic_dump_raw^M
>>> Register dump of ioapic0^M
>>> [  13.0193374] 00 08000000 00170011 08000000(XEN) vioapic.c:141:d0v0 apic_mem_readl:undefined ioregsel 3
>>> (XEN) vioapic.c:512:vioapic_irq_positive_edge: vioapic_deliver 2
>>> (XEN) Assertion '!print' failed at vioapic.c:512
>>> (XEN) ----[ Xen-4.15-unstable  x86_64  debug=y   Tainted:   C   ]----
>>> (XEN) CPU:    0
>>> (XEN) RIP:    e008:[<ffff82d0402c4164>] vioapic_irq_positive_edge+0x14e/0x150
>>> (XEN) RFLAGS: 0000000000010202   CONTEXT: hypervisor (d0v0)
>>> (XEN) rax: ffff82d0405c806c   rbx: ffff830836650580   rcx: 0000000000000000
>>> (XEN) rdx: ffff8300688bffff   rsi: 000000000000000a   rdi: ffff82d0404b36b8
>>> (XEN) rbp: ffff8300688bfde0   rsp: ffff8300688bfdc0   r8:  0000000000000004
>>> (XEN) r9:  0000000000000032   r10: 0000000000000000   r11: 00000000fffffffd
>>> (XEN) r12: ffff8308366dc000   r13: 0000000000000022   r14: ffff8308366dc31c
>>> (XEN) r15: ffff8308366d1d80   cr0: 0000000080050033   cr4: 00000000003526e0
>>> (XEN) cr3: 00000008366c9000   cr2: 0000000000000000
>>> (XEN) fsb: 0000000000000000   gsb: 0000000000000000   gss: 0000000000000000
>>> (XEN) ds: 0000   es: 0000   fs: 0000   gs: 0000   ss: 0000   cs: e008
>>> (XEN) Xen code around <ffff82d0402c4164> (vioapic_irq_positive_edge+0x14e/0x150):
>>> (XEN)  3d 10 be 1d 00 00 74 c2 <0f> 0b 55 48 89 e5 41 57 41 56 41 55 41 54 53 48
>>> (XEN) Xen stack trace from rsp=ffff8300688bfdc0:
>>> (XEN)    0000000200000086 ffff8308366dc000 0000000000000022 0000000000000000
>>> (XEN)    ffff8300688bfe08 ffff82d0402bcc33 ffff8308366dc000 0000000000000022
>>> (XEN)    0000000000000001 ffff8300688bfe40 ffff82d0402bd18f ffff830835a7eb98
>>> (XEN)    ffff8308366dc000 ffff830835a7eb40 ffff8300688bfe68 0100100100100100
>>> (XEN)    ffff8300688bfea0 ffff82d04026f6e1 ffff830835a7eb30 ffff8308366dc0f4
>>> (XEN)    ffff830835a7eb40 ffff8300688bfe68 ffff8300688bfe68 ffff82d0405cec80
>>> (XEN)    ffffffffffffffff ffff82d0405cec80 0000000000000000 ffff82d0405d6c80
>>> (XEN)    ffff8300688bfed8 ffff82d04022b6fa ffff83083663f000 ffff83083663f000
>>> (XEN)    0000000000000000 0000000000000000 0000000a7c62165b ffff8300688bfee8
>>> (XEN)    ffff82d04022b798 ffff8300688bfe08 ffff82d0402a4bcb 0000000000000000
>>> (XEN)    0000000000000206 ffff8316da86e61c ffff8316da86e600 ffff938031fd47c0
>>> (XEN)    0000000000000003 0000000000000400 ff889e8da08f928a 0000000000000000
>>> (XEN)    0000000000000002 0000000000000100 000000000000b86e ffff93803237f010
>>> (XEN)    0000000000000000 ffff8316da86e61c 0000beef0000beef ffffffff80555918
>>> (XEN)    000000bf0000beef 0000000000000046 ffff938031fd4790 000000000000beef
>>> (XEN)    000000000000beef 000000000000beef 000000000000beef 000000000000beef
>>> (XEN)    0000e01000000000 ffff83083663f000 0000000000000000 00000000003526e0
>>> (XEN)    0000000000000000 0000000000000000 0000060100000001 0000000000000000
>>> (XEN) Xen call trace:
>>> (XEN)    [<ffff82d0402c4164>] R vioapic_irq_positive_edge+0x14e/0x150
>>> (XEN)    [<ffff82d0402bcc33>] F arch/x86/hvm/irq.c#assert_gsi+0x5e/0x7b
>>> (XEN)    [<ffff82d0402bd18f>] F hvm_gsi_assert+0x62/0x77
>>> (XEN)    [<ffff82d04026f6e1>] F drivers/passthrough/io.c#dpci_softirq+0x261/0x29e
>>> (XEN)    [<ffff82d04022b6fa>] F common/softirq.c#__do_softirq+0x8a/0xbf
>>> (XEN)    [<ffff82d04022b798>] F do_softirq+0x13/0x15
>>> (XEN)    [<ffff82d0402a4bcb>] F vmx_asm_do_vmentry+0x2b/0x30
>>> (XEN) 
>>> (XEN) 
>>> (XEN) ****************************************
>>> (XEN) Panic on CPU 0:
>>> (XEN) Assertion '!print' failed at vioapic.c:512
>>> (XEN) ****************************************
>>
>> Right, this was the expected path after what you've sent prior to this.
>> Which turned my attention back to the 'i' debug key output you had sent
>> the other day. There we have
>>
>> (XEN)    IRQ:  34 vec:51 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
>>
>> i.e. at that point we're waiting for Dom0 to signal it's done handling
>> the IRQ. There is, however, a timer associated with this. Yet that's
>> actually to prevent the system getting stuck, i.e. the "in-flight"
>> state ought to clear 1ms later (when that timer expires), and hence
>> ought to be pretty unlikely to catch when non-zero _and_ something's
>> actually stuck.
> 
> I somehow assumed the interrupt was in-flight because the printing to
> the Xen console caused one to be injected, and thus dom0 didn't had
> time to Ack it yet.

By "injected" you mean from Xen into Dom0, or by the hardware for Xen
to handle? (I ask because I think I saw you use the term also for the
latter case, in some context.) If the former, then something would
need to have caused Xen to inject it, while in the latter case there
would need to have been a reason that it didn't get delivered earlier.

From the stack trace above the only possibility I could derive for
now would be that we didn't run softirqs for a long time, but I don't
think that's very realistic here. Otoh, Manuel, does the NMI watchdog
work on that system? It certainly wouldn't hurt if you turned it on,
just in case.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 20.11.2020 09:52, Manuel Bouyer wrote:
> On Fri, Nov 20, 2020 at 09:28:55AM +0100, Roger Pau Monné wrote:
>>> i.e. at that point we're waiting for Dom0 to signal it's done handling
>>> the IRQ. There is, however, a timer associated with this. Yet that's
>>> actually to prevent the system getting stuck, i.e. the "in-flight"
>>> state ought to clear 1ms later (when that timer expires), and hence
>>> ought to be pretty unlikely to catch when non-zero _and_ something's
>>> actually stuck.
>>
>> I somehow assumed the interrupt was in-flight because the printing to
>> the Xen console caused one to be injected, and thus dom0 didn't had
>> time to Ack it yet.
> 
> What does Xen consider to be an ACK from the dom0 ?
> AFAIK we have EOI only for LAPIC interrupts.

Well, anything coming through the LAPIC needs ack-ing (except for
the spurious interrupt of course), or else ISR won't get updated
and further interrupts at this or lower priority can't be serviced
(delivered) anymore. This includes interrupts originally coming
through the IO-APIC. But the same constraint / requirement exists
on baremetal.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 20, 2020 at 09:54:42AM +0100, Jan Beulich wrote:
> [...]
> >From the stack trace above the only possibility I could derive for
> now would be that we didn't run softirqs for a long time, but I don't
> think that's very realistic here. Otoh, Manuel, does the NMI watchdog
> work on that system? It certainly wouldn't hurt if you turned it on,
> just in case.

I just did, this doesn't changes anything.
For the record, my boot params are now

menu=Boot Xen PVH:load /test console=com0 root=dk0 -vx; multiboot /xen-test.gz dom0_mem=1024M console=com2 com2=57600,8n1,,0 loglvl=all guest_loglvl=all gnttab_max_nr_frames=64 dom0=pvh iommu=debug dom0_vcpus_pin sync_console dom0_max_vcpus=1 watchdog=force

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 20, 2020 at 09:59:57AM +0100, Jan Beulich wrote:
> Well, anything coming through the LAPIC needs ack-ing (except for
> the spurious interrupt of course), or else ISR won't get updated
> and further interrupts at this or lower priority can't be serviced
> (delivered) anymore. This includes interrupts originally coming
> through the IO-APIC. But the same constraint / requirement exists
> on baremetal.

OK, so even if I didn't see where this happens, it's happening.
Is it what's Xen is using as ACK from the dom0 for a IOAPIC
interrupt, or is it something else (at the IOAPIC level) ?

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 20.11.2020 10:27, Manuel Bouyer wrote:
> On Fri, Nov 20, 2020 at 09:59:57AM +0100, Jan Beulich wrote:
>> Well, anything coming through the LAPIC needs ack-ing (except for
>> the spurious interrupt of course), or else ISR won't get updated
>> and further interrupts at this or lower priority can't be serviced
>> (delivered) anymore. This includes interrupts originally coming
>> through the IO-APIC. But the same constraint / requirement exists
>> on baremetal.
> 
> OK, so even if I didn't see where this happens, it's happening.
> Is it what's Xen is using as ACK from the dom0 for a IOAPIC
> interrupt, or is it something else (at the IOAPIC level) ?

It's the traditional LAPIC based EOI mechanism that Xen intercepts
(as necessary) on the guest side and then translates (via
surprisingly many layers of calls) into the necessary EOI /
unmask / whatever at the hardware level. Our vIO-APIC
implementation so far doesn't support IO-APIC based EOI at all
(which is reflected in the IO-APIC version ID being 0x11).

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 20, 2020 at 11:00:05AM +0100, Jan Beulich wrote:
> On 20.11.2020 10:27, Manuel Bouyer wrote:
> > On Fri, Nov 20, 2020 at 09:59:57AM +0100, Jan Beulich wrote:
> >> Well, anything coming through the LAPIC needs ack-ing (except for
> >> the spurious interrupt of course), or else ISR won't get updated
> >> and further interrupts at this or lower priority can't be serviced
> >> (delivered) anymore. This includes interrupts originally coming
> >> through the IO-APIC. But the same constraint / requirement exists
> >> on baremetal.
> > 
> > OK, so even if I didn't see where this happens, it's happening.
> > Is it what's Xen is using as ACK from the dom0 for a IOAPIC
> > interrupt, or is it something else (at the IOAPIC level) ?
> 
> It's the traditional LAPIC based EOI mechanism that Xen intercepts
> (as necessary) on the guest side and then translates (via
> surprisingly many layers of calls) into the necessary EOI /
> unmask / whatever at the hardware level. Our vIO-APIC
> implementation so far doesn't support IO-APIC based EOI at all
> (which is reflected in the IO-APIC version ID being 0x11).

OK.
I finally found where the EOI occurs (it's within a macro so s simple grep
didn't show it).

When interrupts are not masked (e.g. via cli), the ioapic halder is called.
From here, 2 paths can happen:
a) the software interrupt priority level (called spl in BSD world) allows the
  driver's handler to run. In this case it's called, then the interrupt
  is unmasked at ioapic level, and EOI'd at lapic.
b) the software interrupt priority level doesn't allow this driver's handler to
  run. In this case, the interrupt is marked as pending in software,
  explicitely masked at the iopic level and EOI'd at lapic.
  Later, when the spl is lowered, the driver's interrupt handler is run,
  then the interrupt is unmasked at ioapic level, and EOI'd at lapic
  (this is the same path as a)). here we may EOI the lapic twice, and the
  second time when there's no hardware interrupt pending any more.

I suspect it's case b) which causes the problem with Xen.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Fri, Nov 20, 2020 at 09:54:42AM +0100, Jan Beulich wrote:
> On 20.11.2020 09:28, Roger Pau Monné wrote:
> > On Fri, Nov 20, 2020 at 09:09:51AM +0100, Jan Beulich wrote:
> >> On 19.11.2020 18:57, Manuel Bouyer wrote:
> >>> I added an ASSERT() after the printf to ket a stack trace, and got:
> >>> db{0}> call ioapic_dump_raw^M
> >>> Register dump of ioapic0^M
> >>> [  13.0193374] 00 08000000 00170011 08000000(XEN) vioapic.c:141:d0v0 apic_mem_readl:undefined ioregsel 3
> >>> (XEN) vioapic.c:512:vioapic_irq_positive_edge: vioapic_deliver 2
> >>> (XEN) Assertion '!print' failed at vioapic.c:512
> >>> (XEN) ----[ Xen-4.15-unstable  x86_64  debug=y   Tainted:   C   ]----
> >>> (XEN) CPU:    0
> >>> (XEN) RIP:    e008:[<ffff82d0402c4164>] vioapic_irq_positive_edge+0x14e/0x150
> >>> (XEN) RFLAGS: 0000000000010202   CONTEXT: hypervisor (d0v0)
> >>> (XEN) rax: ffff82d0405c806c   rbx: ffff830836650580   rcx: 0000000000000000
> >>> (XEN) rdx: ffff8300688bffff   rsi: 000000000000000a   rdi: ffff82d0404b36b8
> >>> (XEN) rbp: ffff8300688bfde0   rsp: ffff8300688bfdc0   r8:  0000000000000004
> >>> (XEN) r9:  0000000000000032   r10: 0000000000000000   r11: 00000000fffffffd
> >>> (XEN) r12: ffff8308366dc000   r13: 0000000000000022   r14: ffff8308366dc31c
> >>> (XEN) r15: ffff8308366d1d80   cr0: 0000000080050033   cr4: 00000000003526e0
> >>> (XEN) cr3: 00000008366c9000   cr2: 0000000000000000
> >>> (XEN) fsb: 0000000000000000   gsb: 0000000000000000   gss: 0000000000000000
> >>> (XEN) ds: 0000   es: 0000   fs: 0000   gs: 0000   ss: 0000   cs: e008
> >>> (XEN) Xen code around <ffff82d0402c4164> (vioapic_irq_positive_edge+0x14e/0x150):
> >>> (XEN)  3d 10 be 1d 00 00 74 c2 <0f> 0b 55 48 89 e5 41 57 41 56 41 55 41 54 53 48
> >>> (XEN) Xen stack trace from rsp=ffff8300688bfdc0:
> >>> (XEN)    0000000200000086 ffff8308366dc000 0000000000000022 0000000000000000
> >>> (XEN)    ffff8300688bfe08 ffff82d0402bcc33 ffff8308366dc000 0000000000000022
> >>> (XEN)    0000000000000001 ffff8300688bfe40 ffff82d0402bd18f ffff830835a7eb98
> >>> (XEN)    ffff8308366dc000 ffff830835a7eb40 ffff8300688bfe68 0100100100100100
> >>> (XEN)    ffff8300688bfea0 ffff82d04026f6e1 ffff830835a7eb30 ffff8308366dc0f4
> >>> (XEN)    ffff830835a7eb40 ffff8300688bfe68 ffff8300688bfe68 ffff82d0405cec80
> >>> (XEN)    ffffffffffffffff ffff82d0405cec80 0000000000000000 ffff82d0405d6c80
> >>> (XEN)    ffff8300688bfed8 ffff82d04022b6fa ffff83083663f000 ffff83083663f000
> >>> (XEN)    0000000000000000 0000000000000000 0000000a7c62165b ffff8300688bfee8
> >>> (XEN)    ffff82d04022b798 ffff8300688bfe08 ffff82d0402a4bcb 0000000000000000
> >>> (XEN)    0000000000000206 ffff8316da86e61c ffff8316da86e600 ffff938031fd47c0
> >>> (XEN)    0000000000000003 0000000000000400 ff889e8da08f928a 0000000000000000
> >>> (XEN)    0000000000000002 0000000000000100 000000000000b86e ffff93803237f010
> >>> (XEN)    0000000000000000 ffff8316da86e61c 0000beef0000beef ffffffff80555918
> >>> (XEN)    000000bf0000beef 0000000000000046 ffff938031fd4790 000000000000beef
> >>> (XEN)    000000000000beef 000000000000beef 000000000000beef 000000000000beef
> >>> (XEN)    0000e01000000000 ffff83083663f000 0000000000000000 00000000003526e0
> >>> (XEN)    0000000000000000 0000000000000000 0000060100000001 0000000000000000
> >>> (XEN) Xen call trace:
> >>> (XEN)    [<ffff82d0402c4164>] R vioapic_irq_positive_edge+0x14e/0x150
> >>> (XEN)    [<ffff82d0402bcc33>] F arch/x86/hvm/irq.c#assert_gsi+0x5e/0x7b
> >>> (XEN)    [<ffff82d0402bd18f>] F hvm_gsi_assert+0x62/0x77
> >>> (XEN)    [<ffff82d04026f6e1>] F drivers/passthrough/io.c#dpci_softirq+0x261/0x29e
> >>> (XEN)    [<ffff82d04022b6fa>] F common/softirq.c#__do_softirq+0x8a/0xbf
> >>> (XEN)    [<ffff82d04022b798>] F do_softirq+0x13/0x15
> >>> (XEN)    [<ffff82d0402a4bcb>] F vmx_asm_do_vmentry+0x2b/0x30
> >>> (XEN) 
> >>> (XEN) 
> >>> (XEN) ****************************************
> >>> (XEN) Panic on CPU 0:
> >>> (XEN) Assertion '!print' failed at vioapic.c:512
> >>> (XEN) ****************************************
> >>
> >> Right, this was the expected path after what you've sent prior to this.
> >> Which turned my attention back to the 'i' debug key output you had sent
> >> the other day. There we have
> >>
> >> (XEN)    IRQ:  34 vec:51 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
> >>
> >> i.e. at that point we're waiting for Dom0 to signal it's done handling
> >> the IRQ. There is, however, a timer associated with this. Yet that's
> >> actually to prevent the system getting stuck, i.e. the "in-flight"
> >> state ought to clear 1ms later (when that timer expires), and hence
> >> ought to be pretty unlikely to catch when non-zero _and_ something's
> >> actually stuck.
> > 
> > I somehow assumed the interrupt was in-flight because the printing to
> > the Xen console caused one to be injected, and thus dom0 didn't had
> > time to Ack it yet.
> 
> By "injected" you mean from Xen into Dom0, or by the hardware for Xen
> to handle? (I ask because I think I saw you use the term also for the
> latter case, in some context.) If the former, then something would
> need to have caused Xen to inject it, while in the latter case there
> would need to have been a reason that it didn't get delivered earlier.

Sorry, wrote this in a hurry and didn't realize it could be
misleading. I meant injected from hardware to Xen, which would then
also be injected from Xen to dom0.

I would expect softirqs to be running normally (as you have already
asked and Manuel proved the watchdog is not triggering).

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Fri, Nov 20, 2020 at 11:38:24AM +0100, Manuel Bouyer wrote:
> On Fri, Nov 20, 2020 at 11:00:05AM +0100, Jan Beulich wrote:
> > On 20.11.2020 10:27, Manuel Bouyer wrote:
> > > On Fri, Nov 20, 2020 at 09:59:57AM +0100, Jan Beulich wrote:
> > >> Well, anything coming through the LAPIC needs ack-ing (except for
> > >> the spurious interrupt of course), or else ISR won't get updated
> > >> and further interrupts at this or lower priority can't be serviced
> > >> (delivered) anymore. This includes interrupts originally coming
> > >> through the IO-APIC. But the same constraint / requirement exists
> > >> on baremetal.
> > > 
> > > OK, so even if I didn't see where this happens, it's happening.
> > > Is it what's Xen is using as ACK from the dom0 for a IOAPIC
> > > interrupt, or is it something else (at the IOAPIC level) ?
> > 
> > It's the traditional LAPIC based EOI mechanism that Xen intercepts
> > (as necessary) on the guest side and then translates (via
> > surprisingly many layers of calls) into the necessary EOI /
> > unmask / whatever at the hardware level. Our vIO-APIC
> > implementation so far doesn't support IO-APIC based EOI at all
> > (which is reflected in the IO-APIC version ID being 0x11).
> 
> OK.
> I finally found where the EOI occurs (it's within a macro so s simple grep
> didn't show it).
> 
> When interrupts are not masked (e.g. via cli), the ioapic halder is called.
> From here, 2 paths can happen:
> a) the software interrupt priority level (called spl in BSD world) allows the
>   driver's handler to run. In this case it's called, then the interrupt
>   is unmasked at ioapic level, and EOI'd at lapic.
> b) the software interrupt priority level doesn't allow this driver's handler to
>   run. In this case, the interrupt is marked as pending in software,
>   explicitely masked at the iopic level and EOI'd at lapic.
>   Later, when the spl is lowered, the driver's interrupt handler is run,
>   then the interrupt is unmasked at ioapic level, and EOI'd at lapic
>   (this is the same path as a)). here we may EOI the lapic twice, and the
>   second time when there's no hardware interrupt pending any more.
> 
> I suspect it's case b) which causes the problem with Xen.

Case b) should be handled fine AFAICT. If there's no interrupt pending
in the lapic ISR the EOI is just a noop. Iff there's somehow another
vector pending in ISR you might actually be EOIing the wrong vector,
and thus this would be a bug in NetBSD. I certainly don't know much of
NetBSD interrupt model in order to know whether this second EOI is just
not necessary or whether it could cause issues.

Can you actually assert that disabling this second unneeded EOI does
solve the problem?

Thanks, Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Mon, Nov 23, 2020 at 10:57:13AM +0100, Roger Pau Monné wrote:
> > [...]
> > OK.
> > I finally found where the EOI occurs (it's within a macro so s simple grep
> > didn't show it).
> > 
> > When interrupts are not masked (e.g. via cli), the ioapic halder is called.
> > From here, 2 paths can happen:
> > a) the software interrupt priority level (called spl in BSD world) allows the
> >   driver's handler to run. In this case it's called, then the interrupt
> >   is unmasked at ioapic level, and EOI'd at lapic.
> > b) the software interrupt priority level doesn't allow this driver's handler to
> >   run. In this case, the interrupt is marked as pending in software,
> >   explicitely masked at the iopic level and EOI'd at lapic.
> >   Later, when the spl is lowered, the driver's interrupt handler is run,
> >   then the interrupt is unmasked at ioapic level, and EOI'd at lapic
> >   (this is the same path as a)). here we may EOI the lapic twice, and the
> >   second time when there's no hardware interrupt pending any more.
> > 
> > I suspect it's case b) which causes the problem with Xen.
> 
> Case b) should be handled fine AFAICT. If there's no interrupt pending
> in the lapic ISR the EOI is just a noop. Iff there's somehow another
> vector pending in ISR you might actually be EOIing the wrong vector,
> and thus this would be a bug in NetBSD. I certainly don't know much of
> NetBSD interrupt model in order to know whether this second EOI is just
> not necessary or whether it could cause issues.
> 
> Can you actually assert that disabling this second unneeded EOI does
> solve the problem?

I tried this, and it didn't change anything ...

I'm out of idea to try.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Mon, Nov 23, 2020 at 12:32:41PM +0100, Manuel Bouyer wrote:
> On Mon, Nov 23, 2020 at 10:57:13AM +0100, Roger Pau Monné wrote:
> > > [...]
> > > OK.
> > > I finally found where the EOI occurs (it's within a macro so s simple grep
> > > didn't show it).
> > > 
> > > When interrupts are not masked (e.g. via cli), the ioapic halder is called.
> > > From here, 2 paths can happen:
> > > a) the software interrupt priority level (called spl in BSD world) allows the
> > >   driver's handler to run. In this case it's called, then the interrupt
> > >   is unmasked at ioapic level, and EOI'd at lapic.
> > > b) the software interrupt priority level doesn't allow this driver's handler to
> > >   run. In this case, the interrupt is marked as pending in software,
> > >   explicitely masked at the iopic level and EOI'd at lapic.
> > >   Later, when the spl is lowered, the driver's interrupt handler is run,
> > >   then the interrupt is unmasked at ioapic level, and EOI'd at lapic
> > >   (this is the same path as a)). here we may EOI the lapic twice, and the
> > >   second time when there's no hardware interrupt pending any more.
> > > 
> > > I suspect it's case b) which causes the problem with Xen.
> > 
> > Case b) should be handled fine AFAICT. If there's no interrupt pending
> > in the lapic ISR the EOI is just a noop. Iff there's somehow another
> > vector pending in ISR you might actually be EOIing the wrong vector,
> > and thus this would be a bug in NetBSD. I certainly don't know much of
> > NetBSD interrupt model in order to know whether this second EOI is just
> > not necessary or whether it could cause issues.
> > 
> > Can you actually assert that disabling this second unneeded EOI does
> > solve the problem?
> 
> I tried this, and it didn't change anything ...
> 
> I'm out of idea to try.

Hm, yes, it's quite weird. Do you know whether a NetBSD kernel can be
multibooted from pxelinux with Xen? I would like to see if I can
reproduce this myself.

I have the following patch also which will print a warning message
when GSI 34 is injected from hardware or when Xen performs an EOI
(either from a time out or when reacting to a guest one). I would
expect at least the interrupt injection one to trigger together with
the existing message.

Thanks, Roger.
---8<---
diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..bbd141a3d9 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -43,7 +43,12 @@
 /* HACK: Route IRQ0 only to VCPU0 to prevent time jumps. */
 #define IRQ0_SPECIAL_ROUTING 1
 
-static void vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int irq);
+static void _vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int irq);
+
+bool __read_mostly irqprint;
+#define vioapic_deliver(vioapic, irq) ({\
+    WARN_ON(irqprint && vioapic->base_gsi + irq == 34); \
+    _vioapic_deliver(vioapic, irq); })
 
 static struct hvm_vioapic *addr_vioapic(const struct domain *d,
                                         unsigned long addr)
@@ -119,6 +124,16 @@ static uint32_t vioapic_read_indirect(const struct hvm_vioapic *vioapic)
 
         if ( redir_index >= vioapic->nr_pins )
         {
+            switch ( vioapic->ioregsel )
+            {
+            case 3:
+                irqprint = true;
+                break;
+
+            case 0xf:
+                irqprint = false;
+                break;
+            }
             gdprintk(XENLOG_WARNING, "apic_mem_readl:undefined ioregsel %x\n",
                      vioapic->ioregsel);
             break;
@@ -391,7 +406,7 @@ static void ioapic_inj_irq(
     vlapic_set_irq(target, vector, trig_mode);
 }
 
-static void vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int pin)
+static void _vioapic_deliver(struct hvm_vioapic *vioapic, unsigned int pin)
 {
     uint16_t dest = vioapic->redirtbl[pin].fields.dest_id;
     uint8_t dest_mode = vioapic->redirtbl[pin].fields.dest_mode;
diff --git a/xen/arch/x86/irq.c b/xen/arch/x86/irq.c
index 8d1f9a9fc6..91fb99d271 100644
--- a/xen/arch/x86/irq.c
+++ b/xen/arch/x86/irq.c
@@ -1388,10 +1388,12 @@ static void set_eoi_ready(void *data)
     flush_ready_eoi();
 }
 
+extern bool irqprint;
 void pirq_guest_eoi(struct pirq *pirq)
 {
     struct irq_desc *desc;
 
+    WARN_ON(irqprint && pirq->pirq == 34);
     ASSERT(local_irq_is_enabled());
     desc = pirq_spin_lock_irq_desc(pirq, NULL);
     if ( desc )
@@ -1837,6 +1839,8 @@ static void do_IRQ_guest(struct irq_desc *desc, unsigned int vector)
     unsigned int        i;
     struct pending_eoi *peoi = this_cpu(pending_eoi);
 
+    WARN_ON(irqprint && desc->irq == 34);
+
     if ( unlikely(!action->nr_guests) )
     {
         /* An interrupt may slip through while freeing an ACKTYPE_EOI irq. */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Mon, Nov 23, 2020 at 01:51:12PM +0100, Roger Pau Monné wrote:
> Hm, yes, it's quite weird. Do you know whether a NetBSD kernel can be
> multibooted from pxelinux with Xen? I would like to see if I can
> reproduce this myself.

Yes, if Xen+linux can boot, Xen+netbsd should boot too.
In a previous mail I wrote:
In case it helps, I put by Xen and netbsd kernels at
http://www-soc.lip6.fr/~bouyer/netbsd-dom0-pvh/
I boot it from the NetBSD boot loader with:
menu=Boot Xen PVH:load /netbsd-test console=com0 root=dk0 -vx; multiboot /xen-te
st.gz dom0_mem=1024M console=com2 com2=57600,8n1 loglvl=all guest_loglvl=all gnt
tab_max_nr_frames=64 dom0=pvh iommu=debug
I guess with grub this would be
kernel /xen-test.gz dom0_mem=1024M console=com2 com2=57600,8n1 loglvl=all guest_
loglvl=all gnttab_max_nr_frames=64 dom0=pvh iommu=debug
module /netbsd-test console=com0 root=dk0 -vx

(yes, com2 for xen and com0 for netbsd, that's not a bug :)
You can enter the NetBSD debugger with
+++++
you can then enter commands, lile
sh ev /i
to see the interrupt counters

> 
> I have the following patch also which will print a warning message
> when GSI 34 is injected from hardware or when Xen performs an EOI
> (either from a time out or when reacting to a guest one). I would
> expect at least the interrupt injection one to trigger together with
> the existing message.

It's quite verbose. I put the full log at
http://www-soc.lip6.fr/~bouyer/xen-log4.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Mon, Nov 23, 2020 at 03:31:50PM +0100, Manuel Bouyer wrote:
> On Mon, Nov 23, 2020 at 01:51:12PM +0100, Roger Pau Monné wrote:
> > Hm, yes, it's quite weird. Do you know whether a NetBSD kernel can be
> > multibooted from pxelinux with Xen? I would like to see if I can
> > reproduce this myself.
> 
> Yes, if Xen+linux can boot, Xen+netbsd should boot too.
> In a previous mail I wrote:
> In case it helps, I put by Xen and netbsd kernels at
> http://www-soc.lip6.fr/~bouyer/netbsd-dom0-pvh/
> I boot it from the NetBSD boot loader with:
> menu=Boot Xen PVH:load /netbsd-test console=com0 root=dk0 -vx; multiboot /xen-te
> st.gz dom0_mem=1024M console=com2 com2=57600,8n1 loglvl=all guest_loglvl=all gnt
> tab_max_nr_frames=64 dom0=pvh iommu=debug
> I guess with grub this would be
> kernel /xen-test.gz dom0_mem=1024M console=com2 com2=57600,8n1 loglvl=all guest_
> loglvl=all gnttab_max_nr_frames=64 dom0=pvh iommu=debug
> module /netbsd-test console=com0 root=dk0 -vx
> 
> (yes, com2 for xen and com0 for netbsd, that's not a bug :)
> You can enter the NetBSD debugger with
> +++++
> you can then enter commands, lile
> sh ev /i
> to see the interrupt counters
> 
> > 
> > I have the following patch also which will print a warning message
> > when GSI 34 is injected from hardware or when Xen performs an EOI
> > (either from a time out or when reacting to a guest one). I would
> > expect at least the interrupt injection one to trigger together with
> > the existing message.
> 
> It's quite verbose. I put the full log at
> http://www-soc.lip6.fr/~bouyer/xen-log4.txt

OK, I'm afraid this is likely too verbose and messes with the timings.

I've been looking (again) into the code, and I found something weird
that I think could be related to the issue you are seeing, but haven't
managed to try to boot the NetBSD kernel provided in order to assert
whether it solves the issue or not (or even whether I'm able to
repro it). Would you mind giving the patch below a try?

Thanks, Roger.
---8<---
diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..ebd6c8e933 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -174,7 +174,6 @@ 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);
         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);

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Mon, Nov 23, 2020 at 06:06:10PM +0100, Roger Pau Monné wrote:
> OK, I'm afraid this is likely too verbose and messes with the timings.
> 
> I've been looking (again) into the code, and I found something weird
> that I think could be related to the issue you are seeing, but haven't
> managed to try to boot the NetBSD kernel provided in order to assert
> whether it solves the issue or not (or even whether I'm able to
> repro it). Would you mind giving the patch below a try?

With this, I get the same hang but XEN outputs don't wake up the interrupt
any more. The NetBSD counter shows only one interrupt for ioapic2 pin 2,
while I would have about 8 at the time of the hang.

So, now it looks like interrupts are blocked forever. At
http://www-soc.lip6.fr/~bouyer/xen-log5.txt
you'll find the output of the 'i' key.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 23.11.2020 18:39, Manuel Bouyer wrote:
> On Mon, Nov 23, 2020 at 06:06:10PM +0100, Roger Pau Monné wrote:
>> OK, I'm afraid this is likely too verbose and messes with the timings.
>>
>> I've been looking (again) into the code, and I found something weird
>> that I think could be related to the issue you are seeing, but haven't
>> managed to try to boot the NetBSD kernel provided in order to assert
>> whether it solves the issue or not (or even whether I'm able to
>> repro it). Would you mind giving the patch below a try?
> 
> With this, I get the same hang but XEN outputs don't wake up the interrupt
> any more. The NetBSD counter shows only one interrupt for ioapic2 pin 2,
> while I would have about 8 at the time of the hang.
> 
> So, now it looks like interrupts are blocked forever.

Which may be a good thing for debugging purposes, because now we have
a way to investigate what is actually blocking the interrupt's
delivery without having to worry about more output screwing the
overall picture.

> At
> http://www-soc.lip6.fr/~bouyer/xen-log5.txt
> you'll find the output of the 'i' key.

(XEN)    IRQ:  34 vec:59 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)

(XEN)     IRQ 34 Vec 89:
(XEN)       Apic 0x02, Pin  2: vec=59 delivery=LoPri dest=L status=1 polarity=1 irr=1 trig=L mask=0 dest_id:00000001

(XEN) ioapic 2 pin 2 gsi 34 vector 0x67
(XEN)   delivery mode 0 dest mode 0 delivery status 0
(XEN)   polarity 1 IRR 0 trig mode 1 mask 0 dest id 0

IOW from guest pov the interrupt is entirely idle (mask and irr clear),
while Xen sees it as both in-flight and irr also already having become
set again. I continue to suspect the EOI timer not doing its job. Yet
as said before, for it to have to do anything in the first place the
"guest" (really Dom0 here) would need to fail to EOI the IRQ within
the timeout period. Which in turn, given your description of how you
handle interrupts, cannot be excluded (i.e. the handling may simply
take "slightly" too long).

What we're missing is LAPIC information, since the masked status logged
is unclear: (-MM) isn't fully matching up with "mask=0". But of course
the former is just a software representation, while the latter is what
the RTE holds. IOW for the interrupt to not get delivered, there needs
to be this or a higher ISR bit set (considering we don't use the TPR),
or (I think we can pretty much exclude this) we'd need to be running
with IRQs off for extended periods of time.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 24, 2020 at 11:05:12AM +0100, Jan Beulich wrote:
> On 23.11.2020 18:39, Manuel Bouyer wrote:
> > On Mon, Nov 23, 2020 at 06:06:10PM +0100, Roger Pau Monné wrote:
> >> OK, I'm afraid this is likely too verbose and messes with the timings.
> >>
> >> I've been looking (again) into the code, and I found something weird
> >> that I think could be related to the issue you are seeing, but haven't
> >> managed to try to boot the NetBSD kernel provided in order to assert
> >> whether it solves the issue or not (or even whether I'm able to
> >> repro it). Would you mind giving the patch below a try?
> > 
> > With this, I get the same hang but XEN outputs don't wake up the interrupt
> > any more. The NetBSD counter shows only one interrupt for ioapic2 pin 2,
> > while I would have about 8 at the time of the hang.
> > 
> > So, now it looks like interrupts are blocked forever.
> 
> Which may be a good thing for debugging purposes, because now we have
> a way to investigate what is actually blocking the interrupt's
> delivery without having to worry about more output screwing the
> overall picture.
> 
> > At
> > http://www-soc.lip6.fr/~bouyer/xen-log5.txt
> > you'll find the output of the 'i' key.
> 
> (XEN)    IRQ:  34 vec:59 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
> 
> (XEN)     IRQ 34 Vec 89:
> (XEN)       Apic 0x02, Pin  2: vec=59 delivery=LoPri dest=L status=1 polarity=1 irr=1 trig=L mask=0 dest_id:00000001
> 
> (XEN) ioapic 2 pin 2 gsi 34 vector 0x67
> (XEN)   delivery mode 0 dest mode 0 delivery status 0
> (XEN)   polarity 1 IRR 0 trig mode 1 mask 0 dest id 0
> 
> IOW from guest pov the interrupt is entirely idle (mask and irr clear),
> while Xen sees it as both in-flight and irr also already having become
> set again. I continue to suspect the EOI timer not doing its job. Yet
> as said before, for it to have to do anything in the first place the
> "guest" (really Dom0 here) would need to fail to EOI the IRQ within
> the timeout period. Which in turn, given your description of how you
> handle interrupts, cannot be excluded (i.e. the handling may simply
> take "slightly" too long).

I've tried to force some of those scenarios myself by modifying the
code, and didn't seem to be able to trigger the same scenario. I guess
the NetBSD case is slightly difficult to recreate.

> What we're missing is LAPIC information, since the masked status logged
> is unclear: (-MM) isn't fully matching up with "mask=0". But of course
> the former is just a software representation, while the latter is what
> the RTE holds. IOW for the interrupt to not get delivered, there needs
> to be this or a higher ISR bit set (considering we don't use the TPR),
> or (I think we can pretty much exclude this) we'd need to be running
> with IRQs off for extended periods of time.

Let's dump the physical lapic(s) IRR and ISR together with the
IO-APIC state. Can you please apply the following patch and use the
'i' key again? (please keep the previous patch applied)

Thanks, Roger.
---8<---
diff --git a/xen/arch/x86/apic.c b/xen/arch/x86/apic.c
index 60627fd6e6..c33d682b69 100644
--- a/xen/arch/x86/apic.c
+++ b/xen/arch/x86/apic.c
@@ -1547,3 +1547,24 @@ void check_for_unexpected_msi(unsigned int vector)
 {
     BUG_ON(apic_isr_read(vector));
 }
+
+static DEFINE_SPINLOCK(dump_lock);
+void dump_lapic(void *unused)
+{
+    unsigned int i;
+    unsigned long flags;
+
+    spin_lock_irqsave(&dump_lock, flags);
+    printk("CPU %u APIC ID %u\n", smp_processor_id(), apic_read(APIC_ID));
+
+    printk("IRR ");
+    for ( i = APIC_ISR_NR - 1; i-- > 0; )
+        printk("%08x", apic_read(APIC_ISR + i*0x10));
+
+    printk("\nISR ");
+    for ( i = APIC_ISR_NR - 1; i-- > 0; )
+        printk("%08x", apic_read(APIC_IRR + i*0x10));
+    printk("\n");
+
+    spin_unlock_irqrestore(&dump_lock, flags);
+}
diff --git a/xen/arch/x86/io_apic.c b/xen/arch/x86/io_apic.c
index e66fa99ec7..92edb3000a 100644
--- a/xen/arch/x86/io_apic.c
+++ b/xen/arch/x86/io_apic.c
@@ -2470,6 +2470,7 @@ static const char * delivery_mode_2_str(
     }
 }
 
+void dump_lapic(void *unused);
 void dump_ioapic_irq_info(void)
 {
     struct irq_pin_list *entry;
@@ -2516,6 +2517,9 @@ void dump_ioapic_irq_info(void)
             entry = &irq_2_pin[entry->next];
         }
     }
+
+    dump_lapic(NULL);
+    smp_call_function(dump_lapic, NULL, true);
 }
 
 static unsigned int __initdata max_gsi_irqs;

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Tue, Nov 24, 2020 at 01:21:02PM +0100, Roger Pau Monné wrote:
> [...]
> > What we're missing is LAPIC information, since the masked status logged
> > is unclear: (-MM) isn't fully matching up with "mask=0". But of course
> > the former is just a software representation, while the latter is what
> > the RTE holds. IOW for the interrupt to not get delivered, there needs
> > to be this or a higher ISR bit set (considering we don't use the TPR),
> > or (I think we can pretty much exclude this) we'd need to be running
> > with IRQs off for extended periods of time.
> 
> Let's dump the physical lapic(s) IRR and ISR together with the
> IO-APIC state. Can you please apply the following patch and use the
> 'i' key again? (please keep the previous patch applied)

Done, you'll find the log at
http://www-soc.lip6.fr/~bouyer/xen-log6.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 24.11.2020 14:59, Manuel Bouyer wrote:
> On Tue, Nov 24, 2020 at 01:21:02PM +0100, Roger Pau Monné wrote:
>> [...]
>>> What we're missing is LAPIC information, since the masked status logged
>>> is unclear: (-MM) isn't fully matching up with "mask=0". But of course
>>> the former is just a software representation, while the latter is what
>>> the RTE holds. IOW for the interrupt to not get delivered, there needs
>>> to be this or a higher ISR bit set (considering we don't use the TPR),
>>> or (I think we can pretty much exclude this) we'd need to be running
>>> with IRQs off for extended periods of time.
>>
>> Let's dump the physical lapic(s) IRR and ISR together with the
>> IO-APIC state. Can you please apply the following patch and use the
>> 'i' key again? (please keep the previous patch applied)
> 
> Done, you'll find the log at
> http://www-soc.lip6.fr/~bouyer/xen-log6.txt

Hmm, I can't spot respective output. Are you sure you did this with
a hypervisor with Roger's latest patch in place?

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Tue, Nov 24, 2020 at 03:09:55PM +0100, Jan Beulich wrote:
> >> [...]
> >>> What we're missing is LAPIC information, since the masked status logged
> >>> is unclear: (-MM) isn't fully matching up with "mask=0". But of course
> >>> the former is just a software representation, while the latter is what
> >>> the RTE holds. IOW for the interrupt to not get delivered, there needs
> >>> to be this or a higher ISR bit set (considering we don't use the TPR),
> >>> or (I think we can pretty much exclude this) we'd need to be running
> >>> with IRQs off for extended periods of time.
> >>
> >> Let's dump the physical lapic(s) IRR and ISR together with the
> >> IO-APIC state. Can you please apply the following patch and use the
> >> 'i' key again? (please keep the previous patch applied)
> > 
> > Done, you'll find the log at
> > http://www-soc.lip6.fr/~bouyer/xen-log6.txt
> 
> Hmm, I can't spot respective output. Are you sure you did this with
> a hypervisor with Roger's latest patch in place?

Ops, sorry I copied xen.gz to the wrong place.
new log at
http://www-soc.lip6.fr/~bouyer/xen-log7.txt

this one ends up in a panic, I hope you'll find what you expect here.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 24.11.2020 15:27, Manuel Bouyer wrote:
> On Tue, Nov 24, 2020 at 03:09:55PM +0100, Jan Beulich wrote:
>>>> [...]
>>>>> What we're missing is LAPIC information, since the masked status logged
>>>>> is unclear: (-MM) isn't fully matching up with "mask=0". But of course
>>>>> the former is just a software representation, while the latter is what
>>>>> the RTE holds. IOW for the interrupt to not get delivered, there needs
>>>>> to be this or a higher ISR bit set (considering we don't use the TPR),
>>>>> or (I think we can pretty much exclude this) we'd need to be running
>>>>> with IRQs off for extended periods of time.
>>>>
>>>> Let's dump the physical lapic(s) IRR and ISR together with the
>>>> IO-APIC state. Can you please apply the following patch and use the
>>>> 'i' key again? (please keep the previous patch applied)
>>>
>>> Done, you'll find the log at
>>> http://www-soc.lip6.fr/~bouyer/xen-log6.txt
>>
>> Hmm, I can't spot respective output. Are you sure you did this with
>> a hypervisor with Roger's latest patch in place?
> 
> Ops, sorry I copied xen.gz to the wrong place.
> new log at
> http://www-soc.lip6.fr/~bouyer/xen-log7.txt
> 
> this one ends up in a panic,

Argh - too much output triggered the watchdog. I guess we need to
cut down on the vIO-APIC dumping, permaps limiting it to just the
one RTE we care about. But let me (and Roger) see if there's
anything to be derived from the LAPIC state...

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 24.11.2020 15:33, Jan Beulich wrote:
> On 24.11.2020 15:27, Manuel Bouyer wrote:
>> Ops, sorry I copied xen.gz to the wrong place.
>> new log at
>> http://www-soc.lip6.fr/~bouyer/xen-log7.txt
>>
>> this one ends up in a panic,
> 
> Argh - too much output triggered the watchdog. I guess we need to
> cut down on the vIO-APIC dumping, permaps limiting it to just the
> one RTE we care about. But let me (and Roger) see if there's
> anything to be derived from the LAPIC state...

All IRRs and ISRs are completely clear of set bits. Highly mysterious
how the IRQ then doesn't get delivered.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 24.11.2020 11:05, Jan Beulich wrote:
> On 23.11.2020 18:39, Manuel Bouyer wrote:
>> On Mon, Nov 23, 2020 at 06:06:10PM +0100, Roger Pau Monné wrote:
>>> OK, I'm afraid this is likely too verbose and messes with the timings.
>>>
>>> I've been looking (again) into the code, and I found something weird
>>> that I think could be related to the issue you are seeing, but haven't
>>> managed to try to boot the NetBSD kernel provided in order to assert
>>> whether it solves the issue or not (or even whether I'm able to
>>> repro it). Would you mind giving the patch below a try?
>>
>> With this, I get the same hang but XEN outputs don't wake up the interrupt
>> any more. The NetBSD counter shows only one interrupt for ioapic2 pin 2,
>> while I would have about 8 at the time of the hang.
>>
>> So, now it looks like interrupts are blocked forever.
> 
> Which may be a good thing for debugging purposes, because now we have
> a way to investigate what is actually blocking the interrupt's
> delivery without having to worry about more output screwing the
> overall picture.
> 
>> At
>> http://www-soc.lip6.fr/~bouyer/xen-log5.txt
>> you'll find the output of the 'i' key.
> 
> (XEN)    IRQ:  34 vec:59 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
> 
> (XEN)     IRQ 34 Vec 89:
> (XEN)       Apic 0x02, Pin  2: vec=59 delivery=LoPri dest=L status=1 polarity=1 irr=1 trig=L mask=0 dest_id:00000001

Since it repeats in Manuel's latest dump, perhaps the odd combination
of status=1 and irr=1 is to tell us something? It is my understanding
that irr ought to become set only when delivery-status clears. Yet I
don't know what to take from this...

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 24.11.2020 15:27, Manuel Bouyer wrote:
> new log at
> http://www-soc.lip6.fr/~bouyer/xen-log7.txt
> 
> this one ends up in a panic, I hope you'll find what you expect here.

Did you actually, just to have the data point, ever try to disable
interrupt remapping ("iommu=no-intremap")? For PVH we can't ask you
to turn of the IOMMU as a whole, but aiui interrupt remapping is
not a strict prereq. (I'm sure Roger will correct me if I'm wrong.)

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 24, 2020 at 03:42:28PM +0100, Jan Beulich wrote:
> On 24.11.2020 11:05, Jan Beulich wrote:
> > On 23.11.2020 18:39, Manuel Bouyer wrote:
> >> On Mon, Nov 23, 2020 at 06:06:10PM +0100, Roger Pau Monné wrote:
> >>> OK, I'm afraid this is likely too verbose and messes with the timings.
> >>>
> >>> I've been looking (again) into the code, and I found something weird
> >>> that I think could be related to the issue you are seeing, but haven't
> >>> managed to try to boot the NetBSD kernel provided in order to assert
> >>> whether it solves the issue or not (or even whether I'm able to
> >>> repro it). Would you mind giving the patch below a try?
> >>
> >> With this, I get the same hang but XEN outputs don't wake up the interrupt
> >> any more. The NetBSD counter shows only one interrupt for ioapic2 pin 2,
> >> while I would have about 8 at the time of the hang.
> >>
> >> So, now it looks like interrupts are blocked forever.
> > 
> > Which may be a good thing for debugging purposes, because now we have
> > a way to investigate what is actually blocking the interrupt's
> > delivery without having to worry about more output screwing the
> > overall picture.
> > 
> >> At
> >> http://www-soc.lip6.fr/~bouyer/xen-log5.txt
> >> you'll find the output of the 'i' key.
> > 
> > (XEN)    IRQ:  34 vec:59 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
> > 
> > (XEN)     IRQ 34 Vec 89:
> > (XEN)       Apic 0x02, Pin  2: vec=59 delivery=LoPri dest=L status=1 polarity=1 irr=1 trig=L mask=0 dest_id:00000001
> 
> Since it repeats in Manuel's latest dump, perhaps the odd combination
> of status=1 and irr=1 is to tell us something? It is my understanding
> that irr ought to become set only when delivery-status clears. Yet I
> don't know what to take from this...

My reading of this is that one interrupt was accepted by the lapic
(irr=1) and that there's a further interrupt pending that hasn't yet
been accepted by the lapic (status=1) because it's still serving the
previous one. But that's all weird because there's no matching
vector in ISR, and hence the IRR bit on the IO-APIC has somehow become
stale or out of sync with the lapic state?

I'm also unsure about how Xen has managed to reach this state, it
shouldn't be possible in the first place.

I don't think I can instrument the paths further with printfs because
it's likely to result in the behavior itself changing and console
spamming. I could however create a static buffer to trace relevant
actions and then dump all them together with the 'i' debug key output.

Sorry Manuel, you seem to have hit some kind of weird bug regarding
interrupt management. If you want to progress further with NetBSD PVH
dom0 it's likely to work on a different box, but I would ask if you
can keep the current box in order for us to continue debugging.

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 24, 2020 at 03:52:25PM +0100, Jan Beulich wrote:
> On 24.11.2020 15:27, Manuel Bouyer wrote:
> > new log at
> > http://www-soc.lip6.fr/~bouyer/xen-log7.txt
> > 
> > this one ends up in a panic, I hope you'll find what you expect here.
> 
> Did you actually, just to have the data point, ever try to disable
> interrupt remapping ("iommu=no-intremap")? For PVH we can't ask you
> to turn of the IOMMU as a whole, but aiui interrupt remapping is
> not a strict prereq. (I'm sure Roger will correct me if I'm wrong.)

No, interrupt remapping is not required for PVH dom0. I was actually
going to ask the same, albeit I'm not sure it will make a difference.

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Tue, Nov 24, 2020 at 03:52:25PM +0100, Jan Beulich wrote:
> On 24.11.2020 15:27, Manuel Bouyer wrote:
> > new log at
> > http://www-soc.lip6.fr/~bouyer/xen-log7.txt
> > 
> > this one ends up in a panic, I hope you'll find what you expect here.
> 
> Did you actually, just to have the data point, ever try to disable
> interrupt remapping ("iommu=no-intremap")? For PVH we can't ask you
> to turn of the IOMMU as a whole, but aiui interrupt remapping is
> not a strict prereq. (I'm sure Roger will correct me if I'm wrong.)

I just tried, it doesn't seem to change anything.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Tue, Nov 24, 2020 at 03:59:27PM +0100, Roger Pau Monné wrote:
> [...]
> 
> Sorry Manuel, you seem to have hit some kind of weird bug regarding
> interrupt management. If you want to progress further with NetBSD PVH
> dom0 it's likely to work on a different box,

the problem is, I don't have a different box with iommu to test it yet.

> but I would ask if you
> can keep the current box in order for us to continue debugging.

This systems isn't in production yet, and I can probably delay migrating the
domUs some more. I think we have 2 more weeks to work on this.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jürgen Groß]

[-- Attachment #1.1.1: Type: text/plain, Size: 3058 bytes --]

On 24.11.20 15:59, Roger Pau Monné wrote:
> On Tue, Nov 24, 2020 at 03:42:28PM +0100, Jan Beulich wrote:
>> On 24.11.2020 11:05, Jan Beulich wrote:
>>> On 23.11.2020 18:39, Manuel Bouyer wrote:
>>>> On Mon, Nov 23, 2020 at 06:06:10PM +0100, Roger Pau Monné wrote:
>>>>> OK, I'm afraid this is likely too verbose and messes with the timings.
>>>>>
>>>>> I've been looking (again) into the code, and I found something weird
>>>>> that I think could be related to the issue you are seeing, but haven't
>>>>> managed to try to boot the NetBSD kernel provided in order to assert
>>>>> whether it solves the issue or not (or even whether I'm able to
>>>>> repro it). Would you mind giving the patch below a try?
>>>>
>>>> With this, I get the same hang but XEN outputs don't wake up the interrupt
>>>> any more. The NetBSD counter shows only one interrupt for ioapic2 pin 2,
>>>> while I would have about 8 at the time of the hang.
>>>>
>>>> So, now it looks like interrupts are blocked forever.
>>>
>>> Which may be a good thing for debugging purposes, because now we have
>>> a way to investigate what is actually blocking the interrupt's
>>> delivery without having to worry about more output screwing the
>>> overall picture.
>>>
>>>> At
>>>> http://www-soc.lip6.fr/~bouyer/xen-log5.txt
>>>> you'll find the output of the 'i' key.
>>>
>>> (XEN)    IRQ:  34 vec:59 IO-APIC-level   status=010 aff:{0}/{0-7} in-flight=1 d0: 34(-MM)
>>>
>>> (XEN)     IRQ 34 Vec 89:
>>> (XEN)       Apic 0x02, Pin  2: vec=59 delivery=LoPri dest=L status=1 polarity=1 irr=1 trig=L mask=0 dest_id:00000001
>>
>> Since it repeats in Manuel's latest dump, perhaps the odd combination
>> of status=1 and irr=1 is to tell us something? It is my understanding
>> that irr ought to become set only when delivery-status clears. Yet I
>> don't know what to take from this...
> 
> My reading of this is that one interrupt was accepted by the lapic
> (irr=1) and that there's a further interrupt pending that hasn't yet
> been accepted by the lapic (status=1) because it's still serving the
> previous one. But that's all weird because there's no matching
> vector in ISR, and hence the IRR bit on the IO-APIC has somehow become
> stale or out of sync with the lapic state?
> 
> I'm also unsure about how Xen has managed to reach this state, it
> shouldn't be possible in the first place.
> 
> I don't think I can instrument the paths further with printfs because
> it's likely to result in the behavior itself changing and console
> spamming. I could however create a static buffer to trace relevant
> actions and then dump all them together with the 'i' debug key output.

debugtrace is your friend here. It already has a debug key for printing
the buffer contents to console ('T').

As the buffer is wrap-around you can even add debug prints in the
related interrupt paths for finding out which paths have been called in
which order and on which cpu. Depending on the findings you might want
to use percpu buffers.


Juergen

[-- Attachment #1.1.2: OpenPGP_0xB0DE9DD628BF132F.asc --]
[-- Type: application/pgp-keys, Size: 3135 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 24, 2020 at 04:08:42PM +0100, Manuel Bouyer wrote:
> On Tue, Nov 24, 2020 at 03:52:25PM +0100, Jan Beulich wrote:
> > On 24.11.2020 15:27, Manuel Bouyer wrote:
> > > new log at
> > > http://www-soc.lip6.fr/~bouyer/xen-log7.txt
> > > 
> > > this one ends up in a panic, I hope you'll find what you expect here.
> > 
> > Did you actually, just to have the data point, ever try to disable
> > interrupt remapping ("iommu=no-intremap")? For PVH we can't ask you
> > to turn of the IOMMU as a whole, but aiui interrupt remapping is
> > not a strict prereq. (I'm sure Roger will correct me if I'm wrong.)
> 
> I just tried, it doesn't seem to change anything.

Could you also give a try with ioapic_ack=new on the Xen command line?

Thanks, Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Tue, Nov 24, 2020 at 04:49:17PM +0100, Roger Pau Monné wrote:
> Could you also give a try with ioapic_ack=new on the Xen command line?

With this I still have the interrupt issue, but Xen doesn't panic on 'i'.
http://www-soc.lip6.fr/~bouyer/xen-log8.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Tue, Nov 24, 2020 at 05:09:14PM +0100, Manuel Bouyer wrote:
> On Tue, Nov 24, 2020 at 04:49:17PM +0100, Roger Pau Monné wrote:
> > Could you also give a try with ioapic_ack=new on the Xen command line?
> 
> With this I still have the interrupt issue, but Xen doesn't panic on 'i'.
> http://www-soc.lip6.fr/~bouyer/xen-log8.txt

Sorry for the delay, I have yet another debug patch for you to try.
Can you remove the ioapic_ack=new from the command line and rebuild
the hypervisor with the provided patch applied and debug trace
enabled? (`gmake -C xen menuconfig` and go into Debugging Options to
find it).

Then once the system stalls use the 'T' debug key to dump the buffer.

Thanks, Roger.
---8<---
diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..adbfccdd0f 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -278,6 +278,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 +289,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 +412,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..baef41cd37 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,10 @@ 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\n", desc->irq);
+
+
     if ( unlikely(!action->nr_guests) )
     {
         /* An interrupt may slip through while freeing an ACKTYPE_EOI irq. */
diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..25ee1791f8 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -1010,6 +1010,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__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Thu, Nov 26, 2020 at 02:34:44PM +0100, Roger Pau Monné wrote:
> On Tue, Nov 24, 2020 at 05:09:14PM +0100, Manuel Bouyer wrote:
> > On Tue, Nov 24, 2020 at 04:49:17PM +0100, Roger Pau Monné wrote:
> > > Could you also give a try with ioapic_ack=new on the Xen command line?
> > 
> > With this I still have the interrupt issue, but Xen doesn't panic on 'i'.
> > http://www-soc.lip6.fr/~bouyer/xen-log8.txt
> 
> Sorry for the delay, I have yet another debug patch for you to try.
> Can you remove the ioapic_ack=new from the command line and rebuild
> the hypervisor with the provided patch applied and debug trace
> enabled? (`gmake -C xen menuconfig` and go into Debugging Options to
> find it).

menuconfig doens't build on NetBSD, I set CONFIG_DEBUG_TRACE=y in
.config. I guess it is enough ?

For the record, my boot commad line is now
menu=Boot Xen PVH:load /test console=com0 root=dk0 -vx; multiboot /xen-test.gz dom0_mem=1024M console=com2 com2=57600,8n1,,0 loglvl=all guest_loglvl=all gnttab_max_nr_frames=64 dom0=pvh iommu=debug dom0_vcpus_pin sync_console dom0_max_vcpus=1 watchdog=force iommu=no-intremap


> 
> Then once the system stalls use the 'T' debug key to dump the buffer.

Here it is. It seems to be stuck in an infinite loop, I hit the 'R' key
after several minutes
http://www-soc.lip6.fr/~bouyer/xen-log9.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Thu, Nov 26, 2020 at 03:16:08PM +0100, Manuel Bouyer wrote:
> On Thu, Nov 26, 2020 at 02:34:44PM +0100, Roger Pau Monné wrote:
> > On Tue, Nov 24, 2020 at 05:09:14PM +0100, Manuel Bouyer wrote:
> > > On Tue, Nov 24, 2020 at 04:49:17PM +0100, Roger Pau Monné wrote:
> > > > Could you also give a try with ioapic_ack=new on the Xen command line?
> > > 
> > > With this I still have the interrupt issue, but Xen doesn't panic on 'i'.
> > > http://www-soc.lip6.fr/~bouyer/xen-log8.txt
> > 
> > Sorry for the delay, I have yet another debug patch for you to try.
> > Can you remove the ioapic_ack=new from the command line and rebuild
> > the hypervisor with the provided patch applied and debug trace
> > enabled? (`gmake -C xen menuconfig` and go into Debugging Options to
> > find it).
> 
> menuconfig doens't build on NetBSD, I set CONFIG_DEBUG_TRACE=y in
> .config. I guess it is enough ?
> 
> For the record, my boot commad line is now
> menu=Boot Xen PVH:load /test console=com0 root=dk0 -vx; multiboot /xen-test.gz dom0_mem=1024M console=com2 com2=57600,8n1,,0 loglvl=all guest_loglvl=all gnttab_max_nr_frames=64 dom0=pvh iommu=debug dom0_vcpus_pin sync_console dom0_max_vcpus=1 watchdog=force iommu=no-intremap
> 
> 
> > 
> > Then once the system stalls use the 'T' debug key to dump the buffer.
> 
> Here it is. It seems to be stuck in an infinite loop, I hit the 'R' key
> after several minutes
> http://www-soc.lip6.fr/~bouyer/xen-log9.txt

Oh, that's actually very useful. The interrupt is being constantly
injected from the hardware and received by Xen, it's just not then
injected into dom0 - that's the bit we are missing. Let me look into
adding some more debug to that path, hopefully it will tell us where
things are getting blocked.

Roger.

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Thu, Nov 26, 2020 at 03:26:35PM +0100, Roger Pau Monné wrote:
> On Thu, Nov 26, 2020 at 03:16:08PM +0100, Manuel Bouyer wrote:
> > On Thu, Nov 26, 2020 at 02:34:44PM +0100, Roger Pau Monné wrote:
> > > On Tue, Nov 24, 2020 at 05:09:14PM +0100, Manuel Bouyer wrote:
> > > > On Tue, Nov 24, 2020 at 04:49:17PM +0100, Roger Pau Monné wrote:
> > > > > Could you also give a try with ioapic_ack=new on the Xen command line?
> > > > 
> > > > With this I still have the interrupt issue, but Xen doesn't panic on 'i'.
> > > > http://www-soc.lip6.fr/~bouyer/xen-log8.txt
> > > 
> > > Sorry for the delay, I have yet another debug patch for you to try.
> > > Can you remove the ioapic_ack=new from the command line and rebuild
> > > the hypervisor with the provided patch applied and debug trace
> > > enabled? (`gmake -C xen menuconfig` and go into Debugging Options to
> > > find it).
> > 
> > menuconfig doens't build on NetBSD, I set CONFIG_DEBUG_TRACE=y in
> > .config. I guess it is enough ?
> > 
> > For the record, my boot commad line is now
> > menu=Boot Xen PVH:load /test console=com0 root=dk0 -vx; multiboot /xen-test.gz dom0_mem=1024M console=com2 com2=57600,8n1,,0 loglvl=all guest_loglvl=all gnttab_max_nr_frames=64 dom0=pvh iommu=debug dom0_vcpus_pin sync_console dom0_max_vcpus=1 watchdog=force iommu=no-intremap
> > 
> > 
> > > 
> > > Then once the system stalls use the 'T' debug key to dump the buffer.
> > 
> > Here it is. It seems to be stuck in an infinite loop, I hit the 'R' key
> > after several minutes
> > http://www-soc.lip6.fr/~bouyer/xen-log9.txt
> 
> Oh, that's actually very useful. The interrupt is being constantly
> injected from the hardware and received by Xen, it's just not then
> injected into dom0 - that's the bit we are missing. Let me look into
> adding some more debug to that path, hopefully it will tell us where
> things are getting blocked.

So I have yet one more patch for you to try, this one has more
debugging and a slight change in the emulated IO-APIC behavior.
Depending on the result I might have to find a way to mask the
interrupt so it doesn't spam the whole buffer in order for us to see
exactly what triggered this scenario you are in.

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..aeff9c7687 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -257,7 +257,17 @@ 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;
+        if ( is_iommu_enabled(d) )
+        {
+            spin_unlock(&d->arch.hvm.irq_lock);
+            hvm_dpci_eoi(d, gsi, pent);
+            spin_lock(&d->arch.hvm.irq_lock);
+        }
+    }
     else if ( !ent.fields.mask &&
               !ent.fields.remote_irr &&
               hvm_irq->gsi_assert_count[idx] )
@@ -278,6 +288,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 +299,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 +422,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..baef41cd37 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,10 @@ 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\n", desc->irq);
+
+
     if ( unlikely(!action->nr_guests) )
     {
         /* An interrupt may slip through while freeing an ACKTYPE_EOI irq. */
diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..92f3670508 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -828,6 +828,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 +1013,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__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

[-- Attachment #1: Type: text/plain, Size: 1012 bytes --]

On Thu, Nov 26, 2020 at 04:09:37PM +0100, Roger Pau Monné wrote:
> > 
> > Oh, that's actually very useful. The interrupt is being constantly
> > injected from the hardware and received by Xen, it's just not then
> > injected into dom0 - that's the bit we are missing. Let me look into
> > adding some more debug to that path, hopefully it will tell us where
> > things are getting blocked.
> 
> So I have yet one more patch for you to try, this one has more
> debugging and a slight change in the emulated IO-APIC behavior.
> Depending on the result I might have to find a way to mask the
> interrupt so it doesn't spam the whole buffer in order for us to see
> exactly what triggered this scenario you are in.

OK, here it is:
http://www-soc.lip6.fr/~bouyer/xen-log9.txt

I had to restart from a clean source tree to apply this patch, so to make
sure we're in sync I attached the diff from my sources

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

[-- Attachment #2: xen.diff --]
[-- Type: text/plain, Size: 6752 bytes --]

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..aeff9c7687 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -257,7 +257,17 @@ 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;
+        if ( is_iommu_enabled(d) )
+        {
+            spin_unlock(&d->arch.hvm.irq_lock);
+            hvm_dpci_eoi(d, gsi, pent);
+            spin_lock(&d->arch.hvm.irq_lock);
+        }
+    }
     else if ( !ent.fields.mask &&
               !ent.fields.remote_irr &&
               hvm_irq->gsi_assert_count[idx] )
@@ -278,6 +288,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 +299,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 +422,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 e66fa99ec7..c28025657d 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 93c4fb9a79..cc5a0e2a21 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,10 @@ 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\n", desc->irq);
+
+
     if ( unlikely(!action->nr_guests) )
     {
         /* An interrupt may slip through while freeing an ACKTYPE_EOI irq. */
diff --git a/xen/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..86c2db9da0 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -174,7 +174,6 @@ 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);
         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 +827,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 +1012,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/drivers/vpci/msix.c b/xen/drivers/vpci/msix.c
index 64dd0a929c..3eb6102a61 100644
--- a/xen/drivers/vpci/msix.c
+++ b/xen/drivers/vpci/msix.c
@@ -370,7 +370,7 @@ static int msix_write(struct vcpu *v, unsigned long addr, unsigned int len,
 
             entry->updated = false;
         }
-        else
+        else if ( msix->enabled )
             vpci_msix_arch_mask_entry(entry, pdev, entry->masked);
 
         break;
diff --git a/xen/include/xen/irq.h b/xen/include/xen/irq.h
index 43d567fe44..871810134f 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__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

On Thu, Nov 26, 2020 at 06:20:34PM +0100, Manuel Bouyer wrote:
> On Thu, Nov 26, 2020 at 04:09:37PM +0100, Roger Pau Monné wrote:
> > > 
> > > Oh, that's actually very useful. The interrupt is being constantly
> > > injected from the hardware and received by Xen, it's just not then
> > > injected into dom0 - that's the bit we are missing. Let me look into
> > > adding some more debug to that path, hopefully it will tell us where
> > > things are getting blocked.
> > 
> > So I have yet one more patch for you to try, this one has more
> > debugging and a slight change in the emulated IO-APIC behavior.
> > Depending on the result I might have to find a way to mask the
> > interrupt so it doesn't spam the whole buffer in order for us to see
> > exactly what triggered this scenario you are in.
> 
> OK, here it is:
> http://www-soc.lip6.fr/~bouyer/xen-log9.txt
> 
> I had to restart from a clean source tree to apply this patch, so to make
> sure we're in sync I attached the diff from my sources

I'm quite confused about why your trace don't even get into
hvm_do_IRQ_dpci, so I've added some more debug info.

Here is the new patch, sorry for so many rounds of testing.
---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/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..92f3670508 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -828,6 +828,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 +1013,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__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 27.11.2020 11:59, Roger Pau Monné wrote:
> On Thu, Nov 26, 2020 at 06:20:34PM +0100, Manuel Bouyer wrote:
>> On Thu, Nov 26, 2020 at 04:09:37PM +0100, Roger Pau Monné wrote:
>>>>
>>>> Oh, that's actually very useful. The interrupt is being constantly
>>>> injected from the hardware and received by Xen, it's just not then
>>>> injected into dom0 - that's the bit we are missing. Let me look into
>>>> adding some more debug to that path, hopefully it will tell us where
>>>> things are getting blocked.
>>>
>>> So I have yet one more patch for you to try, this one has more
>>> debugging and a slight change in the emulated IO-APIC behavior.
>>> Depending on the result I might have to find a way to mask the
>>> interrupt so it doesn't spam the whole buffer in order for us to see
>>> exactly what triggered this scenario you are in.
>>
>> OK, here it is:
>> http://www-soc.lip6.fr/~bouyer/xen-log9.txt
>>
>> I had to restart from a clean source tree to apply this patch, so to make
>> sure we're in sync I attached the diff from my sources
> 
> I'm quite confused about why your trace don't even get into
> hvm_do_IRQ_dpci, so I've added some more debug info.

Are you sure it doesn't? I'm somewhat worried we may ...

> --- a/xen/drivers/passthrough/io.c
> +++ b/xen/drivers/passthrough/io.c
> @@ -828,6 +828,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);

... take the early exit path up from here. I still wouldn't be
able to say why that is, because when I looked yesterday I
think I found all failure paths leading to HVM_IRQ_DPCI_MAPPED
remaining clear to have a log message associated, while Manuel
said there were no other log messages.

In the context of this I also started wondering whether it's
the right thing to do to start the EOI timer if the subsequent
call to send_guest_pirq() also doesn't actually send any event.
In this case the guest is effectively guaranteed to not handle
the interrupt. When the interrupt isn't shared, I think we
ought to ->end() it right away, but without unmasking it, to
unblock same or lower priority interrupts. What to do in the
shared case is less obvious to me ...

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 27, 2020 at 11:59:48AM +0100, Roger Pau Monné wrote:
> > 
> > I had to restart from a clean source tree to apply this patch, so to make
> > sure we're in sync I attached the diff from my sources
> 
> I'm quite confused about why your trace don't even get into
> hvm_do_IRQ_dpci, so I've added some more debug info.
> 
> Here is the new patch, sorry for so many rounds of testing.

No problem, it's expected for this kind of debug :)

http://www-soc.lip6.fr/~bouyer/xen-log11.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 27.11.2020 12:19, Manuel Bouyer wrote:
> On Fri, Nov 27, 2020 at 11:59:48AM +0100, Roger Pau Monné wrote:
>>>
>>> I had to restart from a clean source tree to apply this patch, so to make
>>> sure we're in sync I attached the diff from my sources
>>
>> I'm quite confused about why your trace don't even get into
>> hvm_do_IRQ_dpci, so I've added some more debug info.
>>
>> Here is the new patch, sorry for so many rounds of testing.
> 
> No problem, it's expected for this kind of debug :)
> 
> http://www-soc.lip6.fr/~bouyer/xen-log11.txt

Hmm, this one now has hvm_do_IRQ_dpci entries. Maybe the previous one
was again from a stale binary?

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

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.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 27, 2020 at 12:21:23PM +0100, Jan Beulich wrote:
> On 27.11.2020 12:19, Manuel Bouyer wrote:
> > On Fri, Nov 27, 2020 at 11:59:48AM +0100, Roger Pau Monné wrote:
> >>>
> >>> I had to restart from a clean source tree to apply this patch, so to make
> >>> sure we're in sync I attached the diff from my sources
> >>
> >> I'm quite confused about why your trace don't even get into
> >> hvm_do_IRQ_dpci, so I've added some more debug info.
> >>
> >> Here is the new patch, sorry for so many rounds of testing.
> > 
> > No problem, it's expected for this kind of debug :)
> > 
> > http://www-soc.lip6.fr/~bouyer/xen-log11.txt
> 
> Hmm, this one now has hvm_do_IRQ_dpci entries. Maybe the previous one
> was again from a stale binary?

But I do see hvm_do_IRQ_dpci in the previous one too (xen-log10.txt)

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

[-- Attachment #1: Type: text/plain, Size: 1299 bytes --]

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 

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

[-- Attachment #2: xen.diff --]
[-- Type: text/plain, Size: 6705 bytes --]

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 e66fa99ec7..c28025657d 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 93c4fb9a79..c3a75d98a7 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/drivers/passthrough/io.c b/xen/drivers/passthrough/io.c
index 6b1305a3e5..86c2db9da0 100644
--- a/xen/drivers/passthrough/io.c
+++ b/xen/drivers/passthrough/io.c
@@ -174,7 +174,6 @@ 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);
         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 +827,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 +1012,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/drivers/vpci/msix.c b/xen/drivers/vpci/msix.c
index 64dd0a929c..3eb6102a61 100644
--- a/xen/drivers/vpci/msix.c
+++ b/xen/drivers/vpci/msix.c
@@ -370,7 +370,7 @@ static int msix_write(struct vcpu *v, unsigned long addr, unsigned int len,
 
             entry->updated = false;
         }
-        else
+        else if ( msix->enabled )
             vpci_msix_arch_mask_entry(entry, pdev, entry->masked);
 
         break;
diff --git a/xen/include/xen/irq.h b/xen/include/xen/irq.h
index 43d567fe44..871810134f 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__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 27.11.2020 14:10, Manuel Bouyer wrote:
> On Fri, Nov 27, 2020 at 12:21:23PM +0100, Jan Beulich wrote:
>> On 27.11.2020 12:19, Manuel Bouyer wrote:
>>> On Fri, Nov 27, 2020 at 11:59:48AM +0100, Roger Pau Monné wrote:
>>>>>
>>>>> I had to restart from a clean source tree to apply this patch, so to make
>>>>> sure we're in sync I attached the diff from my sources
>>>>
>>>> I'm quite confused about why your trace don't even get into
>>>> hvm_do_IRQ_dpci, so I've added some more debug info.
>>>>
>>>> Here is the new patch, sorry for so many rounds of testing.
>>>
>>> No problem, it's expected for this kind of debug :)
>>>
>>> http://www-soc.lip6.fr/~bouyer/xen-log11.txt
>>
>> Hmm, this one now has hvm_do_IRQ_dpci entries. Maybe the previous one
>> was again from a stale binary?
> 
> But I do see hvm_do_IRQ_dpci in the previous one too (xen-log10.txt)

Ah yes. In your respective mail the link said 9 though instead of 10.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 27, 2020 at 02:14:55PM +0100, Jan Beulich wrote:
> Ah yes. In your respective mail the link said 9 though instead of 10.

Ops, sorry. I forgot to update the link I guess ...

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

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.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

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.
I removed it, here's a new trace

http://www-soc.lip6.fr/~bouyer/xen-log12.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

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

I was sort of expecting that this might be where we fail to
set the assert count back to zero. Will need further
thinking, if nothing else than how to turn down the verbosity
without hiding crucial information. Or maybe Roger has got
some idea ...

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jürgen Groß]

[-- Attachment #1.1.1: Type: text/plain, Size: 2782 bytes --]

On 27.11.20 14:40, 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
> 
> I was sort of expecting that this might be where we fail to
> set the assert count back to zero. Will need further
> thinking, if nothing else than how to turn down the verbosity
> without hiding crucial information. Or maybe Roger has got
> some idea ...

Set debugtrace buffer size to something huge?

Panic when the buffer is full?

It should be noted that the debugtrace in being printed in case of a
panic.


Juergen


[-- Attachment #1.1.2: OpenPGP_0xB0DE9DD628BF132F.asc --]
[-- Type: application/pgp-keys, Size: 3135 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

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

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

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__ */

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Fri, Nov 27, 2020 at 09:22:11PM +0100, Roger Pau Monné wrote:
> > 
> > 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
the trace is at
http://www-soc.lip6.fr/~bouyer/xen-log13.txt

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Roger Pau Monné]

[-- Attachment #1: Type: text/plain, Size: 1011 bytes --]

On Fri, Nov 27, 2020 at 10:44:20PM +0100, Manuel Bouyer wrote:
> On Fri, Nov 27, 2020 at 09:22:11PM +0100, Roger Pau Monné wrote:
> > > 
> > > 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
> the trace is at
> http://www-soc.lip6.fr/~bouyer/xen-log13.txt

Thanks! I think I've found the issue and I'm attaching a possible fix
(fix.patch) to this email. In any case I've also attached a further
debug patch, in case the fix turns out to be wrong. Please test the
fix first, as the debug patch will end up triggering a panic when the
buffer is full.

Roger.

[-- Attachment #2: fix.patch --]
[-- Type: text/plain, Size: 1389 bytes --]

From 232112a292c3b82b3063ea6c7aab56afc8e03f67 Mon Sep 17 00:00:00 2001
From: Roger Pau Monne <roger.pau@citrix.com>
Date: Sat, 28 Nov 2020 15:06:26 +0100
Subject: [PATCH] x86/vioapic: fix usage of index in place of GSI in
 vioapic_write_redirent
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

The usage of idx instead of the GSI in vioapic_write_redirent when
accessing gsi_assert_count can cause a PVH dom0 with multiple
vIO-APICs to lose interrupts in case a pin of a IO-APIC different than
the first one is unmasked with pending interrupts.

Switch to use gsi instead to fix the issue.

Fixes: 9f44b08f7d0e4 ('x86/vioapic: introduce support for multiple vIO APICS')
Signed-off-by: Roger Pau Monné <roge.rpau@citrix.com>
---
 xen/arch/x86/hvm/vioapic.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/xen/arch/x86/hvm/vioapic.c b/xen/arch/x86/hvm/vioapic.c
index 67d4a6237f..e64abee7a9 100644
--- a/xen/arch/x86/hvm/vioapic.c
+++ b/xen/arch/x86/hvm/vioapic.c
@@ -260,7 +260,7 @@ static void vioapic_write_redirent(
         pent->fields.remote_irr = 0;
     else if ( !ent.fields.mask &&
               !ent.fields.remote_irr &&
-              hvm_irq->gsi_assert_count[idx] )
+              hvm_irq->gsi_assert_count[gsi] )
     {
         pent->fields.remote_irr = 1;
         vioapic_deliver(vioapic, idx);
-- 
2.29.2


[-- Attachment #3: debug.patch --]
[-- Type: text/plain, Size: 7609 bytes --]

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 e64abee7a9..df82147f9b 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[gsi] )
@@ -278,6 +282,12 @@ 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 irr %u mask %u assert count %u\n",
+                              gsi, pent->fields.remote_irr, pent->fields.mask,
+                              hvm_irq->gsi_assert_count[gsi]);
+
         if ( ret )
         {
             gprintk(XENLOG_ERR,
@@ -285,6 +295,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 +418,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..e0949b7057 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,10 @@ 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 irr %u\n", guest_gsi,
+                          ent->fields.remote_irr);
+
     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 17
+
 #endif /* __XEN_IRQ_H__ */
-- 
2.29.2

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
> > the trace is at
> > http://www-soc.lip6.fr/~bouyer/xen-log13.txt
> 
> Thanks! I think I've found the issue and I'm attaching a possible fix
> (fix.patch) to this email. In any case I've also attached a further
> debug patch, in case the fix turns out to be wrong. Please test the
> fix first, as the debug patch will end up triggering a panic when the
> buffer is full.

Yes, fix.patch does make the system boot as expected !
thanks !

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Sat, Nov 28, 2020 at 06:14:30PM +0100, Manuel Bouyer wrote:
> On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
> > > the trace is at
> > > http://www-soc.lip6.fr/~bouyer/xen-log13.txt
> > 
> > Thanks! I think I've found the issue and I'm attaching a possible fix
> > (fix.patch) to this email. In any case I've also attached a further
> > debug patch, in case the fix turns out to be wrong. Please test the
> > fix first, as the debug patch will end up triggering a panic when the
> > buffer is full.
> 
> Yes, fix.patch does make the system boot as expected !
> thanks !

FYI it also works with Xen 4.13

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 28.11.2020 18:14, Manuel Bouyer wrote:
> On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
>>> the trace is at
>>> http://www-soc.lip6.fr/~bouyer/xen-log13.txt
>>
>> Thanks! I think I've found the issue and I'm attaching a possible fix
>> (fix.patch) to this email. In any case I've also attached a further
>> debug patch, in case the fix turns out to be wrong. Please test the
>> fix first, as the debug patch will end up triggering a panic when the
>> buffer is full.
> 
> Yes, fix.patch does make the system boot as expected !

May I translate this to a Tested-by?

Patch also
Reviewed-by: Jan Beulich <jbeulich@suse.com>

Thanks much to both of you for all the effort here!

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Mon, Nov 30, 2020 at 11:00:23AM +0100, Jan Beulich wrote:
> On 28.11.2020 18:14, Manuel Bouyer wrote:
> > On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
> >>> the trace is at
> >>> http://www-soc.lip6.fr/~bouyer/xen-log13.txt
> >>
> >> Thanks! I think I've found the issue and I'm attaching a possible fix
> >> (fix.patch) to this email. In any case I've also attached a further
> >> debug patch, in case the fix turns out to be wrong. Please test the
> >> fix first, as the debug patch will end up triggering a panic when the
> >> buffer is full.
> > 
> > Yes, fix.patch does make the system boot as expected !
> 
> May I translate this to a Tested-by?

Sure !

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

[-- Attachment #1: Type: text/plain, Size: 988 bytes --]

On Mon, Nov 30, 2020 at 11:00:23AM +0100, Jan Beulich wrote:
> On 28.11.2020 18:14, Manuel Bouyer wrote:
> > On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
> >>> the trace is at
> >>> http://www-soc.lip6.fr/~bouyer/xen-log13.txt
> >>
> >> Thanks! I think I've found the issue and I'm attaching a possible fix
> >> (fix.patch) to this email. In any case I've also attached a further
> >> debug patch, in case the fix turns out to be wrong. Please test the
> >> fix first, as the debug patch will end up triggering a panic when the
> >> buffer is full.
> > 
> > Yes, fix.patch does make the system boot as expected !
> 
> May I translate this to a Tested-by?
> 
> Patch also
> Reviewed-by: Jan Beulich <jbeulich@suse.com>
> 
> Thanks much to both of you for all the effort here!

Also, please don't forget the attached patch !
Without it, the hypervisor panics.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

[-- Attachment #2: patch-pvh-panic --]
[-- Type: text/plain, Size: 441 bytes --]

diff --git a/xen/drivers/vpci/msix.c b/xen/drivers/vpci/msix.c
index 64dd0a929c..3eb6102a61 100644
--- xen/drivers/vpci/msix.c.orig
+++ xen/drivers/vpci/msix.c
@@ -370,7 +370,7 @@ static int msix_write(struct vcpu *v, unsigned long addr, unsigned int len,
 
             entry->updated = false;
         }
-        else
+        else if ( msix->enabled )
             vpci_msix_arch_mask_entry(entry, pdev, entry->masked);
 
         break;

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 30.11.2020 12:35, Manuel Bouyer wrote:
> On Mon, Nov 30, 2020 at 11:00:23AM +0100, Jan Beulich wrote:
>> On 28.11.2020 18:14, Manuel Bouyer wrote:
>>> On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
>>>>> the trace is at
>>>>> http://www-soc.lip6.fr/~bouyer/xen-log13.txt
>>>>
>>>> Thanks! I think I've found the issue and I'm attaching a possible fix
>>>> (fix.patch) to this email. In any case I've also attached a further
>>>> debug patch, in case the fix turns out to be wrong. Please test the
>>>> fix first, as the debug patch will end up triggering a panic when the
>>>> buffer is full.
>>>
>>> Yes, fix.patch does make the system boot as expected !
>>
>> May I translate this to a Tested-by?
>>
>> Patch also
>> Reviewed-by: Jan Beulich <jbeulich@suse.com>
>>
>> Thanks much to both of you for all the effort here!
> 
> Also, please don't forget the attached patch !
> Without it, the hypervisor panics.

Well - this one still needs a proper description and S-o-b.
The other one came in immediately consumable shape right away.

Jan

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Manuel Bouyer]

On Mon, Nov 30, 2020 at 12:44:23PM +0100, Jan Beulich wrote:
> On 30.11.2020 12:35, Manuel Bouyer wrote:
> > On Mon, Nov 30, 2020 at 11:00:23AM +0100, Jan Beulich wrote:
> >> On 28.11.2020 18:14, Manuel Bouyer wrote:
> >>> On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
> >>>>> the trace is at
> >>>>> http://www-soc.lip6.fr/~bouyer/xen-log13.txt
> >>>>
> >>>> Thanks! I think I've found the issue and I'm attaching a possible fix
> >>>> (fix.patch) to this email. In any case I've also attached a further
> >>>> debug patch, in case the fix turns out to be wrong. Please test the
> >>>> fix first, as the debug patch will end up triggering a panic when the
> >>>> buffer is full.
> >>>
> >>> Yes, fix.patch does make the system boot as expected !
> >>
> >> May I translate this to a Tested-by?
> >>
> >> Patch also
> >> Reviewed-by: Jan Beulich <jbeulich@suse.com>
> >>
> >> Thanks much to both of you for all the effort here!
> > 
> > Also, please don't forget the attached patch !
> > Without it, the hypervisor panics.
> 
> Well - this one still needs a proper description and S-o-b.
> The other one came in immediately consumable shape right away.

The patch was sent by Roger on 12 Nov 2020, in reply to my mail
about the panic. The panic is:

(XEN) Xen call trace:
(XEN)    [<ffff82d08031cc28>] R vpci_msix_arch_mask_entry+0x18/0x20
(XEN)    [<ffff82d08025a38a>] S drivers/vpci/msix.c#msix_write+0x18a/0x2b0
(XEN)    [<ffff82d08030d943>] S arch/x86/hvm/intercept.c#hvm_mmio_write+0x23/0x3
0
(XEN)    [<ffff82d08030dd19>] S hvm_process_io_intercept+0x1e9/0x260
(XEN)    [<ffff82d08030ddad>] S hvm_io_intercept+0x1d/0x40
(XEN)    [<ffff82d0802fe7ba>] S arch/x86/hvm/emulate.c#hvmemul_do_io+0x26a/0x4d0
(XEN)    [<ffff82d080259ef9>] S drivers/vpci/msix.c#msix_accept+0x9/0x20
(XEN)    [<ffff82d0802fea56>] S arch/x86/hvm/emulate.c#hvmemul_do_io_buffer+0x36
/0x70
(XEN)    [<ffff82d0802ff005>] S arch/x86/hvm/emulate.c#hvmemul_linear_mmio_access+0x1e5/0x300
(XEN)    [<ffff82d0802fff44>] S arch/x86/hvm/emulate.c#linear_write+0x84/0x160
(XEN)    [<ffff82d080301ca8>] S arch/x86/hvm/emulate.c#hvmemul_write+0xe8/0x100
(XEN)    [<ffff82d0802de6cc>] S x86_emulate+0x289dc/0x2cfb0
(XEN)    [<ffff82d08027c7ab>] S map_domain_page+0x4b/0x600
(XEN)    [<ffff82d080340eaa>] S __get_gfn_type_access+0x6a/0x100
(XEN)    [<ffff82d08034a367>] S arch/x86/mm/p2m-ept.c#ept_next_level+0x107/0x150
(XEN)    [<ffff82d0802e4961>] S x86_emulate_wrapper+0x21/0x60
(XEN)    [<ffff82d08030024f>] S arch/x86/hvm/emulate.c#_hvm_emulate_one+0x4f/0x220
(XEN)    [<ffff82d0803004ed>] S hvmemul_get_seg_reg+0x4d/0x50
(XEN)    [<ffff82d08030042e>] S hvm_emulate_one+0xe/0x10
(XEN)    [<ffff82d08030e4ca>] S hvm_emulate_one_insn+0x3a/0xf0
(XEN)    [<ffff82d0802e4af0>] S x86_insn_is_mem_access+0/0x260
(XEN)    [<ffff82d08030e5c9>] S handle_mmio_with_translation+0x49/0x60
(XEN)    [<ffff82d080305d78>] S hvm_hap_nested_page_fault+0x2c8/0x720
(XEN)    [<ffff82d0802fea56>] S arch/x86/hvm/emulate.c#hv(XEN) 
(XEN) ****************************************
(XEN) Panic on CPU 13:
(XEN) Assertion 'entry->arch.pirq != INVALID_PIRQ' failed at vmsi.c:843
(XEN) ****************************************

This is when it configures the broadcom network interface, which interrupts
at "msix3 vec 0". It is the first MSI-X device configured; the previous
ones are MSI only.

-- 
Manuel Bouyer <bouyer@antioche.eu.org>
     NetBSD: 26 ans d'experience feront toujours la difference
--

Re: NetBSD dom0 PVH: hardware interrupts stalls

[Jan Beulich]

On 30.11.2020 12:50, Manuel Bouyer wrote:
> On Mon, Nov 30, 2020 at 12:44:23PM +0100, Jan Beulich wrote:
>> On 30.11.2020 12:35, Manuel Bouyer wrote:
>>> On Mon, Nov 30, 2020 at 11:00:23AM +0100, Jan Beulich wrote:
>>>> On 28.11.2020 18:14, Manuel Bouyer wrote:
>>>>> On Sat, Nov 28, 2020 at 03:53:11PM +0100, Roger Pau Monné wrote:
>>>>>>> the trace is at
>>>>>>> http://www-soc.lip6.fr/~bouyer/xen-log13.txt
>>>>>>
>>>>>> Thanks! I think I've found the issue and I'm attaching a possible fix
>>>>>> (fix.patch) to this email. In any case I've also attached a further
>>>>>> debug patch, in case the fix turns out to be wrong. Please test the
>>>>>> fix first, as the debug patch will end up triggering a panic when the
>>>>>> buffer is full.
>>>>>
>>>>> Yes, fix.patch does make the system boot as expected !
>>>>
>>>> May I translate this to a Tested-by?
>>>>
>>>> Patch also
>>>> Reviewed-by: Jan Beulich <jbeulich@suse.com>
>>>>
>>>> Thanks much to both of you for all the effort here!
>>>
>>> Also, please don't forget the attached patch !
>>> Without it, the hypervisor panics.
>>
>> Well - this one still needs a proper description and S-o-b.
>> The other one came in immediately consumable shape right away.
> 
> The patch was sent by Roger on 12 Nov 2020, in reply to my mail
> about the panic.

I'm aware, but that wasn't a patch I can take and commit. I'm not
even entirely certain the code change is the final one, not the
least because of not having seen a description of the change, yet.

Jan