Rule execution lags, possibly Java GC

Setup, Configuration and Use Scripts & Rules
41

@mstormi Took a while, but Ive performed a good few tests:

Boot area being modified
Ive setup an entirely new build of Armbian OS, based on latest bionic build version, then updated, then performed a full install of OpenHabian. The good news is that the Boot area was NOT modified in any way and the system continued to boot fine.

I suspect that when I tried OpenHabnian a couple of years ago, the build and u-boot area had something similar to the Khadas build, which cased things to be removed. Though I know that the boot process has been modified over the last year and of course, generally the system is updated anyway… so my suspicion is that the Arping install issue may only be an issue on much older builds of Ubuntu on Arm and therefore pretty rare nowadays… However at the time, it caused me a problem and thats why I never used OpenHabian.

JAVA performance etc
-XX:+UseParallelGC - My openhab just wont fully start if I use that, so Ive settled on the -XX:+UseParNewGC as the only option in my specific case. I cant figure why its an issue, but it is.

-Xcomp and -XX:+NeverTenure - Ive settled on using both of these, as well as adding XMM and XMS settings to increase my memory. Either of those alone, doesnt seem to have a full result, but all the above in tandem seems to be working ok (so far).

So in my case, things are… stable now. Openhab is a bit slower to actually start up and first time a rule is processed, its slow, but after 1st time rule run, things are remaining pretty fast.

I guess I will monitor over time and feed back here if theres any variation. I may also try reducing commands out of the EXTRA_JAVA_OPTS to see if I can figure my smallest/most optimal settings, though that will take time to test.

Openhab on ARM/Ubuntu etc
Ive now got a system here I can trash/rebuild/play around with… if theres anything else you would like me to look at for you or try, specific to these systems… as long as I have time, Im happy to give something a go!

If you need more info/test on any of the above, let me know!

Thanks for all your help/input on this, its been really appreciated!

1 Like
42

FWIW another bunch of stuff to try:

BTW I’ve added AdoptOpenJDK as an alternative to Zulu. Maybe it makes a difference to your original problem.
If you want to help with testing, cd /opt/openhabian; git pull; git checkout testbuild then in menu 40 change Java.

43

Ok… theres a fair few settings I could try out there :slight_smile:

Ill try out the AdoptOpenJDK though first. Ill keep the settings vanilla and then maybe try XMM and XMS additions and see if that gives any different results from the Zulu Java.

Ill give it a few days run and let you know.

44

FWIW, we’ve just added Zulu 11 and Adopt 11 as java options to openhabian.
Update when openhabian-config asks you to (stay on master) to find it in menu 40.

45

Hi… Sorry I thought I replied last week to you, but obviously I didnt! (It was a very busy week for me mind).

Adopt OpenJDK seems to run ok. Still the occasional delays, but nothing worse. Im guessing that Openhab has now been made functional with Java 11? (It didnt used to be as I recall?)

Im happy to swap again and give that a shot… see how it goes!

Hope you’re keeping well.

Thanks

46

Well that’s to be found out. Anything to require a serial interface is said to be problematic, still.

47

Hi

Hope you are keeping well. So Ive been trying out Zulu 11… It seems to be running ok on my setup. There are still occasional delays here and there, but overall I think its being a much better experience than v8 and the delays seem much fewer/far between… I guess its memory management is better in whatever way. At this time Im only running it with XMS and XMX settings, similar to what we have listed before.

For me at least, Id say that this has resolved my initial complaints to a satisfactory or more than satisfactory level… meaning I would never have raised any issues about delays, were my system running this well on v8.

I dont however have anything serial to test that side of things with… so I cant provide feedback there.

If other people get similar results to myself and there is no other major gotchas with going up to v11, Id say the upgrade is very worthwhile.

Thanks

48

Exactly what I do (Zulu 11, too, with no special -XX: options but Xmx/Xms only).
And yes, I, too, feel my (few) delays are minimized or gone. It’s just a feeling, however. I don’t have any tests or measurements to support that statement.

The test-drive is to find out about compatibility of Java 11 with OH 2.5 rather than about Java tuning, but if it helps, why not :slight_smile: Status of findings see over there.

49

@ewrw @mstormi hello I expirenced the same issue and I am using raspberry pi 4 with 4gb with openhabian how can I solve this issue???

50

@milo

To to summarize, you’re getting a delay on actions/rules processing…not just on the 1st time a rule runs, but intermittently after the rule hasnt been run e.g. the system has been booted for 24+ hours… the rule you are experiencing the delay with HAS been run before in that 24 hours… but now its being slow/delayed again?

If thats what you’re experiencing, obviously there are a ton of variables involved e.g. have you a massive rule-set etc… but for the purposes of this reply, Ill just assume theres nothing too special going on… that your device doesnt have a lack of memory or is busy doing much more than running Openhab… But those are things you would need to consider.

The seeming root cause with my setup was Azul Java v8 not having enough memory given to it to keep all my rules stored in memory… so this would result in garbage collection occurring … which means the rule is removed from memory and has to be loaded from disk again (causing the delay).

In my case, the rules would be removed from memory because either:

  • Java didnt have enough memory to store all rules being used, so had to swap them in/out of memory.
  • They rule in question just hadnt been used in a long time so was dropped out of memory for memory management purposes.
  • Java v8 wasnt as good at memory management as later versions of Java seemingly are.

So… Things you can try:

  • Currently, at the bottom of this long post, you can see we are testing later versions of Java (v11) which Marcus is involved in the testing/approval process of that. So you could try out a later version too (instructions are a few posts up from this one). Please remember though, this is a test, so you could experience other issues.

  • Use the XMX and XMS settings to increase your java memory available. You could also use this with the Java 11. Certainly this is what I am doing and things seem to be better for me. It may provide you some improvement with Java v8. Suggested settings are in the above posts as well as how to implement it (just a quick edit of a config file).

  • There are other settings which are listed in the above posts, and you edit the same configuration file, these basically alter the way that Java Garbage collection works… and I did have some successes with these. I at least reached a satisfactory state with Java v8… though I am now on testing Java v11 because its (in my view) just a better version of Java… and it seems to be working better at this time.

You will always get the initial delay on a reboot where the rules are loaded for the 1st time, but after that, things should be smoother.

My recommendation overall, would be to check you have spare memory and your system isnt overloaded with other things taking cpu/memory…and if all looks good there, Id suggest change the EXTRA_JAVA_OPTS settings to add your XMX and XMS settings to something like 400 800 (look at the above posts for the my settings)… try that on Java v8.

If that doesnt relieve things and you dont have any other issues with trying it, Id go to Java v11 and keep in the XMX and XMS settings and feed back to Marcus if you still have problems.

EDIT: Just adding this to the post
EXTRA_JAVA_OPTS in the /etc/default/openhab2 file.

EXTRA_JAVA_OPTS="-Xms400m -Xmx800m"

Something like the above is quite a lot of memory to give Openhab on a small setup (in my view)… but it might be a good place to start testing and probably work your way in 50MB chunks if it resolves things e.g. -Xms350m -Xmx750m etc… If the 400 and 800 have no impact… def try the Java v11 with these settings… otherwise, assuming no other cpu/memory issues… youre looking at adding other Garbage collection settings and checking there are no issues in your rules.

Thats my thoughts at least.

Thanks

51

Thanks @ewrw for your summary

This is what I experienced Problems with item changed and-received-update - #12 by rossko57

After some hours not using a rule it is delayed by 20s. And I only run openhab on it…there are some posts here with the same issue faced…I will link your post to them

52

@milo

Certainly my rules did always run, but the 20 second delay is very much the reason I started off my post and investigation.

As you noted in your other post, your MQTT messages are arriving… so if its an intermittent 20 second delay kind of problem you’re experiencing, then yes, the stuff Ive said above should work or be the right direction to look at.

If on the other hand, the MQTT messages arrive (according to openhab AND mosquito logs), but its a rule not being processed at all, even after 20+ seconds… then my guess would be a problem with the rule in question OR overlapping rules competing with each other OR not enough threads available to process it (though I think not enough threads would cause a further delay than nothing processed at all). You can bump the thread count up though if you need in the Openhab settings files somewhere.

It could even be that other rules are tying up all your threads if those rules have issues within them. (just trying to give you other ideas if you get nowhere with the Java changes).

I think 10-15 threads is/was the standard setting… but dont quote me on that… and obviously smaller processors will only handle so much… but you could always bump it up 5-10 more threads without much issue IF youre convinced that was a problem and your system is running a heavier workload rules wise. (Im not claiming to be an expert at that area, so this is more my own previous research/experience and there may be much better info from other forum posts).

Hopefully the Java bits fixes it though… it may take you a few days of changing a setting, seeing how that goes, changing another setting, see how that goes etc. It took me a couple of weeks testing individual changes with Java v8 and different settings.

Best method… make your config change… reboot your server… make the rule you have a problem with run once after the reboot so its loaded into memory… then leave it 6-8 hours or overnight… test your rule again and see if it has the delay. Id always expect the occasional delay to occur from time to time… but not repeatably/frequently e.g. every morning after sleep the rules are all delayed again, which is what I was experiencing.

Hope you manage to figure it!! :slight_smile:

53

@ewrw yes the rule is handled correctly after using it once only the first start after 2h not using there is the delay…

I will check and report back

54

@ewrw is there a way to see the heap used and if there is not much of the heap left?

55

Hi Milo

Sorry for the late reply… I couldnt pick up my emails for a few days, so only just seen this.

I think on the Extra Java Options you need to add:

-Xloggc:<file>

Detailed here:

This logs out your Java memory settings… though, Marcus was looking through those logs for me to figure what was going on, so I cant tell you what to look for in the files themselves.

Thanks

56

@milo First thing you should do is find out where the delay is happening.
Insert debug statements into your rule(s) that run with a delay or enable debug level for scripts
(if you log using logDebug("tag", "debug XXX"), use log:set debug org.eclipse.smarthome.model.script.tag in Karaf console).

Compare these with events.log

also remember to correctly set an RPI’s date, it has no RTC.

57

Hello and how do I display now this debug entry?

58

It appears as a line in openhab.log.

59

Got it…

What is seen is

2020-06-26 06:00:51.992 [vent.ItemStateChangedEvent] - string_button_statejson changed from {"event":"p[6].b[4].val", "value":0} to {"event":"p[6].b[4]", "value":"ON"}

2020-06-26 06:00:51.994 [vent.ItemStateChangedEvent] - string_button_statejsonvalue changed from 0 to ON

2020-06-26 06:00:51.994 rule exexuted

If I wait for ~1h doing nothing

It looks like


2020-06-26 07:00:51.992 [vent.ItemStateChangedEvent] - string_button_statejson changed from {"event":"p[6].b[4].val", "value":0} to {"event":"p[6].b[4]", "value":"ON"}

2020-06-26 07:00:51.994 [vent.ItemStateChangedEvent] - string_button_statejsonvalue changed from 0 to ON
2020-06-26 07:01:21.994 rule exexuted

And after it runs ones it will come up directly

60

That’s curious, a 30 second delay, exact to the millisecond.