FHEM Forum

Hallo,

ich habe aktuell das Problem, dass ich meine MQTT2-Devices nicht mehr nutzen kann. Nach einem Neustart funktioniert es ein/zwei Minuten, dann nicht mehr.
Meine parallel dazu noch existierenden MQTT-Devices (also "altes" Modul) laufen dagegen ganz normal weiter...

Was mir im Log aufgefallen ist, ist dass das Modul ein "PINGREQ" absendet, obwohl direkt davor Nachrichten empfangen wurden, und dann wird vom Mosquitto anscheinend auch kein "PINGRESP" gesendet, wenn es andere übertragene Daten gibt.
Ab dann hängt das Modul anscheinend in dem Zustand fest, dass es eine Response erwartet, obwohl zwischendurch neue Verbindungsversuche gemacht werden. Zumindest rettet sich das Modul nicht mehr bis zum nächsten Neustart.

Hier mal der Log mit den Ereignisse, die ich meinte:
2020.06.08 18:53:06 5: mqtt2: received PUBLISH (0).shellies/shellyswitch25-F40867/overtemperature0
2020.06.08 18:53:06 5: mqtt2: dispatch autocreate=no\000fhemMQTT2\000shellies/shellyswitch25-F40867/overtemperature\0000
2020.06.08 18:53:07 5: mqtt2: sending PINGREQ (192)(0)
2020.06.08 18:53:13 5: mqtt2: received PUBLISH (0)%sensors/flur_Aussenwand_01/RSSI/Value-76.00
2020.06.08 18:53:13 5: mqtt2: dispatch autocreate=no\000fhemMQTT2\000sensors/flur_Aussenwand_01/RSSI/Value\000-76.00
.
.
2020.06.08 18:53:13 5: mqtt2: received PUBLISH (0),sensors/aussen_Terrasse_Switch_02/LEDs/set/0set_done
2020.06.08 18:53:13 5: mqtt2: dispatch autocreate=no\000fhemMQTT2\000sensors/aussen_Terrasse_Switch_02/LEDs/set/0\000set_done
.
.
2020.06.08 18:53:15 1: 192.168.0.11:1883 disconnected, waiting to reappear (mqtt2)
2020.06.08 18:53:15 4: IP: 192.168.0.11 -> 192.168.0.11
2020.06.08 18:53:15 1: 192.168.0.11:1883 reappeared (mqtt2)
2020.06.08 18:53:45 2: mqtt2: No PINGRESP for last PINGREQ (at 2020-06-08 18:53:07), disconnecting
2020.06.08 18:53:45 1: 192.168.0.11:1883 disconnected, waiting to reappear (mqtt2)
2020.06.08 18:53:47 4: IP: 192.168.0.11 -> 192.168.0.11
2020.06.08 18:53:49 1: 192.168.0.11:1883 reappeared (mqtt2)
2020.06.08 18:54:40 1: 192.168.0.11:1883 disconnected, waiting to reappear (mqtt2)
2020.06.08 18:54:41 4: IP: 192.168.0.11 -> 192.168.0.11
2020.06.08 18:54:41 1: 192.168.0.11:1883 reappeared (mqtt2)
2020.06.08 18:55:30 2: mqtt2: No PINGRESP for last PINGREQ (at 2020-06-08 18:54:34), disconnecting
2020.06.08 18:55:30 1: 192.168.0.11:1883 disconnected, waiting to reappear (mqtt2)
2020.06.08 18:55:39 4: IP: 192.168.0.11 -> 192.168.0.11
2020.06.08 18:55:39 1: 192.168.0.11:1883 reappeared (mqtt2)
2020.06.08 19:01:10 1: 192.168.0.11:1883 disconnected, waiting to reappear (mqtt2)
2020.06.08 19:01:11 4: IP: 192.168.0.11 -> 192.168.0.11
2020.06.08 19:01:12 1: 192.168.0.11:1883 reappeared (mqtt2)
2020.06.08 19:01:42 2: mqtt2: No PINGRESP for last PINGREQ (at 2020-06-08 19:00:39), disconnecting
2020.06.08 19:01:42 1: 192.168.0.11:1883 disconnected, waiting to reappear (mqtt2)
2020.06.08 19:01:44 4: IP: 192.168.0.11 -> 192.168.0.11
2020.06.08 19:01:44 1: 192.168.0.11:1883 reappeared (mqtt2)
Es gibt auch noch weitere Einträge, dass auf ein Response gewartet wird (19:01:42, 18:55:30 und 18:53:45), obwohl vorher im Log kein Request dazu ausgegeben wurde...

Vielleicht kann Rudi oder jemand anderes damit was anfangen, bzw. das bestätigen?

Grüße
Reinerlein

Existiert das Problem auch ohne den MQTT Geraeten?
Im Netz gibt es ein paar Hinweise auf kaputte Docker-Verbindungen, wenn man nach "mosquitto no pingresp" sucht: wo laeuft mosquitto?

Hi Rudi,

Mosquitto läuft, genauso wie FHEM, nativ direkt auf meinem Debian 10 (buster).
Ob es ohne Geräte läuft, kann ich ja nur schwer testen... meinst du einfach mit einem anderen, nicht verwendeten, MQTT-Broker verbinden?

Der Mosquitto selbst läuft auch normal weiter, ich kann das ja auf der Konsole bzw. mit einem MQTT Client auf dem Desktop-Rechner sehen.
Da ist auch schon ein bißchen was los (laut Mosquitto Statistik ca. 270 Messages pro Minute). Vielleicht kommt MQTT2 damit nicht ganz klar? Der nimmt ja immer alle Nachrichten an...

Grüße
Reinerlein

Hi Rudi,

ich habe es mal genauer untersucht...

Das Modul hat ein Problem mit längeren Laufzeiten beim Setzen von Readings-Werten.
Das passiert dann, wenn man langlaufende Userreadings oder langlaufende Notifies an einem Reading, welches vom Modul gesetzt werden soll, hat.

Dann ruft er die Daten vom Socket nicht mehr schnell genug ab, und wenn dann der Mosquitto weitersenden möchte, und der Empfangspuffer in FHEM voll ist, dann gibt es auf Mosquitto-Seite einen Socket-Error, und in Folge dann einen Verbindungsabbruch.

Ich hatte zwei etwas länger laufende Notifies an zwei Readings. Die haben so ca. 5 Sekunden gebraucht. Das "alte" MQTT-Modul hat damit scheinbar nur geringe Probleme... dort war ein Verbindungsabbruch zwar auch mal aufgetreten, aber deutlich seltener (vielleicht so 1-3 mal am Tag).

Vielleicht bringt es was, wenn du erst den gesamten Socket leer liest und danach die Verteilung der gesammelten Informationen durchführst?

Ich habe bei mir jedenfalls die Langläufer durch ein anderes Konzept ersetzt, damit ich erstmal wieder Ruhe habe...
Aber vielleicht hilft diese Info dem einen oder anderen ja auch weiter...

Grüße
Reinerlein

Hallo nochmal,

nach einem Tag Ruhe gingen die Abbrüche wieder los.
Leider fängt sich das Modul dabei nicht mehr ein.

Ich habe mal eine Änderung im Code gemacht, die mir auch logisch korrekter erschien, und nun habe ich seit 1,5 Tagen wieder etwas stabilere Zustände.

Ich habe in der Zeile 161 (MQTT2_CLIENT_keepalive), das return-Statement angepasst.
Dort wird bei einer Zeitüberschreitung (bzw. ausbleibender PINGRESP) auch noch was auf den Socket geschickt. Das erschien mir komisch.
Ich habe dort nun ein direktes Schliessen der Verbindung eingesetzt, womit sich da zumindest mal was retten kann...
Aus
return  MQTT2_CLIENT_Disco($hash);
habe ich ein
return DevIo_Disconnected($hash);
gemacht.

Damit ist immer noch das Problem, dass der Socketpuffer nicht immer vollständig geleert wird, aber der Zustand korrigiert sich damit wenigstens wieder...
Vielleicht kann das ja noch jemand testen und Rudi kann das vielleicht einchecken...

Für den vollen Puffer (und damit in Folge ein Socket-Error auf Seiten Mosquitto) müsste die Verarbeitung umgebaut werden... vielleicht probiere ich da auch mal was...

Grüße
Reinerlein

Servus Reinerlein,

nur so zum Verständnis:

Zitatlanglaufende Userreadings oder langlaufende Notifies an einem Reading

Kannst du das mal konkretisieren? Du hattest da Laufzeiten von 5 Sekunden erwähnt, was ja schon ziemlich aussergewöhnlich scheint.

Gruß
Danny

Hi Danny,

ich hatte so einen eigenen Notify-Watchdog, der bei Aktualisierung eines Readings eines Devices ein "at"-Device mit einem neuen Zeitstempel erzeugt hatte (und vorher ein bereits vorhandenes entfernt hatte).
Damit kann man sehr einfach das Ausbleiben einer Reading-Aktualisierung melden... Allerdings wird bei jeder Reading-Aktualisierung (ich hatte bei meinen Devices ein paar angegeben, der sehr zyklisch aktualisiert wurden) das bestehende "at"-Device gelöscht, und ein neues angelegt...
Das hat bei mir schon mal so 2-7 Sekunden gedauert...

Außerdem habe ich einige Userreadings, die etwas komplexere Berechnungen durchführen (eines war eine HSV (3 Readings lesen) -> RGBW-Umrechnung (4 Readings setzen), welche bei jeder Änderung eines der drei Readings getriggert wurde... Ich sehe in einem Userreading ja leider nicht, ob S und V noch kommen würden, wenn ich gerade auf H reagiere, und muss deshalb immer triggern (unter Umständen eben dreimal)...

Da das dann im Trigger der MQTT2-Aktualisierung durchgeführt wurde, wurde dieser natürlich sehr lang in der Abarbeitung...
Das habe ich jetzt auf "watchdog" umgestellt... bzw. Altlasten muss man auch mal irgendwann wegräumen :) Man muss sie nur finden...

Grüße
Reiner

Hallo nochmal,

ich habe mich mal wieder diesem Thema gewidmet, da es immer hinderlicher wird.

ich habe mal den perfmon installiert, um dem auf die Schliche zu kommen. Dabei habe ich mal bei einem MQTT2-Device (mein Shelly EM3) verbose auf 5 gesetzt.
Folgendes finde ich z.B. im Log.
.
.
2020.07.20 00:21:09.988 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => state
2020.07.20 00:21:09.989 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => relay
2020.07.20 00:21:10.308 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/power => 0_power
2020.07.20 00:21:10.633 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/pf => 0_pf
2020.07.20 00:21:10.922 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/current => 0_current
2020.07.20 00:21:11.223 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/voltage => 0_voltage
2020.07.20 00:21:11.504 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.20 00:21:11.835 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.20 00:21:12.125 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.20 00:21:12.421 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.20 00:21:12.712 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 00:21:13.039 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 00:21:13.320 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 00:21:13.620 1: Perfmon: possible freeze starting at 00:21:10, delay is 3.619
.
.
Da sieht man sehr deutlich, dass die Verarbeitung der MQTT-Nachrichten (also das Dispatch) bei 00:21:09.988 begonnen hat, und bis 00:21:13.320 gedauert hat. Währenddessen hat fhem anscheinend nichts anderes verarbeitet (deshalb die untere freeze-Meldung, als fhem wieder "frei" war)...

Ich habe an dem Device userReadings, die immer die Summen der drei Phasenwerte bildet:
power:._power.* {
  my $power0 = ReadingsVal($name, '0_power', 0);
  my $power1 = ReadingsVal($name, '1_power', 0);
  my $power2 = ReadingsVal($name, '2_power', 0);

  return $power0 + $power1 + $power2;
},

current:._current.* {
  my $current0 = ReadingsVal($name, '0_current', 0);
  my $current1 = ReadingsVal($name, '1_current', 0);
  my $current2 = ReadingsVal($name, '2_current', 0);

  return $current0 + $current1 + $current2;
},

energy:._energy.* {
  my $energy0 = ReadingsVal($name, '0_energy', 0);
  my $energy1 = ReadingsVal($name, '1_energy', 0);
  my $energy2 = ReadingsVal($name, '2_energy', 0);

  return $energy0 + $energy1 + $energy2;
},

energyKWh:._energyKWh.* {
  my $energy0 = ReadingsVal($name, '0_energyKWh', 0);
  my $energy1 = ReadingsVal($name, '1_energyKWh', 0);
  my $energy2 = ReadingsVal($name, '2_energyKWh', 0);

  return $energy0 + $energy1 + $energy2;
},

energy_total:._energy_total.* {
  my $energy0 = ReadingsVal($name, '0_energy_total', 0);
  my $energy1 = ReadingsVal($name, '1_energy_total', 0);
  my $energy2 = ReadingsVal($name, '2_energy_total', 0);

  return $energy0 + $energy1 + $energy2;
},

energy_totalKWh:._energy_totalKWh.* {
  my $energy0 = ReadingsVal($name, '0_energy_totalKWh', 0);
  my $energy1 = ReadingsVal($name, '1_energy_totalKWh', 0);
  my $energy2 = ReadingsVal($name, '2_energy_totalKWh', 0);

  return $energy0 + $energy1 + $energy2;
}

Hier noch das komplette List des Devices:
Internals:
   CID        shellyem3-68C63AFB3952
   DEF        shellyem3-68C63AFB3952
   DEVICETOPIC hwr_Hausstrom
   FUUID      5ed8943e-f33f-6779-b85e-129424228df3d2f1
   IODev      mqtt2
   LASTInputDev mqtt2
   MSGCNT     1443
   NAME       hwr_Hausstrom
   NR         1748
   STATE      off
   TYPE       MQTT2_DEVICE
   mqtt2_MSGCNT 1443
   mqtt2_TIME 2020-07-20 00:30:17
   READINGS:
     2020-07-20 00:30:11   0_current       0.24
     2020-07-20 00:30:02   0_energy        156
     2020-07-20 00:30:02   0_energyKWh     0.00
     2020-07-20 00:30:02   0_energy_total  106707.3
     2020-07-20 00:30:02   0_energy_totalKWh 106.71
     2020-07-20 00:30:11   0_pf            0.54
     2020-07-20 00:30:11   0_power         31.12
     2020-07-20 00:30:12   0_voltage       235.69
     2020-07-20 00:30:12   1_current       1.15
     2020-07-20 00:30:02   1_energy        1068
     2020-07-20 00:30:02   1_energyKWh     0.02
     2020-07-20 00:30:03   1_energy_total  364072.6
     2020-07-20 00:30:03   1_energy_totalKWh 364.07
     2020-07-20 00:30:12   1_pf            0.78
     2020-07-20 00:30:12   1_power         213.45
     2020-07-20 00:30:13   1_voltage       237.95
     2020-07-20 00:30:17   2_current       3.04
     2020-07-20 00:30:03   2_energy        3078
     2020-07-20 00:30:03   2_energyKWh     0.05
     2020-07-20 00:30:04   2_energy_total  562907.9
     2020-07-20 00:30:04   2_energy_totalKWh 562.91
     2020-07-20 00:30:16   2_pf            0.83
     2020-07-20 00:30:16   2_power         601.88
     2020-07-20 00:30:17   2_voltage       237.43
     2020-06-04 08:27:20   associatedWith  mqtt2_GeneralBridge
     2020-07-20 00:30:17   current         4.43
     2020-07-20 00:30:04   energy          4302
     2020-07-20 00:30:03   energyKWh       0.07
     2020-07-20 00:30:04   energy_total    1033636.5
     2020-07-20 00:30:04   energy_totalKWh 1033.69
     2020-07-13 11:57:54   fw_ver          20200702-133522/v1.7.4@1d8b9fca
     2020-07-13 11:57:54   id              shellyem3-68C63AFB3952
     2020-07-13 11:57:54   ip              192.168.0.82
     2020-07-13 11:57:54   mac             68C63AFB3952
     2020-07-13 11:57:54   new_fw          false
     2020-07-13 11:57:54   online          true
     2020-07-20 00:30:16   power           846.45
     2020-07-20 00:30:10   relay           off
     2020-07-20 00:30:17   statCurrentDay  Min: 4.13 Avg: 4.64 Max: 7.13
     2020-07-19 23:59:50   statCurrentDayLast Min: 4.57 Avg: 5.14 Max: 5.62
     2020-07-20 00:30:17   statCurrentMonth Min: 2.85 Avg: 5.00 Max: 40.06
     2020-06-30 23:59:47   statCurrentMonthLast Min: 0.00 Avg: 4.82 Max: 39.19 (since: 2020-06-14_13:33:03 )
     2020-07-20 00:30:17   statCurrentYear Min: 0.00 Avg: 4.92 Max: 40.06 (since: 2020-06-14_13:33:03 )
     2020-07-20 00:30:17   statEnergy      Hour: -798 Day: -798 Month: 168 Year: -954 (since: 2020-06-05 )
     2020-07-20 00:30:17   statEnergyKWh   Hour: -0.01 Day: -0.01 Month: 0.00 Year: -0.02 (since: 2020-06-05 )
     2020-07-19 23:59:50   statEnergyKWhLast Hour: -0.01 Day: -0.01 Month: -0.02 Year: - (since: 2020-06-05 )
     2020-07-19 23:59:50   statEnergyLast  Hour: -558 Day: -558 Month: -1122 Year: - (since: 2020-06-05 )
     2020-07-20 00:30:17   statEnergy_total Hour: 534.7 Day: 534.7 Month: 442407.5 Year: 1023210.6 (since: 2020-06-05 )
     2020-07-20 00:30:17   statEnergy_totalKWh Hour: 0.53 Day: 0.53 Month: 442.46 Year: 1023.26 (since: 2020-06-05 )
     2020-07-19 23:59:50   statEnergy_totalKWhLast Hour: 0.19 Day: 0.19 Month: 580.80 Year: - (since: 2020-06-05 )
     2020-07-19 23:59:50   statEnergy_totalLast Hour: 128.1 Day: 128.1 Month: 580803.1 Year: - (since: 2020-06-05 )
     2020-07-20 00:30:17   statPowerDay    Min: 779.90 Avg: 910.40 Max: 1585.43
     2020-07-19 23:59:50   statPowerDayLast Min: 893.17 Avg: 1049.30 Max: 1177.62
     2020-07-20 00:30:17   statPowerHour   Min: 779.90 Avg: 910.42 Max: 1585.43
     2020-07-19 23:59:50   statPowerHourLast Min: 893.17 Avg: 1049.30 Max: 1177.62
     2020-07-20 00:30:17   statPowerMonth  Min: 455.02 Avg: 969.47 Max: 9360.88
     2020-06-30 23:59:47   statPowerMonthLast Min: 0.00 Avg: 925.46 Max: 8933.18 (since: 2020-06-04_10:10:01 )
     2020-07-20 00:30:17   statPowerYear   Min: 0.00 Avg: 943.83 Max: 9360.88 (since: 2020-06-04_10:10:01 )
     2020-07-20 00:30:17   statStateDay    off: 00:30:27 off_Count: 1
     2020-07-19 23:59:50   statStateDayLast off: 00:13:21 off_Count: 1
     2020-07-20 00:30:17   statStateHour   off: 00:30:27 off_Count: 1
     2020-07-19 23:59:50   statStateHourLast off: 00:13:21 off_Count: 1
     2020-07-20 00:30:17   statStateMonth  off: 18d 23:59:06 off_Count: 4 x_update: 00:31:05 x_update_Count: 3
     2020-06-30 23:59:47   statStateMonthLast off: 26d 13:48:55 off_Count: 2 on: 00:00:39 on_Count: 1 (since: 2020-06-04_10:10:01)
     2020-07-20 00:30:17   statStateYear   off: 45d 13:48:00 off_Count: 5 on: 00:00:39 on_Count: 1 x_update: 00:31:05 x_update_Count: 3 (since: 2020-06-04_10:10:01)
     2020-07-20 00:30:10   state           off
   helper:
     _98_statistics Statistik
     bm:
       MQTT2_DEVICE_Attr:
         cnt        1
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        20.07. 00:18:46
         max        3.88622283935547e-05
         tot        3.88622283935547e-05
         mAr:
           set
           hwr_Hausstrom
           verbose
           5
       MQTT2_DEVICE_Get:
         cnt        2
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        20.07. 00:18:23
         max        8.79764556884766e-05
         tot        0.000167131423950195
         mAr:
           HASH(0x6a9143c)
           hwr_Hausstrom
           ?
       MQTT2_DEVICE_Set:
         cnt        2726
         dmx        -1000
         dtot       0
         dtotcnt    0
         mTS        20.07. 00:00:54
         max        0.00174403190612793
         tot        2.15269947052002
         mAr:
           HASH(hwr_Hausstrom)
           hwr_Hausstrom
           ?
Attributes:
   Firmware   Shelly
   IODev      mqtt2
   alias      Hausstrom
   devStateIcon {my $onl = ReadingsVal($name,"online","false") eq "false" ? "red" : ReadingsVal($name,"state","...") eq "x_update" ? "gold" : ReadingsVal($name,"new_fw","false") eq "true" ? "yellow" : "green";; my $light = ReadingsVal($name,"relay","off");; my $cons = ReadingsVal($name,"power","unknown");; my $tag = getStatisticsDay(ReadingsVal($name,'statEnergy_totalKWh','0'));; my $show = '<a href="';; $show .= $onl eq "yellow" ? "/fhem?cmd.dummy=set $name x_update&XHR=1\">" : "http://".ReadingsVal($name,"ip","none").' "target="_blank">';; $show .= FW_makeImage('fa_circle_small@'.$onl)."</a>";; "<div> $show &nbsp; <a href=\"/fhem?cmd.dummy=set $name toggle&XHR=1\">".FW_makeImage('taster_ch_'.($light eq 'on' ? 'an_gruen' : 'aus_rot'), $light)." &nbsp; </a> Aktuell: $cons W Tag: $tag kWh</div>"}
   group      Stromverbrauch
   icon       measure_power
   readingList shellies/shellyem3-68C63AFB3952/online:.* online
shellies/announce:.* { $EVENT =~ m,..id...shellyem3-68C63AFB3952...mac.*, ? json2nameValue($EVENT) : undef }
shellies/shellyem3-68C63AFB3952/announce:.* { json2nameValue($EVENT) }
shellies/shellyem3-68C63AFB3952/relay/0:.* state
shellies/shellyem3-68C63AFB3952/relay/0:.* relay
shellies/shellyem3-68C63AFB3952/emeter/0/power:.* 0_power
shellies/shellyem3-68C63AFB3952/emeter/0/pf:.* 0_pf
shellies/shellyem3-68C63AFB3952/emeter/0/current:.* 0_current
shellies/shellyem3-68C63AFB3952/emeter/0/voltage:.* 0_voltage
shellies/shellyem3-68C63AFB3952/emeter/0/energy:.* 0_energy
shellies/shellyem3-68C63AFB3952/emeter/0/energy:.* {'0_energyKWh' => sprintf("%.2f",$EVENT/60/1000)}
shellies/shellyem3-68C63AFB3952/emeter/0/total:.* 0_energy_total
shellies/shellyem3-68C63AFB3952/emeter/0/total:.* {'0_energy_totalKWh' => sprintf("%.2f",$EVENT/1000)}
shellies/shellyem3-68C63AFB3952/emeter/1/power:.* 1_power
shellies/shellyem3-68C63AFB3952/emeter/1/pf:.* 1_pf
shellies/shellyem3-68C63AFB3952/emeter/1/current:.* 1_current
shellies/shellyem3-68C63AFB3952/emeter/1/voltage:.* 1_voltage
shellies/shellyem3-68C63AFB3952/emeter/1/energy:.* 1_energy
shellies/shellyem3-68C63AFB3952/emeter/1/energy:.* {'1_energyKWh' => sprintf("%.2f",$EVENT/60/1000)}
shellies/shellyem3-68C63AFB3952/emeter/1/total:.* 1_energy_total
shellies/shellyem3-68C63AFB3952/emeter/1/total:.* {'1_energy_totalKWh' => sprintf("%.2f",$EVENT/1000)}
shellies/shellyem3-68C63AFB3952/emeter/2/power:.* 2_power
shellies/shellyem3-68C63AFB3952/emeter/2/pf:.* 2_pf
shellies/shellyem3-68C63AFB3952/emeter/2/current:.* 2_current
shellies/shellyem3-68C63AFB3952/emeter/2/voltage:.* 2_voltage
shellies/shellyem3-68C63AFB3952/emeter/2/energy:.* 2_energy
shellies/shellyem3-68C63AFB3952/emeter/2/energy:.* {'2_energyKWh' => sprintf("%.2f",$EVENT/60/1000)}
shellies/shellyem3-68C63AFB3952/emeter/2/total:.* 2_energy_total
shellies/shellyem3-68C63AFB3952/emeter/2/total:.* {'2_energy_totalKWh' => sprintf("%.2f",$EVENT/1000)}
   room       Info,Zentrales
   setList    relay:on,off,toggle shellies/shellyem3-68C63AFB3952/relay/0/command $EVTPART1
off:noArg shellies/shellyem3-68C63AFB3952/relay/0/command off
on:noArg shellies/shellyem3-68C63AFB3952/relay/0/command on
x_update:noArg shellies/shellyem3-68C63AFB3952/command update_fw
x_mqttcom shellies/shellyem3-68C63AFB3952/command $EVTPART1

   sortby     1
   userReadings power:._power.* {
  my $power0 = ReadingsVal($name, '0_power', 0);
  my $power1 = ReadingsVal($name, '1_power', 0);
  my $power2 = ReadingsVal($name, '2_power', 0);

  return $power0 + $power1 + $power2;
},

current:._current.* {
  my $current0 = ReadingsVal($name, '0_current', 0);
  my $current1 = ReadingsVal($name, '1_current', 0);
  my $current2 = ReadingsVal($name, '2_current', 0);

  return $current0 + $current1 + $current2;
},

energy:._energy.* {
  my $energy0 = ReadingsVal($name, '0_energy', 0);
  my $energy1 = ReadingsVal($name, '1_energy', 0);
  my $energy2 = ReadingsVal($name, '2_energy', 0);

  return $energy0 + $energy1 + $energy2;
},

energyKWh:._energyKWh.* {
  my $energy0 = ReadingsVal($name, '0_energyKWh', 0);
  my $energy1 = ReadingsVal($name, '1_energyKWh', 0);
  my $energy2 = ReadingsVal($name, '2_energyKWh', 0);

  return $energy0 + $energy1 + $energy2;
},

energy_total:._energy_total.* {
  my $energy0 = ReadingsVal($name, '0_energy_total', 0);
  my $energy1 = ReadingsVal($name, '1_energy_total', 0);
  my $energy2 = ReadingsVal($name, '2_energy_total', 0);

  return $energy0 + $energy1 + $energy2;
},

energy_totalKWh:._energy_totalKWh.* {
  my $energy0 = ReadingsVal($name, '0_energy_totalKWh', 0);
  my $energy1 = ReadingsVal($name, '1_energy_totalKWh', 0);
  my $energy2 = ReadingsVal($name, '2_energy_totalKWh', 0);

  return $energy0 + $energy1 + $energy2;
}
   verbose    5


Dauert das Auswerten der userReadings solange?
Wenn ja, wie kann man eine solche Addition optimieren?

Danke schon mal für Hinweise...

Grüße
Reinerlein

Moin.

Da an den userReadings auch noch statistics hängt und evtl. dann auch noch weitere Eventhandler die Events  (einschl. der userReadings...) analysieren (FileLog, ...?), wäre es evtl. eine Überlegung, die userReadings-trigger noch etwas enger zu fassen:
Im Moment hast du bei jedem Durchgang (der Shelly sendet wenn, dann doch immer alle Werte, oder?) z.B. drei Mal eine Aktualisierung, nämlich für jeden Kanal. Eigentlich sollte es reichen, nur jeweils den letzten (z.B. 2_power) triggern zu lassen, oder? (Dann müßten m.E. auch die Zeitpunkte besser zur Auswertung passen, sonst ist beim ersten Duchlauf noch was eigentlich veraltetes für Kanal 2+3 drin?).

Btw.: Es gibt zwischenzeitlich auch ein attrTemplate für den em3, allerdings ist das (gefühlt) noch nicht ganz fertig. Vielleicht magst du das mit optimieren?

Hi Beta-User,

das mit dem letzten Readings-Trigger ist ja schwer, da man nicht sicher sagen kann, welcher nun als letzter gesendet und/oder verarbeitet wird. Deswegen muss man das, meiner Meinung nach, schon so machen. Es könnte ja auch durch den MQTT-Broker (Mosquitto) verzögert zugestellt werden, dann fehlt einer in der Menge...
Das klingt nicht nach "sicher ausgewertet" :)

Aber warum dauert es solange (das liegt ja teilweise schon im Sekundenbereich)?
Und die Events, die nach dieser Paket-Aktualisierung erzeugt werden (auf die dann Notify und FileLog usw. reagieren), kommen doch erst, nachdem alle userReadings berechnet wurden, oder?

Ich bin mir nicht sicher, ob ich der richtige für eine Optimierung der attrTemplates bin. Ich verwende die nur als Basis, und habe einige (teilweise erhebliche) Anpassungen, da ich eine andere Philosophie der Namensgebung für die Readings verfolge...

Grüße
Reinerlein

Hallo Beta-User,

ich habe das nochmal im Log nachgesehen: Leider kommen die Werte nicht in einer Welle zusammen an:
2020.07.20 08:35:07.197 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/energy => {'0_energyKWh' => sprintf("%.2f",$EVENT/60/1000)}
2020.07.20 08:35:07.201 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/energy => 0_energy
2020.07.20 08:35:07.553 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/total => 0_energy_total
2020.07.20 08:35:07.555 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/total => {'0_energy_totalKWh' => sprintf("%.2f",$EVENT/1000)}
2020.07.20 08:35:07.927 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/energy => {'1_energyKWh' => sprintf("%.2f",$EVENT/60/1000)}
2020.07.20 08:35:07.931 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/energy => 1_energy
2020.07.20 08:35:08.288 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/total => 1_energy_total
2020.07.20 08:35:08.291 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/total => {'1_energy_totalKWh' => sprintf("%.2f",$EVENT/1000)}
2020.07.20 08:35:08.667 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/energy => {'2_energyKWh' => sprintf("%.2f",$EVENT/60/1000)}
2020.07.20 08:35:08.671 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/energy => 2_energy
2020.07.20 08:35:09.024 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/total => {'2_energy_totalKWh' => sprintf("%.2f",$EVENT/1000)}
2020.07.20 08:35:09.029 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/total => 2_energy_total
2020.07.20 08:35:11.338 1: Perfmon: possible freeze starting at 08:35:05, delay is 6.338
2020.07.20 08:35:25.654 1: Perfmon: possible freeze starting at 08:35:24, delay is 1.654
2020.07.20 08:35:26.281 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:35:26.622 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:35:26.915 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:35:27.234 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:35:27.544 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => state
2020.07.20 08:35:27.545 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => relay
2020.07.20 08:35:27.874 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/power => 0_power
2020.07.20 08:35:28.209 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/pf => 0_pf
2020.07.20 08:35:28.505 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/current => 0_current
2020.07.20 08:35:28.813 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/voltage => 0_voltage
2020.07.20 08:35:29.100 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.20 08:35:29.440 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.20 08:35:29.736 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.20 08:35:30.040 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.20 08:35:30.337 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:35:30.678 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:35:30.965 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:35:31.280 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:35:31.570 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:35:31.904 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:35:32.192 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:35:32.505 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:35:32.787 1: Perfmon: possible freeze starting at 08:35:28, delay is 4.787
2020.07.20 08:35:34.337 1: Perfmon: possible freeze starting at 08:35:33, delay is 1.337
2020.07.20 08:35:36.196 1: Perfmon: possible freeze starting at 08:35:35, delay is 1.195
2020.07.20 08:35:57.965 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => state
2020.07.20 08:35:57.966 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => relay
2020.07.20 08:35:58.292 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/power => 0_power
2020.07.20 08:35:58.547 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/pf => 0_pf
2020.07.20 08:35:58.764 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/current => 0_current
2020.07.20 08:35:58.994 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/voltage => 0_voltage
2020.07.20 08:35:59.203 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.20 08:35:59.416 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.20 08:35:59.634 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.20 08:35:59.842 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.20 08:36:00.061 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:36:00.269 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:36:00.479 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:36:00.698 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:36:00.954 1: Perfmon: possible freeze starting at 08:35:58, delay is 2.954
2020.07.20 08:36:03.416 1: Perfmon: possible freeze starting at 08:36:01, delay is 2.416
2020.07.20 08:36:05.352 1: Perfmon: possible freeze starting at 08:36:04, delay is 1.352
2020.07.20 08:36:27.072 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => state
2020.07.20 08:36:27.073 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => relay
2020.07.20 08:36:27.398 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/power => 0_power
2020.07.20 08:36:27.652 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/pf => 0_pf
^@2020.07.20 08:36:27.869 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/current => 0_current
2020.07.20 08:36:28.099 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/voltage => 0_voltage
2020.07.20 08:36:28.308 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.20 08:36:28.521 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.20 08:36:28.739 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.20 08:36:28.946 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.20 08:36:29.155 1: Perfmon: possible freeze starting at 08:36:28, delay is 1.155
2020.07.20 08:36:29.166 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:36:29.374 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:36:29.584 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:36:29.803 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:36:32.597 1: Perfmon: possible freeze starting at 08:36:30, delay is 2.597
2020.07.20 08:36:35.090 1: Perfmon: possible freeze starting at 08:36:34, delay is 1.09
2020.07.20 08:36:48.288 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:36:48.631 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:36:48.841 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:36:49.078 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:36:54.412 1: Perfmon: possible freeze starting at 08:36:53, delay is 1.412
2020.07.20 08:36:55.837 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:36:55.845 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:36:55.855 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:36:55.870 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 08:36:59.245 1: Perfmon: possible freeze starting at 08:36:57, delay is 2.245
2020.07.20 08:36:59.251 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => state
2020.07.20 08:36:59.252 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => relay
2020.07.20 08:36:59.503 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/power => 0_power
2020.07.20 08:36:59.709 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/pf => 0_pf
2020.07.20 08:36:59.926 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/current => 0_current
2020.07.20 08:37:00.138 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/voltage => 0_voltage
2020.07.20 08:37:00.347 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.20 08:37:00.560 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.20 08:37:00.778 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.20 08:37:00.985 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.20 08:37:01.204 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 08:37:01.212 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 08:37:01.222 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 08:37:01.237 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage

Da ist immer mal zwischendurch fhem an der Reihe, sodass man erkennen kann, dass die Werte in verschiedenen Events verarbeitet werden...

Grüße
Reinerlein

Bei meinem Vorschlag, den Trigger für die userReadings einzuschränken, bin ich schon davon ausgegangen, dass jede eingehende Message jeweils eine eigene Event-Verarbeitungskaskade in FHEM verursacht (einschließlich Logging, dewpoint, DOIF-Aggregationen, was auch immer...).
Wie es (zumindest nach diesen hier geposteten kurzen Log-Auszügen) aussieht, arbeiten auch sowohl der Shelly wie Mosquitto (wie FEM auch) alles streng linear ab, von daher dürfte ein eventueller Fehler durch das triggern nur auf die 2-er-Readings (also die letzten versendeten bzw. übermittelten) wenn, dann eher gering ausfallen. Ich sehe also das befürchtete Problem noch nicht... (Vielleicht schaust du im Event-Monitor mal eine Zeitlang zu, was da so alles passiert?).

Ohne dafür jetzt Expertenwissen für mich beanspruchen zu wollen: die letzten geposteten Freezes paßen m.E. teilweise zeitlich nicht zu den MQTT2-Events; deutet das nicht eher darauf hin, dass irgendwas anderes da auch noch rumspukt?

---

Was die attrTemplate-Geschichte angeht: Das könntest du ja in einem Testsystem ausentwickeln (Readingnamen sind ja nur ein Teil des Gesamtthemas). Der bisher einzige andere User, der so einem Shelly hat, war irgendwann mit seinen Einstellungen zufrieden, die aber m.E. nicht so ganz mit der API zusammengepßat hatten. Daher ist das eben noch unfertig...
Ansonsten muß ich halt warten, bis sich wieder jemand mit so einem Teil outet ::) .

Hi Beta-User,

ich habe 16 Shelly-Devices im System, und dieses sind aktuell die einzigen, die über MQTT2 laufen (meine anderen MQTT-Devices laufen über das "alte" MQTT-Modul und auch einen anderen Mosquitto-Broker zur sauberen Trennung, und erzeugen keinerlei Freezes).
Alle diese MQTT2-Devices erzeugen hin und wieder diese Freezes, ich habe allerdings nur den EM3 auf verbose 5 gesetzt, um überhaupt etwas erkennen zu können.

Also, ja, da sind noch andere Devices, die Freezes erzeugen :)
Ich habe diese Freezes auch erst, seit ich MQTT2 verwende...

--
Was fehlt denn noch bei den attrTemplates zum EM3? Soweit ich mich erinnern kann, war eigentlich alles da, nur habe ich mir einiges umbenannt...

Grüße
Reinerlein

Ich kann nicht beurteilen, ob es der 3em ist, der die Freezes erzeugt. Der em3 verursacht in jedem Fall auch einige/viele Events, jedenfalls mehr, als der mir bekannte Rest, dazu kommen eben noch die userReadings. An sich sollte das nicht so lange dauern, aber näheres - außer, dass die Event-Verarbeitung selbst mMn. optimiert werden könnte - kann ich dazu nicht sagen; evtl. könntest du auch das Freezemon-Modul austesten, das läßt dem Vernehmen nach wohl bessere Rückschlüsse zu, wo Freezes herkommen.

---

Betr. das template: Da waren noch ein paar Dinge offen wie die Frage, ob jetzt monotonic Sinn macht oder nicht; mein letzter Stand: https://forum.fhem.de/index.php/topic,111905.msg1063526.html#msg1063526. Leider hat der TE da meine Frage nicht so recht verstanden und auch (gefühlt) keine Infos zu dem geliefert, was das Teil eigentlich wann und warum sendet.
Irgendwie wäre für mich noch die Frage, ob man über die Einstellungen am Web-Interface z.B. auch Infos zur Gesamtenergie bekommt bzw. ob es ggf. möglich wäre, dass der Hersteller das einbaut. Macht ja uU. Sinn, den Shelly rechnen zu lassen und dann einfach nur das Ergebnis entgegenzunehmen, dann sind alle Infos tendenziell besser synchronisiert... (womit wir indirekt wieder beim Thema wären ;) ).

Hi Beta-User,

also die userRedings sind es mal nicht. Ich habe sie einfach mal gelöscht, und auch auf freezemon umgestellt:
2020.07.20 10:53:31.937 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => state
2020.07.20 10:53:31.937 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/relay/0 => relay
2020.07.20 10:53:32.167 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/power => 0_power
2020.07.20 10:53:32.390 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/pf => 0_pf
2020.07.20 10:53:32.620 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/current => 0_current
2020.07.20 10:53:32.839 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/0/voltage => 0_voltage
2020.07.20 10:53:33.067 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.20 10:53:33.285 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.20 10:53:33.514 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.20 10:53:33.738 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.20 10:53:33.961 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/power => 2_power
2020.07.20 10:53:34.181 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/pf => 2_pf
2020.07.20 10:53:34.402 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/current => 2_current
2020.07.20 10:53:34.627 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/2/voltage => 2_voltage
2020.07.20 10:53:35.022 1: [Freezemon] myFreezemon: possible freeze starting at 10:53:32, delay is 3.021 possibly caused by: no bad guy found :-(

Es scheint schon so zu sein, dass MQTT2 diese Readings sehr langsam verarbeitet. Anscheinend ist das Dispatch für jedes Readings sehr aufwändig... vielleicht könnte man da eine "Abkürzung" im Code einbauen? Ich blicke das Gesamtsystem MQTT2 dazu aber zuwenig...
Allerdings sind es wohl nicht meine Additions-userReadings...

Grüße
Reinerlein

Hmm, "no bad guy" kann ich nicht deuten...

Und an sich sieht es auch so aus, als würde das immer um die 200+ms dauern, bis das einzelne Dispatch komplett durch ist; das sieht mir nicht wild aus, vor allem, weil sich theoretisch auch was dazwischenklemmen könnte (ich denke an ein anderes Interface, das ebenfalls irgendwelche Event-relevanten Daten abliefert).

Wenn man von 35.022 die 3.021 abziehet, landet man bei 32.001. Das deutet darauf hin, dass es evtl. mit dem update von "state" (eher als relay) zusammenhängen könnte; da FHEM auch weiterläuft, müßte das eigentlich irgendwas im Hintergrund sein, oder? Wie logs du? DBLog? (das forkt afaik, was auch kein echter freeze wäre, oder?).

Aber im Prinzip muß ich zugeben, dass ich völlig im Dunkeln tappe...

Hi Rudi,

ich habe das Problem in den Griff bekommen.
Ich habe hier einen Patch, in dem ich die Verarbeitung von Nachrichten auf einzelne umgestellt habe. Zwischen jeder Nachrichtenverarbeitung wird ein InternalTimer ausgeführt, sodass Fhem nicht geblockt wird.
Dadurch skaliert die Verarbeitung auch viel besser. Ich habe teilweise in einer Lieferung vom MQTT-Broker 30 Nachrichten. Durch das einzelne Dispatching (da könnte man vielleicht auch noch Optimieren) braucht er für eine Nachricht auf meiner Kiste 0,5-2,5 Sekunden, für dieses ganze Paket also mal 30-45 Sekunden, in denen Fhem angehalten ist.

Des Weiteren habe ich das Abbrechen wegen fehlender PingResp auf Disconnect umgestellt, damit sich das selber retten kann.
Wenn keine Antwort vom Broker gekommen ist, kann man auch nicht erwarten, dass eine normale Abmeldung möglich ist. u.U. muss da aber noch was wegen der Meldung an die Fhem-Readings gemacht werden...

Hier mal die Codeänderung:
#####################################
sub
MQTT2_CLIENT_Read($)
{
  my ($hash) = @_;

  my $name = $hash->{NAME};
  my $fd = $hash->{FD};

  my $buf = DevIo_SimpleRead($hash);
  if(!defined($buf)) {
    DevIo_Disconnected($hash);
    return "";
  }
  $hash->{BUF} .= $buf;

  RemoveInternalTimer($hash, 'MQTT2_CLIENT_Read_Consume');
  MQTT2_CLIENT_Read_Consume($hash);
}

#####################################
sub
MQTT2_CLIENT_Read_Consume($)
{
  my ($hash) = @_;

  my $name = $hash->{NAME};
  my $fd = $hash->{FD};

  my ($tlen, $off) = MQTT2_CLIENT_getRemainingLength($hash);
  if($tlen < 0 || $tlen+$off<=0) {
    Log3 $name, 1, "Bogus data from $name, closing connection";
    DevIo_Disconnected($hash);
    return;
  }
  return if(length($hash->{BUF}) < $tlen+$off);

  my $fb = substr($hash->{BUF}, 0, 1);
  my $pl = substr($hash->{BUF}, $off, $tlen); # payload
  $hash->{BUF} = substr($hash->{BUF}, $tlen+$off);

  my $cp = ord(substr($fb,0,1)) >> 4;
  my $cpt = $cptype{$cp};
  $hash->{lastMsgTime} = gettimeofday();

  # Lowlevel debugging
  if(AttrVal($name, "verbose", 1) >= 5) {
    my $pltxt = $pl;
    $pltxt =~ s/([^ -~])/"(".ord($1).")"/ge;
    Log3 $name, 5, "$name: received $cpt $pltxt";
  }

  ####################################
  if($cpt eq "CONNACK")  {
    my $rc = ord(substr($pl,1,1));
    if($rc == 0) {
      MQTT2_CLIENT_doinit($hash);

    } else {
      my @txt = ("Accepted", "bad proto", "bad id", "server unavailable",
                  "bad user name or password", "not authorized");
      Log3 $name, 1, "$name: Connection refused, ".
        ($rc <= int(@txt) ? $txt[$rc] : "unknown error $rc");
      $hash->{authError} = $rc;
      MQTT2_CLIENT_Disco($hash);
      return;
    }

  } elsif($cpt eq "PUBACK") {
    shift(@{$hash->{qosQueue}}) if($hash->{qosQueue});

  } elsif($cpt eq "SUBACK") {
    MQTT2_CLIENT_doinit($hash) if($hash->{connecting});

  } elsif($cpt eq "PINGRESP") {
    delete($hash->{waitingForPingRespSince});
   
  } elsif($cpt eq "PUBLISH")  {
    my $cf = ord(substr($fb,0,1)) & 0xf;
    my $qos = ($cf & 0x06) >> 1;
    my ($tp, $val, $pid);
    ($tp, $off) = MQTT2_CLIENT_getStr($pl, 0);
    if($qos) {
      $pid = unpack('n', substr($pl, $off, 2));
      $off += 2;
    }
    $val = substr($pl, $off);
    MQTT2_CLIENT_send($hash, pack("CCnC*", 0x40, 2, $pid)) if($qos); # PUBACK

    if(!IsDisabled($name)) {
      $val = "" if(!defined($val));

      my $ir = AttrVal($name, "ignoreRegexp", undef);
      next if(defined($ir) && "$tp:$val" =~ m/$ir/);

      my $ac = AttrVal($name, "autocreate", "no");
      $ac = $ac eq "1" ? "simple" : ($ac eq "0" ? "no" : $ac); # backward comp.

      my $cid = makeDeviceName($hash->{clientId});
      $tp =~ s/:/_/g; # 96608
      Dispatch($hash, "autocreate=$ac\0$cid\0$tp\0$val", undef, $ac eq "no");

      my $re = AttrVal($name, "rawEvents", undef);
      DoTrigger($name, "$tp:$val") if($re && $tp =~ m/$re/);
    }

  } else {
    Log 1, "M2: Unhandled packet $cpt, disconneting $name";
    MQTT2_CLIENT_Disco($hash);
  }
 
  InternalTimer(gettimeofday(), 'MQTT2_CLIENT_Read_Consume', $hash, 0);
 
  return undef;
  }

Im Prinzip wurde nur die Verarbeitung der Nachrichten aus der ReadFn verschoben in eine Consume-Funktion, die sich dann selber mittels Timer sofort wieder aufrufen läßt, wenn noch etwas im Buffer ist.
Der erste Aufruf dieser Consume-Funktion erfolgt noch direkt durch die ReadFn, sodass damit die Consume-Kette angestossen wird.

Hier mal der Patch:
Index: 00_MQTT2_CLIENT.pm
===================================================================
--- 00_MQTT2_CLIENT.pm (revision 22441)
+++ 00_MQTT2_CLIENT.pm (working copy)
@@ -325,26 +325,37 @@

#####################################
sub
-MQTT2_CLIENT_Read($@)
+MQTT2_CLIENT_Read($)
{
-  my ($hash, $reread) = @_;
+  my ($hash) = @_;

   my $name = $hash->{NAME};
   my $fd = $hash->{FD};

-  if(!$reread) {
-    my $buf = DevIo_SimpleRead($hash);
-    if(!defined($buf)) {
-      MQTT2_CLIENT_Disco($hash);
-      return "";
-    }
-    $hash->{BUF} .= $buf;
+  my $buf = DevIo_SimpleRead($hash);
+  if(!defined($buf)) {
+    DevIo_Disconnected($hash);
+    return "";
   }
+  $hash->{BUF} .= $buf;

+  RemoveInternalTimer($hash, 'MQTT2_CLIENT_Read_Consume');
+  MQTT2_CLIENT_Read_Consume($hash);
+}
+
+#####################################
+sub
+MQTT2_CLIENT_Read_Consume($)
+{
+  my ($hash) = @_;
+
+  my $name = $hash->{NAME};
+  my $fd = $hash->{FD};
+
   my ($tlen, $off) = MQTT2_CLIENT_getRemainingLength($hash);
   if($tlen < 0 || $tlen+$off<=0) {
     Log3 $name, 1, "Bogus data from $name, closing connection";
-    MQTT2_CLIENT_Disco($hash);
+    DevIo_Disconnected($hash);
     return;
   }
   return if(length($hash->{BUF}) < $tlen+$off);
@@ -422,8 +433,11 @@
     Log 1, "M2: Unhandled packet $cpt, disconneting $name";
     MQTT2_CLIENT_Disco($hash);
   }
-  return MQTT2_CLIENT_Read($hash, 1);
-}
+ 
+  InternalTimer(gettimeofday(), 'MQTT2_CLIENT_Read_Consume', $hash, 0);
+ 
+  return undef;
+  }

######################################
# send topic to client if its subscriptions matches the topic


Ich habe das bei mir jetzt drei Tage sehr stabil laufen. In dieser Zeit hatte ich keinen Abbruch meiner Verbindung mehr, und auch keine größeren Freezes. Außerdem reagiert Fhem deutlich zügiger auf der Weboberfläche...

Vielleicht kannst du das ja einfließen lassen. Danke schon mal...

Grüße
Reinerlein

Tut mir leid, die Benachrichtigung fuer dieses Thema wurde bei mir nie aktiviert, ich habe die Diskussion nur per Zufall wieder gefunden.

Zu den vielen Punkten:
- falls eine Event-Verarbeitung 2.5 Sekunden braucht, dann ist da was falsch, entweder beim Definieren der Instanzen, oder in den Modulen. Kannst Du ein "attr global verbose 5" Log eines Events hier anhaengen? Ich meine, da passiert deutlich mehr, als das gezeigte userReadings.
- MQTT2_DEVICE ist (noch) nicht optimiert fuer eine sehr grosse Menge an readingsList Zeilen. Vieviele sind es in deinem Fall?
- mit InternalTimer ermoeglichst Du, dass zwischen der Abarbeitung einzelner Events IO stattfindet. Das ist sinnvoll fuer ueberlastete Systeme, wichtiger waere aber die Ueberlastung zu vermeiden. Ich habe die Idee trotzdem aufgegriffen, und sie in MQTT2_CLIENT und MQTT2_SERVER eingebaut.
- den MQTT2_CLIENT_Disco Aufruf habe ich gelassen, aber die Funktion mit einem $noMsg Parameter erweitert. Allerdings meine ich, dass bei ausbleibenden PINGRESP man noch ein normales Disconnect versuchen sollte.

Zitat- MQTT2_DEVICE ist (noch) nicht optimiert fuer eine sehr grosse Menge an readingsList Zeilen. Vieviele sind es in deinem Fall?

Wenn deine 16 Shelly Devices alle 3ems sind, dann sind das (wenn ich das shelly3em Template richtig lese) 16*32 = 512 readingsList Zeilen, die pro Event alle mindestens 2-mal geprueft werden.

Bis mir einfaellt, wie ich das Modul fuer solche Faelle optimieren kann, schlage ich vor im template die 25 emeter Zeilen in readingsList gegen Folgendes auszutauschen:
shellies/DEVNAME/emeter/./.* { $TOPIC =~ m,emeter/(.)/(.*),;; { "emeter_$1_$2" => $EVENT } }\
shellies/DEVNAME/emeter/./total:.* {$TOPIC =~ m,emeter/(.)/.*,;; {"emeter_$1_kWh" => sprintf("%.2f",$EVENT/1000)}}

Das sollte die Anzahl der Pruefungen auf 144 (ca ein drittel) verringern.

Hi Rudi,

diese Zeitverzögerung habe ich bei allen Topics, die abgearbeitet werden. Bei den meisten habe ich natürlich keinerlei Notify oder userreadings dran.
Aber ich habe einige Statistik-Werte eingerichtet.

Die ReadingLists sind natürlich teilweise eine Menge...
Ein normaler Shelly-Schalter hat schon so 12 Einträge im Attribut ReadingList stehen. Teilweise mit mehreren "json2nameValue".
Ein EM3 hat 28 Einträge... aber den habe ich momentan auch nur einmal...

Hier mal ein Log:(im Anhang, wieder gelöscht)

Kannst Du bitte deinen Beitrag modifizieren, und das Log als Anhang hinzufuegen?

Weiterhin interessiert mich die Ausgabe von
{ @{$ntfyHash{"*"}}." ".@{$ntfyHash{"Statistik"}} }

Sonst:
- wovor ich Angst gehabt habe (das Matchen der vielen Regexps) scheint kaum Zeit in Anspruch zu nehmen (<10s)
- die Statistik scheint viel Unsinn zu treiben, nimmt aber nicht sooo viel Zeit in Anspruch, pro Event ca 40ms
- das durch die Statistik ausgeloesten Events tun allerdings weh mit 100ms, auch wenn scheinbar niemand daran Interesse hat.
- kannst Du testweise pruefen, wie sich das System verhaelt ohne Statistik? (ich meine damit ein verbose 5 Log fuer ein Event)
- hast Du viele DOIFs?

Hi Rudi,

die Ausgabe erzeugt eine Fehlermeldung:
Can't use an undefined value as an ARRAY reference at (eval 6454273) line 1.
Leider weiß ich nicht genau, was da raus kommen sollte, und kann es deshalb nicht selber korrigieren. Kannst du mir da helfen?

Hier das Log mit Statistik disabled:
2020.07.23 22:01:24.122 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/power => 1_power
2020.07.23 22:01:24.128 5: Starting notify loop for hwr_Hausstrom, 2 event(s), first is 1_power: 349.17
2020.07.23 22:01:24.129 5: statistics Statistik: Notify.296 Notification of 'hwr_Hausstrom' received. Update statistics.
2020.07.23 22:01:24.178 5: Starting notify loop for global_Powerlist, 1 event(s), first is hwr_Hausstrom.power:d: <html><div style='text-align:right'>1318.5 W</div></html>
2020.07.23 22:01:24.204 5: End notify loop for global_Powerlist
2020.07.23 22:01:24.206 5: Starting notify loop for global_Powerlist, 13 event(s), first is min: 0.00
2020.07.23 22:01:24.255 5: End notify loop for global_Powerlist
2020.07.23 22:01:24.293 5: End notify loop for hwr_Hausstrom
2020.07.23 22:01:24.300 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/pf => 1_pf
2020.07.23 22:01:24.307 5: Starting notify loop for hwr_Hausstrom, 1 event(s), first is 1_pf: 0.88
2020.07.23 22:01:24.308 5: statistics Statistik: Notify.296 Notification of 'hwr_Hausstrom' received. Update statistics.
2020.07.23 22:01:24.374 5: End notify loop for hwr_Hausstrom
2020.07.23 22:01:24.381 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/current => 1_current
2020.07.23 22:01:24.391 5: Starting notify loop for hwr_Hausstrom, 2 event(s), first is 1_current: 1.68
2020.07.23 22:01:24.392 5: statistics Statistik: Notify.296 Notification of 'hwr_Hausstrom' received. Update statistics.
2020.07.23 22:01:24.481 5: End notify loop for hwr_Hausstrom
2020.07.23 22:01:24.485 4: MQTT2_DEVICE_Parse: hwr_Hausstrom shellies/shellyem3-68C63AFB3952/emeter/1/voltage => 1_voltage
2020.07.23 22:01:24.496 5: Starting notify loop for hwr_Hausstrom, 1 event(s), first is 1_voltage: 237.22
2020.07.23 22:01:24.497 5: statistics Statistik: Notify.296 Notification of 'hwr_Hausstrom' received. Update statistics.
2020.07.23 22:01:24.563 5: End notify loop for hwr_Hausstrom
2020.07.23 22:01:25.587 4: Connection closed for WEB_Black_192.168.0.32_56041: Connection reset by peer
2020.07.23 22:01:26.504 5: publish received for sensors/garten_Schrank_01/Uptime/Value, 36460
2020.07.23 22:01:26.506 5: Starting notify loop for garten_Schrank_01, 1 event(s), first is transmission-state: incoming publish received
2020.07.23 22:01:26.554 5: End notify loop for garten_Schrank_01
2020.07.23 22:01:26.555 5: calling readingsSingleUpdate(garten_Schrank_01,Uptime,36460,1)
2020.07.23 22:01:26.556 5: Starting notify loop for garten_Schrank_01, 1 event(s), first is Uptime: 36460
2020.07.23 22:01:26.604 5: End notify loop for garten_Schrank_01
Das ist deutlich kürzer... Also liegt das an Statistik... kennst du dich damit aus? Bring es etwas möglichst *ein* Statistik-Device pro zu übewachendem Device zu haben? Oder ändert das sowieso nix?
Momentan ist es ja ein einziges Statistik-Device für alle...

DOIFs habe ich so ca. 50, wieso?

Grüße
Reinerlein

Moin,

{ join "\n", @{$ntfyHash{"*"}} }
liefert bei mir auch keine Ausgabe, die irgendwas mit einem Gerät TYPE=statistics zu tun hätte... (Hier läuft auch 1 statistics für mehrere Geräte - allerdings noch nicht sooo lange; NOTIFYDEV ist aber im list des statistics-Device vorhanden).

Irgendwie werde ich den Verdacht nicht los, dass die Verzögerung was mit dem Loggen (v.a. der Statistik-Werte!) zu tun hat. Nutzt du DBLog? Wenn ja, ist das optimiert?

Zu DOIF: Soweit mir bekannt, hängt das sich das seit einigen Monaten (?) in die normale notify-Verarbeitung rein, was lt. Aussage des Modulautors 30% Performance-Gewinn bedeuten würde... Das Modul dürfte aber aktuell sein, oder?

@Rudi, noch was anderes, was mir jüngst in MQTT2_DEVICE aufgefallen ist. Da wird in Zeile 161 eine Array-Variable @retData eingeführt, ich verstehe allerdings nicht so recht, welchen Zweck die anschließend hat, außer - ohne weitere Auswertungsaktion - gefüllt zu werden?
(Hat allerdings vermutlich nichts substantielles mit den Verzögerungen zu tun).

@Reinerlein: sorry, haette denken koennen, dass fuer Statistik keine extra Schlange angelegt wird: es gibt kein notify/DOIF/FileLog/etc, was explizit danach fragt. Ersatz:
fhem> trigger global x
fhem> { @{$ntfyHash{"*"}}  }
trigger garantiert, dass ntfyHash{"*"} angelegt ist.

Das Problem ist nicht so sehr statistik an sich (mit 40ms), sondern dass es scheinbar zusaetzliche Event-Loops anstoesst, die bei dir ueber 100ms dauern, selbst wenn kein notify/DOIF/etc an den Daten interessiert ist:

Zitat2020.07.23 19:39:05.075 5: Starting notify loop for Statistik, 1 event(s), first is Updated stats for: hwr_Hausstrom
2020.07.23 19:39:05.185 5: End notify loop for Statistik

fhem.pl versucht sinnlose NotifyFn Aufrufe durch den NOTIFYDEV Internal (bzw. mit dem daraus abgeleiteten ntfyHash) zu vermeiden, diese festzustellen gelingt aber nicht immer. Ich habe den Verdacht, dass DOIF NOTIFYDEV nicht setzt, deswegen DOIF:NotifyFn sinnlos aufgerufen wird, und die Pruefung, ob ein Event relevant ist, lange dauert.
Das kann fuer andere Module genauso gelten, ich habe nur DOIF ausgepickt, weil es komplex ist, und eine Pruefung vmtl. aufwendig.

Kannst Du bitte in fhem.pl, Zeile 3175 (vor dem NotifyFn Aufruf)
Log 1, "Calling $dev $n";
einfuegen, und das Ergebnis hier zeigen? Ich will damit sehen, welches NotifyFn wie lange braucht.


@Beta-User: danke fuer den Hinweis, habe retData entfernt.

Hi Rudi, hallo Beta-User,

ja, mein System ist aktuell. Unterschiede gibt es aktuell nur in der Änderung von mir...

Die Angabe von
{ join "\n", @{$ntfyHash{"*"}} }

ergibt:
DbLog
FileLog_CULMAX
FileLog_DELETE_aussen_Einfahrt_PIR
FileLog_DELETE_aussen_Einfahrt_Switch_01
FileLog_DELETE_vorgarten_Gehweg
FileLog_Sonos_Jim
FileLog_aussen_Terrasse_Steckdose_Kamin
FileLog_aussen_Terrasse_Steckdose_Wand
FileLog_aussen_Terrasse_Switch_01
FileLog_flur_Delete_Klingel
FileLog_flur_Delete_Taster
FileLog_garten_Regensensor_Rain
FileLog_garten_Schrank_Steckdose_Innen_02
FileLog_hwr_Heizung_FernwaermeTemperatur
FileLog_hwr_Heizung_KreisTemperatur
FileLog_hwr_Heizungsanlage
FileLog_hwr_Lueftung
FileLog_hwr_Taster_Ausgang
FileLog_hwr_WasserTemperatur
FileLog_myTwilight
FileLog_rauchmelder_Joe_OLD
FileLog_schlafzimmer_temp
FileLog_server_ShellyAnnounce
FileLog_unbekannt_Garagentorantrieb_1
FileLog_unbekannt_Garagentorantrieb_10
FileLog_unbekannt_Garagentorantrieb_11
FileLog_unbekannt_Garagentorantrieb_12
FileLog_unbekannt_Garagentorantrieb_3
FileLog_unbekannt_Garagentorantrieb_5
FileLog_unbekannt_Garagentorantrieb_6
FileLog_unbekannt_Garagentorantrieb_7
FileLog_unbekannt_Garagentorantrieb_8
FileLog_unbekannt_Garagentorantrieb_9
FileLog_vorgarten_Fahrradschuppen_PIR_DOIF
FileLog_weihnachten_Aussen_Lightscene
FileLog_weihnachten_Innen_Lightscene
FileLog_wohnzimmer_Sensorfeld_1
FileLog_wohnzimmer_Sensorfeld_2
FileLog_wohnzimmer_Sensorfeld_3
FileLog_wohnzimmer_Sensorfeld_4
FileLog_wohnzimmer_Sensorfeld_5
FileLog_wohnzimmer_Sensorfeld_6
FileLog_wohnzimmer_Sensorfeld_7
FileLog_wohnzimmer_Sensorfeld_8
FileLog_wohnzimmer_Stehlampe
HMLAN
Logfile
SonosRG
Sonos_GaestezimmerRG_Favourites
Sonos_GaestezimmerRG_Playlists
Sonos_GaestezimmerRG_Queue
Sonos_GaestezimmerRG_Radios
Sonos_WohnzimmerRG_Favourites
WEBGeoFancy
WEB_Black
WEB_Default
aussen_Einfahrt_Lightscene
aussen_Terrasse_Lightscene
aussen_Terrasse_TuerLightscene
aussen_Vorgarten_Lightscene
automation_Anwesenheit_Eltern_Lightscene
automation_Fernsehen_LightScene
dash
eventTypes
expandJSON
expandJSON_TasmotaDevices
flur_Taster_Notify
garten_Beleuchtung_LightScene
garten_Regen_HourCounter
global_ActiveDevices
global_Batteries_StateChanger
global_Batteries_StateWatchdog
global_Batteries_StateWatchdogVorlage
global_Home_Notify
global_InnenTemperatur
global_Monitoring_DeviceActivity
global_Monitoring_DeviceActivityNotify
global_Monitoring_DeviceActivity_SetActivityNotify
global_Monitoring_WindowOpen
global_OpenedDevices
global_OverTemperature
global_Panic_Lightscene
global_Panic_Notify
global_Powerlist
global_ShellyStates
global_batteries
heizung_Arbeitszimmer
heizung_Arbeitszimmer_WT
heizung_Bad
heizung_BadFussboden
heizung_Bad_FK_Links
heizung_Bad_FK_Rechts
heizung_Bad_TK
heizung_Bad_WT
heizung_Flur
heizung_Flur_WT
heizung_GaesteWC
heizung_GaesteWC_FK
heizung_GaesteWC_TK
heizung_GaesteWC_WT
heizung_Gaestezimmer
heizung_Gaestezimmer_FK_Links
heizung_Gaestezimmer_FK_Rechts
heizung_Gaestezimmer_WT
heizung_Jim
heizung_Jim_FK_Links
heizung_Jim_FK_Rechts
heizung_Jim_TK
heizung_Jim_WT
heizung_Joe
heizung_Joe_FK
heizung_Joe_TK
heizung_Joe_WT
heizung_ModusWechsel_Notify
heizung_Sammler_FK
heizung_Sammler_FTK
heizung_Sammler_NotifyFK
heizung_Sammler_Stellventile
heizung_Sammler_Stellventile_Trigger
heizung_Sammler_Vorgabe
heizung_Sammler_Wandthermostate
heizung_Schlafzimmer
heizung_Schlafzimmer_FK_Links
heizung_Schlafzimmer_FK_Rechts
heizung_Schlafzimmer_WT
heizung_TK_Notify
heizung_Weekprofile
heizung_Wohnzimmer
heizung_Wohnzimmer_FK_Terrasse_Rechts
heizung_Wohnzimmer_WT
heizung_global_ecobtn
hmInfo
hwr_Fritzbox_CallList_RG
hwr_FrizboxNew_PresenceLog
hwr_Hausstrom_Watchdog
hwr_Heizungsanlage_Watchdog
hwr_Lueftung_Notify
ledBeleuchtung_Lightscene
modbus
mqtt_LostConnectionNotify
rauchmelder_Uebersicht
sensorlog
vorgarten_Beetbeleuchtung_Lightscene
weihnachten_Aussen_Lightscene
weihnachten_Innen_Lightscene
wohnzimmer_AVReceiver_Zone2_Hours
wohnzimmer_AVSystem
wohnzimmer_Lightscene_Fernsehmodus
wohnzimmer_TasterTerrasse_1_Notify_Short
wohnzimmer_TasterTerrasse_2_Notify_Short
wohnzimmer_TasterTerrasse_3_Notify_Short
wohnzimmer_TasterTerrasse_4_Notify_Short
wohnzimmer_TasterTerrasse_5_Notify_Short
wohnzimmer_TasterTerrasse_6_Notify_Short
wohnzimmer_XBox_Hours
myFreezemon
WEB_Black_192.168.0.66_58366
WEB_Default_192.168.0.14_39453
WEB_Default_192.168.0.14_44962
DBLog ist zwar definiert, aber auf disable, da ich es bislang noch nicht aktiv verwenden wollte... das waren nur Tests...

Die Angabe von:
{ @{$ntfyHash{"*"}}  }
ergibt 159

Wie ist die Ausgabe zu verstehen?
Sollen das die sein, die ein Sternchen im NotifyDev haben. Das haben ja im Prinzip alle, da ich ja spätestens beim Wert ein Sternchen habe...

Es werden aktuell nur von meinem EM3 die Statistiken weggespeichert (alles in FileLog), wobei es dort aber nur zwei "_Last"-Statistiken betrifft:
- hwr_Hausstrom:statEnergy_totalKWhLast:.*
- hwr_Hausstrom:statPowerHourLast:.*
Damit fülle ich dann meine Vergangenheitsplots. Das ist aber auch nur jeweils einer pro Stunde...

Ansonsten wird schon einiges ins Log geschrieben. An meinem EM3 z.B.:
hwr_Hausstrom:0_energyKWh:.*
hwr_Hausstrom:0_energy_totalKWh:.*
hwr_Hausstrom:0_power:.*
hwr_Hausstrom:1_energyKWh:.*
hwr_Hausstrom:1_energy_totalKWh:.*
hwr_Hausstrom:1_power:.*
hwr_Hausstrom:2_energyKWh:.*
hwr_Hausstrom:2_energy_totalKWh:.*
hwr_Hausstrom:2_power:.*
hwr_Hausstrom:energyKWh:.*
hwr_Hausstrom:energy_totalKWh:.*
hwr_Hausstrom:power:.*
hwr_Hausstrom:online:.*
hwr_Hausstrom:relay:.*

Grüße
Reinerlein

Hmm, ja, bin im Moment nicht sicher, wie viele Events statistics tatsächlich wirft.

Aber da FileLog: Kann es dann sein, dass die Logfile, in der
Ansonsten wird schon einiges ins Log geschrieben. An meinem EM3 z.B.:
landen, eine sehr große ist? Das könnte - ggf. in Verbindung mit der Aktualisierung von Plots - das System durchaus ausbremsen, oder?

$ntfyHash{"*"} enthaelt die Liste der "notify"-Instanzen (DOIF,FileLog,etc), deren Regexp fhem.pl nicht einzelnen Geraeten zuordnen konnte.
Die Laenge ist ein Hinweis darauf, wieviele unoptimierte Aufrufe erfolgen.

@Beta-User: Eine grosse FileLog Datei an sich ist kein Problem, die Suche nach dem ersten Eintrag ist relativ schnell. FileLog wird dann langsam, wenn im Bereich der anzuzeigenden Daten sehr viel Unnoetiges ist. D.h. falls eine Datei nur das enthaelt, was fuer ein SVG-Plot relevant ist, dann kann sie Daten fuer viele Jahre enthalten. Auf der anderen Seite sind Tages-Dateien, die alles sammeln, langsam. Fuer unser Problem hier sind beide Arten gleich, und vmtl. irrelevant.

@Reinerlein: Bitte das Log mit dem "Calling" Zeilen nicht vergessen.

Hallo,

ja, die eine EM3-Logdatei (mit den Power-Werten usw.) ist schon groß. Sie steht auf monatlich und hat jetzt für Juli knapp 730.000 Einträge.

Aber die Verzögerungen gab es ja von Anfang an, und auch, wenn ich nicht die Plots dazu auf der Oberfläche anzeige.
Das Schreiben in eine so große Datei sollte ja eigentlich keine zusätzliche Zeit benötigen...

@Rudi: In der angegebenen Zeile ist der Kommentar über der "sub sleep_WakeUpFn()". Meine fhem.pl ist vom 16.7.2020 - 9:19 (Version 22408)

Grüße
Reinerlein

Sorry, Zahlendreher, ich meinte 3715.
Vor dem einzigen CallFn(...,"NotifyFn",...)

Hi Rudi,

im Anhang mal das Log... ich habe davor ein Log für Calling und danach ein Log für Calling-End eingebaut. Das steht also direkt um den NotifyFn-Aufruf herum.

Grüße
Reinerlein

P.S.: Achtung, die Datei ist entpackt 12MB groß...

Ich sehe pro Event ca 150 (sinnlose) Aufrufe, jeweils mit ca 0.2ms, macht in Summe ca 30ms.
Dabei sind aber auch 2 WEB_Default Anrufe, die jeweils ca 30ms brauchen.

- es wundert mich, dass in deinem Fall die Filterung der notifies so schlecht funktioniert. Wie schauen deine Regexps aus? Z.Bsp. fuer wohnzimmer_TasterTerrasse_6_Notify_Short oder flur_Taster_Notify?
- die 2 WEB-Notifies klingen nach "Wandtablet". Kannst Du mehr dazu sagen?

Hi Rudi,

die WEB-Teile kommen daher, das ich mehrere Browserfenster offen hatte, um zügig die verbose-Einstellungen ändern zu können...

Diese Notifies sehen eigentlich normal aus:
wohnzimmer_TasterTerrasse_6_Notify_Short
Internals:
   DEF        wohnzimmer_TasterTerrasse_6.Short.* set garten_Beleuchtung_LightScene scene myOn
   FUUID      5d84d3a1-f33f-6779-19b5-aa2baffbc9977f48
   NAME       wohnzimmer_TasterTerrasse_6_Notify_Short
   NR         1020
   NTFY_ORDER 50-wohnzimmer_TasterTerrasse_6_Notify_Short
   REGEXP     wohnzimmer_TasterTerrasse_6.Short.*
   STATE      active
   TYPE       notify
   READINGS:
     2020-07-24 11:20:10   state           active
Attributes:

flur_Taster_Notify
Internals:
   DEF        flur_Taster set vorgarten_Gehweg on-for-timer 300
   FUUID      5d84d3a0-f33f-6779-86a6-2666224ad2c84a4c
   NAME       flur_Taster_Notify
   NR         409
   NTFY_ORDER 50-flur_Taster_Notify
   REGEXP     flur_Taster
   STATE      active
   TYPE       notify
   READINGS:
     2020-07-24 11:20:10   state           active
Attributes:

Ich habe auch einige auf der Notify-Liste gesehen, die eigentlich sehr genau definiert sind. Hauptsächlich Lightscene, wo ja jedes Device im Define angegeben wird oder auch Max-Devices. Und natürlich ein Haufen FileLog-Devices...
Es scheint so zu sein, dass einige Module "NOTIFYDEV" nicht setzen. In diesen Fällen taucht das dann hier auf der Device-Unbestimmten-Liste auf.
Das muss wohl jedes Modul selber machen... leider scheinen das einige Module, die auch noch oft in einer Installation genutzt werden, nicht zu tun...

Grüße
Reinerlein

ZitatDiese Notifies sehen eigentlich normal aus:

Normal schon, leider erkennt fhem.pl nicht das Geraet: es gibt kein NOTIFYDEV Internal.
Um es zu erkennen, muesste es "wohnzimmer_TasterTerrasse_6:Short.* heissen, weil : als Trenner zwischen Geraetename und Event dient, und notifyRegexpChanged das : braucht, um ein Geraet zu erkennen.

Um das bessere Regexp einfacher zu finden habe ich eine Funktion notifyRegexpCheck eingecheckt, hier sind ein paar Beispiele.
Die Testinstallation kennt mehrere Geraete die mit s300 anfangen und wz.

fhem> { notifyRegexpCheck('s300th_og') }
s300th_og: device s300th_og (OK)

fhem> { notifyRegexpCheck('s300.*T.*') }
s300.*T.*: no match (ignored)

fhem> { notifyRegexpCheck('s300.*:T.*') }
s300.*:T.*: devspec s300th_2,s300th_dach,s300th_keller,s300th_kueche,s300th_og (OK)

fhem> { notifyRegexpCheck('s300.*:T.*|wz.*temperature.*') }
s300.*:T.*: devspec s300th_2,s300th_dach,s300th_keller,s300th_kueche,s300th_og (OK)
wz.*temperature.*: no match (ignored)

fhem> { notifyRegexpCheck('(s300.*:T|wz:temperature).*') }
(s300.*:T: devspec s300th_2,s300th_dach,s300th_keller,s300th_kueche,s300th_og (OK)
wz:temperature).*: device wz (OK)


Hi Rudi,

ok, danke für den Tipp, dann baue ich das mal entsprechend um.
Vielleicht sollte man in der Doku darauf hinweisen. Für mich waren die beiden Varianten equivalent... zumal ja beides funktioniert...

Aber auch da habe ich gerade ein Device gefunden, wo es eigentlich korrekt drinsteht, aber trotzdem kein notifydev gesetzt wurde:
Internals:
   DEF        /opt/fhem/log/garten_Regensensor_Rain-%Y-%m.log garten_Regensensor_Heating:state:.(on|off)|garten_Regensensor_Rain:state:.*|garten_Regensensor_Rain:stateNumber:.*
   FD         161
   FUUID      5d84d3b9-f33f-6779-51d7-4f0a7d65a282a433
   NAME       FileLog_garten_Regensensor_Rain
   NR         1522
   NTFY_ORDER 50-FileLog_garten_Regensensor_Rain
   REGEXP     garten_Regensensor_Heating:state:.(on|off)|garten_Regensensor_Rain:state:.*|garten_Regensensor_Rain:stateNumber:.*
   STATE      active
   TYPE       FileLog
   currentlogfile /opt/fhem/log/garten_Regensensor_Rain-2020-07.log
   logfile    /opt/fhem/log/garten_Regensensor_Rain-%Y-%m.log
   READINGS:
     2020-07-24 17:59:46   linesInTheFile  2528
Attributes:
   addStateEvent 1

Da kämen halt zwei Devices rein:
garten_Regensensor_Heating,garten_Regensensor_Rain

Muss man noch was anderes beachten?

Grüße
Reinerlein

Hi Rudi,

außerdem habe einige Regexp in dem Stil:


Internals:
   DEF        /opt/fhem/log/hwr_WasserTemperatur-%Y-%m.log hwr_WasserTemperatur:(temperature|diffTemp).*
   FD         15
   FUUID      5d84d3a0-f33f-6779-cd4b-a739785e66630cd0
   NAME       FileLog_hwr_WasserTemperatur
   NR         222
   NTFY_ORDER 50-FileLog_hwr_WasserTemperatur
   REGEXP     hwr_WasserTemperatur:(temperature|diffTemp).*
   STATE      active
   TYPE       FileLog
   currentlogfile /opt/fhem/log/hwr_WasserTemperatur-2020-07.log
   logfile    /opt/fhem/log/hwr_WasserTemperatur-%Y-%m.log
   READINGS:
     2020-07-24 18:29:18   linesInTheFile  27263
Attributes:
   logtype    myWaterTemp:Temp,text
Das verwende ich gerne, wenn ich mehrere Readings eines Devices matchen möchte...

Grüße
Reinerlein

Mit der neuen Funktion sieht man, wie fhem.pl "denkt":
fhem> { notifyRegexpCheck('garten_Regensensor_Heating:state:.(on|off)|garten_Regensensor_Rain:state:.*|garten_Regensensor_Rain:stateNumber:.*') }
garten_Regensensor_Heating:state:.(on: device garten_Regensensor_Heating (OK)
off): unknown (ignored)
garten_Regensensor_Rain:state:.*: device garten_Regensensor_Rain (OK)
garten_Regensensor_Rain:stateNumber:.*: device garten_Regensensor_Rain (OK)



Damit NOTIFYDEV angelegt wird, muss (on|off) entweder samt device verdoppelt werden, oder als o[nf]+ geschrieben werden, oder...
NOTIFYDEV ist kein _muss_, es ermoeglich aber fhem.pl eine Optimierung vorzunehmen.

There is a small bug in notifyRegexpCheck when devspec2array returns a single item. Also avoids PERL WARNING "isn't numeric".

fhem> {devspec2array 'Rt_EnO.+'}
1
fhem> {notifyRegexpCheck 'Rt_EnO.+' }
Rt_EnO.+: unknown (ignored)

Patch:
@@ -5418,7 +5426,7 @@
       "$_: device $1 (OK)";
     } else {
       my @ds = devspec2array($1);
-      if(@ds > 1 || $ds[0] != $1) {
+      if(@ds > 1 || $ds[0] ne $1) {
         "$_: devspec ".join(",",@ds)." (OK)";
       } else {
         "$_: unknown (ignored)";


I suppose @ds > 1 is also not necessary.

Thanks, Patch applied.

Seit einem Update vor ein paar Tagen habe ich nun das Problem, dass sich meine MQTT Clients ständig neu anmelden, und zwar immer dann, wenn der FHEM-Prozess unter hoher Last fährt (Rendern von mehreren SVG-Plots oder Rastern skalierter SVG-Icons für einen RSS Feed), und dann für eine Weile auf 100% CPU läuft. So weit ich sehen kann, gab es da diese Änderung:

http://svn.fhem.de/trac/changeset/22454/trunk/fhem/FHEM/00_MQTT2_SERVER.pm

Könnte die das Phänomen verursachen?

List vom MQTT2_SERVER:

Internals:
   CONNECTS   24063
   DEF        1883 global
   FD         8
   FUUID      5e2b233f-f33f-edb2-bdca-36d41dc0d88c567e
   NAME       mqtt
   NR         43
   PORT       1883
   STATE      Initialized
   TYPE       MQTT2_SERVER
   READINGS:
     2020-08-13 07:49:25   RETAIN          {"cmd/climate/bedroom/backlight":"0","cmd/climate/bedroom/mode":"R","cmd/climate/bedroom/radiator":"0","cmd/climate/bedroom/setpoint":"24.6","cmd/climate/bedroom/tolerance":"0.1","cmd/climate/main/backlight":"0","cmd/climate/main/mode":"L","cmd/climate/main/radiator1":"0","cmd/climate/main/radiator2":"1","cmd/climate/main/setpoint":"30.0","cmd/climate/main/tolerance":"0.1","cmd/climate/server/backlight":"0","status/climate/bedroom/arduino":"1","status/climate/main/arduino":"1","status/climate/server/arduino":"1"}
     2020-05-02 16:58:44   lastPublish     status/server/climate/arduino:
     2020-08-13 08:43:02   nrclients       54
     2020-08-10 13:10:58   state           Initialized
   clients:
     mqtt_192.168.1.116_58005 1
     mqtt_192.168.1.117_58005 1
     mqtt_192.168.1.119_57967 1
   retain:
     cmd/climate/bedroom/backlight:
       ts         1597054259.15503
       val        0
     cmd/climate/bedroom/mode:
       ts         1597054259.15503
       val        R
     cmd/climate/bedroom/radiator:
       ts         1597054259.15503
       val        0
     cmd/climate/bedroom/setpoint:
       ts         1597054259.15503
       val        24.6
     cmd/climate/bedroom/tolerance:
       ts         1597054259.15503
       val        0.1
     cmd/climate/main/backlight:
       ts         1597054259.15503
       val        0
     cmd/climate/main/mode:
       ts         1597054259.15503
       val        L
     cmd/climate/main/radiator1:
       ts         1597054259.15503
       val        0
     cmd/climate/main/radiator2:
       ts         1597054259.15503
       val        1
     cmd/climate/main/setpoint:
       ts         1597054259.15503
       val        30.0
     cmd/climate/main/tolerance:
       ts         1597054259.15503
       val        0.1
     cmd/climate/server/backlight:
       ts         1597054259.15503
       val        0
     status/climate/bedroom/arduino:
       ts         1597294164.97552
       val        1
     status/climate/main/arduino:
       ts         1597294165.02614
       val        1
     status/climate/server/arduino:
       ts         1597294165.00912
       val        1
Attributes:
   autocreate no
   icon       it_i-net
   room       System->Interfaces

Ein MQTT2_DEVICE:

Internals:
   DEVICETOPIC climate_server
   FUUID      5ea5ae48-f33f-edb2-3a37-084c09f683aed438
   IODev      mqtt
   LASTInputDev mqtt
   MSGCNT     68079
   NAME       climate_server
   NR         48
   STATE      1:online
2:ok
3:off
<br>
28.8&deg;C
35.0&percnt;
   TYPE       MQTT2_DEVICE
   mqtt_MSGCNT 68079
   mqtt_TIME  2020-08-13 08:45:09
   READINGS:
     2020-08-13 08:44:59   absoluteHumidity 9.9
     2020-08-13 07:49:25   arduino         online
     2020-08-13 07:49:26   backlight       off
     2020-08-13 08:44:59   dewpoint        11.8
     2020-08-13 08:45:09   humidity        35.0
     2020-06-05 01:15:26   state           backlight
     2020-08-13 08:45:09   temperature     28.8
     2020-08-13 08:45:09   valid           ok
     2020-08-13 08:44:59   vapourPressure  13.8
Attributes:
   IODev      mqtt
   devStateIcon 1.online:arduino@green 1.offline:arduino@red 2.ok:temperature_humidity@green 2.error:temperature_humidity@red 3.on:light_light_dim_100@orange:backlight+off 3.off:light_light_dim_00@black:backlight+on
   event-on-change-reading .*
   icon       sani_heating_temp
   readingList status/climate/server/arduino:.* {{"arduino" => ($EVTPART0 ? "online" : "offline")}}
status/climate/server/humidity:.* humidity
status/climate/server/temperature:.* temperature
status/climate/server/valid:.* {{"valid" => ($EVTPART0 ? "ok" : "error")}}
status/climate/server/backlight:.* {{"backlight" => ($EVTPART0 ? "on" : "off")}}
   room       Rooms->Server,Sensors->Climate
   setList    backlight:on,off {"cmd/climate/server/backlight:r " . ($EVTPART1 eq "on" ? 1 : 0)}
   stateFormat 1:arduino
2:valid
3:backlight
<br>
temperature&deg;C
humidity&percnt;

Log-Auszug:

2020.08.13 08:49:49 4: Connection accepted from mqtt_192.168.1.119_59750
2020.08.13 08:49:50 4: Connection accepted from mqtt_192.168.1.117_59486
2020.08.13 08:49:50 5: in:  CONNECT: (16)<(0)(4)MQTT(4)&(0)(15)(0)(14)arduino_server(0)(29)status/climate/server/arduino(0)(1)0
2020.08.13 08:49:50 4:   mqtt_192.168.1.119_59750 cid:arduino_server CONNECT V:4 keepAlive:15 LWT:status/climate/server/arduino:0
2020.08.13 08:49:50 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:50 5: in:  CONNECT: (16)8(0)(4)MQTT(4)&(0)(15)(0)(12)arduino_main(0)(27)status/climate/main/arduino(0)(1)0
2020.08.13 08:49:50 4:   mqtt_192.168.1.117_59486 cid:arduino_main CONNECT V:4 keepAlive:15 LWT:status/climate/main/arduino:0
2020.08.13 08:49:50 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:50 4: Connection accepted from mqtt_192.168.1.116_58006
2020.08.13 08:49:50 5: in:  CONNECT: (16)>(0)(4)MQTT(4)&(0)(15)(0)(15)arduino_bedroom(0)(30)status/climate/bedroom/arduino(0)(1)0
2020.08.13 08:49:50 4:   mqtt_192.168.1.116_58006 cid:arduino_bedroom CONNECT V:4 keepAlive:15 LWT:status/climate/bedroom/arduino:0
2020.08.13 08:49:50 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:50 5: in:  PUBLISH: 1(30)(0)(27)status/climate/main/arduino1
2020.08.13 08:49:50 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/arduino:1
2020.08.13 08:49:50 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/arduino\0001
2020.08.13 08:49:51 5: in:  SUBSCRIBE: (130)(23)(0)(2)(0)(18)cmd/climate/main/+(0)
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main SUBSCRIBE
2020.08.13 08:49:51 4:   topic:cmd/climate/main/+ qos:0
2020.08.13 08:49:51 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.08.13 08:49:51 5: in:  PUBLISH: 0"(0)(28)status/climate/main/humidity43.5
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/humidity:43.5
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/humidity\00043.5
2020.08.13 08:49:51 5: in:  PUBLISH: 0%(0)(31)status/climate/main/temperature24.3
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/temperature:24.3
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/temperature\00024.3
2020.08.13 08:49:51 5: in:  PUBLISH: 0(28)(0)(25)status/climate/main/valid1
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/valid:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/valid\0001
2020.08.13 08:49:51 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:51 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:51 5: in:  PUBLISH: 1!(0)(30)status/climate/bedroom/arduino1
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/arduino:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/arduino\0001
2020.08.13 08:49:51 5: in:  SUBSCRIBE: (130)(26)(0)(2)(0)(21)cmd/climate/bedroom/+(0)
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom SUBSCRIBE
2020.08.13 08:49:51 4:   topic:cmd/climate/bedroom/+ qos:0
2020.08.13 08:49:51 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.08.13 08:49:51 5: in:  PUBLISH: 0%(0)(31)status/climate/bedroom/humidity46.0
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/humidity:46.0
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/humidity\00046.0
2020.08.13 08:49:51 5: in:  PUBLISH: 0((0)"status/climate/bedroom/temperature25.1
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/temperature:25.1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/temperature\00025.1
2020.08.13 08:49:51 5: in:  PUBLISH: 0(31)(0)(28)status/climate/bedroom/valid1
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/valid:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/valid\0001
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/tolerance:0.1
2020.08.13 08:49:52 5: out: PUBLISH: 0(31)(0)(26)cmd/climate/main/tolerance0.1
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/radiator2:1
2020.08.13 08:49:52 5: out: PUBLISH: 0(29)(0)(26)cmd/climate/main/radiator21
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/backlight:0
2020.08.13 08:49:52 5: out: PUBLISH: 0(29)(0)(26)cmd/climate/main/backlight0
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/mode:L
2020.08.13 08:49:52 5: out: PUBLISH: 0(24)(0)(21)cmd/climate/main/modeL
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/setpoint:30.0
2020.08.13 08:49:52 5: out: PUBLISH: 0(31)(0)(25)cmd/climate/main/setpoint30.0
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/radiator1:0
2020.08.13 08:49:52 5: out: PUBLISH: 0(29)(0)(26)cmd/climate/main/radiator10
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/backlight:0
2020.08.13 08:49:52 5: out: PUBLISH: 0 (0)(29)cmd/climate/bedroom/backlight0
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/radiator:0
2020.08.13 08:49:52 5: out: PUBLISH: 0(31)(0)(28)cmd/climate/bedroom/radiator0
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/setpoint:24.6
2020.08.13 08:49:52 5: out: PUBLISH: 0"(0)(28)cmd/climate/bedroom/setpoint24.6
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/tolerance:0.1
2020.08.13 08:49:52 5: out: PUBLISH: 0"(0)(29)cmd/climate/bedroom/tolerance0.1
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/mode:R
2020.08.13 08:49:52 5: out: PUBLISH: 0(27)(0)(24)cmd/climate/bedroom/modeR
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(29)status/climate/main/tolerance0.1
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/tolerance:0.1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/tolerance\0000.1
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0#(0) status/climate/bedroom/backlight0
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/backlight:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/backlight\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(31)status/climate/bedroom/radiator0
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/radiator:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/radiator\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0%(0)(31)status/climate/bedroom/setpoint24.6
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/setpoint:24.6
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/setpoint\00024.6
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/backlight0
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/backlight:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/backlight\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0(27)(0)(24)status/climate/main/modeL
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/mode:L
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/mode\000L
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0%(0) status/climate/bedroom/tolerance0.1
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/tolerance:0.1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/tolerance\0000.1
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0(30)(0)(27)status/climate/bedroom/modeR
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/mode:R
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/mode\000R
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(31)status/climate/bedroom/radiator0
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/radiator:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/radiator\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(28)status/climate/main/setpoint30.0
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/setpoint:30.0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/setpoint\00030.0
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:53 4: Connection accepted from mqtt_192.168.1.119_57967
2020.08.13 08:49:53 5: in:  CONNECT: (16)<(0)(4)MQTT(4)&(0)(15)(0)(14)arduino_server(0)(29)status/climate/server/arduino(0)(1)0
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 cid:arduino_server CONNECT V:4 keepAlive:15 LWT:status/climate/server/arduino:0
2020.08.13 08:49:53 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:53 5: in:  PUBLISH: 1 (0)(29)status/climate/server/arduino1
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/arduino:1
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/arduino\0001
2020.08.13 08:49:53 5: in:  SUBSCRIBE: (130)(25)(0)(2)(0)(20)cmd/climate/server/+(0)
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server SUBSCRIBE
2020.08.13 08:49:53 4:   topic:cmd/climate/server/+ qos:0
2020.08.13 08:49:53 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.08.13 08:49:53 5: in:  PUBLISH: 0$(0)(30)status/climate/server/humidity34.9
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/humidity:34.9
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/humidity\00034.9
2020.08.13 08:49:53 5: in:  PUBLISH: 0'(0)!status/climate/server/temperature28.8
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/temperature:28.8
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/temperature\00028.8
2020.08.13 08:49:53 5: in:  PUBLISH: 0(30)(0)(27)status/climate/server/valid1
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/valid:1
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/valid\0001
2020.08.13 08:50:26 5:   mqtt_192.168.1.119_57967 arduino_server => cmd/climate/server/backlight:0
2020.08.13 08:50:26 5: out: PUBLISH: 0(31)(0)(28)cmd/climate/server/backlight0
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.119_59750/arduino_server left us (keepalive check)
2020.08.13 08:50:26 4: Closing second connection for arduino_server/192.168.1.119 without lwt
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.116_58006/arduino_bedroom left us (keepalive check)
2020.08.13 08:50:26 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/arduino\0000
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.119_57967/arduino_server left us (keepalive check)
2020.08.13 08:50:26 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/arduino\0000
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.117_59486/arduino_main left us (keepalive check)
2020.08.13 08:50:26 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/arduino\0000

Dass die verlinkte Aenderung das Problem verursacht, ist zwar moeglich, aber nur bei einem blockierten System, und dann je nach Glueck und Umgebung funktioniert die alte oder die neue Methode besser. Ich habe noch meinen Zweifel daran, dass die Ursache des gemeldeten Problems diese Aenderung ist.

Ich sehe im Log keine Hinweise fuer eine Blockierung, evtl. hilft da "attr global verbose 5". Das einzige "Problem" im Log ist eine "keepalive check / left us", allerdings kommt das erst, nachdem das gleiche Geraet 30 Sekunden vorher eine zweite Verbindung aufgebaut hat, was bei "kaputten" WLAN oefters beobachtet wurde.

Falls man ein Blockieren des Systems beobachtet, dann sollte man das natuerlich fixen, z.Bsp. indem Plots mit "attr WEB plotEmbed 2" oder "attr WEB plotfork 1" in einem geforkten Prozess berechnet.

Zitat von: rudolfkoenig am 13 August 2020, 09:39:37
Ich sehe im Log keine Hinweise fuer eine Blockierung, evtl. hilft da "attr global verbose 5". Das einzige "Problem" im Log ist eine "keepalive check / left us", allerdings kommt das erst, nachdem das gleiche Geraet 30 Sekunden vorher eine zweite Verbindung aufgebaut hat, was bei "kaputten" WLAN oefters beobachtet wurde.

Mein Verdacht kommt u.a. daher, dass das Problem seit einem Update vor ein paar Tagen auftritt - davor war nichts dergleichen festzustellen, obwohl die CPU-Last gleich war. Deshalb hatte ich die Vermutung, dass durch die Methode mit InternalTimer in dem Fall die Kommunikation so lange verzögert bzw. der Timer so spät ausgelöst wird, dass der Client inzwischen einen Timeout feststellt und sich neu verbindet.

Zitat
Falls man ein Blockieren des Systems beobachtet, dann sollte man das natuerlich fixen, z.Bsp. indem Plots mit "attr WEB plotEmbed 2" oder "attr WEB plotfork 1" in einem geforkten Prozess berechnet.

Das werde ich auf jeden Fall versuchen. Wirkt sich das denn auch auf die Erzeugung von PNG Grafiken im RSS-Modul aus (und zwar nicht auf das Einbinden von SVG-Plots in PNG-Grafiken, sondern Icons, Text etc.). Bei SVG-Plots hatte ich schon vorher plotfork auf 1, nun versuche ich es auch mit plotEmbed auf 2. Beide führen noch zu anderen Problemen, aber die poste ich im SVG-Bereich, weil sie nicht zu diesem Thema passen.

Inzwischen habe ich die Ursache ausfindig machen können, weshalb FHEM bei mir für bis zu 30 Sekunden hängt und die Timeouts auftreten. Es handelt sich dabei um das RSS-Modul. Und zwar hatte ich in einem Feed zwei Laptop-Icons (http://forum.fhem.de/index.php/topic,12605.msg1073139.html#msg1073139), und anscheinend braucht Perl so lange, um die von SVG nach PNG zu konvertieren. Wenn ich die beiden durch andere ersetze, dauert es wenige Sekunden und das PNG erscheint. Da gibt es auch keine Verbindungsabbrüche mehr.

Vielleicht könnte man die Erzeugung von RSS-Feeds ähnlich wie die SVG-Plots optional über Fork auslagern, falls man doch mal etwas komplexeres rendern möchte... Ich werde das mal in einem eigenen Thread im entsprechenden Forum anregen.