Startup takes up to 70 Minutes - Raspberry Pi 3 Model B

wlanrouter1 · October 6, 2020, 3:55pm

How did the B came in? I never edited this file manually. Same char at legacy! So true means all bindings are downloaded? When? On every start? Where to change it, what to do about the char B?

I know, but as the Debian installation is still my first installation and I wanted to start from scratch and configure everythings by files this time. All good, I do as I told me, just want to clean up too.

Update: The openhabian installation is driving me nuts!!!

I’ve got pretty far by adding things, items, bindings. Then I went to copying rules. I copied first 18 rules at once. Measured the boot time by stopwatch. About 4 Minutes. After I added additional few rules, time went up to 7 Minutes. So I erased the last added rules. 4 Minutes again.

I wrote a shell script which is starting by cron @reboot.
It saves the OS boot timestamp. After that it sends ON to an item (boot_input) by REST api frequently (every 5 seconds) and see if bootTestRule is working and boot_output has changed from NULL to ON. After that the script writes the difference between the OS boot timestamp and now timestamp into that file, waits 30 seconds, stops openhab service, reboots the OS and starts again.
That is done 10 times. So I have time measurements of startup time of 10 startups without any changes by me. So i can compare startup time with every change I will further do.

rule
	"bootTestRule"
when
	Item boot_input changed
then
	boot_output.sendCommand( ON )
end

This is the startup duration time until the the bootTestRule worked out with 18 rules:
5:25 Minutes
4:36 Minutes
5:54 Minutes
6:14 Minutes
4:53 Minutes
4:41 Minutes
4:44 Minutes
4:34 Minutes
4:31 Minutes

After that I added another rule and startes the script again (automatically 10 times). Not so complicated rule to me.
5:18 Minutes
6:09 Minutes
6:48 Minutes
5:29 Minutes
5:24 Minutes
6:56 Minutes
5:23 Minutes
5:13 Minutes
5:07 Minutes

Rule which added almost a minute of startup time:

rule
	"regelStatusHelligkeitAenderung"
when
	Item Bewegungsmelder1_helligkeit changed
then
	var helligkeit = Bewegungsmelder1_helligkeit .state
	
	var leicht = 175
	var mittel = 149
	var dunkel = 122
	var voll = 10
	var rollo_mittel = 70
	var rollo_sehr = 20

	if (helligkeit < voll && st_helligkeit_dunkel_voll.state != ON) st_helligkeit_dunkel_voll.sendCommand(ON)
	else if (helligkeit > (voll + 20) && st_helligkeit_dunkel_voll.state != OFF) st_helligkeit_dunkel_voll.sendCommand(OFF)
	
	
	if ( helligkeit < dunkel || ( helligkeit < (dunkel + 10) && st_helligkeit_dunkel_sehr.state != OFF ) ) {
	
		if ( st_helligkeit_dunkel_sehr.state != ON ) logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: jetzt dunkel.")
		if ( st_helligkeit_dunkel_sehr.state != ON ) st_helligkeit_dunkel_sehr.sendCommand(ON)
		if ( st_helligkeit_dunkel_mittel.state != OFF ) st_helligkeit_dunkel_mittel.sendCommand(OFF)
		if ( st_helligkeit_dunkel_leicht.state != OFF ) st_helligkeit_dunkel_leicht.sendCommand(OFF)
		if ( st_helligkeit_dunkel_aus.state != OFF ) st_helligkeit_dunkel_aus.sendCommand(OFF)


	} else if (helligkeit < mittel || ( helligkeit < (mittel + 10) && st_helligkeit_dunkel_mittel.state != OFF )) {
		
		if ( st_helligkeit_dunkel_mittel.state != ON ) logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: jetzt mittel.")
		if ( st_helligkeit_dunkel_sehr.state != OFF ) st_helligkeit_dunkel_sehr.sendCommand(OFF)
		if ( st_helligkeit_dunkel_mittel.state != ON ) st_helligkeit_dunkel_mittel.sendCommand(ON)
		if ( st_helligkeit_dunkel_leicht.state != OFF ) st_helligkeit_dunkel_leicht.sendCommand(OFF)
		if ( st_helligkeit_dunkel_aus.state != OFF ) st_helligkeit_dunkel_aus.sendCommand(OFF)


	} else if (helligkeit < leicht || ( helligkeit < (leicht + 10) && st_helligkeit_dunkel_leicht.state != OFF )) {
		
		if ( st_helligkeit_dunkel_leicht.state != ON ) logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: jetzt leicht.")
		if ( st_helligkeit_dunkel_sehr.state != OFF ) st_helligkeit_dunkel_sehr.sendCommand(OFF)
		if ( st_helligkeit_dunkel_mittel.state != OFF ) st_helligkeit_dunkel_mittel.sendCommand(OFF)
		if ( st_helligkeit_dunkel_leicht.state != ON ) st_helligkeit_dunkel_leicht.sendCommand(ON)
		if ( st_helligkeit_dunkel_aus.state != OFF ) st_helligkeit_dunkel_aus.sendCommand(OFF)
		
		
	} else {
		if ( st_helligkeit_dunkel_aus.state != ON  )logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: jetzt hell.")
		if ( st_helligkeit_dunkel_sehr.state != OFF ) st_helligkeit_dunkel_sehr.sendCommand(OFF)
		if ( st_helligkeit_dunkel_mittel.state != OFF ) st_helligkeit_dunkel_mittel.sendCommand(OFF)
		if ( st_helligkeit_dunkel_leicht.state != OFF ) st_helligkeit_dunkel_leicht.sendCommand(OFF)
		if ( st_helligkeit_dunkel_aus.state != ON ) st_helligkeit_dunkel_aus.sendCommand(ON)
		
		
	}
	
	
	
	
	
	
	
	if ( helligkeit < rollo_sehr || ( helligkeit < ( rollo_sehr + 5) && st_helligkeit_rollo_sehr.state != OFF ) ) {
		
		if ( st_helligkeit_rollo_sehr.state != ON ) logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: Rollo jetzt sehr.")
		if ( st_helligkeit_rollo_sehr.state != ON )  st_helligkeit_rollo_sehr.sendCommand(ON)
		if ( st_helligkeit_rollo_mittel.state != OFF ) st_helligkeit_rollo_mittel.sendCommand(OFF)
		if ( st_helligkeit_rollo_aus.state != OFF ) st_helligkeit_rollo_aus.sendCommand(OFF)
		
		
	} else if (helligkeit < rollo_mittel || ( helligkeit < ( rollo_mittel + 5) && st_helligkeit_rollo_mittel.state != OFF )) {
		
		if ( st_helligkeit_rollo_mittel.state != ON ) logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: Rollo jetzt mittel.")
		if ( st_helligkeit_rollo_sehr.state != OFF )  st_helligkeit_rollo_sehr.sendCommand(OFF)
		if ( st_helligkeit_rollo_mittel.state != ON ) st_helligkeit_rollo_mittel.sendCommand(ON)
		if ( st_helligkeit_rollo_aus.state != OFF ) st_helligkeit_rollo_aus.sendCommand(OFF)
		
		
	} else {
		if ( st_helligkeit_rollo_aus.state != ON  )logInfo("st_helligkeit.rules", "regelStatusHelligkeitAenderung: Rollo jetzt hell.")
		if ( st_helligkeit_rollo_sehr.state != OFF )  st_helligkeit_rollo_sehr.sendCommand(OFF)
		if ( st_helligkeit_rollo_mittel.state != OFF ) st_helligkeit_rollo_mittel.sendCommand(OFF)
		if ( st_helligkeit_rollo_aus.state != ON ) st_helligkeit_rollo_aus.sendCommand(ON)
		
		
	}
end

After that, I have tried to add all missing rules (another 14) at once to see what startup time will turn to. My srcipt run endlessly. After checking what happend, I found out that not all rules were loaded. Even after hours of running. The bootTestRule, which worked before and was not touched since than, was not loaded anymore. I can reboot as often or wait as long as I want, rules are not loaded. Files are there, permissions and ownership are equal, filesystem is fine.

What is going on? Why are not all rules loaded? Why is adding one rule so much time to startup. Where to seach? I try so hard with karaf, but I don’t know where to look at.

mstormi · October 6, 2020, 4:06pm

Please - it’s openHAB to drive you nuts, not openHABian. That’s completely different things (and people to blame )

The load times you show are somewhat normal (btw to get specific log output set e.g.
log:set debug org.eclipse.smarthome.model.script.st_helligkeit.rules)

Some code constructions are known to be deadly for compilation times, Java math primitives like those I quoted for example. Try eliminating these ( ‘10.0’ instead of ‘10’ or better introduce Number variables instead at the beginning of a file).

wlanrouter1 · October 6, 2020, 5:22pm

I know, I know I just use those two terms to differe between my old server (installed debian and openhab by apt, which took 70 Minutes to boot) and new server (openhabian image).

Optimizing rules is definitely on my todo list to, as I never analyzed it before. Thanks for the hints.

But more important to me is: what do I need to debug in karaf, when not all rules are loaded. What is hapening there? Every single rules is loaded on the debian server. But debian and openhabian server have both the same openhab and bindings versions.
I could expand my script to also check if all rules are loaded by reading the openhab.log automatically anjd compare it to the folder. Add on rule after another and see when problems starting. But I am not sure if one of the rules is the reason why not all are loaded. Especially when working fine on the debian server and no error eintries in openhab.log

mstormi · October 6, 2020, 5:42pm

You should be seeing an error like
2020-10-06 19:41:04.722 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'Test.rules' has errors, therefore ignoring it: [392,1]: extraneous input 'xxxx' expecting EOF

wlanrouter1 · October 7, 2020, 1:58pm

There are no errors. But in the end the code constructions were the problem. In some rules I used massivly Java math primitives. I don’t know why, but all these rules active at once lead to massive problems. As I mentioned, not all rules were loaded, took very much time to startup, and so on.

I cleaned up as far as I could and deactivated all heavy mathematical rules. Now the startup time is about 10 Minutes which is fine for me. So many many thanks to all of you, for help me finding the cause. I will try to add those heavy rules automatically after startup is done.

May I ask for some help regarding this problem?

Is there a topic or HowTo regarding optimization of rules? Especially wen working with var and calculationg code. I have searched a lot, but keywords like “optimization” or “compiling” lead to a lot of topics which are not general or in a different context.
Is there a Chance to get the exact time the compiler need to compile the rule? Going just by karaf log wallclock doesnt seem to be really accurate.
Is there a way to get autmatically the names/array of the already loaded rules? Reading the openhab.log is pretty unfortunate. If you reboot mutliple times or change a rule while running, you have multiple entries.

hilbrand · October 7, 2020, 2:29pm

The best solution is to rewrite these rules to the new rule engine in either jython or Javascript as that doesn’t have the compilation problem.

rlkoshak · October 7, 2020, 2:36pm

Xtend, the language upon which Rules DSL is built, is a loosely typed language. It expects to not have to worry about the types of things until runtime. But it’s not a typeless language. When you do specify type, and most especially when you specify the type to be a primitive, the loader must do a lot more work at load time in order to check those types. And it’s really bad at this checking. Not bad in that it gets it wrong, but bad in that it looks like it’s using an exponential algorithm to do the job. Consequently it doesn’t take more than a few primitives to add minutes to your .rules files loading times.

Several but most of the content is buried in replies to posts like this one. The tl;dr though is to follow these rules of thumb:
- Never specify the type unless absolutely necessary.
- When it is necessary to specify the type, don’t do so until the last possible moment. For example, if you are calculating how long a Timer needs to be set for, don’t convert the number to an int until the actual call to now.plusSeconds(somenumber.intValue). Leave it as a Number up to that point.
- The result of all calculations and the type of all numbers (when a type is not provided) is BigDecimal which itself is of type Number. When a calculation doesn’t work because you are using the state of an Item, cast that state to Number. When defining a constant don’t provide a type and it will be a BigDecimal (e.g. var MY_CONSTANT = 7)

That’s all there is to it really. Avoid forcing the parser to look at type at load time and let it manage the type at runtime where it has way more information and can more efficiently handle it.

Not that I know of. Maybe you can put the rule engine into debug mode and see when it starts to load the rule if it logs that.
Not with Rules DSL.

I’ll also second Hilbrand’s suggestion (I was going to anyway but he beat me to it). None of these are problems with the new rule engine using Jython, JavaScript, or Groovy. I don’t know if they are problems with Rules DSL on the new rule engine in OH 3 or not. These languages have no similar problems with long load times. They also appear in PaperUI under Rules where they can be manually run (for testing), enabled, and disabled and you can see when they are running. And events get put into events.log when the rules are loaded and when they are running. All of these provide way more capability and information about the running of your rules than is possible with the default OH 2 rules engine.

It’s worth noting that the NGRE in OH 2 is just “the rules engine” in OH 3. And Rules DSL language is one of the supported languages. So even with .rules files some of the above advantages will come to .rules files too.

rossko57 · October 7, 2020, 2:46pm

Gut instinct was on the money there.

wlanrouter1 · October 8, 2020, 9:39am

You guys are amazing! Speaking of instinct, you always meantion Jython first, than JavaScript and Groovy. As my time is pretty limited, which of those three would you prefer to choose? I kind of can’t find an overview of Pros and Conts comparing those three. I don’t care about the complexity, just about posibilities and future-proof.

mstormi · October 8, 2020, 9:41am

Jython it is.

wlanrouter1 · October 8, 2020, 9:44am

Frustrating. Not even by openhab console? If not, it seems like I will need to acomplish it by a bash script and crontab and updating by REST Api by scanning the rules folder and greping openhab.log. I will post the final script, i guess some people could use that too.