[gelöst] FHEM blockiert für einige Sekunden, wo ansetzen?

[ronny332]

Hallo zusammen,

meine FHEM Installation wächst und gedeiht, wenn ich ein Jahr zurück an meine Gehversuche mit Homematic und einer CCU2 denke kommt doch pure Zufriedenheit auf.

Was mich aktuell etwas "nervt" (eher ein Luxus Problem als ein wirklicher Schaden) ist ein gefühlt alle 3-5 Minuten stattfindender Hänger, bei welchem die Weboberfläche komplett blockiert (für ca. 10 Sekunden). Meine eigenen Module (SMA Wechselrichter, ABUS Alarmanlage, ...) habe ich nach und nach komplett auf Blockingcall() umgestellt, auch alles was auf 1-Wire basiert nutzt mittlerweile OWX_ASYNC (hier aber aktuell nur Fühler, Schalter sind inaktiv). Ansonsten kommt viel Homematic (ca. 50 Devices), FS20 (ca. 10 Geräte), ein bisschen TRX und HM485 zum Einsatz. Basis ist configdb und logdb, beide mit MySQL als Datenbank.
Der Server ist mittlerweile ein i5 Intel NUC der aktuellen Generation, an der Performance sollte es nicht scheitern.

Wenn der Hänger auftritt passiert optisch "nichts". "lsof" und andere bekannte Tools liefern keine Anhaltspunkte, der Kernel Log ist leer, "ps aux" (oder auch top) zeigen keine aktuelle Last. Auch der "wa" (was auf Bus Last hindeuten würde) ist auf 0.0%.

Nun die Frage: wie kann ich am Besten ansetzen? Gibt es in Perl oder FHEM eine Möglichkeit in einer Art Debug-Modus eine Nutzung nach Zeit zurückbezogen auf Funktionen oder auch Zeilennummer zu bekommen? Ich denke der Ansatz ist Profiling, aber bisher kam ich da mit nichts wirklich weiter.
Einen blockierenden Garbagde Controller ala Java oder Javascript scheint Perl nicht zu haben, zumindest war die Suche im Netz danach nicht sonderlich erfolgreich. Ausserdem würde ich dann eine hohe CPU Last erwarten, welche aber nicht da ist.

Vielen Dank und weiter frohes Schwitzen !

[Puschel74]

perfmon und apptime

Sorry, sind nur Stichwörter aber durchsuchen musst du dich schon selbst.
Ich benutze beide nicht wären aber eine Möglichkeit für einen Ansatz (hoffe ich).

[Wuppi68]

Puschel74's Kommentar ist genau das richtige zum ermitteln der "Latenzen"

gerne sind auch immer wieder Netzverbindungen und auch dblog zu finden ...

[ronny332]

Dankeschön, dann setze ich da mal an !

[reibuehl]

Ich habe genau das selbe Problem! Mir kommt es so vor als ob die Delays nur vom Web Frontend kommen würden, da ich die entsprechenden "Denkpausen" bisher nie beim Telnet - Interface beobachten konnte. Ist das bei Dir auch so?

[ronny332]

Perfmon hat perfekt geholfen , danke nochmals für den Tip. Es liegt wirklich am SMA Wechselrichter Modul, welches ich aber durch zwei sich im Einsatz befindliche Geräte doch ziemlich umgebaut habe. Mittlerweile hat es mit http://www.fhemwiki.de/wiki/SMAWechselrichter nicht mehr viel gemeinsam, ausser der Teil, welcher sich gerade als Problem herausstellt.

Ich stelle hier mal Teile des Codes und Logs ein, hoffentlich hat hemand eine Idee.

Hintergrund:
- 2x SMA Wechselrichter gleichen Typs, betrieben via SMAspot (SPFspot heute)
- Ursprüngliches Modul von http://www.fhemwiki.de/wiki/SMAWechselrichter
- Blockierende Aufrufe in der Konsole wurden mit BlockingCall() entschärft
- Das Updaten der Readings scheint im Parallel Betrieb von zwei Wechselrichtern Probleme zu machen

Log:

Code Auswählen Erweitern


2015.07.19 10:48:38 2: sma_wr_1 begin blocking call
2015.07.19 10:48:38 2: sma_wr_2 begin blocking call
2015.07.19 10:48:38 2: sma_wr_1 in blocking call
2015.07.19 10:48:38 2: sma_wr_2 in blocking call
2015.07.19 10:48:39 2: sma_wr_1 ended blocking call
2015.07.19 10:48:39 2: sma_wr_1 begin update
2015.07.19 10:48:39 2: sma_wr_1 end update
2015.07.19 10:48:54 2: sma_wr_1 ended updating
2015.07.19 10:48:54 1: Perfmon: possible freeze starting at 10:48:40, delay is 14.898
2015.07.19 10:48:54 2: sma_wr_2 ended blocking call
2015.07.19 10:48:54 2: sma_wr_2 begin update
2015.07.19 10:48:54 2: sma_wr_2 end update
2015.07.19 10:48:54 2: sma_wr_2 ended updating


Codeausschnitt (die BlockingCall Geschichte lasse ich weg, da blockiert nichts (mehr) wie man am Log sieht):

Code Auswählen Erweitern


sub
Handle_Inverterdata($) {
...
  Log(2, $hash->{NAME}." ended blocking call");

...
   #Variablendeklaration
...
 
  Log(2, $hash->{NAME}." begin update");
  readingsBeginUpdate($hash);
   
  foreach my $line (@lines) {
...
   #Aufbereitung des Inputs
...
   #Update der Readings
           readingsBulkUpdate($hash,$readingsname,$readingsvalue);
...
   }
   #Ende Update der Readings
   Log(2, $hash->{NAME}." end update");
   readingsEndUpdate($hash, 1);
   Log(2, $hash->{NAME}." ended updating");
...
}


"readingsEndUpdate($hash, 1);" blockiert nun laut Log für 15 Sekunden. Beide Wechselrichter laufen eigentlich in einer eigenen Umgebung, mein Wissen ist aber ehrlich gesagt was eigene Modul Deklarationen in FHEM angeht noch nicht weit genug um es mit 100%iger Sicherheit zu behaupten.

Ist es daher ein Fehler "readingsEndUpdate($hash, 1);" aufzurufen, wenn ein weiterer Wechselrichter gerade noch Daten sammelt und eventuell einspielt?

Kleine Nachtrag:
der Hash ist grundverschieden, die Device Namen auch, alles andere muss damit in Bezug auf diese beiden Punkte auch unabhängig sein. Ich kann da keinerlei Einschränkung oder Grund erkennen, wieso es hier zu einem Hänger kommen kann. Andere Module wie z.B. Netatmo machen es auf die gleiche Art und Weise ohne Rücksicht auf andere Nutzungen des Bulkupdates.

[herrmannj]

perfmon kann nur als Indikator für "fhem-Blockaden" agieren.

Generell kommen auch andere Möglichkeiten in Betracht. Im Log siehst Du ja nur Module die da was reinschreiben.

Wenn also modul X was macht und sich im Log vereweigt, dann modul Y (notify, at, sub ...) was tut und fhem dabei 15 sec blockiert meldet perfmon nur das ein freeze gemessen wurde.

Im log kann das dann so aussehen als wäre Modul X der Verursacher weil der der letzte Eintrag eben von X kommt. Aber auch nur weil Y nix ins log geschrieben hat.

Von daher:
* perfmon ist der Indikator DAS ETWAS blockiert.
* Apptime hilft rauszufinden WER blockiert.

Schau mal ob notify oder doif mit events VOM sma modul getriggert werden.

vg
joerg

[ronny332]

Hallo,

es blockiert readingsEndUpdate. Der Log bestätigt mir das, da readingsEndUpdate von je einem Log eingekeilt ist und ich mit Änderung der Position auch die Position im Log verändern kann.

Code Auswählen Erweitern


2015.07.19 10:48:39 2: sma_wr_1 end update
2015.07.19 10:48:54 2: sma_wr_1 ended updating


"end update" steht vor dem Aufruf von "readingsEndUpdate" und "ended updating" kommt genau in der Zeile danach. Da Perl an dieser Stelle nach meinem Verständnis kaum eine Möglichkeit besitzt aus der Funktion herauszuspringen (sollte ja alles sequentiell sein), müsste der Hänger in/bei readingsEndUpdate geschehen. Apptime selber war an der Stelle bisher nicht hilfreich, oder ich habe bis hierhin etwas missverstanden. Es tauchen keinerlei auf diese "Ecke" bezogenen Einträge auf, aber ich gucke natürlich gerne nochmals .

[herrmannj]

es blockiert readingsEndUpdate.

Ich melde da mal Zweifel an.

Schau mal ob notify oder doif mit events VOM sma modul getriggert werden.

Done ?

vg
joerg

[ronny332]

leider doch, bzw. es liegt an den notifies die erzeugt werden.

mit "readingsEndUpdate($hash, 0);" statt "readingsEndUpdate($hash, 1);" ist der fehler weg. Alles geht in ca. 1s durch ohne Hänger.

Code Auswählen Erweitern


2015.07.19 11:43:38 2: sma_wr_1 begin blocking call
2015.07.19 11:43:38 2: sma_wr_2 begin blocking call
2015.07.19 11:43:38 2: sma_wr_1 in blocking call
2015.07.19 11:43:38 2: sma_wr_2 in blocking call
2015.07.19 11:43:39 2: sma_wr_2 ended blocking call
2015.07.19 11:43:39 2: sma_wr_2 begin update
2015.07.19 11:43:39 2: sma_wr_2 end update
2015.07.19 11:43:39 2: sma_wr_2 ended updating
2015.07.19 11:43:39 2: sma_wr_1 ended blocking call
2015.07.19 11:43:39 2: sma_wr_1 begin update
2015.07.19 11:43:39 2: sma_wr_1 end update
2015.07.19 11:43:39 2: sma_wr_1 ended updating


Aber die Ecke hilft mir in der Tat schon. Wäre jetzt also zu klären, was wo mit den Notifies angestellt wird . Und da wird dann hoffentlich wirklich Apptime helfen können.

[herrmannj]

siehste.

(events ausschalten: gute Idee !)

Jetzt könntest Du doch alle assoziierten notify und/oder DOIF disablen und die dann Stück für Stück enablen.

Dann zeigt sich doch welches "hängt"-

vg
joerg

edith:
in den notifys steht ja code den Du selber da rein geschrieben hast. Wird also nicht AM notify liegen sondern an einem Stück code IN einem notify ...

[ronny332]

So langsam wird mir klar wie Perl/FHEM an der Stelle zu arbeiten scheint. Mein Aufgaben Feld ist beruflich C++/Java(script) (ggf. noch PHP, aber leider kein Perl), wo Event Queues mittlerweile gängig zum Standard gehören, der Fehler war hier genau diese Warteschlangen auch zu erwarten.
Wenn ich den Code hier aber richtig verstehe so ist ein Notify in Perl/FHEM nicht asyncron, sondern es wird quasi vom Sender (Notify Erzeuger) unwissentlich der Empfänger gestartet. Meine Annahme dürfte daher falsch gewesen sein, dass die Funktion selber blockiert, wobei sie es aus der Code Sicht sogar wirklich tut.
Mit dem Ansatz geht es hoffentlich zügig weiter, Danke!

[herrmannj]

Meine Annahme dürfte daher falsch gewesen sein, dass die Funktion selber blockiert, wobei sie es aus der Code Sicht sogar wirklich tut.

Absolut richtige Sicht.

fhem arbeitet generell (fast) nicht asynchron, das was wie Multitasking aussieht (und ja gut implementiert ist) ist "kooperatives" Multitasking. Von der Modulseite gesehen ist es daher wichtig so früh wie möglich zurück zuspringen.

Es gibt für "longrunning" Task verschiedene Möglichkeiten. Für HTTP get zB steht einen non-blocking Variante zur Verfügung, die ist dann asynchron.

vg
joerg

[ronny332]

Hallo Joerg,

Vielen Dank für die Aufklärung, da war wirklich das Problem. Mein Ansatz war immer der falsche bei der Suche nach dem Fehler (schon vor Tagen). Eine Abkopplung des Konsolenrequests an SMAspot brachte zwar 2x 1 Sekunde weniger "Hänger", das eigentliche Problem bliebt bestehen. Nur aus Sicht von Event Queues ist ein abgesetztes Event ein abgeschlossenes Event, vor daher kam ich nicht ansatzweise darauf, dass hier direkt die Verarbeitung stattfindet. Mit dem Wissen ergeben sich auch ganz andere "Aha-Effekte", bei welchen ich mich schon länger gewundert habe.

Die Lösung des Problemes war in der Tat ein notify, welches auf den .etotal Wert des Wechselrichters lauschte (hier muss man wohl dann eher sagen: welches vom neuen Notify angestoßen wird) und bewusst mehrfach um ein paar Sekunden verzögert wurde, damit auch beide Geräte schon Ihre Werte geliefert haben (für ein Dummy Device).

Ganz einleuchtend ist es mir nicht, da ich im Perl Code ein

Code Auswählen Erweitern

fhem("sleep 1;")
stehen hatte, worauf weiterer Perlcode folgte.

Diverse Themen hier im Forum besagen weiterhin, dass ein sleep als fhem Kommando vom Parser in eine Art Timer (at) verwandelt wird, welcher nach X Sekunden von sich aus auslöst und so eine Blockierung vermeidet. Funktioniert das eventuell nur, wenn kein weiterer Perl Code kommt?

[marvin78]

Das FHEM-Kommado sleep ist nur dann nicht blockierend, wenn direkt darauf ein weiteres FHEM Kommando folgt.

Code Auswählen Erweitern

sleep 1;set Lampe on

Andernfalls verhält es sich wie ein Perl sleep.