From: Marcelo Tosatti <marcelo.tosatti@cyclades.com>
To: Jan Kasprzak <kas@fi.muni.cz>
Cc: Andrew Morton <akpm@osdl.org>,
nickpiggin@yahoo.com.au, linux-kernel@vger.kernel.org
Subject: Re: 2.6.14 kswapd eating too much CPU
Date: Sun, 27 Nov 2005 06:42:31 -0200 [thread overview]
Message-ID: <20051127084231.GC20701@logos.cnet> (raw)
In-Reply-To: <20051124083141.GJ28142@fi.muni.cz>
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:<ffffffff80160589>{balance_pgdat+297} <ffffffff80160936>{kswapd+278}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff8010e7d6>{child_rip+8} <ffffffff8011ac50>{flat_send_IPI_mask+0}
> <ffffffff80160820>{kswapd+0} <ffffffff8010e7ce>{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:<ffffffff80160589>{balance_pgdat+297} <ffffffff80160936>{kswapd+278}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff8010e7d6>{child_rip+8} <ffffffff8011ac50>{flat_send_IPI_mask+0}
> <ffffffff80160820>{kswapd+0} <ffffffff8010e7ce>{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:[<ffffffff8019266b>] <ffffffff8019266b>{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:<ffffffff80192814>{shrink_icache_memory+532} <ffffffff8015f20b>{shrink_slab+219}
> <ffffffff801606c9>{balance_pgdat+617} <ffffffff80160957>{kswapd+311}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff8010e7d6>{child_rip+8} <ffffffff8011ac50>{flat_send_IPI_mask+0}
> <ffffffff80160820>{kswapd+0} <ffffffff8010e7ce>{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:[<ffffffff803e8ab3>] <ffffffff803e8ab3>{_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:<ffffffff801925dc>{dispose_list+220} <ffffffff8019260b>{shrink_icache_memory+11}
> <ffffffff801927dc>{shrink_icache_memory+476} <ffffffff8015f20b>{shrink_slab+219}
> <ffffffff801606c9>{balance_pgdat+617} <ffffffff80160957>{kswapd+311}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff8010e7d6>{child_rip+8} <ffffffff8011ac50>{flat_send_IPI_mask+0}
> <ffffffff80160820>{kswapd+0} <ffffffff8010e7ce>{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:[<ffffffff803e760e>] <ffffffff803e760e>{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:<ffffffff8012c4c0>{__wake_up_common+64} <ffffffff803e88f8>{__down+152}
> <ffffffff8012c470>{default_wake_function+0} <ffffffff803e86e8>{__down_failed+53}
> <ffffffff80156440>{mempool_free_slab+0} <ffffffff80192cf6>{.text.lock.inode+5}
> <ffffffff8015f20b>{shrink_slab+219} <ffffffff801606c9>{balance_pgdat+617} <ffffffff80160957>{kswapd+311} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff8010e7d6>{child_rip+8}
> <ffffffff8011ac50>{flat_send_IPI_mask+0} <ffffffff80160820>{kswapd+0}
> <ffffffff8010e7ce>{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:[<ffffffff80192827>] <ffffffff80192827>{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:<ffffffff80192814>{shrink_icache_memory+532} <ffffffff8015f1fe>{shrink_slab+206}
> <ffffffff801606c9>{balance_pgdat+617} <ffffffff80160957>{kswapd+311}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff8010e7d6>{child_rip+8} <ffffffff8011ac50>{flat_send_IPI_mask+0}
> <ffffffff80160820>{kswapd+0} <ffffffff8010e7ce>{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:[<ffffffff80156e54>] <ffffffff80156e54>{__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:<ffffffff8015f22f>{shrink_slab+255} <ffffffff801606c9>{balance_pgdat+617}
> <ffffffff80160957>{kswapd+311} <ffffffff801472a0>{autoremove_wake_function+0}
> <ffffffff801472a0>{autoremove_wake_function+0} <ffffffff8010e7d6>{child_rip+8}
> <ffffffff8011ac50>{flat_send_IPI_mask+0} <ffffffff80160820>{kswapd+0}
> <ffffffff8010e7ce>{child_rip+0}
>
>
> -Yenya
>
> --
> | Jan "Yenya" Kasprzak <kas at {fi.muni.cz - work | yenya.net - private}> |
> | 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/
next prev parent reply other threads:[~2005-11-27 14:22 UTC|newest]
Thread overview: 21+ messages / expand[flat|nested] mbox.gz Atom feed top
2005-11-22 12:59 2.6.14 kswapd eating too much CPU Jan Kasprzak
2005-11-23 0:35 ` Andrew Morton
2005-11-23 1:01 ` Jan Kasprzak
2005-11-23 2:19 ` Nick Piggin
2005-11-23 5:13 ` Jan Kasprzak
2005-11-23 13:14 ` Jan Kasprzak
2005-11-23 19:02 ` Andrew Morton
2005-11-23 20:24 ` Jan Kasprzak
2005-11-23 20:32 ` Jesper Juhl
2005-11-23 20:34 ` Jan Kasprzak
2005-11-23 20:35 ` Andrew Morton
2005-11-24 8:31 ` Jan Kasprzak
2005-11-27 8:42 ` Marcelo Tosatti [this message]
2005-11-27 20:39 ` Jan Kasprzak
2005-11-27 15:45 ` Marcelo Tosatti
2005-11-27 16:02 ` Marcelo Tosatti
2005-11-27 23:21 ` Andrew Morton
2005-11-28 13:16 ` Jan Kasprzak
2005-11-28 8:04 ` Marcelo Tosatti
2005-12-06 0:10 ` Jan Kasprzak
2005-12-06 18:14 ` Marcelo Tosatti
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20051127084231.GC20701@logos.cnet \
--to=marcelo.tosatti@cyclades.com \
--cc=akpm@osdl.org \
--cc=kas@fi.muni.cz \
--cc=linux-kernel@vger.kernel.org \
--cc=nickpiggin@yahoo.com.au \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.