Dropped packets on SUN GEM

Dropped packets on SUN GEM

[Beezly]

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

Hi David,

I've been running some more tests on the GEM card. It seems to be
recovering from the RX hangs ok, but when I ping another host on the
network (with a .1s interval).. I get the following


monkey:/home/andy# ping -s 1472 -i .1 10.0.0.15
PING 10.0.0.15 (10.0.0.15) from 10.0.0.12 : 1472(1500) bytes of data.
1480 bytes from 10.0.0.15: icmp_seq=1 ttl=255 time=0.586 ms
1480 bytes from 10.0.0.15: icmp_seq=2 ttl=255 time=0.554 ms
1480 bytes from 10.0.0.15: icmp_seq=3 ttl=255 time=0.561 ms
1480 bytes from 10.0.0.15: icmp_seq=4 ttl=255 time=0.565 ms
<snip>
1480 bytes from 10.0.0.15: icmp_seq=570 ttl=255 time=0.557 ms
1480 bytes from 10.0.0.15: icmp_seq=571 ttl=255 time=0.550 ms
1480 bytes from 10.0.0.15: icmp_seq=572 ttl=255 time=0.558 ms
1480 bytes from 10.0.0.15: icmp_seq=573 ttl=255 time=0.552 ms
1480 bytes from 10.0.0.15: icmp_seq=574 ttl=255 time=0.558 ms
1480 bytes from 10.0.0.15: icmp_seq=575 ttl=255 time=0.570 ms
1480 bytes from 10.0.0.15: icmp_seq=590 ttl=255 time=0.565 ms
1480 bytes from 10.0.0.15: icmp_seq=591 ttl=255 time=0.562 ms
1480 bytes from 10.0.0.15: icmp_seq=592 ttl=255 time=0.567 ms
1480 bytes from 10.0.0.15: icmp_seq=593 ttl=255 time=0.526 ms
1480 bytes from 10.0.0.15: icmp_seq=594 ttl=255 time=0.560 ms
1480 bytes from 10.0.0.15: icmp_seq=595 ttl=255 time=0.562 ms

notice the missing 14 packets.

Now, if I reproduce the test with a .2s interval between pings, I get
the following results.

monkey:/home/andy# ping -s 1472 -i .2 10.0.0.15
PING 10.0.0.15 (10.0.0.15) from 10.0.0.12 : 1472(1500) bytes of data.
1480 bytes from 10.0.0.15: icmp_seq=1 ttl=255 time=0.645 ms
1480 bytes from 10.0.0.15: icmp_seq=2 ttl=255 time=0.578 ms
1480 bytes from 10.0.0.15: icmp_seq=3 ttl=255 time=0.592 ms
1480 bytes from 10.0.0.15: icmp_seq=4 ttl=255 time=0.585 ms
1480 bytes from 10.0.0.15: icmp_seq=5 ttl=255 time=0.575 ms
1480 bytes from 10.0.0.15: icmp_seq=6 ttl=255 time=0.577 ms
<snip>
1480 bytes from 10.0.0.15: icmp_seq=292 ttl=255 time=0.564 ms
1480 bytes from 10.0.0.15: icmp_seq=293 ttl=255 time=0.559 ms
1480 bytes from 10.0.0.15: icmp_seq=294 ttl=255 time=0.568 ms
1480 bytes from 10.0.0.15: icmp_seq=295 ttl=255 time=0.561 ms
1480 bytes from 10.0.0.15: icmp_seq=310 ttl=255 time=0.588 ms
1480 bytes from 10.0.0.15: icmp_seq=311 ttl=255 time=0.568 ms
1480 bytes from 10.0.0.15: icmp_seq=312 ttl=255 time=0.572 ms
1480 bytes from 10.0.0.15: icmp_seq=313 ttl=255 time=0.576 ms
1480 bytes from 10.0.0.15: icmp_seq=314 ttl=255 time=0.569 ms

notice, 14 missing packets again. 

I'm pretty confident (as confident I can be whilst doing a "watch -n1
ifconfig"!) that it's doing this *during* the RX hang recovery, so it
appears that the RX hang recovery is taking 15 packets-worth of time,
rather than a set period of time (as I would expect - incorrectly?). 

Is this normal? - Because it seems the amount of time to recover from a
hang is inversely proportional to the amount of work it is doing, I am
able to artificially improve the "uptime" of the card by permanantly
running a ping -f <host> on the box!!

Cheers,

Beezly



[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 232 bytes --]

Re: Dropped packets on SUN GEM

[David S. Miller]

   From: Beezly <beezly@beezly.org.uk>
   Date: 12 Mar 2002 23:11:04 +0000
   
   Is this normal? - Because it seems the amount of time to recover from a
   hang is inversely proportional to the amount of work it is doing, I am
   able to artificially improve the "uptime" of the card by permanantly
   running a ping -f <host> on the box!!

What I believe happens is that when the RX overflow condition occurs,
there will be some packets that will be corrupted as a result.

I find it really odd that you can reproduce this condition so readily.
Does it happen under normal usage or do you have to issue a ping flood
or some other packet intensive job to trigger the problem?  Also, are
you getting Pause enabled on the link consistently?

Re: Dropped packets on SUN GEM

[Beezly]

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

Hi David,

On Tue, 2002-03-12 at 23:14, David S. Miller wrote:
> What I believe happens is that when the RX overflow condition occurs,
> there will be some packets that will be corrupted as a result.

Yep, I expected that, but wouldn't this only be packets which had
*already* entered the RX buffer? These packets are being transmitted at
a rate of one every .1/.2 seconds, so I guess it's unlikely that all
these packets have entered the RX buffer and been zapped. OTOH - I'm
just stabbing away wildly in the dark so I most likely wrong ;)

> I find it really odd that you can reproduce this condition so readily.
> Does it happen under normal usage or do you have to issue a ping flood
> or some other packet intensive job to trigger the problem?  Also, are
> you getting Pause enabled on the link consistently?

I'm not getting the Pause enabled message *at all*. The other host is
100Mbit (I've not got another gigabit host to test against yet).

If I stop doing the ping I notice that I loose TCP/IP connectivity for a
while, but it usually comes back after a period of time (sorry to be so
vague, but I haven't been able to tell how long it takes to come back
exactly).

Interestingly, whilst writing this e-mail, I've been running a ping with
a 1 second interval and no options (so we end up with 84 bytes in the
packet). It did the same thing, but took a lot longer than 14 packets to
recover... (FYI: 195.195.14.1 is across an ADSL link from me -
explaining the high rtt :) )

64 bytes from 195.195.14.1: icmp_seq=258 ttl=239 time=33.0 ms
64 bytes from 195.195.14.1: icmp_seq=259 ttl=239 time=32.4 ms
64 bytes from 195.195.14.1: icmp_seq=260 ttl=239 time=63.1 ms
64 bytes from 195.195.14.1: icmp_seq=261 ttl=239 time=32.3 ms
64 bytes from 195.195.14.1: icmp_seq=262 ttl=239 time=33.2 ms
64 bytes from 195.195.14.1: icmp_seq=263 ttl=239 time=33.8 ms
64 bytes from 195.195.14.1: icmp_seq=264 ttl=239 time=33.4 ms
>From 10.0.0.12 icmp_seq=309 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=310 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=311 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=313 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=314 Destination Host Unreachable
<snip>
>From 10.0.0.12 icmp_seq=370 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=371 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=373 Destination Host Unreachable
>From 10.0.0.12 icmp_seq=374 Destination Host Unreachable
64 bytes from 195.195.14.1: icmp_seq=375 ttl=239 time=1036 ms
64 bytes from 195.195.14.1: icmp_seq=376 ttl=239 time=38.2 ms
64 bytes from 195.195.14.1: icmp_seq=377 ttl=239 time=29.4 ms
64 bytes from 195.195.14.1: icmp_seq=378 ttl=239 time=32.1 ms

So I had another brainstorm, perhaps this is related to the amount of
data transfer /rather/ than packets.

If I do ping -i .1 10.0.0.15 (i.e. an 84 byte packet), I get the
following very interesting results.

64 bytes from 10.0.0.15: icmp_seq=298 ttl=255 time=0.223 ms
64 bytes from 10.0.0.15: icmp_seq=299 ttl=255 time=0.209 ms
64 bytes from 10.0.0.15: icmp_seq=300 ttl=255 time=0.233 ms
64 bytes from 10.0.0.15: icmp_seq=301 ttl=255 time=0.210 ms
64 bytes from 10.0.0.15: icmp_seq=302 ttl=255 time=0.220 ms
64 bytes from 10.0.0.15: icmp_seq=303 ttl=255 time=0.208 ms
64 bytes from 10.0.0.15: icmp_seq=304 ttl=255 time=0.213 ms
64 bytes from 10.0.0.15: icmp_seq=630 ttl=255 time=0.214 ms
64 bytes from 10.0.0.15: icmp_seq=631 ttl=255 time=0.212 ms
64 bytes from 10.0.0.15: icmp_seq=632 ttl=255 time=0.202 ms
64 bytes from 10.0.0.15: icmp_seq=633 ttl=255 time=0.201 ms


i.e. it takes the card 325 packets to recover, yet with 1500 byte
packets... I get, 

1480 bytes from 10.0.0.15: icmp_seq=499 ttl=255 time=0.558 ms
1480 bytes from 10.0.0.15: icmp_seq=500 ttl=255 time=0.561 ms
1480 bytes from 10.0.0.15: icmp_seq=501 ttl=255 time=0.550 ms
1480 bytes from 10.0.0.15: icmp_seq=502 ttl=255 time=0.557 ms
1480 bytes from 10.0.0.15: icmp_seq=503 ttl=255 time=0.547 ms
1480 bytes from 10.0.0.15: icmp_seq=518 ttl=255 time=0.566 ms
1480 bytes from 10.0.0.15: icmp_seq=519 ttl=255 time=0.551 ms
1480 bytes from 10.0.0.15: icmp_seq=520 ttl=255 time=0.552 ms
1480 bytes from 10.0.0.15: icmp_seq=521 ttl=255 time=0.552 ms
1480 bytes from 10.0.0.15: icmp_seq=522 ttl=255 time=0.548 ms

14 packets missing.

325*84  = 27300
14*1500 = 21000

Are these number relevant?

Beezly


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 232 bytes --]

Re: Dropped packets on SUN GEM

[David S. Miller]

   From: Beezly <beezly@beezly.org.uk>
   Date: 12 Mar 2002 23:36:21 +0000

   14 packets missing.
   
   325*84  = 27300
   14*1500 = 21000
   
   Are these number relevant?

The size of GEM's receive FIFO is 20K :-)
(TX fifo is 9K)

You say you are on 100Mbit, is this to a hub at half-duplex?
That is basically the worst combination for GEM because without Pause
(even my crappy Netgear 100Mbit switches negotiate pause to on with
my GEMs) there is no way to throttle the sender so that the receive
overflow condition will not occur.

Thinking... I guess my gem_rxmac_reset() does not reset the
receive FIFO so until it is filled up and reset none of the
packets received actually make it past the card.

How does it behave with the patch below added to what you are running
right now?

--- drivers/net/sungem.c.~1~	Tue Mar 12 09:35:37 2002
+++ drivers/net/sungem.c	Tue Mar 12 15:51:05 2002
@@ -401,7 +401,11 @@
 		gp->net_stats.rx_over_errors++;
 		gp->net_stats.rx_fifo_errors++;
 
+#if 1
+		return 1;
+#else
 		ret = gem_rxmac_reset(gp);
+#endif
 	}
 
 	if (rxmac_stat & MAC_RXSTAT_ACE)

Re: Dropped packets on SUN GEM

[Beezly]

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

On Tue, 2002-03-12 at 23:52, David S. Miller wrote:
> Thinking... I guess my gem_rxmac_reset() does not reset the
> receive FIFO so until it is filled up and reset none of the
> packets received actually make it past the card.
> 
> How does it behave with the patch below added to what you are running
> right now?
> 

The problem appears to get worse;

$ ping -s 1472 -i 0.1 10.0.0.3 
<snip>
1480 bytes from 10.0.0.3: icmp_seq=4487 ttl=255 time=4.13 ms
1480 bytes from 10.0.0.3: icmp_seq=4488 ttl=255 time=4.13 ms
1480 bytes from 10.0.0.3: icmp_seq=4489 ttl=255 time=4.13 ms
1480 bytes from 10.0.0.3: icmp_seq=4490 ttl=255 time=4.13 ms
1480 bytes from 10.0.0.3: icmp_seq=4491 ttl=255 time=4.14 ms
1480 bytes from 10.0.0.3: icmp_seq=4517 ttl=255 time=4.18 ms
1480 bytes from 10.0.0.3: icmp_seq=4518 ttl=255 time=4.13 ms
1480 bytes from 10.0.0.3: icmp_seq=4519 ttl=255 time=4.12 ms
1480 bytes from 10.0.0.3: icmp_seq=4520 ttl=255 time=4.13 ms

25 lost packets :(

Also, just to clarify (i wasn't clear earlier), this host is connected
via 1000Mbps full-duplex fibre to the switch.

The other machines on the switch are connected either by 100Mbps copper
or 10Mpbs copper. I'm guessing the other machines shouldn't be able to
flood the RX on this host even if they all transmitted at the same time?
(there are only three of them)

Beezly

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 232 bytes --]

Re: Dropped packets on SUN GEM

[David S. Miller]

   From: Beezly <beezly@beezly.org.uk>
   Date: 13 Mar 2002 00:08:47 +0000
   
   Also, just to clarify (i wasn't clear earlier), this host is connected
   via 1000Mbps full-duplex fibre to the switch.

The fibre port on the switch should be enabling pause then.
It doesn't make any sense for a switch highend enough to have
a fibre port yet not support and negotiate pause.

You told me ealier that "sometimes pause is on, sometimes
not".  Today you told me "pause is not going on".  Please,
which is it? :)

Do you have any manuals on the switch so we can check this
out?

Re: Dropped packets on SUN GEM

[Beezly]

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

Hi David,

I *did* see the Pause is enabled message the other day, but I have only
seen it once. It hasn't been seen at all during tests today.

On Wed, 2002-03-13 at 00:10, David S. Miller wrote:
> You told me ealier that "sometimes pause is on, sometimes
> not".  Today you told me "pause is not going on".  Please,
> which is it? :)
> 
> Do you have any manuals on the switch so we can check this
> out?

I've just checked the manual;

"Flow control is supported only on Gigabit Ethernet ports. It is enabled
or disabled as part of autonegotiation. If autonegotiation is set to
off, flow control is disabled. When autonegotiation is turned on, flow
control is enabled".

According to the switch, it's set up for autonegotiation and flow
control is set to "SYM";

Port Configuration Monitor                           Tue Mar 12 22:14:18
2002
Port        Port    Link   Auto    Speed       Duplex    Flow  Ld Share 
            State   Status Neg   Cfg Actual  Cfg Actual  Ctrl   Master
Pri  Red
========================================================================  50      ENABLED   ACTIVE  ON  1000   1000  AUTO  FULL   SYM           

Sorry to be vague,

Cheers,

Beezly


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 232 bytes --]

Re: Dropped packets on SUN GEM

[David S. Miller]

   From: Beezly <beezly@beezly.org.uk>
   Date: 13 Mar 2002 00:36:07 +0000

   Sorry to be vague,

No problem.  If you add this patch below does it make Pause get
negotiated on?  Please print everything the driver says from module
load to the time the link comes up.

Thank you.

--- drivers/net/sungem.c.~1~	Tue Mar 12 09:35:37 2002
+++ drivers/net/sungem.c	Tue Mar 12 16:53:44 2002
@@ -1792,7 +1792,7 @@
 		 */
 		val = readl(gp->regs + PCS_MIIADV);
 		val |= (PCS_MIIADV_FD | PCS_MIIADV_HD |
-			PCS_MIIADV_SP);
+			PCS_MIIADV_SP | PCS_MIIADV_AP);
 		writel(val, gp->regs + PCS_MIIADV);
 
 		/* Enable and restart auto-negotiation, disable wrapback/loopback,

Re: Dropped packets on SUN GEM

[Beezly]

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

Hi David,

On Wed, 2002-03-13 at 00:56, David S. Miller wrote:
> No problem.  If you add this patch below does it make Pause get
> negotiated on?  Please print everything the driver says from module
> load to the time the link comes up.

It doesn't appear to :(

sungem.c:v0.96 11/17/01 David S. Miller (davem@redhat.com)
PCI: Found IRQ 5 for device 00:0a.0
PCI: Sharing IRQ 5 with 00:0b.1
eth0: Sun GEM (PCI) 10/100/1000BaseT Ethernet 00:00:00:00:00:00 
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is disabled
eth0: PCS AutoNEG complete.
eth0: PCS link is now up.
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is disabled
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is disabled
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is disabled

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 232 bytes --]

Re: Dropped packets on SUN GEM

[David S. Miller]

   From: Beezly <beezly@beezly.org.uk>
   Date: 13 Mar 2002 01:07:14 +0000
   
   It doesn't appear to :(
...   
   eth0: Pause is disabled

Some day I will learn how to program, you do have
Pause enabled I just don't know how to print that
our properly from the driver :-)

--- drivers/net/sungem.c.~2~	Tue Mar 12 16:53:44 2002
+++ drivers/net/sungem.c	Tue Mar 12 17:14:26 2002
@@ -1213,15 +1213,15 @@
 
 	if (netif_msg_link(gp)) {
 		if (pause) {
-			printk(KERN_INFO "%s: Pause is disabled\n",
-			       gp->dev->name);
-		} else {
 			printk(KERN_INFO "%s: Pause is enabled "
 			       "(rxfifo: %d off: %d on: %d)\n",
 			       gp->dev->name,
 			       gp->rx_fifo_sz,
 			       gp->rx_pause_off,
 			       gp->rx_pause_on);
+		} else {
+			printk(KERN_INFO "%s: Pause is disabled\n",
+			       gp->dev->name);
 		}
 	}
 

Re: Dropped packets on SUN GEM

[Beezly]

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

Ahha! ;) 

Looks like some better output now.

sungem.c:v0.96 11/17/01 David S. Miller (davem@redhat.com)
PCI: Found IRQ 5 for device 00:0a.0
PCI: Sharing IRQ 5 with 00:0b.1
eth0: Sun GEM (PCI) 10/100/1000BaseT Ethernet 00:00:00:00:00:00 
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is enabled (rxfifo: 20480 off: 17408 on: 15872)
eth0: PCS AutoNEG complete.
eth0: PCS link is now up.
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is enabled (rxfifo: 20480 off: 17408 on: 15872)
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is enabled (rxfifo: 20480 off: 17408 on: 15872)
eth0: Link is up at 1000 Mbps, full-duplex.
eth0: Pause is enabled (rxfifo: 20480 off: 17408 on: 15872)


On Wed, 2002-03-13 at 01:15, David S. Miller wrote:
>    From: Beezly <beezly@beezly.org.uk>
>    Date: 13 Mar 2002 01:07:14 +0000
>    
>    It doesn't appear to :(
> ...   
>    eth0: Pause is disabled
> 
> Some day I will learn how to program, you do have
> Pause enabled I just don't know how to print that
> our properly from the driver :-)
> 
> --- drivers/net/sungem.c.~2~	Tue Mar 12 16:53:44 2002
> +++ drivers/net/sungem.c	Tue Mar 12 17:14:26 2002
> @@ -1213,15 +1213,15 @@
>  
>  	if (netif_msg_link(gp)) {
>  		if (pause) {
> -			printk(KERN_INFO "%s: Pause is disabled\n",
> -			       gp->dev->name);
> -		} else {
>  			printk(KERN_INFO "%s: Pause is enabled "
>  			       "(rxfifo: %d off: %d on: %d)\n",
>  			       gp->dev->name,
>  			       gp->rx_fifo_sz,
>  			       gp->rx_pause_off,
>  			       gp->rx_pause_on);
> +		} else {
> +			printk(KERN_INFO "%s: Pause is disabled\n",
> +			       gp->dev->name);
>  		}
>  	}
>  
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/


[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 232 bytes --]