Spaß mit Swapping (Debian Squeeze)
15. Juni 2013 um 19:00 Uhr von Atari-Frosch
Vor knapp drei Stunden stellte ich fest, daß mein Server nicht antwortet. Oder besser, fast nicht. Ping ging noch durch, sogar mit relativ normalen Antwortzeiten, aber die Dienste antworteten allesamt nicht.
Das passiert nicht zum ersten Mal, und der zeitliche Zusammenhang mit dem letzten Kernel-Update von Debian Squeeze ist nicht zu übersehen. Der Verlauf ist immer gleich: Vor allem der Swap läuft scheinbar grundlos voll, die CPU-Load geht hoch, und in gleichem Maße verlangsamte sich die Reaktion der Serverdienste, oder sie reagierten eben gar nicht mehr. Allerdings war bisher nicht immer alles „tot“ gewesen; bitlbee und der ZNC waren unbeeindruckt weitergelaufen. Diesmal kam es eine ganze Ecke härter.
Bei den letzten Malen, als der Swap vollzulaufen drohte, genügte es jeweils, die am meisten swappenden Dienste neuzustarten; das waren mysql, apache2, tor (läuft hier als Bridge) und seltsamerweise eine Instanz von eggdrop, die allein etwa 19 MB haben will (eine zweite Instanz hat das Problem nicht; liegt vielleicht an einem Botscript). Welches Programm wieviel Swap belegt, kann man übrigens mit einem kleinen Script von Erik Ljungstrom gut herausfinden.
Auf eine Antwort zu meinem Versuch, mich per ssh einzuloggen, wagte ich schon gar nicht mehr zu hoffen, als sie dann doch endlich kam. So nach 10 Minuten. Nach der Eingabe des Usernamens wartete ich nochmal so lange auf die Paßwortanforderung, danach nochmal so lange, bis der Prompt kam. Und dann nochmal so lange auf die Paßwortanforderung für root.
htop brauchte für eine Reaktion dann schon fast die doppelte Zeit. Und über die Anzeige, die dann kam, war ich „not amused“: CPU-Load über 42, RAM fast voll, der Swap mit 1,1 GB (von 1,9) auch fast voll. Da schien es mir nicht mehr sinnvoll, einzelne Dienste neu zu starten. Den Befehl zum Neustart gab ich um 16:13 Uhr ein. Um 16:49 Uhr flog ich erst raus. Kurz danach war der Server wieder „da“ und reagierte normal, als wäre nichts geschehen.
Schon die Zeiten im Log für den Shutdown sind, ähm, spannend:
Jun 15 16:15:41 seewind shutdown[10410]: shutting down for system reboot
Jun 15 16:16:00 seewind init: Switching to runlevel: 6
Jun 15 16:28:57 seewind bitlbee[8201]: SIGTERM received, cleaning up process.
Jun 15 16:30:37 seewind dovecot: dovecot: Killed with signal 15 (by pid=10475 uid=0 code=kill)
Jun 15 16:35:52 seewind ntpd[1549]: ntpd exiting on signal 15
Jun 15 16:42:51 seewind udevd[354]: worker [1921] unexpectedly returned with status 0x0100
Jun 15 16:42:51 seewind udevd[354]: worker [1921] failed while handling '/devices/virtual/net/tap0'
Jun 15 16:48:14 seewind mysqld: 130615 16:48:14 [Note] /usr/sbin/mysqld: Normal shutdown
Jun 15 16:49:00 seewind kernel: Kernel logging (proc) stopped.
Jun 15 16:49:00 seewind rsyslogd: [origin software="rsyslogd" swVersion="4.6.4" x-pid="1291" x-info="http://www.rsyslog.com"] exiting on signal 15.
Jun 15 16:49:56 seewind kernel: imklog 4.6.4, log source = /proc/kmsg started.
Zwei Minuten nach der Eingabe landete der Befehl erst im Log. Fast eine Viertelstunde später quittierte bitlbee als erster Daemon den Dienst, gefolgt im Abstand von fast zwei Minuten von dovecot. Weitere fünf Minuten brauchte der NTP-Daemon, und postfix und mysql waren erst eine weitere Viertelstunde später soweit.
Nach dem Neustart konnte ich dann endlich mal meine Mails abholen (ich lasse mir ja stündlich ein paar Ausgaben schicken, beispielsweise ein cat /proc/meminfo und den Output von uptime). Daraus ergab sich dann: Bis zur Meldung um 12:00 Uhr war alles noch in Ordnung gewesen. Die nächste Meldung kam dann schon mit 18 Minuten Verspätung, danach kam gar keine mehr. In dieser letzten, verspäteten standen dann so lustige Dinge wie:
MemTotal: 1025708 kB MemFree: 8748 kB SwapCached: 274664 kB SwapTotal: 2000052 kB SwapFree: 828440 kB
und
15:11:20 up 29 days, 12:39, 0 users, load average: 58.54, 55.00, 52.96
Kein Wunder, daß da nichts mehr ging.
Die Logs der Services wissen von keiner Überlastung. Allerdings erzählt mir das kern.log etwas, was ich nicht so richtig einordnen kann:
Jun 15 14:29:37 seewind kernel: [2548680.384020] INFO: task bdi-default:13 blocked for more than 120 seconds.
Jun 15 14:34:44 seewind kernel: [2548680.384053] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Danach kommen bdi_defaults und ein Call Trace.
Das ganze liegt zeitlich aber gut zwei Stunden nach dem Beginn der Probleme, wenn ich die Uhrzeit der verspäteten Statusmail berücksichtige, ist also definitiv nicht die Ursache, sondern wiederum nur eine Wirkung.
Dunkel erinnerte ich mich daran, daß ich so ein Problem schon einmal hatte: Vor drei Jahren beschrieb ich unter Speicherfresser ein nahezu gleichartiges Phänomen: Swap und RAM liefen voll, CPU hatte Überlast gehabt nichts ging mehr. Nach dem Wechsel auf diesen Server hier schien das Problem behoben zu sein. Und erst seit dem letzten Kernel-Update in Squeeze ist es wieder da. Ob der Grund derselbe ist, kann ich aber so nicht feststellen.
Vor allem mache ich mir unter diesen Umständen schon Gedanken darüber, ob ich das System auf diesem Server – AMD Athlon(tm) 64 Processor 3700+, 1 GB RAM – noch auf Wheezy hochziehen kann, ohne daß diese Probleme noch zunehmen. Eigentlich bin ich mit diesem Server von Hetzner nämlich zufrieden, und ein Serverumzug käme mir gerade überhaupt nicht gelegen.
Nun warte ich mal ab, wie er sich weiter verhält, und wenn das wieder passiert, werde ich mir wohl was ausdenken müssen.