oom killer日志分析

早上发现一台业务机器业务运行异常，登陆检查发现crond服务停止

[root@hostname~]# systemctl status crond
* crond.service - Command Scheduler
   Loaded: loaded (/usr/lib/systemd/system/crond.service; enabled; vendor preset: enabled)
   Active: failed (Result: signal) since Sat 2020-03-21 17:17:40 CST; 2 days ago
  Process: 17305 ExecStart=/usr/sbin/crond -n $CRONDARGS (code=killed, signal=KILL)
 Main PID: 17305 (code=killed, signal=KILL)

排查/var/log/message日志，发现crond服务退出前系统发生过oom

Mar 21 17:17:41 hostname kernel: log_listener invoked oom-killer: gfp_mask=0x14201ca(GFP_HIGHUSER_MOVABLE|__GFP_COLD), nodemask=(null),  order=0, oom_score_adj=0

以下是oom_killer被执行之前，系统进行的进程状态排查，主要包括系统可用内存计算和当前进程占用内存情况检查

Mar 21 17:17:41 hostname kernel: Mem-Info:
Mar 21 17:17:41 hostname kernel: active_anon:63896058 inactive_anon:34678 isolated_anon:0#012 active_file:134 inactive_file:604 isolated_file:0#012 unevictable:0 dirty:0 writeback:0 unstable:0#012 slab_reclaimable:107690 slab_unreclaimable:196394#012 mapped:49806 shmem:88002 pagetables:140193 bounce:0#012 free:147239 free_pcp:106 free_cma:0
Mar 21 17:17:41 hostname kernel: Node 0 active_anon:124957960kB inactive_anon:77212kB active_file:720kB inactive_file:1376kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:54400kB dirty:0kB writeback:0kB shmem:188224kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Mar 21 17:17:41 hostname kernel: Node 1 active_anon:130626272kB inactive_anon:61500kB active_file:0kB inactive_file:1040kB unevictable:0kB isolated(anon):0kB isolated(file):0kB mapped:144824kB dirty:0kB writeback:0kB shmem:163784kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
Mar 21 17:17:41 hostname kernel: Node 0 DMA free:15884kB min:0kB low:12kB high:24kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15968kB managed:15884kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Mar 21 17:17:41 hostname kernel: lowmem_reserve[]: 0 1035 128006 128006 128006
Mar 21 17:17:41 hostname kernel: Node 0 DMA32 free:508188kB min:260kB low:1320kB high:2380kB active_anon:581748kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:1967416kB managed:1092064kB mlocked:0kB kernel_stack:0kB pagetables:1148kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Mar 21 17:17:41 hostname kernel: lowmem_reserve[]: 0 0 126970 126970 126970
Mar 21 17:17:41 hostname kernel: Node 0 Normal free:32584kB min:32052kB low:162068kB high:292084kB active_anon:124376212kB inactive_anon:77212kB active_file:720kB inactive_file:1380kB unevictable:0kB writepending:0kB present:132120576kB managed:130018260kB mlocked:0kB kernel_stack:12104kB pagetables:255864kB bounce:0kB free_pcp:432kB local_pcp:152kB free_cma:0kB
Mar 21 17:17:41 hostname kernel: lowmem_reserve[]: 0 0 0 0 0
Mar 21 17:17:41 hostname kernel: Node 1 Normal free:32300kB min:32568kB low:164680kB high:296792kB active_anon:130626272kB inactive_anon:61500kB active_file:0kB inactive_file:1040kB unevictable:0kB writepending:0kB present:134217728kB managed:132114944kB mlocked:0kB kernel_stack:13944kB pagetables:303760kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Mar 21 17:17:41 hostname kernel: lowmem_reserve[]: 0 0 0 0 0
Mar 21 17:17:41 hostname kernel: Node 0 DMA: 1*4kB (U) 1*8kB (U) 0*16kB 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15884kB
Mar 21 17:17:41 hostname kernel: Node 0 DMA32: 104*4kB (UME) 86*8kB (UME) 117*16kB (UME) 116*32kB (UME) 86*64kB (UME) 69*128kB (UME) 43*256kB (UME) 28*512kB (UME) 15*1024kB (UME) 8*2048kB (UE) 105*4096kB (UME) = 508192kB
Mar 21 17:17:41 hostname kernel: Node 0 Normal: 521*4kB (UME) 526*8kB (UME) 212*16kB (UME) 779*32kB (UME) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 34612kB
Mar 21 17:17:41 hostname kernel: Node 1 Normal: 93*4kB (UM) 24*8kB (UME) 606*16kB (UME) 720*32kB (UE) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 33300kB
Mar 21 17:17:41 hostname kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Mar 21 17:17:41 hostname kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Mar 21 17:17:41 hostname kernel: Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Mar 21 17:17:41 hostname kernel: Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Mar 21 17:17:41 hostname kernel: 88879 total pagecache pages
Mar 21 17:17:41 hostname kernel: 0 pages in swap cache
Mar 21 17:17:41 hostname kernel: Swap cache stats: add 0, delete 0, find 0/0
Mar 21 17:17:41 hostname kernel: Free swap  = 0kB
Mar 21 17:17:41 hostname kernel: Total swap = 0kB
Mar 21 17:17:41 hostname kernel: 67080422 pages RAM
Mar 21 17:17:41 hostname kernel: 0 pages HighMem/MovableOnly
Mar 21 17:17:41 hostname kernel: 1270134 pages reserved
Mar 21 17:17:41 hostname kernel: 0 pages hwpoisoned
Mar 21 17:17:41 hostname kernel: [ pid ]   uid  tgid total_vm      rss nr_ptes nr_pmds swapents oom_score_adj name
Mar 21 17:17:41 hostname kernel: [ 6484]     0  6484    18155    10027      42       3        0             0 systemd-journal
Mar 21 17:17:41 hostname kernel: [ 6492]     0  6492    48925      106      31       3        0             0 lvmetad
Mar 21 17:17:41 hostname kernel: [ 6508]     0  6508    10888      204      23       3        0         -1000 systemd-udevd
Mar 21 17:17:41 hostname kernel: [13691]    81 13691    14806      170      34       3        0          -900 dbus-daemon
Mar 21 17:17:41 hostname kernel: [13722]     0 13722    24666      113      36       3        0             0 gssproxy
Mar 21 17:17:41 hostname kernel: [13773]     0 13773     6575      294      18       3        0             0 systemd-logind
Mar 21 17:17:41 hostname kernel: [13828]     0 13828     2552       42       9       3        0             0 mcelog
Mar 21 17:17:41 hostname kernel: [13841]    28 13841   252061      132      49       4        0             0 nscd
Mar 21 17:17:41 hostname kernel: [17297]     0 17297     6305       48      17       3        0             0 atd
Mar 21 17:17:41 hostname kernel: [17305]     0 17305     5457      166      16       3        0             0 crond
Mar 21 17:17:41 hostname kernel: [27666]     0 27666   740002      228     128       8        0          1000 nvidia-device-p
Mar 21 17:17:41 hostname kernel: [27948]     0 27948   768386        0     135       7        0          1000 k8s-rdma-device
Mar 21 17:17:41 hostname kernel: [51762]   500 51762  4924384   540881    1612      11        0          -998 python
Mar 21 17:17:41 hostname kernel: [52267]   500 52267 11123381  6667682   13387      35        0          -998 python
Mar 21 17:17:41 hostname kernel: [52268]   500 52268 17501217  6589798   13038      34        0          -998 python
Mar 21 17:17:41 hostname kernel: [52269]   500 52269 11624600  6773967   13959      36        0          -998 python
Mar 21 17:17:41 hostname kernel: [52270]   500 52270 10244907  5860759   11747      31        0          -998 python
Mar 21 17:17:41 hostname kernel: [52271]   500 52271 26736923 14863168   29197      66        0          -998 python
Mar 21 17:17:41 hostname kernel: [52272]   500 52272 19468376 11931695   23471      54        0          -998 python
Mar 21 17:17:41 hostname kernel: [52273]   500 52273 23800702  6885743   13615      35        0          -998 python
Mar 21 17:17:41 hostname kernel: [52279]   500 52279 13275742  7803480   16552      42        0          -998 python
Mar 21 17:17:41 hostname kernel: [53117]     0 53117     8637       56      13       3        0          -647 server_netflowV

发现 k8s-rdma-device和nvidia-device-p的oom_score_adj值为1000，oom发生时被kill的优先级较高，下面的日志显示干掉了nvidia-device-p，这里虽然两个进程优先级配置一样，但还要结合其他条件如进程存活时间、进程占用内存大小等判断，具体参考https://www.jianshu.com/p/ba1cdf92a602 文章中oom killer 怎么挑选进程这部分

Mar 21 17:17:41 hostname kernel: Out of memory: Kill process 27666 (nvidia-device-p) score 1000 or sacrifice child
Mar 21 17:17:41 hostname kernel: Killed process 27666 (nvidia-device-p) total-vm:2960008kB, anon-rss:912kB, file-rss:0kB, shmem-rss:0kB
Mar 21 17:17:41 hostname kernel: oom_reaper: reaped process 27666 (nvidia-device-p), now anon-rss:0kB, file-rss:32kB, shmem-rss:0kB

上面日志可以看出kill掉进程后系统释放了anon-rss:912kB 物理内存，这里需要额外说明下912kB与进程状态查询出来的rss:228是4:1的关系，这是因为后者展示的是内存页数，x86服务器一般一页为4kB，不要以为日志中进程状态展示的rss单位是kB或者B。

进一步分析oom killer发生前系统统计的进程资源展示，发现几个python进程几乎用满了系统256G内存，联系业务同事增加资源限制，避免再次oom。

参考：

https://www.jianshu.com/p/8dd45fdd8f33

https://www.jianshu.com/p/ba1cdf92a602

https://www.jianshu.com/p/c2e7d36829af

https://blog.csdn.net/hu_jinghui/article/details/81740575