Re: Re: Strange connection slowdown on pcnet32

Re: Re: Strange connection slowdown on pcnet32

[pcnet32]

Are there any messages in the log about timeouts, or anything else from the driver? When it gets in this state, can you communicate with another system, and does it have the same slow behavior?

Looks like my mailer is munging white spaces.

On Fri, Feb 16, 2007 at 09:35:54AM -0500, Lennart Sorensen wrote:
> I have run some tests using 2.6.8 now, and so far it hasn't failed.
> 
> Still investigating...

And 5 minutes later 2.6.8 failed the same way too.  Maybe I will go back
to 2.4 and check.

--
Len Sorensen
-
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

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 10:21:24AM -0600, pcnet32@verizon.net wrote:
> Are there any messages in the log about timeouts, or anything else from the driver? When it gets in this state, can you communicate with another system, and does it have the same slow behavior?

Nope no timeouts or messages.  As far as the system looks, cpu and ram and
logs show nothing unusual.  Just very slow reception on the ethernet port
going towards the server providing the data for the transfer.  Messages do
get through eventually, but very very late (when a ping reply arives at
the port and takes 5 to 10 seconds to make it to the network stack, then
something isn't right, at least when there is no other traffic waiting).

I did have NAPI in the driver even in 2.6.8 (I was adding that at the
time).  I am now testing with 2.6.8 without NAPI (so no mask/unmask of
receive interrupts taking place), and so far it has run for over an hour
without failing, although that doens't prove it won't, just that it has
lasted longer.

I think I will try compiling 2.6.18 again with NAPI disabled on the
pcnet32 and see what that does.  There is a chance that something in the
NAPI implementation is breaking the chip's receive somehow although I
can't currently imagine what it could be or how.

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 12:21:10PM -0500, Lennart Sorensen wrote:
> On Fri, Feb 16, 2007 at 10:21:24AM -0600, pcnet32@verizon.net wrote:
> > Are there any messages in the log about timeouts, or anything else from the driver? When it gets in this state, can you communicate with another system, and does it have the same slow behavior?
> 
> Nope no timeouts or messages.  As far as the system looks, cpu and ram and
> logs show nothing unusual.  Just very slow reception on the ethernet port
> going towards the server providing the data for the transfer.  Messages do
> get through eventually, but very very late (when a ping reply arives at
> the port and takes 5 to 10 seconds to make it to the network stack, then
> something isn't right, at least when there is no other traffic waiting).
> 
> I did have NAPI in the driver even in 2.6.8 (I was adding that at the
> time).  I am now testing with 2.6.8 without NAPI (so no mask/unmask of
> receive interrupts taking place), and so far it has run for over an hour
> without failing, although that doens't prove it won't, just that it has
> lasted longer.
> 
> I think I will try compiling 2.6.18 again with NAPI disabled on the
> pcnet32 and see what that does.  There is a chance that something in the
> NAPI implementation is breaking the chip's receive somehow although I
> can't currently imagine what it could be or how.

So I have determined that when the port gets "stuck/slow" it is hitting
this problem:

(in pcnet32_rx):
        while (quota > npackets && (short)le16_to_cpu(rxp->status) >= 0) {
                if (netif_msg_intr(lp)) printk(KERN_DEBUG "%s: pcnet32_rx npackets %d\n", dev->name, npackets);
                pcnet32_rx_entry(dev, lp, rxp, entry);
                npackets += 1;
                /*
                 * The docs say that the buffer length isn't touched, but Andrew
                 * Boyd of QNX reports that some revs of the 79C965 clear it.
                 */
                rxp->buf_length = le16_to_cpu(2 - PKT_BUF_SZ);
                wmb();  /* Make sure owner changes after others are visible */
                rxp->status = le16_to_cpu(0x8000);
                entry = (++lp->cur_rx) & lp->rx_mod_mask;
                rxp = &lp->rx_ring[entry];
        }

Unfortunately rxp->status reads as 0x8000 for a long time, and then
eventually changes to 0x0310 at which point the receive happens.  Until
that happens, the poll is called about once per second and each time
returns that 0 packets were received but that more packets are waiting.

I can't figure out why it would get a status of 0x8000 which means that
the MAC hasn't changed the ownership flag on the packet yet, even though
it generated a receive interrupt multiple seconds ago.  Could it be some
caching issue that makes the cpu not realize that the memory has in fact
been changed by DMA?  Any way to force a cache update for a memory
location?

The CPU is a Geode SC1200 (Geode GX1 + Companion in one).  So far I have
seen __memcpy from system ram to device memory get data out of order, so
I have no reason to believe the cpu doesn't have more stupid bugs
related to doing I/O.

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 03:23:00PM -0500, Lennart Sorensen wrote:
> So I have determined that when the port gets "stuck/slow" it is hitting
> this problem:
> 
> (in pcnet32_rx):
>         while (quota > npackets && (short)le16_to_cpu(rxp->status) >= 0) {
>                 if (netif_msg_intr(lp)) printk(KERN_DEBUG "%s: pcnet32_rx npackets %d\n", dev->name, npackets);
>                 pcnet32_rx_entry(dev, lp, rxp, entry);
>                 npackets += 1;
>                 /*
>                  * The docs say that the buffer length isn't touched, but Andrew
>                  * Boyd of QNX reports that some revs of the 79C965 clear it.
>                  */
>                 rxp->buf_length = le16_to_cpu(2 - PKT_BUF_SZ);
>                 wmb();  /* Make sure owner changes after others are visible */
>                 rxp->status = le16_to_cpu(0x8000);
>                 entry = (++lp->cur_rx) & lp->rx_mod_mask;
>                 rxp = &lp->rx_ring[entry];
>         }
> 
> Unfortunately rxp->status reads as 0x8000 for a long time, and then
> eventually changes to 0x0310 at which point the receive happens.  Until
> that happens, the poll is called about once per second and each time
> returns that 0 packets were received but that more packets are waiting.
> 
> I can't figure out why it would get a status of 0x8000 which means that
> the MAC hasn't changed the ownership flag on the packet yet, even though
> it generated a receive interrupt multiple seconds ago.  Could it be some
> caching issue that makes the cpu not realize that the memory has in fact
> been changed by DMA?  Any way to force a cache update for a memory
> location?
> 
> The CPU is a Geode SC1200 (Geode GX1 + Companion in one).  So far I have
> seen __memcpy from system ram to device memory get data out of order, so
> I have no reason to believe the cpu doesn't have more stupid bugs
> related to doing I/O.

It seems whenever it gets stuck, it is always the same descripter it is
stuck on.  Here is my current log:

eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: 0310 next->status: 0340
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: pcnet32_poll: pcnet32_rx() got 16 packets
eth1: base: 0x05215812 status: 0310 next->status: 0310
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: netif_receive_skb(skb)
eth1: pcnet32_poll: pcnet32_rx() got 16 packets
eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x6f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
eth1: pcnet32_poll: pcnet32_rx() got 0 packets
eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
eth1: pcnet32_poll: pcnet32_rx() got 0 packets

So somehow it ends up that when it reads the status of the descriptor at
address 0x04c51812, it sees the status as 0x8000 (which means owned by
the MAC I believe), even though the next descriptor in the ring has a
sensible status, indicating that the descriptor is ready to be handled
by the driver.  Since the descriptor isn't ready, we exit without
handling anything and NAPI reschedules is the next time we get an
interrupt, and after some random number of tries, we finally see the
right status and handle the packet, along with a bunch of other packets
waiting in the descriptor ring.  Then we seem to hit the exact same
descriptor address again, with the same problem in the status we read,
and again we are stuck for a while, until finally we see the right
status, and another pile of packets get handled, and we again hit the
same descriptor address and get stuck.

I believe doing ifconfig eth1 down;ifconfig eth1 up actually
reinitialized the port with a new descriptor ring, but I could have got
that part wrong looking at the code.  Either way it clears things up
again for a while, until we get stuck again.

It makes me think the cpu somehow reads the memory location when the
descriptor ring is empty, notes it is owned by the MAC, and stops
handling packets (as it should), but then when the next receive occours,
it doesn't read physical memory again for some odd reason, and see the
previous status rather than the updated status.

Now for some reason it seems when the driver is not using NAPI, and
hence not enabling and disabling interrupt masks, this problem somehow
never occours (well at least I haven't managed to make it occour yet, so
who knows for sure.  Certainly with NAPI enabled I can kill it in
seconds).

Is there a way I can flush the CPU cache and force it to reread memory
for an address range, or for all cache, or some other way to ensure the
memory value I see is really the memory value that is in system memory
for a given address?

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 04:01:57PM -0500, Lennart Sorensen wrote:
> It seems whenever it gets stuck, it is always the same descripter it is
> stuck on.  Here is my current log:
> 
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: 0310 next->status: 0340
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: pcnet32_poll: pcnet32_rx() got 16 packets
> eth1: base: 0x05215812 status: 0310 next->status: 0310
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: pcnet32_poll: pcnet32_rx() got 16 packets
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x6f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> 
> So somehow it ends up that when it reads the status of the descriptor at
> address 0x04c51812, it sees the status as 0x8000 (which means owned by
> the MAC I believe), even though the next descriptor in the ring has a
> sensible status, indicating that the descriptor is ready to be handled
> by the driver.  Since the descriptor isn't ready, we exit without
> handling anything and NAPI reschedules is the next time we get an
> interrupt, and after some random number of tries, we finally see the
> right status and handle the packet, along with a bunch of other packets
> waiting in the descriptor ring.  Then we seem to hit the exact same
> descriptor address again, with the same problem in the status we read,
> and again we are stuck for a while, until finally we see the right
> status, and another pile of packets get handled, and we again hit the
> same descriptor address and get stuck.
> 
> I believe doing ifconfig eth1 down;ifconfig eth1 up actually
> reinitialized the port with a new descriptor ring, but I could have got
> that part wrong looking at the code.  Either way it clears things up
> again for a while, until we get stuck again.
> 
> It makes me think the cpu somehow reads the memory location when the
> descriptor ring is empty, notes it is owned by the MAC, and stops
> handling packets (as it should), but then when the next receive occours,
> it doesn't read physical memory again for some odd reason, and see the
> previous status rather than the updated status.
> 
> Now for some reason it seems when the driver is not using NAPI, and
> hence not enabling and disabling interrupt masks, this problem somehow
> never occours (well at least I haven't managed to make it occour yet, so
> who knows for sure.  Certainly with NAPI enabled I can kill it in
> seconds).
> 
> Is there a way I can flush the CPU cache and force it to reread memory
> for an address range, or for all cache, or some other way to ensure the
> memory value I see is really the memory value that is in system memory
> for a given address?

It seems so far that if I change Kconfig.cpu and force it to enable
X86_OOSTORE for the MGEODE_GX1 then things behave properly.  Perhaps the
out of order memory access crap the MediaGX/Geode processors do is
having some affect, and enabling the code for wmb, etc, actually does
something.

--
Len Sorensen

MediaGX/GeodeGX1 requires X86_OOSTORE. (Was: Re: Strange connection slowdown on pcnet32)

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 05:27:28PM -0500, Lennart Sorensen wrote:
> On Fri, Feb 16, 2007 at 04:01:57PM -0500, Lennart Sorensen wrote:
> > It seems whenever it gets stuck, it is always the same descripter it is
> > stuck on.  Here is my current log:
> > 
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0340
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: 0310 next->status: 0340
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: pcnet32_poll: pcnet32_rx() got 16 packets
> > eth1: base: 0x05215812 status: 0310 next->status: 0310
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: netif_receive_skb(skb)
> > eth1: pcnet32_poll: pcnet32_rx() got 16 packets
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x6f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> > eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> > eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> > eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> > 
> > So somehow it ends up that when it reads the status of the descriptor at
> > address 0x04c51812, it sees the status as 0x8000 (which means owned by
> > the MAC I believe), even though the next descriptor in the ring has a
> > sensible status, indicating that the descriptor is ready to be handled
> > by the driver.  Since the descriptor isn't ready, we exit without
> > handling anything and NAPI reschedules is the next time we get an
> > interrupt, and after some random number of tries, we finally see the
> > right status and handle the packet, along with a bunch of other packets
> > waiting in the descriptor ring.  Then we seem to hit the exact same
> > descriptor address again, with the same problem in the status we read,
> > and again we are stuck for a while, until finally we see the right
> > status, and another pile of packets get handled, and we again hit the
> > same descriptor address and get stuck.
> > 
> > I believe doing ifconfig eth1 down;ifconfig eth1 up actually
> > reinitialized the port with a new descriptor ring, but I could have got
> > that part wrong looking at the code.  Either way it clears things up
> > again for a while, until we get stuck again.
> > 
> > It makes me think the cpu somehow reads the memory location when the
> > descriptor ring is empty, notes it is owned by the MAC, and stops
> > handling packets (as it should), but then when the next receive occours,
> > it doesn't read physical memory again for some odd reason, and see the
> > previous status rather than the updated status.
> > 
> > Now for some reason it seems when the driver is not using NAPI, and
> > hence not enabling and disabling interrupt masks, this problem somehow
> > never occours (well at least I haven't managed to make it occour yet, so
> > who knows for sure.  Certainly with NAPI enabled I can kill it in
> > seconds).
> > 
> > Is there a way I can flush the CPU cache and force it to reread memory
> > for an address range, or for all cache, or some other way to ensure the
> > memory value I see is really the memory value that is in system memory
> > for a given address?
> 
> It seems so far that if I change Kconfig.cpu and force it to enable
> X86_OOSTORE for the MGEODE_GX1 then things behave properly.  Perhaps the
> out of order memory access crap the MediaGX/Geode processors do is
> having some affect, and enabling the code for wmb, etc, actually does
> something.

Well so far it really looks like enabling OOSTORE on the Geode
SC1200/GX1 really does make a difference.  A bit of searching seems to
indicate the person that originally submitted the patch that enabled
load/store reordering on the MediaGX/Geode though it might need OOSTORE,
but was convinced by others it didn't.  Looks like it really does need
it.  The failure that occoured before within a few seconds of starting a
large transfer, no longer fails and all I did was enable
CONFIG_X86_OOSTORE, and recompile pcnet32.ko and load the new module on
the running system.  Moving back to the pcnet32.ko built without OOSTORE
enabled hits the failure again within seconds, until ifconfig eth1
down/up reinitialized it's descriptor ring, after which it survices
another bit of transfer and then fails again.

I hate this CPU.

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE. (Was: Re: Strange connection slowdown on pcnet32)

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 05:48:24PM -0500, Lennart Sorensen wrote:
> Well so far it really looks like enabling OOSTORE on the Geode
> SC1200/GX1 really does make a difference.  A bit of searching seems to
> indicate the person that originally submitted the patch that enabled
> load/store reordering on the MediaGX/Geode though it might need OOSTORE,
> but was convinced by others it didn't.  Looks like it really does need
> it.  The failure that occoured before within a few seconds of starting a
> large transfer, no longer fails and all I did was enable
> CONFIG_X86_OOSTORE, and recompile pcnet32.ko and load the new module on
> the running system.  Moving back to the pcnet32.ko built without OOSTORE
> enabled hits the failure again within seconds, until ifconfig eth1
> down/up reinitialized it's descriptor ring, after which it survices
> another bit of transfer and then fails again.

Well forcing load/store serialize on the CPU doesn't help, disalbing
memory bypass doesn't help.  Enabling the X86_OOSTORE does help.  What a
stupid CPU design.

So far nothing has managed to fix the __memcpy_toio in the jsm driver
getting data out of order when sending on an exar pci uart chip.  Only
calling memcpy with one byte at a time seems to work there.  Works fine
on every other cpu of course.  What else am I going to discover is wrong
with this CPU.

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[takada]

From: lsorense@csclub.uwaterloo.ca (Lennart Sorensen)
Subject: Re: MediaGX/GeodeGX1 requires X86_OOSTORE. (Was: Re: Strange connection slowdown on pcnet32)
Date: Fri, 16 Feb 2007 19:00:19 -0500

> On Fri, Feb 16, 2007 at 05:48:24PM -0500, Lennart Sorensen wrote:
> > Well so far it really looks like enabling OOSTORE on the Geode
> > SC1200/GX1 really does make a difference.  A bit of searching seems to
> > indicate the person that originally submitted the patch that enabled
> > load/store reordering on the MediaGX/Geode though it might need OOSTORE,
> > but was convinced by others it didn't.  Looks like it really does need
> > it.  The failure that occoured before within a few seconds of starting a
> > large transfer, no longer fails and all I did was enable
> > CONFIG_X86_OOSTORE, and recompile pcnet32.ko and load the new module on
> > the running system.  Moving back to the pcnet32.ko built without OOSTORE
> > enabled hits the failure again within seconds, until ifconfig eth1
> > down/up reinitialized it's descriptor ring, after which it survices
> > another bit of transfer and then fails again.
> 
> Well forcing load/store serialize on the CPU doesn't help, disalbing
> memory bypass doesn't help.  Enabling the X86_OOSTORE does help.  What a
> stupid CPU design.

is it mean what doesn't help with doesn't call set_cx86_reoder()?
this function disable to reorder at 0x4000:0000 to 0xffff:ffff.
does pcnet32 access at out of above range?

--- arch/i386/Kconfig.cpu~	2007-02-05 03:44:54.000000000 +0900
+++ arch/i386/Kconfig.cpu	2007-02-17 21:25:52.000000000 +0900
@@ -322,7 +322,7 @@ config X86_USE_3DNOW
 
 config X86_OOSTORE
 	bool
-	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR
+	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR || MGEODEGX1
 	default y
 
 config X86_TSC

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Sat, Feb 17, 2007 at 11:11:13PM +0900, takada wrote:
> is it mean what doesn't help with doesn't call set_cx86_reoder()?
> this function disable to reorder at 0x4000:0000 to 0xffff:ffff.
> does pcnet32 access at out of above range?

No it is accessing system memory by DMA to transfer frames.  Since the
system has 128MB ram, the addresses are probably all in the first 128MB
range.

I tried changing cyrix.c to explicitly set the serialize bit (0x8000 in
PCR0) rather than explcitly clearing it as is done now.  Didn't make a
difference.  I tried reversing the memory bypass setting, which also did
nothing.  Enabling CONFIG_X86_OOSTORE and recompiling however does make
a difference.

> --- arch/i386/Kconfig.cpu~	2007-02-05 03:44:54.000000000 +0900
> +++ arch/i386/Kconfig.cpu	2007-02-17 21:25:52.000000000 +0900
> @@ -322,7 +322,7 @@ config X86_USE_3DNOW
>  
>  config X86_OOSTORE
>  	bool
> -	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR
> +	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR || MGEODEGX1
>  	default y
>  
>  config X86_TSC

I did:
	depends on ((MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR) || MGEODEGX1
since I wasn't sure of the precedence in the Kconfig files.

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Sat, Feb 17, 2007 at 11:11:13PM +0900, takada wrote:
> is it mean what doesn't help with doesn't call set_cx86_reoder()?
> this function disable to reorder at 0x4000:0000 to 0xffff:ffff.
> does pcnet32 access at out of above range?
> 
> --- arch/i386/Kconfig.cpu~	2007-02-05 03:44:54.000000000 +0900
> +++ arch/i386/Kconfig.cpu	2007-02-17 21:25:52.000000000 +0900
> @@ -322,7 +322,7 @@ config X86_USE_3DNOW
>  
>  config X86_OOSTORE
>  	bool
> -	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR
> +	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR || MGEODEGX1
>  	default y
>  
>  config X86_TSC

Well it turns out that enabling OOSTORE doesn't elliminate the problem,
but it does make it go from occouring within seconds to occouring within
many hours.  I am off to investigate some more.

Does anyone know if there is any way to flush a cache line of the cpu to
force rereading system memory for a given address or address range?

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Roland Dreier]

 > Does anyone know if there is any way to flush a cache line of the cpu to
 > force rereading system memory for a given address or address range?

There is the "clflush" instruction, but not all x86 CPUs support it.
You need to check the CPUID flag to know for sure (/proc/cpuinfo will
show a "clflush" flag if it is supported).

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Mon, Feb 19, 2007 at 11:48:27AM -0800, Roland Dreier wrote:
>  > Does anyone know if there is any way to flush a cache line of the cpu to
>  > force rereading system memory for a given address or address range?
> 
> There is the "clflush" instruction, but not all x86 CPUs support it.
> You need to check the CPUID flag to know for sure (/proc/cpuinfo will
> show a "clflush" flag if it is supported).

Well I will check for that.  Of course it is still possible that is it
actually the network chip screwing up somehow.

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[takada]

From: Roland Dreier <rdreier@cisco.com>
Subject: Re: MediaGX/GeodeGX1 requires X86_OOSTORE.
Date: Mon, 19 Feb 2007 11:48:27 -0800

>  > Does anyone know if there is any way to flush a cache line of the cpu to
>  > force rereading system memory for a given address or address range?
> 
> There is the "clflush" instruction, but not all x86 CPUs support it.
> You need to check the CPUID flag to know for sure (/proc/cpuinfo will
> show a "clflush" flag if it is supported).

/proc/cpuinfo with MediaGXm :

processor	: 0
vendor_id	: CyrixInstead
cpu family	: 5
model		: 5
model name	: Cyrix MediaGXtm MMXtm Enhanced
stepping	: 2
cpu MHz		: 199.750
cache size	: 16 KB
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 2
wp		: yes
flags		: fpu tsc msr cx8 cmov mmx cxmmx
bogomips	: 401.00
clflush size	: 32

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Tue, Feb 20, 2007 at 08:56:39AM +0900, takada wrote:
> /proc/cpuinfo with MediaGXm :
> 
> processor	: 0
> vendor_id	: CyrixInstead
> cpu family	: 5
> model		: 5
> model name	: Cyrix MediaGXtm MMXtm Enhanced
> stepping	: 2
> cpu MHz		: 199.750
> cache size	: 16 KB
> fdiv_bug	: no
> hlt_bug		: no
> f00f_bug	: no
> coma_bug	: no
> fpu		: yes
> fpu_exception	: yes
> cpuid level	: 2
> wp		: yes
> flags		: fpu tsc msr cx8 cmov mmx cxmmx
> bogomips	: 401.00
> clflush size	: 32

Hmm with 2.6.18 I am seeing:

processor       : 0
vendor_id       : CyrixInstead
cpu family      : 5
model           : 9
model name      : Geode(TM) Integrated Processor by National Semi
stepping        : 1
cpu MHz         : 266.648
cache size      : 16 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 2
wp              : yes
flags           : fpu tsc msr cx8 cmov mmx cxmmx
bogomips        : 534.50

Similar, but the last line isn't there.  It looks like 2.6.18 doesn't
actually have code to print that information though.

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[takada]

From: lsorense@csclub.uwaterloo.ca (Lennart Sorensen)
Subject: Re: MediaGX/GeodeGX1 requires X86_OOSTORE.
Date: Mon, 19 Feb 2007 19:02:31 -0500

> On Tue, Feb 20, 2007 at 08:56:39AM +0900, takada wrote:
> > /proc/cpuinfo with MediaGXm :

  :

> > flags		: fpu tsc msr cx8 cmov mmx cxmmx
> > bogomips	: 401.00
> > clflush size	: 32
> 
> Hmm with 2.6.18 I am seeing:

I posted with 2.6.20 + enabled X86_OOSTORE.
The clflush sze line is in /proc/cpuinfo. but clfush is not in flags line.

BTW, can we use WBINVD instruction? I tested compile only.
Do you know a method to change dynamically without #ifdef when it works
with MediaGX/GeodeGX.

diff -Narup a/include/asm-i386/io.h b/include/asm-i386/io.h
--- a/include/asm-i386/io.h	2007-02-20 16:23:25.000000000 +0900
+++ b/include/asm-i386/io.h	2007-02-20 17:07:14.000000000 +0900
@@ -232,7 +232,19 @@ static inline void memcpy_toio(volatile 
  *	2. Accidentally out of order processors (PPro errata #51)
  */
  
-#if defined(CONFIG_X86_OOSTORE) || defined(CONFIG_X86_PPRO_FENCE)
+#ifdef CONFIG_MGEODEGX1
+
+static inline void dma_flush_cache(void)
+{
+	__asm__ __volatile__ ("wbinvd": : :"memory");
+}
+
+#define dma_cache_inv(_start,_size)		dma_flush_cache()
+#define dma_cache_wback(_start,_size)		dma_flush_cache()
+#define dma_cache_wback_inv(_start,_size)	dma_flush_cache()
+#define flush_write_buffers()
+
+#elif defined(CONFIG_X86_OOSTORE) || defined(CONFIG_X86_PPRO_FENCE)
 
 static inline void flush_write_buffers(void)
 {

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Tue, Feb 20, 2007 at 08:34:13PM +0900, takada wrote:
> I posted with 2.6.20 + enabled X86_OOSTORE.
> The clflush sze line is in /proc/cpuinfo. but clfush is not in flags line.
> 
> BTW, can we use WBINVD instruction? I tested compile only.
> Do you know a method to change dynamically without #ifdef when it works
> with MediaGX/GeodeGX.
> 
> diff -Narup a/include/asm-i386/io.h b/include/asm-i386/io.h
> --- a/include/asm-i386/io.h	2007-02-20 16:23:25.000000000 +0900
> +++ b/include/asm-i386/io.h	2007-02-20 17:07:14.000000000 +0900
> @@ -232,7 +232,19 @@ static inline void memcpy_toio(volatile 
>   *	2. Accidentally out of order processors (PPro errata #51)
>   */
>   
> -#if defined(CONFIG_X86_OOSTORE) || defined(CONFIG_X86_PPRO_FENCE)
> +#ifdef CONFIG_MGEODEGX1
> +
> +static inline void dma_flush_cache(void)
> +{
> +	__asm__ __volatile__ ("wbinvd": : :"memory");
> +}
> +
> +#define dma_cache_inv(_start,_size)		dma_flush_cache()
> +#define dma_cache_wback(_start,_size)		dma_flush_cache()
> +#define dma_cache_wback_inv(_start,_size)	dma_flush_cache()
> +#define flush_write_buffers()
> +
> +#elif defined(CONFIG_X86_OOSTORE) || defined(CONFIG_X86_PPRO_FENCE)
>  
>  static inline void flush_write_buffers(void)
>  {
> -

Well it is starting to look like it isn't a caching issue, but more
likely an issue of which order writes are performed in.  I think the MAC
might be seeing the ownership bit change before the rest of the
descriptor, which shouldn't happen.  With X86_OOSTORE, wmb() is called
between setting the fields in the descriptor and setting the ownership
bit to the MAC.  I still have to investigate a bit more to find out for
sure, but that could certainly explain why X86_OOSTORE makes the problem
become much less frequent.  It doesn't completely elliminate it though.
Of course maybe there are two different problems with the same symptoms.

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[takada]

From: lsorense@csclub.uwaterloo.ca (Lennart Sorensen)
Subject: Re: MediaGX/GeodeGX1 requires X86_OOSTORE.
Date: Tue, 20 Feb 2007 09:48:23 -0500

Hiroshi Miura posted `Geode out-of-order store enables' patch in Jun, 2003.
There is http://lkml.org/lkml/2003/6/5/57 .
OOSTORE was enabled at this point in time. It seems to have disappeared somewhere.

BTW, I use MediaGX with kernel 2.6.20(and 2.6.20.3) and suspend2. When I resume 
the PC and use the PC Card modem, PC is hungup. However, PC isn't hung up when
I apply a WBINVD patch.
I can't understand it whether there is problem in resume of suspend2 or MediaGX
or both. Many drivers lack support for resume on my PC.

> On Tue, Feb 20, 2007 at 08:34:13PM +0900, takada wrote:
> > I posted with 2.6.20 + enabled X86_OOSTORE.
> > The clflush sze line is in /proc/cpuinfo. but clfush is not in flags line.
> > 
> > BTW, can we use WBINVD instruction? I tested compile only.
> > Do you know a method to change dynamically without #ifdef when it works
> > with MediaGX/GeodeGX.
> > 
> > diff -Narup a/include/asm-i386/io.h b/include/asm-i386/io.h
> > --- a/include/asm-i386/io.h	2007-02-20 16:23:25.000000000 +0900
> > +++ b/include/asm-i386/io.h	2007-02-20 17:07:14.000000000 +0900
> > @@ -232,7 +232,19 @@ static inline void memcpy_toio(volatile 
> >   *	2. Accidentally out of order processors (PPro errata #51)
> >   */
> >   
> > -#if defined(CONFIG_X86_OOSTORE) || defined(CONFIG_X86_PPRO_FENCE)
> > +#ifdef CONFIG_MGEODEGX1
> > +
> > +static inline void dma_flush_cache(void)
> > +{
> > +	__asm__ __volatile__ ("wbinvd": : :"memory");
> > +}
> > +
> > +#define dma_cache_inv(_start,_size)		dma_flush_cache()
> > +#define dma_cache_wback(_start,_size)		dma_flush_cache()
> > +#define dma_cache_wback_inv(_start,_size)	dma_flush_cache()
> > +#define flush_write_buffers()
> > +
> > +#elif defined(CONFIG_X86_OOSTORE) || defined(CONFIG_X86_PPRO_FENCE)
> >  
> >  static inline void flush_write_buffers(void)
> >  {
> > -
> 
> Well it is starting to look like it isn't a caching issue, but more
> likely an issue of which order writes are performed in.  I think the MAC
> might be seeing the ownership bit change before the rest of the
> descriptor, which shouldn't happen.  With X86_OOSTORE, wmb() is called
> between setting the fields in the descriptor and setting the ownership
> bit to the MAC.  I still have to investigate a bit more to find out for
> sure, but that could certainly explain why X86_OOSTORE makes the problem
> become much less frequent.  It doesn't completely elliminate it though.
> Of course maybe there are two different problems with the same symptoms.
> 
> --
> Len Sorensen
> -
> 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/
> 

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Thu, Mar 15, 2007 at 02:39:39PM +0900, takada wrote:
> Hiroshi Miura posted `Geode out-of-order store enables' patch in Jun, 2003.
> There is http://lkml.org/lkml/2003/6/5/57 .
> OOSTORE was enabled at this point in time. It seems to have disappeared somewhere.

I believe the patch was rejected as 'not required' since the data sheet
is not very clear on that "feature".

> BTW, I use MediaGX with kernel 2.6.20(and 2.6.20.3) and suspend2. When I resume 
> the PC and use the PC Card modem, PC is hungup. However, PC isn't hung up when
> I apply a WBINVD patch.
> I can't understand it whether there is problem in resume of suspend2 or MediaGX
> or both. Many drivers lack support for resume on my PC.

Which patch are you refering to?

--
Len Sorensen

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[takada]

From: lsorense@csclub.uwaterloo.ca (Lennart Sorensen)
Subject: Re: MediaGX/GeodeGX1 requires X86_OOSTORE.
Date: Thu, 15 Mar 2007 13:31:37 -0400

> On Thu, Mar 15, 2007 at 02:39:39PM +0900, takada wrote:
> > Hiroshi Miura posted `Geode out-of-order store enables' patch in Jun, 2003.
> > There is http://lkml.org/lkml/2003/6/5/57 .
> > OOSTORE was enabled at this point in time. It seems to have disappeared somewhere.
> 
> I believe the patch was rejected as 'not required' since the data sheet
> is not very clear on that "feature".

Is it http://lkml.org/lkml/2003/6/5/85 you mean?
It seems not to be surely written in data sheet that OOSTORE is necessary. But Geode
reorder memory access.

> > BTW, I use MediaGX with kernel 2.6.20(and 2.6.20.3) and suspend2. When I resume 
> > the PC and use the PC Card modem, PC is hungup. However, PC isn't hung up when
> > I apply a WBINVD patch.
> > I can't understand it whether there is problem in resume of suspend2 or MediaGX
> > or both. Many drivers lack support for resume on my PC.
> 
> Which patch are you refering to?

I tested some patterns. just X86_OOSTORE was effective. WBINVD is needless.

--- arch/i386/Kconfig.cpu~	2007-02-05 03:44:54.000000000 +0900
+++ arch/i386/Kconfig.cpu	2007-02-17 21:25:52.000000000 +0900
@@ -322,7 +322,7 @@ config X86_USE_3DNOW
 
 config X86_OOSTORE
 	bool
-	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR
+	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR || MGEODEGX1
 	default y
 
 config X86_TSC

Re: MediaGX/GeodeGX1 requires X86_OOSTORE.

[Lennart Sorensen]

On Sat, Mar 17, 2007 at 10:08:10PM +0900, takada wrote:
> I tested some patterns. just X86_OOSTORE was effective. WBINVD is needless.
> 
> --- arch/i386/Kconfig.cpu~	2007-02-05 03:44:54.000000000 +0900
> +++ arch/i386/Kconfig.cpu	2007-02-17 21:25:52.000000000 +0900
> @@ -322,7 +322,7 @@ config X86_USE_3DNOW
>  
>  config X86_OOSTORE
>  	bool
> -	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR
> +	depends on (MWINCHIP3D || MWINCHIP2 || MWINCHIPC6) && MTRR || MGEODEGX1
>  	default y
>  
>  config X86_TSC

Well that is exactly what I did for the Geode SC1200 (a GX1 based
design) as well and it certainly improved things a lot for me as well.

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Fri, Feb 16, 2007 at 04:01:57PM -0500, Lennart Sorensen wrote:
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: pcnet32_poll: pcnet32_rx() got 16 packets
> eth1: base: 0x05215812 status: 0310 next->status: 0310
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: netif_receive_skb(skb)
> eth1: pcnet32_poll: pcnet32_rx() got 16 packets
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x6f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0033, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> eth1: interrupt  csr0=0x4f3 new csr=0x33, csr3=0x0000.
> eth1: exiting interrupt, csr0=0x0433, csr3=0x5f00.
> eth1: base: 0x04c51812 status: ffff8000 next->status: 0310
> eth1: pcnet32_poll: pcnet32_rx() got 0 packets
> 
> So somehow it ends up that when it reads the status of the descriptor at
> address 0x04c51812, it sees the status as 0x8000 (which means owned by
> the MAC I believe), even though the next descriptor in the ring has a
> sensible status, indicating that the descriptor is ready to be handled
> by the driver.  Since the descriptor isn't ready, we exit without
> handling anything and NAPI reschedules is the next time we get an
> interrupt, and after some random number of tries, we finally see the
> right status and handle the packet, along with a bunch of other packets
> waiting in the descriptor ring.  Then we seem to hit the exact same
> descriptor address again, with the same problem in the status we read,
> and again we are stuck for a while, until finally we see the right
> status, and another pile of packets get handled, and we again hit the
> same descriptor address and get stuck.

I have been poking at things with firescope to see if the MAC is
actually writing to system memory or not.

The entry that it gets stuch on is _always_ entry 0 in the rx_ring.
There does not appear to be any exceptions to this.  

Here is my firescope (slightly modified for this purpose) dump of the
rx_ring of eth1:

Descriptor:Address: /--base---\ /buf\ /sta\ /-message-\ /reserved-\
          :       : |         | |len| |tus| | length  | |         |
RXdesc[00]:6694000: 12 18 5f 05 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[01]:6694010: 12 78 15 05 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[02]:6694020: 12 a0 52 06 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[03]:6694030: 12 f8 c2 04 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[04]:6694040: 12 70 15 05 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[05]:6694050: 12 e8 37 05 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[06]:6694060: 12 e0 37 05 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[07]:6694070: 12 e8 d5 04 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[08]:6694080: 12 e0 d5 04 fa f9 40 03 ee 05 00 00 00 00 00 00
RXdesc[09]:6694090: 12 d8 d1 05 fa f9 40 03 46 00 00 00 00 00 00 00
RXdesc[10]:66940a0: 12 d0 d1 05 fa f9 40 03 4e 00 00 00 00 00 00 00
RXdesc[11]:66940b0: 12 d8 02 05 fa f9 10 03 40 00 00 00 00 00 00 00
RXdesc[12]:66940c0: 12 d0 02 05 fa f9 40 03 46 00 00 00 00 00 00 00
RXdesc[13]:66940d0: 12 38 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[14]:66940e0: 12 30 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[15]:66940f0: 12 78 2c 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[16]:6694100: 12 a0 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[17]:6694110: 12 b0 04 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[18]:6694120: 12 b8 04 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[19]:6694130: 12 70 2c 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[20]:6694140: 12 f8 56 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[21]:6694150: 12 c8 29 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[22]:6694160: 12 20 03 05 fa f9 00 80 ee 05 00 00 00 00 00 00
RXdesc[23]:6694170: 12 60 4c 05 fa f9 00 80 87 05 00 00 00 00 00 00
RXdesc[24]:6694180: 12 98 53 05 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[25]:6694190: 12 b0 cc 04 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[26]:66941a0: 12 a8 3f 05 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[27]:66941b0: 12 58 e8 04 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[28]:66941c0: 12 b0 4d 06 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[29]:66941d0: 12 38 ef 04 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[30]:66941e0: 12 98 1f 05 fa f9 00 80 40 00 00 00 00 00 00 00
RXdesc[31]:66941f0: 12 28 f1 04 fa f9 00 80 40 00 00 00 00 00 00 00

I only ever see entry 0 as status 0080 (0x8000 which is owned by mac),
and this is while the driver is checking entry 0 every time it tries to
check for any waiting packets.

Running tcpdump while pinging gives the interesting result that some
packets are ariving out of order making it seem like the driver is
processing the packets out of order.  Perhaps the driver is wrong to be
looking at entry 0, and should be looking at entry 1 and is hence stuck
until the whole receive ring has been filled again?

15:06:04.112812 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 1
15:06:05.119799 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 2
15:06:05.120159 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 2
15:06:05.127045 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 1
15:06:06.119862 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 3
15:06:07.119921 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 4
15:06:08.119994 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 5
15:06:08.426400 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 3
15:06:08.427915 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 4
15:06:08.429033 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 5
15:06:09.120053 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 6
15:06:10.120109 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 7
15:06:10.705332 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 6
15:06:10.707258 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 7
15:06:11.120175 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 8
15:06:12.120233 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 9
15:06:13.120297 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 10
15:06:14.120359 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 11
15:06:14.120737 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 11
15:06:14.127064 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 8
15:06:14.127700 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 9
15:06:14.128268 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 10
15:06:15.120426 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 12
15:06:16.120484 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 13
15:06:16.120840 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 13
15:06:16.129476 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 12
15:06:17.120551 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 14
15:06:17.615429 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 14
15:06:18.120612 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 15
15:06:19.120672 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 16
15:06:19.748981 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 15
15:06:19.749976 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 16
15:06:20.120738 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 17
15:06:21.120799 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 18
15:06:22.120859 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 19
15:06:23.120926 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 20
15:06:24.120985 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 21
15:06:24.881809 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 17
15:06:24.882287 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 18
15:06:24.882578 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 19
15:06:24.883347 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 20
15:06:24.884158 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 21
15:06:25.129659 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 22

Does anyone see any reason why the driver would get into such a state
after a pile of traffic in a row?  So far I have only seen it when NAPI
is enabled, so I have to assume so far that it makes a difference to it.

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Mon, Feb 19, 2007 at 03:11:36PM -0500, Lennart Sorensen wrote:
> I have been poking at things with firescope to see if the MAC is
> actually writing to system memory or not.
> 
> The entry that it gets stuch on is _always_ entry 0 in the rx_ring.
> There does not appear to be any exceptions to this.  
> 
> Here is my firescope (slightly modified for this purpose) dump of the
> rx_ring of eth1:
> 
> Descriptor:Address: /--base---\ /buf\ /sta\ /-message-\ /reserved-\
>           :       : |         | |len| |tus| | length  | |         |
> RXdesc[00]:6694000: 12 18 5f 05 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[01]:6694010: 12 78 15 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[02]:6694020: 12 a0 52 06 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[03]:6694030: 12 f8 c2 04 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[04]:6694040: 12 70 15 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[05]:6694050: 12 e8 37 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[06]:6694060: 12 e0 37 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[07]:6694070: 12 e8 d5 04 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[08]:6694080: 12 e0 d5 04 fa f9 40 03 ee 05 00 00 00 00 00 00
> RXdesc[09]:6694090: 12 d8 d1 05 fa f9 40 03 46 00 00 00 00 00 00 00
> RXdesc[10]:66940a0: 12 d0 d1 05 fa f9 40 03 4e 00 00 00 00 00 00 00
> RXdesc[11]:66940b0: 12 d8 02 05 fa f9 10 03 40 00 00 00 00 00 00 00
> RXdesc[12]:66940c0: 12 d0 02 05 fa f9 40 03 46 00 00 00 00 00 00 00
> RXdesc[13]:66940d0: 12 38 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[14]:66940e0: 12 30 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[15]:66940f0: 12 78 2c 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[16]:6694100: 12 a0 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[17]:6694110: 12 b0 04 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[18]:6694120: 12 b8 04 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[19]:6694130: 12 70 2c 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[20]:6694140: 12 f8 56 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[21]:6694150: 12 c8 29 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[22]:6694160: 12 20 03 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> RXdesc[23]:6694170: 12 60 4c 05 fa f9 00 80 87 05 00 00 00 00 00 00
> RXdesc[24]:6694180: 12 98 53 05 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[25]:6694190: 12 b0 cc 04 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[26]:66941a0: 12 a8 3f 05 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[27]:66941b0: 12 58 e8 04 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[28]:66941c0: 12 b0 4d 06 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[29]:66941d0: 12 38 ef 04 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[30]:66941e0: 12 98 1f 05 fa f9 00 80 40 00 00 00 00 00 00 00
> RXdesc[31]:66941f0: 12 28 f1 04 fa f9 00 80 40 00 00 00 00 00 00 00
> 
> I only ever see entry 0 as status 0080 (0x8000 which is owned by mac),
> and this is while the driver is checking entry 0 every time it tries to
> check for any waiting packets.
> 
> Running tcpdump while pinging gives the interesting result that some
> packets are ariving out of order making it seem like the driver is
> processing the packets out of order.  Perhaps the driver is wrong to be
> looking at entry 0, and should be looking at entry 1 and is hence stuck
> until the whole receive ring has been filled again?
> 
> 15:06:04.112812 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 1
> 15:06:05.119799 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 2
> 15:06:05.120159 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 2
> 15:06:05.127045 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 1
> 15:06:06.119862 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 3
> 15:06:07.119921 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 4
> 15:06:08.119994 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 5
> 15:06:08.426400 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 3
> 15:06:08.427915 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 4
> 15:06:08.429033 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 5
> 15:06:09.120053 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 6
> 15:06:10.120109 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 7
> 15:06:10.705332 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 6
> 15:06:10.707258 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 7
> 15:06:11.120175 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 8
> 15:06:12.120233 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 9
> 15:06:13.120297 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 10
> 15:06:14.120359 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 11
> 15:06:14.120737 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 11
> 15:06:14.127064 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 8
> 15:06:14.127700 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 9
> 15:06:14.128268 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 10
> 15:06:15.120426 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 12
> 15:06:16.120484 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 13
> 15:06:16.120840 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 13
> 15:06:16.129476 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 12
> 15:06:17.120551 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 14
> 15:06:17.615429 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 14
> 15:06:18.120612 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 15
> 15:06:19.120672 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 16
> 15:06:19.748981 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 15
> 15:06:19.749976 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 16
> 15:06:20.120738 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 17
> 15:06:21.120799 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 18
> 15:06:22.120859 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 19
> 15:06:23.120926 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 20
> 15:06:24.120985 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 21
> 15:06:24.881809 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 17
> 15:06:24.882287 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 18
> 15:06:24.882578 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 19
> 15:06:24.883347 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 20
> 15:06:24.884158 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 21
> 15:06:25.129659 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 22
> 
> Does anyone see any reason why the driver would get into such a state
> after a pile of traffic in a row?  So far I have only seen it when NAPI
> is enabled, so I have to assume so far that it makes a difference to it.

With more beating of the driver, I have managed to see it fail in places
other than descriptor 0.  It is as if the MAC doesn't transfer the
descriptor to the system memory, although I am not yet sure if there is
packet loss involved involving retransmision or not.

I tried making this change as a test:

  static int pcnet32_rx(struct net_device *dev, int quota)
  {
          struct pcnet32_private *lp = dev->priv;
          int entry = lp->cur_rx & lp->rx_mod_mask;
+         int nextentry = (lp->cur_rx+1) & lp->rx_mod_mask;
          struct pcnet32_rx_head *rxp = &lp->rx_ring[entry];
+         struct pcnet32_rx_head *nextrxp = &lp->rx_ring[nextentry];
          int npackets = 0;

+         /* Check for confused MAC and resync if necesary */
+         if ((short)le16_to_cpu(rxp->status) < 0 && (short)le16_to_cpu(nextrxp->status) >= 0) {
+                 entry = (++lp->cur_rx) & lp->rx_mod_mask;
+                 rxp = &lp->rx_ring[entry];
+                 printk("%s: rx_ring bugfix on entry %d\n",dev->name,entry);
+         }

          /* If we own the next entry, it's a new packet. Send it up. */
          while (quota > npackets && (short)le16_to_cpu(rxp->status) >= 0) {
                  pcnet32_rx_entry(dev, lp, rxp, entry);
                  npackets += 1;
                  /*
                   * The docs say that the buffer length isn't touched, but Andrew
                   * Boyd of QNX reports that some revs of the 79C965 clear it.
                   */
                  rxp->buf_length = le16_to_cpu(2 - PKT_BUF_SZ);
                  wmb();  /* Make sure owner changes after others are visible */
                  rxp->status = le16_to_cpu(0x8000);
                  entry = (++lp->cur_rx) & lp->rx_mod_mask;
                  rxp = &lp->rx_ring[entry];
          }

          return npackets;
  }

Now this really can't be a solution.  It still occationally gets "stuck"
for a short time, but with this change it manages to recover again but
it does seem to be hitting by printk once in a while.  I am starting to
wonder of the PCI transfers are failing once in a while.  I still can't
figure out what NAPI is doing different unless some of the pcnet32_rx
code should be run with interrupts disabled and isn't in NAPI mode.

eth1: rx_ring bugfix on entry 28
eth1: rx_ring bugfix on entry 15
eth1: rx_ring bugfix on entry 31
eth1: rx_ring bugfix on entry 2
eth1: rx_ring bugfix on entry 23
eth1: rx_ring bugfix on entry 25
eth1: rx_ring bugfix on entry 2
eth1: rx_ring bugfix on entry 21
eth1: rx_ring bugfix on entry 24
eth1: rx_ring bugfix on entry 27
eth1: rx_ring bugfix on entry 28
eth1: rx_ring bugfix on entry 23
eth1: rx_ring bugfix on entry 11
eth1: rx_ring bugfix on entry 28
eth1: rx_ring bugfix on entry 27
eth1: rx_ring bugfix on entry 24
eth1: rx_ring bugfix on entry 28
eth1: rx_ring bugfix on entry 17

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Mon, Feb 19, 2007 at 05:18:45PM -0500, Lennart Sorensen wrote:
> On Mon, Feb 19, 2007 at 03:11:36PM -0500, Lennart Sorensen wrote:
> > I have been poking at things with firescope to see if the MAC is
> > actually writing to system memory or not.
> > 
> > The entry that it gets stuch on is _always_ entry 0 in the rx_ring.
> > There does not appear to be any exceptions to this.  
> > 
> > Here is my firescope (slightly modified for this purpose) dump of the
> > rx_ring of eth1:
> > 
> > Descriptor:Address: /--base---\ /buf\ /sta\ /-message-\ /reserved-\
> >           :       : |         | |len| |tus| | length  | |         |
> > RXdesc[00]:6694000: 12 18 5f 05 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[01]:6694010: 12 78 15 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[02]:6694020: 12 a0 52 06 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[03]:6694030: 12 f8 c2 04 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[04]:6694040: 12 70 15 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[05]:6694050: 12 e8 37 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[06]:6694060: 12 e0 37 05 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[07]:6694070: 12 e8 d5 04 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[08]:6694080: 12 e0 d5 04 fa f9 40 03 ee 05 00 00 00 00 00 00
> > RXdesc[09]:6694090: 12 d8 d1 05 fa f9 40 03 46 00 00 00 00 00 00 00
> > RXdesc[10]:66940a0: 12 d0 d1 05 fa f9 40 03 4e 00 00 00 00 00 00 00
> > RXdesc[11]:66940b0: 12 d8 02 05 fa f9 10 03 40 00 00 00 00 00 00 00
> > RXdesc[12]:66940c0: 12 d0 02 05 fa f9 40 03 46 00 00 00 00 00 00 00
> > RXdesc[13]:66940d0: 12 38 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[14]:66940e0: 12 30 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[15]:66940f0: 12 78 2c 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[16]:6694100: 12 a0 58 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[17]:6694110: 12 b0 04 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[18]:6694120: 12 b8 04 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[19]:6694130: 12 70 2c 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[20]:6694140: 12 f8 56 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[21]:6694150: 12 c8 29 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[22]:6694160: 12 20 03 05 fa f9 00 80 ee 05 00 00 00 00 00 00
> > RXdesc[23]:6694170: 12 60 4c 05 fa f9 00 80 87 05 00 00 00 00 00 00
> > RXdesc[24]:6694180: 12 98 53 05 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[25]:6694190: 12 b0 cc 04 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[26]:66941a0: 12 a8 3f 05 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[27]:66941b0: 12 58 e8 04 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[28]:66941c0: 12 b0 4d 06 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[29]:66941d0: 12 38 ef 04 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[30]:66941e0: 12 98 1f 05 fa f9 00 80 40 00 00 00 00 00 00 00
> > RXdesc[31]:66941f0: 12 28 f1 04 fa f9 00 80 40 00 00 00 00 00 00 00
> > 
> > I only ever see entry 0 as status 0080 (0x8000 which is owned by mac),
> > and this is while the driver is checking entry 0 every time it tries to
> > check for any waiting packets.
> > 
> > Running tcpdump while pinging gives the interesting result that some
> > packets are ariving out of order making it seem like the driver is
> > processing the packets out of order.  Perhaps the driver is wrong to be
> > looking at entry 0, and should be looking at entry 1 and is hence stuck
> > until the whole receive ring has been filled again?
> > 
> > 15:06:04.112812 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 1
> > 15:06:05.119799 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 2
> > 15:06:05.120159 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 2
> > 15:06:05.127045 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 1
> > 15:06:06.119862 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 3
> > 15:06:07.119921 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 4
> > 15:06:08.119994 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 5
> > 15:06:08.426400 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 3
> > 15:06:08.427915 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 4
> > 15:06:08.429033 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 5
> > 15:06:09.120053 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 6
> > 15:06:10.120109 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 7
> > 15:06:10.705332 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 6
> > 15:06:10.707258 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 7
> > 15:06:11.120175 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 8
> > 15:06:12.120233 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 9
> > 15:06:13.120297 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 10
> > 15:06:14.120359 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 11
> > 15:06:14.120737 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 11
> > 15:06:14.127064 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 8
> > 15:06:14.127700 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 9
> > 15:06:14.128268 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 10
> > 15:06:15.120426 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 12
> > 15:06:16.120484 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 13
> > 15:06:16.120840 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 13
> > 15:06:16.129476 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 12
> > 15:06:17.120551 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 14
> > 15:06:17.615429 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 14
> > 15:06:18.120612 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 15
> > 15:06:19.120672 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 16
> > 15:06:19.748981 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 15
> > 15:06:19.749976 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 16
> > 15:06:20.120738 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 17
> > 15:06:21.120799 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 18
> > 15:06:22.120859 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 19
> > 15:06:23.120926 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 20
> > 15:06:24.120985 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 21
> > 15:06:24.881809 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 17
> > 15:06:24.882287 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 18
> > 15:06:24.882578 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 19
> > 15:06:24.883347 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 20
> > 15:06:24.884158 IP 10.128.10.1 > 10.128.10.254: icmp 64: echo reply seq 21
> > 15:06:25.129659 IP 10.128.10.254 > 10.128.10.1: icmp 64: echo request seq 22
> > 
> > Does anyone see any reason why the driver would get into such a state
> > after a pile of traffic in a row?  So far I have only seen it when NAPI
> > is enabled, so I have to assume so far that it makes a difference to it.
> 
> With more beating of the driver, I have managed to see it fail in places
> other than descriptor 0.  It is as if the MAC doesn't transfer the
> descriptor to the system memory, although I am not yet sure if there is
> packet loss involved involving retransmision or not.
> 
> I tried making this change as a test:
> 
>   static int pcnet32_rx(struct net_device *dev, int quota)
>   {
>           struct pcnet32_private *lp = dev->priv;
>           int entry = lp->cur_rx & lp->rx_mod_mask;
> +         int nextentry = (lp->cur_rx+1) & lp->rx_mod_mask;
>           struct pcnet32_rx_head *rxp = &lp->rx_ring[entry];
> +         struct pcnet32_rx_head *nextrxp = &lp->rx_ring[nextentry];
>           int npackets = 0;
> 
> +         /* Check for confused MAC and resync if necesary */
> +         if ((short)le16_to_cpu(rxp->status) < 0 && (short)le16_to_cpu(nextrxp->status) >= 0) {
> +                 entry = (++lp->cur_rx) & lp->rx_mod_mask;
> +                 rxp = &lp->rx_ring[entry];
> +                 printk("%s: rx_ring bugfix on entry %d\n",dev->name,entry);
> +         }
> 
>           /* If we own the next entry, it's a new packet. Send it up. */
>           while (quota > npackets && (short)le16_to_cpu(rxp->status) >= 0) {
>                   pcnet32_rx_entry(dev, lp, rxp, entry);
>                   npackets += 1;
>                   /*
>                    * The docs say that the buffer length isn't touched, but Andrew
>                    * Boyd of QNX reports that some revs of the 79C965 clear it.
>                    */
>                   rxp->buf_length = le16_to_cpu(2 - PKT_BUF_SZ);
>                   wmb();  /* Make sure owner changes after others are visible */
>                   rxp->status = le16_to_cpu(0x8000);
>                   entry = (++lp->cur_rx) & lp->rx_mod_mask;
>                   rxp = &lp->rx_ring[entry];
>           }
> 
>           return npackets;
>   }
> 
> Now this really can't be a solution.  It still occationally gets "stuck"
> for a short time, but with this change it manages to recover again but
> it does seem to be hitting by printk once in a while.  I am starting to
> wonder of the PCI transfers are failing once in a while.  I still can't
> figure out what NAPI is doing different unless some of the pcnet32_rx
> code should be run with interrupts disabled and isn't in NAPI mode.
> 
> eth1: rx_ring bugfix on entry 28
> eth1: rx_ring bugfix on entry 15
> eth1: rx_ring bugfix on entry 31
> eth1: rx_ring bugfix on entry 2
> eth1: rx_ring bugfix on entry 23
> eth1: rx_ring bugfix on entry 25
> eth1: rx_ring bugfix on entry 2
> eth1: rx_ring bugfix on entry 21
> eth1: rx_ring bugfix on entry 24
> eth1: rx_ring bugfix on entry 27
> eth1: rx_ring bugfix on entry 28
> eth1: rx_ring bugfix on entry 23
> eth1: rx_ring bugfix on entry 11
> eth1: rx_ring bugfix on entry 28
> eth1: rx_ring bugfix on entry 27
> eth1: rx_ring bugfix on entry 24
> eth1: rx_ring bugfix on entry 28
> eth1: rx_ring bugfix on entry 17

I just noticed, it seems almost all these problems occour right at the
start of transfers when the tcp window size is still being worked out
for the connection speed, and I am seeing the error count go up in
ifconfig for the port when it happens too.  Is it possible for an error
to get flagged in a receive descriptor without the owner bit being
updated?

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Mon, Feb 19, 2007 at 05:29:20PM -0500, Lennart Sorensen wrote:
> I just noticed, it seems almost all these problems occour right at the
> start of transfers when the tcp window size is still being worked out
> for the connection speed, and I am seeing the error count go up in
> ifconfig for the port when it happens too.  Is it possible for an error
> to get flagged in a receive descriptor without the owner bit being
> updated?

It seems the problem actually occours when the receive descriptor ring
is full.  This seems to generate one (or sometimes more) descriptors in
the ring which claim to be owned by the MAC, but at the head of the
receive ring as far as the driver is concerned.  I see some note in the
driver about an SP3G chipset sometimes causing this.  How would one
identify this and clear such descriptors out of the way?  Getting stuck
until the next time the MAC gets around to the descriptor and overwrites
it is not good, since it causes delays, and out of order packets.

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Mon, Feb 19, 2007 at 06:45:48PM -0500, Lennart Sorensen wrote:
> It seems the problem actually occours when the receive descriptor ring
> is full.  This seems to generate one (or sometimes more) descriptors in
> the ring which claim to be owned by the MAC, but at the head of the
> receive ring as far as the driver is concerned.  I see some note in the
> driver about an SP3G chipset sometimes causing this.  How would one
> identify this and clear such descriptors out of the way?  Getting stuck
> until the next time the MAC gets around to the descriptor and overwrites
> it is not good, since it causes delays, and out of order packets.

I am also noticing the receive error count going up, and the source is
this code:

if (status & 0x01)      /* Only count a general error at the */
       lp->stats.rx_errors++;  /* end of a packet. */

It appears this means I am receiving a frame marked with "End Of Packet"
but without "Start of Packet".  I have no idea how that happens, but it
shouldn't be able to make the driver and MAC stop processing the receive
ring.

--
Len Sorensen

Re: Re: Strange connection slowdown on pcnet32

[Lennart Sorensen]

On Mon, Feb 19, 2007 at 06:59:16PM -0500, Lennart Sorensen wrote:
> I am also noticing the receive error count going up, and the source is
> this code:
> 
> if (status & 0x01)      /* Only count a general error at the */
>        lp->stats.rx_errors++;  /* end of a packet. */
> 
> It appears this means I am receiving a frame marked with "End Of Packet"
> but without "Start of Packet".  I have no idea how that happens, but it
> shouldn't be able to make the driver and MAC stop processing the receive
> ring.

Well the packets actually have both start and end marked, but also have
overflow marked, so the cpu simply isn't keeping up it seems (It is
taking about 100% of the cpu to push through 6500KB/s).  Certainly the
CONFIG_X86_OOSTORE makes a major difference, although I am still not
sure why.  Simply skipping ahead one or two receive descriptors when the
current one is marked as owned by the MAC but the one a few ahead is
owned by the CPU allows it to continue receiving when it happens.  I
really want to find out why it happens though, although I am not sure
how to go about doing that.

--
Len Sorensen