what can learn from this log

Sun May 9 14:01:06 UTC 2010

On Sun, May 9, 2010 at 3:47 AM, ning luwen <ningluwen at gmail.com> wrote:
> Hi,
>  I write a program do a lot disk based IO, and when it run, a lot
> memory used for cache it. And at last it throw out out of memory. and
> log as follow(part of the log,this show kill rsyslogd, and many other
> process killed, and at last the program I write killed ...):
>
> Apr 22 17:19:35 *-desktop kernel: [86653.260199] Out of memory: kill
> process 6678 (rsyslogd) score 12520 or a child
> Apr 22 17:19:35 *-desktop kernel: [86653.260337] Killed process 6678 (rsyslogd)
> Apr 22 17:19:35 *-desktop kernel: [86654.672503] smbd invoked
> oom-killer: gfp_mask=0x201da, order=0, oomkilladj=0
> Apr 22 17:19:35 *-desktop kernel: [86654.672526] smbd cpuset=/ mems_allowed=0
> Apr 22 17:19:35 *-desktop kernel: [86654.672540] Pid: 6875, comm: smbd
> Tainted: P        W  2.6.31-21-generic #59-Ubuntu
> Apr 22 17:19:35 *-desktop kernel: [86654.672560] Call Trace:
> Apr 22 17:19:35 *-desktop kernel: [86654.672581]  [<ffffffff810a28c8>]
> ? cpuset_print_task_mems_allowed+0x98/0xa0
> Apr 22 17:19:35 *-desktop kernel: [86654.672600]  [<ffffffff810dd8ee>]
> oom_kill_process+0xce/0x280
> Apr 22 17:19:35 *-desktop kernel: [86654.672615]  [<ffffffff810dde4a>]
> ? select_bad_process+0xea/0x120
> Apr 22 17:19:35 *-desktop kernel: [86654.672631]  [<ffffffff810dded0>]
> __out_of_memory+0x50/0xb0
> Apr 22 17:19:35 *-desktop kernel: [86654.672646]  [<ffffffff810de056>]
> out_of_memory+0x126/0x1a0
> Apr 22 17:19:35 *-desktop kernel: [86654.672664]  [<ffffffff8152df99>]
> ? _spin_lock+0x9/0x10
> Apr 22 17:19:35 *-desktop kernel: [86654.672680]  [<ffffffff810e0971>]
> __alloc_pages_slowpath+0x4f1/0x560
> Apr 22 17:19:35 *-desktop kernel: [86654.672697]  [<ffffffff810e0b2e>]
> __alloc_pages_nodemask+0x14e/0x150
> Apr 22 17:19:35 *-desktop kernel: [86654.672714]  [<ffffffff8110d3c2>]
> alloc_pages_current+0x82/0xd0
> Apr 22 17:19:35 *-desktop kernel: [86654.672730]  [<ffffffff810daa4f>]
> __page_cache_alloc+0x5f/0x70
> Apr 22 17:19:35 *-desktop kernel: [86654.672745]  [<ffffffff810da830>]
> ? sync_page+0x0/0x50
> Apr 22 17:19:35 *-desktop kernel: [86654.672760]  [<ffffffff810e4791>]
> __do_page_cache_readahead+0xc1/0x160
> Apr 22 17:19:35 *-desktop kernel: [86654.672778]  [<ffffffff810e484c>]
> ra_submit+0x1c/0x20
> Apr 22 17:19:35 *-desktop kernel: [86654.672793]  [<ffffffff810da54b>]
> do_sync_mmap_readahead+0x9b/0xd0
> Apr 22 17:19:35 *-desktop kernel: [86654.672809]  [<ffffffff810dc6b4>]
> filemap_fault+0x314/0x3c0
> Apr 22 17:19:35 *-desktop kernel: [86654.672824]  [<ffffffff810f44ff>]
> __do_fault+0x4f/0x4e0
> Apr 22 17:19:35 *-desktop kernel: [86654.672840]  [<ffffffff810f8ca7>]
> handle_mm_fault+0x1a7/0x3c0
> Apr 22 17:19:35 *-desktop kernel: [86654.672857]  [<ffffffff81036419>]
> ? default_spin_lock_flags+0x9/0x10
> Apr 22 17:19:35 *-desktop kernel: [86654.672873]  [<ffffffff81530b3a>]
> do_page_fault+0x16a/0x370
> Apr 22 17:19:35 *-desktop kernel: [86654.672888]  [<ffffffff8152e4b5>]
> page_fault+0x25/0x30
> Apr 22 17:19:35 *-desktop kernel: [86654.672902] Mem-Info:
> Apr 22 17:19:35 *-desktop kernel: [86654.672913] Node 0 DMA per-cpu:
> Apr 22 17:19:35 *-desktop kernel: [86654.672927] CPU    0: hi:    0,
> btch:   1 usd:   0
> Apr 22 17:19:35 *-desktop kernel: [86654.672940] CPU    1: hi:    0,
> btch:   1 usd:   0
> Apr 22 17:19:35 *-desktop kernel: [86654.672953] Node 0 DMA32 per-cpu:
> Apr 22 17:19:35 *-desktop kernel: [86654.672967] CPU    0: hi:  186,
> btch:  31 usd: 137
> Apr 22 17:19:35 *-desktop kernel: [86654.672980] CPU    1: hi:  186,
> btch:  31 usd:  65
> Apr 22 17:19:35 *-desktop kernel: [86654.672996] Active_anon:353239
> active_file:96 inactive_anon:118288
> Apr 22 17:19:35 *-desktop kernel: [86654.672998]  inactive_file:334
> unevictable:0 dirty:0 writeback:12 unstable:0
> Apr 22 17:19:35 *-desktop kernel: [86654.673000]  free:3415 slab:8509
> mapped:129 pagetables:10683 bounce:0
> Apr 22 17:19:35 *-desktop kernel: [86654.673035] Node 0 DMA
> free:8048kB min:40kB low:48kB high:60kB active_anon:2756kB
> inactive_anon:2916kB active_file:12kB inactive_file:8kB
> unevictable:0kB present:15348kB pages_scanned:5 all_unreclaimable? no
> Apr 22 17:19:35 *-desktop kernel: [86654.673075] lowmem_reserve[]: 0
> 2003 2003 2003
> Apr 22 17:19:35 *-desktop kernel: [86654.673098] Node 0 DMA32
> free:5612kB min:5704kB low:7128kB high:8556kB active_anon:1410200kB
> inactive_anon:470236kB active_file:372kB inactive_file:1328kB
> unevictable:0kB present:2051940kB pages_scanned:2208
> all_unreclaimable? no
> Apr 22 17:19:35 *-desktop kernel: [86654.673139] lowmem_reserve[]: 0 0 0 0
> Apr 22 17:19:35 *-desktop kernel: [86654.673161] Node 0 DMA: 24*4kB
> 46*8kB 19*16kB 6*32kB 9*64kB 5*128kB 3*256kB 2*512kB 2*1024kB 1*2048kB
> 0*4096kB = 8064kB
> Apr 22 17:19:35 *-desktop kernel: [86654.673800] Node 0 DMA32:
> 1205*4kB 11*8kB 10*16kB 1*32kB 0*64kB 0*128kB 0*256kB 1*512kB 0*1024kB
> 0*2048kB 0*4096kB = 5612kB
> Apr 22 17:19:35 *-desktop kernel: [86654.673853] 1277 total pagecache pages
> Apr 22 17:19:35 *-desktop kernel: [86654.673864] 724 pages in swap cache
> Apr 22 17:19:35 *-desktop kernel: [86654.673877] Swap cache stats: add
> 507492, delete 506768, find 331401/334036
> Apr 22 17:19:35 *-desktop kernel: [86654.673891] Free swap  = 0kB
> Apr 22 17:19:35 *-desktop kernel: [86654.673902] Total swap = 1951856kB
> Apr 22 17:19:35 *-desktop kernel: [86654.683134] 524192 pages RAM
> Apr 22 17:19:35 *-desktop kernel: [86654.683149] 9807 pages reserved
> Apr 22 17:19:35 *-desktop kernel: [86654.683161] 15997 pages shared
> Apr 22 17:19:35 *-desktop kernel: [86654.683172] 509060 pages non-shared
>

I think the classic way to exaust memory in a IO program is to keep
open() files without doing the close() statement.
Is it? :)

You may need to check your code.
Do you care to post your program? Maybe someone can point something wrong.

> Apr 22 17:19:35 *-desktop kernel: [86654.673891] Free swap  = 0kB
Other thing you may try is to add another swap partition and see if
the program exaust that one too.
Just to see if it is lack of memory, or a senseless hunger :)

Regards
Luis