Openhab works slow, CPU of the RPI is high

Setup, Configuration and Use Runtime
32
  • Platform information:

    • Hardware: RPi 3B+

    • OS: Openhabian

    • Java Runtime Environment:

      openjdk version “1.8.0_202”
      OpenJDK Runtime Environment (Zulu8.36.0.152-CA-linux_aarch32hf) (build 1.8.0_202-b152)
      OpenJDK Client VM (Zulu8.36.0.152-CA-linux_aarch32hf) (build 25.202-b152, mixed mode, Evaluation)

    • openHAB version: Was 2.4 Stable and upgraded to 2.5 M1 (read inside)

    • My system includes Z-Wave modules

    • All of my Things were created using Paper UI

    • All of my Items are defined in files

    • All of my rules are defined in file

    • Using SSD drive (no SD card at all)

My experience with OpenHAB started with version 2.4 Stable on a RPi 3B+ with Openhabian.

I have always been using VS on a Windows machine to directly edit the rule files, which resides on the RPi.

I was using DIRECT saves and SAMBA, both of which (I found out 2 days ago) are not recommended.

In any case, even though I was working this way, whenever I saved the changes I made to a specific rules file, it was immediately “refreshed”, and after a few seconds I could already see the new logic in action.

About 2 days ago, it was no longer the case.
After I saved some changes, the system stopped running all my rules (later on I understood it probably just became very slow).

Stopping and starting the openhab2 service (including clearing the cache) did not solve the issue (the system was slow even after restart), and I also came across the following error:

Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@138f5b7' takes more than 5000ms.

After reading this, I upgraded to OH 2.5 M1, using the instructions here.

After that, when starting the openhab2 service, it works well (or at least it seems to).
I did come across these while writing this message:

2019-06-10 21:06:28.906 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : doFindMethod: Suitable but non-accessible method found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl
2019-06-10 21:06:28.910 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : findMethod: Suitable but non-accessible method setScheduler found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl, subclass of org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl
2019-06-10 21:06:28.914 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : bind method [setScheduler] not found; Component will fail
2019-06-10 21:06:28.917 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : bind method [setScheduler] not found
2019-06-10 21:06:28.921 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : doFindMethod: Suitable but non-accessible method found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl
2019-06-10 21:06:28.923 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : findMethod: Suitable but non-accessible method unsetScheduler found in class org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl, subclass of org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl
2019-06-10 21:06:28.926 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : unbind method [unsetScheduler] not found; Component will fail
2019-06-10 21:06:28.929 [ERROR] [org.eclipse.smarthome.core          ] - bundle org.eclipse.smarthome.core:0.11.0.oh250M1 (102)[org.eclipse.smarthome.core.internal.scheduler.PeriodicSchedulerImpl(106)] : unbind method [unsetScheduler] not found

But I believe these are a known issue, and are not related to my issue.

Still, whenever I change one of the rules files, it becomes slow.

I stopped editing the files directly on OH, and instead I upload them using MobaXTerm.

Sometimes when uploading the files, I receive the following warning:

[WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'filename.rules' is either empty or cannot be parsed correctly!

Sometimes, after this warning, the file is being re-loaded, and sometimes not.
This made me also try to upload the new rules files as

filename.rules.new

and then use the following command to rename it:

mv filename.rules.new filename.rules

I am not sure if it important or not, but the OWNER of my rules files is openhabian and the GROUP is openhab.

I modified it using:

sudo chown -R openhabian:openhab /etc/openhab2/rules

This is because when the owner was openhab I could not upload the files using MobaXTerm.

Still after working this way, sometimes the new rules file is not refreshed again, after the “is either empty or cannot be parsed correctly!” error.

Just to demonstrate how the system becomes slow, I have a Test switch item:

Switch ivTest_Rule_Trigger "Test Rule Trigger" {expire="2s,command=OFF"}

I created a test.rules file with the following content:

rule TestRule
when
        Item ivTest_Rule_Trigger changed to ON
then
        logInfo("Test Rule", "New Test 1")
end

Whenever I click the Test switch on Basic UI, all rule steps are executed very quickly:

2019-06-10 20:22:46.694 [ome.event.ItemCommandEvent] - Item 'ivTest_Rule_Trigger' received command ON
2019-06-10 20:22:46.717 [vent.ItemStateChangedEvent] - ivTest_Rule_Trigger changed from OFF to ON
2019-06-10 20:22:46.770 [INFO ] [pse.smarthome.model.script.Test Rule] - New Test 1
2019-06-10 20:22:49.663 [ome.event.ItemCommandEvent] - Item 'ivTest_Rule_Trigger' received command OFF
2019-06-10 20:22:49.681 [vent.ItemStateChangedEvent] - ivTest_Rule_Trigger changed from ON to OFF

However, once I update one of the other rules files (uploading a new version of it), it takes much longer for the logInfo comment to be executed:

2019-06-10 20:25:43.261 [ome.event.ItemCommandEvent] - Item 'ivTest_Rule_Trigger' received command ON
2019-06-10 20:25:43.270 [vent.ItemStateChangedEvent] - ivTest_Rule_Trigger changed from OFF to ON
2019-06-10 20:25:48.969 [ome.event.ItemCommandEvent] - Item 'ivTest_Rule_Trigger' received command OFF
2019-06-10 20:25:48.998 [vent.ItemStateChangedEvent] - ivTest_Rule_Trigger changed from ON to OFF
2019-06-10 20:27:47.160 [INFO ] [pse.smarthome.model.script.Test Rule] - New Test 1

(this is a 2-minute delay example, but I also had an almost-5-minute delay example)

Looking at the output of the TOP command, it seems like it is using high CPU, after uploading an updated rules filed (even a few minutes later):

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
32231 openhab   20   0  657600 513284  13932 S 139.1 51.4 135:19.98 java

Executing the commands listed here, it seems like I have:

41 Things
151 Items
139 Rules
2503 lines of rules

(note that since I’m learning OpenHAB, I have MANY commented-out lines, that I removed after making all kinds of tests during my learning)

I’d be happy to share any additional data that may be required to analyze the root cause of this issue, and see if it is a problem on my side, or a bug that has to be resolved.