Diese Woche gab es auf einem Server das Phänomen, dass die LOAD bei über 2500% (ca. 150 bei 6 CPUs), aber die CPU Auslastung lag nur bei etwa 5%, was also darauf hindeutete, dass due CPU-Last nicht nicht der Grund für die hohe LOAD sein konnte:
top - 15:53:42 up 7 days, 10:01, 2 users, load average: 159,47, 149,89, 160,80
Tasks: 540 total, 1 running, 468 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2,0 us, 2,0 sy, 0,0 ni, 0,0 id, 95,6 wa, 0,0 hi, 0,4 si, 0,0 st
KiB Mem : 12296516 total, 607940 free, 9710388 used, 1978188 buff/cache
KiB Swap: 12578812 total, 7439140 free, 5139672 used. 1752884 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
5564 user@xyz 20 0 99712 36384 5308 D 4,6 0,3 0:00.22 spamassassin
1539 root 20 0 2394080 55984 7412 S 2,0 0,5 1365:51 fail2ban-server
4561 root 20 0 33784 6168 3700 S 1,3 0,1 0:02.39 htop
8 root 20 0 0 0 0 I 0,7 0,0 11:17.44 rcu_sched
...
Festplattenzugriffe als mögliche Ursache
Neben einer hohen CPU-Auslastung kann auch eine hohe IO-Last, als viele lesende oder schreibende Zugriffe auf die Festplatte zu einer hohen LOAD führen.
Analysetools
Es gibt eine ganz Menge an Tools, mit denen man die IO analysieren kann. Neben vmstat, pmstat und iostat gibt es das Tool iotop, welches sehr ähnlich zu top bzw. htop funktioniert. Die Ausgabe sieht in etwa wie folgt aus:
Total DISK READ : 3.25 M/s | Total DISK WRITE : 97.42 K/s
Actual DISK READ: 3.35 M/s | Actual DISK WRITE: 151.97 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
14457 be/4 example- 1067.69 K/s 0.00 B/s 0.00 % 78.58 % php-fpm: pool 160096117520684
958 be/4 example- 2.20 M/s 0.00 B/s 0.00 % 71.42 % php-fpm: pool 160096117520684
19990 be/4 mysql 3.90 K/s 3.90 K/s 0.00 % 0.50 % mysqld --daemonize --pid-file=/run/mysqld/mysqld.pid
...
Man kann hier mit den Cursortasten die Spalte wählen, nach der sortiert werden soll (hier ist aktuell die Spalte IO ausgewählt, markiert durch das > am Ende).
Auch diese Ansicht zeigte keinen einzelnen Prozesse, die ungewöhnlich hohe Zugriffsraten hatten. Es fiel aber auf, dass sehr viele php-fpm Prozesse dabei waren.
Auffinden von blockierten Prozessen
Der Grund für die sehr hohe LOAD waren Prozesse, die darauf warteten ausgeführt zu werden. Möchten solche Prozesse auf die Disk zugreifen, können dies aber gerade nicht, dann fallen sie in den „uninterruptible sleep“. Solche Prozesse kann man mit dem ps Befehl finden:
$ ps -ax | grep D
PID TTY STAT TIME COMMAND
6292 ? D 1:26 php-fpm: pool 151673661024723
8746 pts/0 S+ 0:00 grep --color=auto D
22261 ? D 0:03 php-fpm: pool 160096117520684
24583 ? D 0:03 php-fpm: pool 16104533493131
24886 ? D 0:02 php-fpm: pool 160096117520684
24894 ? D 0:02 php-fpm: pool 160096117520684
24896 ? D 0:02 php-fpm: pool 160096117520684
25048 ? D 0:02 php-fpm: pool 160096117520684
25050 ? D 0:01 php-fpm: pool 160096117520684
25052 ? D 0:01 php-fpm: pool 160096117520684
26265 ? D 0:01 php-fpm: pool 16104533493131
26315 ? D 0:01 php-fpm: pool 16104533493131
27967 ? D 0:01 php-fpm: pool 16104533493131
28711 ? D 0:01 php-fpm: pool 16104533493131
28966 ? D 0:01 php-fpm: pool 16104533493131
29202 ? D 0:01 php-fpm: pool 160096117520684
...
Diese einfache Suche zeigte (neben ein paar falschen Suchtreffern) sehr viele php-fpm Prozesse an, die aktuell in diesem Zustand waren.
Lösung: Prozesse neustarten
Die Lösung war eigentlich recht einfach. Durch einen Neustart der verschiedenen php-fpm Services (auf dem Server sind mehrere PHP-Versionen installiert) konnten die blockierten Prozesse abgebrochen werden. Die LOAD war im Anschluss bei etwa 0,5 und der Server somit nicht mehr stark ausgelastet.
Fazit
Wenn ein Server eine hohe LOAD hat, dann ist der Grund nicht immer eine hohe CPU-Auslastung. Auch viele Festplattenzugriffe oder aber blockierte Prozesse können zu einer hohen Last führen. Mit den richtigen Tools an der Hand lassen sich solche Fehler aber auch finden und beheben.