Rules sometimes executing with long delay

  • Platform information:

    • Hardware: Raspberry 3B+
    • OS: openhabian
    • openHAB version: 2.3.0-1
  • Issue of the topic:

Hi, I have a Xiaomi motion sensor in my kitchen to turn on the Hue lights - and sometimes the rule needs 15+ seconds after the motion was detected to trigger and turn on the lights. I can’t find any pattern when the rule gets executed immediately and when it needs a long time. Any ideas how to find the problem source?

  • Configurations:
    • Items configuration related to the issue
Group XiaomiBewegungsmelder1
"Xiaomi Bewegungsmelder  Küche"
<motion>
(SensorDevices)

Switch XiaomiBewegungsmelder1_MOTION
"Xiaomi Bewegungsmelder  Küche Auslösung"
<motion>
(XiaomiBewegungsmelder1, Motions)
{mqtt="<[zigbee2mqtt:zigbee2mqtt/xiaomimotionkueche:state:JS(getZigbeeOccupancy2Switch.js)]" }

Number XiaomiBewegungsmelder1_BRIGHTNESS
"Xiaomi Bewegungsmelder  Küche Helligkeit [%d lumen]"
<lightbulb>
(XiaomiBewegungsmelder1, Luxs)
{mqtt="<[zigbee2mqtt:zigbee2mqtt/xiaomimotionkueche:state:JSONPATH($.illuminance)]"}

Number XiaomiBewegungsmelder1_BATTERY
"Xiaomi Bewegungsmelder  Küche Batterie [%.0f %%]"
<batterylevel>
(XiaomiBewegungsmelder1, Batteries)
{mqtt="<[zigbee2mqtt:zigbee2mqtt/xiaomimotionkueche:state:JSONPATH($.battery)]"}

Number XiaomiBewegungsmelder1_LINKQUALI
"Xiaomi Bewegungsmelder  Küche LINK [%d]"
<qualityofservice>
(XiaomiBewegungsmelder1, Verbindung)
{mqtt="<[zigbee2mqtt:zigbee2mqtt/xiaomimotionkueche:state:JSONPATH($.linkquality)]"}
  • Rules code related to the issue
rule "Bewegungsmelder Kueche"
when 
Item XiaomiBewegungsmelder1_MOTION changed

then
logInfo("Testing", "Bewegungsmelder Zeile 1")
var Timer kueche_timer_dimm = null
var Timer kueche_timer_off = null

if (XiaomiBewegungsmelder1_MOTION.state == ON) {
    logInfo("Testing", "Bewegungsmelder Zeile 2")
    if (AstroDayStatus.state == ON) {
        logInfo("Testing", "Bewegungsmelder Zeile 3")
    gKuecheHerdLinksFarbtemperatur.sendCommand(41)
    gKuecheHerdRechtsFarbtemperatur.sendCommand(41)
    HueKuecheLightstripFarbtemperatur.sendCommand(41)

    gKuecheHerdLinksDimmer.sendCommand(100)
    gKuecheHerdRechtsDimmer.sendCommand(100)
    HueKuecheLightstripDimmer.sendCommand(100)

    kueche_timer_dimm = null
    kueche_timer_off = null
    }

    else if (AstroDayStatus.state == OFF && now.getHourOfDay < 23 && now.getHourOfDay > 6) {
    logInfo("Testing", "Bewegungsmelder Zeile 4")
    gKuecheHerdRechtsFarbtemperatur.sendCommand(65)
    gKuecheHerdLinksFarbtemperatur.sendCommand(65)
    gKuecheHerdLinksDimmer.sendCommand(100)
    gKuecheHerdRechtsDimmer.sendCommand(100)
    HueKuecheLightstripFarbtemperatur.sendCommand(73)
    HueKuecheLightstripDimmer.sendCommand(100)
    kueche_timer_dimm = null
    kueche_timer_off = null
    }

    else {
        logInfo("Testing", "Bewegungsmelder Zeile 5")
    gKuecheHerdRechtsFarbtemperatur.sendCommand(90)
    gKuecheHerdLinksFarbtemperatur.sendCommand(90)
    gKuecheHerdLinksDimmer.sendCommand(50)
    gKuecheHerdRechtsDimmer.sendCommand(50)
    HueKuecheLightstripFarbtemperatur.sendCommand(90)
    HueKuecheLightstripDimmer.sendCommand(40)
    kueche_timer_dimm = null
    kueche_timer_off = null 
    }
}

else if (XiaomiBewegungsmelder1_MOTION.state == OFF) {
    logInfo("Testing", "Bewegungsmelder Zeile 6")
    
    if (DinnerZeit.state == ON){
        logInfo("Testing", "Bewegungsmelder Zeile 6,5")
        return;
    }

    else if (HueKuecheLightstripDimmer.state == 0) {
        kueche_timer_dimm = null
        kueche_timer_off = null
        logInfo("Testing", "Bewegungsmelder Zeile 7")
        return;      
    }

    else if (AstroDayStatus.state == OFF && now.getHourOfDay < 23 && now.getHourOfDay > 6) {
        logInfo("Testing", "Bewegungsmelder Zeile 8")
        
            kueche_timer_dimm = createTimer(now.plusSeconds(30))[|
                if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                    logInfo("Testing", "Bewegungsmelder Zeile 9")
                return;
             }
             logInfo("Testing", "Bewegungsmelder Zeile 10")
            gKuecheHerdRechtsFarbtemperatur.sendCommand(100)
            gKuecheHerdLinksFarbtemperatur.sendCommand(100)
            gKuecheHerdLinksDimmer.sendCommand(20)
            gKuecheHerdRechtsDimmer.sendCommand(20)
            HueKuecheLightstripFarbtemperatur.sendCommand(100)
            HueKuecheLightstripDimmer.sendCommand(30)
            ]
    }



    else if (AstroDayStatus.state == ON) {
        logInfo("Testing", "Bewegungsmelder Zeile 11")
        kueche_timer_dimm = createTimer(now.plusSeconds(10))[|
            if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                return;
            }
            logInfo("Testing", "Bewegungsmelder Zeile 12")
            gKuecheHerdRechtsFarbtemperatur.sendCommand(90)
            gKuecheHerdLinksFarbtemperatur.sendCommand(90)
            gKuecheHerdLinksDimmer.sendCommand(40)
            gKuecheHerdRechtsDimmer.sendCommand(40)
            HueKuecheLightstripFarbtemperatur.sendCommand(90)
            HueKuecheLightstripDimmer.sendCommand(35)
            ]

        kueche_timer_off = createTimer(now.plusSeconds(40))[|
            if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                return;
            }
            logInfo("Testing", "Bewegungsmelder Zeile 13")
            gKuecheHerdLinksDimmer.sendCommand(0)
            gKuecheHerdRechtsDimmer.sendCommand(0)
            HueKuecheLightstripDimmer.sendCommand(0)          
        ]
    }
    else if (now.getHourOfDay > 23) {
        logInfo("Testing", "Bewegungsmelder Zeile 14")
        kueche_timer_dimm = createTimer(now.plusSeconds(10))[|
            if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                return;
            }
            logInfo("Testing", "Bewegungsmelder Zeile 15")
            gKuecheHerdRechtsFarbtemperatur.sendCommand(90)
            gKuecheHerdLinksFarbtemperatur.sendCommand(90)
            gKuecheHerdLinksDimmer.sendCommand(40)
            gKuecheHerdRechtsDimmer.sendCommand(40)
            HueKuecheLightstripFarbtemperatur.sendCommand(90)
            HueKuecheLightstripDimmer.sendCommand(35)
            ]

        kueche_timer_off = createTimer(now.plusSeconds(30))[|
            if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                return;
            }
            logInfo("Testing", "Bewegungsmelder Zeile 16")
            gKuecheHerdLinksDimmer.sendCommand(0)
            gKuecheHerdRechtsDimmer.sendCommand(0)
            HueKuecheLightstripDimmer.sendCommand(0)          
        ]
    }
    else if (now.getHourOfDay < 6) {
        logInfo("Testing", "Bewegungsmelder Zeile 17")
        kueche_timer_dimm = createTimer(now.plusSeconds(10))[|
            if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                return;
            }
            logInfo("Testing", "Bewegungsmelder Zeile 18")
            gKuecheHerdRechtsFarbtemperatur.sendCommand(90)
            gKuecheHerdLinksFarbtemperatur.sendCommand(90)
            gKuecheHerdLinksDimmer.sendCommand(40)
            gKuecheHerdRechtsDimmer.sendCommand(40)
            HueKuecheLightstripFarbtemperatur.sendCommand(90)
            HueKuecheLightstripDimmer.sendCommand(35)
            ]

        kueche_timer_off = createTimer(now.plusSeconds(30))[|
            if (XiaomiBewegungsmelder1_MOTION.state == ON) {
                return;
            }
            logInfo("Testing", "Bewegungsmelder Zeile 19")
            gKuecheHerdLinksDimmer.sendCommand(0)
            gKuecheHerdRechtsDimmer.sendCommand(0)
            HueKuecheLightstripDimmer.sendCommand(0)          
        ]
    }
}

end
  • LOGS:
2018-10-22 08:25:07.792 [vent.ItemStateChangedEvent] - XiaomiBewegungsmelder1_LINKQUALI changed from 47 to 60
2018-10-22 08:25:07.855 [vent.ItemStateChangedEvent] - XiaomiBewegungsmelder1_MOTION changed from OFF to ON
==> /var/log/openhab2/openhab.log <==
2018-10-22 08:25:20.820 [INFO ] [lipse.smarthome.model.script.Testing] - Bewegungsmelder Zeile 1
2018-10-22 08:25:20.835 [INFO ] [lipse.smarthome.model.script.Testing] - Bewegungsmelder Zeile 2
2018-10-22 08:25:20.849 [INFO ] [lipse.smarthome.model.script.Testing] - Bewegungsmelder Zeile 3
==> /var/log/openhab2/events.log <==
2018-10-22 08:25:20.873 [ome.event.ItemCommandEvent] - Item 'gKuecheHerdLinksFarbtemperatur' received command 41
2018-10-22 08:25:20.886 [vent.ItemStateChangedEvent] - gKuecheHerdLinksFarbtemperatur changed from 87 to 41
2018-10-22 08:25:20.894 [ome.event.ItemCommandEvent] - Item 'gKuecheHerdRechtsFarbtemperatur' received command 41
2018-10-22 08:25:20.901 [vent.ItemStateChangedEvent] - gKuecheHerdRechtsFarbtemperatur changed from 87 to 41
2018-10-22 08:25:20.906 [ome.event.ItemCommandEvent] - Item 'HueKuecheLightstripFarbtemperatur' received command 41
2018-10-22 08:25:20.921 [ome.event.ItemCommandEvent] - Item 'gKuecheHerdLinksDimmer' received command 100
2018-10-22 08:25:20.925 [vent.ItemStateChangedEvent] - HueKuecheLightstripFarbtemperatur changed from 90 to 41
2018-10-22 08:25:20.928 [ome.event.ItemCommandEvent] - Item 'gKuecheHerdRechtsDimmer' received command 100
2018-10-22 08:25:20.932 [ome.event.ItemCommandEvent] - Item 'HueKuecheLightstripDimmer' received command 100
2018-10-22 08:25:20.943 [vent.ItemStateChangedEvent] - gKuecheHerdLinksDimmer changed from 0 to 100
2018-10-22 08:25:20.946 [vent.ItemStateChangedEvent] - gKuecheHerdRechtsDimmer changed from 0 to 100
2018-10-22 08:25:20.948 [vent.ItemStateChangedEvent] - HueKuecheLightstripDimmer changed from 0 to 100

Some information and ideas here

The post rossko57 linked to also links to the “Why have my Rules stopped running” which is the first thing that came to mind with this behavior.

As best as I can tell it is taking 13 seconds from the event until the Rule starts running which makes me think that you have used up all your Rulle Execution Threads and this Rule has to wait for one to free up before it can run.

Do you have long running Rules: e.g. Rules with Thread::sleep, executeCommandLine, sendHttp*Request, indefinite while loops, etc?

Thanks for your replies and the links!
It’s quite difficult to assess if some changes made a difference since the problem occurs quite at random.
I increased the threaspool size.

Would this also be a good idea?
And what about the part with VSC and the language server? At the moment i have VSC open in the background most of the time…

Your post is brilliant! Is there any way to monitor the Rule Execution Threads? Or the threads/… of openHAB in general?

No Thread::sleep, No executeCommandLine, no while loops but a few sendHttpPutRequests to trigger light scenes from the Hue Bridge and the http binding to get the status of my Hue Motion Sensor and Hue Dimmer Switch

// Hue Motion Senssor - temperature sensor
Number hueMotionSensorTemperature
"Temperatur Hue Motion Sensor [%.1f °C]"
<temperature>
(HueMotionSensorVZ, Temperatures)
{ http="<[hueMotionSensorTemperature:60000:JS(getHueTemperature.js)]" }

DateTime hueMotionSensorTemperatureLastChange
"Letzte Änderung [%1$tH:%1$tM:%1$tS]"
<time>
(HueMotionSensorVZ)
{ http="<[hueMotionSensorTemperature:60000:JS(getHueLastChange.js)]" }

// Hue Motion Sensor - motion sensor
Switch hueMotionSensorPresence
"Bewegung Vorzimmer JA/NEIN [%s]"
<motion>
(HueMotionSensorVZ, Motions)
{ http="<[hueMotionSensorPresence:5000:JS(getHuePresence.js)]" }

DateTime hueMotionSensorPresentLastChange
"Letzte Änderung [%1$tH:%1$tM:%1$tS]"
<time>
(HueMotionSensorVZ)
{ http="<[hueMotionSensorPresence:5000:JS(getHueLastChange.js)]" }

// Hue Motion Sensor - ambient light sensor
Number hueMotionSensorIlluminance
"Helligkeit Vorzimmer [%.1f Lux]"
<light>
(HueMotionSensorVZ, Luxs)
{ http="<[hueMotionSensorIlluminance:15000:JS(getHueIlluminance.js)]" }

DateTime hueMotionSensorIlluminanceLastChange
"Letzte Änderung [%1$tH:%1$tM:%1$tS]"
<time>
(HueMotionSensorVZ)
{ http="<[hueMotionSensorIlluminance:15000:JS(getHueLastChange.js)]" }
when

Item XiaomiWandschalter2_CLICK received update

then

val String bridgeURL = "http://192.168.2.69/api/XXXXXX/"
val String scene_group = "1"

if (XiaomiWandschalter2_CLICK.state.toString == "left") {
    if (AstroDayStatus.state == ON) {
        val String scene_id = "IziAxVom2Egc58Z" //Stehlampe Hell
        sendHttpPutRequest(bridgeURL + "groups/" + scene_group + "/action", "application/json", '{"scene": "' + scene_id + '"}')
    }
    
    else if  (AstroDayStatus.state == OFF && now.getHourOfDay < 22 && now.getHourOfDay > 5) {
        val String scene_id = "yrgqdXYVGKLzZTK"
        sendHttpPutRequest(bridgeURL + "groups/" + scene_group + "/action", "application/json", '{"scene": "' + scene_id + '"}')
    }

    else {
        val String scene_id = "WFNZIyjZcXbPHgv"
        sendHttpPutRequest(bridgeURL + "groups/" + scene_group + "/action", "application/json", '{"scene": "' + scene_id + '"}')
    }
}

else if (XiaomiWandschalter2_CLICK.state.toString == "right") {
    if (AstroDayStatus.state == ON) {
        val String scene_id = "LvQ8i4NvCv4bWIk"
        sendHttpPutRequest(bridgeURL + "groups/" + scene_group + "/action", "application/json", '{"scene": "' + scene_id + '"}')
    }

    else {
        val String scene_id = "VzOR65SMPwN5Lhm"
        sendHttpPutRequest(bridgeURL + "groups/" + scene_group + "/action", "application/json", '{"scene": "' + scene_id + '"}')
    }
}

else if (XiaomiWandschalter2_CLICK.state.toString == "both") {
    HueWZStehlampe1Dimmer.sendCommand(0)
    HueWZStehlampe2Dimmer.sendCommand(0)
    HueWZStehlampe3Dimmer.sendCommand(0)
    HueWZStehlampe4Dimmer.sendCommand(0)
    HueWZIrisBlackDimmer.sendCommand(0)
    HueWZIrisWhiteDimmer.sendCommand(0)
    HueSchreibtischLightstripDimmer.sendCommand(0)
    HueEZDeckeDimmer.sendCommand(0)
    OsramKuecheDeckeDimmer.sendCommand(0)
    gKuecheHerdLinksDimmer.sendCommand(0)
    gKuecheHerdRechtsDimmer.sendCommand(0)
    HueKuecheLightstripDimmer.sendCommand(0) 
    XiaomiWandschalter1_CLICK.send (OFF)

}

end

I just read this topic with a similar problem: Sometimes rules don’t get executed?
I’m persisting all Sensor Data and a bunch more at the moment at every update to an external MySQL Database… maybe i should tone it down a bit and only store the relevant data for my graphs?


UPDATE: it seems like the higher thread pool size improved things but just now i again had a delay of 17 sec.

Try disabling persistance. Higher thread pool size also helped me a little bit, but it didn’t solve the problem at all. However if I understand correctly, your MySQL database is on a different server. If this is the case and after disabling persistance, solves your issue, then might be some bug in openHab. For me, I just thought that the SD card can’t handle that much writing, but if this solves your issue as well, then it might be some other problems…

Certainly couldn’t hurt so long as you don’t choose a size too large.

I’ve mainly seen issues with performance while actively editing Rules in VSCode. I don’t know if just having it up in the background causes much of a problem, but it is worth shutting it down to see if it makes a difference.

Look at 5iver’s posting on that thread (I think it’s post 12) where he lists some shell commands you can run that will show how many threads in each pool are being used.

I can confirm that. Since I moved VSC to a shadow node, my rules are running more reliable. You know when things take longe then you expect, then you start clicking and …

Nice, thanks!
Looks like some rules get stuck quite long, don’t know why yet…

openhab> shell:threads --list |grep "RuleEngine"                                                                                            
45317 │ ESH-RuleEngine-4059                                                                           │ TIMED_WAITING │ 151      │ 150
45339 │ ESH-RuleEngine-4060                                                                           │ TIMED_WAITING │ 140      │ 140
45345 │ ESH-RuleEngine-4061                                                                           │ TIMED_WAITING │ 98       │ 90
45346 │ ESH-RuleEngine-4062                                                                           │ TIMED_WAITING │ 137      │ 120
45347 │ ESH-RuleEngine-4063                                                                           │ TIMED_WAITING │ 94       │ 90
45348 │ ESH-RuleEngine-4064                                                                           │ TIMED_WAITING │ 112      │ 100
45349 │ ESH-RuleEngine-4065                                                                           │ TIMED_WAITING │ 79       │ 70
45350 │ ESH-RuleEngine-4066                                                                           │ TIMED_WAITING │ 55       │ 50
45351 │ ESH-RuleEngine-4067                                                                           │ TIMED_WAITING │ 41       │ 40
45352 │ ESH-RuleEngine-4068                                                                           │ TIMED_WAITING │ 106      │ 100
45353 │ ESH-RuleEngine-4069                                                                           │ TIMED_WAITING │ 80       │ 80
45378 │ pipe-grep "RuleEngine"                                                                        │ RUNNABLE      │ 170      │ 130
45396 │ ESH-RuleEngine-4070                                                                           │ TIMED_WAITING │ 69       │ 60
45398 │ ESH-RuleEngine-4071                                                                           │ TIMED_WAITING │ 94       │ 90
45399 │ ESH-RuleEngine-4072                                                                           │ TIMED_WAITING │ 56       │ 50
45402 │ ESH-RuleEngine-4073                                                                           │ TIMED_WAITING │ 75       │ 70
45404 │ ESH-RuleEngine-4074                                                                           │ TIMED_WAITING │ 67       │ 60
45405 │ ESH-RuleEngine-4075                                                                           │ TIMED_WAITING │ 30       │ 30
45406 │ ESH-RuleEngine-4076                                                                           │ TIMED_WAITING │ 40       │ 30
45407 │ ESH-RuleEngine-4077                                                                           │ TIMED_WAITING │ 40       │ 40
45408 │ ESH-RuleEngine-4078                                                                           │ TIMED_WAITING │ 16       │ 10
45409 │ ESH-RuleEngine-4079                                                                           │ TIMED_WAITING │ 8        │ 0
45410 │ ESH-RuleEngine-4080                                                                           │ TIMED_WAITING │ 45       │ 40
45411 │ ESH-RuleEngine-4081                                                                           │ TIMED_WAITING │ 88       │ 80
45412 │ ESH-RuleEngine-4082                                                                           │ TIMED_WAITING │ 53       │ 50
45413 │ ESH-RuleEngine-4083                                                                           │ TIMED_WAITING │ 14       │ 10

Is there any way to see where each thread comes from?
I suspect that i have an error / bad code in one of my rule files… what would be the easiest and most efficient way to debug them?

Not that I know of.

The only way I know of is to pick the most likely suspects, put start and end log statements in those and start matching up the timestamps to see if you can ID which Rule(s) are taking a long time to run.

2 Likes

Small update: i’m trying to figure out which rule could cause the problems and i noticed that one rule sometimes produces an error in the logs but otherwise functions properly:

2018-10-28 15:52:03.260 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Get Lights On Count': null
rule "Get Lights On Count"
when
    Item gMasterswitchLight received update
then
    HueLightsONCounter.postUpdate(gMasterswitchLight.members.filter(l|l.state==ON).size)
end


EDIT: might have found the solution:

    HueLightsONCounter.postUpdate(gMasterswitchLight.members.filter(l|((l.state != NULL) && (l.state==ON))).size)

EDIT2: Nope, same error as before

I can’t say why there is the error but you don’t really need this rule. If you define a Group of switches as

Group:Number:Sum gMasterswitchLight

And the state of gMasterswitchLight will be the number of on Switches.