Iedere Linux engineer kent het fenomeen wel; om één of andere reden draait een bepaald proces niet meer en je vindt niet direct een goede reden terug in de logs van dat proces. Tot je in de serverlogs gaat graven en ziet dat de OOM killer besloten heeft om het proces af te schieten. Maar wat is die OOM killer nu precies en waarom treedt die zo drastisch op? In dit artikel gaan we daar verder op in.

Wat is de OOM killer?

De OOM (Out Of Memory) killer is een mechanisme binnen de Linux-kernel dat wordt geactiveerd wanneer het systeem niet langer voldoende vrij RAM-geheugen heeft om aan de behoeften van alle actieve processen te voldoen. Dit mechanisme is ontworpen om het systeem te beschermen tegen volledig vastlopen door selectief processen te beëindigen en zo geheugen vrij te maken.

Hoe werkt de OOM killer?

Detectie van een tekort aan geheugen

Wanneer de Linux-kernel detecteert dat er een ernstig geheugenprobleem is, en alle pogingen om extra geheugen vrij te maken (zoals het wissen van de page cache, swap, enz.) zijn uitgeput, besluit de kernel dat een proces moet worden beëindigd om geheugen vrij te maken.

Hoe wordt dat proces bepaald?

De OOM-killer bepaalt welk proces moet worden beëindigd op basis van een heuristisch scoringssysteem. Elke taak of proces in het systeem krijgt een score, genaamd de “oom_score”. Hoe hoger de score, hoe waarschijnlijker het is dat het proces wordt gekozen om te worden beëindigd. Deze score wordt berekend op basis van verschillende factoren:

• Geheugengebruik: Processen die veel geheugen verbruiken, krijgen een hogere score.
• Prioriteit van het proces: System- en kernelprocessen krijgen een lagere score omdat hun beëindiging kritieke systeemproblemen kan veroorzaken.
• Parent-child relaties: Als een parent proces wordt beëindigd, zullen zijn children vaak ook worden beëindigd om zombieprocessen te vermijden.
• Aanpassingen door de gebruiker: Beheerders kunnen de “oom_adj” of “oom_score_adj” waarde van een proces handmatig aanpassen om zijn kans om door de OOM-killer te worden gekozen te verhogen of te verlagen.

De totale “oom_score” van een proces kan worden gevonden in /proc/[pid]/oom_score, en deze waarde is een indicatie van hoe waarschijnlijk het is dat het proces door de OOM-killer wordt gekozen.

Stoppen van het proces

Zodra het proces is gekozen, zal de OOM-killer het beëindigen. Dit beëindigen gebeurt via een signaal (meestal SIGKILL), wat leidt tot onmiddellijke terminatie van het proces zonder kans om zichzelf schoon af te sluiten. Dit is een brute-force methode die ervoor zorgt dat het geheugen direct vrijkomt.

Loggen van deze actie

De kernel logt de acties van de OOM-killer, inclusief welk proces is beëindigd, de reden voor de beëindiging en de hoeveelheid geheugen die hierdoor is vrijgekomen. Deze informatie kan worden teruggevonden in de systeemlogs (vaak in /var/log/syslog of via het commando dmesg).

Een voorbeeld en uiteenzetting van zo’n melding ziet er zo uit:

[Sat Aug 10 12:30:10 2024] git invoked oom-killer: gfp_mask=0x6040c0(GFP_KERNEL|__GFP_COMP), order=2, oom_score_adj=0
[Sat Aug 10 12:30:10 2024] CPU: 2 PID: 509789 Comm: git Kdump: loaded Not tainted 4.18.0-553.el8_10.x86_64 #1
[Sat Aug 10 12:30:10 2024] Hardware name: VMware, Inc. VMware7,1/440BX Desktop Reference Platform, BIOS VMW71.00V.21100432.B64.2301110304 01/11/2023
[Sat Aug 10 12:30:10 2024] Call Trace:
[Sat Aug 10 12:30:10 2024]  dump_stack+0x41/0x60
[Sat Aug 10 12:30:10 2024]  dump_header+0x4a/0x1df
[Sat Aug 10 12:30:10 2024]  oom_kill_process.cold.33+0xb/0x10
[Sat Aug 10 12:30:10 2024]  out_of_memory+0x1bd/0x4e0
[Sat Aug 10 12:30:10 2024]  __alloc_pages_slowpath+0xbf0/0xcd0
[Sat Aug 10 12:30:10 2024]  __alloc_pages_nodemask+0x2e2/0x330
[Sat Aug 10 12:30:10 2024]  new_slab+0x3f4/0x4f0
[Sat Aug 10 12:30:10 2024]  ___slab_alloc+0x3a3/0x950
[Sat Aug 10 12:30:10 2024]  ? copy_process+0x215/0x1b50
[Sat Aug 10 12:30:10 2024]  ? obj_cgroup_charge_pages+0xbe/0xe0
[Sat Aug 10 12:30:10 2024]  ? copy_process+0x215/0x1b50
[Sat Aug 10 12:30:10 2024]  kmem_cache_alloc_node+0x253/0x2b0
[Sat Aug 10 12:30:10 2024]  copy_process+0x215/0x1b50
[Sat Aug 10 12:30:10 2024]  _do_fork+0x8b/0x340
[Sat Aug 10 12:30:10 2024]  do_syscall_64+0x5b/0x1b0
[Sat Aug 10 12:30:10 2024]  entry_SYSCALL_64_after_hwframe+0x61/0xc6
[Sat Aug 10 12:30:10 2024] RIP: 0033:0x7f89cf78d143
[Sat Aug 10 12:30:10 2024] Code: db 0f 85 28 01 00 00 64 4c 8b 0c 25 10 00 00 00 45 31 c0 4d 8d 91 d0 02 00 00 31 d2 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 0f 87 b9 00 00 00 41 89 c5 85 c0 0f 85 c6 00 00
[Sat Aug 10 12:30:10 2024] RSP: 002b:00007ffe060bcae0 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[Sat Aug 10 12:30:10 2024] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f89cf78d143
[Sat Aug 10 12:30:10 2024] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[Sat Aug 10 12:30:10 2024] RBP: 0000000000000000 R08: 0000000000000000 R09: 00007f89d02c6f00
[Sat Aug 10 12:30:10 2024] R10: 00007f89d02c71d0 R11: 0000000000000246 R12: 0000000000000001
[Sat Aug 10 12:30:10 2024] R13: 00007ffe060bcb50 R14: 0000000000000000 R15: 00007ffe060bcb70
[Sat Aug 10 12:30:10 2024] Mem-Info:
[Sat Aug 10 12:30:10 2024] active_anon:3681441 inactive_anon:417474 isolated_anon:0
active_file:30473 inactive_file:16140 isolated_file:0
unevictable:627 dirty:609 writeback:0
slab_reclaimable:1723903 slab_unreclaimable:322374
mapped:27873 shmem:699 pagetables:13466 bounce:0
free:181901 free_pcp:115 free_cma:0
[Sat Aug 10 12:30:10 2024] Node 0 active_anon:14725764kB inactive_anon:1669896kB active_file:121892kB inactive_file:64560kB unevictable:2508kB isolated(anon):0kB isolated(file):0kB mapped:111492kB dirty:2436kB writeback:0kB shmem:2796kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 202752kB writeback_tmp:0kB kernel_stack:19212kB pagetables:53864kB all_unreclaimable? no
[Sat Aug 10 12:30:10 2024] Node 0 DMA free:11264kB min:28kB low:40kB high:52kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[Sat Aug 10 12:30:10 2024] lowmem_reserve[]: 0 2706 31835 31835 31835
[Sat Aug 10 12:30:10 2024] Node 0 DMA32 free:119364kB min:5740kB low:8508kB high:11276kB active_anon:274668kB inactive_anon:85252kB active_file:552kB inactive_file:208kB unevictable:0kB writepending:0kB present:3128732kB managed:2800988kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[Sat Aug 10 12:30:10 2024] lowmem_reserve[]: 0 0 29128 29128 29128
[Sat Aug 10 12:30:10 2024] Node 0 Normal free:596976kB min:90480kB low:120308kB high:150136kB active_anon:14451096kB inactive_anon:1583872kB active_file:121340kB inactive_file:64352kB unevictable:2508kB writepending:2436kB present:30408704kB managed:29836568kB mlocked:2508kB bounce:0kB free_pcp:460kB local_pcp:12kB free_cma:0kB
[Sat Aug 10 12:30:10 2024] lowmem_reserve[]: 0 0 0 0 0
[Sat Aug 10 12:30:10 2024] Node 0 DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 2*4096kB (M) = 11264kB
[Sat Aug 10 12:30:10 2024] Node 0 DMA32: 1081*4kB (UME) 1258*8kB (UME) 1281*16kB (UME) 24*32kB (UME) 872*64kB (UE) 218*128kB (E) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 119364kB
[Sat Aug 10 12:30:10 2024] Node 0 Normal: 75403*4kB (UMEH) 36845*8kB (UEH) 2*16kB (H) 2*32kB (H) 3*64kB (H) 3*128kB (H) 1*256kB (H) 2*512kB (H) 0*1024kB 0*2048kB 0*4096kB = 598324kB
[Sat Aug 10 12:30:10 2024] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[Sat Aug 10 12:30:10 2024] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[Sat Aug 10 12:30:10 2024] 67741 total pagecache pages
[Sat Aug 10 12:30:10 2024] 20408 pages in swap cache
[Sat Aug 10 12:30:10 2024] Swap cache stats: add 53729283, delete 53712173, find 38041573/56230750
[Sat Aug 10 12:30:10 2024] Free swap  = 0kB
[Sat Aug 10 12:30:10 2024] Total swap = 4194300kB
[Sat Aug 10 12:30:10 2024] 8388358 pages RAM
[Sat Aug 10 12:30:10 2024] 0 pages HighMem/MovableOnly
[Sat Aug 10 12:30:10 2024] 225129 pages reserved
[Sat Aug 10 12:30:10 2024] 0 pages hwpoisoned
[Sat Aug 10 12:30:10 2024] Tasks state (memory values in pages):
[Sat Aug 10 12:30:10 2024] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
[Sat Aug 10 12:30:10 2024] [    969]     0   969    55261     3165   319488     2536             0 systemd-journal
[Sat Aug 10 12:30:10 2024] [   1034]     0  1034    26497     1198   225280      737         -1000 systemd-udevd
[Sat Aug 10 12:30:10 2024] [   1476]    32  1476    16832      696   167936      163             0 rpcbind
[Sat Aug 10 12:30:10 2024] [   1478]     0  1478    38521      801   184320      282         -1000 auditd
[Sat Aug 10 12:30:10 2024] [   1480]     0  1480    23569      670   225280    11443             0 sedispatch
[Sat Aug 10 12:30:10 2024] [   1481]     0  1481     2779      433    65536       62             0 audisp-syslog
[Sat Aug 10 12:30:10 2024] [   1513]     0  1513    12625      624   143360      299             0 smartd
[Sat Aug 10 12:30:10 2024] [   1514]     0  1514    31276      695   147456      131             0 irqbalance
[Sat Aug 10 12:30:10 2024] [   1516]     0  1516    18821     1106   188416      430             0 VGAuthService
[Sat Aug 10 12:30:10 2024] [   1517]     0  1517    90949     1487   339968      385             0 vmtoolsd
[Sat Aug 10 12:30:10 2024] [   1518]     0  1518    94880      951   352256      539             0 abrtd
[Sat Aug 10 12:30:10 2024] [   1526]   994  1526    35594      805   180224      142             0 chronyd
[Sat Aug 10 12:30:10 2024] [   1530]    28  1530   208791     1347   241664      137             0 nscd
[Sat Aug 10 12:30:10 2024] [   1537]    81  1537    17914      949   172032      119          -900 dbus-daemon
[Sat Aug 10 12:30:10 2024] [   1544]     0  1544    95236     1597   376832      923             0 NetworkManager
[Sat Aug 10 12:30:10 2024] [   1550]     0  1550    20312     1141   196608      522             0 systemd-logind
[Sat Aug 10 12:30:10 2024] [   1553]     0  1553   419326     3105   253952     1476             0 ScanAssistant
[Sat Aug 10 12:30:10 2024] [   1607]     0  1607    18651     1078   188416      192         -1000 sshd
[Sat Aug 10 12:30:10 2024] [   1608]     0  1608    66019     4784   331776    26070             0 samhain
[Sat Aug 10 12:30:10 2024] [   1609]     0  1609    28906      387   114688      112             0 rhsmcertd
[Sat Aug 10 12:30:10 2024] [   1620]     0  1620    43220      496   200704      719             0 gssproxy
[Sat Aug 10 12:30:10 2024] [   1623]     0  1623   102243     2184   409600     3455             0 tuned
[Sat Aug 10 12:30:10 2024] [   1652]     0  1652    13977      490   135168      156             0 rpc.gssd
[Sat Aug 10 12:30:10 2024] [   1664]     0  1664     6005      602    86016      162             0 crond
[Sat Aug 10 12:30:10 2024] [   1677]     0  1677     6126      308    98304        0             0 atd
[Sat Aug 10 12:30:10 2024] [   1711]     0  1711     1217      201    57344        0             0 agetty
[Sat Aug 10 12:30:10 2024] [   1726] 530229  1726    11910     1511   126976      519             0 SgUx_LogD.pl
[Sat Aug 10 12:30:10 2024] [   1757]     0  1757   399181    11373   675840     8753             0 metricbeat
[Sat Aug 10 12:30:10 2024] [   1761]     0  1761   119583      565   380928      313             0 rsyslogd
[Sat Aug 10 12:30:10 2024] [   1770]   993  1770    49548     1904   282624      322             0 freshclam
[Sat Aug 10 12:30:10 2024] [   1879]     0  1879    44904     7919   303104     1131             0 adclient
[Sat Aug 10 12:30:10 2024] [   1883]     0  1883    25483      345   110592      101             0 cdcwatch
[Sat Aug 10 12:30:10 2024] [   1914]     0  1914    14974     1546   167936     2191             0 SgUx_AutoAction
[Sat Aug 10 12:30:10 2024] [   1933] 530229  1933    17680     4845   184320      536             0 SgUx_LogScanD.p
[Sat Aug 10 12:30:10 2024] [   1946]     0  1946   255409     2146   270336      565             0 dad
[Sat Aug 10 12:30:10 2024] [   1978]     0  1978   130371     3561   225280     2292             0 BESClient
[Sat Aug 10 12:30:10 2024] [   2166]     0  2166    32485      484   147456      181             0 cdawatch
[Sat Aug 10 12:30:10 2024] [   2214]     0  2214    18510      288   159744      316             0 rscd
[Sat Aug 10 12:30:10 2024] [   2228]     0  2228    18572      156   159744      305             0 rscd
[Sat Aug 10 12:30:10 2024] [   2229]     0  2229    18510      612   163840      288             0 rscd
[Sat Aug 10 12:30:10 2024] [   2363]   998  2363   502101      984   372736     1592             0 polkitd
[Sat Aug 10 12:30:10 2024] [   3124]     0  3124    59862      397   380928     3356             0 linux_agent_exe
[Sat Aug 10 12:30:10 2024] [   3225]     0  3225    99238     1484   499712     3746             0 linux_agent_exe
[Sat Aug 10 12:30:10 2024] [   4213] 557223  4213    10198      908   118784     1048             0 ubrokerd
[Sat Aug 10 12:30:10 2024] [   4530] 557223  4530   309311     2079   262144     3104             0 uagsrv
[Sat Aug 10 12:30:10 2024] [   4532]     0  4532     7175      602    98304      140             0 uemsrv
[Sat Aug 10 12:30:10 2024] [   7721]     0  7721    37059       16    90112      192             0 samhain
[Sat Aug 10 12:30:10 2024] [ 417367]     0 417367   438156    13290   745472     7381             0 filebeat
[Sat Aug 10 12:30:10 2024] [3549217]    29 3549217    11311      472   126976      115             0 rpc.statd
[Sat Aug 10 12:30:10 2024] [2193516] 737120 2193516  5426819  3917107 37040128   453875             0 java
[Sat Aug 10 12:30:10 2024] [2474009]     0 2474009   476279    44626  2158592   191968             0 cbdaemon
[Sat Aug 10 12:30:10 2024] [2474021]     0 2474021   147431       81   155648      774             0 ECStateEngine
[Sat Aug 10 12:30:10 2024] [2474024]     0 2474024   179458     9380   700416    16968             0 event_collector
[Sat Aug 10 12:30:10 2024] [3133255]     0 3133255   422240    53018  3121152   295662             0 clamd
[Sat Aug 10 12:30:10 2024] [3788871]     0 3788871     6058      373    81920      207             0 crond
[Sat Aug 10 12:30:10 2024] [3788874]     0 3788874     3234      691    65536       88             0 scb_cron.sh
[Sat Aug 10 12:30:10 2024] [3788989]     0 3788989     4079      814    81920      827             0 scb.sh
[Sat Aug 10 12:30:10 2024] [ 419852]     0 419852     4079      461    73728      827             0 scb.sh
[Sat Aug 10 12:30:10 2024] [ 419855]     0 419855     1958      396    53248        0             0 xargs
[Sat Aug 10 12:30:10 2024] [ 419856]     0 419856     5171      105    86016        0             0 sed
[Sat Aug 10 12:30:10 2024] [ 419877]     0 419877     7987     3564   102400        0             0 find
[Sat Aug 10 12:30:10 2024] [ 509763] 737120 509763     3683      787    77824        0             0 git
[Sat Aug 10 12:30:10 2024] [ 509774] 737120 509774     3683      789    73728        0             0 git
[Sat Aug 10 12:30:10 2024] [ 509775] 737120 509775     3683      779    73728        0             0 git
[Sat Aug 10 12:30:10 2024] [ 509776] 737120 509776     3683      784    73728        0             0 git
[Sat Aug 10 12:30:10 2024] [ 509778] 737120 509778     3683      793    69632        0             0 git
[Sat Aug 10 12:30:10 2024] [ 509779] 737120 509779    38022     2221   184320        0             0 git-remote-http
[Sat Aug 10 12:30:10 2024] [ 509780] 737120 509780     3683      784    73728        0             0 git
[Sat Aug 10 12:30:10 2024] [ 509781] 737120 509781    21585     2197   188416        0             0 git-remote-http
[Sat Aug 10 12:30:10 2024] [ 509784] 737120 509784    38022     2222   192512        0             0 git-remote-http
[Sat Aug 10 12:30:10 2024] [ 509789] 737120 509789     3683      784    69632        0             0 git
[Sat Aug 10 12:30:10 2024] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/system.slice/jenkins.service,task=java,pid=2193516,uid=737120
[Sat Aug 10 12:30:10 2024] Out of memory: Killed process 2193516 (java) total-vm:21707276kB, anon-rss:15668428kB, file-rss:0kB, shmem-rss:0kB, UID:737120 pgtables:36172kB oom_score_adj:0

• pid: Het process ID.
• uid: User ID.
• tgid: Thread group ID. Deze loopt vaak gelijk met de pid maar is dat zeker niet altijd, pas dus zeker op voor verwarring.
• total_vm: Virtual memory use (in 4 kB pages)
• rss: Resident memory use (in 4 kB pages)
• nr_ptes: Page table entries
• swapents: Page table entries
• oom_score_adj: Normaal gezien is dit 0. Een lager cijfer indiceert dat de kans dat dit proces afgeschoten zal worden veel lager is wanneer de OOM killer optreedt.

Het proces dat de hoogste score OOM score krijgt zal met directe ingang stopgezet worden.

(Een uiteenzetting over het verschil tussen Resident en Virtual memory kan je nalezen in dit uitgebreide artikel)

Wanneer treedt de OOM killer op?

De OOM-killer wordt ingeschakeld wanneer alle pogingen van het systeem om extra geheugen vrij te maken zijn mislukt. Dit gebeurt meestal in scenario’s waar:

• Alle fysiek beschikbare RAM is uitgeput: Inclusief swap-ruimte (als deze is geconfigureerd). Dit kan bijvoorbeeld te wijten zijn aan een plotse piek in het geheugenverbruik van de server.
• Systeem kan geen geheugen meer toewijzen: Voor nieuwe of bestaande processen.
• Andere processen kunnen geen geheugen meer teruggeven: Bijvoorbeeld door foutieve processen of geheugenlekken die alle beschikbare geheugenruimte opslokken.

In dergelijke situaties, om te voorkomen dat het systeem volledig onbruikbaar wordt (ook wel “thrashing” genoemd), grijpt de OOM-killer in om de systeembelasting te verminderen door een proces af te sluiten.

Analyse van de voorgaande OOM killer melding

In een volgende post gaan we verder in op de analyse van de melding in dit artikel.

Heb je nood aan een zachtaardige Linux Engineer die OOM killers te snel af is?