[SOLVED] Rule randomly delayed 0-30 seconds

Hi there!

I’m rather new to openHAB, but I’ve set up already some automation. Now I struggle with the usability of the automations, since some rules execute delayed. The delay is not predictable, it varies from instantly to 30 seconds. I can see in the log viewer that the event I’m reacting on in the rule is definitively immediately thrown. I’ve no clue about the origin of the delay and already performed many experiments to narrow down the reason.

Here’s what I tested:

  1. I’ve read in this forum and found a few mentions of similar behavior. Solutions had to do with with rather limited threadpools. So I tried increasing the threadpool using
    org.eclipse.smarthome.threadpool:safeCall=15
    org.eclipse.smarthome.threadpool:ruleEngine=16

This had no effect on the delay.

  1. I uninstalled the Expire plugin for other possible threadpool reasons. At first, it seemed to improve the delay, but it was a false positive due to the nature of the delay (0-30 seconds).

  2. I removed alle rule-files except the motion.rules, where I have a simple rule included, which I planned to extend – but I need to solve the delay first:

rule "Switch table light on if motion is detected in second floor living room"
when
    Item IsensorsSfLrMotion1_Motion received update
then
    if (IsensorsSfLrMotion1_Motion.state == ON) {
        logInfo("motion", "Motion in second floor living room: switching lights on")
        sendCommand(IlightsSfLrTable, 100)
    } else {
        logInfo("motion", "No more motion in second floor living room: switching lights off")
        sendCommand(IlightsSfLrTable, 0)
    }
end

The rule-removal did not have any noticeable effect.

  1. I tried shortening my items-file, only keeping the essential items for the motion-sensor (i.e. light, sensor and gateway). As far as I can say, this worked out. I could not see a delay in a couple of tries. I cannot be 100% sure due to the nature of the delay. Anyway, even if it did solve the issue, it’s no real solution to integrate back the items, since a single removal takes about 15 minutes to evaluate. I’ve a lot of items configured, so even a divide&conquer strategy seems tedious.

  2. I tried to remove all Group:Dimmer*, Group:Switch* etc. items, since I believed this would consume computation power. This had no noticeable effect.

  3. I’ve closed all browser tabs showing my BasicUI. For tests of over an hour this seemed to work flawlessly, i.e. there were no delays. But suddenly (without changing anything to the setup), the rule was delayed again. A next try worked again without delay. I used the reduced items-file from step 5)

  4. I restored the original items file. After several tries I can say that it got worse again, reproduceably. There’s a significant delay between the event and the rule execution.

  5. I’ve monitored the CPU load with top, but could not see peaks go beyond 30%. Is there a better way to monitor CPU load? Could there be IO-waits responsible for the delay? Is there any way to provide log output to see where the delay comes from?

  • Platform information:
    • Hardware: Raspberry Pi Model 3 Model B+
    • OS: Linux 4.14.34-v7+
    • Java Runtime Environment: openjdk version “1.8.0_152”
    • openHAB version:openHAB 2.2.0-1 (Release Build)
1 Like

One of your problem, with this particular rule is your use of the trigger:

rule "Switch table light on if motion is detected in second floor living room"
when
    Item IsensorsSfLrMotion1_Motion received update
then
    if (IsensorsSfLrMotion1_Motion.state == ON) {
        logInfo("motion", "Motion in second floor living room: switching lights on")
        sendCommand(IlightsSfLrTable, 100)
    } else {
        logInfo("motion", "No more motion in second floor living room: switching lights off")
        sendCommand(IlightsSfLrTable, 0)
    }
end

When the trigger received update does not guarantees the the item is actually updated by the time it’s evaluated in the rule. This is due to the time the bus event takes to update item states in the background.

Let’s change the rule a bit:

rule "Switch table light on if motion is detected in second floor living room"
when
    Item IsensorsSfLrMotion1_Motion received update
then
    if (triggeringItem.state == ON) {
        logInfo("motion", "Motion in second floor living room: switching lights on")
        IlightsSfLrTable.sendCommand(100)
    } else {
        logInfo("motion", "No more motion in second floor living room: switching lights off")
        IlightsSfLrTable.sendCommand(0)
    }
end

It might not seem much but the use on the implicit variable will retrieve the state of the updated item. I also changed your use of the sendCommand action and replaced it with the method as recommended in: https://www.openhab.org/docs/configuration/rules-dsl.html#myitem-sendcommand-new-state-versus-sendcommand-myitem-new-state

let me know it it changes anything.

Thanks

Maybe it’s fixed in 2.3.0? There is 6 months of improvements, see the release notes.

Also when you make changes to rules, reloading them takes a while on a RPi3 and it is done the first time a rule is triggered. Using LSP with VSCode also increases CPU load see ESH #4756. Though all this should not be an issue when you’re not making changes to your rules/items.

I modified the rules-file according to your suggestions. All of them make sense to me and even improve redundancy, thanks!

From my observations (later on I added logging at the beginning of the rule, without condition), this will not help. Although as for the last four tries, the light went on very quickly :wink: I’ll monitor it closely and give you feedback!

I indeed wanted to upgrade on this weekend, but did not want to introduce more problems with that than I already have. But I created a backup today, so that I can really try that! Thanks for the suggestion!

Regarding LSP, I’ve noticed going CPU usage up to 150%, but it went down when I did not make any edits. So I discarded that as a possible reason. Am I overlooking something?

Do you use openHABian or did you install Java and openHAB yourself on the RPi3?

The default OpenJDK version that ships with a plain Raspbian installation has performance issues because it does not use hardware for floating point operations. Instead you should use the Oracle JVM or the Zulu JVM which ships with openHABian.

@wborn I use openHABian with the Zulu JVM.

General update: The delays are still there. I get the feeling that rebooting the system causes the delays to appear in a larger fashion (even after JIT ran for that rule), say for the first 10 minutes. Maybe due to other init stuff.

OK then at least that should not be an issue. :wink:

It can take quite some time before everything is finally started on a RPi3. On my RPi3 it could take sometimes 20 minutes before everything was running smoothly. That was one of the reasons why I migrated my main openHAB instance to an Intel NUC. Luckily with OSGi you don’t have to restart the runtime so often because bundles can be installed/updated while everything keeps running! :slight_smile:

Ok, so here’s the next update :wink:

I’ve updated to openHAB 2.3.0-1 (Release Build). After updating my motion rule has been triggered with very little delay (<1s). I tried that for some time.

After that I shut down the raspi and made a backup of the updated system. Then I rebootet the system and the delay problems re-appeared – without changing anything to the system. Sometimes it’s really quick, but sometimes it’s very delayed again.

I guessed that it could be related to a Telegram message I attached as a alarm trigger, so I disabled that message (and rebooted the system). But the problem did not go away (even after a hour).

Next update: right now my installation runs smoothly without any delays – for about 4 hours now, it survived a couple of reboots.

What I did: I’ve copied the whole system to a new sd card, this time a Sandisk model (instead of the noname model bundled with the raspi).

I hope it will stay that responsive!

3 Likes

Setting this to resolved, the issue does not appear any more. I suggest using an expensive sd card to everyone :wink: