Wie Lastspitze in Vergangenheit analysieren?

[dev]

Hallo,

heute morgen ist durch monit eine Kette von Ereignissen in Gang gesetzt worden, die zur Nichterreichbarkeit des lokalen mysqld geführt haben:

Last hoch > lokaler Mail- und MySQL-Server nicht erreichbar > Restart durch monit vom mysqld

Beim Restart von mysql hat sich irgendwas verheddert, der war zwar von monit erreichbar, aber von keinem PHP-Skript mehr.

Hier das Log:

Apr 15 06:30:58 host monit[15861]: 'my.host.net' loadavg(1min) of 5.6 matches resource limit [loadavg(1min)>4.0]
Apr 15 06:30:58 host monit[15861]: Cannot open a connection to the mailserver 'localhost:25' -- Transport endpoint is not connected
Apr 15 06:30:58 host monit[15861]: No mail servers are available
Apr 15 06:30:58 host monit[15861]: Aborting event
Apr 15 06:30:58 host monit[15861]: 'mysqld' failed, cannot open a connection to INET[127.0.0.1:3306] via TCP
Apr 15 06:30:58 host monit[15861]: Cannot open a connection to the mailserver 'localhost:25' -- Transport endpoint is not connected
Apr 15 06:30:58 host monit[15861]: No mail servers are available
Apr 15 06:30:58 host monit[15861]: Aborting event
Apr 15 06:30:58 host monit[15861]: 'mysqld' trying to restart
Apr 15 06:30:58 host monit[15861]: 'mysqld' stop: /etc/init.d/mysqld
Apr 15 06:31:01 host monit[15861]: 'mysqld' start: /etc/init.d/mysqld
Apr 15 06:35:02 host monit[15861]: 'my.host.net' 'my.host.net' loadavg(1min) check succeeded [current loadavg(1min)=0.1]
Apr 15 06:35:02 host monit[15861]: 'mysqld' connection succeeded to INET[127.0.0.1:3306] via TCP

Anbei auch ein Munin-Bild vom Peak (angehängt).

Um ca. 6:25 hat also das System einen Prozess gestartet, der die Last so nach oben getrieben hat, dass postfix und mysql nicht erreichbar waren (wobei ich 5.6 noch nicht so wild finde).

Um 6:25 laufen meine cron.daily, aber das tun sie jeden Tag seit Monaten problemlos:

[root@host /]# ls -ls /etc/cron.daily/
total 24
4 -rwxr-xr-x 1 root root 133 Jan 9 2007 00webalizer
0 lrwxrwxrwx 1 root root 39 Feb 12 14:18 0logwatch -> /usr/share/logwatch/scripts/logwatch.pl
4 -rwxr-xr-x 1 root root 180 Nov 5 15:31 logrotate
4 -rw-r--r-- 1 root root 418 Jan 6 2007 makewhatis.cron
4 -rw-r--r-- 1 root root 137 Sep 3 2009 mlocate.cron
4 -rwxr-xr-x 1 root root 296 Sep 8 2010 rpm
4 -rw-r--r-- 1 root root 328 Feb 26 2009 tmpwatch

Nun meine Frage: Wie kann ich im Nachhinein herausfinden, welcher Prozess ursächlich war? Das Apache-Log sieht unauffällig aus um die Zeit, da war nicht viel los, zumal dann auch die User- statt System-Last gestiegen wäre.


System: Centos 5.5 im OpenVZ-Container

 

[Lord Gurke]

Vielleicht hast du Glück und atop auf diesem System installiert.
Dann kannst du mit
atop -r /var/log/atop.log
im Taskmanager vor- und zurückspulen und nachsehen, welcher Prozess da die CPU belastet oder viel Disk-IO verursacht hat.

 

[dev]

Nein, habe ich noch nicht, nur systat.

Kann man atop auf einer Produktivmaschine mitlaufen lassen oder ist das wegen der anfallenden Datenmenge nicht ratsam?

 

[Ben.]

Hast du mal versucht das Phänomen nachzustellen?

 

[dev]

Ja, habe die Cronjobs mal einzeln durchgeschickt, aber da hat sich nichts besonderes getan. Sie laufen ja auch sonst täglich problemlos.

Logwatch (Perl) erzeugt ein wenig CPU-Last (100% auf einem Kern), Wait IO ist ok.

Es ist aber nicht ganz einfach nachzuvollziehen, da ja Logrotate ebenfalls im selben Zyklus läuft und sich danach die Ausgangsbedingungen ja ändern.

Die heute früh rotierten Logdateien sind aber nicht besonders gross, alle unter 100 kb.

 

[Lord Gurke]

Was mir mal gerade auffällt: Es ist ein Freitag, das ist normalerweise der "ich synchronisiere jetzt die Software-RAIDs"-Tag unter Debian. Vielleicht hat diesmal der Dienst wirklich Inkonsistenzen gefunden und richtig losgelegt.