pinky11
Goto Top

Apache: Server load über 100 aber warum?

Hallo zusammen,

ich habe hier einen gut besuchten Apache vor mir, der seit einigen Wochen regelmäßig den Prozessor-Load auf über 100 bringt. In der Konsequenz ist die Webseite nicht mehr erreichbar. Ein neustart des Apache beseitigt das Problem, weshalb ich als Ursache hier klar den Apache sehe. Allerdings kann ich derzeit kein Script identifizieren welches die Ursache sein könnte.

Die regelmäßig ausgeführten Scripte starten/enden nicht parallel zu den Ausfallzeiten des Apache.
Die Webseitenbesuche sind in der Menge auch nicht den Ausfallzeiten zuzuordnen, sodass man sagen könnte: Viele Besucher gleich zu viel Load.

Demnach durchforste ich also gerade die Logs und werde nicht so richtig schlau.
Es existiert derzeit ein Script welches vom Serveranbieter installiert wurde, welches den Serverload prüft und sobald dieser > 100 liegt checkt ob die Webseite ausgeliefert wird. Sobald das nicht der Fall ist wird der Apache automatisch neugestartet und eine email vesendet. Aus diesen emails kann ich die Ausfallzeiträume eingrenzen.

In der Apache error.log findet sich um den passenden Zeitraum "heute" 08:38 Uhr (ff) ->

[Mon Jun 28 08:38:48.424736 2021] [mpm_event:error] [pid 2373277:tid 140218540782784] AH10159: server is within MinSpareThreads of MaxRequestWorkers, consider raising the MaxRequestWorkers setting
[Mon Jun 28 08:40:09.503860 2021] [mpm_event:error] [pid 2373277:tid 140218540782784] AH00484: server reached MaxRequestWorkers setting, consider raising the MaxRequestWorkers setting
[Mon Jun 28 08:45:15.594025 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2373280 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:15.597791 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2373283 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:15.597810 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2374298 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:15.597829 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2375767 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:15.597842 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2376325 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:15.597852 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2376591 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:17.599700 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2373280 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:17.599748 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2373283 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:17.599759 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2374298 still did not exit, sending a SIGTERM
[Mon Jun 28 08:45:17.599768 2021] [core:warn] [pid 2373277:tid 140218540782784] AH00045: child process 2375767 still did not exit, sending a SIGTERM
...

unter der langen liste:

[Mon Jun 28 08:45:22.607535 2021] [mpm_event:notice] [pid 2373277:tid 140218540782784] AH00491: caught SIGTERM, shutting down

Und auch die Mail stammt von 08:45 Uhr.

Nun habe ich mich auf die Suche nach dem MaxRequestWorkers eintrag gemacht und in der Apache2.conf diese Zeile nicht gefunden. Auch alle anderen confs bin ich durchgegangen und etwas irritiert. Wo genau könnte dieser Eintrag zu finden sein?

Wird er mit einem Standard-Wert belegt wenn man die Zeile weglässt?

Wo könnte ggf. sonst der Fehler zu finden sein?

Hat jemand Tipps?

Gruß

Content-Key: 838133334

Url: https://administrator.de/contentid/838133334

Printed on: April 27, 2024 at 07:04 o'clock

Member: LordGurke
LordGurke Jun 28, 2021 at 07:58:28 (UTC)
Goto Top
Es gilt generell: Wenn nicht definiert, wird der Standardwert genommen und der ist meist nicht auf viele Zugriffe optimiert.

Aber: Da wirklich das System auf Anschlag zu fahren scheint (ist wirklich die CPU ausgelastet oder nur die Load-Avg?), ist es wahrscheinlicher, dass du in einem Script ein Problem hast und dieses einfach nicht endet.
Das kann sein, weil es in eine Endlosschleife rennt oder weil es wahnsinnig viel auf der Festplatte macht oder weil es auf eine Datenbank wartet.
Welches Script das ist findet man raus, wenn man, sobald diese Situation auftritt, den Apache beendet und ihn sauber stoppen lässt — auch wenn es länger dauert.
Bevor du Apache startest, wirf einen Blick ins Access-Log auf die letzten Zeilen, dort findest du dann, woran Apache zuletzt gearbeitet hat. Das muss nicht zwingend die letzte Zeile sein, aber wenn bestimmte URIs resp. Scripte besonders häufig genannt werden, hast du da deinen Punkt wo du suchen musst.
Member: HanTrio
HanTrio Jun 28, 2021 at 10:06:49 (UTC)
Goto Top
Der Wert sollte eigentlich in der mpm_event config liegen (?) also ein Apache Modul. So kenne ich es.

Such vielleicht nochmal:
grep -ir "MaxRequestWorkers" /etc/apache2/  
(oder wo auch immer dein Apache läuft)

Ich hab hier lokal bei mir auch nen Apache laufen, entspr. default Config:
/etc/apache2/mods-available/mpm_event.conf

<IfModule mpm_event_module>
        StartServers                     2
        MinSpareThreads          25
        MaxSpareThreads          75
        ThreadLimit                      64
        ThreadsPerChild          25
        MaxRequestWorkers         150
        MaxConnectionsPerChild   0
</IfModule>

Aktiviert sollte das Modul bei dir bereits sein (es wird ja im error log erwähnt).

Die o.a. Werte spielen teilweise zusammen, ggf. muss man da noch etwas rumexperimentieren ;)

Siehe hier zB:
https://httpd.apache.org/docs/2.4/mod/event.html
https://httpd.apache.org/docs/2.4/mod/worker.html
(event basiert auf worker)
-> Interessant für's Verständnis sind die "How it works"-Abschnitte.
Member: Pinky11
Pinky11 Jun 28, 2021 at 21:22:54 (UTC)
Goto Top
Tag zusammen,

korrekt, ich habe die conf in der Zwischenzeit gefunden.
Ja, es handelt sich dabei um ein Modul, die Confs liegen also innerhalb von mods-enabled.
Genaueres zu den Einstellungen, falls noch wer "erhöhen" muss ist sehr schön hier beschrieben:
https://designmeetscode.de/apache-konfigurieren-maxrequestworkers/

Wir haben also heute erhöht - mal sehen ob DIESE Log-Message dadurch jetzt verschwindet.

Das Server-Load Problem besteht jedoch weiterhin. Gerade ist die Kiste wieder auf >170 Load Avg geschossen. Alle Prozessorkerne lagen bei 100%.

HTOP zeigt jede Menge:
/usr/bin/apache2 -k start
php-fpm: pool www
/usr/sbin/varnishd

Zunächst habe ich herausgefunden welche Prozesse unter www-data alle laufen und habe die laufenden Cronjobs gekillt. Dies brachte keine Verbesserung.

Anschließend habe ich den Varnish beendet: /etc/init.d/varnish stop
Auch das brachte keine Verbesserung.

Danach habe ich auch den Apache beendet: /etc/init.d/apache2 stop
Auch das brachte zunächst keine Verbesserung. Es liefen weiterhin jede Menge php-fpm-Prozesse. Diese beendeten sich dann nach einer ganzen Weile, während ich schon dachte, dass das Beenden des Apaches nichts bewirkt habe. Offenbar sind die Prozesse aber dann zuende gelaufen und es wurden/konnten keine neuen gestartet werden.

Nun interessiert mich brennend, welche Aufgaben die Prozesse ausgeführt haben. Gibt es hier einen sinnvollen Weg herauszufinden was die Prozesse bearbeitet haben?

Die Access-Log ist leider nicht aussagekräftig. Sie steckt voller Bilder/harmloser Files, die nicht ansatzweise verdächtig aussehen.

Gibts da nen weg zu prüfen was die Prozesse tun/getan haben?

Gruß
Member: LordGurke
LordGurke Jun 28, 2021 at 21:42:30 (UTC)
Goto Top
php-fpm ist ein eigenständiger Dienst. Mit etwas Glück wurde ein Slow-Log geschrieben, in dem Protokolliert ist, welche Scripte sehr lange gebraucht haben.
Member: ASP.NET.Core
ASP.NET.Core Jun 29, 2021 updated at 07:55:17 (UTC)
Goto Top
Moin,
wieso killst du wild Prozesse statt erst mal in htop nach CPU Last sortiert zu schauen welche Prozesse den Server auslasten? Wenn das nicht so leicht zu reproduzieren ist kannst du dir auch in deinem Skript welches den Load prüft mal alle Prozesse sortiert nach CPU-Last irgendwo hin schreibe, z.B. so:

date >> /var/log/cpu-usage.log
ps -eo pid,ppid,cmd,%mem,%cpu --sort=-%cpu >> /var/log/cpu-usage.log

Natürlich vorher sicherstellen, dass der Nutzer dort schreiben darf und ggf. woanders hin schreiben. Der Apache wird das nach dem was du hier schreibst wohl eher nicht sein. Zumal du offensichtlich PHP-FPM nutzt, damit liegt die Backend-Last wahrscheinlich eh nicht bei dem Webserver, sofern da nicht noch Module für Perl, Python oder sonst was drauf laufen. Aber ohne die komplette Konfiguration zu kennen sind das alles eher Mutmaßungen statt fundierter Aussagen. Gerade beim Apache, der ja sehr vieles kann. Jedenfalls würde ich nicht die Nadel im Heuhaufen suchen sondern erst mal systematisch herausfinden woher das kommt, dann kannst du das im Detail zielgerichtet weiter analysieren und nach einer Lösung suchen.

Wenn du es auf PHP-FPM eingegrenzt hast (bin mir in denem Post nicht sicher ob du das hast, oder ob du nur "viele Prozesse" gesehen hast, was ja ohne Prüfung der Auslastung normal wäre): Was sagen dessen Logs? Evtl Loglevel erhöhen und mal den Slowlog aktivieren:

slowlog = /var/logs/php-fpm-slow.log
request_slowlog_timeout = 3s

Sollten mehrere Seiten und damit PHP-FPM Instanzen auf dem Server laufen, unbedingt den Standardpool in einen sprechenden Name ändern, damit du die identifizieren kannst. Vor allem wenns auf Docker läuft, da hast du sonst problemlos aus Sicht des Hosts 10 Prozesse die im Pool www laufen...

Btw würde ich generell auch mal über Monitoring nachdenken. Das kann nicht nur Alamieren sondern entsprechende Daten auch gleich automatisch aufzeichnen, dass du generell einen Überblick hast, was wann so auf deinem Server passiert. Ist nicht nur zur Fehlersuche nützlich.
Member: Pinky11
Pinky11 Jun 29, 2021 updated at 12:05:56 (UTC)
Goto Top
Hallo und Danke für eure Antworten!

wieso killst du wild Prozesse statt erst mal in htop nach CPU Last sortiert zu schauen welche Prozesse den Server auslasten? Wenn das nicht so leicht zu reproduzieren ist kannst du dir auch in deinem Skript welches den Load prüft mal alle Prozesse sortiert nach CPU-Last irgendwo hin schreibe, z.B. so:

Da habe ich mich vielleicht missverständlich ausgedrückt. Ich kille nicht "wild" die Prozesse, sondern bin in der Liste der Prozesse die der user www-data ausführt die cronjobs durchgegangen und habe diese beendet. Dies nur um auszuschließen dass die cronjobs ggf. weitere Prozesse starten die hier schuld an der Last sind um auf diesem Wege ausschließen zu können, dass die Scripte die hinter den cronjobs stehen Ursache des Problems sind.

htop läuft hier selbstverständlich auch dauerhaft um die Last zu prüfen und zu sehen wann das Problem auftritt. Daher lässt sich erkennen, dass die php-fpm-Prozesse die Last verursachen. Zum Zeitpunkt der "überlast" liefen mehrere (>~20) php-fpm-Prozesse mit einer Last von ~20%, die die 6 Kerne unter sich aufgeteilt haben. Soweit zu den Prozessen und meiner Vermutung, dass es die php-fpm geschichten sind, die hier zur Überlast führen. Welches Script diese auslöst, habe ich aber noch nicht herausfinden können.


Zumal du offensichtlich PHP-FPM nutzt, damit liegt die Backend-Last wahrscheinlich eh nicht bei dem Webserver,

Nein, auf dem Apache ist kein Perl o.ä. installiert.
Die Last liegt wahrscheinlich nicht beim Webserver? Wo dann? Und wer erzeugt dann die php-fpm-Prozesse wenn nicht der Webserver?
Im Test habe ich wie erwähnt gestern Nacht den Apache beendet. In der Folge sind dann auch die fpm-Prozesse langsam verschwunden. Ich gehe davon aus, dass sie ihre Arbeit abgearbeitet haben und da keine neuen dazukamen hat sich die Liste der Prozesse geleert.
Interpretiere ich das falsch?

Slowlog ist eingerichtet. Hier laufen bereits einige Scripte auf. Ich schaue im Detail mal rein sobald der Server das nächste mal in Überlast geht, was sich hier ansammelt.

Es ist nur eine Seite auf dem Server aktiv, insofern können wir mit den Logs gut arbeiten.

Zum Monitoring: Wir haben diverse Dienste und auch Monitorings aktiv. Hättest du eine Empfehlung die hier im Detail weiterhelfen kann?


Edit: Habe mal einen screen vom gestrigen gtop angefügt. So war der Zustand des Servers gestern über Minuten, bis wir die einzelnen Dienste beendet haben.
load
Member: LordGurke
LordGurke Jun 29, 2021 at 13:20:12 (UTC)
Goto Top
Wie ich bereits schrieb, ist php-fpm ein eigener Dienst, der unabhängig von anderen läuft und über einen Socket einfach angetriggert wird, die Scripte auszuführen.
Der muss auch nicht zwingend in der Identität von www-data laufen.
Member: ASP.NET.Core
ASP.NET.Core Jul 29, 2021 at 14:09:53 (UTC)
Goto Top
Zitat von @Pinky11:
Die Last liegt wahrscheinlich nicht beim Webserver? Wo dann? Und wer erzeugt dann die php-fpm-Prozesse wenn nicht der Webserver?
PHP-FPM ist ein Prozessmanager und genau dafür da: Die PHP-Prozesse aus dem Kontext des Webservers holen. Wenn du das betreust solltest du dich in das Thema einarbeiten, damit dir zumindest grundlegend klar ist, wie die Abfragen abgearbeitet werden. Dann wird auch klar, dass FPM ohne Apache nichts mehr zutun hat, weil der die weiterreicht. Als Schlussfolgerung kommen die Anfragen die PHP so auslasten über den Webserver. Das bestätigt auch dein htop Screenshot. Wobei eine so hohe Apache-Auslastung ungewöhnlich ist. Das könnte eine Endlosschleife sein.

Ich würde mir das Access-Log mal sichern und prüfen, welche Anfragen in den Minuten bevor das aufgetreten ist gesendet wurden. Bedenke, dass eine gewisse Zeit vergeht bis du es merkst (v.a. ohne Monitorring) und je nachdem welche Timeouts eingestellt sind kann es auch sein, dass die Anfragen schon etwas älter sind. mod_status aktivieren ist auch eine gute Idee (aber nur lokal für dich bzw mit IP-Beschränkung!), dann kannst du wenn das wieder auftritt die aktuell laufenden Anfragen einsehen. Da sind wahrscheinlich dann auch deine Anfragen drin, die Probleme machen.

Ansonsten mal die Anwendung genauer anschauen. Was wurde vor dem Auftreten gepusht? Hat sich irgendwas in der Konfiguration geändert? Gibt es einen 2. Admin der das eingerichtet hat und evtl. ohne sich mit dir abzustimmen am System schraubt? Wenn das Problem nicht schon immer da ist, muss sich ja irgendwas am System geändert haben, dass es auslöst.

Fürs Monitorring gibt es gute OS Tools wie Prometheus.