[gelöst] FHEM-Hauptprozess wächst linear ~200 MB/h, Ursache trotz Diagnose nicht ge

[bmwfan]

@Beta-User,

Danke für den Hinweis. Aktuell läuft noch ein 24h-Test, der aber sehr gut aussieht. Fast kein Speicherwachstum mehr. Sobald der abgeschlossen ist, stelle ich eine Zusammenfassung herein und werde Deinen Vorschlag, einen Thread in fhem.pl zu eröffnen (nur Problem und dann die Lösung), aufnehmen. Der Fehler war wirklich nur äußerst aufwendig und mit den Hinweisen aus dem Forum zu entdecken, wurde aber meines Wissens nach (zumindest haben weder die KI noch ich etwas dazu gefunden) bisher noch nicht beschrieben. Ich kann mir durchaus vorstellen, dass daraus tatsächlich Änderungen im Code (aber wo, da nicht nur freezemon beteiligt ist) notwendig sind und dass es den einen oder anderen Nutzer auch interessiert oder sogar betrifft.

Das neue Modul von DS_Starter habe ich schon mitgeteilt bekommen, werde es aber erst nach dem Test (keine Änderung im laufenden Test!) einspielen.

Den genannten Hauptthread habe ich in der Tat vorher nicht gesehen. Bin mit Unterstützung (für die ganzen Befehle) einer KI so vorgegangen, wie ich zu Beginn meiner Berufslaufbahn eigene Programmierfehler gesucht habe.

[bmwfan]

Hallo zusammen,

die Ursache ist gefunden, und danke an alle, die Hinweise gegeben haben (bertl, MadMax, DS_Starter, Beta-User und weitere)

Kurzfassung
Das Modul Freezemon ersetzt Log3 und legt jeden Aufruf in einer Liste ab, die bei deaktiviertem Gerät nie geleert wird. Bei mir war das Gerät disable 1 mit gesetztem fm_logFile. In der fhem.cfg steht disable alphabetisch vor fm_logFile: Beim Einlesen räumt disable 1 zuerst auf (noch ist nichts gewickelt), danach installiert fm_logFile den Ersatz, und niemand räumt mehr auf. Ergebnis: ca. 100 Datensätze je Sekunde, ca. 200 MB/h, bis zum Neustart.

Da ich mir darunter nichts vorstellen konnte, habe ich die KI um eine Analogie gebeten. Die habe ich dann verstanden 
Stell dir eine Poststelle vor. Freezemon stellt einen Kopierer neben den Briefkasten, der von jedem Brief eine Kopie in eine Kiste legt (Wickeln). Ein Mitarbeiter leert die Kiste jede Sekunde (der Timer). Beim normalen Betrieb bleibt die Kiste klein.
Bei dir kam es so:
Zuerst die Anweisung "Kopierer entfernen" (disable 1). Es steht aber noch keiner da, also passiert nichts. Der Mitarbeiter wird gar nicht erst eingestellt (kein Timer, weil das Gerät deaktiviert ist).
Danach die Anweisung "Kopierer aufstellen" (fm_logFile). Der steht jetzt da und kopiert alles aber niemand leert die Kiste und niemand entfernt den Kopierer, denn die Anweisung "entfernen" kommt nur einmal, und zwar schon vorher.

Behoben mit deleteattr <name> fm_logFile, save, Neustart. Danach 0,55 bis 1,7 MB/h (Stand [WERT: Datum, Uhrzeit, RSS und Zuwachs seit Start]; 04.10. 02:01 bis 09:01: 334,9 → 338,8 MB).

Wie es sich zeigte (Zeitlinie aus Minutenwerten)
- bis 09.09. 18:10: 13-18 MB/h
- ab Neustart 09.09. 18:10: ca. 205 MB/h
- 14.09. 21:53 bis 22.09. 09:38: 15-28 MB/h (Freezemon war vermutlich kurz aktiv und wurde dann zur Laufzeit deaktiviert, was den Ersatz entfernt; Schlussfolgerung aus dem Freeze-Log)
- ab Neustart 22.09. 09:40: ca. 190-207 MB/h bis 03.10.
Die Konfiguration war in allen Sicherungen ab 07.09. gleich. Nicht bestätigt: was am 09.09. gegen 18:00 den Zustand des Prozesses geändert hat.

Was es nicht war (jeweils gemessen)
- Image/Perl-Version, einzelne Module (DOIF-Gruppen, SolarForecast, FritzSmart, Shelly-Abfragen), Start ganz ohne Fritz-Gerät: keine oder kaum Wirkung. Sie waren nur Quellen vieler Log3-Aufrufe.
- Allokator: MALLOC_TRIM_THRESHOLD_, malloc_trim(0) (RSS 3817,8 → 3817,9 MB) und malloc_stats() (Arena zu 99,98 % belegt) zeigen: kein zurückgehaltener Speicher, sondern belegter.

Prüfen, ob man betroffen ist

Code Auswählen Erweitern

{ join(", ", map { "$_ disable=".AttrVal($_,"disable",0)." fm_logFile=".AttrVal($_,"fm_logFile","-") } devspec2array("TYPE=freezemon")) }Ein Freezemon mit disable=1 und gesetztem fm_logFile ist die Konstellation. Allgemein zeigt { require B;; my $cv=B::svref_2object(\&Log3);; $cv->FILE } (und entsprechend für CallFn, AnalyzeCommand, HttpUtils_NonblockingGet), ob eine Kernfunktion ersetzt wurde (Original: fhem.pl).

Nebenbefunde, die anderen helfen können
- Docker: docker restart ohne Zeitlimit wartet nur 10 Sekunden. FHEM wartet selbst bis 10 Sekunden (Server shutdown delayed ... max 10 sec), HMCCU weitere 8: FHEM wurde bei mir mitten im Herunterfahren beendet, fhem.save wurde nicht geschrieben, Zustände gingen verloren (Teile der Hausautomatisierung waren verstellt). Abhilfe: docker restart -t 60 bzw. stop_grace_period: 60s in der Compose-Datei.
- FFI::Platypus im fhem-docker-Image: Das Image nutzt /usr/local/bin/perl. Die apt-Anleitung für das System-Perl passt dort vermutlich nicht (Nicht bestätigt, nicht probiert). Bei mir ging es mit nachinstalliertem Compiler und cpanm -L /usr/src/app/3rdparty FFI::Platypus (die README des Images empfiehlt CPAN statt apt).
- Warnung: Ein Skript, das alle Hashes und Arrays über Devel::Gladiator::walk_arena durchlief, und Devel::Size haben bei mir FHEM abstürzen lassen (Segfault in libperl.so bzw. Size.so). Die reine Zählung von Typen und Zeichenketten lief mehrfach ohne Absturz, hält aber Speicher dauerhaft belegt.

Noch offen: Rückmeldung des Freezemon-Maintainers, den ich in einem neuen Thread detaillierter informiert habe. Ich habe den Fehler natürlich nur auf meinem System gesehen.

Gruß Jürgen

P.S.: Wie kann ich den Thread im Betreff als gelöst benennen?

[Wzut]

P.S.: Wie kann ich den Thread im Betreff als gelöst benennen?

in deinem ersten Post das Topic editieren

[bmwfan]

@Wzut:
Das wollte ich, finde aber keinen Button o.ä. dafür und ein Doppelklick auf die Betreffzeile geht auch nicht. Ich habe Buttons für Drucken, Ungelesen markieren, e-mail, aber nichts zum editieren.

Habs gefunden. Muss den ersten Post bearbeiten, dann komme ich an den Betreff