OOM日志解读

计算弹性计算技术服务知识库

问题1:

OOM原理

OOM(out-of-memory)一句话概括就是它会在系统内存耗尽前,启用自己的算法有选择性的杀掉某个进程,以达到回收这个进程占用的内存来补充自己。 那么为什么会有OOM,一般来说用户进程申请内存一般会用malloc,当malloc返回非空时程序认为本次申请是成功的,但是实际上返回成功我们真的就拿到对应的物理内存空间了吗(并没有),从malloc的menu中可以知道Linux系统允许程序申请比系统可用内存更多的内存空间,这个特性叫overcommit这个优化是基于并不是所有程序申请完内存都会立即使用的,所以通过延时分配的方式理论上可以挤出更多的空间这个做法类似于财务上的账期,这也是虚拟内存空间的由来,实际上malloc返回的是一个虚拟地址,只有当程序真正去访问这个内存空间是才会在系统里触发一个缺页事件(page_fault)将真正的物理内存地址映射给虚拟地址。

那么这里的overcommit如何使用呢,内核官方的解释如下:

0: 默认选项,启发式策略允许overcommit,明显超量分配会被拒绝,root比普通用户有更高的余量(单次申请的内存大小不能超过 free memory + free swap + pagecache + SReclaimable) 1: 永远允许,可以理解为从不失败 2: 永远禁止,这种情况下系统允许分配的内存为swap + RAM*overcommit_ratio(ratio默认是50%), overcommit_memory=2就意味着关闭了oom killer 当前有没有overcommit可以用下面的方法判断,Committed_AS > CommitLimit 即有

#grep -i commit /proc/meminfo
CommitLimit:    101037524 kB    //内存分配上限,CommitLimit = 物理内存 * overcommit_ratio(默认50,即50%) + swap大小
Committed_AS:   152507000 kB //是已经分配的内存大小

OOM kill的触发条件:

当应用实际访问某一个已经分配的虚拟内存地址,触发缺页异常系统尝试分配物理内存页与之映射,发现找不到足够的内存叶同时发现通过swap,reclaim等方式也调剂不出足够内存,此时系统会给所有应用程序排名,选举出一个最应该被kill的对象,结束它。 选举谁: 选举方式比较简单,系统给了每个进程一个分数分数越高被选中的概率越高(/proc//oom_score),分数的主要参考依据就是内存占用量,但是同时这种粗暴的方式可能往往不是业务真正需要的,所以系统又引入了另一个*/proc//oom_score_adj 取值范围-1000 - 1000 默认进程的起始分为0,oom_score_adj 通过改变起始分以达到让用户手动调整进程被kill的优先级。*

OOM的其他策略:

  1. 配置OOM后直接panic

我们也可以配置,当触发了OOM后,直接整个服务器重启。

sysctl -w vm.panic_on_oom=1
sysctl -w kernel.panic=10  //10秒后自动重启系统
  1. 配置手动触发一次OOM killer

echo f> /proc/sysrq-trigger 手动启用oom-kill机制,会自动杀掉oom_score指数评分最高的那个进程,用于测试和学习不要在线上环境执行。

问题2:

日志解读

思考:

  1. proxima invoked oom-killer ,proxima触发了oom kill是不是说明proxima有问题?
  2. 如果不是,怎么判断谁可能有问题
[110032.087734] proxima invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0
[110032.089427] proxima cpuset=/ mems_allowed=0
[110032.090240] CPU: 1 PID: 1474 Comm: proxima Tainted: G           OE  ------------   3.10.0-1160.76.1.el7.x86_64 #1
[110032.092281] Hardware name: ByteDance Inc. OpenStack Nova, BIOS  
[110032.093709] Call Trace:
[110032.094671]  [<ffffffff86b865c9>] dump_stack+0x19/0x1b
[110032.095984]  [<ffffffff86b81668>] dump_header+0x90/0x229
[110032.097310]  [<ffffffff86506a42>] ? ktime_get_ts64+0x52/0xf0
[110032.098684]  [<ffffffff8655e0ff>] ? delayacct_end+0x8f/0xb0
[110032.099951]  [<ffffffff865c25ad>] oom_kill_process+0x2cd/0x490
[110032.101195]  [<ffffffff865c1f9d>] ? oom_unkillable_task+0xcd/0x120
[110032.102530]  [<ffffffff865c2c9a>] out_of_memory+0x31a/0x500
[110032.103809]  [<ffffffff865c9894>] __alloc_pages_nodemask+0xad4/0xbe0
[110032.104784]  [<ffffffff866193b8>] alloc_pages_current+0x98/0x110
[110032.106237]  [<ffffffff865be057>] __page_cache_alloc+0x97/0xb0
[110032.107257]  [<ffffffff865c1000>] filemap_fault+0x270/0x420
[110032.108138]  [<ffffffffc03fb756>] ext4_filemap_fault+0x36/0x50 [ext4]
[110032.109075]  [<ffffffff865ee7da>] __do_fault.isra.61+0x8a/0x100
[110032.109930]  [<ffffffff865eed8c>] do_read_fault.isra.63+0x4c/0x1b0
[110032.110884]  [<ffffffff865f65d0>] handle_mm_fault+0xa20/0xfb0
[110032.111795]  [<ffffffff86b94653>] __do_page_fault+0x213/0x500
[110032.112712]  [<ffffffff86b94a26>] trace_do_page_fault+0x56/0x150
[110032.113698]  [<ffffffff86b93fa2>] do_async_page_fault+0x22/0xf0
[110032.114667]  [<ffffffff86b907a8>] async_page_fault+0x28/0x30
[110032.115562] Mem-Info:
[110032.116155] active_anon:1927732 inactive_anon:3983 isolated_anon:0
 active_file:3 inactive_file:544 isolated_file:0
 unevictable:0 dirty:23 writeback:0 unstable:0
 slab_reclaimable:4937 slab_unreclaimable:4810
 mapped:477 shmem:8358 pagetables:4803 bounce:0
 free:25595 free_pcp:159 free_cma:0


[110032.144857] Node 0 DMA: 1*4kB (U) 0*8kB 0*16kB 3*32kB (UM) 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 2*1024kB (UM) 2*2048kB (M) 2*4096kB (M) = 14948kB
[110032.148455] Node 0 DMA32: 268*4kB (UEM) 227*8kB (UEM) 173*16kB (UEM) 143*32kB (UEM) 88*64kB (UE) 60*128kB (UE) 37*256kB (UEM) 25*512kB (UEM) 0*1024kB 0*2048kB 0*4096kB = 45816kB
[110032.151049] Node 0 Normal: 288*4kB (UEM) 374*8kB (UEM) 211*16kB (UEM) 249*32kB (UEM) 111*64kB (UEM) 61*128kB (UE) 33*256kB (EM) 10*512kB (E) 0*1024kB 0*2048kB 0*4096kB = 43968kB
[110032.153560] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[110032.154817] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[110032.156068] 9368 total pagecache pages
[110032.156813] 0 pages in swap cache
[110032.157580] Swap cache stats: add 0, delete 0, find 0/0
[110032.158505] Free swap  = 0kB
[110032.159229] Total swap = 0kB
[110032.159903] 2096205 pages RAM
[110032.160658] 0 pages HighMem/MovableOnly
[110032.161452] 94843 pages reserved
[110032.162184] [ pid ]   uid  tgid total_vm      rss nr_ptes swapents oom_score_adj name
[110032.163342] [  409]     0   409    11363      147      23        0         -1000 systemd-udevd
[110032.164588] [  501]     0   501    13883      113      26        0         -1000 auditd
[110032.165781] [  529]    81   529    14522      133      33        0          -900 dbus-daemon
[110032.167044] [  541]     0   541   246766     1635      43        0             0 cloud-monitor-a
[110032.169003] [  545]     0   545     5424       82      15        0             0 irqbalance
[110032.170929] [  552]   999   552   153058      841      63        0             0 polkitd
[110032.172825] [  553]     0   553     6596       76      19        0             0 systemd-logind
[110032.174797] [  555]   998   555    29452      115      30        0             0 chronyd
[110032.176671] [ 1112]     0  1112    25747      515      48        0             0 dhclient
[110032.178542] [ 1172]     0  1172   143985     3240      98        0             0 tuned
[110032.180360] [ 1408]     0  1408    22447      261      44        0             0 master
[110032.182161] [ 1413]    89  1413    22490      251      44        0             0 qmgr
[110032.183325] [ 1457]     0  1457    80261      467      54        0             0 rsyslogd
[110032.184521] [ 1459]     0  1459   324322     2672      58        0             0 proxima
[110032.185727] [ 1462]     0  1462    28246      259      57        0         -1000 sshd
[110032.186893] [ 1467]     0  1467     6477       51      18        0             0 atd
[110032.188039] [ 1473]     0  1473    31598      157      18        0             0 crond
[110032.189156] [ 1483]     0  1483    27552       33      10        0             0 agetty
[110032.190280] [ 1484]     0  1484    27552       32      10        0             0 agetty
[110032.191393] [ 1505]     0  1505   177582      654      18        0             0 baseline
[110032.192517] [ 1515]     0  1515   313038     4341      67        0             0 collector
[110032.193662] [ 1517]     0  1517     6111      887      15        0             0 driver
[110032.194779] [ 1522]     0  1522     3008       13       9        0             0 journal_watcher
[110032.195964] [ 1528]     0  1528    42923      134      35        0             0 journalctl
[110032.197107] [ 1529]     0  1529   105745     5124      54        0             0 scanner_clamav
[110032.198277] [11909]     0 11909    38693      354      76        0             0 sshd
[110032.199355] [11911]     0 11911    28971      137      15        0             0 bash
[110032.200408] [14593]    89 14593    22473      251      46        0             0 pickup
[110032.201462] [14683]     0 14683     9765      453      21        0             0 systemd-journal
[110032.202575] [14808]     0 14808  1914869  1899499    3717        0             0 test_malloc
[110032.203668] Out of memory: Kill process 14808 (test_malloc) score 922 or sacrifice child
[110032.204741] Killed process 14808 (test_malloc), UID 0, total-vm:7659476kB, anon-rss:7597996kB, file-rss:0kB, shmem-rss:0kB
[root@iv-ybz88tnky35m56blnrfb root]# 
  1. proxima invoked oom-killer: gfp_mask=0x201da, order=0, oom_score_adj=0 proxima 当前请求分配内存也触发了oom kill 的进程 gfp_mask=0x201da,是alloc_page的GFP标志 order=0 : 表示alloc_page的order为0, 也就是说仅请求1^0=1个页面 oom_score_adj=0 默认值
  2. Call trace 有完整的OOM发生时的调用栈,本例中oom发生在尝试将文件内容读取到page cache中,在尝试分配page cache时触发OOM
  3. Node 0 Normal free:42972kB min:42996kB low:53744kB high:64492kB active_anon:4901132kB inactive_anon:8280kB active_file:0kB inactive_file:2644kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:5242880kB managed:5094232kB mlocked:0kB dirty:36kB writeback:0kB mapped:1876kB shmem:20276kB slab_reclaimable:13804kB slab_unreclaimable:14560kB kernel_stack:1920kB pagetables:12148kB unstable:0kB bounce:0kB free_pcp:252kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:3997 all_unreclaimable? yes [110032.144028] lowmem_reserve[]: 0 0 0 0 DMA直接内存访问跳过,直接看Normal段内存分布,free:42972kB min:42996kB,min就是min_free_kbytes已经大于free满足需要回收内存的条件,这里的统计项和/proc/meminfo非常相似它在非应用层内存占用高的场景中有一定的定位意义,比如某些大内存应用但实际每个对象都是小内存这会导致页表的消耗异常巨大。
  4. 最关键的信息如下截图,统计了发生问题前所有进程在那一时刻的内存使用情况,是日志中最有用的部分,RSS为进程在RAM中实际占用的内存总量单位是page,这里可以看到test_malloc占了1899499个page换算后为7419M为内存占用最高的进程,oom_score_adj=0没有做特殊的保护所以最终系统选择了结束它,同时可以看到sshd,udevd,auditd这些是被系统默认保护的。
0
0
0
0
评论
未登录
看完啦,登录分享一下感受吧~
暂无评论