rrd4j gives strange results for Average

Hello,

Trying to average measured light intensities, rrd4j gives very strange results. Can anybody explain what rrd4j is doing with my measurements? I want to have a last-5-minutes average of all measurements.

But when all measurements (between 18:02 and 18:08) are above 4, the average at 18:08 is 3.33. I would expect something like 4.5.

(Part of) grep -E -i “lichtintensiteit|rrd4j|average” /var/log/openhab/openhab.log | tail --lines 500:

18:02:49.455 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:02:49.474 [INFO ] [.model.script.Enable lights on:53 ] - LichtIntensiteit_Woonkamer changed to [5.0]
18:02:49.503 [DEBUG] [o.model.script.LightsOn_Sensor:38 ] - IntensiteitAverage=3.75
18:02:59.450 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:03:03.005 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:03:03.026 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 23ms
18:03:09.609 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:03:09.780 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:03:09.797 [INFO ] [.model.script.Enable lights on:53 ] - LichtIntensiteit_Woonkamer changed to [4.16666666667]
18:03:09.836 [DEBUG] [o.model.script.LightsOn_Sensor:38 ] - IntensiteitAverage=3.3333333333350001481676372350193560123443603515625
18:03:19.775 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:03:29.941 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:03:33.003 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:03:33.014 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 12ms
18:03:40.101 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:03:50.260 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:04:00.419 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:04:03.004 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:04:03.018 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 16ms
18:04:10.634 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:04:20.801 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:04:30.960 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:04:33.004 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:04:33.023 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 21ms
18:04:41.126 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:04:51.293 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:05:01.460 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:05:03.004 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:05:03.025 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 23ms
18:05:11.626 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:05:21.791 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:05:31.950 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:05:33.004 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:05:33.014 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 11ms
18:05:42.112 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:05:52.270 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:06:02.436 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:06:02.608 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:06:02.632 [INFO ] [.model.script.Enable lights on:53 ] - LichtIntensiteit_Woonkamer changed to [5.0]
18:06:02.662 [DEBUG] [o.model.script.LightsOn_Sensor:38 ] - IntensiteitAverage=3.75
18:06:03.003 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:06:03.014 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 12ms
18:06:12.602 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:06:22.762 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:06:32.921 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:06:33.005 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:06:33.018 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 15ms
18:06:43.081 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:06:53.240 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:07:03.005 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:07:03.025 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 22ms
18:07:03.399 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:07:13.558 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:07:23.724 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:07:33.004 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:07:33.031 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 28ms
18:07:33.891 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:07:44.057 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:07:54.223 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:08:03.005 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘5.0’ in rrd4j database
18:08:03.022 [TRACE] [o.c.p.internal.PersistItemsJob:56 ] - Storing item ‘LichtIntensiteit_Woonkamer’ with persistence service ‘rrd4j’ took 19ms
18:08:04.387 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:08:14.545 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:08:24.706 [DEBUG] [.o.b.exec.internal.ExecBinding:120 ] - item ‘LichtIntensiteit_Woonkamer’ is about to be refreshed now
18:08:24.869 [DEBUG] [.p.rrd4j.internal.RRD4jService:130 ] - Stored ‘LichtIntensiteit_Woonkamer’ with state ‘4.16666666667’ in rrd4j database
18:08:24.890 [INFO ] [.model.script.Enable lights on:53 ] - LichtIntensiteit_Woonkamer changed to [4.16666666667]
18:08:24.921 [DEBUG] [o.model.script.LightsOn_Sensor:38 ] - IntensiteitAverage=3.3333333333350001481676372350193560123443603515625

root@raspberrypi:/etc/openhab/configurations# grep -E -i “(rrd4j|^[^#]|mapdb)” openhab.cfg

folder:items=10,items
folder:sitemaps=10,sitemap
folder:rules=10,rules
folder:scripts=10,script
folder:persistence=10,persist
security:netmask=192.168.178.0/24

persistence:default=rrd4j

persistence:default=mapdb
chart:provider=default
########################### RRD4J Persistence Service #################################
#rrd4j:.def=[ABSOLUTE|COUNTER|DERIVE|GAUGE],,[|U],[|U],
#rrd4j:.archives=[AVERAGE|MIN|MAX|LAST|FIRST|TOTAL],,,
#rrd4j:.items=
rrd4j:carl.def=GAUGE,60,U,U,10
rrd4j:carl.archives=AVERAGE,0.5,1,600
rrd4j:carl.items=LichtIntensiteit_Woonkamer
logging:pattern=%date{ISO8601} - %-25logger: %msg%n

########################### MapDB Persistence Service ##################################
#mapdb:commitinterval=5
#mapdb:commitsamestate=false
ntp:hostname=ptbtime1.ptb.de
hue:secret=openHABRuntime
tcp:refreshinterval=250
astro:latitude=52.0704978
astro:longitude=4.3006999
astro:interval=57

root@raspberrypi:/etc/openhab/configurations# cat persistence/rrd4j.persist

Strategies {
everyMinute : "0 * * * * ?"
every30seconds : "3/30 * * * * ?"
everyTenMinute : "0 0/10 * * * ?"
everyHour : "0 0 * * * ?"
everyDay : “0 0 0 * * ?”

// if no strategy is specified for an item entry below, the default list will be used
default = everyChange, restoreOnStartup
}
// Voor rrd moet je in openhab minstens elke minuut, anders doet chart het niet
Items {
LichtIntensiteit_Woonkamer : strategy = everyChange, every30seconds
}

root@raspberrypi:/etc/openhab/configurations# grep -E -i “lichtintensiteit_woonk|average|rrd” items/lichtsensor.items

Number LichtIntensiteit_Woonkamer “Lichtintensiteit woonkamer [%.1f]” (LightSensor) {exec="<[/home/pi/LightSensorBH1750/bh1750_2.sh:10000:]"}

root@raspberrypi:/etc/openhab/configurations# cat rules/lightsOnOff.rules

import org.openhab.core.library.types.*
/* niet nodig import java.lang.Math */
import java.util.concurrent.locks.ReentrantLock
import org.openhab.model.script.actions.Timer
//import java.util.Calendar

var Timer backoffTimer
var ReentrantLock backoffLock=new ReentrantLock()
//var Calendar calendar = Calendar.getInstance()
var boolean inInitialisationPhase = true
var Timer initialisationPhaseTimer = null
var ReentrantLock initLock=new ReentrantLock()

rule "Initialisaties"
when
System started
then
// even hardcoded 20160209
// postUpdate(LightsOnIntensityThreshold,19)
// postUpdate(LightsEnableIntensityThreshold,200)
postUpdate(AutoOnEnabled,0) // niet standaard enablen, dan zouden bij reboot de lampen aan gaan
// via persistence postUpdate(LightsOnIntensityThreshold,25)
// via persistence postUpdate(LightsEnableIntensityThreshold,200)
initialisationPhaseTimer = createTimer(now.plusMinutes(2)) [|
// Init de waardes als ze niet door persistence zijn geinit
logDebug(“Initialisaties”,“initialisationPhaseTimer finished”)
logDebug(“Initialisaties”,“LightsOnIntensityThreshold=”+ LightsOnIntensityThreshold.toString())
logDebug(“Initialisaties”,“initialisationPhaseTimer finished, threshold logged to debug (like this message)”)
if ((LightsOnIntensityThreshold == null) || (LightsOnIntensityThreshold.state == Uninitialized)) {
postUpdate(LightsOnIntensityThreshold,18)
logDebug(“Initialisaties”,“LightsOnIntensityThreshold was null or Unitialized, set to 18”)
}
if ((LightsEnableIntensityThreshold == null) || (LightsEnableIntensityThreshold.state == Uninitialized)) {
postUpdate(LightsEnableIntensityThreshold,88)
logDebug(“Initialisaties”,“LightsOnIntensityThreshold was null or Unitialized, set to 198”)
}
if ((AutoOnEnabled == null) || (AutoOnEnabled.state == Uninitialized)) {
postUpdate(AutoOnEnabled,0)
logDebug(“Initialisaties”,“AutoOnEnabled was null or Unitialized, set to {}”,AutoOnEnabled.state)
}
//postUpdate(AutoOnEnabled,1) // tijdelijk
initialisationPhaseTimer = null
]
end

rule "lightsOn_sunset2"
when
Item Sunset_with_Offset_Event1 received update ON
then
logDebug(“astro”,“item Sunset_with_offset_Event1 received update ON”)
//sendCommand(gGF,ON)
end

rule "lightsOn_sunset"
when
Item Sunset_with_Offset_Event received update ON
then
logDebug(“astro”,“item Sunset_with_offset_Event received update ON”)
sendCommand(gGF,ON)
end

rule "lightsOff"
when
// seconds minuut uur dag (1-31) maand(1-12) dag (0-7)
Time cron "0 38 1 * * ?"
then
sendCommand(gGF,OFF)
end

rule "LightsOn_Sensor"
when
Item LichtIntensiteit_Woonkamer changed
//or Time cron “0/2 * * * * ?” // dat is heel vaak
then
logDebug(“LightsOn_Sensor”,“Start”)
backoffLock.lock()
if (initialisationPhaseTimer == null ) {
logInfo(“LightsOn_Sensor”,“initialisationPhaseTimer is null”)
// Init de waardes als ze niet door persistence zijn geinit
if (LightsOnIntensityThreshold == null) {
logInfo(“LightsOn_Sensor”,“LightsOnIntensityThreshold is null”)
postUpdate(LightsOnIntensityThreshold,17)
}
if (LightsEnableIntensityThreshold == null) {
logInfo(“LightsOn_Sensor”,“LightsEnableIntensityThreshold is null”)
postUpdate(LightsEnableIntensityThreshold,197)
}
//postUpdate(AutoOnEnabled,1) // tijdelijk?
}
logDebug(“LightsOn_Sensor”,“backoffLock aquired”)
try {
var Number IntensiteitAverage = LichtIntensiteit_Woonkamer.averageSince(now.minusSeconds(300))
logDebug(“LightsOn_Sensor”,“Gemiddelde over y mn gemeten is {}, drempel is {}”,IntensiteitAverage.toString(),LightsOnIntensityThreshold.state.toString())
logDebug(“LightsOn_Sensor”,“AutoOnEnabled.state={}”,AutoOnEnabled.state)
if (AutoOnEnabled.state==1) {
logDebug(“LightsOn_Sensor”,“AutoOnEnabled.state is 1”)
}
if (AutoOnEnabled.state==0) {
logDebug(“LightsOn_Sensor”,“AutoOnEnabled.state is 0”)
}
logDebug(“LightsOn_Sensor”,“IntensiteitAverage={}”,IntensiteitAverage)
logDebug(“LightsOn_Sensor”,“LightsOnIntensityThreshold={}”, LightsOnIntensityThreshold) // print ongeveer type=NumberItem State=19
if ((AutoOnEnabled.state==1) && ((IntensiteitAverage)<(LightsOnIntensityThreshold.state))) {
logInfo(“LightsOn_Sensor”,“Het is donker”)
logInfo(“LightsOn_Sensor”,“Het is donker [{}] [{}] en de lichten moeten aan.”,IntensiteitAverage.toString(),LightsOnIntensityThreshold.state.toString())
// Het is donker, zet de lichten aan als ze nog niet aan staan
sendCommand(gGF,ON)
logInfo(“LightsOn_Sensor”,“Update AutoOnEnabled to 0”)
postUpdate(AutoOnEnabled,0) // niet steeds opnieuw automatisch aanzetten
logInfo(“LightsOn_Sensor”,“Update AutoOnEnabled to 0 finished”)
// nu iets dat niet helemaal klopt, want er zal tijdsverschil zijn tussen beide timers…
// weet niet hoe timer te updaten BackoffTimer.postUpdate(now.plusMinutes(1200) as DateTime)
logInfo(“LightsOn_Sensor”,“Update BackoffTimer finished”)
backoffTimer = createTimer(now.plusMinutes(1200)) [| // 1200 minuten is 20 uur
postUpdate(AutoOnEnabled,1)
]
}
}
finally {
backoffLock.unlock()
}
end
rule "Enable lights on by light sensor"
when
Time is noon
or Item Sunset_minus_1hour received update ON
// or Time cron "0/4 * * * * ?"
then
logInfo(“Enable lights on”,“Het is noon, zorg dat de lichten weer aan mogen als het donker wordt”)
backoffLock.lock()
logInfo(“Enable lights on”,“Lock acquired”)
try {
postUpdate(AutoOnEnabled,1)
logInfo(“Enable lights on”,“AutoOnEnabled op 1 gezet”)
if (backoffTimer!=null) {
logInfo(“Enable lights on”,“cancel backoffTimer”)
backoffTimer.cancel()
logInfo(“Enable lights on”,“backoffTimer gecancelled”)
backoffTimer=null
}
}
finally {
backoffLock.unlock()
}
end

// Enable het aanzetten als er erg veel licht is
rule "Enable lights on by daylight"
when
Item LichtIntensiteit_Woonkamer changed
then
logInfo(“Enable lights on”,“LichtIntensiteit_Woonkamer changed to [{}]”,LichtIntensiteit_Woonkamer.state.toString())
backoffLock.lock()
try {
if (AutoOnEnabled.state==0 && (LichtIntensiteit_Woonkamer.state != Uninitialized)
&& ((LichtIntensiteit_Woonkamer.state as float)>(LightsEnableIntensityThreshold.state as float))
) {
logInfo(“Enable lights on”,“Het is erg licht [{}], drempel=[{}] en de automaat mag weer aan.”,LichtIntensiteit_Woonkamer.state.toString(),LightsEnableIntensityThreshold.state)
postUpdate(AutoOnEnabled,1)
if ( backoffTimer !=null) {
backoffTimer.cancel()
backoffTimer=null
}
// Zet de lampen uit
sendCommand(gGF,OFF)
}
}
finally {
backoffLock.unlock()
}
end

When dealing with rrd4j you must use the everyMinute strategy or else any use of it that involves historic data is unlikly to work. Charts will be blank, calls to historicState or previousState in rules often will return null, etc. There are technical reason why this is the case and if you really dig into the options you can change the behavior, but by default if you don’t use everyMinute it is likely not going to work.

I am using every 30 seconds, because I thought that would be even better than every minute. If using every minute, there is a chance you miss a minute if a cron activation occurs just a bit later e.g. because the cpu is busy. The logging shows there is a save every 30 seconds into rrd4j.
I would love to see some documentation about reading the rrd4j persistence file.

If you use every minute along with every change you will miss no events.

I’ve looked into how to read rrd4j before and unfortunately none of them work for tge Java version so unless you write your own code you are out of luck.