r8169: page allocation failure

r8169: page allocation failure

[Jan Killius]

Hello,
I'm getting a page allocation failure under high net load.
Here is the error:
swapper: page allocation failure. order:3, mode:0x20
[<c013131e>]
[<c0131458>]
[<c0134337>]
[<c0134eaa>]
[<c013510d>]
[<c01354cc>]
[<c01ff9b2>]
[<c0204584>]
[<e09731b8>]
[<c020d9d5>]

This problem happens while a ftp transfer. The kernel version is 2.6.9-rc4 but 
I'm using the r8169 driver and the netdev snapshot from 2.6.9-rc4-mm1.

ethtool -k:
Offload parameters for eth2:
rx-checksumming: on
tx-checksumming: on
scatter-gather: on
tcp segmentation offload: on
-- 
        Jan

Re: r8169: page allocation failure

[Francois Romieu]

Jan Killius <jkillius@arcor.de> :
[...]
> Here is the error:
> swapper: page allocation failure. order:3, mode:0x20
> [<c013131e>]
> [<c0131458>]
> [<c0134337>]

It would be useful to map some of these adresses with the relevant
functions in your System.map.

[...]
> This problem happens while a ftp transfer. The kernel version is
> 2.6.9-rc4 but I'm using the r8169 driver and the netdev snapshot
> from 2.6.9-rc4-mm1.
> 
> ethtool -k:
> Offload parameters for eth2:
> rx-checksumming: on
> tx-checksumming: on
> scatter-gather: on
> tcp segmentation offload: on

The r8169 driver is not expected to allocate > 0 order pages until
the day it handles jumbo frames. Scary messages apart, how does the
system behave ?

--
Ueimor

Re: r8169: page allocation failure

[Jan Killius]

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

On Saturday 16 October 2004 21:54, you wrote:
> Jan Killius <jkillius@arcor.de> :
> [...]
>
> > I've tried to map them down but I didn't have any success. The adresses
> > weren't in my System.map.
>
> Were they not at least between two addresses in your System.map ?
Here is the first error I have attached my bzipped System.map
Oct 16 19:27:00 gate swapper: page allocation failure. order:3, mode:0x20
Oct 16 19:27:00 gate [<c013131e>]
Oct 16 19:27:00 gate [<c0131458>]
Oct 16 19:27:00 gate [<c0134337>]
Oct 16 19:27:00 gate [<c0134eaa>]
Oct 16 19:27:00 gate [<c013510d>]
Oct 16 19:27:00 gate [<c01354cc>]
Oct 16 19:27:00 gate [<c01ff1c0>]
Oct 16 19:27:00 gate [<c022d975>]
Oct 16 19:27:00 gate [<c022ddb2>]
Oct 16 19:27:00 gate [<c022eaa1>]
Oct 16 19:27:00 gate [<c022ec44>]
Oct 16 19:27:00 gate [<c0228f47>]
Oct 16 19:27:00 gate [<c022ba9e>]
Oct 16 19:27:00 gate [<c0234320>]
Oct 16 19:27:00 gate [<c0234a3e>]
Oct 16 19:27:00 gate [<c0219cf0>]
Oct 16 19:27:00 gate [<c0219d64>]
Oct 16 19:27:00 gate [<c020dd47>]
Oct 16 19:27:00 gate [<c0219cf0>]
Oct 16 19:27:00 gate [<c0219c54>]
Oct 16 19:27:00 gate [<c0219cf0>]
Oct 16 19:27:00 gate [<c021a478>]
Oct 16 19:27:00 gate [<c020d9d5>]
Oct 16 19:27:00 gate [<c021a2f0>]
Oct 16 19:27:00 gate [<c021a2f0>]
Oct 16 19:27:00 gate [<c020dd47>]
Oct 16 19:27:00 gate [<c021a2f0>]
Oct 16 19:27:00 gate [<c021a1f5>]
Oct 16 19:27:00 gate [<c021a2f0>]
Oct 16 19:27:00 gate [<c0106174>]
Oct 16 19:27:00 gate [<c0204e42>]
Oct 16 19:27:00 gate [<e087150c>]
Oct 16 19:27:00 gate [<e08715c0>]
Oct 16 19:27:00 gate [<e08717a4>]
Oct 16 19:27:00 gate [<c0205011>]
Oct 16 19:27:00 gate [<c011aae2>]
Oct 16 19:27:00 gate [<c011ab56>]
Oct 16 19:27:00 gate [<c0106516>]
Oct 16 19:27:00 gate [<c010454c>]
Oct 16 19:27:00 gate [<c0101d73>]
Oct 16 19:27:00 gate [<c0101ded>]
Oct 16 19:27:00 gate [<c02d677f>]
Oct 16 19:27:00 gate [<c02d6390>]

>
> [...]
>
> > The system is behaving normal, only the data rate is stagnating.
>
> Rate value and 'vmstat 1' for a few seconds during test would be
> welcome.
 1  0 131328  54876  15540  43616    0    0     0   132 33110  6424  0 93  7 0
 1  0 131328  54812  15540  43616    0    0     0     0 35681 18766  2 90  8 0
 1  0 131328  54428  15540  43616    0    0     0     0 35664 19280  0 91  9 0
 1  0 131328  53340  15540  43616    0    0     0     0 35668 18263  1 91  8 0
 1  0 131328  53404  15540  43616    0    0     0     0 35745 20324  2 90  8 0
 1  0 131328  53412  15540  43616    0    0     0     0 35688 20244  0 92  8 0
 2  0 131328  53412  15540  43616    0    0     0     0 34983 18064  1 89 10 0
 1  0 131328  53476  15540  43616    0    0     0     0 35373 20532  1 89 10 0
 1  0 131328  53404  15548  43616    0    0     8   140 35484 19244  1 89  9 1
 1  0 131328  53404  15548  43616    0    0     0     0 35221 20991  1 89 10 0
 1  0 131328  53388  15548  43616    0    0     0     0 35456 19485  1 91  8 0
 1  0 131328  53388  15556  43616    0    0     0    24 35547 20610  1 91  8 0
 2  0 131328  53388  15556  43616    0    0     0     0 35398 19624  1 90  9 0
 2  0 131328  53388  15556  43616    0    0     0     0 35610 19196  1 88 11 0
 1  0 131328  53452  15556  43616    0    0     0     0 35657 20496  1 89 10 0
 1  0 131328  53452  15556  43616    0    0     0     0 35834 20126  1 91  8 0
 1  0 131328  53452  15556  43616    0    0     0     0 35605 20334  1 92  7 0
 1  0 131328  53468  15556  43616    0    0     0     0 35819 20711  1 91  8 0
 2  0 131328  53468  15556  43616    0    0     0     0 35769 19753  1 77 22 0
 1  0 131328  53468  15556  43616    0    0     0     0 35810 21609  1 89 10 0
 1  0 131328  53404  15556  43616    0    0     0     0 35151 21286  0 90 10 0
 1  0 131328  53476  15556  43616    0    0     0     0 35508 21409  1 91  8 0
 1  0 131328  53476  15556  43616    0    0     0     0 35216 22581  1 89 10 0
 1  0 131328  53468  15572  43616    0    0     8    80 35276 20625  1 89 10 0
 2  0 131328  53212  15572  43616    0    0     0     0 36289 19173  2 90  8 0
 1  0 131328  45340  15572  43616    0    0     0     0 31957  9366 14 82  4 0
 2  0 131328  45404  15572  43616    0    0     0     0 35237 21628  1 90  9 0
 1  0 131328  45468  15572  43616    0    0     0     0 35666 21426  1 88 11 0
 1  0 131328  45276  15668  43708    0    0     0   272 35269 20345  1 90  9 0
 1  0 131328  45276  15668  43708    0    0     0     0 35348 21849  2 88 10 0
 1  0 131328  45276  15668  43708    0    0     0     0 35358 20267  1 89 10 0
 1  0 131328  45276  15668  43708    0    0     0     0 35449 20505  1 90  9 0
 1  0 131328  45284  15668  43708    0    0     0     0 35403 19478  0 91  9 0
 2  0 131328  45284  15676  43708    0    0     0   100 35653 20336  1 90  9 0
 1  0 131328  45284  15676  43708    0    0     0     0 35653 19626  2 88 10 0
 1  0 131328  45284  15676  43708    0    0     0     0 35545 20062  0 92  8 0
 1  0 131328  45220  15676  43708    0    0     0     0 35867 20312  1 92  7 0
 1  0 131328  45284  15676  43708    0    0     0     0 35410 18833  1 79 20 0
>
> <finger in the wind>
> Can you disable TSO and tell if the messages disappear ?
> </finger in the wind>
with TSO off there are no messages.
>
> > Now I have new errors:
> > eth2: Rx buffers exhausted
> > The system is still running and the network is functional too.
>
> You are running with NAPI enabled, right ?
Yes.
>
> Please, pretty please, keep the Cc: on netdev. It is archived and
> googlable whereas my mailbox is not.
sorry.
>
> --
> Ueimor

-- 
        Jan

[-- Attachment #2: System.map-2.6.9-rc4.bz2 --]
[-- Type: application/x-bzip2, Size: 150980 bytes --]

Re: r8169: page allocation failure

[Francois Romieu]

Jan Killius <jkillius@arcor.de> :
> On Saturday 16 October 2004 21:54, you wrote:
> > Jan Killius <jkillius@arcor.de> :
[...]
> Here is the first error I have attached my bzipped System.map
> Oct 16 19:27:00 gate swapper: page allocation failure. order:3, mode:0x20
> Oct 16 19:27:00 gate [<c013131e>]
> Oct 16 19:27:00 gate [<c0131458>]
> Oct 16 19:27:00 gate [<c0134337>]
> Oct 16 19:27:00 gate [<c0134eaa>]
> Oct 16 19:27:00 gate [<c013510d>]
> Oct 16 19:27:00 gate [<c01354cc>]
> Oct 16 19:27:00 gate [<c01ff1c0>]

c01ff130 T skb_under_panic
c01ff180 T alloc_skb
c01ff270 t skb_drop_fraglist

> Oct 16 19:27:00 gate [<c022d975>]
> Oct 16 19:27:00 gate [<c022ddb2>]

c022d8d0 T tcp_set_skb_tso_segs
c022d920 t tcp_fragment
c022dc70 t __pskb_trim_head

[...]
> > Rate value and 'vmstat 1' for a few seconds during test would be
> > welcome.
>  1  0 131328  54876  15540  43616    0    0     0   132 33110  6424  0 93  7 0
>  1  0 131328  54812  15540  43616    0    0     0     0 35681 18766  2 90  8 0
>  1  0 131328  54428  15540  43616    0    0     0     0 35664 19280  0 91  9 0
>  1  0 131328  53340  15540  43616    0    0     0     0 35668 18263  1 91  8 0
>  1  0 131328  53404  15540  43616    0    0     0     0 35745 20324  2 90  8 0

- what is the current transfer rate and is it better/worse w/o TSO ?
- which cpu/disk system are there within the (?) 128Mo box ?

I am not sure there is much to do. Lower the cache ? Suggestions anyone ?

[...]
> > <finger in the wind>
> > Can you disable TSO and tell if the messages disappear ?
> > </finger in the wind>
> with TSO off there are no messages.
> >
> > > Now I have new errors:
> > > eth2: Rx buffers exhausted
> > > The system is still running and the network is functional too.
> >
> > You are running with NAPI enabled, right ?
> Yes.

The system would probably not have recovered from Rx buffers
exhaustion otherwise. :o)

> > Please, pretty please, keep the Cc: on netdev. It is archived and
> > googlable whereas my mailbox is not.
> sorry.

No problem.

--
Ueimor

Re: r8169: page allocation failure

[Jan Killius]

> - what is the current transfer rate and is it better/worse w/o TSO ?
I'm getting almost the same with both settings ~405Mbit/s.
> - which cpu/disk system are there within the (?) 128Mo box ?
Athlon XP 1600+ the disk is a Maxtor 6Y060L0 gets with hdparm 42.76 MB/s

-- 
        Jan

Re: r8169: page allocation failure

[Jan Killius]

On Saturday 16 October 2004 23:04, Jan Killius wrote:
> > - what is the current transfer rate and is it better/worse w/o TSO ?
>
> I'm getting almost the same with both settings ~405Mbit/s.
>
> > - which cpu/disk system are there within the (?) 128Mo box ?
>
> Athlon XP 1600+ the disk is a Maxtor 6Y060L0 gets with hdparm 42.76 MB/s
ups forget to say the ram size 512MB FSB333 DDR RAM
-- 
        Jan

Re: r8169: page allocation failure

[Francois Romieu]

Jan Killius <jkillius@arcor.de> :
> On Saturday 16 October 2004 23:04, Jan Killius wrote:
> > > - what is the current transfer rate and is it better/worse w/o TSO ?
> >
> > I'm getting almost the same with both settings ~405Mbit/s.

Roughly the same CPU usage ?

> >
> > > - which cpu/disk system are there within the (?) 128Mo box ?
> >
> > Athlon XP 1600+ the disk is a Maxtor 6Y060L0 gets with hdparm 42.76 MB/s
> ups forget to say the ram size 512MB FSB333 DDR RAM

I did not notice it first but the bi/bo columns of the vmstat output
are mostly null. Assuming this is a single session ftp transfer, what ftp
software does the r8169 based system run ?

Pure curiosity: can you issue a test+vmstat with a blowfish scp to see if
TSO makes a difference for your setup when the system is not disk-limited ?

--
Ueimor

Re: r8169: page allocation failure

[Jan Killius]

On Saturday 16 October 2004 23:49, Francois Romieu wrote:
> Jan Killius <jkillius@arcor.de> :
> > On Saturday 16 October 2004 23:04, Jan Killius wrote:
> > > > - what is the current transfer rate and is it better/worse w/o TSO ?
> > >
> > > I'm getting almost the same with both settings ~405Mbit/s.
>
> Roughly the same CPU usage ?
I have tested the maximum transfer rate with netperf here makes TSO no 
difference in cpu usage.
>
> > > > - which cpu/disk system are there within the (?) 128Mo box ?
> > >
> > > Athlon XP 1600+ the disk is a Maxtor 6Y060L0 gets with hdparm 42.76
> > > MB/s
> >
> > ups forget to say the ram size 512MB FSB333 DDR RAM
>
> I did not notice it first but the bi/bo columns of the vmstat output
> are mostly null. Assuming this is a single session ftp transfer, what ftp
> software does the r8169 based system run ?
vsftpd
>
> Pure curiosity: can you issue a test+vmstat with a blowfish scp to see if
> TSO makes a difference for your setup when the system is not disk-limited ?
without TSO(1628MB  11.1MB/s   02:27):
 1  0 166388  27716    332  97264    0    0 12300     0 12323  7616 37 45  0 
18
 1  0 166388  26108    332  99804    0    0 12880     4 12727  7975 39 52  0 9
 1  0 166388  24612    336 102796    0    0 12720     0 12590  7900 38 48  0 
15
 1  0 166388  27644    332 100420    0    0  8232     0 8845  5517 27 30  2 40
 1  2 166388  27648    368 101024    0    0 11240     4 11705  7546 35 44  0 
21
 1  0 166388  26592    384 102536    0    0 12372    56 13001  8409 34 55  0 
11
 1  2 166388  25192    388 104424    0    0 12504     0 12428  7700 43 44  0 
13
 1  0 166388  25488    436 104424    0    0 10844    48 10900  6868 34 40  0 
27
 0  1 166388  25076    452 105200    0    0 11928     0 11949  7412 36 48  0 
17
 1  1 166388  24412    456 106108    0    0 12172    60 12225  7612 39 45  0 
15
with TSO(1628MB  12.8MB/s   02:07):
 1  0 166340  27672    376 120056    0    0 13740     0 11879  2041 36 58  6  
0
 1  0 166340  25352    384 122288    0    0 13968     4 12148  2072 41 55  3  
1
 1  0 166340  22924    376 124692    0    0 14028     0 12174  2050 36 60  4  
0
 1  0 166340  20896    368 126696    0    0 13644     0 11859  2016 39 54  7  
0
 0  0 166340  30792    352 116856    0    0 13328     0 11646  2013 36 56  8  
0
 1  0 166340  28440    332 119280    0    0 14156     0 12343  2063 37 59  2  
2
 1  3 166340  28120    348 119556    0    0 11936     4 10527  2329 32 49  4 
15
 1  3 166340  27728    456 119920    0    0 12152     4 10549  2516 31 52  0 
17
 2  0 166340  26600    492 120588    0    0 12216   208 10347  2274 37 48  0 
16
 0  2 166340  24344    572 122760    0    0 13900     0 11937  2217 37 58  0  
5

>
> --
> Ueimor

-- 
        Jan

Re: r8169: page allocation failure

[Herbert Xu]

Francois Romieu <romieu@fr.zoreil.com> wrote:
> 
>> Oct 16 19:27:00 gate [<c022d975>]
>> Oct 16 19:27:00 gate [<c022ddb2>]
> 
> c022d8d0 T tcp_set_skb_tso_segs
> c022d920 t tcp_fragment
> c022dc70 t __pskb_trim_head

Good catch.  tcp_fragment's behaviour is broken when TSO is present.
We can start with a list of n 1-mss fragments and tcp_fragment will
end up allocating a continuous skb of n-1 mss bytes.

It should instead allocate a new skb of 1 mss.  I'll work on it.

Thanks,
-- 
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt

Re: r8169: page allocation failure

[Herbert Xu]

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

On Sun, Oct 17, 2004 at 05:47:52PM +1000, Herbert Xu wrote:
> 
> It should instead allocate a new skb of 1 mss.  I'll work on it.

In fact it was allocating space that it wasn't even using :)

The following patch makes it allocate skb_headlen(skb) - len instead
of skb->len - len.  When skb is linear there is no difference.  When
it's non-linear we only ever copy the bytes in the header.

Please let me know whether this fixes your problem.

Cheers,
-- 
Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <herbert@gondor.apana.org.au>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt

[-- Attachment #2: p --]
[-- Type: text/plain, Size: 431 bytes --]

===== net/ipv4/tcp_output.c 1.67 vs edited =====
--- 1.67/net/ipv4/tcp_output.c	2004-10-01 13:56:45 +10:00
+++ edited/net/ipv4/tcp_output.c	2004-10-17 18:58:47 +10:00
@@ -455,8 +455,12 @@
 {
 	struct tcp_opt *tp = tcp_sk(sk);
 	struct sk_buff *buff;
-	int nsize = skb->len - len;
+	int nsize;
 	u16 flags;
+
+	nsize = skb_headlen(skb) - len;
+	if (nsize < 0)
+		nsize = 0;
 
 	if (skb_cloned(skb) &&
 	    skb_is_nonlinear(skb) &&

Re: r8169: page allocation failure

[Jan Killius]

On Sunday 17 October 2004 11:08, Herbert Xu wrote:
> On Sun, Oct 17, 2004 at 05:47:52PM +1000, Herbert Xu wrote:
> > It should instead allocate a new skb of 1 mss.  I'll work on it.
>
> In fact it was allocating space that it wasn't even using :)
>
> The following patch makes it allocate skb_headlen(skb) - len instead
> of skb->len - len.  When skb is linear there is no difference.  When
> it's non-linear we only ever copy the bytes in the header.
>
> Please let me know whether this fixes your problem.
Yes the patch solved the problem completely
>
> Cheers,

-- 
        Jan

Re: r8169: page allocation failure

[Francois Romieu]

Jan Killius <jkillius@arcor.de> :
[scp test]
> without TSO(1628MB  11.1MB/s   02:27):
>  1  0 166388  27716    332  97264    0    0 12300     0 12323  7616 37 45  0 18
>  1  0 166388  26108    332  99804    0    0 12880     4 12727  7975 39 52  0 9
>  1  0 166388  24612    336 102796    0    0 12720     0 12590  7900 38 48  0 15
[...]
> with TSO(1628MB  12.8MB/s   02:07):
>  1  0 166340  27672    376 120056    0    0 13740     0 11879  2041 36 58  6  0
>  1  0 166340  25352    384 122288    0    0 13968     4 12148  2072 41 55  3  1
>  1  0 166340  22924    376 124692    0    0 14028     0 12174  2050 36 60  4  0

It could be done again now that M. Xu fixed the issue but the numbers seem
consistent with the improvement I see here. TSO saves 5~8% of the cpu for
this kind of setup.

Thanks for the testing.

--
Ueimor

Re: r8169: page allocation failure

[David S. Miller]

On Sun, 17 Oct 2004 19:08:37 +1000
Herbert Xu <herbert@gondor.apana.org.au> wrote:

> On Sun, Oct 17, 2004 at 05:47:52PM +1000, Herbert Xu wrote:
> > 
> > It should instead allocate a new skb of 1 mss.  I'll work on it.
> 
> In fact it was allocating space that it wasn't even using :)
> 
> The following patch makes it allocate skb_headlen(skb) - len instead
> of skb->len - len.  When skb is linear there is no difference.  When
> it's non-linear we only ever copy the bytes in the header.
> 
> Please let me know whether this fixes your problem.

Looks great, good catch.  Patch applied.