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:
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':
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:
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:
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:
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:
Jan 27 04:39:08 blackbird systemd[1]: mariadb.service: Main process exited, code=killed, status=9/KILL
Jan 27 04:39:08 blackbird rndc[19408]: rndc: connect failed: 127.0.0.1#953: connection refused
Jan 27 04:39:08 blackbird systemd[1]: mariadb.service: Unit entered failed state.
Jan 27 04:39:08 blackbird systemd[1]: mariadb.service: Failed with result 'signal'.
Jan 27 04:39:08 blackbird systemd[1]: bind9.service: Main process exited, code=killed, status=9/KILL
Jan 27 04:39:08 blackbird systemd[1]: bind9.service: Control process exited, code=exited status=1
Jan 27 04:39:08 blackbird systemd[1]: bind9.service: Unit entered failed state.
Jan 27 04:39:08 blackbird systemd[1]: bind9.service: Failed with result 'exit-code'.
Jan 27 04:39:08 blackbird systemd[1]: mariadb.service: Service hold-off time over, scheduling restart.
Jan 27 04:39:08 blackbird systemd[1]: Stopped MariaDB database server.
Jan 27 04:39:08 blackbird systemd[1]: Starting MariaDB database server...
Alles anzeigen
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:
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