OOM问题排查,Linux进程突然被杀掉(OOM killer)

Linux 内核有个机制叫OOM killer(Out Of Memory killer),该机制会监控那些占用内存过大,尤其是瞬间占用内存很快的进程,
然后防止内存耗尽而自动把该进程杀掉。内核检测到系统内存不足、挑选并杀掉某个进程的过程可以参考内核源代码linux/mm/oom_kill.c,
当系统内存不足的时候,out_of_memory()被触发,然后调用select_bad_process()选择一个”bad”进程杀掉。
如何判断和选择一个”bad进程呢?linux选择”bad”进程是通过调用oom_badness(),挑选的算法和想法都很简单很朴实:
最bad的那个进程就是那个最占用内存的进程。 具体OOM的解释可以看这篇文章:http:
//www.wowotech.net/memory_management/oom.html

 1.预备知识

在解读日志之前,我们先回顾一下linux内核的内存管理。

(1)Page 页

处理器的最小‘寻址单元’是字节或者字,而页是内存的‘管理单元’。

(2) Zone 区

(a)区存在的原因:

有些硬件设备只能对特定的内存地址执行DMA(direct memory access)操作。

在一些架构中,实际物理内存是比系统可寻址的虚拟内存要大的,这就导致有些物理内存没有办法被永久的映射在内核的地址空间中。

区的划分也是直接以上面两个原因为依据的。

(b)区的种类 

ZONE_DMA—这个区包含的page可以执行DMA操作。这部分区域的大小和CPU架构有关,在x86架构中,该部分区域大小限制为16MB。

ZONE_DMA32—类似于ZOME_DMA, 这个区也包含可以执行DMA操作的page。该区域只存在于64位系统中,适合32位的设备访问。

ZONE_NORMAL—这个区包含可以正常映射到地址空间中的page,或者说这个区包含了除了DMA和HIGHMEM以外的内存。许多内核操作都仅在这个区域进行。

ZONE_HIGHMEM—这个区包含的是high memory,也就是那些不能被永久映射到内核地址空间的页。

32位的x86架构中存在三种内存区域,ZONE_DMA,ZONE_NORMAL,ZONE_HIGHMEM。根据地址空间划分的不同,三个区域的大小不一样:

1)1G内核空间/3G用户空间

OOM问题排查,Linux进程突然被杀掉(OOM killer)

2) 4G内核空间/4G用户空间

OOM问题排查,Linux进程突然被杀掉(OOM killer)

64位的系统由于寻址能力的提高,不存在highmem区,所以64位系统中存在的区有DMA,DMA32和NORMAL三个区。

OOM问题排查,Linux进程突然被杀掉(OOM killer)
OOM问题排查,Linux进程突然被杀掉(OOM killer)

1.2 内核分配内存的函数

下面是内核分配内存的核心函数之一,它会分配2的order次方个连续的物理页内存,并将第一页的逻辑地址返回。

unsigned long __get_free_pages(gfp_t gfp_mask, unsigned int order)

内核空间的内存分配函数和用户空间最大的不同就是每个函数会有一个gfp_mask参数。

其中gfp 代表的就是我们上面的内存分配函数 __get_free_pages()。

gfp_mask可以分成三种: 行为修饰符(action modifier),区修饰符 (zone modifier)和类型( type).

(1)行为修饰符是用来指定内核该如何分配内存的。比如分配内存时是否可以进行磁盘io,是否可以进行文件系统操作,内核是否可以睡眠(sleep)等等。

(2)区修饰符指定内存需要从哪个区来分配。

(3)类型是行为修饰符和区修饰符结合之后的产物。在一些特定的内存分配场合下,我们可能需要同时指定多个行为修饰符和区修饰符,而type就是针对这些固定的场合,将所需要的行为修饰符和区修饰符都整合到了一起,这样使用者只要指定一个type就可以了。

不同type所代表的含义可以参看下面的表格:

OOM问题排查,Linux进程突然被杀掉(OOM killer)

2 日志解读

 下面是从oom killer被触发到进程到被杀掉的一个大概过程,我们来具体看一下。

Mar 25 03:02:44 BJPVZXJL-1 kernel: easy_collector invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Mar 25 03:02:44 BJPVZXJL-1 kernel: easy_collector cpuset=/ mems_allowed=0
Mar 25 03:02:44 BJPVZXJL-1 kernel: CPU: 4 PID: 4575 Comm: easy_collector Tainted: G OE ------------ 3.10.0-957.12.2.el7.x86_64 #1
Mar 25 03:02:44 BJPVZXJL-1 kernel: Hardware name: Alibaba Cloud Alibaba Cloud ECS, BIOS 8a46cfe 04/01/2014
Mar 25 03:02:44 BJPVZXJL-1 kernel: Call Trace:
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb63041>] dump_stack+0x19/0x1b
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb5da6a>] dump_header+0x90/0x229
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c501212>] ? ktime_get_ts64+0x52/0xf0
Mar 25 03:00:01 BJPVZXJL-1 systemd: Started Session 772087 of user root.
Mar 25 03:00:01 BJPVZXJL-1 systemd: Started Session 772088 of user root.
Mar 25 03:00:01 BJPVZXJL-1 systemd: Started Session 772089 of user root.
Mar 25 03:00:01 BJPVZXJL-1 systemd: Started Session 772090 of user root.
Mar 25 03:01:01 BJPVZXJL-1 systemd: Started Session 772092 of user root.
Mar 25 03:01:01 BJPVZXJL-1 systemd: Started Session 772091 of user root.
Mar 25 03:02:01 BJPVZXJL-1 systemd: Started Session 772093 of user root.
Mar 25 03:02:01 BJPVZXJL-1 systemd: Started Session 772095 of user root.
Mar 25 03:02:01 BJPVZXJL-1 systemd: Started Session 772094 of user root.
Mar 25 03:02:44 BJPVZXJL-1 kernel: easy_collector invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Mar 25 03:02:44 BJPVZXJL-1 kernel: easy_collector cpuset=/ mems_allowed=0
Mar 25 03:02:44 BJPVZXJL-1 kernel: CPU: 4 PID: 4575 Comm: easy_collector Tainted: G OE ------------ 3.10.0-957.12.2.el7.x86_64 #1
Mar 25 03:02:44 BJPVZXJL-1 kernel: Hardware name: Alibaba Cloud Alibaba Cloud ECS, BIOS 8a46cfe 04/01/2014
Mar 25 03:02:44 BJPVZXJL-1 kernel: Call Trace:
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb63041>] dump_stack+0x19/0x1b
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb5da6a>] dump_header+0x90/0x229
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c501212>] ? ktime_get_ts64+0x52/0xf0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c55845f>] ? delayacct_end+0x8f/0xb0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5ba7b4>] oom_kill_process+0x254/0x3d0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5ba25d>] ? oom_unkillable_task+0xcd/0x120
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5ba306>] ? find_lock_task_mm+0x56/0xc0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5baff6>] out_of_memory+0x4b6/0x4f0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb5e56e>] __alloc_pages_slowpath+0x5d6/0x724
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5c13d4>] __alloc_pages_nodemask+0x404/0x420
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c60e288>] alloc_pages_current+0x98/0x110
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5b6617>] __page_cache_alloc+0x97/0xb0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5b9278>] filemap_fault+0x298/0x490
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffffc0494186>] ext4_filemap_fault+0x36/0x50 [ext4]
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5e476a>] __do_fault.isra.59+0x8a/0x100
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5e4d1c>] do_read_fault.isra.61+0x4c/0x1b0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5e96c4>] handle_pte_fault+0x2f4/0xd10
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c65843d>] ? core_sys_select+0x26d/0x340
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9c5ec1fd>] handle_mm_fault+0x39d/0x9b0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb70603>] __do_page_fault+0x203/0x4f0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb709d6>] trace_do_page_fault+0x56/0x150
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb6ff62>] do_async_page_fault+0x22/0xf0
Mar 25 03:02:44 BJPVZXJL-1 kernel: [<ffffffff9cb6c798>] async_page_fault+0x28/0x30
Mar 25 03:02:44 BJPVZXJL-1 kernel: Mem-Info:
Mar 25 03:02:44 BJPVZXJL-1 kernel: active_anon:1872940 inactive_anon:85 isolated_anon:0#012 active_file:5818 inactive_file:7456 isolated_file:32#012 unevictable:0 dirty:3
writeback:0 unstable:0#012 slab_reclaimable:10679 slab_unreclaimable:8296#012 mapped:487 shmem:196 pagetables:6158 bounce:0#012 free:25631 free_pcp:1598 free_cma:0
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 DMA free:15908kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0
kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0
kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Mar 25 03:02:44 BJPVZXJL-1 kernel: lowmem_reserve[]: 0 2812 7802 7802
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 DMA32 free:43660kB min:24312kB low:30388kB high:36468kB active_anon:2716820kB inactive_anon:92kB active_file:4228kB inactive_file
:7100kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3129192kB managed:2882968kB mlocked:0kB dirty:12kB writeback:0kB mapped:560kB shmem:212kB slab_reclai
mable:13480kB slab_unreclaimable:10992kB kernel_stack:3744kB pagetables:8256kB unstable:0kB bounce:0kB free_pcp:3508kB local_pcp:280kB free_cma:0kB writeback_tmp:0kB pages
_scanned:24664 all_unreclaimable? yes
Mar 25 03:02:44 BJPVZXJL-1 kernel: lowmem_reserve[]: 0 0 4989 4989
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 Normal free:42956kB min:43132kB low:53912kB high:64696kB active_anon:4774940kB inactive_anon:248kB active_file:19044kB inactive_f
ile:22724kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:5242880kB managed:5109360kB mlocked:0kB dirty:0kB writeback:0kB mapped:1388kB shmem:572kB slab_
reclaimable:29236kB slab_unreclaimable:22192kB kernel_stack:8592kB pagetables:16376kB unstable:0kB bounce:0kB free_pcp:2884kB local_pcp:124kB free_cma:0kB writeback_tmp:0k
B pages_scanned:54356 all_unreclaimable? yes
Mar 25 03:02:44 BJPVZXJL-1 kernel: lowmem_reserve[]: 0 0 0 0
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 1*32kB (U) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15908k
B
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 DMA32: 425*4kB (UEM) 172*8kB (UEM) 134*16kB (UEM) 132*32kB (UEM) 233*64kB (UEM) 128*128kB (UEM) 12*256kB (UEM) 0*512kB 0*1024kB 0
*2048kB 0*4096kB = 43812kB
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 Normal: 729*4kB (UE) 798*8kB (UE) 744*16kB (UE) 555*32kB (UEM) 34*64kB (UEM) 11*128kB (UE) 3*256kB (UE) 0*512kB 0*1024kB 0*2048kB
0*4096kB = 43316kB
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Mar 25 03:02:44 BJPVZXJL-1 kernel: 14026 total pagecache pages
Mar 25 03:02:44 BJPVZXJL-1 kernel: 0 pages in swap cache
Mar 25 03:02:44 BJPVZXJL-1 kernel: Swap cache stats: add 0, delete 0, find 0/0
Mar 25 03:02:44 BJPVZXJL-1 kernel: Free swap = 0kB
Mar 25 03:02:44 BJPVZXJL-1 kernel: Total swap = 0kB
Mar 25 03:02:44 BJPVZXJL-1 kernel: 2097016 pages RAM
Mar 25 03:02:44 BJPVZXJL-1 kernel: 0 pages HighMem/MovableOnly
Mar 25 03:02:44 BJPVZXJL-1 kernel: 94957 pages reserved
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 1654] 0 1654 16203 117 35 0 0 systemd-journal
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 1678] 0 1678 11204 226 24 0 -1000 systemd-udevd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 1683] 0 1683 47590 99 29 0 0 lvmetad
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3149] 0 3149 13880 112 27 0 -1000 auditd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3182] 0 3182 75446 2218 28 0 0 Cms*.linu
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3183] 999 3183 153164 2254 62 0 0 polkitd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3186] 0 3186 5416 82 15 0 0 irqbalance
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3197] 81 3197 14556 164 32 0 -900 dbus-daemon
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3204] 38 3204 11818 178 29 0 0 ntpd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3224] 0 3224 6702 186 19 0 0 systemd-logind
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3238] 32 3238 17332 168 38 0 0 rpcbind
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3268] 0 3268 48775 118 35 0 0 gssproxy
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3282] 0 3282 31579 174 18 0 0 crond
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3287] 0 3287 6476 53 18 0 0 atd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3300] 0 3300 27523 34 10 0 0 agetty
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3301] 0 3301 27523 34 10 0 0 agetty
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3311] 0 3311 540824 6666 95 0 0 exe
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3512] 0 3512 25710 519 47 0 0 dhclient
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3579] 0 3579 347531 6501 438 0 0 rsyslogd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3582] 0 3582 143483 2788 95 0 0 tuned
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 3981] 0 3981 28216 260 57 0 -1000 sshd
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 4503] 0 4503 231103 3007 50 0 0 easyAgent
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 4575] 0 4575 93554 3203 65 0 0 easy_collector
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 4576] 0 4576 118079 3938 83 0 0 easy_collector
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 4577] 0 4577 158580 6926 92 0 0 easy_collector
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 4586] 0 4586 95280 3394 73 0 0 easy_monitor
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 5465] 0 5465 109224 147 28 0 0 AliSecGuard
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 6502] 0 6502 370821 20447 114 0 0 n9e-collector
Mar 25 03:02:44 BJPVZXJL-1 kernel: [25907] 0 25907 8133 358 20 0 0 AliYunDunUpdate
Mar 25 03:02:44 BJPVZXJL-1 kernel: [26058] 0 26058 39401 6788 76 0 0 AliYunDun
Mar 25 03:02:44 BJPVZXJL-1 kernel: [23520] 1003 23520 1822301 470784 1181 0 0 java
Mar 25 03:02:44 BJPVZXJL-1 kernel: [21969] 1003 21969 2107100 542660 1304 0 0 java
Mar 25 03:02:44 BJPVZXJL-1 kernel: [17330] 0 17330 111143 11199 96 0 0 titanagent
Mar 25 03:02:44 BJPVZXJL-1 kernel: [25907] 0 25907 8133 358 20 0 0 AliYunDunUpdate
Mar 25 03:02:44 BJPVZXJL-1 kernel: [26058] 0 26058 39401 6788 76 0 0 AliYunDun
Mar 25 03:02:44 BJPVZXJL-1 kernel: [23520] 1003 23520 1822301 470784 1181 0 0 java
Mar 25 03:02:44 BJPVZXJL-1 kernel: [21969] 1003 21969 2107100 542660 1304 0 0 java
Mar 25 03:02:44 BJPVZXJL-1 kernel: [17330] 0 17330 111143 11199 96 0 0 titanagent
Mar 25 03:02:44 BJPVZXJL-1 kernel: [17332] 0 17332 21926 104 13 0 0 titan_monitor
Mar 25 03:02:44 BJPVZXJL-1 kernel: [25236] 0 25236 201609 1405 14 0 0 aliyun-service
Mar 25 03:02:44 BJPVZXJL-1 kernel: [25359] 0 25359 4450 122 12 0 0 assist_daemon
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 658] 1003 658 2118259 771363 1734 0 0 java
Mar 25 03:02:44 BJPVZXJL-1 kernel: [ 1322] 0 1322 30815 63 16 0 0 anacron
Mar 25 03:02:44 BJPVZXJL-1 kernel: Out of memory: Kill process 658 (java) score 386 or sacrifice child
Mar 25 03:02:44 BJPVZXJL-1 kernel: Killed process 658 (java) total-vm:8473036kB, anon-rss:3085452kB, file-rss:0kB, shmem-rss:0kB


 

先来看一下第一行,它给出了oom killer是由谁触发的信息。

nginx invoked oom-killer: gfp_mask=0x200da, order=0, oom_score_adj=0

order=0 告诉我们所请求的内存的大小是多少,即nginx请求了2的0次方这么多个page的内存,也就是一个page,或者说是4KB。

gfp_mask的最后两个bit代表的是zone mask,也就是说它指明内存应该从哪个区来分配。

Flag value Description

OOM问题排查,Linux进程突然被杀掉(OOM killer)
 
 

__GFP_DMA 0x01u Allocate from ZONE_DMA if possible

__GFP_HIGHMEM 0x02u Allocate from ZONE_HIGHMEM if possible

(这里有一点需要注意,在64位的x86系统中,是没有highmem区的,64位系统中的normal区就对应上表中的highmem区。)

在本案例中,zonemask是2,也就是说nginx正在从zone-normal(64位系统)中请求内存。

其他标志位的含义如下:

OOM问题排查,Linux进程突然被杀掉(OOM killer)

所以我们当前这个内存请求带有这几个标志:GFP_NORECLAIM,GFP_FS,GFP_IO,GFP_WAIT, 都是比较正常的几个标志,那么我们这个请求为什么会有问题呢?继续往下看,可以看到下面的信息:

Mar 25 03:02:44 BJPVZXJL-1 kernel: Node 0 Normal free:42956kB min:43132kB low:53912kB high:64696kB active_anon:4774940kB inactive_anon:248kB active_file:19044kB inactive_f
ile:22724kB unevictable:0kB isolated(anon):0kB isolated(file):128kB present:5242880kB managed:5109360kB mlocked:0kB dirty:0kB writeback:0kB mapped:1388kB shmem:572kB slab_
reclaimable:29236kB slab_unreclaimable:22192kB kernel_stack:8592kB pagetables:16376kB unstable:0kB bounce:0kB free_pcp:2884kB local_pcp:124kB free_cma:0kB writeback_tmp:0k
B pages_scanned:54356 all_unreclaimable? yes

可以看到normal区free的内存只有42956kB,比系统允许的最小值(min)43132kB还要低,这意味着application已经无法再从系统中申请到内存了,并且系统会开始启动oom killer来缓解系统内存压力。

OOM问题排查,Linux进程突然被杀掉(OOM killer)

这里我们说一下一个常见的误区,就是有人会认为触发了oom-killer的进程就是问题的罪魁祸首,比如我们这个例子中的这个nginx进程。其实日志中invoke oom-killer的这个进程有时候可能只是一个受害者,因为其他应用/进程已将系统内存用尽,而这个invoke oomkiller的进程恰好在此时发起了一个分配内存的请求而已。在系统内存已经不足的情况下,任何一个内存请求都可能触发oom killer的启动。

oom-killer的启动会使系统从用户空间转换到内核空间。内核会在短时间内进行大量的工作,比如计算每个进程的oom分值,从而筛选出最适合杀掉的进程。我们从日志中也可以看到这一筛选过程OOM问题排查,Linux进程突然被杀掉(OOM killer)

 

OOM问题排查,Linux进程突然被杀掉(OOM killer)

上一篇:linux ftp服务


下一篇:Linux C申请内存三种基本方式