FB7270v2: set auf Arrays dauert 6 Sekunden

[OiledAmoeba]

Moin,

seit einiger Zeit habe ich das Phänomen, dass wenn ein Array per set angesprochen wird, die Befehle jeweils mit ziemlich genau 6 Sekunden abgesetzt werden und zudem fhem während der kompletten Zeit, die die Abarbeitung benötigt, blockiert ist.

In telnet sieht das so aus:

fhem> set TYPE=FHT report2 7
2013-05-09 21:41:04 FHT fht.Bad report2 7
2013-05-09 21:41:10 FHT fht.Kueche report2 7
2013-05-09 21:41:16 FHT fht.Nobody report2 7
2013-05-09 21:41:23 FHT fht.Schlafen report2 7
2013-05-09 21:41:29 FHT fht.Stube report2 7

Jemand eine Idee?

[rudolfkoenig]

Bitte das Gleiche mit "attr global verbose 5" nochmal durchfuehren. Ich vermute irgendwelche Notifys als Ursache, oder ein DbLog-Problem.

[OiledAmoeba]

Hm, Schuld zu sein scheint der fhtsoftbuf 1.
Ohne Softpuffer:

2013.05.10 12:45:45 5: Cmd: >set TYPE=FHT report2 7<
2013.05.10 12:45:45 5: Sending 8109047c02018350396607
2013.05.10 12:45:45 2: FHT set fht.Bad report2 7
2013.05.10 12:45:45 5: Triggering fht.Bad (1 changes)
2013.05.10 12:45:46 5: Notify loop for fht.Bad report2 7
2013.05.10 12:45:46 5: Sending 8109046b0201832c4c6607
2013.05.10 12:45:46 2: FHT set fht.Kueche report2 7
2013.05.10 12:45:46 5: Triggering fht.Kueche (1 changes)
2013.05.10 12:45:46 5: Notify loop for fht.Kueche report2 7
2013.05.10 12:45:46 5: Sending 8109047102018345396607
2013.05.10 12:45:46 2: FHT set fht.Nobody report2 7
2013.05.10 12:45:46 5: Triggering fht.Nobody (1 changes)
2013.05.10 12:45:46 5: Notify loop for fht.Nobody report2 7
2013.05.10 12:45:46 5: Sending 8109046902018341356607
2013.05.10 12:45:46 2: FHT set fht.Schlafen report2 7
2013.05.10 12:45:46 5: Triggering fht.Schlafen (1 changes)
2013.05.10 12:45:46 5: Notify loop for fht.Schlafen report2 7
2013.05.10 12:45:46 5: Sending 8109044c02018313466607
2013.05.10 12:45:46 2: FHT set fht.Stube report2 7
2013.05.10 12:45:46 5: Triggering fht.Stube (1 changes)
2013.05.10 12:45:46 5: Notify loop for fht.Stube report2 7
2013.05.10 12:45:54 5: Cmd: >attr global verbose 3<

Mit Softpuffer:

2013.05.10 13:16:46 5: Cmd: >set TYPE=FHT report2 7<
2013.05.10 13:16:46 5: Sending 8105044fc90185
2013.05.10 13:16:47 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:47 5: getFhtBuffer: 0 Timeout reading answer for get fhtbuf
2013.05.10 13:16:47 5: Sending 8105044fc90185
2013.05.10 13:16:48 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:48 5: getFhtBuffer: 1 Timeout reading answer for get fhtbuf
2013.05.10 13:16:48 5: Sending 8105044fc90185
2013.05.10 13:16:48 4: FHZ/RAW: 8107c9a6010285011d
2013.05.10 13:16:48 5: GET Got: 8107c9a6010285011d
2013.05.10 13:16:48 5: getFhtBuffer: 2   fhtbuf => 1d
2013.05.10 13:16:48 5: Sending 8109047c02018350396607
2013.05.10 13:16:48 2: FHT set fht.Bad report2 7
2013.05.10 13:16:48 5: Triggering fht.Bad (1 changes)
2013.05.10 13:16:48 5: Notify loop for fht.Bad report2 7
2013.05.10 13:16:48 5: Sending 8105044fc90185
2013.05.10 13:16:49 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:49 5: getFhtBuffer: 0 Timeout reading answer for get fhtbuf
2013.05.10 13:16:49 5: Sending 8105044fc90185
2013.05.10 13:16:50 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:50 5: getFhtBuffer: 1 Timeout reading answer for get fhtbuf
2013.05.10 13:16:50 5: Sending 8105044fc90185
2013.05.10 13:16:51 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:51 5: getFhtBuffer: 2 Timeout reading answer for get fhtbuf
2013.05.10 13:16:51 5: Sending 8105044fc90185
2013.05.10 13:16:52 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:52 5: getFhtBuffer: 3 Timeout reading answer for get fhtbuf
2013.05.10 13:16:52 5: Sending 8105044fc90185
2013.05.10 13:16:53 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:53 5: getFhtBuffer: 4 Timeout reading answer for get fhtbuf
2013.05.10 13:16:53 5: Sending 8105044fc90185
2013.05.10 13:16:54 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:54 5: getFhtBuffer: 5 Timeout reading answer for get fhtbuf
2013.05.10 13:16:54 5: Triggering fht.Kueche (1 changes)
2013.05.10 13:16:54 5: Notify loop for fht.Kueche report2 7
2013.05.10 13:16:55 5: Sending 8105044fc90185
2013.05.10 13:16:56 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:56 5: getFhtBuffer: 0 Timeout reading answer for get fhtbuf
2013.05.10 13:16:56 5: Sending 8105044fc90185
2013.05.10 13:16:57 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:57 5: getFhtBuffer: 1 Timeout reading answer for get fhtbuf
2013.05.10 13:16:57 5: Sending 8105044fc90185
2013.05.10 13:16:58 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:58 5: getFhtBuffer: 2 Timeout reading answer for get fhtbuf
2013.05.10 13:16:58 5: Sending 8105044fc90185
2013.05.10 13:16:59 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:16:59 5: getFhtBuffer: 3 Timeout reading answer for get fhtbuf
2013.05.10 13:16:59 5: Sending 8105044fc90185
2013.05.10 13:17:00 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:00 5: getFhtBuffer: 4 Timeout reading answer for get fhtbuf
2013.05.10 13:17:00 5: Sending 8105044fc90185
2013.05.10 13:17:01 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:01 5: getFhtBuffer: 5 Timeout reading answer for get fhtbuf
2013.05.10 13:17:01 5: Triggering fht.Nobody (1 changes)
2013.05.10 13:17:01 5: Notify loop for fht.Nobody report2 7
2013.05.10 13:17:01 5: Sending 8105044fc90185
2013.05.10 13:17:02 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:02 5: getFhtBuffer: 0 Timeout reading answer for get fhtbuf
2013.05.10 13:17:02 5: Sending 8105044fc90185
2013.05.10 13:17:03 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:03 5: getFhtBuffer: 1 Timeout reading answer for get fhtbuf
2013.05.10 13:17:03 5: Sending 8105044fc90185
2013.05.10 13:17:04 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:04 5: getFhtBuffer: 2 Timeout reading answer for get fhtbuf
2013.05.10 13:17:04 5: Sending 8105044fc90185
2013.05.10 13:17:04 4: FHZ/RAW: 810c04d10909a00145390000a000
2013.05.10 13:17:04 5: GET Got: 810c04d10909a00145390000a000
2013.05.10 13:17:04 5: getFhtBuffer: 3 810c04d10909a00145390000a000
2013.05.10 13:17:04 5: Sending 8105044fc90185
2013.05.10 13:17:05 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:05 5: getFhtBuffer: 4 Timeout reading answer for get fhtbuf
2013.05.10 13:17:05 5: Sending 8105044fc90185
2013.05.10 13:17:06 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:06 5: getFhtBuffer: 5 Timeout reading answer for get fhtbuf
2013.05.10 13:17:06 2: fht.Schlafen set report2 7: no confirmation after 4 tries, giving up
2013.05.10 13:17:06 5: Triggering fht.Schlafen (1 changes)
2013.05.10 13:17:06 5: Notify loop for fht.Schlafen report2 7
2013.05.10 13:17:06 5: Sending 8105044fc90185
2013.05.10 13:17:07 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:07 5: getFhtBuffer: 0 Timeout reading answer for get fhtbuf
2013.05.10 13:17:07 5: Sending 8105044fc90185
2013.05.10 13:17:08 4: FHZ/RAW: 810c042e0909a001134600002200
2013.05.10 13:17:08 5: GET Got: 810c042e0909a001134600002200
2013.05.10 13:17:08 5: getFhtBuffer: 1 810c042e0909a001134600002200
2013.05.10 13:17:08 5: Sending 8105044fc90185
2013.05.10 13:17:09 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:09 5: getFhtBuffer: 2 Timeout reading answer for get fhtbuf
2013.05.10 13:17:09 5: Sending 8105044fc90185
2013.05.10 13:17:10 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:10 5: getFhtBuffer: 3 Timeout reading answer for get fhtbuf
2013.05.10 13:17:10 5: Sending 8105044fc90185
2013.05.10 13:17:11 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:11 5: getFhtBuffer: 4 Timeout reading answer for get fhtbuf
2013.05.10 13:17:11 5: Sending 8105044fc90185
2013.05.10 13:17:12 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.10 13:17:12 5: getFhtBuffer: 5 Timeout reading answer for get fhtbuf
2013.05.10 13:17:12 5: Triggering fht.Stube (1 changes)
2013.05.10 13:17:12 5: Notify loop for fht.Stube report2 7
2013.05.10 13:17:12 5: Sending 8105044fc90185
2013.05.10 13:17:12 5: PRESENCE_DoLocalPingScan: Florian|...|0
2013.05.10 13:17:12 4: FHZ/RAW: 8107c9a6010285011d
2013.05.10 13:17:12 5: GET Got: 8107c9a6010285011d
2013.05.10 13:17:12 5: getFhtBuffer: 0   fhtbuf => 1d
2013.05.10 13:17:12 5: Sending 8109046902018341356607
2013.05.10 13:17:12 2: FHT set fht.Schlafen report2 7
2013.05.10 13:17:12 5: Sending 8109046b0201832c4c6607
2013.05.10 13:17:12 2: FHT set fht.Kueche report2 7
2013.05.10 13:17:12 5: Sending 8109047102018345396607
2013.05.10 13:17:12 2: FHT set fht.Nobody report2 7
2013.05.10 13:17:12 5: Sending 8109044c02018313466607
2013.05.10 13:17:12 2: FHT set fht.Stube report2 7
2013.05.10 13:17:12 5: Cmd: >set FHZ time<
2013.05.10 13:17:12 5: Sending 810ac99e0201610d050a0d11
2013.05.10 13:17:12 5: Triggering FHZ (1 changes)
2013.05.10 13:17:12 5: Notify loop for FHZ time
2013.05.10 13:17:12 5: Triggering global (1 changes)
2013.05.10 13:17:12 5: Notify loop for global DELETED FHZ_Zeit
2013.05.10 13:17:12 5: Triggering global (1 changes)
2013.05.10 13:17:12 5: Notify loop for global DEFINED FHZ_Zeit

[rudolfkoenig]

Deine Vermutung scheint mir plausibel zu sein, ich wuerde sogar sagen, dass das drunterliegende Geraet (FHZ/CUL) nicht auf "get fhtbuf" reagiert. Kannst Du das bitte auch direkt pruefen? Es interessant zu wissen, was das fuer ein Geraet ist, ob es nach einem reset die Probleme immer noch bestehen, usw.

[OiledAmoeba]

Moin,

darunter liegt eine FHZ1300PC WLAN an einer FRITZ!Box 7270v2.

Ich habe hier mal telnet und Log5 während get FHZ fhtbuf mitgeschnitten:

telnet:

fhem> get FHZ fhtbuf
FHZ fhtbuf => 4a
fhem> 2013-05-11 12:21:30 structure Zuhause present
2013-05-11 12:21:30 PRESENCE Florian present
2013-05-11 12:21:31 Global global DELETED FHZ_buff
2013-05-11 12:21:31 Global global DEFINED FHZ_buff
2013-05-11 12:21:32 dummy fhtbuf 4a
2013-05-11 12:21:32 FHZ FHZ fhtbuf: 4a

Log5:

2013.05.11 12:21:30 5: Cmd: >get FHZ fhtbuf<
2013.05.11 12:21:30 5: Sending 8105044fc90185
2013.05.11 12:21:31 5: GET Got: Timeout reading answer for get fhtbuf
2013.05.11 12:21:31 5: Triggering global (1 changes)
2013.05.11 12:21:31 5: Notify loop for global DELETED FHZ_buff
2013.05.11 12:21:31 5: Triggering global (1 changes)
2013.05.11 12:21:31 5: Notify loop for global DEFINED FHZ_buff
2013.05.11 12:21:32 4: FHZ/RAW: 8107c9d3010285014a (Unparsed: )
2013.05.11 12:21:32 5: FHZ dispatch 8107c9d3010285014a
2013.05.11 12:21:32 4: FHZ FHZ fhtbuf: 4a
2013.05.11 12:21:32 5: Triggering FHZ (1 changes)
2013.05.11 12:21:32 5: Notify loop for FHZ fhtbuf: 4a
2013.05.11 12:21:32 5: Triggering FHZ.fhtbuf
2013.05.11 12:21:32 5: Cmd: >{\
my $buff = ReadingsVal("FHZ","fhtbuf",0);\
fhem "set fhtbuf $buff"}<
2013.05.11 12:21:32 5: Cmd: >set fhtbuf 4a<
2013.05.11 12:21:32 5: Triggering fhtbuf (1 changes)
2013.05.11 12:21:32 5: Notify loop for fhtbuf 4a
2013.05.11 12:21:32 5: Cmd: ><

Da ist auch gerade ein at reingelaufen. Das at habe ich, weil die Verbindung über WLAN und symlink so fragil ist. Ich frage minütlich nach dem Pufferstand. Ich brauche eine bidirektionale Verbindung um zu erkennen, ob der symlink noch aktiv ist.
Wenn nach 10 Minuten kein Pufferstand gemeldet wurde, dann schließt ein watchdog den symlink, startet die FHZ1300PCWLAN neu und setzt den symlink wieder. fhem reagiert dann mit DISCONNECTED, CONNECTED. Anders kann fhem die abgebrochene Verbindung scheinbar leider nicht erkennen.

Da ist auch mein Problem: 00_FHZ.pm erwartet eine serielle Schnittstelle. Also auch eine kurze Response-Zeit. Leider braucht eine Abfrage über WLAN ihre Zeit, so dass viele get FHZ fhtbuf erst einen Timeout melden und ein bis zwei Sekunden später das Ergebnis doch noch kommt.
Die Response-Zeit konnte ich schon beschleunigen, indem ich die Baudrate in 00_FHZ.pm von 9600 auf 115200 hochgesetzt habe. Auch der Symlink ist auf diese Rate eingestellt. Auf diese Weise ist die Kommunikation spürbar schneller und die timeouts weniger. Deshalb auch in der Wunschliste meine Frage nach einer TCP/IP-Anpassung der 00_FHZ.

Leider brauche ich den fhtsoftbuf, da durch die fragile Symlink-Geschichte sonst viele Befehle verloren gehen würden. Und wegen eines Problem-FHT (übrigens der Einzige von ELV. Die von Lifetec laufen um längen besser.).

Die FHZ sieht so aus:

Internals:
   DEF        /dev/pty50 strangetty mobile
   DeviceName /dev/pty50
   FD         10
   FHZ_MSGCNT 5667
   FHZ_RAWMSG 8107c9d3010285014a
   FHZ_TIME   2013-05-11 14:49:12
   LASTInputDev FHZ
   MOBILE     1
   MSGCNT     810
   NAME       FHZ
   NR         26
   NR_CMD_LAST_H 62
   NTFY_TRIGGERTIME 2013-05-11 14:49:00
   PARTIAL    
   RAWMSG     810c04d50909a0012c4c0000aa00
   STATE      Initialized
   TYPE       FHZ
   ttytype    strangetty
   Readings:
     2013-05-11 14:48:30   fhtbuf          4a
     2013-05-11 01:02:01   init1           1f04a0015c018019
     2013-05-11 01:02:13   init2           1f04a0011c018019
     2013-05-11 01:02:22   init3           1f04a001b6018019
     2013-05-11 01:02:37   serial          136e7219
   Softbuffer:
   XMIT_TIME:
[...]
Attributes:
   fhtsoftbuffer 1
   loglevel   6
   model      fhz1300
   room       Wohnzimmer

Softbuffer habe ich rausgeschnitten. Die Anpassungen mit strangetty und mobile sind gerade drin, weil ich gerade teste, ob das eventuell positive Auswirkungen auf mein Problem hat.