Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751500AbZJEFOm (ORCPT ); Mon, 5 Oct 2009 01:14:42 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1750845AbZJEFOl (ORCPT ); Mon, 5 Oct 2009 01:14:41 -0400 Received: from cpsmtpm-eml105.kpnxchange.com ([195.121.3.9]:52418 "EHLO CPSMTPM-EML105.kpnxchange.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750730AbZJEFOk convert rfc822-to-8bit (ORCPT ); Mon, 5 Oct 2009 01:14:40 -0400 From: Frans Pop To: Mel Gorman Subject: Re: [Bug #14141] order 2 page allocation failures in iwlagn Date: Mon, 5 Oct 2009 07:13:58 +0200 User-Agent: KMail/1.9.9 Cc: "Rafael J. Wysocki" , Linux Kernel Mailing List , Kernel Testers List , "Pekka Enberg" , Reinette Chatre , Bartlomiej Zolnierkiewicz , Karol Lewandowski , linux-mm@kvack.org References: <3onW63eFtRF.A.xXH.oMTxKB@chimera> <200910021111.55749.elendil@planet.nl> In-Reply-To: <200910021111.55749.elendil@planet.nl> MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: 8BIT Content-Disposition: inline Message-Id: <200910050714.01908.elendil@planet.nl> X-OriginalArrivalTime: 05 Oct 2009 05:14:02.0304 (UTC) FILETIME=[A6F76C00:01CA457A] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 10801 Lines: 206 On Friday 02 October 2009, Frans Pop wrote: > On Thursday 01 October 2009, Rafael J. Wysocki wrote: > > Bug-Entry     : http://bugzilla.kernel.org/show_bug.cgi?id=14141 > > Subject       : order 2 page allocation failures in iwlagn > > Submitter     : Frans Pop > > Date          : 2009-09-06 7:40 (26 days old) > > References    : http://marc.info/?l=linux-kernel&m=125222287419691&w=4 > > Handled-By    : Pekka Enberg > > I'm not sure about this. > > The error messages from failed allocations should now be a lot less as a > result of this commit: > commit f82a924cc88a5541df1d4b9d38a0968cd077a051 > Author: Reinette Chatre > Date:   Thu Sep 17 10:43:56 2009 -0700 >     iwlwifi: reduce noise when skb allocation fails > > That commit is in mainline, and I'm not sure if it is important enough > for a stable update (AFAICT it's not listed for 2.6.31.2). > > That commit is mostly cosmetic, but possibly the real regression is not > in iwlagn but in the way memory is freed/defragmented. That aspect was > also reported by Bartlomiej (#14016) and was extensively discussed > (without a clear conclusion) here: http://lkml.org/lkml/2009/8/26/140. I may be getting somewhere with this. I just got the allocation failures included below on .32-rc3. Note that these are not the "fixable" failures that got suppressed with the commit referenced above, but the "this could affect networking" failures that are still reported. What I was doing when I got them is also interesting: - a kernel build - a gitk for the kernel tree (with full history this uses ~40% of memory) - by mistake I then started a _second_ gitk The second gitk (which shows as 'wish8.5' in top) caused a massive swap out which brought the system to a standstill for a while (with huge latencies as well, including a completely stuck mouse cursor, which happens rarely). The system has 2GB RAM + 2GB swap, so IIUC there is no danger of getting into an OOM as the first gitk can be swapped out completely. I'll dig into this a bit more as it looks like this should be reproducible, probably even without the kernel build. Next step is to see how .30 behaves in the same situation. Even if it is reproducible with .30, I wonder if the kernel shouldn't be more robust in this situation. Currently it seems to allow one single process to claim so much memory before swapping out that "normal" operation of other processes is affected. I can understand that such a situation may be hard to avoid on a very busy system where multiple processes start claiming (a lot of) memory at roughly the same time, but I'd say it should be avoidable if a single process is the culprit. BTW, the system recovered completely, although that took some time (the first gitk remained visible in top long after I closed its window; I think because the system was busy swapping it back in before terminating it). Cheers, FJP kcryptd: page allocation failure. order:2, mode:0x4020 Pid: 1483, comm: kcryptd Not tainted 2.6.32-rc3 #22 Call Trace: [] __alloc_pages_nodemask+0x5a2/0x5ec [] ? _spin_unlock+0x9/0xb [] ? __alloc_skb+0x3c/0x15b [] ? iwl_rx_allocate+0x8f/0x305 [iwlcore] [] __get_free_pages+0x12/0x41 [] __kmalloc_track_caller+0x3b/0xed [] __alloc_skb+0x66/0x15b [] iwl_rx_allocate+0x8f/0x305 [iwlcore] [] iwl_rx_replenish_now+0x16/0x23 [iwlcore] [] iwl_rx_handle+0x3a8/0x3c1 [iwlagn] [] ? sched_clock_local+0x1c/0x80 [] iwl_irq_tasklet_legacy+0x52c/0x7a4 [iwlagn] [] ? __iwl_read32+0xa5/0xb4 [iwlcore] [] tasklet_action+0x71/0xbc [] __do_softirq+0x96/0x11b [] call_softirq+0x1c/0x28 [] do_softirq+0x33/0x6b [] irq_exit+0x36/0x75 [] do_IRQ+0xa3/0xba [] ret_from_intr+0x0/0xa [] ? scatterwalk_start+0x11/0x19 [] ? blkcipher_walk_first+0x173/0x196 [] ? blkcipher_walk_done+0xe6/0x1b8 [] ? blkcipher_walk_virt+0x1a/0x1d [] ? crypto_cbc_encrypt+0x43/0x18e [cbc] [] ? blk_recount_segments+0x1b/0x2c [] ? aes_encrypt+0x0/0xf [aes_x86_64] [] ? async_encrypt+0x38/0x3a [] ? crypt_convert+0x1f9/0x28b [dm_crypt] [] ? kcryptd_crypt+0x423/0x449 [dm_crypt] [] ? kcryptd_crypt+0x0/0x449 [dm_crypt] [] ? worker_thread+0x146/0x1d8 [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1d8 [] ? kthread+0x7d/0x85 [] ? child_rip+0xa/0x20 [] ? kthread+0x0/0x85 [] ? 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: 171 CPU 1: hi: 186, btch: 31 usd: 177 active_anon:298532 inactive_anon:100163 isolated_anon:52 active_file:3993 inactive_file:4001 isolated_file:12 unevictable:399 dirty:0 writeback:76102 unstable:0 buffer:125 free:14107 slab_reclaimable:4510 slab_unreclaimable:20421 mapped:7949 shmem:0 pagetables:4437 bounce:0 DMA free:7928kB min:40kB low:48kB high:60kB active_anon:3340kB inactive_anon:3608kB active_file:384kB inactive_file:472kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15336kB mlocked:0kB dirty:0kB writeback:80kB mapped:256kB shmem:0kB slab_reclaimable:12kB slab_unreclaimable:104kB kernel_stack:0kB pagetables:16kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no lowmem_reserve[]: 0 1976 1976 1976 DMA32 free:48500kB min:5664kB low:7080kB high:8496kB active_anon:1190788kB inactive_anon:397044kB active_file:15588kB inactive_file:15532kB unevictable:1596kB isolated(anon):208kB isolated(file):48kB present:2023748kB mlocked:1596kB dirty:0kB writeback:304328kB mapped:31540kB shmem:0kB slab_reclaimable:18028kB slab_unreclaimable:81496kB kernel_stack:1672kB pagetables:17732kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no lowmem_reserve[]: 0 0 0 0 DMA: 19*4kB 13*8kB 3*16kB 7*32kB 11*64kB 11*128kB 5*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 7940kB DMA32: 9299*4kB 1341*8kB 4*16kB 0*32kB 0*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 48500kB 98572 total pagecache pages 90213 pages in swap cache Swap cache stats: add 175874, delete 85661, find 7850/8731 Free swap = 1425944kB Total swap = 2097144kB 518064 pages RAM 10350 pages reserved 82388 pages shared 437481 pages non-shared iwlagn 0000:10:00.0: Failed to allocate SKB buffer with GFP_ATOMIC. Only 0 free buffers remaining. swapper: page allocation failure. order:2, mode:0x4020 Pid: 0, comm: swapper Not tainted 2.6.32-rc3 #22 Call Trace: [] __alloc_pages_nodemask+0x5a2/0x5ec [] ? _spin_unlock+0x9/0xb [] ? __alloc_skb+0x3c/0x15b [] ? iwl_rx_allocate+0x8f/0x305 [iwlcore] [] __get_free_pages+0x12/0x41 [] __kmalloc_track_caller+0x3b/0xed [] __alloc_skb+0x66/0x15b [] iwl_rx_allocate+0x8f/0x305 [iwlcore] [] iwl_rx_replenish_now+0x16/0x23 [iwlcore] [] iwl_rx_handle+0x3a8/0x3c1 [iwlagn] [] iwl_irq_tasklet_legacy+0x52c/0x7a4 [iwlagn] [] ? __iwl_read32+0xa5/0xb4 [iwlcore] [] tasklet_action+0x71/0xbc [] __do_softirq+0x96/0x11b [] call_softirq+0x1c/0x28 [] do_softirq+0x33/0x6b [] irq_exit+0x36/0x75 [] do_IRQ+0xa3/0xba [] ret_from_intr+0x0/0xa [] ? acpi_idle_enter_simple+0xf9/0x127 [processor] [] ? acpi_idle_enter_simple+0xef/0x127 [processor] [] ? cpuidle_idle_call+0x8c/0xc7 [] ? cpu_idle+0x55/0x8d [] ? rest_init+0x61/0x63 [] ? start_kernel+0x348/0x353 [] ? x86_64_start_reservations+0xaa/0xae [] ? x86_64_start_kernel+0xe1/0xe8 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: 171 CPU 1: hi: 186, btch: 31 usd: 155 active_anon:297901 inactive_anon:99948 isolated_anon:52 active_file:3920 inactive_file:3948 isolated_file:12 unevictable:399 dirty:0 writeback:34634 unstable:0 buffer:125 free:23390 slab_reclaimable:4510 slab_unreclaimable:11714 mapped:7819 shmem:0 pagetables:4437 bounce:0 DMA free:7908kB min:40kB low:48kB high:60kB active_anon:3340kB inactive_anon:3608kB active_file:384kB inactive_file:472kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15336kB mlocked:0kB dirty:0kB writeback:36kB mapped:256kB shmem:0kB slab_reclaimable:12kB slab_unreclaimable:12kB kernel_stack:0kB pagetables:16kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no lowmem_reserve[]: 0 1976 1976 1976 DMA32 free:85652kB min:5664kB low:7080kB high:8496kB active_anon:1188264kB inactive_anon:396184kB active_file:15296kB inactive_file:15320kB unevictable:1596kB isolated(anon):208kB isolated(file):48kB present:2023748kB mlocked:1596kB dirty:0kB writeback:138500kB mapped:31020kB shmem:0kB slab_reclaimable:18028kB slab_unreclaimable:46844kB kernel_stack:1672kB pagetables:17732kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no lowmem_reserve[]: 0 0 0 0 DMA: 17*4kB 12*8kB 4*16kB 6*32kB 11*64kB 11*128kB 5*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 7908kB DMA32: 12419*4kB 4439*8kB 1*16kB 0*32kB 1*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 85652kB 97616 total pagecache pages 89394 pages in swap cache Swap cache stats: add 175906, delete 86512, find 7850/8733 Free swap = 1425864kB Total swap = 2097144kB 518064 pages RAM 10350 pages reserved 82282 pages shared 428383 pages non-shared iwlagn 0000:10:00.0: Failed to allocate SKB buffer with GFP_ATOMIC. Only 0 free buffers remaining. -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/