diff mbox

NIU driver: Sun x8 Express Quad Gigabit Ethernet Adapter

Message ID 20081111.161849.251632080.davem@davemloft.net
State RFC, archived
Delegated to: David Miller
Headers show

Commit Message

David Miller Nov. 12, 2008, 12:18 a.m. UTC 
From: David Miller <davem@davemloft.net>
Date: Tue, 11 Nov 2008 15:50:41 -0800 (PST)

> If you could run those test patches when I post them and give
> the log messages they produce, I'd appreciate it.

Ok, let's start with this debugging patch below.

When the chip gets a TX timeout it's going to dump a lot of
state.  First it will dump the state of the logic device group
interrupt vectors (both hardware and software copies).

Then, for each TX ring, it will dump the TX_CS register (both
software and hardware copies), the mapping from that TX ring
to logical-device number and logical device group.  It will
also print out how many packets are in the ring but not freed
up yet.

Please post the dump that results when the condition triggers.
Just provide the first dump the kernel spits out.

Thanks.

--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Comments

Jesper Dangaard Brouer Nov. 12, 2008, 9:36 a.m. UTC | #1 
Hi DaveM

Before trying out the patch, I'll give you a small status on my
progress.

When using Sun's "nxge" driver everything works.  Although this driver
is quite slow because it does not use the new TX qdisc scheme.  I hacked
net/core/dev.c to avoid the qdisc TX code-path, and got an amazing
speedup, as I now can route 930 kpps (packets per sec).

I played a bit with the msglvl (debug log level) via:
  ethtool -s eth2 msglvl 0x587

Enabling:
 NETIF_MSG_TX_ERR
 NETIF_MSG_TX_QUEUED
 NETIF_MSG_TX_DONE

The thing I noticed is that it looks like the function niu_tx_work() is
never called... (it contains a niudbg(TX_DONE, ...))
David Miller Nov. 12, 2008, 9:49 a.m. UTC | #2 
From: Jesper Dangaard Brouer <jdb@comx.dk>
Date: Wed, 12 Nov 2008 10:36:33 +0100

> The thing I noticed is that it looks like the function niu_tx_work() is
> never called... (it contains a niudbg(TX_DONE, ...))

That means no interrupts are arriving at all for TX.

Oddly, you tried without MSI enabled (do I remember right ?) and that
still failed, so it doesn't seem like it could be a MSI specific
problem.

Get the dump from the patch I sent and I should be able to have some
idea why this problem might be happening.

Thanks.
--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Jesper Dangaard Brouer Nov. 12, 2008, 10:04 a.m. UTC | #3 
On Wed, 2008-11-12 at 01:49 -0800, David Miller wrote:
> From: Jesper Dangaard Brouer <jdb@comx.dk>
> Date: Wed, 12 Nov 2008 10:36:33 +0100
>
> Oddly, you tried without MSI enabled (do I remember right ?) and that
> still failed, so it doesn't seem like it could be a MSI specific
> problem.

Yes, I have tried to disable MSI.

> Get the dump from the patch I sent and I should be able to have some
> idea why this problem might be happening.

------------[ cut here ]------------
WARNING: at net/sched/sch_generic.c:226 dev_watchdog+0x21e/0x230()
NETDEV WATCHDOG: eth2 (niu): transmit timed out
Modules linked in: niu rng_core hpilo bnx2 serio_raw ipmi_si ipmi_msghandler hpwdt zlib_inflate ehci_hcd uhci_hcd sr_mod cdrom [last unloaded: nxge]
Pid: 0, comm: swapper Not tainted 2.6.28-rc2-davem #15
Call Trace:
 [<c01256a3>] warn_slowpath+0x63/0x80
 [<c011ef6e>] ? __enqueue_entity+0x8e/0xb0
 [<c0145154>] ? __lock_acquire+0x104/0x8e0
 [<c0144899>] ? lock_release_holdtime+0x79/0xc0
 [<c021fb4e>] ? strlcpy+0x1e/0x60
 [<c031f2ae>] dev_watchdog+0x21e/0x230
 [<c0144899>] ? lock_release_holdtime+0x79/0xc0
 [<c012e33d>] ? run_timer_softirq+0x10d/0x190
 [<c012e34f>] run_timer_softirq+0x11f/0x190
 [<c014333c>] ? tick_dev_program_event+0x3c/0xc0
 [<c031f090>] ? dev_watchdog+0x0/0x230
 [<c012a084>] __do_softirq+0x94/0x160
 [<c013c4c0>] ? hrtimer_interrupt+0x150/0x180
 [<c012a18b>] do_softirq+0x3b/0x50
 [<c012a395>] irq_exit+0x75/0x90
 [<c011365a>] smp_apic_timer_interrupt+0x5a/0x90
 [<c013c2ca>] ? hrtimer_start+0x1a/0x20
 [<c0103f0c>] apic_timer_interrupt+0x28/0x30
 [<c01090e5>] ? mwait_idle+0x35/0x40
 [<c0101c1e>] cpu_idle+0x4e/0xa0
---[ end trace aebd29b927afeb8b ]---
niu 0000:0b:00.0: niu: eth2: Transmit timed out, resetting
niu 0000:0b:00.0: niu: eth2: LDG[idx(0):num(0)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(1):num(1)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(2):num(2)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(3):num(3)] V0[sw(0x1)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(4):num(4)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(5):num(5)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(6):num(6)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(7):num(7)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(8):num(8)] V0[sw(0x0)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: LDG[idx(9):num(9)] V0[sw(0x400000000)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: Dumping transmitter state.
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] CHANNEL 0 LDN 32
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] parent->lgd_map[ldn] 7
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] Num pending TX SKBs: 3
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] TX_CS sw[0000000000000000] hw[0003000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] CHANNEL 1 LDN 33
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] parent->lgd_map[ldn] 8
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] TX_CS sw[0000000000000000] hw[0000000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] CHANNEL 2 LDN 34
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] parent->lgd_map[ldn] 9
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] Num pending TX SKBs: 237
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] TX_CS sw[00c000bf00000000] hw[00ed00bf00000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] CHANNEL 3 LDN 35
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] TX_CS sw[0000000000000000] hw[0000000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] CHANNEL 4 LDN 36
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] parent->lgd_map[ldn] 1
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] TX_CS sw[0000000000000000] hw[0000000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] CHANNEL 5 LDN 37
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] parent->lgd_map[ldn] 2
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] TX_CS sw[0000000000000000] hw[0000000000000000]
Jesper Dangaard Brouer Nov. 12, 2008, 11:01 a.m. UTC | #4 
On Wed, 2008-11-12 at 01:49 -0800, David Miller wrote:
> Oddly, you tried without MSI enabled (do I remember right ?) and that
> still failed, so it doesn't seem like it could be a MSI specific
> problem.

Just to be absolutly sure that MSI got disabled, I have compiled a
kernel without SMP and without MSI support.

This kernel still shows the problem.

dcu-router-ng:~# cat /proc/interrupts 
           CPU0       
  0:     373724    XT-PIC-XT        timer
  1:          2    XT-PIC-XT        i8042
  2:          0    XT-PIC-XT        cascade
  3:          7    XT-PIC-XT        serial
  5:       4539    XT-PIC-XT        uhci_hcd:usb1, ehci_hcd:usb6, ipmi_si, eth0, eth2
  7:          0    XT-PIC-XT        uhci_hcd:usb2, eth3
  9:          0    XT-PIC-XT        acpi
 10:      40319    XT-PIC-XT        cciss0, uhci_hcd:usb3, uhci_hcd:usb4, uhci_hcd:usb5
 12:          4    XT-PIC-XT        i8042
 14:         58    XT-PIC-XT        ata_piix
 15:          0    XT-PIC-XT        ata_piix
NMI:          0   Non-maskable interrupts
TRM:          0   Thermal event interrupts
ERR:          0


niu: disagrees about version of symbol struct_module
------------[ cut here ]------------
WARNING: at net/sched/sch_generic.c:226 dev_watchdog+0x221/0x230()
NETDEV WATCHDOG: eth2 (niu): transmit timed out
Modules linked in: serio_raw ipmi_si ipmi_msghandler hpilo hpwdt rng_core ehci_hcd uhci_hcd bnx2 zlib_inflate niu sr_mod cdrom
Pid: 0, comm: swapper Not tainted 2.6.28-rc4-davem-nosmp #16
Call Trace:
 [<c0118fe3>] warn_slowpath+0x63/0x80
 [<c0130030>] ? down_interruptible+0x30/0x50
 [<c0136249>] ? lock_release_holdtime+0x79/0xc0
 [<c0132ffb>] ? clocksource_get_next+0x3b/0x50
 [<c0107fbc>] ? native_sched_clock+0x1c/0x70
 [<c0136abd>] ? __lock_acquire+0xfd/0x8e0
 [<c0136abd>] ? __lock_acquire+0xfd/0x8e0
 [<c0136abd>] ? __lock_acquire+0xfd/0x8e0
 [<c0136249>] ? lock_release_holdtime+0x79/0xc0
 [<c020c87e>] ? strlcpy+0x1e/0x60
 [<c0308f71>] dev_watchdog+0x221/0x230
 [<c0136249>] ? lock_release_holdtime+0x79/0xc0
 [<c01217d7>] ? run_timer_softirq+0x107/0x180
 [<c01217e9>] run_timer_softirq+0x119/0x180
 [<c0308d50>] ? dev_watchdog+0x0/0x230
 [<c011d754>] __do_softirq+0x64/0x110
 [<c014d660>] ? handle_level_irq+0xa0/0xd0
 [<c011d82b>] do_softirq+0x2b/0x40
 [<c011dac5>] irq_exit+0x65/0x80
 [<c0104c16>] do_IRQ+0x46/0x80
 [<c0103d6f>] common_interrupt+0x23/0x28
 [<c0108800>] ? mwait_idle+0x30/0x40
 [<c0101c01>] cpu_idle+0x31/0x80
 [<c035aa61>] rest_init+0x61/0x70
---[ end trace d500bfdcd991627f ]---
niu 0000:0b:00.0: niu: eth2: Transmit timed out, resetting
niu 0000:0b:00.0: niu: eth2: LDG[idx(0):num(0)] V0[sw(0x1)hw(0x0)] V1[sw(0x0)hw(0x0)] V2[sw(0x0)hw(0x0)]
niu 0000:0b:00.0: niu: eth2: Dumping transmitter state.
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] CHANNEL 0 LDN 32
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] Num pending TX SKBs: 2
niu 0000:0b:00.0: niu: eth2: TX_RING[ 0] TX_CS sw[0000000000000000] hw[0002000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] CHANNEL 1 LDN 33
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 1] TX_CS sw[0000000000000000] hw[0000000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] CHANNEL 2 LDN 34
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 2] TX_CS sw[0000000000000000] hw[0000000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] CHANNEL 3 LDN 35
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 3] TX_CS sw[0000000000000000] hw[0000000000000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] CHANNEL 4 LDN 36
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] Num pending TX SKBs: 237
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] TX_CS sw[00c000bf00000000] hw[00ed00bf00000000]
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] CHANNEL 5 LDN 37
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] Num pending TX SKBs: 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 5] TX_CS sw[0000000000000000] hw[0000000000000000]
David Miller Nov. 12, 2008, 11:52 a.m. UTC | #5 
From: Jesper Dangaard Brouer <jdb@comx.dk>
Date: Wed, 12 Nov 2008 12:01:50 +0100

> On Wed, 2008-11-12 at 01:49 -0800, David Miller wrote:
> > Oddly, you tried without MSI enabled (do I remember right ?) and that
> > still failed, so it doesn't seem like it could be a MSI specific
> > problem.
> 
> Just to be absolutly sure that MSI got disabled, I have compiled a
> kernel without SMP and without MSI support.

Thanks for the additional checks.

niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] CHANNEL 4 LDN 36
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] parent->lgd_map[ldn] 0
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] Num pending TX SKBs: 237
niu 0000:0b:00.0: niu: eth2: TX_RING[ 4] TX_CS sw[00c000bf00000000] hw[00ed00bf00000000]

So what's supposed to happen is that, in the TX ring, we periodically
set the MARK bit in the TX descriptors.

MARK bits are what trigger TX ring interrupts.

The TX ring is full (237 ~= TX_RING_SIZE [256] - MAX_SKB_FRAGS [18]).

What's supposed to happen is that when a MARK bit is seen, the completion
of sending that packet causes the TX_CS_MK bit to be set (or, alternatively,
the TX_CS_MMK bit if TX_CS_MK is already set) and then the interrupt
is signaled.

Reading the TX_CS register clears the TX_CS_MK bit.

But in all of these traces the TX_CS_MK bit is not set, but we DID
sample the TX_CS register which means we did get an interrupt signaled
for that TX ring.

niu_tx_work() never runs because it doesn't see the TX_CS_MK bit set.
I don't see any error bits set and there are no TX error dumps in your
logs.

Ok, Jesper, please try two things for me, leave the debugging patch
in there for all the tests:

1) Retrigger the problem (with or without MSI, doesn't matter) but
   add back in that test I asked you to try last week.  The one
   where the "if (++rp->mark_counter == rp->mark_freq)" condition
   test in niu_start_xmit() is commented out, so that the
   "mrk |= TX_DESC_MARK;" statement always runs.

   Get me the log dump produced by that scenerio.

2) Next, simply comment out the:

	if (unlikely(!(cs & (TX_CS_MK | TX_CS_MMK))))
		goto out;

   lines in niu_tx_work().

Let's see what new info we can get out of this.

Thanks.

--
To unsubscribe from this list: send the line "unsubscribe netdev" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
diff mbox

Patch

diff --git a/drivers/net/niu.c b/drivers/net/niu.c
index 2c3bb36..beffbc5 100644
--- a/drivers/net/niu.c
+++ b/drivers/net/niu.c
@@ -6070,12 +6070,79 @@  static void niu_reset_task(struct work_struct *work)
 	spin_unlock_irqrestore(&np->lock, flags);
 }
 
+static void niu_dump_ldg_vecs(struct net_device *dev)
+{
+	struct niu *np = netdev_priv(dev);
+	int i;
+
+	for (i = 0; i < np->num_ldg; i++) {
+		struct niu_ldg *lp = &np->ldg[i];
+		u64 v0, v1, v2;
+
+		v0 = nr64(LDSV0(lp->ldg_num));
+		v1 = nr64(LDSV1(lp->ldg_num));
+		v2 = nr64(LDSV2(lp->ldg_num));
+
+		dev_err(np->device, PFX "%s: LDG[idx(%d):num(%u)] "
+			"V0[sw(0x%llx)hw(0x%llx)] "
+			"V1[sw(0x%llx)hw(0x%llx)] "
+			"V2[sw(0x%llx)hw(0x%llx)]\n",
+			dev->name, i, lp->ldg_num,
+			(unsigned long long) lp->v0,
+			(unsigned long long) v0,
+			(unsigned long long) lp->v1,
+			(unsigned long long) v1,
+			(unsigned long long) lp->v2,
+			(unsigned long long) v2);
+	}
+}
+
+static void niu_dump_one_tx_ring(struct net_device *dev,
+				 struct niu *np, int index)
+{
+	struct tx_ring_info *rp = &np->tx_rings[index];
+	struct niu_parent *parent = np->parent;
+	int ldn = LDN_TXDMA(rp->tx_channel);
+	int i, num_pending_skbs = 0;
+
+	dev_err(np->device, PFX "%s: TX_RING[%2u] CHANNEL %u LDN %u\n",
+		dev->name, index, rp->tx_channel, ldn);
+
+	dev_err(np->device, PFX "%s: TX_RING[%2u] parent->lgd_map[ldn] %u\n",
+		dev->name, index, parent->ldg_map[ldn]);
+
+	for (i = 0; i < MAX_TX_RING_SIZE; i++) {
+		if (rp->tx_buffs[i].skb)
+			num_pending_skbs++;
+	}
+	dev_err(np->device, PFX "%s: TX_RING[%2u] Num pending TX SKBs: %d\n",
+		dev->name, index, num_pending_skbs);
+	dev_err(np->device, PFX "%s: TX_RING[%2u] TX_CS sw[%016llx] "
+		"hw[%016llx]\n",
+		dev->name, index,
+		(unsigned long long) rp->tx_cs,
+		(unsigned long long) nr64(TX_CS(rp->tx_channel)));
+}
+
+static void niu_dump_tx_state(struct net_device *dev)
+{
+	struct niu *np = netdev_priv(dev);
+	int i;
+
+	dev_err(np->device, PFX "%s: Dumping transmitter state.\n",
+		dev->name);
+	for (i = 0; i < np->num_tx_rings; i++)
+		niu_dump_one_tx_ring(dev, np, i);
+}
+
 static void niu_tx_timeout(struct net_device *dev)
 {
 	struct niu *np = netdev_priv(dev);
 
 	dev_err(np->device, PFX "%s: Transmit timed out, resetting\n",
 		dev->name);
+	niu_dump_ldg_vecs(dev);
+	niu_dump_tx_state(dev);
 
 	schedule_work(&np->reset_task);
 }