page allocation failures in mv643xx_eth_poll (was Re: Swapper problems?)
Did anyone figure this one out? I'm getting these regularly on
my Sheevaplug. I have a cron job that runs every 4 hours running
tar to create a ~1.5gb backup file. Sometimes (every few days)
it causes the following dmesg output:
Nov 22 12:01:36 chaos kernel: [1360924.210000] tar: page allocation failure. order:1, mode:0x20
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c002cd68>] (unwind_backtrace+0x0/0xdc) from [<c00906b0>] (__alloc_pages_internal+0x3c0/0x3e4)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c00906b0>] (__alloc_pages_internal+0x3c0/0x3e4) from [<c00acdc4>] (cache_alloc_refill+0x268/0x528)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c00acdc4>] (cache_alloc_refill+0x268/0x528) from [<c00ad1ec>] (kmem_cache_alloc+0x50/0xdc)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c00ad1ec>] (kmem_cache_alloc+0x50/0xdc) from [<c0205ce0>] (sk_prot_alloc+0x28/0xe8)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0205ce0>] (sk_prot_alloc+0x28/0xe8) from [<c0206190>] (sk_clone+0x14/0x1d0)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0206190>] (sk_clone+0x14/0x1d0) from [<c023e2c4>] (inet_csk_clone+0x14/0x98)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c023e2c4>] (inet_csk_clone+0x14/0x98) from [<c0253704>] (tcp_create_openreq_child+0x18/0x340)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0253704>] (tcp_create_openreq_child+0x18/0x340) from [<c0252854>] (tcp_v4_syn_recv_sock+0x4c/0x208)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0252854>] (tcp_v4_syn_recv_sock+0x4c/0x208) from [<c0253528>] (tcp_check_req+0x254/0x418)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0253528>] (tcp_check_req+0x254/0x418) from [<c0251ab8>] (tcp_v4_do_rcv+0x218/0x348)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0251ab8>] (tcp_v4_do_rcv+0x218/0x348) from [<c02520dc>] (tcp_v4_rcv+0x4f4/0x7e0)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c02520dc>] (tcp_v4_rcv+0x4f4/0x7e0) from [<c02356c0>] (ip_local_deliver_finish+0x190/0x274)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c02356c0>] (ip_local_deliver_finish+0x190/0x274) from [<c0235258>] (ip_rcv_finish+0x320/0x340)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0235258>] (ip_rcv_finish+0x320/0x340) from [<c02115cc>] (netif_receive_skb+0x538/0x584)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c02115cc>] (netif_receive_skb+0x538/0x584) from [<bf07a868>] (mv643xx_eth_poll+0x4d0/0x670 [mv643xx_eth])
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<bf07a868>] (mv643xx_eth_poll+0x4d0/0x670 [mv643xx_eth]) from [<c0211cec>] (net_rx_action+0x90/0x1c0)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0211cec>] (net_rx_action+0x90/0x1c0) from [<c0044d50>] (__do_softirq+0xa4/0x180)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0044d50>] (__do_softirq+0xa4/0x180) from [<c0044e6c>] (irq_exit+0x40/0x90)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0044e6c>] (irq_exit+0x40/0x90) from [<c0026054>] (_text+0x54/0x6c)
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0026054>] (_text+0x54/0x6c) from [<c0026a14>] (__irq_svc+0x34/0x80)
Nov 22 12:01:36 chaos kernel: [1360924.210000] Exception stack(0xda991a28 to 0xda991a70)
Nov 22 12:01:36 chaos kernel: [1360924.210000] 1a20: c5d01248 d6441948 d6441948 00000000 c3cda3c8 ded8d200
Nov 22 12:01:36 chaos kernel: [1360924.210000] 1a40: bf041bb6 c3cda3c8 00002694 d66a7748 c0e80440 d6441948 c788f240 da991a70
Nov 22 12:01:36 chaos kernel: [1360924.210000] 1a60: bf03ed94 bf01d374 60000013 ffffffff
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<c0026a14>] (__irq_svc+0x34/0x80) from [<bf03ed94>] (__ext3_journal_dirty_metadata+0x20/0x50 [ext3])
Nov 22 12:01:36 chaos kernel: [1360924.210000] [<bf03ed94>] (__ext3_journal_dirty_metadata+0x20/0x50 [ext3]) from [<00002694>] (0x2694)
Nov 22 12:01:36 chaos kernel: [1360924.210000] Mem-info:
Nov 22 12:01:36 chaos kernel: [1360924.210000] Normal per-cpu:
Nov 22 12:01:36 chaos kernel: [1360924.210000] CPU 0: hi: 186, btch: 31 usd: 78
Nov 22 12:01:36 chaos kernel: [1360924.210000] Active_anon:949 active_file:4664 inactive_anon:6816
Nov 22 12:01:36 chaos kernel: [1360924.210000] inactive_file:109966 unevictable:0 dirty:20769 writeback:1295 unstable:0
Nov 22 12:01:36 chaos kernel: [1360924.210000] free:1141 slab:3916 mapped:777 pagetables:251 bounce:0
Nov 22 12:01:36 chaos kernel: [1360924.210000] Normal free:4564kB min:2884kB low:3604kB high:4324kB active_anon:3796kB inactive_anon:27264kB active_file:18656kB inactive_file:439864kB unevictable:0kB present:520192kB pages_scanned:0 all_unreclaimable? no
Nov 22 12:01:36 chaos kernel: [1360924.210000] lowmem_reserve[]: 0 0
Nov 22 12:01:36 chaos kernel: [1360924.210000] Normal: 1095*4kB 5*8kB 3*16kB 1*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4564kB
Nov 22 12:01:36 chaos kernel: [1360924.210000] 114774 total pagecache pages
Nov 22 12:01:36 chaos kernel: [1360924.210000] 0 pages in swap cache
Nov 22 12:01:36 chaos kernel: [1360924.210000] Swap cache stats: add 0, delete 0, find 0/0
Nov 22 12:01:36 chaos kernel: [1360924.210000] Free swap = 979924kB
Nov 22 12:01:36 chaos kernel: [1360924.210000] Total swap = 979924kB
Nov 22 12:01:36 chaos kernel: [1360924.210000] 131072 pages of RAM
Nov 22 12:01:36 chaos kernel: [1360924.210000] 1422 free pages
Nov 22 12:01:36 chaos kernel: [1360924.210000] 2111 reserved pages
Nov 22 12:01:36 chaos kernel: [1360924.210000] 3916 slab pages
Nov 22 12:01:36 chaos kernel: [1360924.210000] 64911 pages shared
Nov 22 12:01:36 chaos kernel: [1360924.210000] 0 pages swap cached
I'm starting to suspect there may be a problem with some sheevaplug-specific
drivers (the mv643xx ethernet driver?), because I used to run exactly the
same configuration on an NSLU2 with only 32mb ram, and I never got these
page allocation failures. The stacktrace ALWAYS contains
tcp_v4_syn_recv_sock .... mv643xx_eth_poll ...
Strangely it looks like the tar process completes successfully, or at least
I can't remember seeing anything odd in the cron mail output.
Relevant output from 'sar -A':
00:00:01 kbmemfree kbmemused %memused kbbuffers kbcached kbswpfree kbswpused %swpused kbswpcad
11:15:01 384580 131308 25.45 34644 23604 979924 0 0.00 0
11:25:01 384084 131804 25.55 35000 23628 979924 0 0.00 0
11:35:01 336496 179392 34.77 36108 64632 979924 0 0.00 0
11:45:01 341180 174708 33.87 36328 64804 979924 0 0.00 0
11:55:02 331316 184572 35.78 36964 68464 979924 0 0.00 0
12:05:01 6808 509080 98.68 3652 457636 979924 0 0.00 0
12:15:01 390752 125136 24.26 31312 15220 979924 0 0.00 0
12:25:01 385028 130860 25.37 31876 23380 979924 0 0.00 0
I'm running latest debian lenny stable with kernel:
Linux version 2.6.30-2-kirkwood (Debian 2.6.30-8) (waldi@debian.org) (gcc version 4.3.4 (Debian 4.3.4-3) ) #1 Sun Sep 27 22:57:55 UTC 2009
On Sun, Aug 23, 2009 at 17:01:39 +0100, David Given wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> When my Sheevaplug has been under load, I've been occasionally been
> getting swapper page allocation failures (monster kernel log attached).
>
> What's particularly worrying about this is that the system's got a
> gigabyte of swap, and the log claims that it's all free. So why should
> it be behaving as if it's running out of memory? Given that I want to
> run Java on this machine, this could be an issue!
>
> This problem is, in fact, strikingly similar to recurrent issue on
> Debian on the NSLU2, where when the system was under heavy load the OOM
> killer would erroneously start nuking processes at random, regardless of
> the amount of available swap. Are there any known problems with the VM
> on ARM?
>
> I'm using:
>
> Linux chur 2.6.30-rc8-kirkwood #1 Wed Jun 3 22:03:05 UTC 2009 armv5tel
> GNU/Linux
>
> The swap is a file on a JFS partition on a RAID0 volume on USB, if that
> helps. I'm about to retry with 2.6.31-rc7 and see if that helps.
>
> Aug 22 03:50:31 chur kernel: [25651.180000] swapper: page allocation
> failure. order:1, mode:0x20
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c002bcec>]
> (unwind_backtrace+0x0/0xd4) from [<c008d6c8>]
> (__alloc_pages_internal+0x390/0x3ac)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c008d6c8>]
> (__alloc_pages_internal+0x390/0x3ac) from [<c00a9764>]
> (cache_alloc_refill+0x268/0x504)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c00a9764>]
> (cache_alloc_refill+0x268/0x504) from [<c00a9b64>]
> (kmem_cache_alloc+0x50/0xd8)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c00a9b64>]
> (kmem_cache_alloc+0x50/0xd8) from [<c01ffd58>] (sk_prot_alloc+0x24/0xc0)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c01ffd58>]
> (sk_prot_alloc+0x24/0xc0) from [<c02005a0>] (sk_clone+0x14/0x1c0)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c02005a0>]
> (sk_clone+0x14/0x1c0) from [<c02388d0>] (inet_csk_clone+0x14/0x9c)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c02388d0>]
> (inet_csk_clone+0x14/0x9c) from [<c024ccd0>]
> (tcp_create_openreq_child+0x18/0x338)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c024ccd0>]
> (tcp_create_openreq_child+0x18/0x338) from [<c024ad28>]
> (tcp_v4_syn_recv_sock+0x4c/0x1c0)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c024ad28>]
> (tcp_v4_syn_recv_sock+0x4c/0x1c0) from [<c024caec>]
> (tcp_check_req+0x250/0x41c)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c024caec>]
> (tcp_check_req+0x250/0x41c) from [<c024a4ac>] (tcp_v4_do_rcv+0x1cc/0x2f4)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c024a4ac>]
> (tcp_v4_do_rcv+0x1cc/0x2f4) from [<c024c768>] (tcp_v4_rcv+0x750/0x7bc)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c024c768>]
> (tcp_v4_rcv+0x750/0x7bc) from [<c022f650>]
> (ip_local_deliver_finish+0x1a0/0x270)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c022f650>]
> (ip_local_deliver_finish+0x1a0/0x270) from [<c022f490>]
> (ip_rcv_finish+0x348/0x368)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c022f490>]
> (ip_rcv_finish+0x348/0x368) from [<c020b69c>]
> (netif_receive_skb+0x54c/0x5a0)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c020b69c>]
> (netif_receive_skb+0x54c/0x5a0) from [<bf14e1c0>]
> (mv643xx_eth_poll+0x44c/0x5c8 [mv643xx_eth])
> Aug 22 03:50:31 chur kernel: [25651.180000] [<bf14e1c0>]
> (mv643xx_eth_poll+0x44c/0x5c8 [mv643xx_eth]) from [<c020e214>]
> (net_rx_action+0x98/0x194)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c020e214>]
> (net_rx_action+0x98/0x194) from [<c0043538>] (__do_softirq+0x98/0x160)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c0043538>]
> (__do_softirq+0x98/0x160) from [<c004381c>] (irq_exit+0x40/0x90)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c004381c>]
> (irq_exit+0x40/0x90) from [<c0025054>] (_text+0x54/0x6c)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c0025054>]
> (_text+0x54/0x6c) from [<c00259b4>] (__irq_svc+0x34/0x80)
> Aug 22 03:50:31 chur kernel: [25651.180000] Exception stack(0xc0369f40
> to 0xc0369f88)
> Aug 22 03:50:31 chur kernel: [25651.180000] 9f40: 000d0d2d 000003e8
> 00000000 4a8f5cf6 c036dd28 c036dd28 c0022ee8 c036bde8
> Aug 22 03:50:31 chur kernel: [25651.180000] 9f60: c036dd28 56251311
> c03edc00 00000000 32fb787f c0369f88 c0059e54 c002fb9c
> Aug 22 03:50:31 chur kernel: [25651.180000] 9f80: 20000013 ffffffff
>
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c00259b4>]
> (__irq_svc+0x34/0x80) from [<c0059e54>] (do_gettimeofday+0x28/0x34)
> Aug 22 03:50:31 chur kernel: [25651.180000] [<c0059e54>]
> (do_gettimeofday+0x28/0x34) from [<000d0c4d>] (0xd0c4d)
> Aug 22 03:50:31 chur kernel: [25651.180000] Mem-info:
> Aug 22 03:50:31 chur kernel: [25651.180000] Normal per-cpu:
> Aug 22 03:50:31 chur kernel: [25651.180000] CPU 0: hi: 186, btch:
> 31 usd: 167
> Aug 22 03:50:31 chur kernel: [25651.180000] Active_anon:2135
> active_file:43341 inactive_anon:5588
> Aug 22 03:50:31 chur kernel: [25651.180000] inactive_file:36610
> unevictable:0 dirty:17629 writeback:0 unstable:0
> Aug 22 03:50:31 chur kernel: [25651.180000] free:904 slab:37848
> mapped:2767 pagetables:182 bounce:0
> Aug 22 03:50:31 chur kernel: [25651.180000] Normal free:3616kB
> min:2884kB low:3604kB high:4324kB active_anon:8540kB
> inactive_anon:22352kB active_file:173364kB inactive_file:146440kB
> unevictable:0kB present:520192kB pages_scanned:0 all_unreclaimable? no
> Aug 22 03:50:31 chur kernel: [25651.180000] lowmem_reserve[]: 0 0
> Aug 22 03:50:31 chur kernel: [25651.180000] Normal: 870*4kB 1*8kB 2*16kB
> 1*32kB 1*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3616kB
> Aug 22 03:50:31 chur kernel: [25651.180000] 79978 total pagecache pages
> Aug 22 03:50:31 chur kernel: [25651.180000] 0 pages in swap cache
> Aug 22 03:50:31 chur kernel: [25651.180000] Swap cache stats: add 0,
> delete 0, find 0/0
> Aug 22 03:50:31 chur kernel: [25651.180000] Free swap = 1048568kB
> Aug 22 03:50:31 chur kernel: [25651.180000] Total swap = 1048568kB
> Aug 22 03:50:31 chur kernel: [25651.180000] 131072 pages of RAM
> Aug 22 03:50:31 chur kernel: [25651.180000] 1285 free pages
> Aug 22 03:50:31 chur kernel: [25651.180000] 2119 reserved pages
> Aug 22 03:50:31 chur kernel: [25651.180000] 37848 slab pages
> Aug 22 03:50:31 chur kernel: [25651.180000] 53987 pages shared
> Aug 22 03:50:31 chur kernel: [25651.180000] 0 pages swap cached
>
> - --
> ???????????? ?????????????????????????????????????????? ??????????????? http://www.cowlark.com ???????????????
> ???
> ??? "People who think they know everything really annoy those of us who
> ??? know we don't." --- Bjarne Stroustrup
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.9 (GNU/Linux)
> Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
>
> iD8DBQFKkWfjf9E0noFvlzgRAqGOAKCjhEFakjm7PZTID9Pt61lt9iaGzQCfVVZ7
> kYwAvi1S9tBS+o3hBg7xa+0=
> =vUgL
> -----END PGP SIGNATURE-----
>
>
> --
> To UNSUBSCRIBE, email to debian-arm-REQUEST@lists.debian.org
> with a subject of "unsubscribe". Trouble? Contact listmaster@lists.debian.org
Reply to: