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.
>From 9f1cf4f5f4f143be2d9e87d1b2f4c4cf4c286b69 Mon Sep 17 00:00:00 2001
From: Roger Pau Monne <[email protected]>
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
>From 381eebe51657a3b3101dc80880fa3350dcfb1e23 Mon Sep 17 00:00:00 2001
From: Roger Pau Monne <[email protected]>
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
