HMCCURPC: Multithreaded RPC Server für HMCCU

[zap]

Ich habe gerade ein neues Client Modul für HMCCU eingecheckt (zusammen mit einer neuen Version von HMCCU). Das Modul HMCCURPC stellt einen neuen, Thread basierten RPC-Server für HMCCU zur Verfügung. Die Vorteile:

• Keine Filequeues mehr, dadurch Schonung der SD Karte
• Schnellere Reaktion auf CCU Events durch Verwendung des Standard FHEM I/O Mechanismus. Die Timer basierte Abfrage von CCU Events (konfiguriert über rpcinterval) und die damit einhergehende Verzögerung bei der Reaktion auf Events von einigen Sekunden entfällt.

HINWEIS: DAS MODUL IST NOCH IM BETA STATUS. BENUTZUNG AUF EIGENE GEFAHR! Allerdings läuft es bei mir schon recht stabil.

Das Modul benötigt folgende Perl-Module:

• threads
• Thread::Queue
• Time::HiRes

Zur Verwendung gibt es 2 Möglichkeiten (nach FHEM Update und Neustart):

1. Über das I/O Device (empfohlene Vorgehensweise, Annahme I/O bzw. HMCCU Device = d_ccu). Dabei wird automatisch ein Device mit dem Namen "d_ccu_rpc" vom Typ HMCCURPC angelegt. Dieses Device erbt die Attribute room und group vom I/O Device.

Code Auswählen Erweitern


set d_ccu rpcserver off
attr d_ccu ccuflags extrpc
set d_ccu rpcserver on


2. Über ein manuell definiertes RPC-Device (Annahme I/O Device = d_ccu):

Code Auswählen Erweitern


define d_ccu_rpc HMCCURPC my_ccu_ip_or_name iodev=d_ccu
set d_ccu rpcserver off
attr d_ccu ccuflags extrpc
set d_ccu rpcserver on


Grundsätzlich lässt sich der RPC-Server auch über das HMCCURPC Device starten. Davon rate ich jedoch ab.

Um zum alten integrierten RPC-Server zurückzukehren:

Code Auswählen Erweitern


set d_ccu rpcserver off
attr ccuflags intrpc
set d_ccu rpcserver on


Also: wer möchte bitte mal testen. Wenn das stabil läuft, wird das mittelfristig das Filequeue Verfahren ersetzen.

P.S. Musste einen Trick verwenden, um dem FHEM I/O Prozess die Shared Memory Queue unter zu jubeln, da Threads in FHEM nicht so gern gesehen sind. Optimal wäre, wenn man im I/O Loop von FHEM neben File Descriptoren auch Shared Memory Queues angeben könnte, also statt $hash->{FD} = Descriptor z.B. ein $hash->{TQ} = ThreadQueue. Nur mal so als Denkanstoss

[Raymund]

Teste gerade: läuft. Aber ein rereadcfg führt reproduzierbar zur Endlosschleife mit folgendem Logeintrag:

Code Auswählen Erweitern

2017.03.23 19:25:52 2: CCURPC: I/O error during data processing (select found no reader)

Gruß
Raymund

[zap]

Ist nicht unbedingt eine Endlosschleife. Die Meldung kommt, wenn FHEM beschäftigt ist und keine I/O Operationen ausführen kann. Ich habe gerade ein Update eingecheckt, bei dem die Zahl der Meldungen deutlich reduziert ist. Ggf. werde ich es ganz abschalten, da es eigentlich kein Fehler ist.

Wenn Du Lust hast, kannst Du nach einem rereadcfg einfach mal eine Zeit lang warten ob die Meldungen von alleine aufhören.

UPDATE: Habe rereadconfig noch nie benutzt aber jetzt mal die Commandref gelesen. Übel. Da werden alle Devices gelöscht. Das ist nicht so gut für den laufenden RPC-Server. Ich würde davon abraten, diesen Befehl bei laufendem RPC-Server zu verwenden.

[Raymund]

Läuft jetzt mit der 'alten' Version seit ca. 10 Minuten in der Schleife.

Gruß
Raymund

[zap]

Das fängt sich nicht mehr. Das Problem ist: bei rereadcfg werden die Devices gelöscht. Die RPC Server Threads überstehen das Löschen und versuchen weiterhin, Daten an das HMCCURPC Device zu schicken, das aber nicht mehr existiert. Das funktioniert natürlich nicht und produziert die Fehlermeldung.

Daher: erst RPC Server stoppen. Dann rereadcfg. Ich will aber nicht ausschließen, dass das noch andere Nbeneffekte hat, sogar beim alten RPC Server.

Wozu braucht man eigentlich rereadcfg?

[Raymund]

na, wenn man z.B. die fhem.cfg manuell geändert hat ... mache ich eher selten. War Zufall 😉

Update: ich lese gerade, dass es einen Trigger nach rereadcfg gibt. Vielleicht kann man damit etwas machen. Ich bin nach vielen Jahren in der Entwicklung der Meinung, dass der User damit nicht 'belastet' werden sollte. Oder man entfernt rereadcfg ...

[zap]

Ja, den Trigger gibt es. Allerdings erst nach rereadcf, und dann ist es zu spät.

HMCCU versucht zwar den RPC Server zu stoppen, wenn das Device gelöscht wird. Allerdings läuft dieses Stoppen asynchron in eine separaten Thread/Prozess, d.h. das Device Löschen wartet nicht, bis der RPC Server gestoppt ist. Daher das "Chaos".

Ich sehe keine Möglichkeit, da verlässlich einzugreifen.

[Raymund]

Hallo zap,

wollte Dir aber mal sagen, dass Du hier einen tollen Job machst. Und jetzt wird der RPCServer auch noch schnell ... 

Danke und Grüße
Raymund

[Loredo]

Super klasse, danke für diesen wichtigen Schritt! 

Hatte einige Freezes bei dem vorgehen, was du als Möglichkeit 1 beschreibst:

2017.03.25 09:20:44.906 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.03.25 09:20:45.169 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for events for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for new devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for deleted devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for modified devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for replaced devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for readded devices for server CB2010
2017.03.25 09:20:45.169 2: HMCCURPC: Adding callback for list devices for server CB2010
2017.03.25 09:20:45.170 2: CCURPC: CB2010 accepting connections. TID=3
2017.03.25 09:21:19.961 2: HMCCURPC: RPC server thread started for interface VirtualDevices with TID=4
2017.03.25 09:21:19.961 2: CCURPC: Initializing RPC server CB9292 for interface VirtualDevices
2017.03.25 09:21:20.126 2: HMCCURPC: Callback server CB9292 created. Listening on port 14702
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for events for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for new devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for deleted devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for modified devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for replaced devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for readded devices for server CB9292
2017.03.25 09:21:20.126 2: HMCCURPC: Adding callback for list devices for server CB9292
2017.03.25 09:21:20.127 2: CCURPC: CB9292 accepting connections. TID=4
2017.03.25 09:21:20.962 1: HMCCURPC: RPC server(s) starting
2017.03.25 09:21:21.291 1: Perfmon: possible freeze starting at 09:20:03, delay is 78.291
2017.03.25 09:21:31.348 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.03.25 09:21:31.348 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.03.25 09:21:31.349 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2017.03.25 09:21:31.349 1: HMCCURPC: Received SL event. RPC server CB9292 enters server loop
2017.03.25 09:21:31.349 1: HMCCURPC: All threads working
2017.03.25 09:21:31.349 1: HMCCURPC: Registering callback http://192.168.178.2:7411/fh2001 with ID CB2001 at http://192.168.6.31:2001/
2017.03.25 09:21:31.361 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2017.03.25 09:21:31.623 1: HMCCURPC: RPC callback with URL http://192.168.178.2:7411/fh2001 registered
2017.03.25 09:21:31.623 1: HMCCURPC: Registering callback http://192.168.178.2:7420/fh2010 with ID CB2010 at http://192.168.6.31:2010/
2017.03.25 09:21:31.652 1: HMCCURPC: RPC callback with URL http://192.168.178.2:7420/fh2010 registered
2017.03.25 09:21:31.652 1: HMCCURPC: Registering callback http://192.168.178.2:14702/fh9292 with ID CB9292 at http://192.168.6.31:9292/groups
2017.03.25 09:21:32.009 2: CCURPC: CB2001 NewDevice received 156 device specifications
2017.03.25 09:21:32.194 1: CCURPC: CB2010 ListDevices. Sending init to HMCCU
2017.03.25 09:21:32.201 1: CCURPC: CB9292 ListDevices. Sending init to HMCCU
2017.03.25 09:21:32.318 2: CCURPC: CB9292 NewDevice received 9 device specifications
2017.03.25 09:21:41.693 1: HMCCURPC: RPC callback with URL http://192.168.178.2:14702/fh9292 registered
2017.03.25 09:21:41.693 1: HMCCURPC: Received IN event. RPC server CB2001 running.
2017.03.25 09:21:41.698 1: Perfmon: possible freeze starting at 09:21:22, delay is 19.698
2017.03.25 09:21:43.293 1: HMCCURPC: Received IN event. RPC server CB2010 running.
2017.03.25 09:21:43.293 1: HMCCURPC: Received IN event. RPC server CB9292 running.
2017.03.25 09:21:43.293 1: HMCCURPC: All RPC servers running
2017.03.25 09:21:44.173 2: HMCCURPC: Updated devices. Success=24 Failed=0
2017.03.25 09:21:46.272 1: Perfmon: possible freeze starting at 09:21:45, delay is 1.272
2017.03.25 09:21:59.595 1: Perfmon: possible freeze starting at 09:21:57, delay is 2.595
2017.03.25 09:28:58.032 1: Perfmon: possible freeze starting at 09:28:54, delay is 3.788
2017.03.25 09:29:02.283 1: Perfmon: possible freeze starting at 09:28:59, delay is 3.283

[zap]

Habe mich mit Perfmon noch nicht beschäftigt. Heißt das, dass sich FHEM nicht mehr bedienen lässt? Bei mir läuft alles performant.

Kann sein, dass der erste Start etwas holprig ist, weil erst das Device definiert werden muss. Das sollte bei weiteren Starts besser laufen, da es ja gespeichert wird.

Außerdem musst Du bedenken, dass nach dem Start des RPC-Servers alle Datenpunkte von der CCU geholt und aktualisiert werden. Je nach Anzahl Devices kann das auch 1-3 Sekunden dauern.

[Loredo]

Habe mich mit Perfmon noch nicht beschäftigt. Heißt das, dass sich FHEM nicht mehr bedienen lässt?

Ja, 78 Sekunden ging gar nix mehr.

Kann sein, dass der erste Start etwas holprig ist, weil erst das Device definiert werden muss. Das sollte bei weiteren Starts besser laufen, da es ja gespeichert wird.

Der heutige Neustart lief soweit ok ab.
Diese Meldung ist mir aufgefallen:

2017.03.26 11:41:23.932 2: HMCCURPC: Starting thread for data processing
2017.03.26 11:41:24.141 2: HMCCURPC: Started thread for data processing. TID=1
2017.03.26 11:41:24.141 2: CCURPC: Thread DATA processing RPC events. TID=1
2017.03.26 11:41:26.569 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=2
2017.03.26 11:41:26.569 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2017.03.26 11:41:29.015 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2017.03.26 11:41:29.015 2: HMCCURPC: Adding callback for events for server CB2001
2017.03.26 11:41:29.015 2: HMCCURPC: Adding callback for new devices for server CB2001
2017.03.26 11:41:29.015 2: HMCCURPC: Adding callback for deleted devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for modified devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for replaced devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for readded devices for server CB2001
2017.03.26 11:41:29.016 2: HMCCURPC: Adding callback for list devices for server CB2001
2017.03.26 11:41:29.016 2: CCURPC: CB2001 accepting connections. TID=2
2017.03.26 11:41:31.157 2: CCURPC: I/O error during data processing (Select found no reader)
2017.03.26 11:41:37.470 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.03.26 11:41:37.470 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2017.03.26 11:41:37.482 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for events for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for new devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for deleted devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for modified devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for replaced devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for readded devices for server CB2010
2017.03.26 11:41:37.482 2: HMCCURPC: Adding callback for list devices for server CB2010

[zap]

Die Meldung werde ich abschalten. Ursache: Wenn FHEM mit etwas anderem beschäftigt ist und eine Zeit lang keine I/O Operation ausführen kann, schlägt HMCCURPC seitig das Senden der I/O Notification an FHEM fehl.

Das ist jedoch nicht kritisch, da HMCCURPC intern die Daten puffert und es ein paar Millisekunden später einfach noch mal versucht. Kritisch wird es erst, wenn die Meldung "CCURPC: Size of event queue exceeds ..." kommt. Dann ist nämlich die maximale Puffergröße erreicht und es werden CCU Events verworfen. Falls das mal vorkommt, kann man die Größe der Queue mit dem Attribut rpcQueueSize erhöhen.

BTW: Bin selbst von der schnellen Reaktion des Moduls auf CCU Events überrascht. Aktuell gibt es bei mir eine durchschnittliche Verzögerung zwischen Empfang der Daten durch den RPC-Server und Verarbeitung durch FHEM von 0.18 Sekunden. Scheint mir akzeptabel zu sein

[Loredo]

Die Schnelligkeit ist in der Tat nun super! 

[Chris8888]

Hallo Zap,

ich habe heute mal ein Update durchgeführt.
Ebenfalls habe ich die 3 Module per CPAN nachinstalliert und das Attribute für den neuen RPC-Server gesetzt.

So sieht das Startlog aus:

Code Auswählen Erweitern

2017.03.27 18:45:37 2: HMCCURPC: Starting thread for data processing
2017.03.27 18:45:38 2: HMCCURPC: Started thread for data processing. TID=1
2017.03.27 18:45:38 2: CCURPC: Thread DATA processing RPC events. TID=1
2017.03.27 18:45:39 2: HMCCURPC: RPC server thread started for interface BidCos-RF with TID=2
2017.03.27 18:45:39 2: CCURPC: Initializing RPC server CB2001 for interface BidCos-RF
2017.03.27 18:45:39 2: HMCCURPC: Callback server CB2001 created. Listening on port 7411
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for events for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for new devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for deleted devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for modified devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for replaced devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for readded devices for server CB2001
2017.03.27 18:45:39 2: HMCCURPC: Adding callback for list devices for server CB2001
2017.03.27 18:45:39 2: CCURPC: CB2001 accepting connections. TID=2
2017.03.27 18:45:40 2: HMCCURPC: RPC server thread started for interface HmIP-RF with TID=3
2017.03.27 18:45:40 2: CCURPC: Initializing RPC server CB2010 for interface HmIP-RF
2017.03.27 18:45:40 2: HMCCURPC: Callback server CB2010 created. Listening on port 7420
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for events for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for new devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for deleted devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for modified devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for replaced devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for readded devices for server CB2010
2017.03.27 18:45:40 2: HMCCURPC: Adding callback for list devices for server CB2010
2017.03.27 18:45:40 2: CCURPC: CB2010 accepting connections. TID=3
2017.03.27 18:45:41 1: HMCCURPC: RPC server(s) starting
2017.03.27 18:45:41 1: HMCCURPC: Received SL event. RPC server DATA enters server loop
2017.03.27 18:45:41 1: HMCCURPC: Received SL event. RPC server CB2001 enters server loop
2017.03.27 18:45:41 1: HMCCURPC: Received SL event. RPC server CB2010 enters server loop
2017.03.27 18:45:41 1: HMCCURPC: All threads working
2017.03.27 18:45:41 1: HMCCURPC: Registering callback http://192.168.100.35:7411/fh2001 with ID CB2001 at http://192.168.100.65:2001/
2017.03.27 18:45:41 1: CCURPC: CB2001 ListDevices. Sending init to HMCCU
2017.03.27 18:45:42 1: HMCCURPC: RPC callback with URL http://192.168.100.35:7411/fh2001 registered
2017.03.27 18:45:42 1: HMCCURPC: Registering callback http://192.168.100.35:7420/fh2010 with ID CB2010 at http://192.168.100.65:2010/
2017.03.27 18:45:42 1: HMCCURPC: RPC callback with URL http://192.168.100.35:7420/fh2010 registered
2017.03.27 18:45:42 1: HMCCURPC: Received IN event. RPC server CB2001 running.
2017.03.27 18:45:42 1: CCURPC: CB2010 ListDevices. Sending init to HMCCU
2017.03.27 18:45:42 2: CCURPC: CB2001 NewDevice received 52 device specifications
2017.03.27 18:45:43 2: CCURPC: CB2010 NewDevice received 93 device specifications
2017.03.27 18:45:45 1: HMCCURPC: Received IN event. RPC server CB2010 running.
2017.03.27 18:45:45 1: HMCCURPC: All RPC servers running
2017.03.27 18:45:46 2: HMCCURPC: Updated devices. Success=11 Failed=0

Soweit sieht es erst einmal gut aus.

Das Device "HMCCURPC" ist running/ok, aber der HMCCU ist immer running/busy.
Ist das richtig so?

Auch bekomme ich bei einigen HmIP-Kommandos folgende Fehlermeldung: zB
2017.03.27 19:03:43 1: HMCCUDEV: HM_Thermostat_Wohnzimmer Execution of CCU script or command failed

Die CCU2 habe ich heute ebenfalls auf 2.27.8 upgedatet (ganz frisch draussen).

Viele Grüße
Christian

[zap]

Dass das I/O Device auf "running/busy" stehen bleibt, ist leider noch ein (kosmetischer) Fehler.
Wenn die Readings der einzelnen Devices automatisch aktualisiert werden ist alles OK. Das Log sieht jedenfalls gut aus.

Für das Device mit der Fehlermeldung kannst Du vielleicht mal ccuflags auf trace setzen. Dann gibt es mehr Infos im Log.