Thanks,
I will plan an upgrade, however I think I have traced part of the delay.
It seems as if rules do not get triggered while persistence is storing values. This could just be a coincidence, but I have a significant number of items that are persisted every minute (for graphs), I can see these in the logs, every minute:
2018-04-23 15:42:00.029 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'RGBIndicator_153_rssi' with state '58' in rrd4j database
2018-04-23 15:42:00.059 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'RGBIndicator_153_memory' with state '22360' in rrd4j database
2018-04-23 15:42:00.090 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'Weather_Temperature' with state '20.90' in rrd4j database
2018-04-23 15:42:00.122 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'DToutsidetemperature' with state '18.44' in rrd4j database
2018-04-23 15:42:00.152 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'Weather_Temp_Min' with state '0.200000000000000011102230246251565404236316680908203125' in rrd4j database
2018-04-23 15:42:00.181 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'Weather_Temp_Max' with state '21' in rrd4j database
2018-04-23 15:42:00.214 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'ousidetemperature' with state '17.20' in rrd4j database
2018-04-23 15:42:00.243 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'casetemperature' with state '34.06' in rrd4j database
2018-04-23 15:42:00.273 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'RGBDIRECT_or_Pi' with state 'ON' in rrd4j database (again)
2018-04-23 15:42:00.274 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'RGBDIRECT_or_Pi' with state '1' in rrd4j database
2018-04-23 15:42:00.316 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'psu2temperature' with state '32.18' in rrd4j database
2018-04-23 15:42:00.345 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'psu5volttemperature' with state '28.31' in rrd4j database
2018-04-23 15:42:00.377 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'psu1temperature' with state '27.02' in rrd4j database
2018-04-23 15:42:00.406 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'leds_mA' with state '-150' in rrd4j database
2018-04-23 15:42:00.437 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'outsidepsu5volttemperature' with state '19.12' in rrd4j database
and so on - there are a lot of these, and it seems to take about 10 seconds every minute to store them. First - this seems like a huge amount of time to store about 400 items, and second, while watching my rules log, no rules are triggered for the whole 10 seconds (which is unusual, I usually have one rule or another triggering all the time).
I have set org.eclipse.smarthome.threadpool:RuleEngine
to 30, so that rules can run more threads, but that doesn’t help.Is it possible that while the rrd4j persistence service is storing it’s values, no rules can be triggerd - they all seem to trigger at once, once persistence has finished storing. look at this (Rules output log):
23-Apr-2018 15:49:00.001 [INFO ] [smarthome.model.script.Testing Rules] - rules_operating status: True
23-Apr-2018 15:49:10.486 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Roomba Last Update Timestamp'
23-Apr-2018 15:49:10.487 [INFO ] [e.smarthome.model.script.Last Update] - roomba_lastheardfrom DateTimeItem updated at: Mon 15:49
23-Apr-2018 15:49:10.489 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Calculate energy cost'
23-Apr-2018 15:49:10.489 [INFO ] [clipse.smarthome.model.script.Energy] - Current kW being used: 2.03593
23-Apr-2018 15:49:10.490 [INFO ] [clipse.smarthome.model.script.Energy] - Current kWh used since last update: 0.0101101169088
23-Apr-2018 15:49:10.492 [INFO ] [clipse.smarthome.model.script.Energy] - Instanteneous Energy Cost is: 2.03593kWh @9.5c/kWh = 19.341335c/h
23-Apr-2018 15:49:10.557 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Monitor LED Current'
23-Apr-2018 15:49:10.558 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'HEM Update Timer'
23-Apr-2018 15:49:10.558 [INFO ] [se.smarthome.model.script.HEM Update] - Updating HEM Reset Timer
23-Apr-2018 15:49:10.558 [INFO ] [se.smarthome.model.script.HEM Update] - Rescheduled HEM Timer
23-Apr-2018 15:49:10.617 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Compute garden humidex'
23-Apr-2018 15:49:10.789 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Update In Use Light Sensor Back Garden'
23-Apr-2018 15:49:11.039 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Monitor LED Current'
23-Apr-2018 15:49:11.082 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'basement Register Main Control'
23-Apr-2018 15:49:11.654 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Convert Sensorpuck 2 Lux to text value'
23-Apr-2018 15:49:11.655 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Update In Use Light Sensor SP2 Back Garden'
23-Apr-2018 15:49:11.710 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Roomba Last Update Timestamp'
23-Apr-2018 15:49:11.713 [INFO ] [e.smarthome.model.script.Last Update] - roomba_lastheardfrom DateTimeItem updated at: Mon 15:49
23-Apr-2018 15:49:12.059 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Vent 4 (Nick's Office) Received Pressure update'
23-Apr-2018 15:49:12.060 [INFO ] [se.smarthome.model.script.Flair Vent] - Nick's Office Pressure Diff: 60.000
23-Apr-2018 15:49:13.151 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Vent 6 (Hallway) Received Pressure update'
23-Apr-2018 15:49:13.152 [INFO ] [se.smarthome.model.script.Flair Vent] - Hallway Pressure Diff: 30.000
23-Apr-2018 15:49:14.301 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Vent 2a (Family Room - dining area) Received Pressure update'
23-Apr-2018 15:49:14.302 [INFO ] [se.smarthome.model.script.Flair Vent] - Family Room (dining) Pressure Diff: 20.000
23-Apr-2018 15:49:14.839 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Compute garden humidex'
23-Apr-2018 15:49:15.258 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Vent 5 (Washroom) Received Pressure update'
23-Apr-2018 15:49:15.259 [INFO ] [se.smarthome.model.script.Flair Vent] - Washroom Pressure Diff: 40.000
Notice the time difference between the first two entries - nearly 10.5 seconds.
Here is my other log showing what is happening at that time (which includes rules output):
2018-04-23 15:49:00.001 [INFO ] [smarthome.model.script.Testing Rules] - rules_operating status: True
2018-04-23 15:49:00.002 [DEBUG] [inding.expire.internal.ExpireBinding] - Item rules_operating will expire (with 'False' command) in 90000 ms
2018-04-23 15:49:00.002 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'RGBIndicator_153_rssi' with state '58' in rrd4j database
2018-04-23 15:49:00.035 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'RGBIndicator_153_memory' with state '22360' in rrd4j database
2018-04-23 15:49:00.065 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'Weather_Temperature' with state '20.90' in rrd4j database
2018-04-23 15:49:00.097 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'DToutsidetemperature' with state '18.44' in rrd4j database
2018-04-23 15:49:00.127 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'psu2temperature' with state '32.18' in rrd4j database
... 375 of these
...
2018-04-23 15:49:10.308 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'flairvent1Open' with state '0.99000000' in rrd4j database
2018-04-23 15:49:10.350 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'thunderboard4BatteryVolt' with state '3' in rrd4j database
2018-04-23 15:49:10.380 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'ButtonGreen2Battery' with state '100' in rrd4j database
2018-04-23 15:49:10.412 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'AeonMS65F' with state 'OFF' in rrd4j database (again)
2018-04-23 15:49:10.412 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'AeonMS65F' with state '0' in rrd4j database
2018-04-23 15:49:10.453 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'psu5volttemperature' with state '28.31' in rrd4j database
2018-04-23 15:49:10.486 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Roomba Last Update Timestamp'
2018-04-23 15:49:10.487 [INFO ] [e.smarthome.model.script.Last Update] - roomba_lastheardfrom DateTimeItem updated at: Mon 15:49
2018-04-23 15:49:10.489 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Calculate energy cost'
2018-04-23 15:49:10.489 [INFO ] [clipse.smarthome.model.script.Energy] - Current kW being used: 2.03593
2018-04-23 15:49:10.490 [INFO ] [clipse.smarthome.model.script.Energy] - Current kWh used since last update: 0.0101101169088
2018-04-23 15:49:10.492 [INFO ] [clipse.smarthome.model.script.Energy] - Instanteneous Energy Cost is: 2.03593kWh @9.5c/kWh = 19.341335c/h
2018-04-23 15:49:10.496 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'psu1temperature' with state '26.70' in rrd4j database
2018-04-23 15:49:10.527 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored 'Energy_Daily_MidPeak' with state '2.54180055674800' in rrd4j database
2018-04-23 15:49:10.557 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'Monitor LED Current'
2018-04-23 15:49:10.558 [DEBUG] [ntime.internal.engine.RuleEngineImpl] - Executing rule 'HEM Update Timer'
2018-04-23 15:49:10.558 [INFO ] [se.smarthome.model.script.HEM Update] - Updating HEM Reset Timer
2018-04-23 15:49:10.558 [INFO ] [se.smarthome.model.script.HEM Update] - Rescheduled HEM Timer
You see the timing of the ‘storing’ coincides exactly with the period of no rules being triggered (if a rule is triggered before this with a delay, it is still running).
I realize I can persist less items, but honestly why would persistence have anything to do with whether rules are triggered or not? and why does it take so long to write? (I have an SSD, and plenty of resources on my server).
I think this is partly the root of my issue, as every minute there is a 10 second delay on all rules, so it looks like there is a random ‘lag’ in response from the system.
Is this possible or am I going crazy?