Blockiertes Archiv als Absturzursache?

Hallo,

heute Morgen hat mir IPS ganz plötzlich mitgeteilt, dass es neu gestartet wäre.
Ich habe dann mal recherchiert, was da los war und habe mittlerweile das Archiv in Verdacht.

Das Log bricht irgendwann einfach ab, nachdem zuvor einige Minuten die Meldungen „Zu viele gleichzeitige Skripte. Verwerfe Ausführung…“ kamen. Im Log selbst war nichts auffälliges zu sehen. Keine Fehler, keine unnormalen oder häufigen Skriptaufrufe.

Also habe ich mir mal die Prometheus-Daten angesehen und festgestellt, dass kurz nach 6 Uhr plötzlich die Fehler kontinuierlich zugenommen haben, wovon ich aber dummerweise nichts im Log sehe. Außerdem ist zu sehen, dass die Anzahl genutzter Threads ab diesem Zeitpunkt anfängt, kontinuierlich zu steigen (ca. 1 Thread pro Minute). Das ging etwa über 40 Minuten so weiter, bis alle verfügbaren Threads ausgelastet waren. Nach ca. weiteren 15 Minuten hat sich der IPS-Dienst dann sang- und klanglos verabschiedet und ist neu gestartet.

Allein das wundert mich schon etwas, weil der Dienst bei mir noch nie nach einem Absturz von alleine wieder gestartet ist. Und es ist mir auch nich ganz klar, warum der Neustart letzten Endes erfolgte. Denn CPU-Ressourcen und RAM waren trotz belegter Threads nach wie vor vorhanden.

Naja, ich habe dann mal mit den sperrlichen Informationen weiter versucht, eine Ursache ausfindig zu machen. Crash Dumps gab es keine, das Log gab auch erst mal nichts her und die Metriken zeigten zwar den schleichenden Tod, aber keine Ursache.

Dann viel mir ein, dass ich minütlich die aktiven Threads und deren Laufzeit logge und habe mir die Daten mal aus dem Log-File gezogen. Und siehe da, jede Minute kamen immer wieder dieselben Skripts hinzu, welche offensichtlich endlos liefen. Die längsten Threads hatten 42 Minuten auf dem Buckel, wovon man komischer Weise aber nichts in den Metriken sieht (max. Laufzeit 5 Minuten). Die betroffenen Skripte selbst haben noch nie Probleme gemacht und laufen so seit Jahren vor sich hin. Allerdings gibt es eine Gemeinsamkeit der Skripte: alle greifen auf das Archiv zu und lesen geloggte Variablenwerte aus.

Und nun die Frage der Fragen:
Kann es sein, dass sich das Archiv unter bestimmten Umständen verklemmt und jegliche weitere Abfragen mittels AC_GetLoggedValues() und AC_GetAggregatedValues() blockiert und damit jedes Skript zum Hängen bringt, was diese Funktionen nutzt?

Das ist wirklich die einzige schlüssige Erklärung, die mir als Ursache einfällt. Und wenn dem so sein sollte, gibt es irgendeine Möglichkeit, dem zukünftig entgegen zu wirken?

Die zweite Frage, die sich mir stellt ist, warum der Dienst dann irgendwann scheinbar abgeschmiert und neu gestartet ist. In den seltenen Fällen, wo früher mal Skripte bei mir hängen geblieben sind, war es so, dass zwar irgendwann mangels freier Threads nichts mehr lief, aber der Dienst trotzdem noch halb tot im System hing und eher den ganzen Server in Mitleidenschaft gezogen hat, statt neu zu starten.

Hier noch ein paar Metriken, wo man den heutigen Absturz schön nachvollziehen kann.


IP-Symcon 6.3, Windows (amd64), 29.11.2022, 07e763adc3e2

Sorry für die späte Rückmeldung. Je nach Einstellungen unter Windows kann der Dienst automatisch nach Absturz durch Windows neu gestartet werden. Schau mal in den Einstellung nach, was bei dir Konfiguriert wird.

Nun zu deiner Analyse: Ja, wenn überall das Archiv verwendet wurde, dann halte ich dein Vermutung über einen Deadlock für extrem Wahrscheinlich. Es wurde von deinem System auch netterweise ein Crashdump übermittelt in dem ich der Meinung bin genau diese Ursache auch zu sehen.

Zur genauen Analyse werden wir vermutlich erst im neuen Jahr kommen - ich wollte dir nur Bescheid geben, dass wir immerhin Daten für eine Analyse haben und uns drum kümmern werden.

Falls es öfters passiert gib gerne noch mal Bescheid!

paresy

Vielen Dank für deine Rückmeldung!

Stimmt, jetzt fällt es mir wieder ein. Vor ziemlich genau einem Jahr hatte ich eine längere Absturzserie, bei der ich den Dienst so umkonfiguriert habe, dass er automatisch neu startet. Da ich seitdem keine Abstürze mehr hatte, war mir das irgendwie entfallen.
Die damalige Absturzursache konnte ich bis heute nicht identifizieren. Es hing mit einigen Skripten zusammen, die UNIX-Zeitstempel verarbeiten und zyklisch ausgeführt werden. Manchmal kam es vor, dass es - meist kurz nach Mitternacht - zu einer Endlosschleife in den betroffenen Skripten kam. In seltenen Fällen passierte das auch tagsüber. Eigentlich dürfte das nicht passieren, aber ich habe damals zur Sicherheit die Schleifen so umgebaut, dass diese im Falle einer außergewöhnlich häufigen Wiederholung abgebrochen werden. Dieser Workaround kam damals ein paar Mal zum Tragen und danach war auf mysteriöse Art und Weise wieder Ruhe und die Skripte liefen, wie sie es zuvor auch jahrelang ohne Probleme getan haben.

Ja, das war die einzige Gemeinsamkeit, die ich bei den hängenden Skripten erkennen konnte. Alle anderen Skripte wurden in dem problematischen Zeitraum ganz normal ausgeführt und auch wieder beendet. Nur die Skripte mit Archivoperationen (lesend) blieben alle hängen. Meistens war es dasselbe Skript, welches immer wieder zyklisch aufgerufen wurde. Aber es waren auch andere Skripte mit Archivzugriff betroffen, die untereinander nichts miteinander zu tun haben und auch auf unterschiedliche Daten im Archiv zugreifen.

Interessant. Ich wusste gar nicht, dass automatisch Crashdumps übermittelt werden. Hängt das mit der gewählten Datenschutzeinstellung (Übermittlung anonymisierter Daten) zusammen? Auch die hatte ich vor einem Jahr mal angepasst.

Vielen Dank! Kein Stress deswegen. Bis jetzt war es das erste Mal in Zusammenhang mit dem Archiv. Da ich aber häufiger das Archiv in meinen Skripten nutze, wäre es ganz cool, wenn man das irgendwie robuster gestalten könnte, falls es aus irgendwelchen Gründen zu Problemen beim Zugriff auf das Archiv kommt.

Viele Grüße
Slummi