[PATCH 0/1] NIU: fix spurious interrupts

[PATCH 0/1] NIU: fix spurious interrupts

[Hong H. Pham]

Hi,

I've tracked down a hang on a SPARC64 system (a Netra T5220 with 64 strands)
whenever the NIU is handling lots of receive traffic.  The hang is
reproducible by running iperf with multiple TCP streams (eg. iperf -P16 ...),
with the SPARC box being the listener.

I've found that it's possible for an RX DMA interrupt to be triggered
while NAPI is in progress.  When this happens, spurious interrupts will
keep being regenerated which will cause the CPU to hang.  It's too busy
servicing the spurious interrupts, and the NIU NAPI handler (or anything
else on that CPU) never gets a chance to run.

In niu_schedule_napi(), if the logical device interrupt is unconditionally
masked out by calling __niu_fastpath_interrupt(), the hang goes away.

Regards,
Hong

[PATCH 1/1] NIU: fix spurious interrupts

[Hong H. Pham]

It's possible for an interrupt to be triggered while NAPI is in progress
(at least on a SPARC64 SUN4V system).  Unconditionally call
__niu_fastpath_interrupt() in niu_schedule_napi() to mask out the logical
device being serviced to avoid further spurious interrupts from being
generated.

Signed-off-by: Hong H. Pham <hong.pham@windriver.com>
---
 drivers/net/niu.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/drivers/net/niu.c b/drivers/net/niu.c
index 2b17453..80d4fb6 100644
--- a/drivers/net/niu.c
+++ b/drivers/net/niu.c
@@ -4221,11 +4221,11 @@ static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 	if (likely(napi_schedule_prep(&lp->napi))) {
 		lp->v0 = v0;
 		lp->v1 = v1;
 		lp->v2 = v2;
-		__niu_fastpath_interrupt(np, lp->ldg_num, v0);
 		__napi_schedule(&lp->napi);
 	}
+	__niu_fastpath_interrupt(np, lp->ldg_num, v0);
 }
 
 static irqreturn_t niu_interrupt(int irq, void *dev_id)
 {
-- 
1.6.0.3

Re: [PATCH 0/1] NIU: fix spurious interrupts

[David Miller]

From: "Hong H. Pham" <hong.pham@windriver.com>
Date: Mon, 11 May 2009 15:00:52 -0400

> I've tracked down a hang on a SPARC64 system (a Netra T5220 with 64 strands)
> whenever the NIU is handling lots of receive traffic.  The hang is
> reproducible by running iperf with multiple TCP streams (eg. iperf -P16 ...),
> with the SPARC box being the listener.
> 
> I've found that it's possible for an RX DMA interrupt to be triggered
> while NAPI is in progress.  When this happens, spurious interrupts will
> keep being regenerated which will cause the CPU to hang.  It's too busy
> servicing the spurious interrupts, and the NIU NAPI handler (or anything
> else on that CPU) never gets a chance to run.
> 
> In niu_schedule_napi(), if the logical device interrupt is unconditionally
> masked out by calling __niu_fastpath_interrupt(), the hang goes away.

Thanks for tracking down this problem, but I want to understand
why this even happens.  As far as I can tell it shouldn't.

When we are done polling, the order of events is:

1) unmask LDG interrupt(s)
2) napi_complete()
3) rearm LDG interrupt(s)

The interrupts should not be sent again until that rearm operation,
which is after NAPI is completed.  So the condition you are hitting
does not seem possible.

Matheos, can the chip violate this?  If an RX event is reported
in an LDG, it is masked, and then unmaked the interrupt should
not appear until the LDG is also rearmed right?

Re: [PATCH 0/1] NIU: fix spurious interrupts

[Hong H. Pham]

David Miller wrote:
> Thanks for tracking down this problem, but I want to understand
> why this even happens.  As far as I can tell it shouldn't.
> 
> When we are done polling, the order of events is:
> 
> 1) unmask LDG interrupt(s)
> 2) napi_complete()
> 3) rearm LDG interrupt(s)
> 
> The interrupts should not be sent again until that rearm operation,
> which is after NAPI is completed.  So the condition you are hitting
> does not seem possible.

My thoughts exactly... this should not happen.

> Matheos, can the chip violate this?  If an RX event is reported
> in an LDG, it is masked, and then unmaked the interrupt should
> not appear until the LDG is also rearmed right?

Unfortunately I don't have a PCIe NIU card to test in an x86 box.  If
the hang does not happen on x86 (which is my suspicion), that would rule
out a problem with the NIU chip.  That would mean there's some
interaction between the NIU and sun4v hypervisor that's causing the
spurious interrupts.

Hong

Re: [PATCH 0/1] NIU: fix spurious interrupts

[David Miller]

From: "Hong H. Pham" <hong.pham@windriver.com>
Date: Tue, 19 May 2009 17:52:15 -0400

> Unfortunately I don't have a PCIe NIU card to test in an x86 box.
> If the hang does not happen on x86 (which is my suspicion), that
> would rule out a problem with the NIU chip.  That would mean there's
> some interaction between the NIU and sun4v hypervisor that's causing
> the spurious interrupts.

I am still leaning towards the NIU chip, or our programming of
it, as causing this behavior.

Although it's possible that the interrupt logic inside of
Niagara-T2, or how it's hooked up to the internal NIU ASIC
inside of the CPU, might be to blame I don't consider it likely
given the basic gist of the behavior you see.

To quote section 17.3.2 of the UltraSPARC-T2 manual:

	An interrupt will only be issued if the timer is zero,
	the arm bit is set, and one of more LD's in the LDG, have
	their flags set and not masked.

which confirms our understanding of how this should work.

Can you test something Hong?  Simply trigger the hung case
and when it happens read the LDG registers to see if the ARM
bit is set, and what the LDG mask bits say.

There might be a bug somewhere that causes us to call
niu_ldg_rearm() improperly.  In particular I'm looking
at that test done in niu_interrupt():

	if (likely(v0 & ~((u64)1 << LDN_MIF)))
		niu_schedule_napi(np, lp, v0, v1, v2);
	else
		niu_ldg_rearm(np, lp, 1);

If we call niu_ldg_rearm() on an LDG being serviced by NAPI
before that poll sequence calls napi_complete() we could
definitely see this weird behavior.  And whatever causes
that would be the bug to fix.

Thanks!

 

Re: [PATCH 0/1] NIU: fix spurious interrupts

[Hong H. Pham]

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

I've added the suggested instrumentations to dump out the LD interrupt registers
when spurious interrupts occur.  Attached below is a kernel log.

In all cases, interrupts are being generated even though the LDG has been disarmed!

Regards,
Hong

[502327.615387] niu: eth4: Link is up at 10Gb/sec, full duplex
[502337.835372] NIU: eth4 CPU=42 LDG=38: interrupt received while NAPI is in progress
[502337.835392]   rx_vec=0x0400 LD_IM0[ldf_mask]=0x00
[502337.835404]   LDG_IMGMT=0x0000000000814018 [arm=0x00 timer=0x18]
[502337.835426] NIU: eth4 CPU=42 LDG=38: interrupt received while NAPI is in progress
[502337.835440]   rx_vec=0x0400 LD_IM0[ldf_mask]=0x00
[502337.835451]   LDG_IMGMT=0x0000000000814018 [arm=0x00 timer=0x18]
[502337.835472] NIU: eth4 CPU=42 LDG=38: interrupt received while NAPI is in progress
[502337.835486]   rx_vec=0x0400 LD_IM0[ldf_mask]=0x00
[502337.835498]   LDG_IMGMT=0x0000000000814018 [arm=0x00 timer=0x18]
[502337.835519] NIU: eth4 CPU=42 LDG=38: interrupt received while NAPI is in progress
[502337.835533]   rx_vec=0x0400 LD_IM0[ldf_mask]=0x00
[502337.835544]   LDG_IMGMT=0x0000000000814018 [arm=0x00 timer=0x18]
[502338.215733] NIU: eth4 CPU=5 LDG=41: interrupt received while NAPI is in progress
[502338.215753]   rx_vec=0x2000 LD_IM0[ldf_mask]=0x00
[502338.215765]   LDG_IMGMT=0x000000000081a018 [arm=0x00 timer=0x18]
[502338.215789] NIU: eth4 CPU=5 LDG=41: interrupt received while NAPI is in progress
[502338.215803]   rx_vec=0x2000 LD_IM0[ldf_mask]=0x00
[502338.215814]   LDG_IMGMT=0x000000000081a018 [arm=0x00 timer=0x18]
[502338.215835] NIU: eth4 CPU=5 LDG=41: interrupt received while NAPI is in progress
[502338.215849]   rx_vec=0x2000 LD_IM0[ldf_mask]=0x00
[502338.215860]   LDG_IMGMT=0x000000000081a018 [arm=0x00 timer=0x18]
[502338.215881] NIU: eth4 CPU=5 LDG=41: interrupt received while NAPI is in progress
[502338.215895]   rx_vec=0x2000 LD_IM0[ldf_mask]=0x00
[502338.215906]   LDG_IMGMT=0x000000000081a018 [arm=0x00 timer=0x18]
[502385.547793] BUG: soft lockup - CPU#5 stuck for 61s! [iperf:3070]
[502385.547809] Modules linked in:
[502385.547829] TSTATE: 0000000080001602 TPC: 00000000004a8bb8 TNPC: 00000000004a8bbc Y: 00000000    Not tainted
[502385.547867] TPC: <handle_IRQ_event+0x18/0x120>
[502385.547881] g0: fffff803fb741ec0 g1: 0000000000000000 g2: 0000000000000000 g3: 0000000000010103
[502385.547898] g4: fffff803f3ad3840 g5: fffff803fed9a000 g6: fffff803f3b28000 g7: 000000000000000f
[502385.547914] o0: 0000000000000001 o1: 0000000000000001 o2: fffff803fa8909e4 o3: 0000000000000000
[502385.547931] o4: 000000000000004f o5: 00000000000000a4 sp: fffff803ff6535c1 ret_pc: 00000000007794e8
[502385.547951] RPC: <_spin_unlock+0x28/0x40>
[502385.547963] l0: 0000000000000001 l1: 0000000000000018 l2: 0000000000000018 l3: 0000000000835848
[502385.547980] l4: 0000000000007ba2 l5: 0000000000008001 l6: 0000000000924090 l7: 0000000000936000
[502385.547997] i0: 0000000000000018 i1: fffff803f5a60c00 i2: 0000000000000001 i3: 0000000000000000
[502385.548013] i4: 0000000000000000 i5: fffff803fed72000 i6: fffff803ff653681 i7: 00000000004aab74
[502385.548036] I7: <handle_fasteoi_irq+0x74/0x100>
[502385.548946] BUG: soft lockup - CPU#42 stuck for 61s! [iperf:3056]
[502385.548958] Modules linked in:
[502385.548976] TSTATE: 0000004480001606 TPC: 00000000007793f8 TNPC: 00000000007793fc Y: 00000000    Not tainted
[502385.549012] TPC: <_spin_unlock_irqrestore+0x38/0x60>
[502385.549026] g0: 0000000000001000 g1: 0000000000000000 g2: 0000000000000000 g3: 000000000abffc30
[502385.549045] g4: fffff803f3a40000 g5: fffff803feec2000 g6: fffff803f3a0c000 g7: 000000000000000c
[502385.549062] o0: 00000000000001a8 o1: 0000000038ac8a43 o2: 000000008716e61f o3: 00000000c6db4f40
[502385.549080] o4: 000000000098f658 o5: 000000004cd739c3 sp: fffff803ff52b421 ret_pc: 00000000005d7630
[502385.549105] RPC: <mix_pool_bytes_extract+0x170/0x180>
[502385.549119] l0: 000000000000006a l1: 000000000000007f l2: 0000000095961289 l3: 0000000000000019
[502385.549135] l4: 0000000000000033 l5: 000000000000004c l6: 0000000000000067 l7: 0000000000000001
[502385.549152] i0: 00000000008b7d98 i1: 0000000000000000 i2: fffff803ff52bdb0 i3: 0000000000000000
[502385.549168] i4: 00000000007923b8 i5: 0000000000000020 i6: fffff803ff52b4e1 i7: 00000000005d87d8
[502385.549188] I7: <add_timer_randomness+0xb8/0x200>


David Miller wrote:
> From: "Hong H. Pham" <hong.pham@windriver.com>
> Date: Tue, 19 May 2009 17:52:15 -0400
> 
>> Unfortunately I don't have a PCIe NIU card to test in an x86 box.
>> If the hang does not happen on x86 (which is my suspicion), that
>> would rule out a problem with the NIU chip.  That would mean there's
>> some interaction between the NIU and sun4v hypervisor that's causing
>> the spurious interrupts.
> 
> I am still leaning towards the NIU chip, or our programming of
> it, as causing this behavior.
> 
> Although it's possible that the interrupt logic inside of
> Niagara-T2, or how it's hooked up to the internal NIU ASIC
> inside of the CPU, might be to blame I don't consider it likely
> given the basic gist of the behavior you see.
> 
> To quote section 17.3.2 of the UltraSPARC-T2 manual:
> 
> 	An interrupt will only be issued if the timer is zero,
> 	the arm bit is set, and one of more LD's in the LDG, have
> 	their flags set and not masked.
> 
> which confirms our understanding of how this should work.
> 
> Can you test something Hong?  Simply trigger the hung case
> and when it happens read the LDG registers to see if the ARM
> bit is set, and what the LDG mask bits say.
> 
> There might be a bug somewhere that causes us to call
> niu_ldg_rearm() improperly.  In particular I'm looking
> at that test done in niu_interrupt():
> 
> 	if (likely(v0 & ~((u64)1 << LDN_MIF)))
> 		niu_schedule_napi(np, lp, v0, v1, v2);
> 	else
> 		niu_ldg_rearm(np, lp, 1);
> 
> If we call niu_ldg_rearm() on an LDG being serviced by NAPI
> before that poll sequence calls napi_complete() we could
> definitely see this weird behavior.  And whatever causes
> that would be the bug to fix.
> 
> Thanks!
> 
>  

[-- Attachment #2: niu-instrument-ldg-interrupt.patch --]
[-- Type: text/plain, Size: 2857 bytes --]

---
 drivers/net/niu.c |   61 ++++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 files changed, 60 insertions(+), 1 deletions(-)

diff --git a/drivers/net/niu.c b/drivers/net/niu.c
index 2b17453..a40653e 100644
--- a/drivers/net/niu.c
+++ b/drivers/net/niu.c
@@ -4210,26 +4210,85 @@ static void __niu_fastpath_interrupt(struct niu *np, int ldg, u64 v0)
 			continue;
 
 		nw64(LD_IM0(ldn), LD_IM0_MASK);
 		if (tx_vec & (1 << rp->tx_channel))
 			niu_txchan_intr(np, rp, ldn);
 	}
 }
 
+// HHP
+static void niu_dump_ldg_irq(struct niu *np, int ldg, u64 v0)
+{
+	static DEFINE_PER_CPU(unsigned long, spurious_count) = { 4 };
+
+	struct niu_parent *parent = np->parent;
+	u64 ld_im0_reg, ldg_imgmt_reg;
+	u32 rx_vec, tx_vec;
+	int ldn, i;
+
+	if (!__get_cpu_var(spurious_count))
+		return;
+
+	__get_cpu_var(spurious_count)--;
+	printk(KERN_DEBUG "NIU: %s CPU=%i LDG=%i: interrupt received while NAPI is in progress\n",
+	       np->dev->name, smp_processor_id(), ldg);
+
+	tx_vec = (v0 >> 32);
+	rx_vec = (v0 & 0xffffffff);
+
+	for (i = 0; i < np->num_rx_rings; i++) {
+		struct rx_ring_info *rp = &np->rx_rings[i];
+
+		ldn = LDN_RXDMA(rp->rx_channel);
+		if (parent->ldg_map[ldn] != ldg)
+			continue;
+
+		ld_im0_reg    = LD_IM0(ldn);
+		ldg_imgmt_reg = LDG_IMGMT(ldn);
+		printk(KERN_DEBUG "  rx_vec=0x%04x LD_IM0[ldf_mask]=0x%02lx\n",
+		       rx_vec,
+		       (unsigned long)(ld_im0_reg & LD_IM0_MASK)),
+		printk(KERN_DEBUG "  LDG_IMGMT=0x%016lx [arm=0x%02lx timer=0x%02lx]\n",
+		       (unsigned long)ldg_imgmt_reg,
+		       (unsigned long)((ldg_imgmt_reg & LDG_IMGMT_ARM) >> 31),
+		       (unsigned long)(ldg_imgmt_reg & LDG_IMGMT_TIMER));
+	}
+
+	/* Spurious TX interrupts should not happen */
+	for (i = 0; i < np->num_tx_rings; i++) {
+		struct tx_ring_info *rp = &np->tx_rings[i];
+		ldn = LDN_TXDMA(rp->tx_channel);
+
+		if (parent->ldg_map[ldn] != ldg)
+			continue;
+
+		ld_im0_reg    = LD_IM0(ldn);
+		ldg_imgmt_reg = LDG_IMGMT(ldn);
+		printk(KERN_DEBUG "  tx_vec=0x%04x LD_IM0[ldf_mask]=0x%02lx\n",
+		       tx_vec,
+		       (unsigned long)(ld_im0_reg & LD_IM0_MASK)),
+		printk(KERN_DEBUG "  LDG_IMGMT=0x%016lx [arm=0x%02lx timer=0x%02lx]\n",
+		       (unsigned long)ldg_imgmt_reg,
+		       (unsigned long)((ldg_imgmt_reg & LDG_IMGMT_ARM) >> 31),
+		       (unsigned long)(ldg_imgmt_reg & LDG_IMGMT_TIMER));
+	}
+}
+
 static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 			      u64 v0, u64 v1, u64 v2)
 {
 	if (likely(napi_schedule_prep(&lp->napi))) {
 		lp->v0 = v0;
 		lp->v1 = v1;
 		lp->v2 = v2;
 		__niu_fastpath_interrupt(np, lp->ldg_num, v0);
 		__napi_schedule(&lp->napi);
-	}
+	} else
+		niu_dump_ldg_irq(np, lp->ldg_num, v0);
 }
 
 static irqreturn_t niu_interrupt(int irq, void *dev_id)
 {
 	struct niu_ldg *lp = dev_id;
 	struct niu *np = lp->np;
 	int ldg = lp->ldg_num;
 	unsigned long flags;

Re: [PATCH 0/1] NIU: fix spurious interrupts

[David Miller]

From: "Hong H. Pham" <hong.pham@windriver.com>
Date: Wed, 20 May 2009 11:57:16 -0400

> I've added the suggested instrumentations to dump out the LD interrupt
> registers
> when spurious interrupts occur.  Attached below is a kernel log.
> 
> In all cases, interrupts are being generated even though the LDG has
> been disarmed!

Thanks for doing this testing, I'll think about how to
attack this bug.

Re: [PATCH 0/1] NIU: fix spurious interrupts

[David Miller]

From: "Hong H. Pham" <hong.pham@windriver.com>
Date: Wed, 20 May 2009 11:57:16 -0400

> I've added the suggested instrumentations to dump out the LD interrupt
> registers
> when spurious interrupts occur.  Attached below is a kernel log.
> 
> In all cases, interrupts are being generated even though the LDG has
> been disarmed!

There's a bug in your debugging patch:

+		ld_im0_reg    = LD_IM0(ldn);
+		ldg_imgmt_reg = LDG_IMGMT(ldn);

You're reading the register "address", not the register's "value".
So all of the debugging output is bogus.

You need to do nr64(ld_im0_reg) and use that as the value, for
example.

Can you rerun the test with this fixed?  Thanks!

Re: [PATCH 0/1] NIU: fix spurious interrupts

[Hong H. Pham]

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

David Miller wrote:
> There's a bug in your debugging patch:
> 
> +		ld_im0_reg    = LD_IM0(ldn);
> +		ldg_imgmt_reg = LDG_IMGMT(ldn);
> 
> You're reading the register "address", not the register's "value".
> So all of the debugging output is bogus.
> 
> You need to do nr64(ld_im0_reg) and use that as the value, for
> example.
> 
> Can you rerun the test with this fixed?  Thanks!

I don't know how I missed that.. thanks for pointing it out.  Posted
below is a log with the fix.

What's interesting (baffling?) is that interrupts are being received
with the LD interrupt mask set or cleared.  The mask also changes
in between interrupts.  The mask always changes from 3 to 0, and never
from 0 to 3.

Please let me know if there are other tests you would like me to run
to help track this down.
Regards,
Hong

[113570.320487] niu: eth4: Link is up at 10Gb/sec, full duplex
[113576.834042] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834066]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113576.834080]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834107] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834124]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113576.834137]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834164] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834181]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113576.834195]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834222] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834239]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113576.834252]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834276] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834291]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113576.834303]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834326] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834341]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113576.834353]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834374] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834389]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113576.834401]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113576.834423] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: interrupt received while NAPI is in progress
[113576.834438]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113576.834450]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.311747] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.311770]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113578.311782]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.311805] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.311821]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.311833]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.311855] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.311870]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.311882]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.311904] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.311919]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.311931]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.311952] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.311968]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.311980]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.312001] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.312016]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.312028]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.312050] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.312065]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.312077]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113578.312098] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: interrupt received while NAPI is in progress
[113578.312114]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113578.312126]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932434] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932458]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113582.932471]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932499] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932516]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932529]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932556] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932571]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932583]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932605] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932621]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932633]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932655] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932670]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932682]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932704] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932719]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932731]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932752] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932768]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932779]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113582.932801] NIU: eth4 CPU=13 LDG=42 rx_vec=0x4000: interrupt received while NAPI is in progress
[113582.932816]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113582.932828]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656434] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656459]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113584.656471]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656525] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656542]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656555]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656581] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656598]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656612]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656637] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656653]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656666]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656689] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656705]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656718]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656740] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656756]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656768]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656790] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656806]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656818]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113584.656840] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: interrupt received while NAPI is in progress
[113584.656856]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113584.656869]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659480] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659502]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113591.659514]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659537] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659553]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113591.659565]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659587] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659602]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113591.659614]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659636] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659651]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.659663]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659685] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659700]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.659712]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659734] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659749]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.659761]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659783] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659798]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.659810]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.659832] NIU: eth4 CPU=50 LDG=39 rx_vec=0x0800: interrupt received while NAPI is in progress
[113591.659847]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.659859]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846419] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846444]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846459]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846489] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846508]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846523]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846551] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846567]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846579]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846602] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846617]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846629]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846651] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846666]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846679]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846700] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846716]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846727]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846750] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846765]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846777]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113591.846798] NIU: eth4 CPU=34 LDG=37 rx_vec=0x0200: interrupt received while NAPI is in progress
[113591.846814]   LD_IM0   =0x0000000000000000 [ldf_mask=0x00]
[113591.846826]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471277] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471302]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471316]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471346] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471365]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471379]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471408] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471426]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471440]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471468] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471484]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471496]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471518] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471533]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471545]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471567] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471582]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471594]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471616] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471631]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471643]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113597.471665] NIU: eth4 CPU=42 LDG=38 rx_vec=0x0400: interrupt received while NAPI is in progress
[113597.471680]   LD_IM0   =0x0000000000000003 [ldf_mask=0x03]
[113597.471692]   LDG_IMGMT=0x0000000000000000 [arm=0x00 timer=0x00]
[113627.656758] BUG: soft lockup - CPU#5 stuck for 61s! [iperf:3055]


[-- Attachment #2: niu-instrument-ldg-interrupt.patch --]
[-- Type: text/x-patch, Size: 2805 bytes --]

---
 drivers/net/niu.c |   62 ++++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 files changed, 61 insertions(+), 1 deletions(-)

diff --git a/drivers/net/niu.c b/drivers/net/niu.c
index 2b17453..433fced 100644
--- a/drivers/net/niu.c
+++ b/drivers/net/niu.c
@@ -4214,8 +4214,67 @@ static void __niu_fastpath_interrupt(struct niu *np, int ldg, u64 v0)
 			niu_txchan_intr(np, rp, ldn);
 	}
 }
 
+// HHP
+static void niu_dump_ldg_irq(struct niu *np, int ldg, u64 v0)
+{
+	static DEFINE_PER_CPU(unsigned long, spurious_count) = { 8 };
+
+	struct niu_parent *parent = np->parent;
+	u64 ld_im0_val, ldg_imgmt_val;
+	u32 rx_vec, tx_vec;
+	int ldn, i;
+
+	if (!__get_cpu_var(spurious_count))
+		return;
+
+	__get_cpu_var(spurious_count)--;
+
+	tx_vec = (v0 >> 32);
+	rx_vec = (v0 & 0xffffffff);
+	printk(KERN_DEBUG "NIU: %s CPU=%i LDG=%i rx_vec=0x%04x: interrupt received while NAPI is in progress\n",
+	       np->dev->name, smp_processor_id(), ldg, rx_vec);
+
+
+	for (i = 0; i < np->num_rx_rings; i++) {
+		struct rx_ring_info *rp = &np->rx_rings[i];
+
+		ldn = LDN_RXDMA(rp->rx_channel);
+		if (parent->ldg_map[ldn] != ldg)
+			continue;
+
+		ld_im0_val    = nr64(LD_IM0(ldn));
+		ldg_imgmt_val = nr64(LDG_IMGMT(ldn));
+		printk(KERN_DEBUG "  LD_IM0   =0x%016lx [ldf_mask=0x%02lx]\n",
+		       (unsigned long)ld_im0_val,
+		       (unsigned long)(ld_im0_val & LD_IM0_MASK)),
+		printk(KERN_DEBUG "  LDG_IMGMT=0x%016lx [arm=0x%02lx timer=0x%02lx]\n",
+		       (unsigned long)ldg_imgmt_val,
+		       (unsigned long)((ldg_imgmt_val & LDG_IMGMT_ARM) >> 31),
+		       (unsigned long)(ldg_imgmt_val & LDG_IMGMT_TIMER));
+	}
+
+	/* Spurious TX interrupts should not happen */
+	for (i = 0; i < np->num_tx_rings; i++) {
+		struct tx_ring_info *rp = &np->tx_rings[i];
+		ldn = LDN_TXDMA(rp->tx_channel);
+
+		if (parent->ldg_map[ldn] != ldg)
+			continue;
+
+		ld_im0_val    = LD_IM0(ldn);
+		ldg_imgmt_val = LDG_IMGMT(ldn);
+		printk(KERN_DEBUG "  LD_IM0   =0x%016lx [ldf_mask=0x%02lx]\n",
+		       (unsigned long)ld_im0_val,
+		       (unsigned long)(ld_im0_val & LD_IM0_MASK)),
+		printk(KERN_DEBUG "  LDG_IMGMT=0x%016lx [arm=0x%02lx timer=0x%02lx]\n",
+		       (unsigned long)ldg_imgmt_val,
+		       (unsigned long)((ldg_imgmt_val & LDG_IMGMT_ARM) >> 31),
+		       (unsigned long)(ldg_imgmt_val & LDG_IMGMT_TIMER));
+	}
+}
+
 static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 			      u64 v0, u64 v1, u64 v2)
 {
 	if (likely(napi_schedule_prep(&lp->napi))) {
@@ -4223,9 +4282,10 @@ static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 		lp->v1 = v1;
 		lp->v2 = v2;
 		__niu_fastpath_interrupt(np, lp->ldg_num, v0);
 		__napi_schedule(&lp->napi);
-	}
+	} else
+		niu_dump_ldg_irq(np, lp->ldg_num, v0);
 }
 
 static irqreturn_t niu_interrupt(int irq, void *dev_id)
 {

Re: [PATCH 0/1] NIU: fix spurious interrupts

[David Miller]

From: "Hong H. Pham" <hong.pham@windriver.com>
Date: Thu, 21 May 2009 20:40:06 -0400

> Posted below is a log with the fix.

Thank you.

> What's interesting (baffling?) is that interrupts are being received
> with the LD interrupt mask set or cleared.  The mask also changes
> in between interrupts.  The mask always changes from 3 to 0, and never
> from 0 to 3.

The "3 --> 0" transition is made by niu_poll_core() as we are
about to napi_complete() and rearm the LDG.

But yes this log doesn't make any sense.  Neither the masks
nor the ARM bit appear to be working.

I wonder if the spurious interrupts trigger exactly at the

		nw64(LD_IM0(LDN_RXDMA(rp->rx_channel)), 0);

in niu_poll_core().

Can you run one more test?  Supplement the debugging output
with:

	"%pS", get_irq_regs()->tpc

so we can see where the program counter is at the time of
the spurious interrupt?

Meanwhile, even if we go with your patch to fix this, we can't
use it as-is.  Let me explain.

Suppose that we get this spurious interrupt right after we unmask the
interrupt and right before napi_complete().  Your change will make us
re-mask the interrupts, but without scheduling NAPI.

So once the napi_complete() happens, if no further interrupts trigger
in that LDG, we'll never process those interrupt events cleared by
your new code.  See what I mean?

I don't know how to fix this, it's full of races.  I suppose we could
recheck if events are pending in the LDG after we do the
napi_complete() and reschedule NAPI again if so.  But that might be
expensive (several register reads, just to check something that's not
going to happen most of the time).

I'm also wondering why we see this on Niagara-2 and not on PCI-E
cards.  If the interrupts that go into the NCU unit of Niagara-2 are
levelled interrupts, and somehow the ARM bit is not implemented
correctly in the NIU logic when hooked up to NCU instead of PCI-E
logic, that could explain things.

I bet that our Linux driver is the only one that bangs on the LDG
mask registers like this.

Re: [PATCH 0/1] NIU: fix spurious interrupts

[Hong H. Pham]

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

David Miller wrote:
> I wonder if the spurious interrupts trigger exactly at the
> 
> 		nw64(LD_IM0(LDN_RXDMA(rp->rx_channel)), 0);
> 
> in niu_poll_core().
> 
> Can you run one more test?  Supplement the debugging output
> with:
> 
> 	"%pS", get_irq_regs()->tpc
> 
> so we can see where the program counter is at the time of
> the spurious interrupt?

The tpc at the time of the spurious interrupt is niu_poll+0x99c.
Looking this address up, it's at this line in niu_ldg_rearm():

   nw64(LDG_IMGMT(lp->ldg_num), val);

Since the timer is also reprogrammed when the LDG is rearmed,
interrupts should not have been generated immediately after
writing to LDG_IMGMT.

The tpc also showed interrupts happening in net_rx_action.  In
this case the LDG has been rearmed, but the timer prevented
interrupt delivery until after niu_poll is done.

> Meanwhile, even if we go with your patch to fix this, we can't
> use it as-is.  Let me explain.
> 
> Suppose that we get this spurious interrupt right after we unmask the
> interrupt and right before napi_complete().  Your change will make us
> re-mask the interrupts, but without scheduling NAPI.
> 
> So once the napi_complete() happens, if no further interrupts trigger
> in that LDG, we'll never process those interrupt events cleared by
> your new code.  See what I mean?

Understood.

> I don't know how to fix this, it's full of races.  I suppose we could
> recheck if events are pending in the LDG after we do the
> napi_complete() and reschedule NAPI again if so.  But that might be
> expensive (several register reads, just to check something that's not
> going to happen most of the time).

> I'm also wondering why we see this on Niagara-2 and not on PCI-E
> cards.  If the interrupts that go into the NCU unit of Niagara-2 are
> levelled interrupts, and somehow the ARM bit is not implemented
> correctly in the NIU logic when hooked up to NCU instead of PCI-E
> logic, that could explain things.
> 
> I bet that our Linux driver is the only one that bangs on the LDG
> mask registers like this.

I tried the test on a T5440, which has a PCI-E NIU (4 x 1GB) card.
I could not reproduce the spurious interrupts.  So this bug seems
to be limited to XAUI NIU cards.  Which also makes it a Niagara-2
specific problem.

Regards,
Hong

[ 2226.589782] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: spurious interrupt
[ 2226.589800]   tpc      = <niu_poll+0x99c/0xc20>
[ 2226.589814]   LD_IM0   = 0x0000000000000003 [ldf_mask=0x03]
[ 2226.589826]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2226.589855] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: spurious interrupt
[ 2226.589867]   tpc      = <niu_poll+0x99c/0xc20>
[ 2226.589878]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2226.589890]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2226.589915] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: spurious interrupt
[ 2226.589927]   tpc      = <niu_poll+0x99c/0xc20>
[ 2226.589938]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2226.589950]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2226.589974] NIU: eth4 CPU=5 LDG=41 rx_vec=0x2000: spurious interrupt
[ 2226.589986]   tpc      = <niu_poll+0x99c/0xc20>
[ 2226.589996]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2226.590008]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2229.380931] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: spurious interrupt
[ 2229.380949]   tpc      = <niu_poll+0x99c/0xc20>
[ 2229.380962]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2229.380974]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2229.381003] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: spurious interrupt
[ 2229.381015]   tpc      = <niu_poll+0x99c/0xc20>
[ 2229.381026]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2229.381038]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2229.381063] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: spurious interrupt
[ 2229.381075]   tpc      = <niu_poll+0x99c/0xc20>
[ 2229.381086]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2229.381097]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2229.381122] NIU: eth4 CPU=58 LDG=40 rx_vec=0x1000: spurious interrupt
[ 2229.381134]   tpc      = <niu_poll+0x99c/0xc20>
[ 2229.381145]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2229.381156]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2236.743967] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: spurious interrupt
[ 2236.743983]   tpc      = <net_rx_action+0x138/0x260>
[ 2236.743996]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2236.744008]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2236.744034] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: spurious interrupt
[ 2236.744046]   tpc      = <net_rx_action+0x138/0x260>
[ 2236.744058]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2236.744070]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2236.744095] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: spurious interrupt
[ 2236.744107]   tpc      = <net_rx_action+0x138/0x260>
[ 2236.744118]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2236.744130]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]
[ 2236.744155] NIU: eth4 CPU=21 LDG=43 rx_vec=0x8000: spurious interrupt
[ 2236.744167]   tpc      = <net_rx_action+0x138/0x260>
[ 2236.744178]   LD_IM0   = 0x0000000000000000 [ldf_mask=0x00]
[ 2236.744190]   LDG_IMGMT= 0x0000000000000000 [arm=0x00 timer=0x00]


[-- Attachment #2: niu-instrument-ldg-interrupt.patch --]
[-- Type: text/plain, Size: 2469 bytes --]

---
 drivers/net/niu.c |   52 +++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 files changed, 51 insertions(+), 1 deletions(-)

diff --git a/drivers/net/niu.c b/drivers/net/niu.c
index 2b17453..cd47fad 100644
--- a/drivers/net/niu.c
+++ b/drivers/net/niu.c
@@ -24,8 +24,11 @@
 #include <linux/crc32.h>
 
 #include <linux/io.h>
 
+#include <linux/kallsyms.h>
+#include <asm/irq_regs.h>
+
 #ifdef CONFIG_SPARC64
 #include <linux/of_device.h>
 #endif
 
@@ -4214,8 +4217,54 @@ static void __niu_fastpath_interrupt(struct niu *np, int ldg, u64 v0)
 			niu_txchan_intr(np, rp, ldn);
 	}
 }
 
+// HHP
+static void niu_dump_ldg_irq(struct niu *np, int ldg, u64 v0)
+{
+	static DEFINE_PER_CPU(unsigned long, spurious_count) = { 4 };
+
+	struct niu_parent *parent = np->parent;
+	char buf[KSYM_SYMBOL_LEN];
+	u64 ld_im0_val, ldg_imgmt_val;
+	u32 rx_vec, tx_vec;
+	int ldn, i;
+
+	if (!__get_cpu_var(spurious_count))
+		return;
+
+	__get_cpu_var(spurious_count)--;
+
+	tx_vec = (v0 >> 32);
+	rx_vec = (v0 & 0xffffffff);
+	sprint_symbol(buf, get_irq_regs()->tpc);
+
+	printk(KERN_DEBUG "NIU: %s CPU=%i LDG=%i rx_vec=0x%04x: spurious interrupt\n",
+	       np->dev->name, smp_processor_id(), ldg, rx_vec);
+	printk(KERN_DEBUG "  tpc      = <%s>\n", buf);
+
+	for (i = 0; i < np->num_rx_rings; i++) {
+		struct rx_ring_info *rp = &np->rx_rings[i];
+
+		ldn = LDN_RXDMA(rp->rx_channel);
+		if (parent->ldg_map[ldn] != ldg)
+			continue;
+
+		ld_im0_val    = nr64(LD_IM0(ldn));
+		ldg_imgmt_val = nr64(LDG_IMGMT(ldn));
+		printk(KERN_DEBUG "  LD_IM0   = 0x%016lx [ldf_mask=0x%02lx]\n",
+		       (unsigned long)ld_im0_val,
+		       (unsigned long)(ld_im0_val & LD_IM0_MASK)),
+		printk(KERN_DEBUG "  LDG_IMGMT= 0x%016lx [arm=0x%02lx timer=0x%02lx]\n",
+		       (unsigned long)ldg_imgmt_val,
+		       (unsigned long)((ldg_imgmt_val & LDG_IMGMT_ARM) >> 31),
+		       (unsigned long)(ldg_imgmt_val & LDG_IMGMT_TIMER));
+	}
+
+	if (tx_vec)
+		printk(KERN_DEBUG "NIU: spurious TX interrupt. WTF?\n");
+}
+
 static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 			      u64 v0, u64 v1, u64 v2)
 {
 	if (likely(napi_schedule_prep(&lp->napi))) {
@@ -4223,9 +4272,10 @@ static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 		lp->v1 = v1;
 		lp->v2 = v2;
 		__niu_fastpath_interrupt(np, lp->ldg_num, v0);
 		__napi_schedule(&lp->napi);
-	}
+	} else
+		niu_dump_ldg_irq(np, lp->ldg_num, v0);
 }
 
 static irqreturn_t niu_interrupt(int irq, void *dev_id)
 {

Re: [PATCH 0/1] NIU: fix spurious interrupts

[David Miller]

From: "Hong H. Pham" <hong.pham@windriver.com>
Date: Fri, 22 May 2009 12:42:30 -0400

> The tpc at the time of the spurious interrupt is niu_poll+0x99c.
> Looking this address up, it's at this line in niu_ldg_rearm():
> 
>   nw64(LDG_IMGMT(lp->ldg_num), val);
> 
> Since the timer is also reprogrammed when the LDG is rearmed,
> interrupts should not have been generated immediately after
> writing to LDG_IMGMT.
> 
> The tpc also showed interrupts happening in net_rx_action.  In
> this case the LDG has been rearmed, but the timer prevented
> interrupt delivery until after niu_poll is done.

The mystery is even deeper now!

First of all, we've been tricking ourselves.  OF COURSE we will see
the ARM bit cleared in these logs.  Any time the interrupt is sent,
the chip will clear the ARM bit.  So let's stop considering that as
unexpected :-)

If we are at the LDG rarm, we should have called napi_complete()
first.  Which happens in niu_poll().  napi_complete() therefore
always runs first, and therefore via this code path the LDG
rearm triggered interrupt should not see the NAPI scheduled.

There are only two other (both unlikely) paths that calls this,
niu_enable_interrupts() and the niu_interrupt() path that handles MIF,
RX error, and TX error interrupts.

I wonder if it's the niu_interrupt path, and all the v0 bits are
clear.  Yeah, I bet that's it.  We're taking some slowpath interrupt
for RX or TX counter overflows or errors, and then we try to rearm the
LDG even though we're already handling normal RX/TX via NAPI.

But that shouldn't happen, the thing that went into RX/TX NAPI work
should have turned those interrupt off.  We handle RX normal work and
error interrupts in the same LDG, and similar for TX, and thus using
the same interrupt.

Can you check to see who calls niu_ldg_rearm() when we see it trigger
the interrupt with NAPI already scheduled?  That will help narrow this
down even further.  Probably the best thing to do is to get a full
stack trace using show_stack() or dump_stack().

This is looking more and more like a driver bug at this point.

Re: [PATCH 0/1] NIU: fix spurious interrupts

[Hong H. Pham]

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

David Miller wrote:
> I wonder if it's the niu_interrupt path, and all the v0 bits are
> clear.  Yeah, I bet that's it.  We're taking some slowpath interrupt
> for RX or TX counter overflows or errors, and then we try to rearm the
> LDG even though we're already handling normal RX/TX via NAPI.
> 
> But that shouldn't happen, the thing that went into RX/TX NAPI work
> should have turned those interrupt off.  We handle RX normal work and
> error interrupts in the same LDG, and similar for TX, and thus using
> the same interrupt.
> 
> Can you check to see who calls niu_ldg_rearm() when we see it trigger
> the interrupt with NAPI already scheduled?  That will help narrow this
> down even further.  Probably the best thing to do is to get a full
> stack trace using show_stack() or dump_stack().
> 
> This is looking more and more like a driver bug at this point.

I've added a check for v0 being zero in niu_interrupt().  I have not seen
this check succeed, so niu_ldg_rearm() is never invoked prior to or
during a spurious interrupt in niu_interrupt().  So it seems the only
other place where the LDG is rearmed during network activity is in
niu_poll(), which is expected.

Here's something else that doesn't make sense.  I've added a check
in __niu_fastpath_interrupt() and niu_rx_work() to see if the RCR qlen
is zero, i.e. we're scheduling NAPI with no work.  This could happen if
there's a spurious interrupt, but the interrupt is not a run away that
would hang the CPU.  This check happens quite frequently, much more than
the spurious interrupt check.  Also, it happens with both the PCI-E and
XAUI cards (I could not reproduce run away spurious interrupts with a
PCI-E card).

This is a log from a test with 1 TCP stream.  If there's no work to do,
one would expect to see for each __niu_fastpath_interrupt(), there is only
one corresponding niu_rx_work().  i.e. work_done in niu_poll is 0, so NAPI
is done and should not have been rescheduled.  The check for spurious
interrupts in niu_schedule_napi() is not reached.

[  474.387984] niu: __niu_fastpath_interrupt() CPU=58 rx_channel=12 qlen is 0!
[  474.388009] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  474.663008] niu: __niu_fastpath_interrupt() CPU=58 rx_channel=12 qlen is 0!
[  474.663034] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  474.805663] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  475.657501] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  476.139072] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  476.264352] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  476.474596] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!
[  476.698176] niu: __niu_fastpath_interrupt() CPU=58 rx_channel=12 qlen is 0!
[  476.698201] niu: niu_rx_work() CPU=58 rx_channel=12 qlen is zero!

Here's another log excerpt with 1 TCP stream.  In this case NAPI is being
rescheduled multiple times with no work to do.  Again, run away spurious
interrupts did not happen.

[ 1098.870170] niu: niu_rx_work() CPU=50 rx_channel=11 qlen is zero!
[ 1098.879759] niu: __niu_fastpath_interrupt() CPU=50 rx_channel=11 qlen is 0!
[ 1098.904478] niu: __niu_fastpath_interrupt() CPU=50 rx_channel=11 qlen is 0!
[ 1098.908674] niu: __niu_fastpath_interrupt() CPU=50 rx_channel=11 qlen is 0!
[ 1098.908703] niu: niu_rx_work() CPU=50 rx_channel=11 qlen is zero!

In any case, interrupts with qlen being 0 always happen before we see the
run away spurious interrupts (but that could be due to the latter happening
a lot less frequently).

Regards,
Hong





[-- Attachment #2: niu-debug-spurious-interrupts.patch --]
[-- Type: text/plain, Size: 2869 bytes --]

diff --git a/drivers/net/niu.c b/drivers/net/niu.c
index 2b17453..125450a 100644
--- a/drivers/net/niu.c
+++ b/drivers/net/niu.c
@@ -3724,6 +3724,10 @@ static int niu_rx_work(struct napi_struct *napi, struct niu *np,
 	mbox->rx_dma_ctl_stat = 0;
 	mbox->rcrstat_a = 0;
 
+	if (!qlen)
+		printk(KERN_DEBUG PFX "%s() CPU=%i rx_channel=%i qlen is zero!\n",
+		       __FUNCTION__, raw_smp_processor_id(), rp->rx_channel);
+
 	niudbg(RX_STATUS, "%s: niu_rx_work(chan[%d]), stat[%llx] qlen=%d\n",
 	       np->dev->name, rp->rx_channel, (unsigned long long) stat, qlen);
 
@@ -4193,10 +4197,17 @@ static void __niu_fastpath_interrupt(struct niu *np, int ldg, u64 v0)
 	for (i = 0; i < np->num_rx_rings; i++) {
 		struct rx_ring_info *rp = &np->rx_rings[i];
 		int ldn = LDN_RXDMA(rp->rx_channel);
+		u64 qlen;
 
 		if (parent->ldg_map[ldn] != ldg)
 			continue;
 
+		qlen = nr64(RCRSTAT_A(rp->rx_channel)) & RCRSTAT_A_QLEN;
+		if (!qlen) {
+			printk(KERN_DEBUG PFX "%s() CPU=%i rx_channel=%i qlen is 0!\n",
+			       __FUNCTION__, smp_processor_id(), rp->rx_channel);
+		}
+
 		nw64(LD_IM0(ldn), LD_IM0_MASK);
 		if (rx_vec & (1 << rp->rx_channel))
 			niu_rxchan_intr(np, rp, ldn);
@@ -4215,6 +4226,22 @@ static void __niu_fastpath_interrupt(struct niu *np, int ldg, u64 v0)
 	}
 }
 
+static void niu_dump_ldg_irq(struct niu *np, int ldg, u64 v0)
+{
+	static DEFINE_PER_CPU(unsigned long, spurious_count) = { 4 };
+
+	struct niu_parent *parent = np->parent;
+	int qlen, ldn, i;
+
+	if (!__get_cpu_var(spurious_count))
+		return;
+
+	__get_cpu_var(spurious_count)--;
+
+	printk(KERN_DEBUG PFX "%s CPU=%i LDG=%i v0=%p: spurious interrupt\n",
+	       np->dev->name, smp_processor_id(), ldg, (void *)v0);
+}
+
 static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 			      u64 v0, u64 v1, u64 v2)
 {
@@ -4224,7 +4251,8 @@ static void niu_schedule_napi(struct niu *np, struct niu_ldg *lp,
 		lp->v2 = v2;
 		__niu_fastpath_interrupt(np, lp->ldg_num, v0);
 		__napi_schedule(&lp->napi);
-	}
+	} else
+		niu_dump_ldg_irq(np, lp->ldg_num, v0);
 }
 
 static irqreturn_t niu_interrupt(int irq, void *dev_id)
@@ -4251,6 +4279,10 @@ static irqreturn_t niu_interrupt(int irq, void *dev_id)
 		       (unsigned long long) v1,
 		       (unsigned long long) v2);
 
+	if (!v0)
+		printk(KERN_DEBUG PFX "%s() CPU=%i LDG=%i v0 is zero!\n",
+		       __FUNCTION__, smp_processor_id(), ldg);
+
 	if (unlikely(!v0 && !v1 && !v2)) {
 		spin_unlock_irqrestore(&np->lock, flags);
 		return IRQ_NONE;
@@ -4263,8 +4295,11 @@ static irqreturn_t niu_interrupt(int irq, void *dev_id)
 	}
 	if (likely(v0 & ~((u64)1 << LDN_MIF)))
 		niu_schedule_napi(np, lp, v0, v1, v2);
-	else
+	else {
+		printk(KERN_DEBUG PFX "%s() CPU=%i no DMA work, rearming LDG\n",
+		       __FUNCTION__, smp_processor_id());
 		niu_ldg_rearm(np, lp, 1);
+	}
 out:
 	spin_unlock_irqrestore(&np->lock, flags);