這篇是一例oom killer日志的具體分析,有疑問(wèn)的可以先看上一篇：
oom killer理解和日志分析:知識(shí)儲(chǔ)備i
下面是一臺(tái)8G內(nèi)存上的一次oom killer的日志，上面跑的是RocketMQ 3.2.6，java堆配置：-server -Xms4g -Xmx4g -Xmn2g -XX:PermSize=128m -XX:MaxPermSize=320m
Jun 4 17:19:10 iZ23tpcto8eZ kernel: AliYunDun invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Jun 4 17:19:10 iZ23tpcto8eZ kernel: AliYunDun cpuset=/ mems_allowed=0
Jun 4 17:19:10 iZ23tpcto8eZ kernel: active_anon:1813257 inactive_anon:37301 isolated_anon:0 active_file:84 inactive_file:0 isolated_file:0 unevictable:0 dirty:0 writeback:0 unstable:0 free:23900 slab_reclaimable:34218 slab_unreclaimable:5636 mapped:1252 shmem:100531 pagetables:68092 bounce:0 free_cma:0
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 DMA free:15900kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB 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:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Jun 4 17:19:10 iZ23tpcto8eZ kernel: lowmem_reserve[]: 0 2801 7792 7792
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 DMA32 free:43500kB min:24252kB low:30312kB high:36376kB
active_anon:2643608kB(2.5G) inactive_anon:61560kB active_file:40kB inactive_file:40kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3129216kB managed:2869240kB mlocked:0kB dirty:0kB writeback:0kB mapped:748kB shmem:160024kB slab_reclaimable:54996kB slab_unreclaimable:6816kB kernel_stack:704kB pagetables:67440kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:275 all_unreclaimable? yes
Jun 4 17:19:10 iZ23tpcto8eZ kernel: lowmem_reserve[]: 0 0 4990 4990
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 Normal free:36200kB min:43192kB low:53988kB high:64788kB
active_anon:4609420kB(4.3G) inactive_anon:87644kB active_file:296kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:5242880kB managed:5110124kB mlocked:0kB dirty:0kB writeback:0kB mapped:4260kB shmem:242100kB slab_reclaimable:81876kB slab_unreclaimable:15720kB kernel_stack:1808kB pagetables:204928kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:511 all_unreclaimable? yes
Jun 4 17:19:10 iZ23tpcto8eZ kernel: lowmem_reserve[]: 0 0 0 0
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 DMA: 1*4kB (U) 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (R) 3*4096kB (M) = 15900kB
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 DMA32: 1281*4kB (UEM) 825*8kB (UEM) 1404*16kB (UEM) 290*32kB (EM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 43468kB
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 Normal: 1441*4kB (UEM) 3177*8kB (UEM) 315*16kB (UEM) 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 36220kB
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Jun 4 17:19:10 iZ23tpcto8eZ kernel: 100592 total pagecache pages
Jun 4 17:19:10 iZ23tpcto8eZ kernel: 0 pages in swap cache
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Swap cache stats: add 0, delete 0, find 0/0
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Free swap = 0kB
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Total swap = 0kB
Jun 4 17:19:10 iZ23tpcto8eZ kernel: 2097151 pages RAM
Jun 4 17:19:10 iZ23tpcto8eZ kernel: 94167 pages reserved
Jun 4 17:19:10 iZ23tpcto8eZ kernel: 284736 pages shared
Jun 4 17:19:10 iZ23tpcto8eZ kernel: 1976069 pages non-shared
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 338] 0 338 10748 844 25 0 0 systemd-journal
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 351] 0 351 26113 61 20 0 0 lvmetad
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 368] 0 368 10509 149 23 0 -1000 systemd-udevd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 521] 0 521 170342 908 178 0 0 rsyslogd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 525] 0 525 8671 82 21 0 0 systemd-logind
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 526] 81 526 7157 96 19 0 -900 dbus-daemon
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 530] 0 530 31575 162 17 0 0 crond
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 540] 28 540 160978 131 37 0 0 nscd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 548] 0 548 27501 30 10 0 0 agetty
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 588] 0 588 1621 26 9 0 0 iprinit
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 590] 0 590 1621 25 9 0 0 iprupdate
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 601] 0 601 9781 23 8 0 0 iprdump
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 838] 38 838 7399 169 18 0 0 ntpd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 881] 0 881 386 44 4 0 0 aliyun-service
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 5973] 1000 5973 41595 165 32 0 0 gmond
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 3829] 0 3829 33413 292 67 0 0 sshd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 3831] 1000 3831 33582 476 68 0 0 sshd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 3832] 1000 3832 29407 622 16 0 0 bash
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [14638] 0 14638 20697 210 42 0 -1000 sshd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [11531] 0 11531 33413 293 66 0 0 sshd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [11533] 1000 11533 33413 292 64 0 0 sshd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [11534] 1000 11534 29361 584 15 0 0 bash
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 3172] 0 3172 6338 161 17 0 0 AliYunDunUpdate
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 3224] 0 3224 32867 2270 61 0 0 AliYunDun
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 5417] 1000 5417 28279 51 14 0 0 sh
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 5421] 1000 5421 28279 53 13 0 0 sh
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [ 5424] 1000 5424 36913689 1537770 66407 0 0 java
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [17132] 0 17132 21804 215 44 0 0 zabbix_agentd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [17133] 0 17133 21804 285 43 0 0 zabbix_agentd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [17134] 0 17134 21866 290 44 0 0 zabbix_agentd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [17135] 0 17135 21866 290 44 0 0 zabbix_agentd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [17136] 0 17136 21841 290 44 0 0 zabbix_agentd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [17137] 0 17137 21804 245 43 0 0 zabbix_agentd
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [13669] 1000 13669 28279 51 14 0 0 sh
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [13673] 1000 13673 28279 50 13 0 0 sh
Jun 4 17:19:10 iZ23tpcto8eZ kernel: [13675] 1000 13675 879675 204324 494 0 0 java
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Out of memory: Kill process 5424 (java) score 800 or sacrifice child
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Killed process 5424 (java) total-vm:147654756kB, anon-rss:6151080kB, file-rss:0kB
還是跟上篇一樣，帶著問(wèn)題看
1.誰(shuí)申請(qǐng)內(nèi)存以及誰(shuí)被kill了？
這兩個(gè)問(wèn)題，可以從頭部和尾部的日志分析出來(lái)：
Jun 4 17:19:10 iZ23tpcto8eZ kernel: AliYunDun invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Killed process 5424 (java) total-vm:147654756kB, anon-rss:6151080kB, file-rss:0kB
AliYunDun申請(qǐng)內(nèi)存，kill掉了java進(jìn)程5424，他占用的內(nèi)存是6151080K(5.8G)
還有一個(gè)小問(wèn)題可能會(huì)有疑問(wèn)，那就是進(jìn)程5424的RSS（1537770）明明小于6151080，實(shí)際是因?yàn)檫@里的RSS是4K位單位的，所以要乘以4，算出來(lái)就對(duì)了
物理內(nèi)存申請(qǐng)我們?cè)谏弦黄治隽耍瑫?huì)到不同的Node不同的zone，那么這次申請(qǐng)的是哪一部分？這個(gè)可以從gfp_mask=0x201da, order=0分析出來(lái)，gfp_mask(get free page)是申請(qǐng)內(nèi)存的時(shí)候，會(huì)傳的一個(gè)標(biāo)記位，里面包含三個(gè)信息：區(qū)域修飾符、行為修飾符、類(lèi)型修飾符：
0X201da = 0x20000 | 0x100| 0x80 | 0x40 | 0x10 | 0x08 | 0x02
也就是下面幾個(gè)值：
___GFP_HARDWAL | ___GFP_COLD | ___GFP_FS | ___GFP_IO | ___GFP_MOVABLE| ___GFP_HIGHMEM
同時(shí)設(shè)置了___GFP_MOVABLE和___GFP_HIGHMEM會(huì)掃描ZONE_MOVABLE，其實(shí)也就是會(huì)在ZONE_NORMAL，再貼一次神圖
image
另外order表示了本次申請(qǐng)內(nèi)存的大小0，也就是4KB
也就是說(shuō)AliYunDun嘗試從ZONE_NORMAL申請(qǐng)4KB的內(nèi)存，但是失敗了，導(dǎo)致了OOM KILLER
2.各個(gè)zone的情況如何？
接下來(lái)，自然就會(huì)問(wèn)，連4KB都沒(méi)有，那到底還有多少？看這部分日志：
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 DMA free:15900kB min:132kB low:164kB high:196kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB 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:8kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Jun 4 17:19:10 iZ23tpcto8eZ kernel: lowmem_reserve[]: 0 2801 7792 7792
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 DMA32 free:43500kB min:24252kB low:30312kB high:36376kB
active_anon:2643608kB(2.5G) inactive_anon:61560kB active_file:40kB inactive_file:40kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3129216kB managed:2869240kB mlocked:0kB dirty:0kB writeback:0kB mapped:748kB shmem:160024kB slab_reclaimable:54996kB slab_unreclaimable:6816kB kernel_stack:704kB pagetables:67440kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:275 all_unreclaimable? yes
Jun 4 17:19:10 iZ23tpcto8eZ kernel: lowmem_reserve[]: 0 0 4990 4990
Jun 4 17:19:10 iZ23tpcto8eZ kernel: Node 0 Normal free:36200kB min:43192kB low:53988kB high:64788kB
active_anon:4609420kB(4.3G) inactive_anon:87644kB active_file:296kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:5242880kB managed:5110124kB mlocked:0kB dirty:0kB writeback:0kB mapped:4260kB shmem:242100kB slab_reclaimable:81876kB slab_unreclaimable:15720kB kernel_stack:1808kB pagetables:204928kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:511 all_unreclaimable? yes
Jun 4 17:19:10 iZ23tpcto8eZ kernel: lowmem_reserve[]: 0 0 0 0
可以看到Normal還有36200KB，DMA32還有43500KB，DMA還有15900KB，其中Normal的free確實(shí)小于min，但是DMA32和DMA的free沒(méi)問(wèn)題?。繌纳掀恼路治鰜?lái)看，分配是有鏈條的，Normal不夠了，會(huì)從DMA32以及DMA去請(qǐng)求分配，所以為什么分配失敗了呢？
2.1 lowmem_reserve
雖然說(shuō)分配內(nèi)存會(huì)按照Normal、DMA32、DMA的順序去分配，但是低端內(nèi)存相對(duì)來(lái)說(shuō)更寶貴些，為了防止低端內(nèi)存被高端內(nèi)存用完，linux設(shè)計(jì)了保護(hù)機(jī)制，也就是lowmen_reserve，從上面的日志看，他們的值是這樣的：
- DMA（index=0）: lowmem_reserve[]:0 2801 7792 7792
- DMA32（index=1）: lowmem_reserve[]: 0 0 4990 4990
- Normal（index=2）: lowmem_reserve[]: 0 0 0 0
lowmen_reserve的值是一個(gè)數(shù)組，當(dāng)Normal(index=2)像DMA32申請(qǐng)內(nèi)存的時(shí)候，需要滿(mǎn)足條件：DMA32 high+lowmem_reserve[2] < free，才能申請(qǐng)，來(lái)算下：
- Normal：從自己這里申請(qǐng)，free(36200) < min(43192)，所以申請(qǐng)失敗了(watermark[min]以下的內(nèi)存屬于系統(tǒng)的自留內(nèi)存，用以滿(mǎn)足特殊使用，所以不會(huì)給用戶(hù)態(tài)的普通申請(qǐng)來(lái)用)
- Normal轉(zhuǎn)到DMA32申請(qǐng):high(36376KB) + lowmem_reserve[2](4990)*4=56336KB > DMA32 Free(43500KB),不允許申請(qǐng)
- Normal轉(zhuǎn)到DMA申請(qǐng):high(196KB) + lowmem_reserve[2](7792)*4 = 31364KB > DMA Free(15900KB),不允許申請(qǐng),所以....最終失敗了
2.2 min_free_kbytes
這里屬于擴(kuò)展知識(shí)了，和分析oom問(wèn)題不大
我們知道了每個(gè)區(qū)都有min、low、high，那他們是怎么計(jì)算出來(lái)的，就是根據(jù)min_free_kbytes計(jì)算出來(lái)的，他本身在系統(tǒng)初始化的時(shí)候計(jì)算，最小128K，最大64M
- watermark[min] = min_free_kbytes換算為page單位即可，假設(shè)為min_free_pages。（因?yàn)槭敲總€(gè)zone各有一套watermark參數(shù)，實(shí)際計(jì)算效果是根據(jù)各個(gè)zone大小所占內(nèi)存總大小的比例，而算出來(lái)的per zone min_free_pages）
- watermark[low] = watermark[min] * 5 / 4
- watermark[high] = watermark[min] * 3 / 2
min 和 low的區(qū)別：
- min下的內(nèi)存是保留給內(nèi)核使用的；當(dāng)?shù)竭_(dá)min，會(huì)觸發(fā)內(nèi)存的direct reclaim
- low水位比min高一些，當(dāng)內(nèi)存可用量小于low的時(shí)候，會(huì)觸發(fā) kswapd回收內(nèi)存，當(dāng)kswapd慢慢的將內(nèi)存 回收到high水位，就開(kāi)始繼續(xù)睡眠
3.最后的問(wèn)題：java為什么占用了這么多內(nèi)存？
內(nèi)存不足申請(qǐng)失敗的細(xì)節(jié)都分析清楚了，剩下的問(wèn)題就是為什么java會(huì)申請(qǐng)這么多內(nèi)存(5.8G)，明明-Xmx配置的是4G，加上PermSize，也就最多4.3G。
因?yàn)檫@上面跑的是RocketMQ，他會(huì)有文件映射mmap，所以在仔細(xì)分析oom日志之前，懷疑是pagecache占用，導(dǎo)致RSS為5.8G，這帶來(lái)了另一個(gè)問(wèn)題，為什么pagecache沒(méi)有回收？分析了日志以后，發(fā)現(xiàn)和pagecache基本沒(méi)關(guān)系，看這個(gè)日志(換行是我后來(lái)加上的)：
Jun 4 17:19:10 iZ23tpcto8eZ kernel: active_anon:1813257 inactive_anon:37301 isolated_anon:0 active_file:84
inactive_file:0 isolated_file:0
unevictable:0 dirty:0 writeback:0
unstable:0 free:23900
slab_reclaimable:34218
slab_unreclaimable:5636 mapped:1252
shmem:100531 pagetables:68092 bounce:0
free_cma:0
當(dāng)時(shí)的內(nèi)存大部分都是活躍的匿名頁(yè)(active_anon 18132574KB=6.9G)，其他的非活躍匿名頁(yè)（inactive_anon 145M），活躍文件頁(yè)（active_file 844=336KB）,非活躍文件頁(yè)（inactive_file 0），也就是說(shuō)當(dāng)時(shí)基本沒(méi)有pagecache，因?yàn)閜agecache會(huì)屬于文件頁(yè)
并且，這臺(tái)機(jī)器上的gc log沒(méi)配置好，進(jìn)程重啟以后gc文件被覆蓋了，另外被oom killer也沒(méi)有java dump，所以…..真的不知道到底為什么java占了5.8G!!! 懸案還是沒(méi)有解開(kāi) T_T
參考：
