ReadyFn wird ständig mehrmals pro Sekunde aufgerufen?

vbs · 31 März 2017, 20:50:19

Ich habe gerade durch Zufall festgestellt, dass die ReadyFn-Funktion im KODI-Modul (welches ich momentan betreue) permanent mehrmals pro Sekunde aufgerufen wird, solange das Modul keine Verbindung aufgebaut hat:

Code Auswählen

2017.03.31 20:32:08.415 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:08.762 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:08.775 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:08.780 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:08.780 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:08.801 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.001 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.008 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.066 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.089 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.091 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.092 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.152 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.232 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.297 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.362 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.472 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.791 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.792 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:09.793 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:10.001 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:10.298 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:11.001 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:11.368 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:11.449 3: READYFN: sz_kodi.192.168.2.24:9090
2017.03.31 20:32:11.474 3: READYFN: sz_kodi.192.168.2.24:9090

Das ist doch aber so nicht gedacht, oder? Ich hab jetzt schon recht viel Wiki und Forum gelesen und bin mehrfach darauf gestoßen, dass ReadyFn nur alle 5 Sekunden aufgerufen werden sollte. In meinem Fall wie gesagt sehr viel häufiger.

Was mache ich da falsch? Ich glaube zu verstehen, warum das ReadyFn so oft aufgerufen wird (Modul trägt sich in readyfnlist ein, welche dann von fhem.pl ständig durchlaufen wird). Aber ich kann einfach nichts finden, was dazu führen würde, dass ReadyFn nur alle 5 Sekunden aufgerufen werden würde. $:-\$

Hat da jemand einen Tipp bitte? Danke!

EDIT:
Achso: das Modul verwendet DevIO um eine TCP-Verbindung aufzubauen bzw. wieder aufzubauen.

vbs · 31 März 2017, 22:29:15

Hm, habe das jetzt mal mit dem Verhalten vom Modul HMLAN verglichen: das ist da genauso.

Hab einfach mal ein Device angelegt:

Code Auswählen

define fadf HMLAN 192.168.2.232:54000

Da fällt zum einen auf, dass beim Define schon versucht wird, die Verbindung aufzubauen. Das passiert offenbar blockierend in DevIO_Open (3 Sekunden Timeout):

Code Auswählen

name             function    max  count    total  average maxDly 
              WEB_192.168.2.21_50160              FW_Read   3027      7     3035   433.57      0 HASH(WEB_192.168.2.21_50160) 
                                fadf         HMLAN_Define   3011      1     3011  3011.00      0 HASH(fadf); fadf HMLAN 192.168.2.232:54000

Und danach ist das genau wie bei KODI: es wird dann fortwährend mehrfach pro Sekunde Ready aufgerufen:

Code Auswählen

2017.03.31 22:25:25.108 1: HMLAN_Ready
2017.03.31 22:25:25.222 1: HMLAN_Ready
2017.03.31 22:25:25.299 1: HMLAN_Ready
2017.03.31 22:25:25.299 1: HMLAN_Ready
2017.03.31 22:25:25.318 1: HMLAN_Ready
2017.03.31 22:25:25.512 1: HMLAN_Ready
2017.03.31 22:25:25.522 1: HMLAN_Ready
2017.03.31 22:25:25.664 1: HMLAN_Ready
2017.03.31 22:25:25.744 1: HMLAN_Ready
2017.03.31 22:25:26.000 1: HMLAN_Ready
2017.03.31 22:25:27.000 1: HMLAN_Ready
2017.03.31 22:25:27.154 1: HMLAN_Ready
2017.03.31 22:25:27.159 1: HMLAN_Ready
2017.03.31 22:25:27.160 1: HMLAN_Ready
2017.03.31 22:25:27.168 1: HMLAN_Ready
2017.03.31 22:25:27.231 1: HMLAN_Ready
2017.03.31 22:25:27.231 1: HMLAN_Ready
2017.03.31 22:25:27.235 1: HMLAN_Ready

Offenbar mache ich also zumindest nix falsch bei KODI. Ist das wirklich das gewünschte Verhalten oder hat sich da auf fhem-Seite ein Bug eingeschlichen?

Ralf9 · 31 März 2017, 23:07:59

ZitatDa fällt zum einen auf, dass beim Define schon versucht wird, die Verbindung aufzubauen. Das passiert offenbar blockierend in DevIO_Open (3 Sekunden Timeout):

Wenn ich das richtig sehe, verwendest Du noch den blockierenden connect.

Der nicht blockierende sieht so aus:

Code Auswählen

$ret = DevIo_OpenDev($hash, 0, "SIGNALduino_DoInit", 'SIGNALduino_Connect');

Du kannst Dir auch mal den SIGNALduino anschauen, den haben ich und Sidey inzwischen komplett auf nicht blockierend umgestellt.
https://github.com/RFD-FHEM/RFFHEM/blob/dev-r33/FHEM/00_SIGNALduino.pm

Gruß Ralf

vbs · 31 März 2017, 23:13:17

Oh mann, danke!!! Das hilft schonmal sehr! Ich habs bestimmt 3 mal gelesen und immer den dritten Parameter für "Callback" gehalten... :/ Tomaten auf den Augen...

Und ist das bei dir auch so, dass er permanent mehrmals pro Sekunde die Ready-Funktion aufruft, wenn die Verbindung nicht besteht?

Ralf9 · 31 März 2017, 23:22:25

ZitatUnd ist das bei dir auch so, dass er permanent mehrmals pro Sekunde die Ready-Funktion aufruft, wenn die Verbindung nicht besteht?

Ja, dies ist bei mir genauso, dies ist anscheinend normal.

vbs · 01 April 2017, 01:16:00

Danke dir, funktioniert jetzt nicht-blockierend! Nur diese vielen readyfn-Aufrufe sind mir irgendwie noch ein Dorn im Auge... kann mir nicht vorstellen, dass das sinnvoll bzw. so gedacht ist.

rudolfkoenig · 01 April 2017, 11:25:12

ReadyFn hat eine Doppelfunktion: es soll bei Nicht-Vorhandensein von einem USB-Geraet oder einer nicht erreichbaren TCP-IP Verbindung pruefen, ob es wieder da ist. Unter Windows wird es _zusaetzlich_ auch fuer die "seriell" angeschlossenen (also USB) Geraete verwendet, da diese in select nicht pruefbar sind. MS hat den TCP-Stack (und die select Funktion) von Berkeley geklaut, und war zu faul es "ordentlich" einzubauen. Damit funktioniert select unter Windows nur fuer Geraete, die per Netzwerk angebunden sind.

ReadyFn wird deswegen unter Windows spaetestens alle 0.1s aufgerufen, unter Linux/Unix/OSX alle 5 Sekunden. Wenn dazwischen was anderes passiert (Timeout/User-Interaktion/Input von einer anderen Schnittstelle), dann wird sie auch aufgerufen. Aber wie gesagt, nur fuer nicht erreichbare Geraete/Verbindungen (oder USB@Windows). Im Normalzustand auf einem Linux/UNIX/OSX Rechner wird ReadyFn gar nicht aufgerufen.

vbs · 03 April 2017, 18:20:34

Zitat von: rudolfkoenig am 01 April 2017, 11:25:12
Im Normalzustand auf einem Linux/UNIX/OSX Rechner wird ReadyFn gar nicht aufgerufen.

Normalzustand bedeutet, dass alle Gegenstellen erreichbar sind, oder? Also ein Kodi (MediaCenter) ist bei Nichtbenutzung normalerweise ausgeschaltet. Daher würde ich es da eher als normal ansehen wollen, dass die Gegenstelle _nicht_ erreichbar ist.

Zitat von: rudolfkoenig am 01 April 2017, 11:25:12
ReadyFn wird deswegen unter Windows spaetestens alle 0.1s aufgerufen, unter Linux/Unix/OSX alle 5 Sekunden.

Genau, hatte ich auch so aus Forum/Wiki rausgelesen. Darum war es für mich nicht erklärbar, dass bei meinen Tests (sowohl mit Kodi als auch mit zB HMLAN), die ReadyFn-Funktion permanent mehrmals pro Sekunde aufgerufen wurde:

Code Auswählen

2017.03.31 22:25:25.108 1: HMLAN_Ready
2017.03.31 22:25:25.222 1: HMLAN_Ready
2017.03.31 22:25:25.299 1: HMLAN_Ready
2017.03.31 22:25:25.299 1: HMLAN_Ready
2017.03.31 22:25:25.318 1: HMLAN_Ready
2017.03.31 22:25:25.512 1: HMLAN_Ready
2017.03.31 22:25:25.522 1: HMLAN_Ready
2017.03.31 22:25:25.664 1: HMLAN_Ready
2017.03.31 22:25:25.744 1: HMLAN_Ready
2017.03.31 22:25:26.000 1: HMLAN_Ready
2017.03.31 22:25:27.000 1: HMLAN_Ready
2017.03.31 22:25:27.154 1: HMLAN_Ready
2017.03.31 22:25:27.159 1: HMLAN_Ready
2017.03.31 22:25:27.160 1: HMLAN_Ready
2017.03.31 22:25:27.168 1: HMLAN_Ready
2017.03.31 22:25:27.231 1: HMLAN_Ready
2017.03.31 22:25:27.231 1: HMLAN_Ready
2017.03.31 22:25:27.235 1: HMLAN_Ready

Ist das wirklich so gewollt? Hatte dich jetzt auch so verstanden, dass es eher die Ausnahme sein sollte, dass es öfter als 5 Sekunden aufgerufen wird.

rudolfkoenig · 03 April 2017, 18:58:26

ZitatDaher würde ich es da eher als normal ansehen wollen, dass die Gegenstelle _nicht_ erreichbar ist.

Darueber kann man diskutieren, ich persoenlich finde das Pollen von nicht-erreichbaren Geraeten ein Unding und nicht normal.

ZitatIst das wirklich so gewollt?

Ich weiss zwar immer noch nicht, ob es sich um ein Windows System handelt, ich tippe auf nein. Damit bleibt ein Programmierfehler irgendwo, oder (meine Theorie), irgendetwas anderes, was haeufig den Select-Loop aufweckt, wie ein Geraet, was staendig was erzaehlt, oder Netzwerkaktivitaet. DevIo_OpenDev hat dagegen schon eine Vorkehrung mit eigenen Zeitstempel, siehe Code um #53309 in DevIo.pm.

vbs · 03 April 2017, 19:31:54

Zitat von: rudolfkoenig am 03 April 2017, 18:58:26
Ich weiss zwar immer noch nicht, ob es sich um ein Windows System handelt, ich tippe auf nein. Damit bleibt ein Programmierfehler irgendwo, oder (meine Theorie), irgendetwas anderes, was haeufig den Select-Loop aufweckt, wie ein Geraet, was staendig was erzaehlt, oder Netzwerkaktivitaet. DevIo_OpenDev hat dagegen schon eine Vorkehrung mit eigenen Zeitstempel, siehe Code um #53309 in DevIo.pm.

Richtig, sorry, hätte ich schreiben sollen: Handelt sich um ein Ubuntu 16.10 x64 als VM innerhalb eines Win10-Systems.

Da ich das Verhalten jetzt bei drei von drei Modulen festgestellt habe (Kodi, HMLAN und auch SIGNALduino wie Ralf9 oben bestätigt hat), halte ich auch deine Theorie, dass irgendwas das select ständig vom Schlafen abhält, für sehr plausibel. Netzwerkverkehr... hm... ich kann mir gut vorstellen, dass ich sicherlich ständig was habe... muss ich mal näher unter die Lupe nehmen.
Danke dir erstmal!