98_statistics.pm: Triggert userreading ungewollt

[vbs]

Ich habe gerade ein kleines Problemchen mit dem statistik-Modul, welches ich mir nicht erklären kann:
Ich habe bei meinem Gas-Zähler ein userreading, das so aussieht:

Code Auswählen Erweitern

gasPowerRealKWh:gasCnt {getGasPowerReal()}

Also bei jedem gasCnt-Event sollte mein userreading gasPowerRealKWh durch Aufruf der Funktion getGasPowerReal gesetzt werden. Also der Gas-Zähler schickt ca. alle 2,5 Minuten seine Nachricht inkl. gasCnt und mein userreading wird auch brav aktualisiert. So weit so gut.
Nun ist es so: Sobald ich mein Gas-Zähler-Device vom Statistik-Modul überwachen lasse und in dessen DEF eintrage, dann wird bei jeder gasCnt-Änderung mein userreading gasPowerRealKWh immer zweimal aktualisiert. Das merke ich zB. daran, dass meine Funktion getGasPowerReal zweimal hintereinander läuft.

Im Event-Monitor jedoch taucht gasCnt immer nur einmal auf, darum versteh ich eigentlich erstmal nicht, warum mein userreading zweimal getriggert wird. Das sieht im Event-Monitor so aus:

Code Auswählen Erweitern


2015-07-10 18:48:06 CUL_HM env_gasMeter gasCnt: 1.82
2015-07-10 18:48:06 CUL_HM env_gasMeter gasPower: 1.729
2015-07-10 18:48:06 CUL_HM env_gasMeter costPerHour: 0.00
2015-07-10 18:48:06 CUL_HM env_gasMeter gasPowerRealKWh: 0.00
2015-07-10 18:48:06 CUL_HM env_gasMeter costPerHour: 0.00
2015-07-10 18:48:06 CUL_HM env_gasMeter gasPowerRealKWh: 0.00

Also das Gerät schickt gasCnt und gasPower. In meiner Funktion setze ich costPerHour und gasPowerRealKWh. Man sieht, dass die in der gleichen Sekunde immer doppelt gesetzt werden. Sobald ich den Gas-Zähler aus dem statistik-Modul rausnehme, passiert das nicht mehr.

Hat da evtl. jemand eine Idee zu? Also warum das passiert (Bug oder Feature?) und was man dagegen machen kann? Dankeschön!

[tupol]

Das Statistik Modul sendet ein Event für die statWerte, die es aktualisiert.

Ich bin mir nicht sicher, wie das userreading funktioniert. Da steht was von RegExpr und gasCnt kommt auch im statGasCnt vor.
Teste mal mit'^gasCnt$

Ansonsten, hast Du die event-on-... Attribute gesetzt?

[justme1968]

die user readings prüfen auf /^$trigger/ und auch case sensitiv. d.h. es passt eigentlich nicht.

warum nicht auf /^$trigger$/ geprüft wird weiss ich gerade nicht mehr. kann sein das das ein versehen ist.

gruss
  andre

[vbs]

Hi Tupol, danke für die schnelle Antwort!

Also wenn ich mein userreading ändere in:

Code Auswählen Erweitern


gasPowerRealKWh:^gasCnt$ {getGasPowerReal()}

dann triggerts erstmal gar nicht mehr.

Auch hier triggerts gar nicht mehr:

Code Auswählen Erweitern


gasPowerRealKWh:env_gasMeter.gasCnt {getGasPowerReal()}

Passt ja zu dem, was Andre gepostet hat.

Im Event-Monitor sieht mMn alles gut aus. Da kann ich einfach kein Event sehen, was ein zweites Triggern des userreadings rechtfertigen würde. Darum versteh ich das nicht
(Ich sehe da eigentlich auch die besagten stat*-Events nicht)

Code Auswählen Erweitern


...
2015-07-10 19:51:56 dummy wz_airSensor airQuality: 653.816309544088
2015-07-10 19:52:07 statistics env_stats Updated stats for: env_gasMeter
2015-07-10 19:52:07 CUL_HM env_gasMeter gasCnt: 1.98
2015-07-10 19:52:07 CUL_HM env_gasMeter gasPower: 1.686
2015-07-10 19:52:07 CUL_HM env_gasMeter costPerHour: 0.00
2015-07-10 19:52:07 CUL_HM env_gasMeter gasPowerRealKWh: 0.00
2015-07-10 19:52:07 CUL_HM env_gasMeter costPerHour: 0.00
2015-07-10 19:52:07 CUL_HM env_gasMeter gasPowerRealKWh: 0.00
2015-07-10 19:52:07 HMLAN HMLAN0 loadLvl: low
...


Hier ein list von meinem Gas- und von dem statistic-Device:

Code Auswählen Erweitern


Internals:
   DEF        3BD485
   HMLAN0_MSGCNT 42
   HMLAN0_RAWMSG E3BD485,0000,D4E3685C,FF,FFD5,D086533BD485000000000007BC000696
   HMLAN0_RSSI -43
   HMLAN0_TIME 2015-07-10 19:50:01
   IODev      HMLAN0
   LASTInputDev HMLAN0
   MSGCNT     42
   NAME       env_gasMeter
   NR         487
   NTFY_ORDER 50-env_gasMeter
   STATE      E: 1.98 P: 1.686
   TYPE       CUL_HM
   lastMsg    No:D0 - t:53 s:3BD485 d:000000 000007BC000696
   protCmdDel 4
   protLastRcv 2015-07-10 19:50:01
   protNack   1 last_at:2015-07-10 18:18:39
   protResnd  1 last_at:2015-07-10 18:18:13
   protSnd    2 last_at:2015-07-10 18:18:38
   protState  CMDs_done_Errors:1
   rssi_at_HMLAN0 lst:-43 avg:-43.49 min:-44 max:-43 cnt:42
   CHANGETIME:
   Helper:
     Dblog:
       Gascntoverallkwh:
         Bendblog:
           TIME       1436547933.85732
           VALUE      39306.08
       Gaspowerrealkwh:
         Bendblog:
           TIME       1436550140.79582
           VALUE      0.00
   Readings:
     2015-07-10 18:28:07   Activity        alive
     2015-07-10 18:18:39   CommandAccepted no
     2015-07-09 14:10:38   D-firmware      1.0
     2015-07-09 14:10:38   D-serialNr      MEQ0380556
     2015-07-09 14:11:51   PairedTo        0xF15544
     2015-07-09 14:11:52   R-mtrConstGas   0.009 m3/I
     2015-07-09 14:11:52   R-mtrConstIr    100 U/kWh
     2015-07-09 14:11:52   R-mtrConstLed   10000 i/kWh
     2015-07-09 14:11:52   R-mtrSensIr     0 %
     2015-07-09 14:11:52   R-mtrType       gas
     2015-07-09 14:11:51   R-pairCentral   0xF15544
     2015-07-09 14:11:51   R-transmDevTryMax 6
     2015-07-09 14:11:52   R-transmitTryMax 6
     2015-07-10 19:50:01   boot            off
     2015-07-09 15:07:17   costKWh         4.9
     2015-07-10 19:42:20   costPerHour     0.00
     2015-07-10 19:50:01   eState          E: 1.98 P: 1.686
     2015-07-10 19:50:01   gasCnt          1.98
     2015-07-09 14:34:50   gasCntOffset    4173.295
     2015-07-10 19:42:20   gasCntOverallKWh 39306.08
     2015-07-10 19:42:20   gasCntPrev      1.98
     2015-07-10 19:50:01   gasPower        1.686
     2015-07-10 19:42:20   gasPowerRealKWh 0.00
     2015-07-09 14:11:51   powerOn         2015-07-09 14:11:51
     2015-07-10 19:50:01   statGasPowerRealKWhDay Min: 0.00 Avg: 0.00 Max: 0.06 (since: 2015-07-10_18:25:16 )
     2015-07-10 19:50:01   statGasPowerRealKWhHour Min: 0.00 Avg: 0.00 Max: 0.06 (since: 2015-07-10_18:25:16 )
     2015-07-10 19:50:01   statGasPowerRealKWhMonth Min: 0.00 Avg: 0.00 Max: 0.06 (since: 2015-07-10_18:25:16 )
     2015-07-10 19:50:01   statGasPowerRealKWhYear Min: 0.00 Avg: 0.00 Max: 0.06 (since: 2015-07-10_18:25:16 )
     2015-07-10 18:18:39   state           Nack
   Helper:
     HM_CMDNR   208
     _98_statistics env_stats
     getCfgListNo
     mId        00DE
     rxType     12
     Io:
       newChn     +3BD485,00,00,00
       nextSend   1436550601.45684
       rxt        2
       vccu       VCCU
       p:
         3BD485
         00
         00
         00
       prefIO:
         HMLAN0
     Mrssi:
       mNo        D0
       Io:
         HMLAN0     -41
     Prt:
       bErr       0
       sProc      0
       Rspwait:
     Q:
       qReqConf
       qReqStat
     Role:
       chn        1
       dev        1
     Rssi:
       At_hmlan0:
         avg        -43.5
         cnt        42
         lst        -43
         max        -43
         min        -44
Attributes:
   IODev      HMLAN0
   IOgrp      VCCU:HMLAN0
   actCycle   000:10
   actStatus  alive
   alias      Gaszähler
   autoReadReg 4_reqStatus
   event-on-change-reading (gasCntOverallKWh)
   event-on-update-reading (gasCnt|gasPower|gasPowerRealKWh|costPerHour)
   expert     2_full
   firmware   1.0
   group      Energie
   model      HM-ES-TX-WM
   room       Wohnung
   serialNr   MEQ0380556
   stateFormat eState
   subType    powerSensor
   userReadings gasPowerRealKWh:gasCnt {getGasPowerReal()}


Code Auswählen Erweitern


Internals:
   DEF        (env_electricMeter|env_gasMeter|.*_hmTcWeather|.*_thgr228n|env_thpl)
   DEV_REGEXP (env_electricMeter|env_gasMeter|.*_hmTcWeather|.*_thgr228n|env_thpl)
   NAME       env_stats
   NR         433
   NTFY_ORDER 10-env_stats
   PREFIX     stat
   STATE      Updated stats for: env_thpl
   TYPE       statistics
   Readings:
     2015-07-10 18:25:16   monitoredDevicesCUL_HM env_electricMeter,wz_hmTcWeather,env_thpl,sz_hmTcWeather,env_gasMeter
     2015-07-10 18:18:17   monitoredDevicesTRX_WEATHER bd_thgr228n,ku_thgr228n,fl_thgr228n
     2015-07-10 18:24:18   monitoredDevicesUnsupported SVG_bd_thgr228n#SVG,SVG_fl_thgr228n#SVG,SVG_ku_thgr228n#SVG,SVG_sz_hmTcWeather#SVG,SVG_wz_hmTcWeather#SVG,env_gasMeter#CUL_HM
     2015-07-10 19:36:43   nextPeriodChangeCalc 2015-07-10 19:59:58
     2015-07-10 19:59:01   state           Updated stats for: env_thpl
   Fhem:
     modulVersion $Date: 2015-04-28 20:51:42 +0200 (Di, 28 Apr 2015) $
Attributes:
   alias      Statistiken
   deltaReadings energyOverall
   ignoreDefaultAssignments 1
   minAvgMaxReadings power,measured-temp,humidity,luminosity,temperature,pressure,gasPowerRealKWh
   periodChangePreset 2
   room       System
   singularReadings (env_electricMeter|env_gasMeter):(energyOverall|gasCntOverallKWh):Delta:(Hour|Day|Month|Year)


[tupol]

Da auf die statWerte keine event-on gesetzt ist gibt es auch nix im Monitor.

Ansonsten scheint es irgendwas mit userReadings zu sein. Aber keine Ahnung was. Vielleicht hilft ein verbose 5

Noch was. Ich würde mal die def etwas anpassen ^(...)$. Die DeviceUnsupported kosten Rechenzeit.

[vbs]

Ok, danke. Die UnsupportedDevices hab ich jetzt weg. Im verbose 5 war für mich erstmal nichts hilfreiches zu sehen.

Ich hab mal Stacktracers erzeugt für die beiden Aufrufe. Ist eigentlich wie wir es erwartet haben: Der erste Aufruf getriggert durch das Einliefern des Readings durch CUL_HM und der zweite Aufruf wird tatsächlich getriggert durch das Erzeugen der Statistik (Also das statistic-Modul ruft readingsEndUpdate auf, was dann das Userreading triggert):

Code Auswählen Erweitern

Trace begun at FHEM/99_VBSUtils_Logic.pm line 1077
main::getGasPowerReal at (eval 274) line 1
eval '{getGasPowerReal()}' at fhem.pl line 3747
main::readingsEndUpdate('HASH(0xaf86910)', 1) called at FHEM/10_CUL_HM.pm line 7413
main::CUL_HM_UpdtReadBulk('HASH(0xaf86910)', 1, 'gasCnt:2', 'gasPower:0.006', 'eState:E: 2 P: 0.006', 'boot:off') called at FHEM/10_CUL_HM.pm line 3153
main::CUL_HM_pushEvnts at FHEM/10_CUL_HM.pm line 2518
main::CUL_HM_Parse('HASH(0x89d8590)', 'A101186533BD485000000000007D0000006::-44:HMLAN0') called at fhem.pl line 3177
main::Dispatch('HASH(0x89d8590)', 'A101186533BD485000000000007D0000006::-44:HMLAN0', 'HASH(0xb4faaf8)') called at FHEM/00_HMLAN.pm line 738
main::HMLAN_Parse('HASH(0x89d8590)', 'E3BD485,0000,D576CC06,FF,FFD4,1186533BD485000000000007D0000006') called at FHEM/00_HMLAN.pm line 561
main::HMLAN_Read('HASH(0x89d8590)') called at fhem.pl line 3040
main::CallFn('HMLAN0', 'ReadFn', 'HASH(0x89d8590)') called at fhem.pl line 646
2015.07.10 22:31:00 3: getGasPowerReal: Cur: 2 Prev: 1.99

Trace begun at FHEM/99_VBSUtils_Logic.pm line 1077
main::getGasPowerReal at (eval 275) line 1
eval '{getGasPowerReal()}' at fhem.pl line 3747
main::readingsEndUpdate('HASH(0xaf86910)', 0) called at FHEM/98_statistics.pm line 450
main::statistics_DoStatistics('HASH(0x9e0b9e8)', 'HASH(0xaf86910)', 0) called at FHEM/98_statistics.pm line 275
main::statistics_Notify('HASH(0x9e0b9e8)', 'HASH(0xaf86910)') called at fhem.pl line 3040
main::CallFn('env_stats', 'NotifyFn', 'HASH(0x9e0b9e8)', 'HASH(0xaf86910)') called at fhem.pl line 2963
main::DoTrigger('env_gasMeter', undef) called at fhem.pl line 3257
main::Dispatch('HASH(0x89d8590)', 'A101186533BD485000000000007D0000006::-44:HMLAN0', 'HASH(0xb4faaf8)') called at FHEM/00_HMLAN.pm line 738
main::HMLAN_Parse('HASH(0x89d8590)', 'E3BD485,0000,D576CC06,FF,FFD4,1186533BD485000000000007D0000006') called at FHEM/00_HMLAN.pm line 561
main::HMLAN_Read('HASH(0x89d8590)') called at fhem.pl line 3040
main::CallFn('HMLAN0', 'ReadFn', 'HASH(0x89d8590)') called at fhem.pl line 646
2015.07.10 22:31:00 3: getGasPowerReal: Cur: 2 Prev: 2

Das bringt nicht zufällig jemanden auf eine Idee, oder?

[vbs]

Also irgendwie werden diese Readings mit-gesetzt, wenn das Modul readingsEndUpdate aufruft, obwohl es die besagten Readings selbst gar nicht gesetzt hat. Scheint so, als würden da noch alte Readings irgendwo in der "Pipeline" von fhem stecken, die dann noch gesetzt werden.

Hab dafür mal einen Thread angelegt:
http://forum.fhem.de/index.php/topic,39008.0.html

[tupol]

Seltsam ist, dass diese nur bei userReadings passiert.

[drdownload]

Gibt es dazu eine Idee wie man in einer Device userreadings und statistics kombinieren kann ohne dass sie sich in die quere kommen?

[mcmuller]

Gibt es dazu eine Idee wie man in einer Device userreadings und statistics kombinieren kann ohne dass sie sich in die quere kommen?

Hole das Thema nochmal hoch, weil ich sonst nix dazu gefunden habe:
Ich habe hier genau das gleiche Problem - ein mqtt-Device das Power-Werte pro Phase liefert, die ich per userReadings aufsummiere und in kWh umrechne. Lasse ich das Statistics.pm darauf los, triggert es die userReadings erneut...

Code Auswählen Erweitern

define emonmqtt MQTT_DEVICE
attr emonmqtt IODev mqttbroker
attr emonmqtt room Mobil,Strom
attr emonmqtt stateFormat time
attr emonmqtt subscribeReading_Vrms emon/3phase/Vrms
attr emonmqtt subscribeReading_powerL1 emon/3phase/powerL1
attr emonmqtt subscribeReading_powerL2 emon/3phase/powerL2
attr emonmqtt subscribeReading_powerL3 emon/3phase/powerL3
attr emonmqtt subscribeReading_rssi emon/3phase/rssi
attr emonmqtt userReadings \
time:powerL3.* {time()},\
total:time.* {ReadingsVal("emonmqtt","powerL1",0)+ ReadingsVal("emonmqtt","powerL2",0)+ ReadingsVal("emonmqtt","powerL3",0)},\
kWhTotal:total.* {((ReadingsVal("emonmqtt","total",0) * (time() - OldValue("emonmqtt")) / 3600000.0 ) + ReadingsVal("emonmqtt","kWhTotal",0))}


[tupol]

Statistic benutzt das Event-Modell, um die Werte loggen zu können.

Dafür müßten meines Erachtens also die userreadings überarbeitet werden und nur reagieren, wenn die enthaltenen Readings sich ändern. Anscheinend wird es aber durch andere Sachen getriggert.

Vom FHEM-Framework gäbe es vielleicht ein Workaround, wenn die userreadings nur bei readingsEndUpdate aktualisiert werden und nicht bei readingsSingleUpdate. Bin mir aber nicht sicher, ob das so ist.

[justme1968]

user readings werden nur bei EndUpadate aktualisiert. SingleUpdate ruft aber intern automatisch EndUpdate auf.

welche reaadings/events erzeugt denn stastitics bei dir? ist deine trigger regex beim user reading vielleicht einfach nicht spezifisch genug? geht es mit total:^time.* besser ?

gruss
  andre

[mcmuller]

Danke tupol & andre dafür, daß Ihr Euch dessen annehmt.

Der trigger ist das mqtt-Reading der dritten Phase powerL3.* , periodisch so ca. alle 10 Sekunden und laut Event-Log auch wirklich je nur einmal vorhanden. Das triggern mit time.* und total.* für die weiteren userReadings erschien mir in der Abfolge logisch - ändert aber auch nichts am Verhalten, wenn ich nur per powerL3.* triggere.

Zur Frage, was das statistics.pm erzeugt:

Code Auswählen Erweitern

define Energystat statistics emonmqtt.*
attr Energystat deltaReadings kWhTotal
attr Energystat excludedReadings emonmqtt:rssi|emonmqtt:power.*|emonmqtt:V.*|emonmqtt:total
attr Energystat singularReadings emonmqtt:kWhTotal:Delta:Day

...also nur kWhTotal, mein Ergebnis aus dem userReading.

Zur Übersicht nochmal mein mqtt-device:

Code Auswählen Erweitern

define emonmqtt MQTT_DEVICE
attr emonmqtt IODev mqttbroker
attr emonmqtt room Mobil,Strom
attr emonmqtt stateFormat time
attr emonmqtt subscribeReading_Vrms emon/3phase/Vrms
attr emonmqtt subscribeReading_powerL1 emon/3phase/powerL1
attr emonmqtt subscribeReading_powerL2 emon/3phase/powerL2
attr emonmqtt subscribeReading_powerL3 emon/3phase/powerL3
attr emonmqtt subscribeReading_rssi emon/3phase/rssi
attr emonmqtt userReadings \
time:powerL3.* {time()},\
total:time.* {ReadingsVal("emonmqtt","powerL1",0)+ ReadingsVal("emonmqtt","powerL2",0)+ ReadingsVal("emonmqtt","powerL3",0)},\
kWhTotal:total.* {((ReadingsVal("emonmqtt","total",0) * (time() - OldValue("emonmqtt")) / 3600000.0 ) + ReadingsVal("emonmqtt","kWhTotal",0))}


Grüße aus Portugal,
Gregor

[justme1968]

sehe ich das richtig das du ein user reading auf ein anderes triggern lässt? eventuell ist da das problem. lass mal alle auf powerL3 triggern. dir user readings werden sowieso von links nach rechts abgearbeitet.

[tupol]

Müsste emonmqtt nicht auch ein event-on-change haben?