Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751069AbVK0OWJ (ORCPT ); Sun, 27 Nov 2005 09:22:09 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751077AbVK0OWI (ORCPT ); Sun, 27 Nov 2005 09:22:08 -0500 Received: from hera.kernel.org ([140.211.167.34]:42468 "EHLO hera.kernel.org") by vger.kernel.org with ESMTP id S1751069AbVK0OWH (ORCPT ); Sun, 27 Nov 2005 09:22:07 -0500 Date: Sun, 27 Nov 2005 06:42:31 -0200 From: Marcelo Tosatti To: Jan Kasprzak Cc: Andrew Morton , nickpiggin@yahoo.com.au, linux-kernel@vger.kernel.org Subject: Re: 2.6.14 kswapd eating too much CPU Message-ID: <20051127084231.GC20701@logos.cnet> References: <20051122125959.GR16080@fi.muni.cz> <20051122163550.160e4395.akpm@osdl.org> <20051123010122.GA7573@fi.muni.cz> <4383D1CC.4050407@yahoo.com.au> <20051123051358.GB7573@fi.muni.cz> <20051123131417.GH24091@fi.muni.cz> <20051123110241.528a0b37.akpm@osdl.org> <20051123202438.GE28142@fi.muni.cz> <20051123123531.470fc804.akpm@osdl.org> <20051124083141.GJ28142@fi.muni.cz> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20051124083141.GJ28142@fi.muni.cz> User-Agent: Mutt/1.5.5.1i Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 13260 Lines: 240 On Thu, Nov 24, 2005 at 09:31:41AM +0100, Jan Kasprzak wrote: > Andrew Morton wrote: > : > # dmesg -c >/dev/null; echo -n p >/proc/sysrq-trigger ; sleep 5; dmesg > : > SysRq : Show Regs > : > # > : > : You won't get anything useful from sysrq-p via /proc/sysrq-trigger - it'll > : just show the backtrace of the process `echo'. It has to be via the > : keyboard. > > OK, at the end of this mail I am attaching few instances of > ( top -n 1 -b -p 17,18 ; dmesg -c ) after sysrq-p entered via the > serial console. However, I have now kswapd0 at 99% CPU and kswapd1 at > about 50%, and sysrq-p is now apparently handled by the CPU1, so I get > traces of kswapd1 only. How can I switch the serial interrupt to CPU0? > > : If there's no keyboard, do `echo t > /proc/sysrq-trigger' to get an > : all-task backtrace, then locate the trace for kswapd in the resulting > : output. > > I had to increase CONFIG_LOG_BUF_SHIFT first, because sysrq-t > output was too long, but nevertheless - for the running processes there > are no call traces, just the note that the process is in the "R" state. Here > are few excerpts of sysrq-t: > > ----- > kswapd1 S ffff810100000000 0 17 1 18 11 (L-TLB) > ffff8101047bfea8 0000000000000046 ffff8101047bfe08 0000000000000292 > 0000000000000292 ffffffff80160589 ffff8101ae564240 000000008012cf35 > 0000000000000076 ffff8101ae564240 > Call Trace:{balance_pgdat+297} {kswapd+278} > {autoremove_wake_function+0} {autoremove_wake_function+0} > {child_rip+8} {flat_send_IPI_mask+0} > {kswapd+0} {child_rip+0} > kswapd0 R running task 0 18 1 33 17 (L-TLB) > ----- > kswapd1 S ffff810100000000 0 17 1 18 11 (L-TLB) > ffff8101047bfea8 0000000000000046 ffff8101047bfe08 0000000000000292 > 0000000000000292 ffffffff80160589 ffff8101ae564240 000000008012cf35 > 0000000000000076 ffff8101ae564240 > Call Trace:{balance_pgdat+297} {kswapd+278} > {autoremove_wake_function+0} {autoremove_wake_function+0} > {child_rip+8} {flat_send_IPI_mask+0} > {kswapd+0} {child_rip+0} > kswapd0 R running task 0 18 1 33 17 (L-TLB) > ----- Out of curiosity, what is the size of the inode cache from /proc/slabinfo at this moment? Because even though the traces shows kswapd trying to reclaim i-cache, the percentage of i-cache is really small: inode_cache 1164 1224 600 6 1 : tunables 54 27 8 : slabdata 204 204 0 dentry_cache 44291 48569 224 17 1 : tunables 120 60 8 : slabdata 2857 2857 51 Maybe you should also try profile/oprofile during the kswapd peeks? Just my two cents. > > And here are the sysrq-p outputs: > > top - 09:17:11 up 10:09, 2 users, load average: 13.56, 7.14, 3.45 > Tasks: 2 total, 2 running, 0 sleeping, 0 stopped, 0 zombie > Cpu(s): 2.2% us, 20.4% sy, 3.0% ni, 65.9% id, 6.6% wa, 0.1% hi, 1.8% si > Mem: 8173472k total, 5769752k used, 2403720k free, 35436k buffers > Swap: 14651256k total, 656k used, 14650600k free, 5388176k cached > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 18 root 15 0 0 0 0 R 91.9 0.0 118:24.00 kswapd0 > 17 root 15 0 0 0 0 R 49.8 0.0 35:17.26 kswapd1 > > SysRq : Show Regs > CPU 1: > Modules linked in: binfmt_misc floppy > Pid: 17, comm: kswapd1 Not tainted 2.6.15-rc2 #2 > RIP: 0010:[] {shrink_icache_memory+107} > RSP: 0000:ffff8101047bfd78 EFLAGS: 00000246 > RAX: 00000000ffffffff RBX: 00000000000000c8 RCX: ffff8101046f6140 > RDX: 0000000000000000 RSI: 00000000000000d0 RDI: ffffffff804683e0 > RBP: 0000000000200200 R08: ffff8101047be000 R09: 0000000000000003 > R10: 0000000000000000 R11: ffffffff8028caf0 R12: ffffffff8012c533 > R13: ffff8101047bfd18 R14: 0000000000000003 R15: 0000000000000296 > FS: 00002aaaaac3ed20(0000) GS:ffffffff80624880(0000) knlGS:00000000555565a0 > CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b > CR2: 00002aaaaacc1000 CR3: 00000001eeef9000 CR4: 00000000000006e0 > > Call Trace:{shrink_icache_memory+532} {shrink_slab+219} > {balance_pgdat+617} {kswapd+311} > {autoremove_wake_function+0} {autoremove_wake_function+0} > {child_rip+8} {flat_send_IPI_mask+0} > {kswapd+0} {child_rip+0} > > top - 09:17:28 up 10:09, 2 users, load average: 17.42, 8.31, 3.89 > Tasks: 2 total, 2 running, 0 sleeping, 0 stopped, 0 zombie > Cpu(s): 2.2% us, 20.4% sy, 3.0% ni, 65.9% id, 6.6% wa, 0.1% hi, 1.8% si > Mem: 8173472k total, 5980464k used, 2193008k free, 36076k buffers > Swap: 14651256k total, 656k used, 14650600k free, 5593984k cached > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 18 root 15 0 0 0 0 R 96.4 0.0 118:39.98 kswapd0 > 17 root 15 0 0 0 0 R 60.3 0.0 35:26.37 kswapd1 > > SysRq : Show Regs > CPU 1: > Modules linked in: binfmt_misc floppy > Pid: 17, comm: kswapd1 Not tainted 2.6.15-rc2 #2 > RIP: 0010:[] {_spin_lock+3} > RSP: 0000:ffff8101047bfd40 EFLAGS: 00000246 > RAX: 0000000000000000 RBX: ffffffff803e8951 RCX: ffff8101046f6140 > RDX: 0000000000000000 RSI: 00000000000000d0 RDI: ffffffff80468400 > RBP: 0000000000000296 R08: ffff8101047be000 R09: 0000000000000000 > R10: 0000000000000000 R11: 0000000000000000 R12: ffff8101047bfd88 > R13: ffff8101047bfcc8 R14: ffff8101046f6140 R15: ffffffff804683e8 > FS: 00002aaaaaab79e0(0000) GS:ffffffff80624880(0000) knlGS:00000000555565a0 > CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b > CR2: 000000000056f448 CR3: 000000003f0ee000 CR4: 00000000000006e0 > > Call Trace:{dispose_list+220} {shrink_icache_memory+11} > {shrink_icache_memory+476} {shrink_slab+219} > {balance_pgdat+617} {kswapd+311} > {autoremove_wake_function+0} {autoremove_wake_function+0} > {child_rip+8} {flat_send_IPI_mask+0} > {kswapd+0} {child_rip+0} > > top - 09:17:46 up 10:10, 2 users, load average: 15.03, 8.36, 4.00 > Tasks: 2 total, 2 running, 0 sleeping, 0 stopped, 0 zombie > Cpu(s): 2.2% us, 20.5% sy, 3.0% ni, 65.9% id, 6.6% wa, 0.1% hi, 1.8% si > Mem: 8173472k total, 6117468k used, 2056004k free, 36460k buffers > Swap: 14651256k total, 656k used, 14650600k free, 5731640k cached > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 18 root 15 0 0 0 0 R 86.2 0.0 118:56.67 kswapd0 > 17 root 15 0 0 0 0 R 60.1 0.0 35:36.46 kswapd1 > > SysRq : Show Regs > CPU 1: > Modules linked in: binfmt_misc floppy > Pid: 17, comm: kswapd1 Not tainted 2.6.15-rc2 #2 > RIP: 0010:[] {thread_return+94} > RSP: 0000:ffff8101047bfc08 EFLAGS: 00000246 > RAX: ffff810103841860 RBX: 000000000050fb40 RCX: 0000000000000018 > RDX: ffff810058446e40 RSI: ffff8101046f6140 RDI: 0000000000000000 > RBP: 0000000000000246 R08: ffff8101047be000 R09: 0000000000000004 > R10: 000000000050fb40 R11: 00000000ffffffff R12: ffffffff802645a8 > R13: 0000000000000296 R14: ffff8101de939700 R15: 0000000000000008 > FS: 00002aaaaaab79e0(0000) GS:ffffffff80624880(0000) knlGS:00000000555565a0 > CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b > CR2: 00002aaaaaaaf0b8 CR3: 000000003f0ee000 CR4: 00000000000006e0 > > Call Trace:{__wake_up_common+64} {__down+152} > {default_wake_function+0} {__down_failed+53} > {mempool_free_slab+0} {.text.lock.inode+5} > {shrink_slab+219} {balance_pgdat+617} {kswapd+311} {autoremove_wake_function+0} > {autoremove_wake_function+0} {child_rip+8} > {flat_send_IPI_mask+0} {kswapd+0} > {child_rip+0} > top - 09:18:32 up 10:10, 2 users, load average: 10.25, 8.02, 4.09 > Tasks: 2 total, 2 running, 0 sleeping, 0 stopped, 0 zombie > Cpu(s): 2.2% us, 20.5% sy, 3.0% ni, 65.8% id, 6.6% wa, 0.1% hi, 1.8% si > Mem: 8173472k total, 6259616k used, 1913856k free, 37192k buffers > Swap: 14651256k total, 656k used, 14650600k free, 5860380k cached > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 18 root 15 0 0 0 0 R 96.1 0.0 119:38.63 kswapd0 > 17 root 15 0 0 0 0 R 56.0 0.0 36:03.12 kswapd1 > > SysRq : Show Regs > CPU 1: > Modules linked in: binfmt_misc floppy > Pid: 17, comm: kswapd1 Not tainted 2.6.15-rc2 #2 > RIP: 0010:[] {shrink_icache_memory+551} > RSP: 0000:ffff8101047bfd78 EFLAGS: 00000256 > RAX: 0000000051eb851f RBX: 0000000000000000 RCX: 0000000000000018 > RDX: 0000000000000000 RSI: 00000000000000d0 RDI: 0000000000000000 > RBP: 0000000000200200 R08: ffff8101047be000 R09: 0000000000000000 > R10: 0000000000000000 R11: ffffffff80156440 R12: 0000000000100100 > R13: ffffffff8012c470 R14: ffff8101046f6140 R15: 0000000000000001 > FS: 00002aaaaac3ed20(0000) GS:ffffffff80624880(0000) knlGS:00000000555565a0 > CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b > CR2: 00002aaaaae70000 CR3: 00000000f8625000 CR4: 00000000000006e0 > > Call Trace:{shrink_icache_memory+532} {shrink_slab+206} > {balance_pgdat+617} {kswapd+311} > {autoremove_wake_function+0} {autoremove_wake_function+0} > {child_rip+8} {flat_send_IPI_mask+0} > {kswapd+0} {child_rip+0} > > top - 09:18:48 up 10:11, 2 users, load average: 9.96, 8.08, 4.17 > Tasks: 2 total, 2 running, 0 sleeping, 0 stopped, 0 zombie > Cpu(s): 2.2% us, 20.6% sy, 3.0% ni, 65.8% id, 6.6% wa, 0.1% hi, 1.8% si > Mem: 8173472k total, 6361680k used, 1811792k free, 37592k buffers > Swap: 14651256k total, 656k used, 14650600k free, 5962320k cached > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 18 root 15 0 0 0 0 R 90.2 0.0 119:53.39 kswapd0 > 17 root 15 0 0 0 0 R 70.2 0.0 36:12.62 kswapd1 > > SysRq : Show Regs > CPU 1: > Modules linked in: binfmt_misc floppy > Pid: 17, comm: kswapd1 Not tainted 2.6.15-rc2 #2 > RIP: 0010:[] {__mod_page_state+36} > RSP: 0000:ffff8101047bfdc8 EFLAGS: 00000292 > RAX: ffff810103844e00 RBX: ffffffff801925dc RCX: ffff8101046f6140 > RDX: ffffffff8066dca0 RSI: 0000000000000080 RDI: 00000000000000f8 > RBP: 0000000000000000 R08: ffff8101047be000 R09: 0000000000000000 > R10: 0000000000000000 R11: ffffffff80156440 R12: 0000000000000000 > R13: ffffffff80156440 R14: ffffffff803e86e8 R15: ffffffff804683e0 > FS: 00002aaaaaab79e0(0000) GS:ffffffff80624880(0000) knlGS:00000000555565a0 > CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b > CR2: 00000000004472f0 CR3: 000000003f0ee000 CR4: 00000000000006e0 > > Call Trace:{shrink_slab+255} {balance_pgdat+617} > {kswapd+311} {autoremove_wake_function+0} > {autoremove_wake_function+0} {child_rip+8} > {flat_send_IPI_mask+0} {kswapd+0} > {child_rip+0} > > > -Yenya > > -- > | Jan "Yenya" Kasprzak | > | GPG: ID 1024/D3498839 Fingerprint 0D99A7FB206605D7 8B35FCDE05B18A5E | > | http://www.fi.muni.cz/~kas/ Journal: http://www.fi.muni.cz/~kas/blog/ | > > Specs are a basis for _talking_about_ things. But they are _not_ a basis < > > for implementing software. --Linus Torvalds < > - > 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/ - 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/