3.2.8/amd64 full interrupt hangs and deadlocks under big network copies (page allocation failure)

4 messages, 3 authors, 2012-04-09 · open the first message on its own page

3.2.8/amd64 full interrupt hangs and deadlocks under big network copies (page allocation failure)

From: Marc MERLIN <hidden>
Date: 2012-03-29 17:15:07

Howdy,

I need some help narrowing this bug down so that I can give a better report.

First, the problem is not new to 3.2.8, it appeared after I upgraded
my laptop to a new distribution and switched from 32bits to 64bit kernel
and userland. This in turn seems to be causing memory allocation problems.

When I make a big NFS copy, apparently interrupts don't get serviced
after a while, and my X screen won't update itself (clock) and my mouse
cursor won't move.
Then, after maybe a minute or more, it usually recovers for a few
seconds, and then locks again. The copy usually finishes eventually
if I leave the laptop for a few hours on its own while the UI is
unresponsive.
I've had the problem with both wired and wireless copies, and tried
doing a copy with smbmount instead of nfs, and the issue was similar.

I first had a vol prempt kernel, and tried recompiling with preempt and
that did not help.
My kernel config is here: http://marc.merlins.org/tmp/config.txt

Last night, I started a big copy, and this morning found the copy half
hung. The laptop was responsive, but while I could ping, TCP connections
would put the process in unkillable kernel hung state.

Below are some sysreq dumps I took (syslog to local disk was still
working fine). I know I have Tainted 'G', and I have no idea where that
came from, sorry :-/

It looks like I may run out of some kind of memory which in turn is
deadlocking some drivers?
(actual total memory is fine, user apps do not get OOM'ed and 'free' looked fine)

I ran the relevant sysrq commands wihch are at 
http://marc.merlins.org/tmp/sysrq.txt
(too big to paste here) 

But lots of tasks are hung like so:
[28451.191115] WorkerPool/1248 D ffff88013bc93580     0 12483   3740 0x00000080
[28451.191115]  ffff8801189ba100 0000000000000082 0000000000000000 ffff880134f2e180
[28451.191115]  0000000000013580 ffff88001614bfd8 ffff88001614bfd8 ffff8801189ba100
[28451.191115]  ffffffff811b4b62 000000010164525a 0000000000000046 ffffffff8165a250
[28451.191115] Call Trace:
[28451.191115]  [<ffffffff811b4b62>] ? sha_transform+0x395/0x1209
[28451.191115]  [<ffffffff8134a9b4>] ? __mutex_lock_common.isra.6+0x13d/0x219
[28451.191115]  [<ffffffff81242714>] ? extract_buf+0x86/0xf2
[28451.191115]  [<ffffffff8134a7e6>] ? mutex_lock+0xf/0x1f
[28451.191115]  [<ffffffff81298979>] ? rtnetlink_rcv+0xe/0x28
[28451.191115]  [<ffffffff812ad007>] ? netlink_unicast+0xe6/0x14e
[28451.191115]  [<ffffffff812ad26b>] ? netlink_sendmsg+0x1fc/0x237
[28451.191115]  [<ffffffff8127c770>] ? sock_sendmsg+0xc1/0xde
[28451.191115]  [<ffffffff810eca23>] ? __cache_free.isra.40+0x19/0x1a7
[28451.191115]  [<ffffffff813496be>] ? nl_pid_hash_rehash+0xc8/0xef
[28451.191115]  [<ffffffff8103e0fa>] ? get_parent_ip+0x9/0x1b
[28451.191115]  [<ffffffff8103e0fa>] ? get_parent_ip+0x9/0x1b
[28451.191115]  [<ffffffff8134e1d2>] ? sub_preempt_count+0x83/0x94
[28451.191115]  [<ffffffff810fd81e>] ? fget_light+0x85/0x8d
[28451.191115]  [<ffffffff8127e0e3>] ? sys_sendto+0xf7/0x137
[28451.191115]  [<ffffffff8103e0fa>] ? get_parent_ip+0x9/0x1b
[28451.191115]  [<ffffffff8134e1d2>] ? sub_preempt_count+0x83/0x94
[28451.191115]  [<ffffffff8134b725>] ? _raw_spin_unlock+0x24/0x30
[28451.191115]  [<ffffffff8108d73e>] ? audit_syscall_entry+0x105/0x130
[28451.191115]  [<ffffffff8134fd52>] ? system_call_fastpath+0x16/0x1b



Below are lines I got in syslog during the copy.
Highlight is:
[ 4437.367046] kworker/1:1: page allocation failure: order:1, mode:0x20
and then:
[ 8640.516177] INFO: task flush-0:37:7122 blocked for more than 120 seconds.
and then 120,000 lines(!) of:
[ 9654.042164] ieee80211 phy0: failed to reallocate TX buffer

unedited lines below.

So, any idea of what I can try next?

Thanks,
Marc


[ 4437.367046] kworker/1:1: page allocation failure: order:1, mode:0x20
[ 4437.367053] Pid: 8067, comm: kworker/1:1 Tainted: G           O 3.2.8-amd64-volpreempt-noide-20120208 #1
[ 4437.367056] Call Trace:
[ 4437.367058]  <IRQ>  [<ffffffff810b9ec0>] ? warn_alloc_failed+0x11f/0x132
[ 4437.367074]  [<ffffffff810bcdaa>] ? __alloc_pages_nodemask+0x6b1/0x72f
[ 4437.367081]  [<ffffffff810ec911>] ? kmem_getpages+0x4c/0xd9
[ 4437.367086]  [<ffffffff810ec911>] ? kmem_getpages+0x4c/0xd9
[ 4437.367090]  [<ffffffff810edd21>] ? fallback_alloc+0x123/0x1c2
[ 4437.367096]  [<ffffffff812846db>] ? pskb_expand_head+0xe0/0x24a
[ 4437.367101]  [<ffffffff810ee215>] ? __kmalloc+0xb2/0x10a
[ 4437.367105]  [<ffffffff812846db>] ? pskb_expand_head+0xe0/0x24a
[ 4437.367139]  [<ffffffffa03e22c1>] ? ieee80211_skb_resize+0x64/0x9d [mac80211]
[ 4437.367154]  [<ffffffffa03e4252>] ? ieee80211_subif_start_xmit+0x705/0x883 [mac80211]
[ 4437.367175]  [<ffffffff8128e767>] ? dev_hard_start_xmit+0x40b/0x552
[ 4437.367179]  [<ffffffff812a4adc>] ? sch_direct_xmit+0x63/0x13a
[ 4437.367182]  [<ffffffff8128eb8e>] ? dev_queue_xmit+0x2e0/0x4b5
[ 4437.367185]  [<ffffffff812b764d>] ? ip_finish_output2+0x1c7/0x218
[ 4437.367188]  [<ffffffff812b86aa>] ? __ip_flush_pending_frames.isra.29+0x69/0x69
[ 4437.367191]  [<ffffffff812b8a6a>] ? ip_queue_xmit+0x2cd/0x30d
[ 4437.367195]  [<ffffffff81066be9>] ? getnstimeofday+0x4a/0x7b
[ 4437.367198]  [<ffffffff812ca1d2>] ? tcp_transmit_skb+0x6d7/0x70a
[ 4437.367201]  [<ffffffff812cac5f>] ? tcp_write_xmit+0x698/0x7a1
[ 4437.367204]  [<ffffffff812c77bf>] ? tcp_ack+0x14e3/0x1658
[ 4437.367207]  [<ffffffff812c89bd>] ? tcp_established_options+0x2b/0x9e
[ 4437.367210]  [<ffffffff812cada9>] ? __tcp_push_pending_frames+0x18/0x44
[ 4437.367213]  [<ffffffff812c4e27>] ? tcp_data_snd_check+0x2c/0xfd
[ 4437.367216]  [<ffffffff812c86c5>] ? tcp_rcv_established+0x4f0/0x549
[ 4437.367220]  [<ffffffff8103ec39>] ? select_task_rq_fair+0x67b/0x690
[ 4437.367223]  [<ffffffff812ce735>] ? tcp_v4_do_rcv+0x166/0x323
[ 4437.367226]  [<ffffffff812cfdce>] ? tcp_v4_rcv+0x404/0x65d
[ 4437.367230]  [<ffffffff812b4d55>] ? ip_local_deliver_finish+0x148/0x1ba
[ 4437.367233]  [<ffffffff8128cfa4>] ? __netif_receive_skb+0x3f2/0x43f
[ 4437.367236]  [<ffffffff8128d31d>] ? netif_receive_skb+0x7e/0x84
[ 4437.367239]  [<ffffffff8128d7dd>] ? napi_gro_receive+0x1c/0x29
[ 4437.367241]  [<ffffffff8128d398>] ? napi_skb_finish+0x1c/0x31
[ 4437.367253]  [<ffffffffa026bde3>] ? e1000_clean_rx_irq+0x1f3/0x290 [e1000e]
[ 4437.367261]  [<ffffffffa026c26c>] ? e1000_clean+0x69/0x208 [e1000e]
[ 4437.367264]  [<ffffffff8128d8fb>] ? net_rx_action+0xa4/0x1c0
[ 4437.367268]  [<ffffffff8104c581>] ? __do_softirq+0xc0/0x188
[ 4437.367272]  [<ffffffff81351fac>] ? call_softirq+0x1c/0x30
[ 4437.367276]  [<ffffffff8100f98d>] ? do_softirq+0x3c/0x7b
[ 4437.367278]  [<ffffffff8104c87c>] ? irq_exit+0x3d/0xa7
[ 4437.367281]  [<ffffffff8100f6b4>] ? do_IRQ+0x81/0x97
[ 4437.367285]  [<ffffffff8134ba2e>] ? common_interrupt+0x6e/0x6e
[ 4437.367287]  <EOI>  [<ffffffffa008b32c>] ? dec128+0x434/0x80c [aes_x86_64]
[ 4437.367307]  [<ffffffffa0085164>] ? crypt+0xae/0x101 [xts]
[ 4437.367313]  [<ffffffffa008b712>] ? aes_decrypt+0xe/0xe [aes_x86_64]
[ 4437.367320]  [<ffffffffa008b704>] ? dec128+0x80c/0x80c [aes_x86_64]
[ 4437.367327]  [<ffffffffa00851f6>] ? decrypt+0x3f/0x44 [xts]
[ 4437.367331]  [<ffffffff8118cdb3>] ? async_decrypt+0x37/0x3c
[ 4437.367338]  [<ffffffffa0105e2a>] ? crypt_convert+0x22f/0x2c4 [dm_crypt]
[ 4437.367342]  [<ffffffff8100d02f>] ? load_TLS+0x7/0xa
[ 4437.367348]  [<ffffffffa01061b8>] ? kcryptd_crypt+0x56/0x342 [dm_crypt]
[ 4437.367352]  [<ffffffff81038cd2>] ? finish_task_switch+0x86/0xb7
[ 4437.367355]  [<ffffffff8103e0fa>] ? get_parent_ip+0x9/0x1b
[ 4437.367358]  [<ffffffff8134e1d2>] ? sub_preempt_count+0x83/0x94
[ 4437.367361]  [<ffffffff8103612b>] ? need_resched+0x1a/0x23
[ 4437.367368]  [<ffffffffa0106162>] ? crypt_convert_init.isra.14+0x4f/0x4f [dm_crypt]
[ 4437.367372]  [<ffffffff8105b867>] ? process_one_work+0x16d/0x298
[ 4437.367375]  [<ffffffff8105c84a>] ? worker_thread+0xc2/0x145
[ 4437.367378]  [<ffffffff8105c788>] ? manage_workers.isra.23+0x15b/0x15b
[ 4437.367381]  [<ffffffff8105f9fe>] ? kthread+0x76/0x7e
[ 4437.367384]  [<ffffffff81351eb4>] ? kernel_thread_helper+0x4/0x10
[ 4437.367387]  [<ffffffff8105f988>] ? kthread_worker_fn+0x139/0x139
[ 4437.367390]  [<ffffffff81351eb0>] ? gs_change+0x13/0x13
[ 4437.367392] Mem-Info:
[ 4437.367393] Node 0 DMA per-cpu:
[ 4437.367396] CPU    0: hi:    0, btch:   1 usd:   0
[ 4437.367397] CPU    1: hi:    0, btch:   1 usd:   0
[ 4437.367399] Node 0 DMA32 per-cpu:
[ 4437.367401] CPU    0: hi:  186, btch:  31 usd: 164
[ 4437.367403] CPU    1: hi:  186, btch:  31 usd: 111
[ 4437.367405] Node 0 Normal per-cpu:
[ 4437.367407] CPU    0: hi:  186, btch:  31 usd: 114
[ 4437.367409] CPU    1: hi:  186, btch:  31 usd: 158
[ 4437.367413] active_anon:391300 inactive_anon:132951 isolated_anon:0
[ 4437.367414]  active_file:136666 inactive_file:140710 isolated_file:31
[ 4437.367415]  unevictable:1 dirty:3402 writeback:26688 unstable:7844
[ 4437.367416]  free:36509 slab_reclaimable:85289 slab_unreclaimable:35524
[ 4437.367417]  mapped:18088 shmem:35934 pagetables:9300 bounce:0
[ 4437.367419] Node 0 DMA free:15712kB min:260kB low:324kB high:388kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:36kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15684kB mlocked:0kB dirty:0kB writeback:36kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:160kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:40833 all_unreclaimable? yes
[ 4437.367428] lowmem_reserve[]: 0 2960 3907 3907
[ 4437.367432] Node 0 DMA32 free:110732kB min:51004kB low:63752kB high:76504kB active_anon:1380396kB inactive_anon:345140kB active_file:422008kB inactive_file:437440kB unevictable:4kB isolated(anon):0kB isolated(file):124kB present:3031688kB mlocked:4kB dirty:7148kB writeback:72004kB mapped:39424kB shmem:64836kB slab_reclaimable:212408kB slab_unreclaimable:80516kB kernel_stack:1720kB pagetables:19252kB unstable:23964kB bounce:0kB writeback_tmp:0kB pages_scanned:63 all_unreclaimable? no
[ 4437.367442] lowmem_reserve[]: 0 0 946 946
[ 4437.367445] Node 0 Normal free:19592kB min:16312kB low:20388kB high:24468kB active_anon:184804kB inactive_anon:186664kB active_file:124656kB inactive_file:125364kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:969600kB mlocked:0kB dirty:6460kB writeback:34712kB mapped:32928kB shmem:78900kB slab_reclaimable:128748kB slab_unreclaimable:61420kB kernel_stack:2792kB pagetables:17948kB unstable:7412kB bounce:0kB writeback_tmp:0kB pages_scanned:89 all_unreclaimable? no
[ 4437.367455] lowmem_reserve[]: 0 0 0 0
[ 4437.367458] Node 0 DMA: 2*4kB 1*8kB 1*16kB 0*32kB 1*64kB 2*128kB 2*256kB 1*512kB 2*1024kB 2*2048kB 2*4096kB = 15712kB
[ 4437.367467] Node 0 DMA32: 25961*4kB 73*8kB 8*16kB 1*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB 1*4096kB = 110732kB
[ 4437.367475] Node 0 Normal: 4134*4kB 0*8kB 1*16kB 1*32kB 0*64kB 2*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 19656kB
[ 4437.367484] 317456 total pagecache pages
[ 4437.367485] 4042 pages in swap cache
[ 4437.367487] Swap cache stats: add 31786, delete 27744, find 10282/11070
[ 4437.367489] Free swap  = 4012560kB
[ 4437.367490] Total swap = 4106248kB
[ 4437.370978] 1032176 pages RAM
[ 4437.370978] 42834 pages reserved
[ 4437.370978] 390787 pages shared
[ 4437.370978] 750687 pages non-shared


[ 8640.516177] INFO: task flush-0:37:7122 blocked for more than 120 seconds.
[ 8640.516182] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 8640.516186] flush-0:37      D ffff88013bc93580     0  7122      2 0x00000080
[ 8640.516192]  ffff880072c28810 0000000000000046 ffff880100000000 ffff880134f2e180
[ 8640.516199]  0000000000013580 ffff88006d491fd8 ffff88006d491fd8 ffff880072c28810
[ 8640.516205]  ffff88013bfd1c50 000000018134b58b ffff88010c3cc1b0 ffff88006d491d18
[ 8640.516211] Call Trace:
[ 8640.516221]  [<ffffffff8110e81a>] ? inode_owner_or_capable+0x36/0x36
[ 8640.516226]  [<ffffffff8110e820>] ? inode_wait+0x6/0xa
[ 8640.516232]  [<ffffffff8134a72c>] ? __wait_on_bit+0x3e/0x71
[ 8640.516241]  [<ffffffff8103e0fa>] ? get_parent_ip+0x9/0x1b
[ 8640.516245]  [<ffffffff81119674>] ? inode_wait_for_writeback+0xa2/0xc8
[ 8640.516249]  [<ffffffff810600c9>] ? autoremove_wake_function+0x2a/0x2a
[ 8640.516252]  [<ffffffff8111b4b4>] ? wb_writeback+0x226/0x255
[ 8640.516255]  [<ffffffff8134e27d>] ? add_preempt_count+0x9a/0x9c
[ 8640.516258]  [<ffffffff8111b8d4>] ? wb_do_writeback+0x150/0x1b2
[ 8640.516261]  [<ffffffff8111b9c5>] ? bdi_writeback_thread+0x8f/0x204
[ 8640.516264]  [<ffffffff8111b936>] ? wb_do_writeback+0x1b2/0x1b2
[ 8640.516266]  [<ffffffff8105f9fe>] ? kthread+0x76/0x7e
[ 8640.516270]  [<ffffffff81351eb4>] ? kernel_thread_helper+0x4/0x10
[ 8640.516273]  [<ffffffff8105f988>] ? kthread_worker_fn+0x139/0x139
[ 8640.516275]  [<ffffffff81351eb0>] ? gs_change+0x13/0x13
[ 8640.516281] INFO: task cp:7568 blocked for more than 120 seconds.
[ 8640.516283] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 8640.516284] cp              D ffff88013bc13580     0  7568   6744 0x00000080
[ 8640.516288]  ffff880123976750 0000000000000082 0000000000000000 ffffffff8160d020
[ 8640.516292]  0000000000013580 ffff88001b3a9fd8 ffff88001b3a9fd8 ffff880123976750
[ 8640.516295]  0000000000000001 0000000181066767 ffff880131463e50 ffff88013bc13e08
[ 8640.516299] Call Trace:
[ 8640.516303]  [<ffffffff810b5d03>] ? __lock_page+0x66/0x66
[ 8640.516306]  [<ffffffff8134a2ec>] ? io_schedule+0x58/0x6f
[ 8640.516308]  [<ffffffff810b5d09>] ? sleep_on_page+0x6/0xa
[ 8640.516311]  [<ffffffff8134a72c>] ? __wait_on_bit+0x3e/0x71
[ 8640.516313]  [<ffffffff810b5e51>] ? wait_on_page_bit+0x6e/0x73
[ 8640.516316]  [<ffffffff810600c9>] ? autoremove_wake_function+0x2a/0x2a
[ 8640.516319]  [<ffffffff810b5f29>] ? filemap_fdatawait_range+0x74/0x139
[ 8640.516327]  [<ffffffff8111acab>] ? writeback_single_inode+0x155/0x2f4
[ 8640.516330]  [<ffffffff8111ae94>] ? sync_inode+0x4a/0x6f
[ 8640.516343]  [<ffffffffa06b9b02>] ? nfs_wb_all+0x39/0x3e [nfs]
[ 8640.516351]  [<ffffffffa06aeed1>] ? nfs_setattr+0x8e/0xf6 [nfs]
[ 8640.516354]  [<ffffffff811104c3>] ? notify_change+0x177/0x24f
[ 8640.516357]  [<ffffffff8111e85c>] ? utimes_common+0x10c/0x135
[ 8640.516361]  [<ffffffff810fd55a>] ? fget+0x50/0x57
[ 8640.516364]  [<ffffffff8111e90f>] ? do_utimes+0x8a/0xd6
[ 8640.516367]  [<ffffffff810fc7a2>] ? vfs_read+0x9f/0xe6
[ 8640.516369]  [<ffffffff8111ea24>] ? sys_utimensat+0x64/0x6b
[ 8640.516372]  [<ffffffff8134fd52>] ? system_call_fastpath+0x16/0x1b


[ 9654.042164] ieee80211 phy0: failed to reallocate TX buffer
[ 9654.042189] ieee80211 phy0: failed to reallocate TX buffer
(120,000 lines of this)

-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: 3.2.8/amd64 full interrupt hangs and deadlocks under big network copies (page allocation failure)

From: Ben Hutchings <hidden>
Date: 2012-03-29 18:09:42

On Thu, 2012-03-29 at 09:38 -0700, Marc MERLIN wrote:
[...]
Below are some sysreq dumps I took (syslog to local disk was still
working fine). I know I have Tainted 'G', and I have no idea where that
came from, sorry :-/
[...]

'G' isn't a taint flag, but the following 'O' is; it means you have one
or more out-of-tree modules loaded.  Care to tell us what they are?

Ben.

-- 
Ben Hutchings, Staff Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

Re: 3.2.8/amd64 full interrupt hangs and deadlocks under big network copies (page allocation failure)

From: Marc MERLIN <hidden>
Date: 2012-04-09 17:20:53

On Thu, Mar 29, 2012 at 07:09:35PM +0100, Ben Hutchings wrote:
On Thu, 2012-03-29 at 09:38 -0700, Marc MERLIN wrote:
[...]
quoted
Below are some sysreq dumps I took (syslog to local disk was still
working fine). I know I have Tainted 'G', and I have no idea where that
came from, sorry :-/
[...]

'G' isn't a taint flag, but the following 'O' is; it means you have one
or more out-of-tree modules loaded.  Care to tell us what they are?
Ok, I just had time to reproduce this without tainting. It was with 3.2.5
though since I'm debugging a battery power use issue too.

I confirmed that the problem only happens when I do NFS copies. Doing the
same copy with rsync over SSH works fine.

I'm not much of a kernel guy, but it looks like there is a memory problem,
which in turn causes the network driver to deadlock waiting on RAM with 
interrupts turned off (mouse cursor won't move). Eventually it gets a bit of
the special RAM it seems to need, at that point, my frozen mouse pointer
unfreezes until it locks again soon after.

So there are 2 problems
1) memory issue
2) driver waits for RAM with interrupts turned off

The log below shows offlineimap first getting memory allocation problems
as soon after I start the copy, then firefox, and some:
ieee80211 phy0: failed to reallocate TX buffer

No taint flags this time.
I'll paste a few lines below.

Any idea what's going on, what bucket of RAM is an issue for the driver
(total RAM is more than plenty), and where I should go from there?

kernel config: http://marc.merlins.org/tmp/config.txt

Thanks,
Marc

09:44:12  offlineimap: page allocation failure: order:1, mode:0x20
09:44:12  Pid: 6269, comm: offlineimap Tainted: G           O 3.2.5amd64-volpreempt-noide-20120208 #1
09:44:12  Call Trace:
09:44:12   <IRQ>  [<ffffffff810b755a>] ? warn_alloc_failed+0x11a/0x12d
09:44:12   [<ffffffff810ba394>] ? __alloc_pages_nodemask+0x6b2/0x726
09:44:12   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:12   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:12   [<ffffffff810ea421>] ? fallback_alloc+0x123/0x1c2
09:44:12   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:12   [<ffffffff810ea923>] ? __kmalloc+0xba/0x112
09:44:12   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:12   [<ffffffffa07a81c0>] ? ieee80211_skb_resize+0x64/0x9d [mac80211]
09:44:12   [<ffffffffa07aa087>] ? ieee80211_subif_start_xmit+0x68e/0x80c [mac80211]
09:44:12   [<ffffffffa07922c8>] ? ieee80211_tx_status_irqsafe+0x2e/0x7f [mac80211]
09:44:12   [<ffffffff812877f3>] ? dev_hard_start_xmit+0x3fc/0x543
09:44:12   [<ffffffff81070551>] ? arch_local_irq_save+0x11/0x17
09:44:12   [<ffffffff8129da01>] ? sch_direct_xmit+0x5e/0x12f
09:44:12   [<ffffffff8129dbc9>] ? __qdisc_run+0xf7/0x10f
09:44:12   [<ffffffff81282d56>] ? net_tx_action+0xf1/0x128
09:44:12   [<ffffffff8104bc88>] ? __do_softirq+0xb9/0x177
09:44:12   [<ffffffff81065863>] ? timekeeping_get_ns+0xd/0x2a
09:44:12   [<ffffffff81349dac>] ? call_softirq+0x1c/0x30
09:44:12   [<ffffffff8100f875>] ? do_softirq+0x3c/0x7b
09:44:12   [<ffffffff8104bef0>] ? irq_exit+0x3c/0x9a
09:44:12   [<ffffffff8100f5a5>] ? do_IRQ+0x82/0x98
09:44:12   [<ffffffff81342e2e>] ? common_interrupt+0x6e/0x6e
09:44:12   <EOI>  [<ffffffff81061e33>] ? hrtimer_cancel+0xc/0x16
09:44:12   [<ffffffff8110629a>] ? select_estimate_accuracy+0xcf/0xed
09:44:12   [<ffffffff8110629a>] ? select_estimate_accuracy+0xcf/0xed
09:44:12   [<ffffffff81106464>] ? do_select+0x13c/0x46a
09:44:12   [<ffffffff81034a8c>] ? walk_tg_tree_from+0x70/0x99
09:44:12   [<ffffffff811060ab>] ? poll_freewait+0x97/0x97
09:44:12   [<ffffffff8103a520>] ? update_curr+0xd0/0xf5
09:44:12   [<ffffffff8100d758>] ? __switch_to+0x1fc/0x20e
09:44:12   [<ffffffff8103ac9c>] ? dequeue_entity+0x13e/0x161
09:44:12   [<ffffffff8103891c>] ? finish_task_switch+0x88/0xb9
09:44:12   [<ffffffff813417fc>] ? __schedule+0x5ac/0x5c3
09:44:12   [<ffffffff8106c902>] ? get_futex_value_locked+0x2d/0x3d
09:44:12   [<ffffffff810349f1>] ? set_task_rq+0x23/0x35
09:44:12   [<ffffffff81035ef0>] ? cpumask_next+0x17/0x1a
09:44:12   [<ffffffff8104073f>] ? select_task_rq_fair+0x435/0x67e
09:44:12   [<ffffffff8101353d>] ? paravirt_read_tsc+0x5/0x8
09:44:12   [<ffffffff81013999>] ? native_sched_clock+0x27/0x2f
09:44:12   [<ffffffff810139a6>] ? sched_clock+0x5/0x8
09:44:12   [<ffffffff810634b0>] ? sched_clock_local+0xd/0x6f
09:44:12   [<ffffffff81026aa4>] ? _flat_send_IPI_mask+0x68/0x78
09:44:12   [<ffffffff8103f175>] ? try_to_wake_up+0x187/0x196
09:44:12   [<ffffffff81106907>] ? core_sys_select+0x175/0x21a
09:44:12   [<ffffffff8106e85a>] ? do_futex+0xab/0x7ed
09:44:12   [<ffffffff8104afef>] ? timespec_add_safe+0x32/0x63
09:44:12   [<ffffffff81028a44>] ? read_hpet+0xd/0x10
09:44:12   [<ffffffff81065863>] ? timekeeping_get_ns+0xd/0x2a
09:44:12   [<ffffffff81106a34>] ? sys_select+0x88/0xad
09:44:12   [<ffffffff81347b52>] ? system_call_fastpath+0x16/0x1b
09:44:12  Mem-Info:
09:44:12  Node 0 DMA per-cpu:
09:44:12  CPU    0: hi:    0, btch:   1 usd:   0
09:44:12  CPU    1: hi:    0, btch:   1 usd:   0
09:44:12  Node 0 DMA32 per-cpu:
09:44:12  CPU    0: hi:  186, btch:  31 usd:  96
09:44:12  CPU    1: hi:  186, btch:  31 usd:  61
09:44:12  Node 0 Normal per-cpu:
09:44:12  CPU    0: hi:  186, btch:  31 usd: 178
09:44:12  CPU    1: hi:  186, btch:  31 usd:  37
09:44:12  active_anon:992922 inactive_anon:263416 isolated_anon:0
09:44:12   active_file:59734 inactive_file:529995 isolated_file:0
09:44:12   unevictable:1 dirty:52839 writeback:339893 unstable:7544
09:44:12   free:55501 slab_reclaimable:33311 slab_unreclaimable:30518
09:44:12   mapped:18500 shmem:43519 pagetables:21479 bounce:0
09:44:12  Node 0 DMA free:15908kB min:128kB low:160kB high:192kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15684kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
09:44:12  lowmem_reserve[]: 0 2960 7947 7947
09:44:12  Node 0 DMA32 free:153280kB min:25128kB low:31408kB high:37692kB active_anon:1579176kB inactive_anon:524080kB active_file:33708kB inactive_file:618072kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3031688kB mlocked:0kB dirty:81192kB writeback:322428kB mapped:6704kB shmem:67068kB slab_reclaimable:41408kB slab_unreclaimable:30268kB kernel_stack:2216kB pagetables:24408kB unstable:10048kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:12  lowmem_reserve[]: 0 0 4986 4986
09:44:12  Node 0 Normal free:52816kB min:42324kB low:52904kB high:63484kB active_anon:2392512kB inactive_anon:529584kB active_file:205228kB inactive_file:1501908kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:5106560kB mlocked:4kB dirty:130164kB writeback:1037144kB mapped:67296kB shmem:107008kB slab_reclaimable:91836kB slab_unreclaimable:91804kB kernel_stack:4216kB pagetables:61508kB unstable:20128kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:12  lowmem_reserve[]: 0 0 0 0
09:44:12  Node 0 DMA: 1*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15908kB
09:44:12  Node 0 DMA32: 37156*4kB 0*8kB 1*16kB 1*32kB 0*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 1*4096kB = 153280kB
09:44:12  Node 0 Normal: 12180*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 52816kB
09:44:12  676507 total pagecache pages
09:44:12  43251 pages in swap cache
09:44:12  Swap cache stats: add 803319, delete 760068, find 297792/318561
09:44:12  Free swap  = 1763732kB
09:44:12  Total swap = 4106248kB
09:44:12  2080752 pages RAM
09:44:12  57163 pages reserved
09:44:12  988140 pages shared
09:44:12  1496507 pages non-shared
09:44:12  ieee80211 phy0: failed to reallocate TX buffer
09:44:12  kworker/0:1: page allocation failure: order:1, mode:0x20
09:44:12  Pid: 8162, comm: kworker/0:1 Tainted: G           O 3.2.5amd64-volpreempt-noide-20120208 #1
09:44:12  Call Trace:
09:44:12   <IRQ>  [<ffffffff810b755a>] ? warn_alloc_failed+0x11a/0x12d
09:44:12   [<ffffffff810ba394>] ? __alloc_pages_nodemask+0x6b2/0x726
09:44:12   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:12   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:12   [<ffffffff810ea421>] ? fallback_alloc+0x123/0x1c2
09:44:12   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:12   [<ffffffff810ea923>] ? __kmalloc+0xba/0x112
09:44:12   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:12   [<ffffffffa07a81c0>] ? ieee80211_skb_resize+0x64/0x9d [mac80211]
09:44:12   [<ffffffffa07aa087>] ? ieee80211_subif_start_xmit+0x68e/0x80c [mac80211]
09:44:12   [<ffffffffa07922c8>] ? ieee80211_tx_status_irqsafe+0x2e/0x7f [mac80211]
09:44:12   [<ffffffff812877f3>] ? dev_hard_start_xmit+0x3fc/0x543
09:44:12   [<ffffffff81070551>] ? arch_local_irq_save+0x11/0x17
09:44:12   [<ffffffff8129da01>] ? sch_direct_xmit+0x5e/0x12f
09:44:12   [<ffffffff8129dbc9>] ? __qdisc_run+0xf7/0x10f
09:44:12   [<ffffffff81282d56>] ? net_tx_action+0xf1/0x128
09:44:12   [<ffffffff8104bc88>] ? __do_softirq+0xb9/0x177
09:44:12   [<ffffffff8103a946>] ? check_preempt_wakeup+0x10c/0x18e
09:44:12   [<ffffffff81349dac>] ? call_softirq+0x1c/0x30
09:44:12   [<ffffffff8100f875>] ? do_softirq+0x3c/0x7b
09:44:12   [<ffffffff8104bef0>] ? irq_exit+0x3c/0x9a
09:44:12   [<ffffffff8100f5a5>] ? do_IRQ+0x82/0x98
09:44:12   [<ffffffff81342e2e>] ? common_interrupt+0x6e/0x6e
09:44:12   <EOI>  [<ffffffffa0089052>] ? dec128+0x15a/0x80c [aes_x86_64]
09:44:12   [<ffffffff8118f263>] ? crypto_cbc_decrypt_inplace.isra.4+0x84/0xef
09:44:12   [<ffffffffa06bb6ee>] ? decode_attr_time+0x2f/0x5d [nfs]
09:44:12   [<ffffffffa0089704>] ? dec128+0x80c/0x80c [aes_x86_64]
09:44:12   [<ffffffff8118f328>] ? crypto_cbc_decrypt+0x5a/0x10a
09:44:12   [<ffffffff8118756b>] ? async_decrypt+0x37/0x3c
09:44:12   [<ffffffffa0108df7>] ? crypt_convert+0x223/0x2b8 [dm_crypt]
09:44:12   [<ffffffffa0109185>] ? kcryptd_crypt+0x56/0x342 [dm_crypt]
09:44:12   [<ffffffffa010912f>] ? crypt_convert_init.isra.17+0x4f/0x4f [dm_crypt]
09:44:12   [<ffffffffa010912f>] ? crypt_convert_init.isra.17+0x4f/0x4f [dm_crypt]
09:44:12   [<ffffffffa010912f>] ? crypt_convert_init.isra.17+0x4f/0x4f [dm_crypt]
09:44:12   [<ffffffff8105ac3d>] ? process_one_work+0x163/0x284
09:44:12   [<ffffffff8105bc05>] ? worker_thread+0xc2/0x145
09:44:12   [<ffffffff8105bb43>] ? manage_workers.isra.23+0x15b/0x15b
09:44:12   [<ffffffff8105ed41>] ? kthread+0x76/0x7e
09:44:12   [<ffffffff81349cb4>] ? kernel_thread_helper+0x4/0x10
09:44:12   [<ffffffff8105eccb>] ? kthread_worker_fn+0x139/0x139
09:44:12   [<ffffffff81349cb0>] ? gs_change+0x13/0x13
09:44:12  Mem-Info:
09:44:12  Node 0 DMA per-cpu:
09:44:12  CPU    0: hi:    0, btch:   1 usd:   0
09:44:12  CPU    1: hi:    0, btch:   1 usd:   0
09:44:12  Node 0 DMA32 per-cpu:
09:44:12  CPU    0: hi:  186, btch:  31 usd:  77
09:44:12  CPU    1: hi:  186, btch:  31 usd:  53
09:44:12  Node 0 Normal per-cpu:
09:44:12  CPU    0: hi:  186, btch:  31 usd: 165
09:44:12  CPU    1: hi:  186, btch:  31 usd:  64
09:44:12  active_anon:992922 inactive_anon:263441 isolated_anon:0
09:44:12   active_file:59734 inactive_file:530249 isolated_file:0
09:44:12   unevictable:1 dirty:52950 writeback:339764 unstable:7673
09:44:12   free:55214 slab_reclaimable:33311 slab_unreclaimable:30507
09:44:12   mapped:18500 shmem:43519 pagetables:21479 bounce:0
09:44:12  Node 0 DMA free:15908kB min:128kB low:160kB high:192kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15684kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
09:44:12  lowmem_reserve[]: 0 2960 7947 7947
09:44:12  Node 0 DMA32 free:152124kB min:25128kB low:31408kB high:37692kB active_anon:1579176kB inactive_anon:524180kB active_file:33708kB inactive_file:618972kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3031688kB mlocked:0kB dirty:81636kB writeback:322428kB mapped:6704kB shmem:67068kB slab_reclaimable:41408kB slab_unreclaimable:30456kB kernel_stack:2216kB pagetables:24408kB unstable:10048kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:12  lowmem_reserve[]: 0 0 4986 4986
09:44:12  Node 0 Normal free:52824kB min:42324kB low:52904kB high:63484kB active_anon:2392512kB inactive_anon:529584kB active_file:205228kB inactive_file:1502024kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:5106560kB mlocked:4kB dirty:130164kB writeback:1036628kB mapped:67296kB shmem:107008kB slab_reclaimable:91836kB slab_unreclaimable:91572kB kernel_stack:4216kB pagetables:61508kB unstable:20644kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:12  lowmem_reserve[]: 0 0 0 0
09:44:12  Node 0 DMA: 1*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15908kB
09:44:12  Node 0 DMA32: 36855*4kB 0*8kB 0*16kB 1*32kB 1*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 1*4096kB = 152124kB
09:44:12  Node 0 Normal: 12182*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 52824kB
09:44:12  676809 total pagecache pages
09:44:12  43260 pages in swap cache
09:44:12  Swap cache stats: add 803337, delete 760077, find 297801/318574
09:44:12  Free swap  = 1763768kB
09:44:12  Total swap = 4106248kB
09:44:12  2080752 pages RAM
09:44:12  57163 pages reserved
09:44:12  988161 pages shared
09:44:12  1496613 pages non-shared
09:44:12  ieee80211 phy0: failed to reallocate TX buffer
09:44:13  firefox-bin: page allocation failure: order:1, mode:0x20
09:44:13  Pid: 6697, comm: firefox-bin Tainted: G           O 3.2.5amd64-volpreempt-noide-20120208 #1
09:44:13  Call Trace:
09:44:13   <IRQ>  [<ffffffff810b755a>] ? warn_alloc_failed+0x11a/0x12d
09:44:13   [<ffffffff810ba394>] ? __alloc_pages_nodemask+0x6b2/0x726
09:44:13   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:13   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:13   [<ffffffff810ea421>] ? fallback_alloc+0x123/0x1c2
09:44:13   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:13   [<ffffffff810ea923>] ? __kmalloc+0xba/0x112
09:44:13   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:13   [<ffffffffa07a81c0>] ? ieee80211_skb_resize+0x64/0x9d [mac80211]
09:44:13   [<ffffffffa07aa087>] ? ieee80211_subif_start_xmit+0x68e/0x80c [mac80211]
09:44:13   [<ffffffff812877f3>] ? dev_hard_start_xmit+0x3fc/0x543
09:44:13   [<ffffffff8129da01>] ? sch_direct_xmit+0x5e/0x12f
09:44:13   [<ffffffff8129dbc9>] ? __qdisc_run+0xf7/0x10f
09:44:13   [<ffffffff81282d56>] ? net_tx_action+0xf1/0x128
09:44:13   [<ffffffff8104bc88>] ? __do_softirq+0xb9/0x177
09:44:13   [<ffffffff8103a95f>] ? check_preempt_wakeup+0x125/0x18e
09:44:13   [<ffffffff81349dac>] ? call_softirq+0x1c/0x30
09:44:13   [<ffffffff8100f875>] ? do_softirq+0x3c/0x7b
09:44:13   [<ffffffff8104bef0>] ? irq_exit+0x3c/0x9a
09:44:13   [<ffffffff8100f5a5>] ? do_IRQ+0x82/0x98
09:44:13   [<ffffffff81342e2e>] ? common_interrupt+0x6e/0x6e
09:44:13   <EOI>  [<ffffffff81347c84>] ? sysret_audit+0x16/0x20
09:44:13  Mem-Info:
09:44:13  Node 0 DMA per-cpu:
09:44:13  CPU    0: hi:    0, btch:   1 usd:   0
09:44:13  CPU    1: hi:    0, btch:   1 usd:   0
09:44:13  Node 0 DMA32 per-cpu:
09:44:13  CPU    0: hi:  186, btch:  31 usd:  78
09:44:13  CPU    1: hi:  186, btch:  31 usd:  66
09:44:13  Node 0 Normal per-cpu:
09:44:13  CPU    0: hi:  186, btch:  31 usd: 165
09:44:13  CPU    1: hi:  186, btch:  31 usd:  70
09:44:13  active_anon:992947 inactive_anon:263499 isolated_anon:0
09:44:13   active_file:59734 inactive_file:535571 isolated_file:0
09:44:13   unevictable:1 dirty:56763 writeback:339764 unstable:7673
09:44:13   free:49597 slab_reclaimable:33311 slab_unreclaimable:30582
09:44:13   mapped:18500 shmem:43562 pagetables:21479 bounce:0
09:44:13  Node 0 DMA free:15908kB min:128kB low:160kB high:192kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15684kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
09:44:13  lowmem_reserve[]: 0 2960 7947 7947
09:44:13  Node 0 DMA32 free:129656kB min:25128kB low:31408kB high:37692kB active_anon:1579276kB inactive_anon:524180kB active_file:33708kB inactive_file:640772kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3031688kB mlocked:0kB dirty:92588kB writeback:322428kB mapped:6704kB shmem:67068kB slab_reclaimable:41408kB slab_unreclaimable:30756kB kernel_stack:2216kB pagetables:24408kB unstable:10048kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:13  lowmem_reserve[]: 0 0 4986 4986
09:44:13  Node 0 Normal free:52824kB min:42324kB low:52904kB high:63484kB active_anon:2392512kB inactive_anon:529816kB active_file:205228kB inactive_file:1501512kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:5106560kB mlocked:4kB dirty:134464kB writeback:1036628kB mapped:67296kB shmem:107180kB slab_reclaimable:91836kB slab_unreclaimable:91572kB kernel_stack:4216kB pagetables:61508kB unstable:20644kB bounce:0kB writeback_tmp:0kB pages_scanned:1703 all_unreclaimable? no
09:44:13  lowmem_reserve[]: 0 0 0 0
09:44:13  Node 0 DMA: 1*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15908kB
09:44:13  Node 0 DMA32: 31254*4kB 0*8kB 0*16kB 1*32kB 0*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 1*4096kB = 129656kB
09:44:13  Node 0 Normal: 12182*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 52824kB
09:44:13  682242 total pagecache pages
09:44:13  43259 pages in swap cache
09:44:13  Swap cache stats: add 803338, delete 760079, find 297802/318575
09:44:13  Free swap  = 1763768kB
09:44:13  Total swap = 4106248kB
09:44:13  2080752 pages RAM
09:44:13  57163 pages reserved
09:44:13  992010 pages shared
09:44:13  1498343 pages non-shared
09:44:13  ieee80211 phy0: failed to reallocate TX buffer
09:44:13  firefox-bin: page allocation failure: order:1, mode:0x20
09:44:13  Pid: 6706, comm: firefox-bin Tainted: G           O 3.2.5amd64-volpreempt-noide-20120208 #1
09:44:13  Call Trace:
09:44:13   <IRQ>  [<ffffffff810b755a>] ? warn_alloc_failed+0x11a/0x12d
09:44:13   [<ffffffff810ba394>] ? __alloc_pages_nodemask+0x6b2/0x726
09:44:13   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:13   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:13   [<ffffffff810ea421>] ? fallback_alloc+0x123/0x1c2
09:44:13   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:13   [<ffffffff810ea923>] ? __kmalloc+0xba/0x112
09:44:13   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:13   [<ffffffffa07a81c0>] ? ieee80211_skb_resize+0x64/0x9d [mac80211]
09:44:13   [<ffffffffa07aa087>] ? ieee80211_subif_start_xmit+0x68e/0x80c [mac80211]
09:44:13   [<ffffffffa07922c8>] ? ieee80211_tx_status_irqsafe+0x2e/0x7f [mac80211]
09:44:13   [<ffffffff812877f3>] ? dev_hard_start_xmit+0x3fc/0x543
09:44:13   [<ffffffff81070551>] ? arch_local_irq_save+0x11/0x17
09:44:13   [<ffffffff8129da01>] ? sch_direct_xmit+0x5e/0x12f
09:44:13   [<ffffffff8129dbc9>] ? __qdisc_run+0xf7/0x10f
09:44:13   [<ffffffff81282d56>] ? net_tx_action+0xf1/0x128
09:44:13   [<ffffffff8104bc88>] ? __do_softirq+0xb9/0x177
09:44:13   [<ffffffff8106a67b>] ? clockevents_program_event+0xaa/0xce
09:44:13   [<ffffffff81349dac>] ? call_softirq+0x1c/0x30
09:44:13   [<ffffffff8100f875>] ? do_softirq+0x3c/0x7b
09:44:13   [<ffffffff8104bef0>] ? irq_exit+0x3c/0x9a
09:44:13   [<ffffffff8100f5a5>] ? do_IRQ+0x82/0x98
09:44:13   [<ffffffff81342e2e>] ? common_interrupt+0x6e/0x6e
09:44:13   <EOI>  [<ffffffff81347c84>] ? sysret_audit+0x16/0x20
09:44:13  Mem-Info:
09:44:13  Node 0 DMA per-cpu:
09:44:13  CPU    0: hi:    0, btch:   1 usd:   0
09:44:13  CPU    1: hi:    0, btch:   1 usd:   0
09:44:13  Node 0 DMA32 per-cpu:
09:44:13  CPU    0: hi:  186, btch:  31 usd:  69
09:44:13  CPU    1: hi:  186, btch:  31 usd:  35
09:44:13  Node 0 Normal per-cpu:
09:44:13  CPU    0: hi:  186, btch:  31 usd: 178
09:44:13  CPU    1: hi:  186, btch:  31 usd:  68
09:44:13  active_anon:992947 inactive_anon:263499 isolated_anon:0
09:44:13   active_file:59734 inactive_file:536198 isolated_file:0
09:44:13   unevictable:1 dirty:57182 writeback:339764 unstable:7673
09:44:13   free:49028 slab_reclaimable:33311 slab_unreclaimable:30581
09:44:13   mapped:18500 shmem:43562 pagetables:21479 bounce:0
09:44:13  Node 0 DMA free:15908kB min:128kB low:160kB high:192kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15684kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
09:44:13  lowmem_reserve[]: 0 2960 7947 7947
09:44:13  Node 0 DMA32 free:127380kB min:25128kB low:31408kB high:37692kB active_anon:1579276kB inactive_anon:524180kB active_file:33708kB inactive_file:643272kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3031688kB mlocked:0kB dirty:93920kB writeback:322428kB mapped:6704kB shmem:67068kB slab_reclaimable:41408kB slab_unreclaimable:30752kB kernel_stack:2216kB pagetables:24408kB unstable:10048kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:13  lowmem_reserve[]: 0 0 4986 4986
09:44:13  Node 0 Normal free:52824kB min:42324kB low:52904kB high:63484kB active_anon:2392512kB inactive_anon:529816kB active_file:205228kB inactive_file:1501520kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:5106560kB mlocked:4kB dirty:134808kB writeback:1036628kB mapped:67296kB shmem:107180kB slab_reclaimable:91836kB slab_unreclaimable:91572kB kernel_stack:4216kB pagetables:61508kB unstable:20644kB bounce:0kB writeback_tmp:0kB pages_scanned:112 all_unreclaimable? no
09:44:13  lowmem_reserve[]: 0 0 0 0
09:44:13  Node 0 DMA: 1*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15908kB
09:44:13  Node 0 DMA32: 30640*4kB 1*8kB 1*16kB 0*32kB 1*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 1*4096kB = 127256kB
09:44:13  Node 0 Normal: 12182*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 52824kB
09:44:13  682828 total pagecache pages
09:44:13  43261 pages in swap cache
09:44:13  Swap cache stats: add 803340, delete 760079, find 297802/318575
09:44:13  Free swap  = 1763760kB
09:44:13  Total swap = 4106248kB
09:44:13  2080752 pages RAM
09:44:13  57163 pages reserved
09:44:13  992430 pages shared
09:44:13  1498647 pages non-shared
09:44:13  ieee80211 phy0: failed to reallocate TX buffer
09:44:13  kworker/0:0: page allocation failure: order:1, mode:0x20
09:44:13  Pid: 7949, comm: kworker/0:0 Tainted: G           O 3.2.5amd64-volpreempt-noide-20120208 #1
09:44:13  Call Trace:
09:44:13   <IRQ>  [<ffffffff810b755a>] ? warn_alloc_failed+0x11a/0x12d
09:44:13   [<ffffffff810ba394>] ? __alloc_pages_nodemask+0x6b2/0x726
09:44:13   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:13   [<ffffffff810e9081>] ? kmem_getpages+0x4c/0xd9
09:44:13   [<ffffffff810ea421>] ? fallback_alloc+0x123/0x1c2
09:44:13   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:13   [<ffffffff810ea923>] ? __kmalloc+0xba/0x112
09:44:13   [<ffffffff8127daae>] ? pskb_expand_head+0xe0/0x24a
09:44:13   [<ffffffffa07a81c0>] ? ieee80211_skb_resize+0x64/0x9d [mac80211]
09:44:13   [<ffffffffa07aa087>] ? ieee80211_subif_start_xmit+0x68e/0x80c [mac80211]
09:44:13   [<ffffffffa07922c8>] ? ieee80211_tx_status_irqsafe+0x2e/0x7f [mac80211]
09:44:13   [<ffffffff812877f3>] ? dev_hard_start_xmit+0x3fc/0x543
09:44:13   [<ffffffff8129da01>] ? sch_d9704>] ? dec128+0x80c/0x80c [aes_x86_64]
09:44:13   [<ffffffff810349f1>] ? set_task_rq+0x23/0x35
09:44:13   [<ffffffff8118f328>] ? crypto_cbc_decrypt+0x5a/0x10a
09:44:13   [<ffffffff8118756b>] ? async_decrypt+0x37/0x3c
09:44:13   [<ffffffffa0108df7>] ? crypt_convert+0x223/0x2b8 [dm_crypt]
09:44:13   [<ffffffffa0109185>] ? kcryptd_crypt+0x56/0x342 [dm_crypt]
09:44:13   [<ffffffff810388e2>] ? finish_task_switch+0x4e/0xb9
09:44:13   [<ffffffff811a4021>] ? cfq_init_queue+0x403/0x403
09:44:13   [<ffffffffa010912f>] ? crypt_convert_init.isra.17+0x4f/0x4f [dm_crypt]
09:44:13   [<ffffffff8105ac3d>] ? process_one_work+0x163/0x284
09:44:13   [<ffffffff8105bc05>] ? worker_thread+0xc2/0x145
09:44:13   [<ffffffff8105bb43>] ? manage_workers.isra.23+0x15b/0x15b
09:44:13   [<ffffffff8105ed41>] ? kthread+0x76/0x7e
09:44:13   [<ffffffff81349cb4>] ? kernel_thread_helper+0x4/0x10
09:44:13   [<ffffffff8105eccb>] ? kthread_worker_fn+0x139/0x139
09:44:13   [<ffffffff81349cb0>] ? gs_change+0x13/0x13
09:44:13  Mem-Info:
09:44:13  Node 0 DMA per-cpu:
09:44:13  CPU    0: hi:    0, btch:   1 usd:   0
09:44:13  CPU    1: hi:    0, btch:   1 usd:   0
09:44:13  Node 0 DMA32 per-cpu:
09:44:13  CPU    0: hi:  186, btch:  31 usd:  17
09:44:13  CPU    1: hi:  186, btch:  31 usd:   0
09:44:13  Node 0 Normal per-cpu:
09:44:13  CPU    0: hi:  186, btch:  31 usd:  69
09:44:13  CPU    1: hi:  186, btch:  31 usd: 125
09:44:13  active_anon:992968 inactive_anon:263499 isolated_anon:1
09:44:13   active_file:59749 inactive_file:538771 isolated_file:12
09:44:13   unevictable:1 dirty:59393 writeback:339244 unstable:8193
09:44:13   free:46512 slab_reclaimable:33220 slab_unreclaimable:30692
09:44:13   mapped:18504 shmem:43598 pagetables:21479 bounce:0
09:44:13  Node 0 DMA free:15908kB min:128kB low:160kB high:192kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15684kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
09:44:13  lowmem_reserve[]: 0 2960 7947 7947
09:44:13  Node 0 DMA32 free:117308kB min:25128kB low:31408kB high:37692kB active_anon:1579336kB inactive_anon:524204kB active_file:33764kB inactive_file:653796kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3031688kB mlocked:0kB dirty:99216kB writeback:322356kB mapped:6716kB shmem:67128kB slab_reclaimable:41324kB slab_unreclaimable:30888kB kernel_stack:2216kB pagetables:24408kB unstable:10120kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:13  lowmem_reserve[]: 0 0 4986 4986
09:44:13  Node 0 Normal free:52832kB min:42324kB low:52904kB high:63484kB active_anon:2392536kB inactive_anon:529792kB active_file:205232kB inactive_file:1501288kB unevictable:4kB isolated(anon):4kB isolated(file):48kB present:5106560kB mlocked:4kB dirty:138356kB writeback:1034620kB mapped:67300kB shmem:107264kB slab_reclaimable:91556kB slab_unreclaimable:91880kB kernel_stack:4216kB pagetables:61508kB unstable:22652kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
09:44:13  lowmem_reserve[]: 0 0 0 0
09:44:13  Node 0 DMA: 1*4kB 0*8kB 0*16kB 1*32kB 2*64kB 1*128kB 1*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15908kB
09:44:13  Node 0 DMA32: 28147*4kB 0*8kB 1*16kB 1*32kB 1*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 1*4096kB = 117308kB
09:44:13  Node 0 Normal: 12094*4kB 5*8kB 12*16kB 4*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 52832kB
09:44:13  685431 total pagecache pages
09:44:13  43261 pages in swap cache
09:44:13  Swap cache stats: add 803341, delete 760080, find 297802/318575
09:44:13  Free swap  = 1763756kB
09:44:13  Total swap = 4106248kB
09:44:13  2080752 pages RAM
09:44:13  57163 pages reserved
09:44:13  994159 pages shared
09:44:13  1498949 pages non-shared
09:44:13  ieee80211 phy0: failed to reallocate TX buffer
09:44:13  kworker/0:0: page allocation failure: order:1, mode:0x20

Marc
-- 
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/  

Re: 3.2.8/amd64 full interrupt hangs and deadlocks under big network copies (page allocation failure)

From: David Miller <davem@davemloft.net>
Date: 2012-04-09 18:12:56

From: Marc MERLIN <redacted>
Date: Mon, 9 Apr 2012 10:20:51 -0700
Any idea what's going on, what bucket of RAM is an issue for the driver
(total RAM is more than plenty), and where I should go from there?
The wireless layer is allocating high-order pages, so it's
not the amount of ram, it's the fragmentation of it leading
to a lack of those high-order pages.
Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help