Hilfe, mein perl fhem Prozess auf dem Rpi ist dauerhaft auf >90%

TimoD · 02 Oktober 2021, 09:27:39

Hallo liebes Forum,

ich dachte erst es liegt an der SONOS Integration. weswegen ich versucht hatte dort Hilfe zu finden. Wie es aber nun aus sieht, liegt es an meinem FHEM selbst. (Habe SONOS komplett gelöscht, Problem bleibt.)

Welches Problem habe ich:

Mein Rase Pi 3 hat wenn ich über SSH Top aufrufe immer >80% CPU last. Zusätzlich ist FHEM / FTUI sehr langsam, bei der Bedienung.

Gefühlt wurde ich sagen, habe ich das Problem, seit ich ein update all ausgeführt habe (FHEM läuft seit ca. 3 Jahren auf dem PRI)

Zum deuchen habe ich nun folgenden versucht:

1. Alle möglichen Module deaktiviert / gelöscht -> bis dahin, das im Event Log kaum noch aufrufe da waren. Leider ohne Erfolg CPU Last weiterhin >80% / meist 99%
2. Debug über verbose 5, viel Aufrufe aber ich sehe keine Auffälligkeiten
3. Debug über strace

Leider fehlen mir die Fähigkeiten / Kenntnisse hier weiter zu kommen. Auch über google konnte ich leider nichts finden.

Meine Vermutung, woran es liegt:

- Es könnte sein, dass ich ein Problem mit der localtime hat und es irgendwie mit ntp zusammenhängt (Allerdings verschwindet der Fehler auch nicht, wenn ich FHEM zur Laufzeit über SSH Neustarte, womit die Fehlerbehebung aus anderen Threads bzgl. Verzögerung bei Neustarten weg fällt. Außerdem starten ich nicht über init.d, dass ich auch nicht weiß, wie ich die Verzögerung bei einem Service ausführen müsste)

Also stehe ich wie der Ochs vorm Berg,... ich hoffe ihr könnt mir helfen, ich würde nur sehr ungern, das Teil neu aufsetzen, da ich sehr viele EnOcean Geräte habe

Im Anhang die folgenden Dateien:

1. Log mit Verbose 5 (Pi läuft sonst in Verbose 1)
2. Auszug aus strace
3. Log mit verbose 1 von heute

Viele liebe Grüße

Timo

Otto123 · 02 Oktober 2021, 10:34:58

Hallo Timo,

hast Du mal FHEM beendet und die Demo cfg gestartet? Letzter Punkt:
https://wiki.fhem.de/wiki/FHEM_startet_nicht_-_Tipps_zur_Fehlersuche

Gruß Otto

rudolfkoenig · 02 Oktober 2021, 20:01:32

Der Verbose 5 Log ist ca 400 Sekunden lang. In dieser Zeit wurde
- /fhem/www/tablet/ftui2/images/empty.jpg 342 mal abgeholt. Weitere 60 Aufrufe vom Webtablet machen den Aufrufzahl rund (1 FHEMWEB-Request pro Sekunde).
- HUEBridge 580-mal gepollt (HTTP Requests)
- 140 weitere HTTP Aufrufe abgesetzt (spotify, netatmo, fritz.box, etc, etc)
- 406 Event-Gruppen verarbeitet. Vermutlich schnell genug, aber ohne "attr global mseclog" sieht man das nicht. Es sind 691 FHEM-Definitionen vorhanden (davon 193 notify, 143 FileLog) d.h. es gibt etliche Geraete, die was tun.

Das sollte ein RPi 3 zwar verkraften, man kann ihm aber auch helfen, indem man seltener pollt.
Fuer bessere Ratschlaege brauche ich zusaetzlich zu "attr global verbose 5" auch "attr global mseclog 1".

Ist sicher, dass FHEM die 80% CPU-Last verursacht?

TimoD · 02 Oktober 2021, 21:10:57

Hallo Ihr beiden,

schonmal vielen Dank für Eure Unterstützung,

zu Otto:

habe gerade meine FHEM Instanz als Demo Config gestartet, hier habe ich kaum CPU Auslastung und kann die Demo Konfiguriert über den Webbrowser aufrufen. Es scheint also nicht grundsätzlich an meinem RPi zu liegen.

zu rudolfkoenig:

ja, ich habe mehrere Tablets / Funktionen die während des Verbose 5 Modes aktiv waren. Hatte aber im Anschluss sehr viele Module deaktiviert / alle FTUIs ausgeschaltet und das Problem bestand weiterhin! Das ich denke, ja es ist viel, aber nicht der Ursprung des Problems, wie meinst du das mit dem seltener Pollen?
--> Wie stelle ich das bei der HUEBridge / in FTUI ein?
--> Kann ich das Global verringern bei HTTP Aufrufen oder muss ich das im jeweiligen Modul (Spotify / netatmo etc. machen?)
--> siehe Anhang Verbose 5 + attr global mseclog Neustart + 3 Minuten Laufzeit fhem mit >80% CPU
--> ob ich mir sicher bin das fhem die CPU Last verursacht? Ich sehe es halt über SSH in der Anzeige über Top (siehe Screenshot im Anhang)

Ihr seid Spitze, ich habe das Gefühl, wie finden den Fehler

Grüße Timo

TimoD · 02 Oktober 2021, 21:14:37

Hab gerade mal geschaut, bei z.B. HUE finde ich gar keine Einstellung um das Rolling zu verringern,...

Otto123 · 02 Oktober 2021, 21:42:17

Ich sag mal noch: das hier ist unnütz - aber scheinbar nicht das Problem. Könntest Du aber beheben

Zitat2021.10.02 00:03:14 1: Error evaluating MS75dummy userReading DurchschnittV: Illegal division by zero at (eval 23789) line 1.

Ansonsten klingt es mir danach, dass durch das update eine Schleife auftaucht. Wie alt war das System vor dem Update?
Wäre es eine Option, zum Test das update mit restore zurück zu drehen?

TimoD · 02 Oktober 2021, 22:24:48

update ist jetzt 1,5 Monate her und davor ca. 1,5 Jahre alt,... was passiert bei ReStore denn genau? (Es war aber nicht das letzte Update, hatte es Gestern auch nochmal ausgeführt) ist Restore dann trotzdem noch möglich?

Was genau passiert den bei Restore? (Ist das reversibel?)

TimoD · 02 Oktober 2021, 22:42:29

Was mir gerade noch auffällt, worauf ich aber keine Erklärung habe:

Meine Logdateien liegen zum Teil in der Zukunft!? Siehe Screenshot aktuell war es 22:40 Uhr. Mein System selbst zeigt aber die Richtige Zeit an, habe es mit:

{ localtime }
{qx(date +%R)}
{$hms}

überprüft. Kann es vielleicht daran liegen,...

rudolfkoenig · 02 Oktober 2021, 23:02:47

Im letzten Log sind 2:25 verwertbare Daten (vom Start bis zum Abschalten des mseclogs).
Die Event-Verarbeitung (notify+Filelog+...) belegt aus diesen 145 Sekunden insg. 17.692 (entspricht 12% CPU), wobei Sonos_WOhnzimmer mit 9.164s ueber die Haelfte ausmacht.
Den Rest kann ich nicht erklaeren, da muss man andere tools / FHEM-Module verwenden.

Die Zeit-Unterschiede koennten auch an den unterschiedlichen Timezonen der beiden Rechner liegen.

TimoD · 02 Oktober 2021, 23:16:09

Zitat von: rudolfkoenig am 02 Oktober 2021, 23:02:47
Im letzten Log sind 2:25 verwertbare Daten (vom Start bis zum Abschalten des mseclogs).
Die Event-Verarbeitung (notify+Filelog+...) belegt aus diesen 145 Sekunden insg. 17.692 (entspricht 12% CPU), wobei Sonos_WOhnzimmer mit 9.164s ueber die Haelfte ausmacht.
Den Rest kann ich nicht erklaeren, da muss man andere tools / FHEM-Module verwenden.

Die Zeit-Unterschiede koennten auch an den unterschiedlichen Timezonen der beiden Rechner liegen.

Bedeutet irgendwas scheint komisch zu sein, da 12% CPU nicht zusammenpasst zu dem was ich in TOP sehe!? Noch eine Idee, was das sein könnte: "andere tools / FHEM-Module verwenden" - also was ich hier noch tun könnte zum Debuggen?

Otto123 · 03 Oktober 2021, 00:18:43

Zitat von: TimoD am 02 Oktober 2021, 22:24:48
update ist jetzt 1,5 Monate her und davor ca. 1,5 Jahre alt,... was passiert bei ReStore denn genau? (Es war aber nicht das letzte Update, hatte es Gestern auch nochmal ausgeführt) ist Restore dann trotzdem noch möglich?

Was genau passiert den bei Restore? (Ist das reversibel?)

gib help restore ein für Hilfe. Restore holt die Moduldateien vor dem Update zurück. Es werden keine Daten geändert. Ich will das aber jetzt nicht empfehlen.

Das mit der Zeit ist sehr komisch. Also das Du etwas anderes als die echte Zeit angezeigt bekommst liegt an Deinem Zugriff, entweder auf dem Pi oder auf dem PC die falsche Zeitzone (ich sage nicht das die Uhr eine falsch Zeit zeigt).
Aber das die Logs unterschiedliche Zeiten haben kann ich nicht erklären, dann müssten Module mit unterschiedlichen Zeiteinstellungen arbeiten?

Was zeigt denn {qx(date)} und {localtime} an?

TimoD · 03 Oktober 2021, 13:45:57

Zitat von: Otto123 am 03 Oktober 2021, 00:18:43
gib help restore ein für Hilfe. Restore holt die Moduldateien vor dem Update zurück. Es werden keine Daten geändert. Ich will das aber jetzt nicht empfehlen.

Das mit der Zeit ist sehr komisch. Also das Du etwas anderes als die echte Zeit angezeigt bekommst liegt an Deinem Zugriff, entweder auf dem Pi oder auf dem PC die falsche Zeitzone (ich sage nicht das die Uhr eine falsch Zeit zeigt).
Aber das die Logs unterschiedliche Zeiten haben kann ich nicht erklären, dann müssten Module mit unterschiedlichen Zeiteinstellungen arbeiten?

Was zeigt denn {qx(date)} und {localtime} an?

Beide das Selbe, die Richtige Zeit

(Hab gerade auch nochmal die Zeitzone konfiguriert, hat aber gepasst). Komme nicht weiter, habe nun so ziemlich alle Logs in FHEm deaktiviert, wirklich alle updates in Stretch / FHEM ausgeführt, FHEM aufgeräumt. Ohne Erfolg immer noch 100% Auslastung auf dem Kern wo FHEM läuft,...

Jamo · 03 Oktober 2021, 13:54:25

Dann würde ich anfangen, einzelne FHEM Module / Devices zu löschen, solange bis die CPU Auslastung wieder normal ist. Dann hast Du den Verursacher.
Z.B, HTTPMOD Devices machen schon mal Probleme wenn der regexp nicht stimmt..

TimoD · 03 Oktober 2021, 15:17:18

Zitat von: Jamo am 03 Oktober 2021, 13:54:25
Dann würde ich anfangen, einzelne FHEM Module / Devices zu löschen, solange bis die CPU Auslastung wieder normal ist. Dann hast Du den Verursacher.
Z.B, HTTPMOD Devices machen schon mal Probleme wenn der regexp nicht stimmt..

Gibt es denn irgendeine Möglichkeit, die Module zu deaktivieren, ohne das ich es in meiner Konfiguration löschen muss? Hatte ich versucht, aber ohne Erfolg,..... (z.B. wenn ich die Modul.pm aus dem FHEM Ordner lösche!? (Was kann ich Adhoc alles löschen?)

Jamo · 03 Oktober 2021, 15:23:15

Ok, ich meinte natürlich nicht die Module an sich aus dem FHEM Ordner. Aber deine Devices, nachdem Du vorher ein backup gemacht hast. Wenn Du den Verursacher gefunden hast, kannst du die fhem.cfg zurückkopieren. attr <device> disable 1 geht natürlich auch, oder z.B ein ,,attr TYPE=HTTPMOD disable 1" wenn du bestimmte Typen disablen willst.