8 seconds lag always after few minutes without script activation

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 .

I set:

log:set DEBUG org.openhab.core
log:set DEBUG org.openhab.model.script.rules
log:set DEBUG org.openhab.model.script.engine
log:set DEBUG org.apache.karaf

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?

image

obviously the difference in how big the file is has an effect on the amount lag

yes, that is what is causing the rules file to be reloaded me thinks
there is the issue
uninstall ui dashboard to test

Yes, exactly. Now I try to get rid of this message:

[core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed

I’m don’t know how to do this.

use the karaf console
no wait… try uninstalling it in Paper UI shown above

[this post was edited to remove idiotic suggestion]

I don’t have any dashboard entry here:

bundle:list:

...
246 │ Active │  80 │ 2.5.2                   │ openHAB Add-ons :: Bundles :: IO :: Web Audio Support
247 │ Active │  80 │ 1.14.0                  │ openHAB InfluxDB Persistence bundle
248 │ Active │  75 │ 2.5.2                   │ openHAB Add-ons :: Bundles :: Transformation Service :: Map
249 │ Active │  75 │ 2.5.2                   │ openHAB Add-ons :: Bundles :: Transformation Service :: RegEx
250 │ Active │  80 │ 2.5.2                   │ openHAB UI :: Bundles :: Basic UI
251 │ Active │  80 │ 2.5.2                   │ openHAB UI :: Bundles :: HABmin UI
252 │ Active │  80 │ 2.5.2                   │ openHAB UI :: Bundles :: HABPanel UI
253 │ Active │  80 │ 2.5.2                   │ openHAB UI :: Bundles :: Icon Set :: Classic
254 │ Active │  80 │ 2.5.2                   │ openHAB UI :: Bundles :: Paper UI
255 │ Active │  80 │ 2.5.2                   │ openHAB UI :: Bundles :: openHAB REST API Documentation
256 │ Active │  80 │ 1.23.0                  │ SnakeYAML
257 │ Active │  80 │ 0.9.10.v20160429-1435   │ reflections (wrap)
...

yeah, sorry, that won’t work, it is complaining about it not being installed and yet shows as install in your screan shot of Paper ui (clearly it is not as per your bundle:list)
Try uninstalling it from Paper UI

Few minutes later, keeps spinning:
image
In logs nothing new, it looks like nothing in uninstall process is happening…

2020-03-01 20:28:55.745 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-03-01 20:28:55.865 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2020-03-01 20:29:22.827 [WARN ] [ng.exec.internal.handler.ExecHandler] - Tried to execute '/opt/vc/bin/vcgencmd measure_temp', but it is not contained in whitelist.
2020-03-01 20:29:55.750 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-03-01 20:29:55.838 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2020-03-01 20:30:55.757 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-03-01 20:30:55.848 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed
2020-03-01 20:31:22.832 [WARN ] [ng.exec.internal.handler.ExecHandler] - Tried to execute '/opt/vc/bin/vcgencmd measure_temp', but it is not contained in whitelist.
2020-03-01 20:31:55.763 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-03-01 20:31:55.856 [DEBUG] [core.karaf.internal.FeatureInstaller] - Failed uninstalling 'openhab-ui-dashboard': Feature named 'openhab-ui-dashboard/0' is not installed

Maybe it does nothing helpful until you restart.
You might now want to look at addons.config

Check addons.config down in the userdata tree. Stop OH before editing though.

yeah Marcin the endless spinning in Paper UI isn’t unusual
As Rossko said, restart openhab

I did that:

It solves problem with uninstall dashboard.

But no the main problem, there is still 8 seconds delay between event and rule reaction…

1 Like

Please be clear about the circumstances; a delay of first-time execution after reboot is expected. Don’t let us just make assumptions that you still mean later on, after some minutes uhh “not used timeout”

A diagnostic move; make sure your xxx.rules file has a little rule triggered on System started that need only log that it ran.
This will give two effects - you’ll be able to see if the rules file is actually reloaded (there have been reports of such)
and as a bonus, it will take the first-time-only delay out of the picture.

I always do the first load of the rule after reboot/save file and then I make the observations, I wrote about it before. And I do tests more than one time, don’t worry :slight_smile:.

28 posts were split to a new topic: Rule execution lags, possibly Java GC

9 posts were split to a new topic: Rules to reload on thing changes