Es ist mal wieder soweit: „mir ham a problem“ (cnr)
Leider ist es kein witziges Problem, deswegen ist der Gag oben auch echt unangebracht, aber wie das so ist, Menschen versuchen ernste Probleme mit Humor zu vereinfachen. Vermutlich geben die „Forscher“ Ihren tollen Sicherheitslücken deswegen Namen wie „Dirty COW“ oder „Poodle“.
Out-Of-Memory
Wie Ihr schon im Beitrag über das Abschalten der RAM Disk für /tmp lesen konntet, sind OOM Probleme grade meine Hauptsorge #1. Seit Kernel 4.7.2 häufen sich die Meldungen, daß Systeme mit exorbitant viel RAM keinen Speicher mehr haben. Das Kürzel ist OOM was für Out-Of-Memory steht und die dafür zuständige Kernelkomponente ist, na wer räts? Der OOM-Killer 🙂
Mein aktuelles Sorgenkind hat 10 GB RAM und benutzt davon im Normalfall 1.5 GB, der Rest geht für Caches drauf, was die Performance des Systems erhöht, aber auch die Ursache sein könnte, denn mit 8.5 GB freiem Speicher, kann man wohl kaum im normalen Betrieb einen OOM produzieren, wenn man einen Webserver betreibt. Es gibt nur einen Grund wieso ein OOM passieren kann : Die Anforderung an RAM ist größer als der freie Speicher + Swap .
Ursachenforschung
Bei der Analyse des Problems fiel auf, daß SWAP überhaupt nicht benutzt wird, wenn es zum OOM kommt, was nur bedeuten kann, der Algorithmus des OOM-Mechanismuses im Kernel hat einen Bug. Wie es der Zufall so will, hatte das 16 GB Laptop von Linus Torvalds im September einen OOM Vorfall, welcher Mr. Linux dazu gebracht hat, eine Email dazu rumzuschicken. In der Email findet sich der Hinweis, daß Linus vermutet, ein 1 KB Ramrequest hätte seine 16 GB Maschine zum OOM gezwungen. Ferner entnehmen wir der Email, daß im Kernel 4.7 ein neuer Patch für OOM Situationen implementiert wurde:
"I'm afraid that the oom situation is still not fixed, and the "let's die quickly" patches are still a nasty regression." (Linus Torvalds, 18.9.2016)
Nun passiert das zum Glück nicht nur mir, weil mir ja sonst wieder Paranoia und „unsupported systemconfigurations“ vorgeworfen würden 😉 . Einer der Bugreporter bei Redhat berichtet dann auch, daß er das verhindern konnte, indem er einen Cron eingerichtet hat, der alle 2 Stunden die Caches auf die Platte geflusht hat.
Ob Cacheflushen hilft ?
sync && echo 1 > /proc/sys/vm/drop_caches
Natürlich werde ich das ausprobieren, denn wenn das funktioniert, ist die Ursache sehr wahrscheinlich Memory Fragmentation caused by Cacheallocations. Das würde nämlich passen. Der Server hat immer dann Probleme, wenn viel Cachespeicher in Gebrauch ist. Caches bauen sich nicht so auf, daß der Kernel sieht „oh jetzt habe ich 8 GB frei, laß mal 8 GB am Stück belegen, ich gebs frei, wenn einer was will“ sondern das wird Portionsweise gemacht, mal hier 100 MB, da mal 200 MB, wie die Aktivitäten des Systems das eben grade brauchen. d.b. Selbst wenn keine neuen Prozesse über die Zeit dazu kämen und Speicher bräuchten, würde der freie Speicher in Cacheblöcke aufgeteilt, die wiederum nach Benutzung ggf. freigegeben und neu alloziert werden.
1 Woche Memorystatistiken und solange die Caches klein waren, gab es keine OOMs.
Dies ist ein hochdynamischer Vorgang, den man sich als Laie schwer vorstellen kann. Selbst Cachblöcke werden intern über einen Poolingalgorithmus verwaltet, d.b. der Kernel nimmt mehr freien Speicher als er grade braucht in der Annahme, daß der in Zukunft schon belegt werden wird. Daher gibt es im MemoryPool Funktionen Speicher innerhalb eines Pools zu allozieren oder freizugeben : Speicherverwaltung in Speicherblöcken.
Memorypools
Das ist beileibe keine neue Erfindung, das hatte schon ein Amiga 1988 zu bieten. So ein MemoryPool ist sogar extrem sinnvoll in dynamischen Situationen, weil man damit Verwaltungslasten vom System auf einen Prozess umlagert (Stichwort Selbstorganisation). Der Kernel muß sich um weniger Speicherbereiche kümmern, was den Aufwand minimiert und die Speicherverwaltungsketten für Speicherblöcke minimiert. Das schafft quasi „Übersicht“ und ist für alle schneller, weil er bessere Entscheidungen treffen kann.
OOM im Logfile
Damit Ihr einen OOM erkennen könnt, so sieht der im Logfile aus :
Nov 16 20:28:52 {VMNAME} kernel: Out of memory: Kill process 4348 (java) score 36 or sacrifice child
Nov 16 20:28:52 {VMNAME} kernel: Killed process 4348 (java) total-vm:1415176kB, anon-rss:411284kB, file-rss:16108kB, shmem-rss:0kB
Nov 16 22:09:07 {VMNAME} kernel: mysqld invoked oom-killer: gfp_mask=0x27000c0(GFP_KERNEL_ACCOUNT|__GFP_NOTRACK), order=1, oom_score_adj=0
Nov 16 22:09:07 {VMNAME} kernel: mysqld cpuset=/ mems_allowed=0
Nov 16 22:09:07 {VMNAME} kernel: CPU: 1 PID: 670 Comm: mysqld Not tainted 4.7.10-100.fc23.i686+PAE #1
Nov 16 22:09:07 {VMNAME} kernel: c0e18967 cebd2808 0000020f d0fd5d30 c0753527 c6b34200 00000021 d0fd5d78
Nov 16 22:09:07 {VMNAME} kernel: c05d8adf c0d35b0c ca15a574 027000c0 d0fd5e6c 00000001 00000000 d0fd5d58
Nov 16 22:09:07 {VMNAME} kernel: c0b4133d d0fd5d78 c075928f ecfa6000 00000000 c0e29320 c6b34200 00000021
Nov 16 22:09:07 {VMNAME} kernel: Call Trace:
Nov 16 22:09:07 {VMNAME} kernel: [<c0753527>] dump_stack+0x58/0x81
Nov 16 22:09:07 {VMNAME} kernel: [<c05d8adf>] dump_header+0x4d/0x18f
Nov 16 22:09:07 {VMNAME} kernel: [<c0b4133d>] ? _raw_spin_unlock_irqrestore+0xd/0x10
Nov 16 22:09:07 {VMNAME} kernel: [<c075928f>] ? ___ratelimit+0x9f/0xf0
Nov 16 22:09:07 {VMNAME} kernel: [<c057426b>] oom_kill_process+0x1db/0x3c0
Nov 16 22:09:07 {VMNAME} kernel: [<c047556a>] ? has_capability_noaudit+0x1a/0x30
Nov 16 22:09:07 {VMNAME} kernel: [<c0573bdd>] ? oom_badness.part.14+0xad/0x120
Nov 16 22:09:07 {VMNAME} kernel: [<c057463b>] out_of_memory+0x18b/0x2c0
Nov 16 22:09:07 {VMNAME} kernel: [<c057920c>] __alloc_pages_nodemask+0xccc/0xd20
Nov 16 22:09:07 {VMNAME} kernel: [<c05795cf>] alloc_kmem_pages_node+0x2f/0xa0
Nov 16 22:09:07 {VMNAME} kernel: [<c04693a4>] copy_process.part.38+0xf4/0x1490
Nov 16 22:09:07 {VMNAME} kernel: [<c0454ab1>] ? pvclock_clocksource_read+0xa1/0x160
Nov 16 22:09:07 {VMNAME} kernel: [<c0454ab1>] ? pvclock_clocksource_read+0xa1/0x160
Nov 16 22:09:07 {VMNAME} kernel: [<c046a904>] _do_fork+0xd4/0x370
Nov 16 22:09:07 {VMNAME} kernel: [<c0761756>] ? _copy_to_user+0x26/0x30
Nov 16 22:09:07 {VMNAME} kernel: [<c046ac8c>] SyS_clone+0x2c/0x30
Nov 16 22:09:07 {VMNAME} kernel: [<c040377e>] do_int80_syscall_32+0x5e/0xc0
Nov 16 22:09:07 {VMNAME} kernel: [<c0b41891>] entry_INT80_32+0x31/0x31
Nov 16 22:09:07 {VMNAME} kernel: [<c0b40000>] ? rt_mutex_futex_unlock+0x30/0x40
Nov 16 22:09:08 {VMNAME} kernel: Mem-Info:
Nov 16 22:09:08 {VMNAME} kernel: active_anon:183856 inactive_anon:113422 isolated_anon:0#012 active_file:1090753 inactive_file:852861 isolated_file:0#012 unevictable:0 dirty:0 writeback:2 unstable:0#012 slab_reclaimable:54066 slab_unreclaimable:12950#012 mapped:32115 shmem:173 pagetables:4656 bounce:0#012 free:271310 free_pcp:0 free_cma:0
Nov 16 22:09:08 {VMNAME} kernel: DMA free:2328kB min:16kB low:20kB high:24kB active_anon:0kB inactive_anon:0kB active_file:1256kB inactive_file:264kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15996kB managed:4472kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:300kB slab_unreclaimable:212kB kernel_stack:16kB pagetables:40kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:336 all_unreclaimable? no
Nov 16 22:09:08 {VMNAME} kernel: lowmem_reserve[]: 0 579 10099 10099
Nov 16 22:09:08 {VMNAME} kernel: Normal free:4724kB min:3068kB low:3832kB high:4596kB active_anon:220kB inactive_anon:292kB active_file:161300kB inactive_file:133144kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:720888kB managed:604904kB mlocked:0kB dirty:0kB writeback:0kB mapped:240kB shmem:0kB slab_reclaimable:215964kB slab_unreclaimable:51588kB kernel_stack:4704kB pagetables:18584kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Nov 16 22:09:08 {VMNAME} kernel: lowmem_reserve[]: 0 0 76160 76160
Nov 16 22:09:08 {VMNAME} kernel: HighMem free:1078188kB min:512kB low:13108kB high:25704kB active_anon:735204kB inactive_anon:453396kB active_file:4200456kB inactive_file:3278036kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:9748488kB managed:9748488kB mlocked:0kB dirty:0kB writeback:8kB mapped:128216kB shmem:692kB slab_reclaimable:0kB slab_unreclaimable:0kB 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? no
Nov 16 22:09:08 {VMNAME} kernel: lowmem_reserve[]: 0 0 0 0
Nov 16 22:09:08 {VMNAME} kernel: DMA: 18*4kB (UMEH) 16*8kB (UME) 13*16kB (UMEH) 12*32kB (UME) 14*64kB (UME) 3*128kB (UME) 1*256kB (U) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2328kB
Nov 16 22:09:08 {VMNAME} kernel: Normal: 1100*4kB (UMEH) 3*8kB (H) 0*16kB 6*32kB (H) 2*64kB (H) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4744kB
Nov 16 22:09:08 {VMNAME} kernel: HighMem: 10121*4kB (UM) 3475*8kB (UM) 6526*16kB (UM) 11333*32kB (UM) 4201*64kB (UM) 981*128kB (UM) 206*256kB (UM) 49*512kB (UM) 31*1024kB (UM) 9*2048kB (M) 5*4096kB (M) = 1078268kB
Nov 16 22:09:08 {VMNAME} kernel: 1944132 total pagecache pages
Nov 16 22:09:08 {VMNAME} kernel: 323 pages in swap cache
Nov 16 22:09:08 {VMNAME} kernel: Swap cache stats: add 6908, delete 6585, find 321637/322832
Nov 16 22:09:08 {VMNAME} kernel: Free swap = 1036992kB
Nov 16 22:09:08 {VMNAME} kernel: Total swap = 1048572kB
Nov 16 22:09:08 {VMNAME} kernel: 2621343 pages RAM
Nov 16 22:09:08 {VMNAME} kernel: 2437122 pages HighMem/MovableOnly
Nov 16 22:09:08 {VMNAME} kernel: 31877 pages reserved
Nov 16 22:09:08 {VMNAME} kernel: 0 pages hwpoisoned
Nov 16 22:09:08 {VMNAME} kernel: [ pid ] uid tgid total_vm rss nr_ptes nr_pmds swapents oom_score_adj name
Nov 16 22:09:08 {VMNAME} kernel: [ 319] 0 319 17618 11423 33 4 26 0 systemd-journal
Nov 16 22:09:08 {VMNAME} kernel: [ 354] 0 354 3343 804 7 4 92 -1000 systemd-udevd
Nov 16 22:09:08 {VMNAME} kernel: [ 422] 0 422 3457 706 6 4 65 -1000 auditd
Nov 16 22:09:08 {VMNAME} kernel: [ 445] 0 445 1550 21 6 4 79 0 rpc.idmapd
Nov 16 22:09:08 {VMNAME} kernel: [ 450] 70 450 1711 902 7 4 65 0 avahi-daemon
Nov 16 22:09:08 {VMNAME} kernel: [ 453] 0 453 583 405 5 4 27 0 acpid
Nov 16 22:09:08 {VMNAME} kernel: [ 454] 0 454 9615 4806 22 4 1336 0 yum-updatesd
Nov 16 22:09:08 {VMNAME} kernel: [ 458] 0 458 989 662 5 4 23 0 systemd-logind
Nov 16 22:09:08 {VMNAME} kernel: [ 464] 0 464 128506 9331 135 4 111 0 rsyslogd
usw. usw. usw.Hier wird ein Java Prozess gekillt, weil Mysql mehr Speicher brauchte 🙁
Wie man an diesen Zeilen sehen kann, war min. 4.5 GB RAM frei und der Swap wurde nicht benutzt.
Nov 16 22:09:08 {VMNAME} kernel: Normal free:4724kB min:3068kB low:3832kB high:4596kB active_anon:220kB inactive_anon:292kB active_file:161300kB inactive_file:133144kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:720888kB managed:604904kB mlocked:0kB dirty:0kB writeback:0kB mapped:240kB shmem:0kB slab_reclaimable:215964kB slab_unreclaimable:51588kB kernel_stack:4704kB pagetables:18584kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Nov 16 22:09:08 {VMNAME} kernel: HighMem free:1078188kB min:512kB low:13108kB high:25704kB active_anon:735204kB inactive_anon:453396kB active_file:4200456kB inactive_file:3278036kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:9748488kB managed:9748488kB mlocked:0kB dirty:0kB writeback:8kB mapped:128216kB shmem:692kB slab_reclaimable:0kB slab_unreclaimable:0kB 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? no
Nov 16 22:09:08 {VMNAME} kernel: Free swap = 1036992kB
Nov 16 22:09:08 {VMNAME} kernel: Total swap = 1048572kBWenn man sich den Thread auf der Kernel-ML weiter durchliest, kommt raus, daß erst mit Kernel 4.9 mit einer Verbesserung zu rechnen ist. Ab 4.9 wird ein anderer Algorithmus benutzt, der „härter“ versuchen soll, den OOM zu verhindern. Man wird sehen.
Update 18:00 Uhr :
Das Wegflushen der Filecache hat nichts gebracht. Aber Kernel 4.6.8 sollte noch keine oom’s produzieren. Das beinhaltet aber wieder eine Angriffsfläche für den Dirty COW Exploit.