Slow rule trigger

[DigitalDB (C S)]

Platform information:

• Hardware: Raspberry Pi 3 Model B Rev 1.2
• OS: Raspbian GNU/Linux 10 (buster) from OpenHABian install
• Java Runtime Environment: openjdk version “1.8.0_222”
  OpenJDK Runtime Environment (Zulu8.40.0.178-CA-linux_aarch32hf) (build 1.8.0_222-b178)
  OpenJDK Client VM (Zulu8.40.0.178-CA-linux_aarch32hf) (build 25.222-b178, mixed mode, Evaluation)
• openHAB version: 2.5.3-1 (Release Build)
• Updated all apt
• CPU load is only 1-5%

When an item changes it should start a rule but it takes between 5 and 20 seconds for the rule to trigger (eg. turn a group of lights on with a switch on the sitemap). Is this usual?

I have uninstalled all unused bindings, UI, addons, removed all rules and just added the lights rule and stopped OH service and restarted Pi.

The lights are mostly using the WiFiLED binding but the delay is with all rules, not just lights. If I operate the light from the sitemap directly it is instant but through the rule there is a 5-20 second delay before the rule triggers.

The light rule I was using to test is simple:

rule "Kitchen Mood Lights" //Change light status
when
    Item GF_Kitchen_Mood changed
then
	logInfo("Lights", "Kitchen Mood changed")
	if (GF_Kitchen_Mood.state == 'off') {
		logInfo("Lights", "Kitchen Lights Off")
		GF_Kitchen_Ceiling.sendCommand(OFF)
		GF_Kitchen_Worktop.sendCommand(OFF)
		GF_Kitchen_Floor.sendCommand(OFF)
		GF_Dining_MainLt.sendCommand(OFF)
		GF_Dining_BacklightPW.sendCommand(OFF)
		GF_Kitchen_Spot.sendCommand(OFF)
		GF_Kitchen_Bar.sendCommand(OFF)
		logInfo("Lights", "Kitchen Lights Off - Done")
	}
	else if (GF_Kitchen_Mood.state == 'morning') {
		logInfo("Lights", "Kitchen Morning Lights")
		GF_Dining_FishtankPW.sendCommand(ON) //
		GF_Kitchen_Ceiling.sendCommand(ON) //
		GF_Kitchen_Worktop.sendCommand(ON) //
		GF_Kitchen_Floor.sendCommand(OFF)
		GF_Dining_MainLt.sendCommand(OFF)
		GF_Dining_BacklightPW.sendCommand(OFF)
		GF_Kitchen_Spot.sendCommand(OFF)
		GF_Kitchen_Bar.sendCommand(OFF)
		logInfo("Lights", "Kitchen Morning Lights - Done")
	}
	else if (GF_Kitchen_Mood.state == 'evening') {
		logInfo("Lights", "Kitchen Evening Lights")
		GF_Kitchen_Ceiling.sendCommand(ON) //
		GF_Kitchen_Worktop.sendCommand(ON) //
		GF_Kitchen_Floor.sendCommand(OFF)
		GF_Dining_MainLt.sendCommand(OFF)
		GF_Dining_BacklightPW.sendCommand(OFF)
		GF_Kitchen_Spot.sendCommand(OFF)
		GF_Kitchen_Bar.sendCommand(OFF)
		logInfo("Lights", "Kitchen Evening Lights - Done")
	}
	else if (GF_Kitchen_Mood.state == 'dinner') {
		logInfo("Lights", "Kitchen Dinner Lights")
		GF_Kitchen_Ceiling.sendCommand(ON) //
		GF_Kitchen_Worktop.sendCommand(OFF)
		GF_Kitchen_Floor.sendCommand(OFF)
		GF_Dining_MainLt.sendCommand(ON) //
		GF_Dining_BacklightPW.sendCommand(ON) //
		GF_Kitchen_Spot.sendCommand(OFF)
		GF_Kitchen_Bar.sendCommand(ON) //
		logInfo("Lights", "Kitchen Dinner Lights - Done")
	}
end

The log shows no errors but does show the massive delay that happens every time and not just for the first compile:

2020-04-02 20:04:04.141 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Mood' received command evening
2020-04-02 20:04:04.152 [vent.ItemStateChangedEvent] - GF_Kitchen_Mood changed from dinner to evening

2020-04-02 20:04:19.974 [INFO ] [clipse.smarthome.model.script.Lights] - Kitchen Mood changed
2020-04-02 20:04:25.491 [INFO ] [clipse.smarthome.model.script.Lights] - Kitchen Evening Lights
2020-04-02 20:04:25.528 [INFO ] [clipse.smarthome.model.script.Lights] - Kitchen Evening Lights - Done

2020-04-02 20:04:25.535 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Ceiling' received command ON
2020-04-02 20:04:25.537 [nt.ItemStatePredictedEvent] - GF_Kitchen_Ceiling predicted to become ON
2020-04-02 20:04:25.578 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Worktop' received command ON
2020-04-02 20:04:25.601 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Floor' received command OFF
2020-04-02 20:04:25.637 [ome.event.ItemCommandEvent] - Item 'GF_Dining_MainLt' received command OFF
2020-04-02 20:04:25.663 [ome.event.ItemCommandEvent] - Item 'GF_Dining_BacklightPW' received command OFF
2020-04-02 20:04:25.673 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Spot' received command OFF
2020-04-02 20:04:25.684 [ome.event.ItemCommandEvent] - Item 'GF_Kitchen_Bar' received command OFF
2020-04-02 20:04:25.689 [nt.ItemStatePredictedEvent] - GF_Kitchen_Worktop predicted to become ON
2020-04-02 20:04:25.723 [nt.ItemStatePredictedEvent] - GF_Kitchen_Floor predicted to become OFF
2020-04-02 20:04:25.754 [nt.ItemStatePredictedEvent] - GF_Dining_BacklightPW predicted to become OFF
2020-04-02 20:04:25.780 [vent.ItemStateChangedEvent] - GF_Kitchen_Worktop changed from OFF to ON
2020-04-02 20:04:25.785 [vent.ItemStateChangedEvent] - GF_Dining_MainLt changed from ON to OFF
2020-04-02 20:04:25.789 [vent.ItemStateChangedEvent] - GF_Dining_BacklightPW changed from ON to OFF
2020-04-02 20:04:25.792 [vent.ItemStateChangedEvent] - GF_Kitchen_Bar changed from ON to OFF

CPU Load over the week is always low:

I am only using 128 Processes of 32768 max available.

Any ideas how to fix this issue?

Thanks

[rlkoshak (Rich Koshak)]

Is it slow every time the Rule runs or only the first time it runs after OH restarts/OH first loads the .rules file?

There are known issues running OpenJDK with openHAB that are particularly pronounced on ARM processors (i.e. RPi). The openHAB docs recommends running with Zulu Java instead of OpenJDK.

[DigitalDB (C S)]

It is slow every time the rule runs but the time delay varies

[rossko57]

Observe closely; there is a version of this kind of thing where if you run the run again within a few minutes, it is fine, but the delay re-appears after some extended time idle.

[DigitalDB (C S)]

I checked the Java version and both are shown:

[21:09:22] openhabian@openhab:~$ java -version
openjdk version “1.8.0_222”
OpenJDK Runtime Environment (Zulu8.40.0.178-CA-linux_aarch32hf) (build 1.8.0_222-b178)
OpenJDK Client VM (Zulu8.40.0.178-CA-linux_aarch32hf) (build 25.222-b178, mixed mode, Evaluation)

Could this be the issue?

[DigitalDB (C S)]

Yes this is exactly the behaviour.
I have changed the switch and sometimes it is instant when I change it straight after the first change, most of the time it is 10 seconds, others it is 20 seconds.

[rossko57]

Try this circumvention

Idea: hack to avoid rule delay, keep time-critical rules in memory

Maybe the java experts can comment on this… Problem: Rules can take 10-20 seconds to trigger if they not have triggered very recently. My theory is that a JIT compiler runs over them before they are executed, and after some time of not using it, the result is purged from memory. Thus it has to be compiled again, which takes time on my Raspi (3+). My solution: I put this in the rule file that I want to prevent from being recompiled: rule "keep this thing in memory" //use the compiled code in t…

[mstormi (Markus Storm)]

It’s possibly Java garbage collection. Increase heap size (-Xms parameter) as told in the thread @rossko57 linked to.

Why did you install Raspbian and Java on your own and did not go for openHABian ? It saves you from running into issues and incompatibilities like this.

[DigitalDB (C S)]

Thanks all for the quick replies.
Adding the cron timer worked well and I have very little delay.

I’ll also try the -Xms change out tomorrow as the delay is across all the rules.

[DigitalDB (C S)]

@mstormi I tried to edit the -Xms parameter and got an error when I tried to save it.
I cancelled the changes and reopened the openhab2 file, without making any changes I tried to save it and I got the error again

/etc/default/openhab2: syntax error near line 35

Line 35 is

EXTRA_JAVA_OPTS=“-Xms250m -Xmx350m”

[mstormi (Markus Storm)]

Possibly your editor config? I don’t know your OS setup.
Again, why don’t you move to openHABian?
It’s right there so we don’t have to go through that hassle with each and every user.

[DigitalDB (C S)]

I loaded it onto the Pi using the OpenHABian image, this shows Raspbian when I login to OpenHABian. My setup is OpenHABian on the Pi3 b v1.2

[mstormi (Markus Storm)]

@DigitalDB

My setup is OpenHABian on the Pi3 b v1.2

v1.2 of what ?
And why don’t you write that ? Correct your original post.
openHABian already has -Xms set so no need to edit that.

[DigitalDB (C S)]

Thanks @mstormi the full details are below, I will correct the info in the original request.
My -Xms is set to -Xms250m -Xmx350m, I haven’t adjusted it since I installed OpenHABian is this correct or should I still increase it?

Release = Raspbian GNU/Linux 10 (buster)
Kernel = Linux 4.19.97-v7+
Platform = Raspberry Pi 3 Model B Rev 1.2
Uptime = 0 day(s). 23:58:44
CPU Usage = 10.49% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
CPU Load = 1m: 0.64, 5m: 0.90, 15m: 0.97
Memory = Free: 0.16GB (17%), Used: 0.79GB (83%), Total: 0.95GB
Swap = Free: 0.07GB (81%), Used: 0.01GB (19%), Total: 0.09GB
Root = Free: 24.38GB (87%), Used: 3.39GB (13%), Total: 28.99GB
Updates = 0 apt updates available.
Sessions = 1 session(s)
Processes = 121 running processes of 32768 maximum processes
openHAB 2.5.3-1 (Release Build)

Java:

openjdk version “1.8.0_222”
OpenJDK Runtime Environment (Zulu8.40.0.178-CA-linux_aarch32hf) (build 1.8.0_222-b178)
OpenJDK Client VM (Zulu8.40.0.178-CA-linux_aarch32hf) (build 25.222-b178, mixed mode, Evaluation)

[mstormi (Markus Storm)]

@DigitalDB

the full details are below, I will correct the info in the original request.

You were missing the most important information: that you already run openHABian. Instead it said it’s a stretch based Raspbian. That was very much misleading.

@DigitalDB

My -Xms is set to -Xms250m -Xmx350m, I haven’t adjusted it since I installed OpenHABian is this correct or should I still increase it?

No it’s fine.

[DigitalDB (C S)]

Thanks
My rules are slow if I don’t add the cron rule to keep them in the memory, the workaround works but is there a solution to the cause of the problem?

[rossko57]

Nope. The workaround is pretty low-cost, though.