Bei mir geht der OOM-Killer um :-(

  • Ich besitze seit ein paar Monaten einen S 2000 G7 - also einen KVM Server mit 'relativ wenig' Ram und 'relativ wenig' CPU. Dafür aber ordentlich Plattenplatz.
    Die Daten in Kürze:

    Code
    - 2 vCores
    - 4 GB DDR4 RAM (ECC)
    - 3 TB SAS Platten
    - Hostname: blackbird


    Auf dem Server läuft ein Ubuntu 16.04.1 LTS mit: Apache, MariaDB, PHP + BIND9 (und Munin + Icinga2).


    Normalerweise hat der Server mehr als genug RAM frei, hier ein aktuelles 'free':

    Code
    total    	used    	free  	shared  buff/cache   available
    Mem:       	3951     	177     	188      	21    	3585    	3442
    Swap:      	4091     	131    	3960


    Nun hat der Server vier Aufgaben:
    a) In der Nacht macht er ordentlich Backups die er sich selber über rsync holt und komprimiert (fängt gegen 1 Uhr an und ist gegen 6 Uhr fertig). Das treibt die load im Zeitraum um 04:39 Uhr rum auf bis zu 2.5 - also etwas mehr als die 2 Cores gemütlich weg frühstücken können.
    b) Er macht DynDNS für eine Domain mittels BIND9.
    c) Er monitored verschiedene andere Server mit Munin.
    d) Er monitored verschiedene andere Server mit Icinga2.


    Nun trägt es sich zu dass im fraglichen Zeitraum (also um 04:39 Uhr) der BIND9 vom OOM-Killer unsanft aus dem Leben befördert wurde. Das sieht man im systemd:

    Code
    root@blackbird:~# service bind9 status
    ? bind9.service - BIND Domain Name Server
       Loaded: loaded (/lib/systemd/system/bind9.service; enabled; vendor preset: enabled)
      Drop-In: /run/systemd/generator/bind9.service.d
           	+-50-insserv.conf-$named.conf
       Active: failed (Result: exit-code) since Fri 2017-01-27 04:39:05 CET; 3h 35min ago
     	Docs: man:named(8)
      Process: 19408 ExecStop=/usr/sbin/rndc stop (code=exited, status=1/FAILURE)
      Process: 26841 ExecStart=/usr/sbin/named -f -u bind (code=killed, signal=KILL)
     Main PID: 26841 (code=killed, signal=KILL)


    Und man sieht es in der syslog:

    Code
    Jan 27 01:42:27 blackbird kernel: [659060.651955] Killed process 26955 (mysqld) total-vm:1421004kB, anon-rss:26276kB, file-rss:7428kB
    Jan 27 04:39:01 blackbird kernel: [669654.885996] Killed process 12941 (mysqld) total-vm:974540kB, anon-rss:10432kB, file-rss:7668kB
    Jan 27 04:39:05 blackbird kernel: [669658.297823] Killed process 12083 (ssh) total-vm:70908kB, anon-rss:24640kB, file-rss:4880kB
    Jan 27 04:39:05 blackbird kernel: [669658.375007] Killed process 26841 (named) total-vm:290684kB, anon-rss:3308kB, file-rss:5320kB


    Die meisten Prozesse wehren sich gegen das ungemütliche vor die Tür setzen dank systemd:

    Code
    Jan 27 01:42:32 blackbird systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL
    Jan 27 01:42:32 blackbird systemd[1]: mariadb.service: Unit entered failed state.
    Jan 27 01:42:32 blackbird systemd[1]: mariadb.service: Failed with result 'signal'.
    Jan 27 01:42:32 blackbird systemd[1]: mariadb.service: Service hold-off time over, scheduling restart.
    Jan 27 01:42:32 blackbird systemd[1]: Stopped MariaDB database server.
    Jan 27 01:42:32 blackbird systemd[1]: Starting MariaDB database server...


    Leider der bind9 nicht:


    Bevor ich aber jetzt im systemd den bind9 auch einfach restarten lasse, würde ich gerne wissen was der OOM eigentlich für ein Problem hat.
    Beim killen vom ersten mysqld in der Nacht sagt er was von "total-vm:1421004kB" - meiner Meinung ist das also eine komplett-Belegung von 1421 MB virtual Memory. Bei 4 GB Ram sollte mich das doch nicht jucken.


    Anbei mal die Speicherbelegung (laut munin) um 01:42 Uhr und um 04:39 Uhr.


    Script mäßig läuft um 01:42 Uhr ein 'tar -cf' einer sehr großen Datei. Und um 04:39 ein komplett Rsync eines kompletten Servers (~8000 MB).


    Die ausführlichere OOM-Ausgabe von 01:42 Uhr habe ich mal angehängt, dort sieht es so aus als sei Icinga für den Start des OOM-Killers verantwortlich:

    Code
    Jan 27 01:42:27 blackbird kernel: [659060.647302] icinga2 invoked oom-killer: gfp_mask=0x26000c0, order=2, oom_score_adj=0


    erklärt aber immer noch nicht warum der OOM-Killer gerade mal was von "total-vm:1421004kB" erzählt.


    Das System läuft momentan, den BIND9 habe ich nicht neu gestartet. Hat jemand Ideen, Erklärungen oder Ecken in denen ich suchen soll?


    Danke!


    Thomas

  • Ich habe im entsprechenden OOM-Killer Log mal die Spalte total_vm aller Prozesse zusammengezählt und komme auf:

    Code
    2489786


    Sollten das also Kb sein so sind das 2489 MB. Also 2 GB. Kein Problem für meine theoretischen 4 GB Ram und 4 GB Swap. Möchte man meinen...
    Das mit dem Swap gibt der OOM-Killer sogar zu:

    Code
    Jan 27 01:42:27 blackbird kernel: [659060.647579] Free swap  = 4013248kB
    Jan 27 01:42:27 blackbird kernel: [659060.647581] Total swap = 4190204kB


    Hier nochmal die aktuelle '/proc/meminfo':

  • Wie viele Dateien (inkl. Hardlinks!) sicherst Du mit rsync? Je nach Anzahl und Konfiguration kann rsync gerne mal ein paar Gigabyte RAM belegen.



    MfG Christian

    "Wer nur noch Enten sieht, hat die Kontrolle über seine Server verloren." (Netzentenfund)

  • Um ~04 Uhr sinds 366565 Inodes. Aber um ~01 Uhr sinds ca. 19344 Dateien.
    Um ~01 Uhr läuft auch garkein rsync, da läuft nur der tar (laut Ausgabe des OOM-Killers).
    Um ~4 Uhr läuft tatsächlich der rsync während der OOM rumturnt, sogar zweimal. Aber an VM belegt er '44176 KB' und '31477 KB'.
    Anbei das Log um 4 Uhr beim OOM-Killer.


    Aber auch hier, wenn ich die Speicherbelegung der Prozesse zusammenzähle komme ich auf 2318 MB.
    Und auch das Munin zeigt ja (siehe Bilder im ersten Beitrag) immer noch mindestens 1 GB Cache an. Also freier Speicher der genutzt werden kann.


    Momentan überlege ich ob eventuell die Hostmaschine den Speicher overprovisioned und meine VM deshalb einfach keinen Speicher mehr allokieren kann, wobei daraufhin der OOM-Killer rumturnt.
    Das wäre momentan die einzige vernünftige Erklärung (aus meiner Sicht).
    Ich habe den netcup-Support angeschrieben und hoffe dass er mir weiter hilft und nachforscht wie die Speicherauslastung des Hosts zu den fraglichen Zeitpunkten war.


    Thomas


    PS: Danke für deine Hilfe killerbees19!

  • Der Support hat geantwortet und gesagt:
    a) Die Systeme werden nicht überbucht, und
    b) Das Hostsystem hatte zum fraglichen Zeitpunkt keine Ressourcenprobleme


    So, und wie komme ich jetzt hier weiter?
    Wenn irgendwo stehen würde dass zum fraglichen Zeitpunkt tatsächlich alle 4 GB (+ SWAP) verwendet worden sind wäres ja klar - aber das steht ja nirgendwo.
    Grumpf!


    Ich reboote jetzt mal das System und guck wanns wieder auftritt...
    Außerdem hab ich die Sicherungsjobs etwas entzerrt und nutze nun mehr Nacht aus :)
    Um 06:25 Uhr laufen natürlich die Daily-Crontabs. Damit auch ein updatedb.
    updatedb bei einer 300 GB SAS Platte dauert auch ein Stück...


    Gutem Rat bin ich natürlich weiterhin nicht abgeneigt!


    Thomas

  • Guten Tag,


    Zitat


    b) Das Hostsystem hatte zum fraglichen Zeitpunkt keine Ressourcenprobleme

    hätte das Hostsystem Ressourcenprobleme, würde ja nicht der OOM-Killer des eigenen Systems ankommen sondern das System würden vermutlich mit Speicherzugriffsfehlern aussteigen. So genau habe ich das noch nicht ausprobiert, allerdings kann ein Gastsystem ja nicht feststellen wie es auf dem Hostsystem aussieht um dann den eigenen OOM-Killer loszuschicken.


    Viele Grüße


    Felix Preuß

  • Ich reboote jetzt mal das System und guck wanns wieder auftritt...
    Gutem Rat bin ich natürlich weiterhin nicht abgeneigt!


    Um das derzeitige Problem zeitnah aufspüren zu können, würde ich das System nicht neu starten, da dadurch mit höchster Wahrscheinlichkeit das derzeitige Problem nur nach hinten verschoben wird.

  • Um das derzeitige Problem zeitnah aufspüren zu können, würde ich das System nicht neu starten, da dadurch mit höchster Wahrscheinlichkeit das derzeitige Problem nur nach hinten verschoben wird.

    Hallo AndreasDe - da hast du natürlich eigentlich recht. Aber das System ist halt doch produktiv und ich will nicht riskieren dass irgendwas notwendiges nicht mehr sauber läuft.
    Beim letzten Mal hat es nach dem Neustart ca. 1 Woche gedauert bis das Problem wieder aufgetreten ist.
    Durchs entzerren der Crontab wirds wohl (hoffentlich) gar nicht mehr auftreten. Ist zwar nur ein Workaround aber auf eine Lösung des "eigentlichen Problemes" habe ich momentan wenig Hoffnung.


    Mehr als die jetzt schon gesicherten Logfiles würde es auch nicht geben. Mehr als ein 5-minütiges Monitoring der Speicherauslastung mit Munin wird wahrscheinlich auch nichts neues zu Tage bringen.


    Außer jemand hätte einen Lösungsansatz, dann probier ich das gerne aus!


    Thomas

  • Naja, ich hatte vermutet dass der OOM-Killer loszieht sobald eine Speicher-Allokierung nicht geklapt hat - und das könnte natürlich der Fall sein wenn der VM-Host keinen Speicher hergibt.


    Sehe ich auch so.


    Durchs entzerren der Crontab wirds wohl (hoffentlich) gar nicht mehr auftreten. Ist zwar nur ein Workaround aber auf eine Lösung des "eigentlichen Problemes" habe ich momentan wenig Hoffnung.


    Diese Maßnahme müßte aber auch ohne Neustart ausreichen. Denn dadurch kann eventuell dessen Auswirkung sofort erkannt werden und nicht erst Wochen später zur sehr ungünstigen Zeit.

  • Das dürfte der Grund für dein Problem sein:
    Ubuntu 16.04 LTS User: “Out of memory” errors after upgrade to kernel v4.4.0-59"


    Bug #1655842 ""Out of memory” errors after upgrade to 4.4.0-59” : Bugs : linux package : Ubuntu



    Scheint aktuell mehrere zu betreffen, egal wie viel RAM die Maschine hat. Ein Nutzer meldet dort, dass es auch bei ihm passiert ist, obwohl nur 4GB von 18 GB RAM genutzt wurden.
    Nach dem Thread auf Launchpad kommt der Patch angeblich erst am 20.02., zwischenzeitlich hilft wohl ein Downgrade auf Kernel v4.4.0-57.

  • Bitte Berichte nachher unbedingt, ob der Kernel-Downgrade etwas gebracht hat! :)



    MfG Christian

    "Wer nur noch Enten sieht, hat die Kontrolle über seine Server verloren." (Netzentenfund)

  • ThomasChr
    Auf einen virtuellen Server (auch KVM) bei einem Fremdanbieter habe ich auch Ubuntu 16.04 LTS mit der Kernelversion 4.4.0-59 drauf und habe mal mit dem DD-Befehl eine ca. 5GB große Datei in einer RAM-Disk geschrieben. Das Ergebnis sieht danach wie folgt aus:



    Da auf diesem virtuellen Server keiner der darauf laufenden Dienste dabei abgestürzt ist, gehe ich mal davon aus, daß es nicht am Kernel liegen dürfte, sondern eher an der Schreibgeschwindigkeit des RAM´s. Siehe folgendes Ergebnis, welches ich auch auf zwei RS 6000er Server bei netcup durchgeführt habe.


    Der Gegentest der beiden RS 6000er bei netcup ergab folgende Ergebnisse:



    Schau dir von daher auch mal die Schreibleistung des RAM´s genauer an.


    Meine Beobachtungen haben gezeigt, dass sich die Schreibgeschwindigkeit schleichend verschlechtert und sich erst nach einer ununterbrochenen Laufzeit von ca. 20 Tagen zeigt.
    Nach einem Serverneustart zeigen beide wieder ihre volle Schreibgeschwindigkeit von ca. 1.7 GB/s.

  • Hmmm, das Problem ist gestern wieder aufgetreten. Diesmal hats sogar den Indianer erwischt.
    Dies ist das einzige System was den Speicher so durchgehend fragmentiert und in der Nacht lange Zeit kräftig CPU braucht.


    Meine anderen Systeme haben den gleichen Kernel aber keine Probleme.


    Wenn ein Fix am 20.02 Februar rauskommen sollte halte ich das bis dahin aus. Alle drei Tage mal routinemäßig rebooten sollte ja ausreichend sein.
    Und tagsüber reboot ist für ein Backup System welches nachts Backups macht auch kein Problem.