Dropped packets on SUN GEM
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
From: Beezly <[email protected]>
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?
Hi David,
Quoted 2 lines · David S. Miller
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 ;)
Quoted 4 lines
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
Quoted 5 lines
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>
Quoted 4 lines
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
From: Beezly <[email protected]>
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?
net/sungem.c renamed from net/sungem.c.~1~ +4 -0
@@ -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 )
Quoted 7 lines · David S. Miller
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
From: Beezly <[email protected]>
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?
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.
Quoted 6 lines · David S. Miller
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 MasterPri Red
======================================================================== 50 ENABLED ACTIVE ON 1000 1000 AUTO FULL SYM
Sorry to be vague,
Cheers,
Beezly
From: Beezly <[email protected]>
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.
net/sungem.c renamed from net/sungem.c.~1~ +1 -1
@@ -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,
Hi David,
Quoted 3 lines · David S. Miller
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 ([email protected])
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
From: Beezly <[email protected]>
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 :-)
net/sungem.c renamed from net/sungem.c.~2~ +3 -3
@@ -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); } }
Ahha! ;)
Looks like some better output now.
sungem.c:v0.96 11/17/01 David S. Miller ([email protected])
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)
Quoted 37 lines · David S. Miller
From: Beezly <[email protected]> Date: 13 Mar 2002 01:07:14 +0000 It doesn't appear to :(...
eth0: Pause is disabledSome 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 :-)net/sungem.c renamed from net/sungem.c.~2~ +3
-4@@ -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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/