2000 Freezes pro Tag

[RockFan]

Hallo zusammen!

Auf Anraten von KölnSolar öffne ich hier mal ein neues Thema zu meinen von Freezemon berichteten Freezes.

Kurz zu meiner Vorgeschichte:
Ich arbeite seit ca. 12 Jahren mit FHEM. Begonnen auf einer FritzBox, dann migriert zu einem BananaPro, später Raspberry Pi 3 und seit einiger Zeit Raspberry Pi 4 (unter Buster).
Dank der hervorragenden Arbeit in dieser FHEM Community habe ich in den vielen Jahren jede Menge Systeme (FS20, TRX, EnOcean, Xiaomi, MiLight, usw.) integriert und unzählige Devices weit über die reinen HW-Geräte hinaus erstellt. In all den Jahren gab es immer wieder mal "Holpereien", sei es Speicherprobleme oder volle CPU-Auslastungen, was sich aber immer weitestgehend lösen ließ. Gefühlt läuft das ganze System für mich in der Vergangenheit und auch heute rund.

Seit FREEZEMON von KernSani der Community zur Verfügung gestellt wurde, setze ich auch dieses Modul mit dem Ziel Holpersteine zu finden ein. Seit Beginn an habe ich nun entsprechende Einträge in meinem Log. Ich glaube mich erinnern zu können dadurch auch ein paar Probleme aufgespürt und beseitigt zu haben. Trotzdem blieben und bleiben viele Freeze-Einträge bis Heute im Log (aktuell liegt der Zähler bei knapp 2.000 pro Tag), bei denen ich ratlos bin oder insgeheim sogar dachte, dass sie an der großen Menge unterschiedlichster Devices liegen.

Markus (KölnSolar) hat mich nun aber überzeugt, dass die vielen Freezes nicht gut sein können und vorgeschlagen ein Thema zu öffnen. Hierzu habe ich gestern Mittag die eigenständige Logdatei definiert. Eigentlich wollte ich schon gestern das Thema aufmachen, habe dann aber gemerkt, dass ich die Logdatei nicht so einfach wegen sensibler Daten hier anhängen kann. Nun habe ich die ca. 10 Stunden von gestern soweit möglich anonymisiert und hänge sie hier mal an.

Für jeden Tipp oder Hinweis bin ich natürlich dankbar. Schon während der Überarbeitung der Logdatei ist mir das ein oder andere nicht mehr verwendete Device aufgefallen und habe schon mal mit etwas Bereinigung begonnen. Allerdings sind diese Devices wohl eher nicht an den Freezes schuld.

Viele Grüße
Dieter

Edit: Anhang gelöscht

[Beta-User]

Hi.

Habe jetzt nicht das komplette Log durchgesehen, aber soweit erkennbar kängen praktisch alle Freezes mit Netzwerkverbindungen zusammen.

Ob das überhaupt relevant ist, müsste jemand klären, der mehr Erfahrung mit dem Tool hat (bei Netzwerkverbindungen wird teils geforkt, gerade um effektive Blockaden zu verhindern).

Allgemein:
- mal https://forum.fhem.de/index.php/topic,117075.0.html durchschauen. Gibt ggf. weitere Hinweise zur Optimierung von Eventhandlern (was aber hier nicht das Problem zu sein scheint).
- Attribut dnsServer (in global) scheint (korrekt) gesetzt zu sein?
- Generell sind Fritzboxen aber nicht allzu gut darin, Netzwerkzentrale zu machen (dem Vernehmen nach ist das ein Euphemismus...). Das scheint bei dir noch der Fall zu sein?
- In FHEM scheinst du die meisten DEF mit IP statt hostname vorgenommen zu haben. Gut!

"MilightBridge" war übrigens bei mir der "Auslöser", mich überhaupt (vor Jahren) mit dem Thema auseinanderzusetzen, und ich bin heilfroh, dass heute eine "Sidoh-Bridge" meine (wenigen verbliebenen) MiLight-Geräte steuert (im Prinzip dieselbe Hardware wie ein MySensors-Gateway, aber andere Firmware, verbunden mit MQTT2_.*). Den Teil würde ich an deiner Stelle auf jeden Fall ändern - sei es durch Tausch der Hardware (ich habe das meiste MiLight-Zeug durch ZigBee ersetzt), sei es durch das andere Interface.

Viel Erfolg!

[KölnSolar]

Hi Dieter,
gefunden. 

Aus Deinem Text fallen mir schon einmal diese Kandidaten auf: Xiaomi, MiLight Xiaomi deshalb, weil ich selber einen Luftreiniger habe, dem ich bis ich eine Lösung gefunden habe den Zugriff auf mein WLAN verweigere. Grund ist die Übertragung der WLAN Credentials an Xiaomi.    Aber performance ist ja etwas anderes. Aber da kommt mir dann in den Sinn, dass gerne fhempy eingesetzt wird, was ich wiederum gar nicht mag, weil Fremdsoftware zum Zuge kommt, die nicht unbedingt, wie wir hier bei FHEM, für das Thema freezes sensibilisiert ist. Meistens sind es standalone-Softwarefragmente, die sich um andere Funktionalitäten einen feuchten scheren.

Bis auf das Frittenthema stimme ich Beta zu.

Ich guck mal durchs Log(ggfs. reicht auch immer mal ein Extrakt oder eine PN, damit Du nicht zu viel anonymisieren musst.

Grüße Markus
Edit: der gefällt mir schon einmal gar nicht. Taucht häufig auf.Ein selbstgestrickter timer

Code Auswählen Erweitern

2022.03.17 11:37:14.223 5: redefine at command on_timer_action as +*00:00:01 {my $e = ReadingsVal("DiscoSettings", "Timer", 0); $e -= 1; if ($e == 0) {fhem("set on_timer_action inactive"); $e = 0;} fhem("setreading DiscoSettings Timer $e");}
--- log skips     3.196 secs. den ich auch nicht ganz verstehe: ein timer-reading(egal wie groß) -1 wird immer auf 0 gesetzt, so dass nach 1s das at deaktiviert wird ? Und an der Klammerung kann man auch arbeiten. 
Das fällt mir ein paar mal ins Auge

Code Auswählen Erweitern

2022.03.17 11:43:33.291 5: DevIo_SimpleWrite local_pybinding: 7b2261776169744964223a37383431303939382c226572726f72223a302c22726573756c74223a6e756c6c7d
2022.03.17 11:43:33.292 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
--- log skips     3.041 secs.Sagt mir nichts. Doch hoffentlich nicht das py-Thema ?
Über den UPNPController reden wir hier natürlich nicht. 
Was ist das: TALKTOUSER?
Und komischerweise tritt nach einem freeze seeeehr oft

Code Auswählen Erweitern

2022.03.17 13:20:32.007 5: HttpUtils url=http://192.168.178.88:9090/ NonBlocking via httpWelches device hat diese IP ? Vielleicht schlecht angebunden(ich hab ein Problem mit powerline-devices).

Damit bist Du ja erst einmal beschäftigt. Das File würde ich jetzt entfernen. Ist ja verdammt viel, was Idioten interessieren könnte.

Edit2: Achso, noch zum Verständnis, nach diesen Zeilen

Code Auswählen Erweitern

--- log skips     3.041 secs.Ausschau halten, denn das bedeutet, dass in dieser Zeit zumindest nichts zu loggen war und in der Regel vorher/nachher der freeze-Grund steht.

[RockFan]

Danke Euch schon mal für Eure ersten Einschätzungen!

@Beta-User:

- mal https://forum.fhem.de/index.php/topic,117075.0.html durchschauen. Gibt ggf. weitere Hinweise zur Optimierung von Eventhandlern (was aber hier nicht das Problem zu sein scheint).

Den Post kannte ich noch nicht. Ich werde mir die einzelnen Punkte bzw. die Tipps mal genauer ansehen.

- Attribut dnsServer (in global) scheint (korrekt) gesetzt zu sein?

Ist auf die IP meiner FritzBox gesetzt.

- Generell sind Fritzboxen aber nicht allzu gut darin, Netzwerkzentrale zu machen (dem Vernehmen nach ist das ein Euphemismus...). Das scheint bei dir noch der Fall zu sein?

Ja, bei mir sitzt eine FritzBox in der Mitte  ... und obendrein noch 2 Repeater, da drei Stockwerke mit WLAN abgedeckt werden müssen

- In FHEM scheinst du die meisten DEF mit IP statt hostname vorgenommen zu haben. Gut!

Muss mal schauen, ob ich das wirklich immer gemacht habe 

Danke für den Hinweis: Das mit der MilightBridge muss ich mir mal überlegen

@Markus:
fhempy hat mir das Tor für ein paar Themen wie z.B. Bluetooth bzw. das Gateway 3 von Xiaomi geöffnet. Da fhempy erst seit sehr kurzer Zeit in meinem Programm ist, die Freezes aber schon jahrelang auftauchen, kann es eigentlich kein "root cause" sein (wenn es den überhaupt gibt )

der gefällt mir schon einmal gar nicht. Taucht häufig auf.Ein selbstgestrickter timer

Der Timer ist mir auch aufgefallen. Es ist mir ein Rätsel, warum er überhaupt etwas macht. Der Status ist "inactive" (über set auf inaktiv gesetzt). Ich brauche ihn eigentlich nur ein- oder zweimal im Jahr. Wieso "arbeitet" der inaktive Timer eigentlich?

Das fällt mir ein paar mal ins Auge
Code: [Auswählen]

2022.03.17 11:43:33.291 5: DevIo_SimpleWrite local_pybinding: 7b2261776169744964223a37383431303939382c226572726f72223a302c22726573756c74223a6e756c6c7d
2022.03.17 11:43:33.292 5: BindingsIo (local_pybinding): QUEUE: finished handling - 0
--- log skips     3.041 secs.

Sagt mir nichts. Doch hoffentlich nicht das py-Thema ?

Doch, das gehört zu fhempy.

Was ist das: TALKTOUSER?

Auch das gehört zu den Punkten, die mir heute selbst aufgefallen sind. Damit wollte ich vor Jahren etwas ausprobieren, habe es dann sein lassen, aber nur deaktiviert. Habe das Device heute Morgen gelöscht.

Und komischerweise tritt nach einem freeze seeeehr oft
Code: [Auswählen]

2022.03.17 13:20:32.007 5: HttpUtils url=http://192.168.178.88:9090/ NonBlocking via http

Welches device hat diese IP ? Vielleicht schlecht angebunden(ich hab ein Problem mit powerline-devices).

Das ist ein alter RPi, auf dem Kodi läuft. IP und Port deuten genau auf das KODI-Device hin. Allerdings läuft Kodi nur "On Demand", da Kodi viel Leistung erfordert, aber eigentlich 95% des Tages gar nicht benötigt wird. Das steuere ich über FHEM. Mit dem Device beende ich Kodi. Das Thema ist aber auch relativ jung (ca. 1,5 Jahre).

Einige Ansätze zur Suche habe ich tatsächlich schon mal. 

Viele Grüße
Dieter

[Beta-User]

Ja, bei mir sitzt eine FritzBox in der Mitte  ... und obendrein noch 2 Repeater, da drei Stockwerke mit WLAN abgedeckt werden müssen

Bei Fritz.* "scheiden sich die Geister". Habe auch eine als Netzwerkzentrale im Einsatz und bin dann aber froh um jedes Netzwerkgerät, das ich nicht habe... Schon alleine das Web-IF von der Fritte ist quälend langsam.

Muss mal schauen, ob ich das wirklich immer gemacht habe 

(so war es gemeint )

wie z.B. Bluetooth

Das "fackle" ich mit OpenMQTTGateway ab (ESP32-basiert), um kompliziert auszulesende GW's mache ich einen großen Bogen.

das Gateway 3 von Xiaomi

Das macht afaik ziemlich viel, und u.a. ZigBee. ZigBee habe ich via deconz eingebunden, würde tendenziell das oder zigbee2mqtt für den Teil empfehlen.

Da fhempy erst seit sehr kurzer Zeit in meinem Programm ist, die Freezes aber schon jahrelang auftauchen, kann es eigentlich kein "root cause" sein (wenn es den überhaupt gibt )

Das läuft afaik einfach parallel und sollte keine freezes verursachen.

Der Timer ist mir auch aufgefallen. Es ist mir ein Rätsel, warum er überhaupt etwas macht.

Das könnte ("as") ein cmdalias sein, der da ggf. unbeabsichtigt immer wieder mit reinspielt.

Das ist ein alter RPi, auf dem Kodi läuft.

Ggf. kann man da was machen, dass die Intervalle verlängert werden u.ä.. Wenn nicht vorhandene/erreichbare Geräte angepingt werden, ist das erfahrungsgemäß "verzögerungsverdächtig".

[RockFan]

Hi,

nach knapp 2 Wochen möchte ich ein Update bzgl. Aktionen und Ergebnissen geben:
Zunächst habe ich ein wenig aufgeräumt, ein paar verwaiste oder gänzlich unbenutzte Devices (z.B. TALKTOUSER) gelöscht, einige fehlende event-on-change-readings .* ergänzt usw.

Ggf. kann man da was machen, dass die Intervalle verlängert werden u.ä.. Wenn nicht vorhandene/erreichbare Geräte angepingt werden, ist das erfahrungsgemäß "verzögerungsverdächtig".

Da ich Start und Stopp von Kodi über FHEM steuere, habe ich einfach das (De-)Aktivieren des Devices in diese Logik mit eingebaut. Dabei hat sich herausgestellt, dass das Disable-Attribut nicht richtig funktioniert. Der Maintainer hat es dann auf meine Anfrage hin erfolgreich korrigiert

Von den ursprünglich 19xx Freezes bin ich damit auf 17xx Freezes pro Tag herunter gekommen.

Alle weiteren der folgenden Schritte habe dann leider keine messbaren Besserungen mehr ergeben:
- Löschen des at-Devices on_timer-action (wie eigentlich schon erwartet)
- Löschen der MilightBridge (hierbei hätte ich mir mehr versprochen)
- Umstellung meiner 3 Shelly Devices auf MQTT (auch hier hatte ich mir mehr versprochen)
- Aufspüren weiterer fehlender event-on-change-readings mit DOIFTools - das waren noch eine ganze Menge  

Achso, noch zum Verständnis, nach diesen Zeilen

Code Auswählen Erweitern


--- log skips     3.041 secs.

Ausschau halten, denn das bedeutet, dass in dieser Zeit zumindest nichts zu loggen war und in der Regel vorher/nachher der freeze-Grund steht.

Dieser Hinweis hat zu einigen der o.g. Aktionen geführt. Z.B. MilightBridge, Shelly und auch on_timer_action standen richtig oft vor oder nach den "log skips". Nach der jeweiligen Änderung habe ich das Log beobachtet und musste einfach nur feststellen, dass nun andere Devices an deren Stelle stehen. Das kann man natürlich nicht wörtlich so nehmen, wie ich es geschrieben habe, da die Logeinträge sehr vielfältig sind. Aber da sich die Anzahl der Freezes nicht wirklich geändert hat, ...

Wie im Eingangspost geschrieben läuft das System gefühlt vollkommen rund - wenn da nicht die vielen Freezes im Log stehen würden 


Viele Grüße
Dieter     

[KölnSolar]

Hi Dieter,

Nach der jeweiligen Änderung habe ich das Log beobachtet und musste einfach nur feststellen, dass nun andere Devices an deren Stelle stehen.

Möglich...
Schickst Du mir mal das freezemon-Log per PN.
Grüße Markus

[RockFan]

Hallo Markus,

man kann scheinbar einer PN nichts anhängen. Ich habe es mal mit "Code" versucht. Ob das mit über 130 Tausend Zeilen funktioniert 

Auf jeden Fall besten Dank für Deine Mühe.

Viele Grüße
Dieter