[Gelöst] Memory Leak ?

sweetie-pie · 18 Februar 2025, 11:51:45

Hallo,

ich betreibe fhem seit Anfang an, genauer gesagt schon seit fhz1000-Zeiten.

In der Folge habe ich mittlerweile eine mächtige Installation mit derzeit 1391 entities, davon einiges als Selbstbauten.
Das fhem läuft auf einer Synology als VM mit einem Debian GNU/Linux 11 (bullseye) als Gastsystem (mit 4GB Ram und 2 CPUs).

Bisher ohne Problem, außer das die Installtion über die Jahre etwas "träger" geworden ist.
Das war für mich aber okay. Die CPU Auslastung in der VM lag immer zwischen 70-95%, mal auch drüber.

Updates spiele ich mehr oder weniger regelmäßig ein, das ganze System inkl. Komponeten steht recht isoliert in einem IoT-Netz mit eigenem WLAN.

Seit ein paar Tagen habe ich das Problem, dass fhem regelmäßig jede 1:00 h bis 1:10 h vom OOM-Killer abgeschossen wird, weil der Speicherverbrauch von fhem bei fast 4GB liegt. Nach dem Neustart liegen wir bei ~200 MB. Ich habe davon zunächst nix mitkommen, da fhem sich ja wieder neu startet. Komisches Verhalten (z.B. Tag/Nacht) von Automatisationen haben mich erst aufmerksam werden lassen.

Was sich bisher schon gemacht habe.

Ich habe die offenen Files angeschaut. Ja das sind viele, aber in meinen Augen stabil:
Beim Start:

Code Auswählen

# lsof -p 18651 | grep LISTEN | wc -l
7
# lsof -p 18651 | grep ESTABLISHED | wc -l
31
# lsof -p 18651 | grep log | wc -l
168
# lsof -p 18651 | egrep -v ".*(log|ESTABLISHED|LISTEN).*" | wc -l
70

Nach ~1 Stunde:

Code Auswählen

# lsof -p 16825 | grep LISTEN | wc -l
7
# lsof -p 16825 | grep ESTABLISHED | wc -l
32
# lsof -p 16825 | grep log | wc -l
168
# lsof -p 16825 | egrep -v ".*(log|ESTABLISHED|LISTEN).*" | wc -l
69

Ich habe mit Apptime und freezemon mein Glück probiert, ab auch nix gefunden.
Klar es gibt Module mit hoher Last, das sagt aber ja nix zum Speicherverbrauch aus.

Das Doofe ist, ich habe keine echte Idee wo ich noch gucken oder wie ich mich dem Problem weiter nähere.
Ich kann für mich auch keine substanzielle Änderung ausmachen, die ich dem Problem zuordnen könnte.

Mittlerweile habe ich auch schon an einigen Stellen rumgedreht und etwas Housekeeping betrieben, aber nix davon hat das Verhalten nachhaltig verändert.
Das Wachstum des Speicherverbrauchs ist ja auch rasant.

Ich denke gerade darüber nach, ob es evtl. Sinn macht, den internen MQTT-Server gegen einen externen zu tauschen.
Ich habe das Gefühl, dass dieser evtl. Teil des Problems sein könnte. Habe derzeit ca. ~40 Tasmota-Devices plus evcc und einen Victron WR. Gerade wenn evcc und Victron Updates bekommen, könnte sich das ja auf das MQTT-Messageverhalten auswirken. Deshalb der Gedanke ob ein seperater MQTT-Server hier evtl. sinnvoller ist. Aber so ist es halt bei historisch gewachsenen Systemen...

Wenn ich in die Logfiles schaue besteht das Problem ungefähr seit dem 13.02. in den Vormittagsstunden.
Ein Update von fhem im unmittelbaren Zusammenhang kann ich nicht sehen.
Das restoredir trägt andere Zeitstempel:

Code Auswählen

drwxr-xr-x  7 fhem dialout 4096 16. Jan 20:41 2025-01-16
drwxr-xr-x  5 fhem dialout 4096  2. Feb 18:50 2025-02-02
drwxr-xr-x  6 fhem dialout 4096 16. Feb 09:44 2025-02-16
drwxr-xr-x  4 fhem dialout 4096 17. Feb 23:35 2025-02-17

Hatte anfangs auch schon mal DNS-Requests probiert mit den Absturzzeiten probiert zu korrelieren, aber das war wohl ein Irrlicht. Der Speicherverbrauch wächst im Turbotempo und ich habe keine Ahnung warum.

Hat wer noch eine hilfreiche Idee, in welche Richtung ich gucken/denken sollte?

Danke & Gruß
sweetie-pie

passibe · 18 Februar 2025, 12:24:52

Ist das wirklich plötzlich bzw. klar definierbar ab dem 13.02 aufgetreten?
Wenn ja: Hast du ein Backup von FHEM von vor dem 13.02, das du mal mit der aktuellen Version vergleichen kannst? Evtl. das Backup entpacken, in dem Ordner ein git repo initialisieren, dann die aktuelle Version drüberkopieren und dann mit git diff schauen, was sich alles geändert hat.

Ansonsten bleibt ja nur, dass irgendeines der Devices, die Daten an FHEM senden, um den 13.02 herum irgendein Update gemacht/bekommen hat, das etwas beeinflusst. Dann bleibt vielleicht nur kluges/systematisches Deaktivieren von Devices, bis der Übeltäter gefunden ist.

rudolfkoenig · 18 Februar 2025, 13:00:33

Die einzige verlaessliche Methode zur Lokalisierung ist mAn. einzelne Module zu deaktivieren.

Nach der Beschreibung waechst FHEM mit ca 10MB pro Minute, damit muss man nicht lange warten, bis man den Unterschied sieht.

frank · 18 Februar 2025, 13:14:35

Zitat von: sweetie-pie am 18 Februar 2025, 11:51:45Das fhem läuft auf einer Synology als VM mit einem Debian GNU/Linux 11 (bullseye) als Gastsystem (mit 4GB Ram und 2 CPUs).

gab es hier updates?

sweetie-pie · 18 Februar 2025, 16:02:04

Zitat von: rudolfkoenig am 18 Februar 2025, 13:00:33Die einzige verlaessliche Methode zur Lokalisierung ist mAn. einzelne Module zu deaktivieren.

Ja, da habe ich auch schon getan und ich stelle fest, wenn ich z.B. den MQTT-Client vom Victron disconnecte oder evcc vom MQTT2-Server trenne, dass dann der Speicherverbrauch deutlich langsamer wird, aber eben nicht aufhört. Es hat also IMHO irgendwie was mit der Eventverarbeitung zu tun!?

sweetie-pie · 18 Februar 2025, 16:11:34

Zitat von: frank am 18 Februar 2025, 13:14:35gab es hier updates?

Du meinst beim Gast oder beim Host?

Ich habe gerade mal in /var/log/apt/history.log beim Gast geguckt:
Nichts was ich in unmittelbaren, zeitlichen Zusammenhang bringen würde.

Code Auswählen

Start-Date: 2025-02-01  13:43:55
Commandline: apt-get dist-upgrade
Requested-By: root (1000)
Upgrade: git:amd64 (1:2.30.2-1+deb11u3, 1:2.30.2-1+deb11u4), busybox:amd64 (1:1.30.1-6+b3, 1:1.30.1-6+deb11u1), ucf:amd64 (3.0043, 3.0043+deb11u2), evcc:amd64 (0.132.1, 0.133.0), libtiff5:amd64 (4.2.0-1+deb11u5, 4.2.0-1+deb11u6), rsync:amd64 (3.2.3-4+deb11u1, 3.2.3-4+deb11u3), git-man:amd64 (1:2.30.2-1+deb11u3, 1:2.30.2-1+deb11u4)
End-Date: 2025-02-01  13:45:01

Start-Date: 2025-02-01  17:25:14
Commandline: apt-get install sysstat

Bei der Synology hab ich bewusst auch nix gemacht.
Wäre denn denkbar, dass das Problem auf dem VM-Host liegt? Halte ich für wenig wahrscheinlich.
Es laufen noch weitere Gast-Maschinen, eigentlich ohne merkbare Probleme.

sweetie-pie · 18 Februar 2025, 16:23:01

Zitat von: passibe am 18 Februar 2025, 12:24:52Wenn ja: Hast du ein Backup von FHEM von vor dem 13.02, das du mal mit der aktuellen Version vergleichen kannst?

Ja, ich habe VM-Snapshots. Leider komme ich da mWn nicht direkt an das Filesystem.
Aber ich könnte nochmal was von Anfang Februar in eine eigene VM deployen und dort testen.

Vielleicht nochmal ein Ansatz...

Selbst mir Diff könnte das ein schwieriges Unterfangen werden:

Code Auswählen

# cat fhem.cfg | wc -l
11255

$:-\$

passibe · 18 Februar 2025, 16:34:54

Zitat von: sweetie-pie am 18 Februar 2025, 16:23:01Selbst mir Diff könnte das ein schwieriges Unterfangen werden:

Ja gut äh ...

Aber: Du wirst ja nicht innerhalb von ein paar Wochen so viele der 11k Zeilen geändert haben. Vielleicht kommt da schon etwas Brauchbares rum. Kann nur nochmal wärmstens die Methode mit git empfehlen (oder jedenfalls ein anderes Tool als diff, ich finde das nämlich, gerade bei längeren Dateien, schrecklich unübersichtlich).

sweetie-pie · 18 Februar 2025, 21:40:48

Also, ich habe einen alten VM-Snapshot mal als neue Maschine deployed.
Die zeigt mit einer Konfig von vor zwei Wochen heute gleiches Verhalten.
Also muss es irgendwie mit Veränderungen von außen zu tun haben.

Dann habe ich nach und nach Geräte gelöscht.
Mit sinkender Anzahl Events hat sich auch der Speicherverbrauch verlangsamt.
Ich habe nachher schon wild mit delete TYPE= DOIF, notifys, sogar FileLogs gelöscht.
Ohne echten Erfolg.

F: Mir ist auch nicht klar ob löschen überhaupt reicht, oder es noch einen Neustart braucht, damit alles "entladen" wird?

Ich habe mir dann einen unkonventionellen Weg überlegt:

Zuerst habe ich mir ein Speicherabbild des Prozess gezogen (sofort nach Neustart und nochmal nach +15 Min).

Code Auswählen

sudo gcore -o /tmp/fhem.neustart 1402
sudo gcore -o /tmp/fhem.plus15m 1402

ls -lah /tmp/
-rw-r--r--  1 root root 239M 18. Feb 20:27 fhem.neustart.1402
-rw-r--r--  1 root root 1,2G 18. Feb 20:41 fhem.plus15m.1402

Dann habe ich strings den lesbaren Inhalt extrahiert.

Code Auswählen

strings /tmp/fhem.neustart.1402 > fhem.neustart.1402.txt
strings /tmp/fhem.plus15m.1402 > fhem.plus15m.1402.txt

Und einfach mal drin rum geblättert. Das ist mir beim durchscrollen u.a. "[Victron moving average]" aufgefallen.
Ich bilde bei meinem Wechselrichter zum Glätten der Werte einen gleitenden Durchschnitt.

Da finde ich dann haufenweise sowas in der Textdatei:

Code Auswählen

[Victron moving average] Value = -144 Time = 2025-02-18 20:34:06
ed__kWQ
[Victron moving average] Value = -144 Time = 2025-02-18 20:34:06
[Victron moving average] Value = 20.1 Time = 2025-02-18 20:34:06
Minimu1
[Victron moving average] Value = 18.0 Time = 2025-02-18 20:34:07
inimum1
[Victron moving average] Value = 20.1 Time = 2025-02-18 20:34:06
19/batQ
[Victron moving average] Value = 18.0 Time = 2025-02-18 20:34:07
[Victron moving average] Value = 18.0 Time = 2025-02-18 20:34:07
venus
[Victron moving average] Value = 20.1 Time = 2025-02-18 20:34:06
19/batQ
[Victron moving average] Value = 16.7 Time = 2025-02-18 20:34:07
inimum1
[Victron moving average] Value = 18.0 Time = 2025-02-18 20:34:07
venus
/Dc/0/Current:
[Victron moving average] Value = -134 Time = 2025-02-18 20:34:04
[Victron moving average] Value = -144 Time = 2025-02-18 20:34:06
[Victron moving average] Value = -144 Time = 2025-02-18 20:34:06

Das habe ich nochmal die Vorkommen verglichen:

Code Auswählen

cat fhem.plus15m.1402.txt | grep "moving average" | wc -l
1605932
cat fhem.neustart.1402.txt | grep "moving average" | wc -l
37432

Ich habe jetzt die Mittelwertbildung entfernt und fhem nochmal gestartet.
Gefühlt läuft er Speicher jetzt langsamer hoch. Habe ich habe noch weiter WRs und Zähler wo ich Mittelwerte bilde.
Ich werde das mal beobachten, für heute ist Schluss.

Ideen und Kommentare nehme ich gerne entgegen.
Gerne auch andere Verdächtige nach denen ich in meiner String-MemDump Datei mal grepen soll

Aber das Thema mit dem git diff werde ich auf jeden fall auch noch mal angehen.

Aber sich von beiden Seiten zu nähern finde ich auch gut, quasi Top-Down, Bottom-Up, Middle Out ...

Danke & Gruß
sweetie-pie

sweetie-pie · 01 März 2025, 10:07:04

So, 10 Tage später ein Update:

Ich habe mit der zuvor beschrieben Methode nur bedingt einen nachhaltigen Erfolg erzielt.

Damit war es mir immerhin möglich, interne Funktionen die sehr häufig aufgerufen werden (z.B. moving average), Notifys und zu breit angelegte User Readings zu identifizieren. Hier konnte ich gut entschlacken, was wieder zu einem sehr responsiven System geführt hat, das Sterben auf OOM-Raten aber nur verlängert hat. Genauso wie das Verändern der OOM-Parameter

Jetzt bin ich mittlerweile bei 7,0 bis 7,5 h für den Neustart angekommen.

Außerdem habe ich vom internen MQTT2_Server plus zwei MQTT2_Clients auf mosquitto geschwenkt und aggregiere dort alle MQTT-Nachrichten. Von da gehts dann per localhost zu fhem mit MQTT2_CLient. Und PRESENCE habe ich gegen PRESENCE2 getauscht. Sowie ein paar redundante oder unnötige Modbus-Anbindungen (teils hatte ich die Daten schon per HTTP oder Echtzeit war nicht wirklich nötig).

Auch die fhem.cfg habe ich mit einer alten Version und diff probiert zu vergleichen. Ich konnte keinen wesentlichen Änderungen identifizieren. Zusätzlich habe ich nochmal die alten fhem-2025-0?.log durchgegrepped. Ich hatte am bereits mal am 03.02.2025 haufenweise Neustarts und dann wie beschrieben ab dem 13.02.2025. Ich kriege einfach keine Änderungen von mir damit korreliert.

Auch hatte ich schon mal einen Klon der aktuellen VM erzeugt und dann nach und nach (hauptsächlich I/O-) Devices rausgelöscht. Auch das hat mich nicht auf die Spur der Verursacher gebracht.

F: Wobei mir auch nicht klar ist, ob ich nach dem Löschen eines Devices ggf. einen Neustart machen muss, damit es richtig entladen wird?

Ich bin relativ ratlos, nach fast 15 Jahren fhem-Nutzung bin ich jetzt an einem Punkt angekommen, wo ich nicht mehr weiter komme.

Gibt es nicht eine Möglichkeit strukturiert dem Speicherverbrauch einzelner Module irgendwie auf die Schliche zu kommen?

Achso: fhemdebug enable führt bei mir zu 100% Last und lässt das System crashen.

sweetie-pie · 05 März 2025, 08:59:51

Update: Es läuft wieder.

Bei allen Kreuztauschen zwischen Betriebssystem, Programmversionen und Konfig-Dateien habe ich ein File außer acht gelassen: Das State-File.

In meiner recht umfangreichen Konfig hat das Statefile mittlerweile > 10k Zeilen.
Ein Diff war auf Grund der enthaltenen, sich permanent ändernden Werte und den Zeitstempeln nicht sinnvoll möglich.

Ich habe am Ende das Statefile jetzt komplett gekickt und von fhem neu anlegen lassen.
Im Anschluss dann an Geräten alles soweit durchgeklickt das aktuelle Werte kommen und den Rest der noch relevant war manuell aus dem alten Statefile herauskopiert und per "setstate" in der aktuellen Umgebung gesetzt.

Jetzt läuft das System wieder stabil mit ~ 400 MB Speicherverbrauch nach 2 Tagen.

@rudolfkoenig: Ist fhem.save für dich irgendwie interessant? Ich könnte mir vorstellen, dass beim Einlesen des Statefiles evtl. an der Validierung der Werte noch was optimiert werden kann.

Gruß und danke fürs mitlesen.
sweetie-pie

rudolfkoenig · 05 März 2025, 09:32:05

Diese Datei wird beim FHEM Start eingelesen, um die Readings zu setzen.
Wenn ein Modul bei bestimmten Reading-Werten kontinuerlich Speicher verliert, dann wuerde es das hier erwaehnte Problem erklaeren.
Ich kann die Datei gerne ueberfliegen, erwarte aber nicht, dass ich die eigentliche Ursache erkenne.