Fehlersuche - FHEM blockt alle 70 sekunden für etwa 10 sek. (IODev)

[der-Lolo]

Hallo Froum,
bereits seit ende Mai kämpfe ich mit meiner FHEM Hauptinstallation, alle paar Wochen mache ich dort mal ein Update, jeweils vor dem Update setze ich händisch den Backup Befehl ab. Leider hat mir das alles nichts gebracht - sowohl ein restore als auch das zurückspielen meines Backups hat mir nicht geholfen.
Das Update welches ich am 26.05 machte - brachte Änderungen in der fhem.pl im Zusammenhang mit IO-Dev mit, das hat meine Installation nicht gut vertragen, ich setze für die meisten meiner defines ein nicht offizielles Modul https://forum.fhem.de/index.php/topic,12655.0.html ModbusTCP für Wago SPS ein.
Die Installation lief in etwa 5 Jahre sehr zuverlässig und nahezu vollkommen unauffällig.
Die meisten funktionen sind grundsätzlich so aufgebaut das sie im zweifelsfall auch ohne FHEM (direkt über den Wago Controller) funktionieren, FHEM sorgt nur für ein wenig Komfort und ein paar Überwachungen.

Beim FHEM Neustart nach dem update fing es damit an das alle defines die auf IO WagoController zugreifen 3-fach auftauchten.
Im moment ist der Zustand bei Neustart das bei den Wago Devices no I/O Device vermerkt wird...

In der zwischenzeit habe ich einiges versucht, ChrisD - der Maintainer des Wago Moduls konnte das Problem leider nicht nachstellen.
Ich habe Freezemon zur Hilfe genommen und stelle fest das irgendetwas im 70 sekunden Rhytmus FHEM für etwa 10 sekunden blockiert.

Code Auswählen Erweitern

2021.07.03 20:37:33 1: [Freezemon] myFreezemon: possible freeze starting at 20:37:24, delay is 9.247 possibly caused by: tmr-DbLog_execmemcache(DbLog) tmr-harmony_connect(HarmonyHub) tmr-ModbusTCPServer_Poll(WagoController) tmr-HOMEMODE_GetUpdate(Home)
2021.07.03 20:36:23 3: ModbusTCPServer_Timeout, request: SimpleWrite [FA E5 00 00 00 06] 00 01 30 00 00 48
2021.07.03 20:36:23 1: [Freezemon] myFreezemon: possible freeze starting at 20:36:14, delay is 9.156 possibly caused by: tmr-ModbusTCPServer_HandleReadQueue(WagoController) tmr-DbLog_execmemcache(DbLog) tmr-harmony_connect(HarmonyHub) tmr-HOMEMODE_GetUpdate(Home) tmr-ModbusTCPServer_Poll(WagoController)
2021.07.03 20:35:13 1: [Freezemon] myFreezemon: possible freeze starting at 20:35:03, delay is 10.05 possibly caused by: tmr-ModbusTCPServer_HandleReadQueue(WagoController) tmr-ModbusTCPServer_Poll(WagoController)
2021.07.03 20:34:02 1: [Freezemon] myFreezemon: possible freeze starting at 20:33:53, delay is 9.76 possibly caused by: tmr-ModbusTCPServer_Poll(WagoController) tmr-harmony_connect(HarmonyHub)
2021.07.03 20:32:52 1: [Freezemon] myFreezemon: possible freeze starting at 20:32:43, delay is 9.71 possibly caused by: tmr-ModbusTCPServer_Poll(WagoController) tmr-DbLog_execmemcache(DbLog) tmr-harmony_connect(HarmonyHub)
2021.07.03 20:31:42 1: [Freezemon] myFreezemon: possible freeze starting at 20:31:33, delay is 9.624 possibly caused by: tmr-ModbusTCPServer_Poll(WagoController) tmr-DbLog_execmemcache(DbLog) tmr-harmony_connect(HarmonyHub) tmr-SONOS_IsSubprocessAliveChecker(Sonos)
2021.07.03 20:30:32 1: [Freezemon] myFreezemon: possible freeze starting at 20:30:23, delay is 9.476 possibly caused by: tmr-ModbusTCPServer_Poll(WagoController) tmr-harmony_connect(HarmonyHub) tmr-HOMEMODE_GetUpdate(Home) tmr-SONOS_IsSubprocessAliveChecker(Sonos)
2021.07.03 20:29:22 3: ModbusTCPServer_Timeout, request: SimpleWrite [FA 1A 00 00 00 06] 00 01 02 40 00 08
2021.07.03 20:29:22 1: [Freezemon] myFreezemon: possible freeze starting at 20:29:13, delay is 9.323 possibly caused by: tmr-ModbusTCPServer_Poll(WagoController) tmr-harmony_connect(HarmonyHub) tmr-HOMEMODE_GetUpdate(Home)
2021.07.03 20:28:12 1: [Freezemon] myFreezemon: possible freeze starting at 20:28:03, delay is 9.28 possibly caused by: tmr-DbLog_execmemcache(DbLog) tmr-ModbusTCPServer_Poll(WagoController)
2021.07.03 20:22:43 1: RMDIR: ./restoreDir/save/2021-06-17

Ich habe keine Idee mehr was ich noch tun könnte - ich habe sogar mal ein "update force" abgesetzt in der Hoffnung das irgendeine defekte Datei ersetzt wird.

Ich denke sogar schon über eine Neu Installation nach - bin aber nicht sicher ob das mein Problem behebt.

Vielleicht hat jemand eine Idee - oder kann bei konstruktiver Fehlersuche unterstützen.

[rudolfkoenig]

Ich wuerde ein "attr global verbose 5" Log erstellen, und dabei auf Zeitspruenge achten.

[der-Lolo]

Mensch Rudi - Tausend Dank!
Wenn ich darauf nur selbst gekommen wäre...
Ich habe nach und nach alle möglichen verursacher via disable attribut abgeschaltet - aber keine Lösung gefunden.

Mit Deinem hinweis auf global verbose 5 bin ich nun über das VeluxGateway gestolpert... Hier gibt es kein disable - also gelöscht.
Und siehe da - nun schon seit einer halben Stunde keine Freezes mehr

Jetzt kann ich gezielt versuche herauszufinden was mit dem Modul los ist - und mich wenn ich keine Lösung finde im entsprechenden Thread melden.

Einzig eine sache bleibt mir nun komisch - sämtliche Wago defines werden beim neustart mit no I/O Device gemeldet...

Code Auswählen Erweitern

2021.07.04 18:16:35 1: Schlafzimmer: no I/O device

ein list des Devices Schlafzimmer zeigt aber das sowohl ein Attribut als auch ein Reading IODev existiert - bei Internals gibt es auch ein IODev...

Code Auswählen Erweitern

Internals:
   DEF        wago MX0.0
   FUUID      5c4470fc-f33f-68f5-6c4a-aed0e7945fa1bf81
   IODev      WagoController
   LASTInputDev WagoController
   MSGCNT     524
   ModbusCoil_lastRcv 2021-07-04 18:27:17
   NAME       Schlafzimmer
   NR         23
   NTFY_ORDER 50-Schlafzimmer
   STATE      off
   TYPE       ModbusCoil
   WagoController_MSGCNT 524
   WagoController_TIME 2021-07-04 18:27:17
   lastUpdate Sun Jul  4 18:27:16 2021
   nextUpdate Sun Jul  4 18:27:17 2021
   READINGS:
     2021-07-04 18:16:42   IODev           WagoController
     2021-07-04 18:27:17   state           off
   helper:
     addr       1 0 12288
     address    12288
     disableRegisterMapping 1
     lastUpdate 0
     nextUpdate 1625416037.78786
     nread      8
     readCmd   
0
     register   12288
     registerType 1
     unitId     0
     updateIntervall 0.1
     wago       1
     wagoDOOffset 0
     wagoT      M
     writeMode:
       DO         0
       addr       1 0 12448
       address    12448
       impDuration 0.5
       register   MX10.0
       registerType 1
       type       IM
Attributes:
   DbLogExclude .*
   IODev      WagoController
   event-on-change-reading .*
   group      Licht-Schalter
   room       01-Schlafzimmer
   writeMode  Impulse:MX10.0

Das scheint aber nur ein Schönheitsfehler zu sein, funktion ist zu 100% in Ordnung.


Nochmal Danke!