2.6.14-rc5 e1000 and page allocation failures.. still

2.6.14-rc5 e1000 and page allocation failures.. still

[John Bäckstrand]

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

Im seeing a massive amount of page allocation failures with 2.6.14-rc5, 
and also earlier kernels, see "E1000 - page allocation failure - saga 
continues :(". Machine is a 1Ghz Athlon with 256MB RAM. Attached is 
example dmesg output. The stack traces come in many variants. Killing 
processes using RAM only seems to help temporarily. Ive also tried 
setting vm.min_free_kbytes=16384, which used to work pretty well, but 
this does not help (atleast not in the state the machine is currently 
in, without rebooting).

free currently gives:

              total       used       free     shared    buffers     cached
Mem:        256520     239128      17392          0       5372      67500
-/+ buffers/cache:     166256      90264
Swap:       506036      21248     484788


I havent yet tried rebooting and using the vm.min_free_kbytes=16384 from 
scratch, but I think something with the default for this is wrong if it 
results in this many page allocation errors. The machine is serving 
files from an encrypted partition with reiserfs on it, and I obivously 
use the e1000 driver.

---
John Bäckstrand

[-- Attachment #2: pagealloc.txt --]
[-- Type: text/plain, Size: 8447 bytes --]

[149649.847890] kcryptd/0: page allocation failure. order:3, mode:0x20
[149649.847945]  [<c01419d8>] __alloc_pages+0x318/0x440
[149649.848002]  [<c0144b0d>] kmem_getpages+0x2d/0xa0
[149649.848043]  [<c0141858>] __alloc_pages+0x198/0x440
[149649.848078]  [<c0145936>] cache_grow+0x96/0x1c0
[149649.848116]  [<c0145c99>] cache_alloc_refill+0x239/0x270
[149649.848156]  [<c0145fb3>] __kmalloc+0x73/0x80
[149649.848190]  [<c027300f>] __alloc_skb+0x5f/0x160
[149649.848233]  [<d099afcc>] e1000_alloc_rx_buffers+0x1dc/0x3a0 [e1000]
[149649.848318]  [<d099a81d>] e1000_clean_rx_irq+0x30d/0x480 [e1000]
[149649.848366]  [<d099afcc>] e1000_alloc_rx_buffers+0x1dc/0x3a0 [e1000]
[149649.848419]  [<d0999f5d>] e1000_intr+0x4d/0x100 [e1000]
[149649.848465]  [<c013b5cd>] handle_IRQ_event+0x3d/0x70
[149649.848512]  [<c013b65d>] __do_IRQ+0x5d/0xc0
[149649.848549]  [<c0105199>] do_IRQ+0x19/0x30
[149649.848590]  [<c0103a72>] common_interrupt+0x1a/0x20
[149649.848628]  [<c011f540>] __do_softirq+0x30/0x90
[149649.848676]  [<c011f5c6>] do_softirq+0x26/0x30
[149649.848710]  [<c010519e>] do_IRQ+0x1e/0x30
[149649.848743]  [<c0103a72>] common_interrupt+0x1a/0x20
[149649.848783]  [<d0a1e8f1>] aes_decrypt+0x121/0x13b0 [aes]
[149649.848865]  [<c01cd966>] cbc_process_decrypt+0xe6/0x160
[149649.848919]  [<c01cde50>] xor_128+0x0/0x20
[149649.848952]  [<d0a1e7d0>] aes_decrypt+0x0/0x13b0 [aes]
[149649.848999]  [<c01cd50c>] crypt+0x12c/0x2b0
[149649.849044]  [<c01cd6d1>] crypt_iv_unaligned+0x41/0x120
[149649.849082]  [<d0a1d320>] aes_encrypt+0x0/0x14b0 [aes]
[149649.849119]  [<c01cd9e0>] ecb_process+0x0/0x60
[149649.849156]  [<c01cdcc5>] cbc_decrypt_iv+0x55/0x60
[149649.849193]  [<d0a1e7d0>] aes_decrypt+0x0/0x13b0 [aes]
[149649.849227]  [<c01cd880>] cbc_process_decrypt+0x0/0x160
[149649.849264]  [<d0a12611>] crypt_convert+0x251/0x2d0 [dm_crypt]
[149649.849314]  [<d08bd2a1>] clone_endio+0x101/0x150 [dm_mod]
[149649.849392]  [<d0a12930>] kcryptd_do_work+0x0/0x70 [dm_crypt]
[149649.849428]  [<d0a12980>] kcryptd_do_work+0x50/0x70 [dm_crypt]
[149649.849474]  [<c012a451>] worker_thread+0x1b1/0x260
[149649.849526]  [<c0117670>] default_wake_function+0x0/0x20
[149649.849566]  [<c012a2a0>] worker_thread+0x0/0x260
[149649.849605]  [<c012e336>] kthread+0xb6/0xc0
[149649.849643]  [<c012e280>] kthread+0x0/0xc0
[149649.849679]  [<c0101379>] kernel_thread_helper+0x5/0xc
[149649.849727] Mem-info:
[149649.849748] DMA per-cpu:
[149649.849773] cpu 0 hot: low 2, high 6, batch 1 used:2
[149649.849799] cpu 0 cold: low 0, high 2, batch 1 used:0
[149649.849824] Normal per-cpu:
[149649.849849] cpu 0 hot: low 62, high 186, batch 31 used:147
[149649.849876] cpu 0 cold: low 0, high 62, batch 31 used:31
[149649.849903] HighMem per-cpu: empty
[149649.849933] Free pages:       16148kB (0kB HighMem)
[149649.849961] Active:5092 inactive:16489 dirty:2 writeback:0 unstable:0 free:4037 slab:36782 mapped:4533 pagetables:175
[149649.850014] DMA free:1340kB min:1024kB low:1280kB high:1536kB active:316kB inactive:4252kB present:16384kB pages_scanned:0 all_unreclaimable? no
[149649.850067] lowmem_reserve[]: 0 239 239
[149649.850106] Normal free:14808kB min:15356kB low:19192kB high:23032kB active:20052kB inactive:61704kB present:245680kB pages_scanned:0 all_unreclaimable? no
[149649.850161] lowmem_reserve[]: 0 0 0
[149649.850198] HighMem free:0kB min:128kB low:160kB high:192kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
[149649.850249] lowmem_reserve[]: 0 0 0
[149649.850284] DMA: 1*4kB 1*8kB 9*16kB 1*32kB 10*64kB 4*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1340kB
[149649.850370] Normal: 102*4kB 772*8kB 468*16kB 1*32kB 1*64kB 3*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 14808kB
[149649.850461] HighMem: empty
[149649.850496] Swap cache: add 465981, delete 465217, find 393848/474450, race 0+5
[149649.850537] Free swap  = 484784kB
[149649.850558] Total swap = 506036kB
[149649.850581] Free swap:       484784kB
[149649.856900] 65516 pages of RAM
[149649.856929] 0 pages of HIGHMEM
[149649.856951] 1386 reserved pages
[149649.856972] 10836 pages shared
[149649.856993] 764 pages swap cached
[149649.857016] 2 pages dirty
[149649.857036] 0 pages writeback
[149649.857056] 4533 pages mapped
[149649.857076] 36784 pages slab
[149649.857097] 175 pages pagetables
[149649.857425] kcryptd/0: page allocation failure. order:3, mode:0x20
[149649.857692]  [<c01419d8>] __alloc_pages+0x318/0x440
[149649.857743]  [<c0144b0d>] kmem_getpages+0x2d/0xa0
[149649.857782]  [<c0145936>] cache_grow+0x96/0x1c0
[149649.859033]  [<c0145c99>] cache_alloc_refill+0x239/0x270
[149649.859072]  [<c0145fb3>] __kmalloc+0x73/0x80
[149649.859105]  [<c027300f>] __alloc_skb+0x5f/0x160
[149649.859148]  [<d099afcc>] e1000_alloc_rx_buffers+0x1dc/0x3a0 [e1000]
[149649.859225]  [<d099a81d>] e1000_clean_rx_irq+0x30d/0x480 [e1000]
[149649.859272]  [<d099afcc>] e1000_alloc_rx_buffers+0x1dc/0x3a0 [e1000]
[149649.859325]  [<d0999f5d>] e1000_intr+0x4d/0x100 [e1000]
[149649.859371]  [<c013b5cd>] handle_IRQ_event+0x3d/0x70
[149649.859416]  [<c013b65d>] __do_IRQ+0x5d/0xc0
[149649.859451]  [<c0105199>] do_IRQ+0x19/0x30
[149649.859485]  [<c0103a72>] common_interrupt+0x1a/0x20
[149649.859523]  [<c011f540>] __do_softirq+0x30/0x90
[149649.859565]  [<c011f5c6>] do_softirq+0x26/0x30
[149649.859596]  [<c010519e>] do_IRQ+0x1e/0x30
[149649.859626]  [<c0103a72>] common_interrupt+0x1a/0x20
[149649.859663]  [<d0a1e8f1>] aes_decrypt+0x121/0x13b0 [aes]
[149649.859735]  [<c01cd966>] cbc_process_decrypt+0xe6/0x160
[149649.859786]  [<c01cde50>] xor_128+0x0/0x20
[149649.859817]  [<d0a1e7d0>] aes_decrypt+0x0/0x13b0 [aes]
[149649.859865]  [<c01cd50c>] crypt+0x12c/0x2b0
[149649.859909]  [<c01cd6d1>] crypt_iv_unaligned+0x41/0x120
[149649.859947]  [<d0a1d320>] aes_encrypt+0x0/0x14b0 [aes]
[149649.859981]  [<c01cd9e0>] ecb_process+0x0/0x60
[149649.860015]  [<c01cdcc5>] cbc_decrypt_iv+0x55/0x60
[149649.860052]  [<d0a1e7d0>] aes_decrypt+0x0/0x13b0 [aes]
[149649.860087]  [<c01cd880>] cbc_process_decrypt+0x0/0x160
[149649.860123]  [<d0a12611>] crypt_convert+0x251/0x2d0 [dm_crypt]
[149649.860171]  [<d08bd2a1>] clone_endio+0x101/0x150 [dm_mod]
[149649.860247]  [<d0a12930>] kcryptd_do_work+0x0/0x70 [dm_crypt]
[149649.860283]  [<d0a12980>] kcryptd_do_work+0x50/0x70 [dm_crypt]
[149649.860333]  [<c012a451>] worker_thread+0x1b1/0x260
[149649.860383]  [<c0117670>] default_wake_function+0x0/0x20
[149649.860422]  [<c012a2a0>] worker_thread+0x0/0x260
[149649.860454]  [<c012e336>] kthread+0xb6/0xc0
[149649.860492]  [<c012e280>] kthread+0x0/0xc0
[149649.860525]  [<c0101379>] kernel_thread_helper+0x5/0xc
[149649.860560] Mem-info:
[149649.860581] DMA per-cpu:
[149649.860603] cpu 0 hot: low 2, high 6, batch 1 used:2
[149649.860629] cpu 0 cold: low 0, high 2, batch 1 used:0
[149649.860655] Normal per-cpu:
[149649.860678] cpu 0 hot: low 62, high 186, batch 31 used:145
[149649.860705] cpu 0 cold: low 0, high 62, batch 31 used:31
[149649.860739] HighMem per-cpu: empty
[149649.860765] Free pages:       16148kB (0kB HighMem)
[149649.860794] Active:5092 inactive:16489 dirty:2 writeback:0 unstable:0 free:4037 slab:36784 mapped:4533 pagetables:175
[149649.860843] DMA free:1340kB min:1024kB low:1280kB high:1536kB active:316kB inactive:4252kB present:16384kB pages_scanned:0 all_unreclaimable? no
[149649.860896] lowmem_reserve[]: 0 239 239
[149649.860932] Normal free:14808kB min:15356kB low:19192kB high:23032kB active:20052kB inactive:61704kB present:245680kB pages_scanned:0 all_unreclaimable? no
[149649.860986] lowmem_reserve[]: 0 0 0
[149649.861022] HighMem free:0kB min:128kB low:160kB high:192kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
[149649.861071] lowmem_reserve[]: 0 0 0
[149649.861104] DMA: 1*4kB 1*8kB 9*16kB 1*32kB 10*64kB 4*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 1340kB
[149649.861189] Normal: 102*4kB 772*8kB 468*16kB 1*32kB 1*64kB 3*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 14808kB
[149649.861270] HighMem: empty
[149649.861294] Swap cache: add 465981, delete 465217, find 393848/474450, race 0+5
[149649.861331] Free swap  = 484784kB
[149649.861351] Total swap = 506036kB
[149649.861371] Free swap:       484784kB
[149649.867621] 65516 pages of RAM
[149649.867650] 0 pages of HIGHMEM
[149649.867670] 1386 reserved pages
[149649.867692] 10836 pages shared
[149649.867713] 764 pages swap cached
[149649.867734] 2 pages dirty
[149649.867764] 0 pages writeback
[149649.867783] 4533 pages mapped

Re: 2.6.14-rc5 e1000 and page allocation failures.. still

[Robert Hancock]

John Bäckstrand wrote:
> Im seeing a massive amount of page allocation failures with 2.6.14-rc5, 
> and also earlier kernels, see "E1000 - page allocation failure - saga 
> continues :(". Machine is a 1Ghz Athlon with 256MB RAM. Attached is 
> example dmesg output. The stack traces come in many variants. Killing 
> processes using RAM only seems to help temporarily. Ive also tried 
> setting vm.min_free_kbytes=16384, which used to work pretty well, but 
> this does not help (atleast not in the state the machine is currently 
> in, without rebooting).
> 
> free currently gives:
> 
>              total       used       free     shared    buffers     cached
> Mem:        256520     239128      17392          0       5372      67500
> -/+ buffers/cache:     166256      90264
> Swap:       506036      21248     484788
> 
> 
> I havent yet tried rebooting and using the vm.min_free_kbytes=16384 from 
> scratch, but I think something with the default for this is wrong if it 
> results in this many page allocation errors. The machine is serving 
> files from an encrypted partition with reiserfs on it, and I obivously 
> use the e1000 driver.
> 
> ---
> John Bäckstrand
> 
> 
> ------------------------------------------------------------------------
> 
> [149649.847890] kcryptd/0: page allocation failure. order:3, mode:0x20

..

> [149649.849933] Free pages:       16148kB (0kB HighMem)

It looks like you have enough memory free - the problem is that the 
driver is allocating a block of memory with order 3, which is 8 pages. 
Quite likely there are not enough contiguous free pages to satisfy that.

That's an awful big buffer size for a packet - I assume you're using 
jumbo frames or something? Ideally the driver and hardware should be 
able to allocate a buffer for those packets in multiple chunks, but I 
have no idea if this is possible.

-- 
Robert Hancock      Saskatoon, SK, Canada
To email, remove "nospam" from hancockr@nospamshaw.ca
Home Page: http://www.roberthancock.com/

Re: 2.6.14-rc5 e1000 and page allocation failures.. still

[Jesse Brandeburg]

On 10/23/05, Robert Hancock <hancockr@shaw.ca> wrote:
> John Bäckstrand wrote:
> > Im seeing a massive amount of page allocation failures with 2.6.14-rc5,
> > and also earlier kernels, see "E1000 - page allocation failure - saga
[snip]
> It looks like you have enough memory free - the problem is that the
> driver is allocating a block of memory with order 3, which is 8 pages.
> Quite likely there are not enough contiguous free pages to satisfy that.
>
> That's an awful big buffer size for a packet - I assume you're using
> jumbo frames or something? Ideally the driver and hardware should be
> able to allocate a buffer for those packets in multiple chunks, but I
> have no idea if this is possible.

the latest e1000 driver (6.2.15) from http://sf.net/projects/e1000
fixes this by using multiple descriptors for jumbo frames, therefore
only doing order 0 (single page) page allocations.

let us know how it goes.

BTW why is this so much more common with recent kernels?

Re: 2.6.14-rc5 e1000 and page allocation failures.. still

[Bill Davidsen]

Jesse Brandeburg wrote:
> On 10/23/05, Robert Hancock <hancockr@shaw.ca> wrote:
> 
>>John Bäckstrand wrote:
>>
>>>Im seeing a massive amount of page allocation failures with 2.6.14-rc5,
>>>and also earlier kernels, see "E1000 - page allocation failure - saga
> 
> [snip]
> 
>>It looks like you have enough memory free - the problem is that the
>>driver is allocating a block of memory with order 3, which is 8 pages.
>>Quite likely there are not enough contiguous free pages to satisfy that.
>>
>>That's an awful big buffer size for a packet - I assume you're using
>>jumbo frames or something? Ideally the driver and hardware should be
>>able to allocate a buffer for those packets in multiple chunks, but I
>>have no idea if this is possible.
> 
> 
> the latest e1000 driver (6.2.15) from http://sf.net/projects/e1000
> fixes this by using multiple descriptors for jumbo frames, therefore
> only doing order 0 (single page) page allocations.
> 
> let us know how it goes.
> 
> BTW why is this so much more common with recent kernels?

I don't know why it's more common, but I agree that it seems so. I have 
speculated that it may be related to 4k stack, but I can't even generate 
a credible wild-ass guess on that, much less find any evidence, so I 
doubt that's much if any correlation.

Getting memory a page at a time is ugly, but it will probably work just 
fine.

-- 
    -bill davidsen (davidsen@tmr.com)
"The secret to procrastination is to put things off until the
  last possible moment - but no longer"  -me