[gelöst] Homematic wired verursacht freezes

RoBra81 · 28 Juli 2015, 10:22:40

Hallo,

ich bin gerade dabei, mein FHEM ein bisschen aufzuräumen und die Performance zu analysieren. Dabei wollte ich auch den schon lange unregelmäßig im Log auftauchenden freeze-Meldungen des Perfmon auf den Grund gehen. Mittels apptime bin ich auf Homematic wired als möglicher Verursacher gestoßen:

Code Auswählen

                                name             function    max  count    total  average maxDly 
           tmr-HM485_ChannelDoUpdate      HASH(0x4f07a00)   1189      1     1189  1189.00      2 HASH(0x4f07a00) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4cad910)   1123      1     1123  1123.00    165 HASH(0x4cad910) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4403cf8)   1117      1     1117  1117.00      2 HASH(0x4403cf8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x3eb3948)   1101      1     1101  1101.00      2 HASH(0x3eb3948) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4899320)   1098      1     1098  1098.00      2 HASH(0x4899320) 
           tmr-HM485_ChannelDoUpdate      HASH(0x445efc0)   1075      1     1075  1075.00      2 HASH(0x445efc0) 
           tmr-HM485_ChannelDoUpdate      HASH(0x49f4c60)   1048      1     1048  1048.00      3 HASH(0x49f4c60) 
           tmr-HM485_ChannelDoUpdate      HASH(0x1b01630)   1027      1     1027  1027.00      2 HASH(0x1b01630) 
           tmr-HM485_ChannelDoUpdate      HASH(0x1af5f20)   1020      1     1020  1020.00      3 HASH(0x1af5f20) 
           tmr-HM485_ChannelDoUpdate      HASH(0x3f16698)   1020      1     1020  1020.00      2 HASH(0x3f16698) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4facb70)   1019      1     1019  1019.00      2 HASH(0x4facb70) 
           tmr-HM485_ChannelDoUpdate      HASH(0x44ed998)   1014      1     1014  1014.00      2 HASH(0x44ed998)

Kann man hier etwas machen, damit das System nicht immer wieder blockiert wird?

Vielen Dank
Ronny

Thorsten Pferdekaemper · 28 Juli 2015, 11:49:19

Hi,
ich bin nicht so ganz vertraut mit der Perfmon-Ausgabe. Könntest Du mir auf die Sprünge helfen? Wie lange dauern denn diese "Freezes"?
Ansonsten: Hast Du die neuste Version der "Wired-Integration"? (https://github.com/kc-GitHub/FHEM-HM485/tree/dev)
Gruß,
Thorsten

RoBra81 · 28 Juli 2015, 11:51:34

Hallo,

ja, ich habe die aktuellste Version. Die Freezes dauern nicht wirklich lange (meist eine reichliche Sekunde), aber sie kommen zeitweise sehr oft - und da ist man manchmal schon auf der halben Treppe bevor der Bewegungsmelder das Licht anschaltet...

Ronny

Thorsten Pferdekaemper · 28 Juli 2015, 12:11:27

Hi,
ich habe mir mal das Coding von HM485_ChannelDoUpdate betrachtet. Da ist eigentlich vom HM485 her nichts "schlimmes" zu sehen. Im Prinzip macht das nur...

Code Auswählen


readingsBeginUpdate
readingsBulkUpdate
readingsEndUpdate

Möglicherweise hängen da viele notifys oder sowas dran?
Kannst Du das irgendwie so nachvollziehen, dass Du mal ein log mit Level 4 machen kannst?
Gruß,
Thorsten

RoBra81 · 29 Juli 2015, 08:05:54

Hallo,

ich habe gestern mal alle HM485-Devices und den Homematic Wired-Adapter auf verbose 4 gestellt, kann aber nicht behaupten, dass man dem viel entnehmen kann (siehe Log anbei). Ich werde mal sehen, ob ich mal das ganze System für ein paar freezes auf Verbose 4 setze...

Ronny

RoBra81 · 29 Juli 2015, 10:22:00

Hallo,

ich habe nochmal ein Log mit HM485d_logVerbose 4 gemacht - vielleicht ist da ja noch was zu sehen...

Ronny

Thorsten Pferdekaemper · 29 Juli 2015, 10:42:18

Hi,
also so direkt sehe ich keinen Grund für die Freezes. Es sieht für mich aber so aus, als ob es sehr wohl Probleme gibt. Ich kann einige "EEPROM-Reads" sehen. Das ist ein Hinweis auf Probleme auf dem Bus und dass das System versucht, Geräte wieder zu "synchronisieren". Das kommt vor Allem bei Gerät 00007900 vor. Was für ein Gerät ist das?
Mir scheint auch, dass das Gerät zum Teil mehrmals pro Sekunde einen set-Befehl (0x78) geschickt bekommt. Danach dann ein oder zwei auf 0000C6D9 und dann geht irgendwas schief.
Weißt Du, was das sein könnte? ...oder drückst Du manchmal "get config all"?

Ich glaube nicht, dass das das ist, was Du im Perfmon siehst, aber es würde erklären, warum das Licht manchmal nicht so schnell angeht, wie gewünscht.

Gruß,
Thorsten

RoBra81 · 29 Juli 2015, 10:58:55

Hallo,

00007900 ist ein HMW_LC_Sw2_DR und 0000C6D9 ist ein HMW_IO_12_Sw7_DR. Get config all habe ich eigentlich noch nie gedrückt - sollte ich? Einige Lampen werden per Bewegungsmelder ein- bzw. ausgeschaltet, vielleicht wird da irgendein on oder off mehrfach gesendet - wie sehe ich, auf welchem Kanal das mehrmalige set erfolgt?

Vielen Dank für deine Hilfe
Ronny

RoBra81 · 29 Juli 2015, 11:19:27

Wie muss ich solch einen Log-Eintrag interpretieren?

Code Auswählen

OG.ze.SE.HomematicWired: TX: (235) I[0](0,F,B)(18) 00000001 -> 0000C6D9 [5] 78(x) 11C8

Ist das Kanal 5?

RoBra81 · 29 Juli 2015, 11:28:45

Zitat von: Thorsten Pferdekaemper am 29 Juli 2015, 10:42:18
Ich kann einige "EEPROM-Reads" sehen. Das ist ein Hinweis auf Probleme auf dem Bus und dass das System versucht, Geräte wieder zu "synchronisieren".
...oder drückst Du manchmal "get config all"?

Kann dieses Verhalten beim Neustart von FHEM auftreten? Der Anfang vom Log war nämlich kurz nach einem Neustart...

Ralf9 · 29 Juli 2015, 11:34:35

Zitat von: RoBra81 am 29 Juli 2015, 11:19:27
Wie muss ich solch einen Log-Eintrag interpretieren?

Code Auswählen Erweitern
OG.ze.SE.HomematicWired: TX: (235) I[0](0,F,B)(18) 00000001 -> 0000C6D9 [5] 78(x) 11C8

Ist das Kanal 5?

Die 11 ist der Kanal - 1 im Hexadezimalsystem. Also hier der Kanal 18.
C8 ist ein und 0 ist aus.

https://de.wikipedia.org/wiki/Hexadezimalsystem

Gruß Ralf

RoBra81 · 30 Juli 2015, 07:16:05

Guten Morgen,

nachdem apptime heute nach durchlieft, sieht der Stand jetzt so aus:

Code Auswählen

           tmr-HM485_ChannelDoUpdate      HASH(0x4c499e0)   6812      1     6812  6812.00      2 HASH(0x4c499e0) 
                        tmr-WakeUpFn      HASH(0x40e5ed0)   5145      1     5145  5145.00      2 HASH(0x40e5ed0) 
           tmr-HM485_ChannelDoUpdate      HASH(0x48619c8)   3400      1     3400  3400.00      2 HASH(0x48619c8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x23de460)   2817      1     2817  2817.00      2 HASH(0x23de460) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4eaf498)   2792      1     2792  2792.00      2 HASH(0x4eaf498) 
           tmr-HM485_ChannelDoUpdate      HASH(0x50ebe70)   2736      1     2736  2736.00      2 HASH(0x50ebe70) 
           tmr-HM485_ChannelDoUpdate      HASH(0x24090d8)   2723      1     2723  2723.00      2 HASH(0x24090d8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4a98e18)   2717      1     2717  2717.00      2 HASH(0x4a98e18) 
           tmr-HM485_ChannelDoUpdate      HASH(0x49ab020)   2713      1     2713  2713.00      2 HASH(0x49ab020) 
           tmr-HM485_ChannelDoUpdate      HASH(0x5024ee8)   2713      1     2713  2713.00      2 HASH(0x5024ee8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x5068bf0)   2712      1     2712  2712.00      2 HASH(0x5068bf0) 
           tmr-HM485_ChannelDoUpdate      HASH(0x5034308)   2708      1     2708  2708.00      2 HASH(0x5034308) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4d210c8)   2683      1     2683  2683.00      2 HASH(0x4d210c8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x40e35b0)   2679      1     2679  2679.00      2 HASH(0x40e35b0) 
           tmr-HM485_ChannelDoUpdate      HASH(0x42bb708)   2654      1     2654  2654.00      2 HASH(0x42bb708) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4fb08e8)   2650      1     2650  2650.00      2 HASH(0x4fb08e8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4fcace8)   2650      1     2650  2650.00      2 HASH(0x4fcace8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x45f34f0)   2642      1     2642  2642.00      2 HASH(0x45f34f0) 
           tmr-HM485_ChannelDoUpdate      HASH(0x492a3f8)   2642      1     2642  2642.00      2 HASH(0x492a3f8) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4c81098)   2638      1     2638  2638.00      2 HASH(0x4c81098) 
           tmr-HM485_ChannelDoUpdate      HASH(0x4fc4670)   2637      1     2637  2637.00      2 HASH(0x4fc4670)

Das Log von heute sieht bis jetzt so aus:

Code Auswählen

2015.07.30 00:01:30 1: PERL WARNING: Missing argument in sprintf at ./FHEM/33_readingsGroup.pm line 1246.
2015.07.30 00:01:30 1: PERL WARNING: Invalid conversion in sprintf: end of string at ./FHEM/33_readingsGroup.pm line 1246.
2015.07.30 00:01:32 1: Perfmon: possible freeze starting at 00:01:31, delay is 1.308
2015.07.30 00:01:35 1: Perfmon: possible freeze starting at 00:01:34, delay is 1.487
2015.07.30 00:01:38 1: Perfmon: possible freeze starting at 00:01:37, delay is 1.673
2015.07.30 00:01:40 1: Perfmon: possible freeze starting at 00:01:39, delay is 1.126
2015.07.30 00:01:43 1: Perfmon: possible freeze starting at 00:01:42, delay is 1.056
2015.07.30 00:01:46 1: Perfmon: possible freeze starting at 00:01:45, delay is 1.7
2015.07.30 00:01:48 1: Perfmon: possible freeze starting at 00:01:47, delay is 1.434
2015.07.30 00:01:51 1: Perfmon: possible freeze starting at 00:01:50, delay is 1.592
2015.07.30 00:01:53 1: Perfmon: possible freeze starting at 00:01:52, delay is 1.38
2015.07.30 00:33:08 1: 192.168.18.13:55000 disconnected, waiting to reappear (DG.wz.TV.WohnzimmerTV)
2015.07.30 00:34:13 1: 192.168.18.13:55000 reappeared (DG.wz.TV.WohnzimmerTV)
2015.07.30 00:34:16 1: 192.168.18.13:55000 reappeared (DG.wz.TV.WohnzimmerTV)
2015.07.30 00:34:17 1: 192.168.18.13:55000 reappeared (DG.wz.TV.WohnzimmerTV)
2015.07.30 01:55:59 2: WhatsApp: setting $HOME to /opt/fhem
2015.07.30 01:55:59 2: WhatsApp: starting yoswup-cli: /opt/yowsup-master/yowsup-cli demos -c /opt/yowsup-master/config.example --yowsup
2015.07.30 02:45:51 1: 192.168.18.13:55000 disconnected, waiting to reappear (DG.wz.TV.WohnzimmerTV)
2015.07.30 05:21:13 1: Perfmon: possible freeze starting at 05:21:11, delay is 2.473
2015.07.30 05:21:17 1: Perfmon: possible freeze starting at 05:21:15, delay is 2.175
2015.07.30 05:22:59 1: Perfmon: possible freeze starting at 05:22:57, delay is 2.144
2015.07.30 05:23:01 1: Perfmon: possible freeze starting at 05:23:00, delay is 1.558
2015.07.30 05:30:04 1: Sub HeatingManual: Device is not a HM-CC-RT-DN:EG.uk.HZ.Wandthermostat.Climate - called with event desired-temp: for room Unten_Kueche
2015.07.30 05:31:22 1: Perfmon: possible freeze starting at 05:31:20, delay is 2.088
2015.07.30 05:31:24 1: Perfmon: possible freeze starting at 05:31:23, delay is 1.907
2015.07.30 05:39:17 1: Perfmon: possible freeze starting at 05:39:15, delay is 2.164
2015.07.30 05:39:19 1: Perfmon: possible freeze starting at 05:39:18, delay is 1.617
2015.07.30 05:39:30 2: ROOMMATE set rr_Ronny home
2015.07.30 05:47:17 1: Perfmon: possible freeze starting at 05:47:16, delay is 1.741
2015.07.30 05:47:20 1: Perfmon: possible freeze starting at 05:47:18, delay is 2.08
2015.07.30 05:48:54 1: Perfmon: possible freeze starting at 05:48:52, delay is 2.142
2015.07.30 05:48:56 1: Perfmon: possible freeze starting at 05:48:55, delay is 1.843
2015.07.30 05:52:54 1: Perfmon: possible freeze starting at 05:52:52, delay is 2.345
2015.07.30 05:52:57 1: Perfmon: possible freeze starting at 05:52:55, delay is 2.162
2015.07.30 05:55:17 1: Perfmon: possible freeze starting at 05:55:15, delay is 2.779
2015.07.30 05:55:20 1: Perfmon: possible freeze starting at 05:55:18, delay is 2.869
2015.07.30 05:56:49 1: Perfmon: possible freeze starting at 05:56:48, delay is 1.841
2015.07.30 05:56:52 1: Perfmon: possible freeze starting at 05:56:50, delay is 2.388
2015.07.30 05:58:31 1: Perfmon: possible freeze starting at 05:58:27, delay is 4.905
2015.07.30 06:00:43 2: ROOMMATE set rr_Ronny location underway
2015.07.30 06:09:38 1: Perfmon: possible freeze starting at 06:09:36, delay is 2.269
2015.07.30 06:09:42 1: Perfmon: possible freeze starting at 06:09:40, delay is 2.039
2015.07.30 06:54:15 1: Perfmon: possible freeze starting at 06:54:13, delay is 2.649
2015.07.30 06:54:19 1: Perfmon: possible freeze starting at 06:54:17, delay is 2.142
2015.07.30 06:55:43 1: Perfmon: possible freeze starting at 06:55:41, delay is 2.411
2015.07.30 06:55:45 1: Perfmon: possible freeze starting at 06:55:44, delay is 1.716
2015.07.30 06:57:45 2: ROOMMATE set rr_Ronny location office
2015.07.30 07:01:32 1: Perfmon: possible freeze starting at 07:01:31, delay is 1.126
2015.07.30 07:01:35 1: Perfmon: possible freeze starting at 07:01:34, delay is 1.432
2015.07.30 07:01:38 1: Perfmon: possible freeze starting at 07:01:37, delay is 1.472

Wie könnte ich noch analysieren, was an bzw. warum ChannelDoUpdate so lange braucht?

Ronny

Thorsten Pferdekaemper · 30 Juli 2015, 09:37:52

Hi,
das hier ist was HM485_ChannelDoUpdate im Prinzip macht:

Code Auswählen


	readingsBeginUpdate($chHash);
        readingsBulkUpdate( $chHash, $valueKey, $value);
	readingsEndUpdate($chHash, 1);

Soweit ich weiß stößt das auch die ganzen NOTIFYs an, die auf die entsprechenden Events registriert sind. Ich gehe mal davon aus, dass das readings...Update-Zeugs kein prinzipielles Problem hat, sonst würde das größere Wellen schlagen.
Was für NOTIFYs hast Du an den HMW-Devices hängen? ...und auch wie viele?

Gruß,
Thorsten

RoBra81 · 31 Juli 2015, 07:07:56

Guten Morgen Thorsten,

vielen Dank für deine Hilfe und Geduld! Ich habe mir mal die Notifys und DOIFs angesehen und da waren/sind tatsächlich einige Langläufer dabei (z.B. wurde bei Auslösen des Bewegungsmelders ein Wandtablet mit einem (vermutlich) blockierendem HTTPRequest eingeschaltet - das habe ich auf nonblocking umgestellt und siehe da, die Freezes wurden deutlich weniger).

Vielen Dank für deine tolle Arbeit!

Ronny

Thorsten Pferdekaemper · 31 Juli 2015, 10:54:19

Zitat von: RoBra81 am 31 Juli 2015, 07:07:56vielen Dank für deine Hilfe und Geduld! Ich habe mir mal die Notifys und DOIFs angesehen und da waren/sind tatsächlich einige Langläufer dabei (z.B. wurde bei Auslösen des Bewegungsmelders ein Wandtablet mit einem (vermutlich) blockierendem HTTPRequest eingeschaltet - das habe ich auf nonblocking umgestellt und siehe da, die Freezes wurden deutlich weniger).

Das freut mich.
Ich kann mich auch daran erinnern, dass in Deinen Logs einige "Response Timeout" waren. Das sollte man vielleicht auch noch analysieren. ...oder ist das jetzt auch weg?

ZitatVielen Dank für deine tolle Arbeit!

Danke für die Anerkennung!

Gruß,
Thorsten