Notify reragiert langsam

[scuba]

Hallo,

Ich möchte mit einem zentralen IT Schalter mehrere IT Steckdosen über FHEM gleichzeitig schalten. (Zentral EIN/AUS Funktion)

Ich hab mir hierzu folgendes notify angelegt:

Code Auswählen Erweitern

Hauptschalter_L set Steckdose_Kinderzimmer_PC $EVENT;set Steckdose_unbenutzt $EVENT;set Steckdose_Wohnzimmer_TV $EVENT

Das Funktioniert auch wie erwartet, allerdings hab ich bemerkt, dass das "Notify" ein ziemlich großes Delay (~ 1,6 Sekunden) auslöst.
Sowohl der Status des Schalters direkt, als auch der Schaltbefehl an die Aktoren wird erst nach dem Delay angezeigt/ausgelöst.

auch in apptime ist das ebenfalls schön ersichtlich.
Ohne Notify verbrät die "Cul_Read" Funktion max. 39ms -> Status des Schalters wird somit auch sofort aktualisiert
Mit Notify wartet "Cul_Read" anscheinend auf "notify_Exec" und braucht somit ~1700ms (avg ist deshalb so niedrig da in der gezeigten Ansicht nur ein Event mit notify ausgelöst wurde)

Natürlich sprechen wir hier von keinen extrem großen Delays allerdings ist die User Experience doch erheblich beeinträchtigt bzw. verleitet das Verhalten zu einem erneuten Tastendruck wenn nicht sofort eine Reaktion erfolgt.

Wie sieht da bei euch aus? Könnt Ihr das Verhalten bestätigen bzw. mach ich eventuell was falsch?
FHEM läuft übrigens auf einem Raspi2.

lg Christian

[scuba]

Nachtrag: Anscheinend wird das Notify mit jedem Gerät, das zum notify hinzugefügt wird langsamer.
Mit nur einer Steckdose funktionierts noch relativ schnell, mit 3 Geräten sind wir bei den besagten 1,7s.

Hab den Test jetzt auch in Kombination mit nicht IT Geräten durchgeführt und meine Somfy Jalousien miteingebunden. auch hier mit dem selben Ergebnis.

[rudolfkoenig]

Um mehr dazu zu sagen, brauche ich ein Mitschnitt der Logfile mit "attr global verbose 5" und "attr global mseclog".

[scuba]

Danke für deine Schnelle Antwort und Hilfe zur Selbsthilfe

Soweit ich das jetzt sehe, ist nicht wirklich das Notify schuld an dem Delay sondern bereits das Versenden der Befehle an die einzelnen Aktoren dauert jeweils ca. 500 - 600 ms. Mit 3 Devices bin ich somit in Summe auf ca. 1500 - 1800 ms.
Da der "Notify Thread" anscheinend auf die Abarbeitung der einzelnen "set" Befehle wartet wird das Event erst danach abgeschlossen und die Webseite refresht sich somit auch erst danach.
Subjektiv hab ich das Gefühl, dass die Aktoren trotzdem erst nach ~1,5s schalten, das kann aber natürlich sein, dass sie nach Erhalt der Datenpakete auch noch etwas "Bedenkzeit" benötigen.

Frage 1: Seht ihr das Auch so? bzw. habt ihr ähnlich "lange" Versandzeiten? (setzte einen NanoCul ein)
Frage 2: Eine Lösung wäre ein zentrales IT Device anzulegen und alle Devices daran zu binden. Somit wär die Latency bei ~500ms


Anbei der Logauszug

Code Auswählen Erweitern

2016.01.15 11:03:48.364 4: WEB_192.168.77.142_41014 POST /fhem?cmd.Hauptschalter_L=set%20Hauptschalter_L%20off&room=IT&XHR=1&fw_id=190; BUFLEN:0
2016.01.15 11:03:48.367 5: Cmd: >set Hauptschalter_L off<
2016.01.15 11:03:48.369 2: IT set Hauptschalter_L off
2016.01.15 11:03:48.371 5: SW: is00111101111010100000000000000001
2016.01.15 11:03:48.879 5: CUL/RAW (ReadAnswer): is001111011110101000000000000000
2016.01.15 11:03:48.884 5: CUL/RAW (ReadAnswer): 01

2016.01.15 11:03:48.887 4: Answer from nanoCul_433:   raw => is00111101111010100000000000000001
2016.01.15 11:03:48.889 5: Triggering Hauptschalter_L (1 changes)
2016.01.15 11:03:48.890 5: Notify loop for Hauptschalter_L off
2016.01.15 11:03:48.896 5: Notify from Device: Hauptschalter_L recieved
2016.01.15 11:03:48.900 5: DbLog: logging of Device: Hauptschalter_L , Type: IT , Event: off , Reading: state , Value: off , Unit:
2016.01.15 11:03:48.918 5: Triggering n_HS_L
2016.01.15 11:03:48.920 4: n_HS_L exec set Steckdose_Kinderzimmer_PC $EVENT;set Steckdose_unbenutzt $EVENT;set Steckdose_Wohnzimmer_TV $EVENT
2016.01.15 11:03:48.922 5: Cmd: >set Steckdose_Kinderzimmer_PC $EVENT<
2016.01.15 11:03:48.924 2: IT set Steckdose_Kinderzimmer_PC off
2016.01.15 11:03:48.926 5: SW: is11111100110101010110011101000001
2016.01.15 11:03:49.435 5: CUL/RAW (ReadAnswer): is111111001101010101100111010000
2016.01.15 11:03:49.440 5: CUL/RAW (ReadAnswer): 01

2016.01.15 11:03:49.442 4: Answer from nanoCul_433:   raw => is11111100110101010110011101000001
2016.01.15 11:03:49.444 5: Triggering Steckdose_Kinderzimmer_PC (1 changes)
2016.01.15 11:03:49.445 5: Notify loop for Steckdose_Kinderzimmer_PC off
2016.01.15 11:03:49.448 5: Notify from Device: Steckdose_Kinderzimmer_PC recieved
2016.01.15 11:03:49.451 5: DbLog: logging of Device: Steckdose_Kinderzimmer_PC , Type: IT , Event: off , Reading: state , Value: off , Unit:
2016.01.15 11:03:49.475 5: Cmd: >set Steckdose_unbenutzt $EVENT<
2016.01.15 11:03:49.477 2: IT set Steckdose_unbenutzt off
2016.01.15 11:03:49.478 5: SW: is11111100110101010110001101000011
2016.01.15 11:03:49.985 5: CUL/RAW (ReadAnswer): is111111001101010101100011010000
2016.01.15 11:03:49.990 5: CUL/RAW (ReadAnswer): 11

2016.01.15 11:03:49.992 4: Answer from nanoCul_433:   raw => is11111100110101010110001101000011
2016.01.15 11:03:49.994 5: Triggering Steckdose_unbenutzt (1 changes)
2016.01.15 11:03:49.995 5: Notify loop for Steckdose_unbenutzt off
2016.01.15 11:03:50.000 5: Notify from Device: Steckdose_unbenutzt recieved
2016.01.15 11:03:50.003 5: DbLog: logging of Device: Steckdose_unbenutzt , Type: IT , Event: off , Reading: state , Value: off , Unit:
2016.01.15 11:03:50.025 5: Cmd: >set Steckdose_Wohnzimmer_TV $EVENT<
2016.01.15 11:03:50.027 2: IT set Steckdose_Wohnzimmer_TV off
2016.01.15 11:03:50.027 5: SW: is11111100110101010110011100000000
2016.01.15 11:03:50.535 5: CUL/RAW (ReadAnswer): is111111001101010101100111000000
2016.01.15 11:03:50.540 5: CUL/RAW (ReadAnswer): 00

2016.01.15 11:03:50.543 4: Answer from nanoCul_433:   raw => is11111100110101010110011100000000
2016.01.15 11:03:50.545 5: Triggering Steckdose_Wohnzimmer_TV (1 changes)
2016.01.15 11:03:50.546 5: Notify loop for Steckdose_Wohnzimmer_TV off
2016.01.15 11:03:50.551 5: Notify from Device: Steckdose_Wohnzimmer_TV recieved
2016.01.15 11:03:50.554 5: DbLog: logging of Device: Steckdose_Wohnzimmer_TV , Type: IT , Event: off , Reading: state , Value: off , Unit:
2016.01.15 11:03:50.588 4: name: /fhem?cmd.Hauptschalter_L=set%20Hauptschalter_L%20off&room=IT&XHR=1&fw_id=190 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2016.01.15 11:03:50.590 1: Perfmon: possible freeze starting at 11:03:49, delay is 1.589
2016.01.15 11:03:50.641 4: WEB_192.168.77.142_41014 GET /fhem/images/default/off.png; BUFLEN:0
2016.01.15 11:03:50.642 4: WEB_192.168.77.142_41014 => 304 Not Modified


[rudolfkoenig]

Ich kenne IT nicht wirklich, ich sehe nur, dass das Modul nicht nur "blind" sendet, sondern auch auf eine Antwort wartet. Ob die vom culfw direkt kommt, oder vom IT-Geraet, das weiss ich nicht.

[scuba]

Kurzer Update zu dem alten Thema.

Hab den Schuldigen nun dingfest gemacht. Grundsätzlich war mein Raspberry einfach überlastet (Load ~ 3). Schuld daran war die mysql DB. Obs nun an defekten Indizes oder generell an mysql gelegen ist hab ich jetzt nicht weiter beobachtet. Bin nun seit 1 1/2 Montaen auf sqlite umgestiegen und die Perfermormance passt seither wieder.