8 seconds lag always after few minutes without script activation

Marcin_J · March 1, 2020, 4:36pm

I know this issue, but this is not that situation.
I have delay for the first and each subsequent time after save rules/openhab restart.

5iver · March 1, 2020, 4:41pm

What is the load at the time the rule is triggered? Assuming you are running on an SD card, have you swapped it out with a new one?

It would be interesting to know if you have the same result with the new rule engine.

Andrew_Rowe · March 1, 2020, 4:52pm

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

Marcin_J · March 1, 2020, 4:54pm

I checked. After activate the trigger I see high CPU load because of openhab process:

I didn’t try to use different SD card, I will try to use another card (no new because I don’t have one now).
I would have to learn new rules language.

mstormi · March 1, 2020, 4:55pm

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.

rossko57 · March 1, 2020, 5:02pm

There have been similar observations. Perhaps something has changed in recent releases that allows for more aggressive paging out of rules.

Marcin_J · March 1, 2020, 5:31pm

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.

mstormi · March 1, 2020, 5:54pm

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.

Marcin_J · March 1, 2020, 6:17pm

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

mstormi · March 1, 2020, 6:20pm

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 .

Marcin_J · March 1, 2020, 6:43pm

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

mstormi · March 1, 2020, 6:47pm

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.

Marcin_J · March 1, 2020, 7:01pm

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?

Andrew_Rowe · March 1, 2020, 7:06pm

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

Andrew_Rowe · March 1, 2020, 7:08pm

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

Marcin_J · March 1, 2020, 7:09pm

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.

Andrew_Rowe · March 1, 2020, 7:10pm

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

[this post was edited to remove idiotic suggestion]

Marcin_J · March 1, 2020, 7:16pm

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)
...

Andrew_Rowe · March 1, 2020, 7:19pm

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

Marcin_J · March 1, 2020, 7:33pm

Few minutes later, keeps spinning:

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