Lock-Situtation

[herman]

Hallo Martin,

seit einiger Zeit hängt sporadisch mein FHEM. Ich bin gerade auf der Suche nach dem Fehler und habe eine Auffälligkeit mit dem HM-Lan Adapter gesehen.

Folgende Situation ist bei mir gegeben.

- aktuelle Version von FHEM auf raspberry PI
- HM-Lan Adapter
- jede Menge HM-Geräte
   7 HM-CC-TCs
   14 HM-CCVDs
   7 Licht Aktoren
   6 Steckdosen Aktoren
   7 Rolladen Aktoren
   1 Bewegungsmelder
   5 Taster
   2 Fernbedienungen
- 60 notifiys - Hauptsächlich als Reaktion auf Tasten
- Sonos-Modul

In finde das System im Schnitt ca. 1x am Tag hängend mit einer konstanten, niedrigen CPU-Auslastung. Manchmal fängt sich das System wieder. In letzterem Fall steht etwas von "HMLAN1 new condition disconnected" im Log. Stellt sich bei mir die Frage, ob FHEM irgendwo etwas länger braucht, somit die Verbindung zum HLAN verloren geht und deshalb das ganze System hängt.

Grundsätzlich Fragen:

Sprengt diese Anzahl von Geräten den Scope von FHEM und dem HM-Modul?
Ist die Anzahl von notifiy ein Problem?
Ist es vlt. die Kombination aus beidem?

Ich wundere mich, denn nach einem Neustart sendet das System ja an alle Geräte einen StatusRequest. Da antworten alle HM-Geräte zeitnah. Nach o.g. Theorie müsste es in dieser Situation öfter zum hängen kommen. Da der Fehler nur einmal am Tag auftritt, und das in ganz unterschiedlichen Situationen, weiß ich gerade nicht wo ich mit der Suche anfangen soll.

Ist es ratsam, den Loglevel mit allen Geräten hochzuschrauben oder würdest Du erstmal das System kleiner dimensionieren (alle notifys löschen, oder Sonos-Modul entfernen etc.)?

Hier eine Lock-Situation mit Loglevel 5 am Sonos-Modul

Code Auswählen Erweitern


2014.02.10 23:04:53 5: SONOS0: Received from UPnP-Server: 'SetCurrent:nextTitle:tangomatrix'
2014.02.10 23:04:53 5: SONOS0: Received from UPnP-Server: 'CurrentBulkUpdate:RINCON_000E58A9DED201400_MR'
2014.02.10 23:04:53 1: 192.168.3.11:1000 reappeared (HMLAN1)
2014.02.10 23:04:53 1: HMLAN_Parse: HMLAN1 new condition init
2014.02.10 23:04:58 1: HMLAN_Parse: HMLAN1 new condition ok
2014.02.10 23:06:50 5: SONOS0: Received from UPnP-Server: 'GetReadingsToCurrentHash:RINCON_000E58A9DED201400_MR:1'
2014.02.10 23:06:50 5: SONOS0: Received from UPnP-Server: 'SetCurrent:TransportState:PLAYING'
2014.02.10 23:06:50 5: SONOS0: Received from UPnP-Server: 'SetCurrent:CrossfadeMode


Ich habe kein Notify an Sonos Geräten und kein AT zu diesem Zeitpunkt. Wie oben beschrieben 60 notifys an der Zahl.

Hättest Du einen Tipp für mich? Vielen Dank!
Merhan

[martinp876]

Hi Merhan


- aktuelle Version von FHEM auf raspberry PI
- HM-Lan Adapter
- jede Menge HM-Geräte
   7 HM-CC-TCs
   14 HM-CCVDs
   7 Licht Aktoren
   6 Steckdosen Aktoren
   7 Rolladen Aktoren
   1 Bewegungsmelder
   5 Taster
   2 Fernbedienungen
- 60 notifiys - Hauptsächlich als Reaktion auf Tasten
- Sonos-Modul

In finde das System im Schnitt ca. 1x am Tag hängend mit einer konstanten, niedrigen CPU-Auslastung.

Die CPU spitze  kann klein sein - könnte bei Mittelwerten verloren gehen

Sprengt diese Anzahl von Geräten den Scope von FHEM und dem HM-Modul?

nicht inbedingt

Ist die Anzahl von notifiy ein Problem?

könnte sein. Rudi hat hier die Performance aber verbessert... also müsste man es ausmessen

Ist es vlt. die Kombination aus beidem?

Die Notifies werden mit Events multipliziert...

=> du solltest wo möglich event-on-change-readings .* setzen - das reduziert die Anzahl der Trigger.

Ist es ratsam, den Loglevel mit allen Geräten hochzuschrauben...

ich würde mit apptime einmal nach verdächtigen suchen.

Gruss Martin

[herman]

Hallo Martin,

Deine Kommentare wecken ein gutes Gefühl - ich muss nur noch etwas recherchieren um sie auch zu verstehen

Kann ich "event-on-change-readings" von HM-Gräten rigoros anwenden oder hat das Einfluss auf Deine Module. Sprich ist Dein Code davon betroffen, wenn ich z.B. an einem HM-CC-TC einstelle, dass nur bei Änderungen des battery - readings events ausgelöst werden sollen.

Grüße,
Merhan

[martinp876]

meine Empfehlung ist immer
event-on-change-readings .*
und das schon lange. Eigentlich würd eich es gerne als Default einbauen, da es in fast allen Fällen sinn macht.

Mir fällt gerade nur eine Ausnahme ein, das ist de motion-detector. Der liefert "motion" bei Bewegung. und bei der nächsten wieder "motion" - das würde gefiltert werden.

Ich empfehle auch, die Anzahl der logfiles zu minimieren. Eine Grundeinstellung sollte sein:
- ein Logfile für alle Events aller Devices
- logfiles für Ventile/TC,... (auch hier kann man mehrere kombinieren)
- das Zentrale logfile für Fehler.
Wenn man mehr braucht, kann man von hier aus erweitern.
Weniger offenen Files entlastet das System sowieso

Aber apptime sollte zeigen, wer wie lange braucht und welcher timer wie lange verzögert war. Das ist m.e. die ultimative Messung zum relevanten Timing

Gruss Martin

[herman]

Hallo Martin,

meine Config entspricht Deinen Empfehlungen. Logfiles waren bereits genau so.
Neu ist das event-on-change-readings .* in fast allen Geräten. Somit ist es deutlich ruhiger im Event-Monitor geworden. Trotzdem habe ich Abstürze und ein die  Meldung "HMLAN1 new condition disconnected" im Log.

Mehrere Stunden apptime liefert folgendes Ergebnis. das einzige Auffällige ist für mich das Yamaha-Modul - wobei ich keine Ahnung habe, ob das ok ist oder nicht.
Faktisch ist ja auch seit dem Start von apptime kein Absturz aufgetreten und wenn das System hängt gibt es ja keine Möglichkeit an die Statistik ranzukommen.

Gibt es eine Möglichkeit den Stand über ein AT zyklisch ins Log zu schreiben?

Danke & Viele Grüße,
Merhan

Code Auswählen Erweitern


                                name             function    max  count    total  average maxDly
                          HomeStatus            dummy_Set   6478     39     7393   189.56      0 HASH(0x2496210); HomeStatus; Weg
                   HomeStatus_Change          notify_Exec   6456      2     7348  3674.00      0 HASH(0x2534ef0); HASH(0x2496210)
            tmr-YAMAHA_AVR_GetStatus      HASH(0x24a8b90)   6007    415  2491608  6003.87   3060 HASH(0x24a8b90)
                               Media            dummy_Set   4147     38     4147   109.13      0 HASH(0x2496270); Media; off
                        Media_Change          notify_Exec   4125      1     4125  4125.00      0 HASH(0x2496480); HASH(0x2496270)
                              WZ_AVR       YAMAHA_AVR_Set   3008     39     4920   126.15      0 HASH(0x24a8b90); WZ_AVR; off
           FHEMWEB:x.x.x.x:50357              FW_Read    916      9      945   105.00      0 HASH(0x302d540)
                              HMLAN1           HMLAN_Read    892   3084   138975    45.06      0 HASH(0x1edec70)
                                CUL1             CUL_Read    578     24     3468   144.50      0 HASH(0x1e5be20)
                    FileLog_CUL_EM_1          FileLog_Log    460     24      512    21.33      0 HASH(0x24771d8); HASH(0x2475108)
                   batteryUebersicht readingsGroup_Notify    352   2519    40156    15.94      0 HASH(0x257a028); HASH(0x2434070)
                            AZ_Licht               IT_Set    345      8      345    43.12      0 HASH(0x2005390); AZ_Licht; off
                                CUL1              CUL_Get    341      1      341   341.00      0 HASH(0x1e5be20);  ; raw; isFFFF00F00F10
                 KUE_Heizung_Climate           CUL_HM_Set    328      8      391    48.88      0 HASH(0x238fb78); KUE_Heizung_Climate; controlMode; auto
           FHEMWEB:x.x.x.x:50354              FW_Read    320     12      353    29.42      0 HASH(0x302d798)
           FHEMWEB:x.x.x.x:49769              FW_Read    319      8      468    58.50      0 HASH(0x3016058)
           FHEMWEB:x.x.x.x:49769            FW_Notify    305    396     5852    14.78      0 HASH(0x3016058); HASH(0x257a028)
                  SZ_Heizung_Climate           CUL_HM_Set    268      8      330    41.25      0 HASH(0x2454ab0); SZ_Heizung_Climate; controlMode; auto
                  WZ_Heizung_Climate           CUL_HM_Set    266      8      329    41.12      0 HASH(0x24c8228); WZ_Heizung_Climate; controlMode; auto
                 tmr-CUL_HM_ActCheck       ActionDetector    167     25      750    30.00   2973 ActionDetector
                   HeizungUebersicht readingsGroup_Notify    132   2519    14876     5.91      0 HASH(0x25415e0); HASH(0x2453d40)


[martinp876]

log muesste schon gehen - dann kannst du es auch zyklisch loeschen...
muss ich aber erst testen, wegen der Syntax.

die einmaligen "dauerbrenner" sind nicht so schlimm. Auffaellig ist
            tmr-YAMAHA_AVR_GetStatus      HASH(0x24a8b90)   6007    415  2491608  6003.87   3060 HASH(0x24a8b90)
Ein timer der 415 mal dran war und immer so 6 sec dauert - das ist nicht schoen.

[herman]

Das Problem kommt daher, dass mein Yamaha-Verstärker hinter einer Funksteckdose hängt und im ausgeschalteten Zustand es zu einem Timeout kommt.
Ich habe im Modul 71_YAMAHA_AVR.pm in der Funktion GetStatus eine Überprüfung eingefügt, die überprüft ob die Steckdose eingeschaltet ist. Somit belastet diese Funktion nicht mehr das System. Mal schauen, ob mein Problem damit erledigt ist.

[herman]

Hallo Martin,

vor ein paar Monaten lief mein FHEM zusammen mit HMLAN problemlos. In der Zwischenzeit habe ich ein paar Updates gemacht und das Sonos-Modul in Verwendung. Seitdem leide ich unter Lock-Situationen.
ich habe jetzt mein Sonos-System aus der FHEM-Instanz rausgenommen und meine FHEM-Konfig wie Du es in diesem Thread empfohlen hast weiter optimiert.
Jetzt stehe ich eigentlich besser das als vor ein paar Monaten - das eventlog ist deutlich ruhiger und apptime zeigt nichts auffälliges an.
Trotzdem habe ich eine Lock-Situation bei der FHEM nicht mehr reagiert.

Ich habe mal die Lock-Situtation weiter laufen lassen.

Code Auswählen Erweitern


2014.02.16 14:52:56 2: IT set AZ_Licht off
2014.02.16 14:52:56 2: CUL_HM set KUE_Sonos_Strom off
2014.02.16 16:19:45 1: HMLAN_Parse: HMLAN1 new condition timeout
2014.02.16 16:19:45 1: 192.168.3.11:1000 disconnected, waiting to reappear
2014.02.16 16:19:45 1: HMLAN_Parse: HMLAN1 new condition disconnected
2014.02.16 16:53:06 1: 192.168.3.11:1000 reappeared (HMLAN1)
2014.02.16 16:53:06 1: HMLAN_Parse: HMLAN1 new condition init
2014.02.16 19:07:40 1: HMLAN_Parse: HMLAN1 new condition timeout
2014.02.16 19:07:40 1: 192.168.3.11:1000 disconnected, waiting to reappear
2014.02.16 19:07:40 1: HMLAN_Parse: HMLAN1 new condition disconnected


Seit ca. 16:30 habe ich von extern gemerkt, dass FHEM nicht mehr reagiert. Ich untersuche gerade die Netzwerkverbindung zwischen HMLAN und FHEM.
Ping sieht sehr gut aus:

Code Auswählen Erweitern


64 bytes from 192.168.3.11: icmp_req=1 ttl=128 time=1.30 ms
64 bytes from 192.168.3.11: icmp_req=2 ttl=128 time=0.715 ms
64 bytes from 192.168.3.11: icmp_req=3 ttl=128 time=0.678 ms
64 bytes from 192.168.3.11: icmp_req=4 ttl=128 time=0.737 ms
64 bytes from 192.168.3.11: icmp_req=5 ttl=128 time=0.741 ms
64 bytes from 192.168.3.11: icmp_req=6 ttl=128 time=0.686 ms
64 bytes from 192.168.3.11: icmp_req=7 ttl=128 time=0.704 ms
64 bytes from 192.168.3.11: icmp_req=8 ttl=128 time=0.687 ms
64 bytes from 192.168.3.11: icmp_req=9 ttl=128 time=0.650 ms
64 bytes from 192.168.3.11: icmp_req=10 ttl=128 time=0.771 ms
64 bytes from 192.168.3.11: icmp_req=11 ttl=128 time=0.739 ms
64 bytes from 192.168.3.11: icmp_req=12 ttl=128 time=0.709 ms
64 bytes from 192.168.3.11: icmp_req=13 ttl=128 time=0.708 ms
64 bytes from 192.168.3.11: icmp_req=14 ttl=128 time=0.766 ms


Hast Du eine Idee wie es sein kann, dass FHEM hängt, jedoch die Meldungen bzgl. HMLAN ins Log kommen?

Vielen Dank & Grüße,
Merhan

[martinp876]

schwer zu sagen. Evtl ist das port blockiert...
ist eher eine Frage ain Rudi...
Gruss Martin

[herman]

welchen Port meinst Du?

[der-Lolo]

Ich habe ähnliche Probleme und vermute mittlerweile das sie entstehen wenn mehrere Geräte gleichzeitig über Ethernet gepollt werden MAXLAN, HMLAN, HUE, SONOS...
Deswegen steige ich auch aktuell um auf den USB Adapter - bin aber noch nicht ganz fertig...

[herman]

Sehr interessant. Ein Bekannter von mir hat FHEM, SONOS und MAXLAN am laufen und hat von Problemen mit dem Sonos-Modul berichtet, wenn er das Pollintervall von MAXLAN auf 30sek stellt. Bei 180sek hat er wohl keine Probleme.

@Martin: Was bedeutet der neue Wert im HMLAN msgKeepAlive dlyMax:1.308 bufferMin:3

Ich habe wdTimer auf 15sek gestellt. Könnte das etwas bringen oder verursacht mehr Probleme, weil öfter mit dem HLAN kommuniziert wird?

Grüße,
Merhan

[martinp876]

Was bedeutet der neue Wert im HMLAN msgKeepAlive dlyMax:1.308 bufferMin:3

neu? lange kein update gemacht?
die keepAlive message wird alle 25 sec gesendet. der maximale Dealy ist 1,3sec gewesen, also 26,3sec. Nach 30sec gibt es eine reboot. du hast einen Puffer von 3sec da hin.

[herman]

Sorry - meinte "mir neu aufgefallen"

Ich habe das Attribut wdTimer auf 15sek gestellet und beobachte weiter. Ich hoffe, dass bei parallel Zugriff auf die Ethernetschnittstelle nun mehr Zeit zur Verfügung steht.

[martinp876]

ich wiederhole mich: wenn dein System es nicht schafft, eine ethernet-message in 1sec zu senden und einen Antwort zu verarbeiten hast du zumindest ein leichtes Problem. Wenn sie es nach 2sec nicht schafft solltest du etwas unternehmen.
Dies ist ein timer.. leicht unterschiedlich zu sonstigen Responszeiten, bei denen wir von 50ms reden. 
Ich wuerde zumindest prufen - da klemmt etwas, das man zumindest verstehen sollte