Java Runtime Environment: java version “1.8.0_151”
openHAB version: 2.5.2 Release Build
After update from OpenHAB 2.3 to 2.5 (in mid January) I experience about 8.5 seconds delay before rule will start. This happens to all of my rules. The time is always close to 8.5 seconds. When script activates there is few minutes of no delay for any rule. After few minutes of no script activity the delay occurs again.
The sample below concern motion detection rule, which in this test I trigger through sitemap switch but of course the same circumstances are when real motion detector triggers.
Please give some advice because I am out of ideas…
Eventslog:
2020-03-01 16:11:26.488 [ome.event.ItemCommandEvent] - Item 'Corridor_MotionSensor' received command ON
2020-03-01 16:11:26.531 [nt.ItemStatePredictedEvent] - Corridor_MotionSensor predicted to become ON
2020-03-01 16:11:26.559 [vent.ItemStateChangedEvent] - Corridor_MotionSensor changed from OFF to ON
2020-03-01 16:11:35.043 [ome.event.ItemCommandEvent] - Item 'Corridor_Ambiance_4' received command 100
2020-03-01 16:11:35.045 [nt.ItemStatePredictedEvent] - Corridor_Ambiance_4 predicted to become 100
2020-03-01 16:11:35.060 [GroupItemStateChangedEvent] - gCorridorLights changed from OFF to ON through Corridor_Ambiance_4
2020-03-01 16:11:35.062 [vent.ItemStateChangedEvent] - Corridor_Ambiance_4 changed from 0 to 100
...
Openhablog:
2020-03-01 16:11:35.014 [INFO ] [g.eclipse.smarthome.model.script.Pir] - Corridor: Korytarz - ruch, jasnosc: 1
2020-03-01 16:11:35.024 [INFO ] [g.eclipse.smarthome.model.script.Pir] - Corridor: Aktywacja swiatla w trybie dzien
------------Second situation------------
Events log:
2020-03-01 16:42:22.771 [ome.event.ItemCommandEvent] - Item 'Corridor_MotionSensor' received command OFF
2020-03-01 16:42:22.793 [nt.ItemStatePredictedEvent] - Corridor_MotionSensor predicted to become OFF
2020-03-01 16:42:22.831 [vent.ItemStateChangedEvent] - Corridor_MotionSensor changed from ON to OFF
2020-03-01 16:42:31.496 [ome.event.ItemCommandEvent] - Item 'Corridor_Ambiance_1' received command 0
2020-03-01 16:42:31.498 [nt.ItemStatePredictedEvent] - Corridor_Ambiance_1 predicted to become 0
2020-03-01 16:42:31.511 [vent.ItemStateChangedEvent] - Corridor_Ambiance_1 changed from 100 to 0
2020-03-01 16:42:31.801 [ome.event.ItemCommandEvent] - Item 'Corridor_Ambiance_2' received command 0
2020-03-01 16:42:31.803 [nt.ItemStatePredictedEvent] - Corridor_Ambiance_2 predicted to become 0
...
Openhablog:
2020-03-01 16:42:31.177 [INFO ] [g.eclipse.smarthome.model.script.Pir] - Corridor: Korytarz - koniec ruchu, jasnosc: 11
Begining of the rules - the log is in first line of each rule:
rule Pir_Corridor_On
when
Item Corridor_MotionSensor changed to ON
then
logInfo("Pir", "Corridor: Korytarz - ruch, jasnosc: " + Corridor_MotionSensor_Luminance.state)
...
rule Pir_Corridor_Off
when
Item Corridor_MotionSensor changed to OFF
then
logInfo("Pir", "Corridor: Korytarz - koniec ruchu, jasnosc: " + Corridor_MotionSensor_Luminance.state)
...
After restarting OH or saving the rule file, there is a known lag in the old rule engine after the first trigger of a rule. Does this explain your issue or is it happening after every trigger? The new rule engine does not have this lag.
This is odd and scary. I have always noticed a little delay the first time a rule runs. With no restarting OpenHAB or reloading the rules, I notice the delay when I get home from work and it has been 9 hours of no activity in the house so I’m guessing the rule gets removed from memory after a certain period of time (I’m guessing??)
While I appreciate Scott’s suggestion that the new rules engine may help, this seems like something we need to look into
I’d guess Java does its garbage collection. That results in a need to recompile rules, explaining that constant offset. Give it more heap space to play with (-Xms parameter).
Why don’t you run openHABian, it has optimized Java parameters so that does not happen.
I don’t remember the reasons now
After increase heap to " -Xms350m -Xmx512m" and check in shell:info if it’s correct applied, the same 8 seconds delay after fire trigger and about 3 minutes of waiting.
I’d guess 3 mins isn’t sufficient. And 350m is a compromise that might not be enough if you have large amounts of code and data.
Check CPU load with top. It has to be well below 100% and would jump to well above once triggered.
Garbage collection is just one potential reason for recompilation to happen. There’s others such as when you touch a rules or items file.
I mean 3-5 minututes is the time after which I need to wait another 8 seconds between trigger and first reaction of rule.
I have full awareness of this and always let the rule load for the first time after edit or restart and my observations starting later.
I removed all my rules file from rules directory, created new file and put inside it part with corridor rule as below. Now the lag after 3-5 min is about 1.2-1.5 second. It’s weird…
rule Pir_Corridor_On
when
Item Corridor_MotionSensor changed to ON
then
logInfo("Pir", "Corridor: Korytarz - ruch, jasnosc: " + Corridor_MotionSensor_Luminance.state)
logInfo("Pir", "Corridor: Aktywacja swiatla w trybie dzien")
sendCommand(Corridor_Ambiance_4, 100)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_3, 100)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_2, 100)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_1, 100)
end
rule Pir_Corridor_Off
when
Item Corridor_MotionSensor changed to OFF
then
logInfo("Pir", "Corridor: Korytarz - koniec ruchu, jasnosc: " + Corridor_MotionSensor_Luminance.state)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_1, 0)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_2, 0)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_3, 0)
Thread::sleep(300)
sendCommand(Corridor_Ambiance_4, 0)
end
And next observation, now I put into my only one rules file two simpler rules as below. In that case there is very small lag, about 250ms. If I fast turn on and off the source item there is no lag at all so the problem still exists.
var String ir_path = "/etc/openhab2/ir_sequences/ir_sequences.sh "
rule "Ir_Music_On"
when
Item IR_Music received command ON
then
logInfo("Pir", "Start of Ir music on rule")
executeCommandLine(ir_path + "JVC-Aux", 5000)
end
rule "Ir_Music_Off"
when
Item IR_Music received command OFF
then
logInfo("Pir", "Start of Ir music off rule")
executeCommandLine(ir_path + "JVC-Power", 5000)
end
Enable vast debugging such as org.openhab and org.apache.karaf to see if there’s bindings to reinstall or similar stuff going on. See also 2.5 issues after upgrade .
My rules configuration is back to my normal daily configuration as in the begining and there is still 8 seconds lag. My increased heap sizes: Maximum heap size 605,824 kbytes, Committed heap size 445,824 kbytes.
In the log I see failed uninstalling openhab ui dashboard (every minute). Do you think this could be a problem?
2020-03-01 19:35:39.582 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-03-01 19:35:39.675 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2020-03-01 19:35:52.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Command received zwave:device:77badcb7:node22:alarm_motion --> OFF [OnOffType]
2020-03-01 19:35:52.108 [DEBUG] [ternal.converter.ZWaveAlarmConverter] - NODE 22: No event found with name 'eventOFF'
2020-03-01 19:35:52.111 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: No messages returned from converter
2020-03-01 19:35:59.677 [INFO ] [g.eclipse.smarthome.model.script.Pir] - Kitchen: Czujka w kuchni changed to OFF. 1=100, 2=100, Current 1 status=100, Current 2 status=100, kitchenOnByMotion=true
2020-03-01 19:35:59.684 [INFO ] [g.eclipse.smarthome.model.script.Pir] - Kitchen: Wylaczanie lamp w kuchni
Yes. Note sure it’s directly related to your problem but a problem it is.
Check the upgrade issues thread I linked to, it’s not exactly the same but should get you an idea where to look for.
addons.cfg is all commented, and other files doesn’t contain anything suspicious.
Should I try to uninstall and install again of dashboard at paper ui webpage?
