Re: iwlagn: order 2 page allocation failures

Mel Gorman
2009-09-16T15:02:38Z

On Wed, Sep 16, 2009 at 04:36:16PM +0200, Frans Pop wrote:
> On Wednesday 09 September 2009, Frans Pop wrote:
> > On Wednesday 09 September 2009, you wrote:
> > > The problem with this theory is that the patches have been in since
> > > Nov 2008 but reports are only showing up now. Frans, how sure are you
> > > that this is a recent problem? Is it readily reproducible?
> >
> > The only thing I can say here is that I've never seen the issue before
> > (and thanks to logcheck I certainly would have).
> > The laptop is in constant use, but I rarely stress the memory like that.
> > Swap is almost always at 0.
>
> JFYI, it happened again yesterday.
> The first time it was swapper, here it's kcryptd. The top part of the
> trace is the same.
>
> kcryptd: page allocation failure. order:2, mode:0x4020
> Pid: 1347, comm: kcryptd Not tainted 2.6.31-rc9 #16

Is this with Reinette Chatre's patch applied or vanilla?

If vanilla, Reinette, is your patch already upstream or in a subsystem
tree somewhere?

> Call Trace:
> <IRQ> [<ffffffff810790b0>] __alloc_pages_nodemask+0x542/0x58a
> [<ffffffff81256a62>] ? _spin_unlock+0x9/0xb
> [<ffffffff811da481>] ? __alloc_skb+0x3c/0x15b
> [<ffffffffa0355644>] ? iwl_rx_allocate+0xac/0x208 [iwlcore]
> [<ffffffff81079153>] __get_free_pages+0x12/0x41
> [<ffffffff810982c5>] __kmalloc_track_caller+0x3b/0xec
> [<ffffffff811da4ab>] __alloc_skb+0x66/0x15b
> [<ffffffffa0355644>] iwl_rx_allocate+0xac/0x208 [iwlcore]
> [<ffffffffa03557b6>] iwl_rx_replenish_now+0x16/0x23 [iwlcore]
> [<ffffffffa037c8e3>] iwl_rx_handle+0x356/0x39a [iwlagn]
> [<ffffffffa00212a2>] ? scsi_io_completion+0x3a8/0x3d1 [scsi_mod]
> [<ffffffffa037ce27>] iwl_irq_tasklet_legacy+0x500/0x74f [iwlagn]
> [<ffffffffa001a81b>] ? scsi_finish_command+0xec/0xf5 [scsi_mod]
> [<ffffffff8103dff0>] tasklet_action+0x71/0xbc
> [<ffffffff8103e877>] __do_softirq+0x9b/0x12c
> [<ffffffff8100cb7c>] call_softirq+0x1c/0x28
> [<ffffffff8100e694>] do_softirq+0x34/0x72
> [<ffffffff8103e601>] irq_exit+0x3f/0x79
> [<ffffffff8100dd95>] do_IRQ+0xa3/0xba
> [<ffffffff8100c413>] ret_from_intr+0x0/0xa
> <EOI> [<ffffffffa01fb5b8>] ? enc128+0x243/0x80b [aes_x86_64]
> [<ffffffffa01fc72b>] ? aes_encrypt+0xd/0xf [aes_x86_64]
> [<ffffffffa01e92b6>] ? crypto_cbc_encrypt+0x12c/0x18e [cbc]
> [<ffffffff81078c9b>] ? __alloc_pages_nodemask+0x12d/0x58a
> [<ffffffffa01fc71e>] ? aes_encrypt+0x0/0xf [aes_x86_64]
> [<ffffffff81113ea0>] ? async_encrypt+0x38/0x3a
> [<ffffffff81075a94>] ? mempool_alloc+0x5b/0x113
> [<ffffffffa01c5b53>] ? crypt_convert+0x1f9/0x278 [dm_crypt]
> [<ffffffffa01c5ff5>] ? kcryptd_crypt+0x423/0x449 [dm_crypt]
> [<ffffffffa01c5bd2>] ? kcryptd_crypt+0x0/0x449 [dm_crypt]
> [<ffffffff81048bc5>] ? worker_thread+0x132/0x1ca
> [<ffffffff8104c647>] ? autoremove_wake_function+0x0/0x38
> [<ffffffff81048a93>] ? worker_thread+0x0/0x1ca
> [<ffffffff8104c325>] ? kthread+0x8f/0x97
> [<ffffffff8100ca7a>] ? child_rip+0xa/0x20
> [<ffffffff8104c296>] ? kthread+0x0/0x97
> [<ffffffff8100ca70>] ? child_rip+0x0/0x20
> Mem-Info:
> DMA per-cpu:
> CPU 0: hi: 0, btch: 1 usd: 0
> CPU 1: hi: 0, btch: 1 usd: 0
> DMA32 per-cpu:
> CPU 0: hi: 186, btch: 31 usd: 172
> CPU 1: hi: 186, btch: 31 usd: 163
> Active_anon:278449 active_file:18846 inactive_anon:93192
> inactive_file:18343 unevictable:407 dirty:0 writeback:7726 unstable:0
> free:25175 slab:10409 mapped:34634 pagetables:4385 bounce:0
> DMA free:7924kB min:40kB low:48kB high:60kB active_anon:2220kB inactive_anon:2464kB
> active_file:1084kB inactive_file:1608kB unevictable:0kB present:15336kB pages_scanned:0
> all_unreclaimable? no
> lowmem_reserve[]: 0 1976 1976 1976
> DMA32 free:92776kB min:5664kB low:7080kB high:8496kB active_anon:1111448kB inactive_anon:370432kB
> active_file:74300kB inactive_file:71764kB unevictable:1628kB present:2023748kB pages_scanned:32
> all_unreclaimable? no
> lowmem_reserve[]: 0 0 0 0
> DMA: 63*4kB 59*8kB 26*16kB 34*32kB 23*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 7924kB
> DMA32: 18882*4kB 2076*8kB 10*16kB 1*32kB 1*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 92776kB
> 82554 total pagecache pages
> 44961 pages in swap cache
> Swap cache stats: add 160004, delete 115046, find 2431510/2434120
> Free swap = 1549576kB
> Total swap = 2097144kB
> 518064 pages RAM
> 10323 pages reserved
> 117029 pages shared
> 398165 pages non-shared
> iwlagn 0000:10:00.0: Can not allocate SKB buffers
> kcryptd: page allocation failure. order:2, mode:0x4020
> Pid: 1347, comm: kcryptd Not tainted 2.6.31-rc9 #16
> Call Trace:
> <IRQ> [<ffffffff810790b0>] __alloc_pages_nodemask+0x542/0x58a
> [<ffffffff81256a62>] ? _spin_unlock+0x9/0xb
> [<ffffffff811da481>] ? __alloc_skb+0x3c/0x15b
> [<ffffffffa0355644>] ? iwl_rx_allocate+0xac/0x208 [iwlcore]
> [<ffffffff81079153>] __get_free_pages+0x12/0x41
> [<ffffffff810982c5>] __kmalloc_track_caller+0x3b/0xec
> [<ffffffff811da4ab>] __alloc_skb+0x66/0x15b
> [<ffffffffa0355644>] iwl_rx_allocate+0xac/0x208 [iwlcore]
> [<ffffffffa03557b6>] iwl_rx_replenish_now+0x16/0x23 [iwlcore]
> [<ffffffffa037c90e>] iwl_rx_handle+0x381/0x39a [iwlagn]
> [<ffffffffa00212a2>] ? scsi_io_completion+0x3a8/0x3d1 [scsi_mod]
> [<ffffffffa037ce27>] iwl_irq_tasklet_legacy+0x500/0x74f [iwlagn]
> [<ffffffffa001a81b>] ? scsi_finish_command+0xec/0xf5 [scsi_mod]
> [<ffffffff8103dff0>] tasklet_action+0x71/0xbc
> [<ffffffff8103e877>] __do_softirq+0x9b/0x12c
> [<ffffffff8100cb7c>] call_softirq+0x1c/0x28
> [<ffffffff8100e694>] do_softirq+0x34/0x72
> [<ffffffff8103e601>] irq_exit+0x3f/0x79
> [<ffffffff8100dd95>] do_IRQ+0xa3/0xba
> [<ffffffff8100c413>] ret_from_intr+0x0/0xa
> <EOI> [<ffffffffa01fb5b8>] ? enc128+0x243/0x80b [aes_x86_64]
> [<ffffffffa01fc72b>] ? aes_encrypt+0xd/0xf [aes_x86_64]
> [<ffffffffa01e92b6>] ? crypto_cbc_encrypt+0x12c/0x18e [cbc]
> [<ffffffff81078c9b>] ? __alloc_pages_nodemask+0x12d/0x58a
> [<ffffffffa01fc71e>] ? aes_encrypt+0x0/0xf [aes_x86_64]
> [<ffffffff81113ea0>] ? async_encrypt+0x38/0x3a
> [<ffffffff81075a94>] ? mempool_alloc+0x5b/0x113
> [<ffffffffa01c5b53>] ? crypt_convert+0x1f9/0x278 [dm_crypt]
> [<ffffffffa01c5ff5>] ? kcryptd_crypt+0x423/0x449 [dm_crypt]
> [<ffffffffa01c5bd2>] ? kcryptd_crypt+0x0/0x449 [dm_crypt]
> [<ffffffff81048bc5>] ? worker_thread+0x132/0x1ca
> [<ffffffff8104c647>] ? autoremove_wake_function+0x0/0x38
> [<ffffffff81048a93>] ? worker_thread+0x0/0x1ca
> [<ffffffff8104c325>] ? kthread+0x8f/0x97
> [<ffffffff8100ca7a>] ? child_rip+0xa/0x20
> [<ffffffff8104c296>] ? kthread+0x0/0x97
> [<ffffffff8100ca70>] ? child_rip+0x0/0x20
> Mem-Info:
> DMA per-cpu:
> CPU 0: hi: 0, btch: 1 usd: 0
> CPU 1: hi: 0, btch: 1 usd: 0
> DMA32 per-cpu:
> CPU 0: hi: 186, btch: 31 usd: 172
> CPU 1: hi: 186, btch: 31 usd: 173
> Active_anon:277951 active_file:18714 inactive_anon:93068
> inactive_file:18252 unevictable:407 dirty:0 writeback:7726 unstable:0
> free:25861 slab:10409 mapped:34634 pagetables:4385 bounce:0
> DMA free:7924kB min:40kB low:48kB high:60kB active_anon:2220kB inactive_anon:2464kB
> active_file:1084kB inactive_file:1608kB unevictable:0kB present:15336kB pages_scanned:0
> all_unreclaimable? no
> lowmem_reserve[]: 0 1976 1976 1976
> DMA32 free:95520kB min:5664kB low:7080kB high:8496kB active_anon:1109584kB inactive_anon:369808kB
> active_file:73772kB inactive_file:71400kB unevictable:1628kB present:2023748kB pages_scanned:66
> all_unreclaimable? no
> lowmem_reserve[]: 0 0 0 0
> DMA: 63*4kB 59*8kB 26*16kB 34*32kB 23*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 7924kB
> DMA32: 19178*4kB 2285*8kB 3*16kB 1*32kB 1*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 95520kB
> 81717 total pagecache pages
> 44349 pages in swap cache
> Swap cache stats: add 160008, delete 115659, find 2431510/2434120
> Free swap = 1549560kB
> Total swap = 2097144kB
> 518064 pages RAM
> 10323 pages reserved
> 117031 pages shared
> 398265 pages non-shared
> iwlagn 0000:10:00.0: Can not allocate SKB buffers
>

--
Mel Gorman
Part-time Phd Student Linux Technology Center
University of Limerick IBM Dublin Software Lab