kern.log out of memory 高手才能解决

Ronux 2013-09-18 03:35:15

运行着的机器，突然某一天死机，查看日志后看到这些信息。

Sep  8 18:12:02 administrior-desktop kernel: [201869.997698] __ratelimit: 27 callbacks suppressed

Sep  8 18:12:07 administrior-desktop kernel: [201869.997702] ZR_HVRCE_WATCH invoked oom-killer: gfp_mask=0xd0, order=1, oom_adj=0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997705] ZR_HVRCE_WATCH cpuset=/ mems_allowed=0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997708] Pid: 2933, comm: ZR_HVRCE_WATCH Not tainted 2.6.32-28-generic #55-Ubuntu

Sep  8 18:12:07 administrior-desktop kernel: [201869.997710] Call Trace:

Sep  8 18:12:07 administrior-desktop kernel: [201869.997717]  [<c01cdcc4>] oom_kill_process+0xa4/0x2b0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997721]  [<c01ce339>] ? select_bad_process+0xa9/0xe0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997724]  [<c01ce3c1>] __out_of_memory+0x51/0xa0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997727]  [<c01ce468>] out_of_memory+0x58/0xb0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997731]  [<c01d0d47>] __alloc_pages_slowpath+0x487/0x4a0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997734]  [<c01d0e9a>] __alloc_pages_nodemask+0x13a/0x170

Sep  8 18:12:07 administrior-desktop kernel: [201869.997737]  [<c01d0eec>] __get_free_pages+0x1c/0x30

Sep  8 18:12:07 administrior-desktop kernel: [201869.997741]  [<c014a1bd>] dup_task_struct+0x3d/0x120

Sep  8 18:12:07 administrior-desktop kernel: [201869.997743]  [<c014b108>] copy_process+0x88/0xc20

Sep  8 18:12:07 administrior-desktop kernel: [201869.997747]  [<c02115e5>] ? alloc_pipe_info+0x25/0xb0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997749]  [<c020a8ff>] ? get_empty_filp+0xcf/0x1c0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997752]  [<c014bd23>] do_fork+0x83/0x3a0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997756]  [<c021189f>] ? do_pipe_flags+0xaf/0x110

Sep  8 18:12:07 administrior-desktop kernel: [201869.997759]  [<c0355309>] ? copy_to_user+0x39/0x130

Sep  8 18:12:07 administrior-desktop kernel: [201869.997762]  [<c0101a89>] sys_clone+0x39/0x50

Sep  8 18:12:07 administrior-desktop kernel: [201869.997764]  [<c01033ec>] syscall_call+0x7/0xb

Sep  8 18:12:07 administrior-desktop kernel: [201869.997766] Mem-Info:

Sep  8 18:12:07 administrior-desktop kernel: [201869.997767] DMA per-cpu:

Sep  8 18:12:07 administrior-desktop kernel: [201869.997769] CPU    0: hi:    0, btch:   1 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997771] CPU    1: hi:    0, btch:   1 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997772] CPU    2: hi:    0, btch:   1 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997774] CPU    3: hi:    0, btch:   1 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997775] Normal per-cpu:

Sep  8 18:12:07 administrior-desktop kernel: [201869.997777] CPU    0: hi:  186, btch:  31 usd:  30

Sep  8 18:12:07 administrior-desktop kernel: [201869.997778] CPU    1: hi:  186, btch:  31 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997780] CPU    2: hi:  186, btch:  31 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997781] CPU    3: hi:  186, btch:  31 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997783] HighMem per-cpu:

Sep  8 18:12:07 administrior-desktop kernel: [201869.997784] CPU    0: hi:  186, btch:  31 usd:  28

Sep  8 18:12:07 administrior-desktop kernel: [201869.997786] CPU    1: hi:  186, btch:  31 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997787] CPU    2: hi:  186, btch:  31 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997789] CPU    3: hi:  186, btch:  31 usd:   0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997792] active_anon:173859 inactive_anon:48532 isolated_anon:0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997793]  active_file:7751 inactive_file:105247 isolated_file:0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997794]  unevictable:0 dirty:0 writeback:67 unstable:0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997795]  free:332753 slab_reclaimable:3016 slab_unreclaimable:198786

Sep  8 18:12:07 administrior-desktop kernel: [201869.997795]  mapped:2157 shmem:12 pagetables:1693 bounce:0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997801] DMA free:3508kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15784kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:4960kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no

Sep  8 18:12:07 administrior-desktop kernel: [201869.997804] lowmem_reserve[]: 0 863 3449 3449

Sep  8 18:12:07 administrior-desktop kernel: [201869.997811] Normal free:9196kB min:3724kB low:4652kB high:5584kB active_anon:0kB inactive_anon:0kB active_file:112kB inactive_file:48kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:883896kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:12064kB slab_unreclaimable:790184kB kernel_stack:2504kB pagetables:52kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:111 all_unreclaimable? no

Sep  8 18:12:07 administrior-desktop kernel: [201869.997815] lowmem_reserve[]: 0 0 20692 20692

Sep  8 18:12:07 administrior-desktop kernel: [201869.997821] HighMem free:1318308kB min:512kB low:3300kB high:6092kB active_anon:695436kB inactive_anon:194128kB active_file:30892kB inactive_file:420940kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2648580kB mlocked:0kB dirty:0kB writeback:268kB mapped:8624kB shmem:48kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:6720kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no

Sep  8 18:12:07 administrior-desktop kernel: [201869.997825] lowmem_reserve[]: 0 0 0 0

Sep  8 18:12:07 administrior-desktop kernel: [201869.997828] DMA: 3*4kB 3*8kB 3*16kB 3*32kB 4*64kB 2*128kB 3*256kB 0*512kB 0*1024kB 1*2048kB 0*4096kB = 3508kB

Sep  8 18:12:07 administrior-desktop kernel: [201869.997837] Normal: 1843*4kB 138*8kB 1*16kB 12*32kB 3*64kB 1*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 9196kB

Sep  8 18:12:07 administrior-desktop kernel: [201869.997844] HighMem: 201*4kB 1463*8kB 14222*16kB 19706*32kB 5823*64kB 547*128kB 14*256kB 3*512kB 0*1024kB 0*2048kB 0*4096kB = 1318460kB

Sep  8 18:12:07 administrior-desktop kernel: [201869.997853] 113434 total pagecache pages

Sep  8 18:12:07 administrior-desktop kernel: [201869.997854] 376 pages in swap cache

Sep  8 18:12:07 administrior-desktop kernel: [201869.997856] Swap cache stats: add 92374, delete 91998, find 28664/30939

Sep  8 18:12:07 administrior-desktop kernel: [201869.997858] Free swap  = 1738696kB

Sep  8 18:12:07 administrior-desktop kernel: [201869.997859] Total swap = 1951736kB

Sep  8 18:12:07 administrior-desktop kernel: [201870.005558] 895657 pages RAM

Sep  8 18:12:07 administrior-desktop kernel: [201870.005560] 668347 pages HighMem

Sep  8 18:12:07 administrior-desktop kernel: [201870.005561] 15102 pages reserved

Sep  8 18:12:07 administrior-desktop kernel: [201870.005562] 132621 pages shared

Sep  8 18:12:07 administrior-desktop kernel: [201870.005563] 452971 pages non-shared

Sep  8 18:12:07 administrior-desktop kernel: [201870.005566] Out of memory: kill process 2933 (ZR_HVRCE_WATCH) score 18366 or a child

Sep  8 18:12:07 administrior-desktop kernel: [201870.005569] Killed process 16702 (ZR_HVRCE_MAIN)

Sep  8 18:12:07 administrior-desktop kernel: [201870.132295] rsyslogd invoked oom-killer: gfp_mask=0xd0, order=1, oom_adj=0

Sep  8 18:12:07 administrior-desktop kernel: [201870.132305] rsyslogd cpuset=/ mems_allowed=0

Sep  8 18:12:07 administrior-desktop kernel: [201870.132312] Pid: 947, comm: rsyslogd Not tainted 2.6.32-28-generic #55-Ubuntu

Sep  8 18:12:07 administrior-desktop kernel: [201870.132317] Call Trace:

不太清楚OOM_killer杀死进程的机制是什么，我看了一些资料，/proc/[pid]/oom_score中记录着优先级别，score越大的，在系统资源临近枯竭时首先被杀死。
本人有几个疑点：
1. 从日志分析来看，出现Out of memory: kill process 2933 (ZR_HVRCE_WATCH) score 18366 or a child这句话后，进程并没有被杀死。是否直到出现Killed process 2933才表示该进程被杀死。
2. HighMem free:1318308kB present:2648580kB还有1G多的内存可用，为什么会out of memory呢？
最后我的系统是ubuntu10.04
还请高手帮忙！！！
不胜感激！
就剩这么点分了，全送出去了，有点对不起大家

...全文

272 2 打赏收藏转发到动态举报

写回复

用AI写文章

2 条回复

切换为时间正序

请发表友善的回复…

发表回复

rucypli 2013-09-23

打赏
举报

2.6的内核oom是杀占用内存最大的进程

Ericz 2013-09-23

打赏
举报

通过调用栈可以看出系统中的确没有空闲页，所以导致内核oom_kill_process被调用。


[201869.997710] Call Trace:
[201869.997717]  [<c01cdcc4>] oom_kill_process+0xa4/0x2b0   
[201869.997721]  [<c01ce339>] ? select_bad_process+0xa9/0xe0         内核认为需要杀死进程获取空闲页
[201869.997724]  [<c01ce3c1>] __out_of_memory+0x51/0xa0
[201869.997727]  [<c01ce468>] out_of_memory+0x58/0xb0                 走到这里说明内核认为此时已经out_of_memory
[201869.997731]  [<c01d0d47>] __alloc_pages_slowpath+0x487/0x4a0        走到这里说明内核中的从freelist里没有分配到free page
[201869.997734]  [<c01d0e9a>] __alloc_pages_nodemask+0x13a/0x170          
[201869.997737]  [<c01d0eec>] __get_free_pages+0x1c/0x30       从这里看出正在分配空闲页
[201869.997741]  [<c014a1bd>] dup_task_struct+0x3d/0x120      复制task_struct时需要分配空间
...
[201869.997752]  [<c014bd23>] do_fork+0x83/0x3a0       创建进程
...
[201869.997764]  [<c01033ec>] syscall_call+0x7/0xb

[201870.005566] Out of memory: kill process 2933 (ZR_HVRCE_WATCH) score 18366 or a child 表示开始杀进程 [201870.005569] Killed process 16702 (ZR_HVRCE_MAIN) 进程被杀死

基本概念：Linux 内核有个机制叫OOM killer(Out Of Memory killer)，该机制会监控那些占用内存过大，尤其是瞬间占用内存很快的进程，然后防止内存耗尽而自动把该进程杀掉。内核检测到系统内存不足、挑选并杀掉某个进程的过程可以参考内核源代码linux/mm/oom_kill.c，当系统内存不足的时候，out_of_memory()被触发，然后调用select_bad_pro...

突然接到应用说连不上数据库了，还发来了一个截图还好不是什么核心库，喝口水，不慌。监听程序无法分发客户机连接——难道数据库宕了，呸呸呸，往好的方面想想，可能只是监听掉了，启动一下监听就好了。登上数据库，监听好好的，但是为啥没实例呢。奇怪了，ps -ef |grep pmon 空空如也。。。。乌鸦嘴了，宕库了毕竟生产库，还是先恢复吧，启库。还好没报什么错，直接就起来了。打电话...

现在是早晨6点钟。已经醒来的我正在总结到底是什么事情使得我的起床闹铃提前了这么多。故事刚开始的时候，手机铃声恰好停止。又困又烦躁的我看了下手机，看看是不是我自己疯了把闹钟调得这么早，居然是早晨5点。然而不是，而是我们的监控系统显示，Plumbr服务出故障了。作为这个领域的经验丰富的老鸟，我打开了咖啡机，这是正确解决问题的第一步。一杯咖啡在手之后，现在我可...

这几天在linux服务器上跑实验，进程占用的空间比较大，而且占用的时间也比较长，有时候会发现进程突然没有了。这个时候去翻了翻系统的内核日志，/var/log 路径下会有一个kern.log的日志文件，你在里面检索被杀掉的进程号（cat kern.log | grep 1026xxx），日志中会有如下记录： Apr 28 14:52:20 xxxx-xx kernel: [1617652.028901] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null)