Delay in performing the role

Setup, Configuration and Use Scripts & Rules
1

I have a delay in the role of closing window blinds. Occurs randomly and most often it is about 7 seconds. Other openhab functions work quickly. Please tell me where the error is in the code.

import org.joda.time.*
import org.openhab.model.script.actions.Timer

var timer0
var timer1
var timer2
var timer3
var timer4
var timer5
var timer6
var timer7
var timer8
var timer9

rule "Nbox_off"
	when
		Time cron "0 30 0 * * ?"
	then
           	sendCommand(nbox, OFF)
		postUpdate(nbox, OFF)
end

rule "Roleta all up"
	when
		Item roleta_all received command UP
	then
		sendCommand(roleta_salonOK, UP)
		sendCommand(roleta_salonT, UP)
		sendCommand(roleta_gosc, UP)
		sendCommand(roleta_kuchnia, UP)
end

rule "Roleta all down"
	when
		Item roleta_all received command DOWN
	then
		sendCommand(roleta_salonOK, DOWN)
		sendCommand(roleta_salonT, DOWN)
		sendCommand(roleta_gosc, DOWN)
		sendCommand(roleta_kuchnia, DOWN)
end

rule "Roleta salonOK up"
	when
		Item roleta_salonOK received command UP
	then
		sendCommand(roleta_salonOK_open_switch, ON)
		timer0 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_salonOK_open_switch, OFF)
		timer0 = null
		])
end

rule "Roleta salonOK close"
	when
		Item roleta_salonOK received command DOWN
	then
		sendCommand(roleta_salonOK_close_switch, ON)
		timer1 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_salonOK_close_switch, OFF)
		timer1 = null
		])
end

rule "Roleta salonOK stop"
	when
		Item roleta_salonOK received command STOP
	then
		sendCommand(roleta_salonOK_open_switch, OFF)
		sendCommand(roleta_salonOK_close_switch, OFF)
		{
		timer0 = null
		timer1 = null
		}
end

rule "Roleta salonT up"
	when
		Item roleta_salonT received command UP
	then
		sendCommand(roleta_salonT_open_switch, ON)
		timer2 = createTimer(now.plusSeconds(30), [|
		sendCommand(roleta_salonT_open_switch, OFF)
		timer2 = null
		])
end

rule "Roleta salonT close"
	when
		Item roleta_salonT received command DOWN
	then
		sendCommand(roleta_salonT_close_switch, ON)
		timer3 = createTimer(now.plusSeconds(23), [|
		sendCommand(roleta_salonT_close_switch, OFF)
		timer3 = null
		])
end

rule "Roleta salonT stop"
	when
		Item roleta_salonT received command STOP
	then
		sendCommand(roleta_salonT_open_switch, OFF)
		sendCommand(roleta_salonT_close_switch, OFF)
		{
		timer2 = null
		timer3 = null
		}
end

rule "Roleta gosc up"
	when
		Item roleta_gosc received command UP
	then
		sendCommand(roleta_gosc_open_switch, ON)
		timer4 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_gosc_open_switch, OFF)
		timer4 = null
		])
end

rule "Roleta gosc down"
	when
		Item roleta_gosc received command DOWN
	then
		sendCommand(roleta_gosc_close_switch, ON)
		timer5 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_gosc_close_switch, OFF)
		timer5 = null
		])
end

rule "Roleta gosc stop"
	when
		Item roleta_gosc received command STOP
	then
		sendCommand(roleta_gosc_open_switch, OFF)
		sendCommand(roleta_gosc_close_switch, OFF)
		{
		timer4 = null
		timer5 = null
		}
end

rule "Roleta kuchnia up"
	when
		Item roleta_kuchnia received command UP
	then
		sendCommand(roleta_kuchnia_open_switch, ON)
		timer6 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_kuchnia_open_switch, OFF)
		timer6 = null
		])
end

rule "Roleta kuchnia close"
	when
		Item roleta_kuchnia received command DOWN
	then
		sendCommand(roleta_kuchnia_close_switch, ON)
		timer7 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_kuchnia_close_switch, OFF)
		timer7 = null
		])
end

rule "Roleta kuchnia stop"
	when
		Item roleta_kuchnia received command STOP
	then
		sendCommand(roleta_kuchnia_open_switch, OFF)
		sendCommand(roleta_kuchnia_close_switch, OFF)
		{
		timer6 = null
		timer7 = null
		}
end

rule "Roleta wykusz up"
	when
		Item roleta_wykusz received command UP
	then
		sendCommand(roleta_wykusz_open_switch, ON)
		timer8 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_wykusz_open_switch, OFF)
		timer8 = null
		])
end

rule "Roleta wykusz close"
	when
		Item roleta_wykusz received command DOWN
	then
		sendCommand(roleta_wykusz_close_switch, ON)
		timer9 = createTimer(now.plusSeconds(21), [|
		sendCommand(roleta_wykusz_close_switch, OFF)
		timer9 = null
		])
end

rule "Roleta wykusz stop"
	when
		Item roleta_wykusz received command STOP
	then
		roleta_wykusz_open_switch.sendCommand(OFF)
		sendCommand(roleta_wykusz_close_switch, OFF)
		{
		timer8 = null
		timer9 = null
		}
end

// this assumes you also have the wake on lan binding configured.
rule "Power on TV via Wake on LAN"
when
Item LG_TV0_Power received command ON
then
    sendCommand( LG_TV0_WOL, ON)
end

// for relative volume changes
rule "VolumeUpDown"
when Item LG_TV0_VolDummy received command
then
    switch receivedCommand{
        case 0: LG_TV0_Volume.sendCommand(DECREASE)
        case 1: LG_TV0_Volume.sendCommand(INCREASE)
    }
end

// for relative channel changes
rule "ChannelUpDown"
when Item LG_TV0_ChannelDummy received command
then
    var currentChannel = LG_TV0_ChannelNo.state as DecimalType
    switch receivedCommand{
        case 0: LG_TV0_ChannelNo.sendCommand(currentChannel - 1)
        case 1: LG_TV0_ChannelNo.sendCommand(currentChannel + 1)
    }
end

// wywylanie tekstu
rule "Komunikat"
when 
Item vTVMessage changed
then
    actions.showToast("Hello World")
    actions.showToast("http://192.168.1.50:8080/icon/energy?format=png","Hello World")
end
2

Which rule(s) exactly show that behaviour? You have shown many rules…
And can you show the log files around the time the delay happens?

3

You don’t need - and should not have - those imports in OH2

To investigate a theory about rules being paged out of memory, can you look in your events.log to see when the Nbox rule is being run? You should be able to see the nbox command OFF, I’m curious if that is a few seconds “late” as well.

4

The nbox command works without delays. The problem is only with the rules roller shutter (name “roleta_”).
Below log - the command to close all blinds (name: roleta_all) was received at 19:19:36.843 but it was actually issued 8 seconds earlier.

2020-03-30 19:19:36.843 [ome.event.ItemCommandEvent] - Item 'roleta_all' received command DOWN
2020-03-30 19:19:36.858 [ome.event.ItemCommandEvent] - Item 'roleta_salonOK' received command DOWN
2020-03-30 19:19:36.874 [vent.ItemStateChangedEvent] - roleta_all changed from 0 to 100
2020-03-30 19:19:36.879 [ome.event.ItemCommandEvent] - Item 'roleta_salonT' received command DOWN
2020-03-30 19:19:36.887 [ome.event.ItemCommandEvent] - Item 'roleta_gosc' received command DOWN
2020-03-30 19:19:36.896 [ome.event.ItemCommandEvent] - Item 'roleta_kuchnia' received command DOWN
2020-03-30 19:19:36.908 [ome.event.ItemCommandEvent] - Item 'roleta_salonOK_close_switch' received command ON
2020-03-30 19:19:36.936 [ome.event.ItemCommandEvent] - Item 'roleta_salonT_close_switch' received command ON
2020-03-30 19:19:36.960 [ome.event.ItemCommandEvent] - Item 'roleta_gosc_close_switch' received command ON
2020-03-30 19:19:36.983 [ome.event.ItemCommandEvent] - Item 'roleta_kuchnia_close_switch' received command ON
2020-03-30 19:19:37.000 [vent.ItemStateChangedEvent] - roleta_salonOK changed from 0 to 100
2020-03-30 19:19:37.003 [nt.ItemStatePredictedEvent] - roleta_salonOK_close_switch predicted to become ON
2020-03-30 19:19:37.018 [vent.ItemStateChangedEvent] - roleta_salonT changed from 0 to 100
2020-03-30 19:19:37.022 [nt.ItemStatePredictedEvent] - roleta_salonT_close_switch predicted to become ON
2020-03-30 19:19:37.036 [vent.ItemStateChangedEvent] - roleta_gosc changed from 0 to 100
2020-03-30 19:19:37.039 [nt.ItemStatePredictedEvent] - roleta_gosc_close_switch predicted to become ON
2020-03-30 19:19:37.054 [vent.ItemStateChangedEvent] - roleta_kuchnia changed from 0 to 100
2020-03-30 19:19:37.060 [nt.ItemStatePredictedEvent] - roleta_kuchnia_close_switch predicted to become ON
2020-03-30 19:19:37.073 [vent.ItemStateChangedEvent] - roleta_salonOK_close_switch changed from OFF to ON
2020-03-30 19:19:37.076 [vent.ItemStateChangedEvent] - roleta_salonT_close_switch changed from OFF to ON
2020-03-30 19:19:37.079 [vent.ItemStateChangedEvent] - roleta_gosc_close_switch changed from OFF to ON
2020-03-30 19:19:37.082 [vent.ItemStateChangedEvent] - roleta_kuchnia_close_switch changed from OFF to ON
2020-03-30 19:19:40.705 [vent.ItemStateChangedEvent] - miio_vacuum_0F90540A_network_life changed from 58429 to 58489
2020-03-30 19:19:40.709 [vent.ItemStateChangedEvent] - miNetLife changed from 58429 to 58489
2020-03-30 19:19:45.329 [vent.ItemStateChangedEvent] - humidity_out changed from 31.899999618530273 to 31.799999237060547
2020-03-30 19:19:45.340 [vent.ItemStateChangedEvent] - Weatherstation_Humidity changed from 31.90000000 to 31.80000000
2020-03-30 19:19:46.126 [vent.ItemStateChangedEvent] - systeminfo_computer_openHABianPi_memory_usedPercent changed from 62.8 to 62.4
2020-03-30 19:19:46.149 [vent.ItemStateChangedEvent] - systeminfo_computer_openHABianPi_memory_used changed from 613 to 609
2020-03-30 19:19:46.151 [vent.ItemStateChangedEvent] - CPU_Temp changed from 39.7 to 40.8
2020-03-30 19:19:49.372 [vent.ItemStateChangedEvent] - temperature_out changed from  to 23.799999237060547
2020-03-30 19:19:52.590 [vent.ItemStateChangedEvent] - GoscinnyR changed from OPEN to CLOSED
2020-03-30 19:19:52.697 [GroupItemStateChangedEvent] - ile_otwarteR changed from OPEN to CLOSED through KuchniaR
2020-03-30 19:19:52.702 [vent.ItemStateChangedEvent] - KuchniaR changed from OPEN to CLOSED
2020-03-30 19:19:53.752 [vent.ItemStateChangedEvent] - pressure_out changed from 1008.53 to 1008.61
2020-03-30 19:19:53.763 [vent.ItemStateChangedEvent] - Weatherstation_Pressure changed from 1008.53000000 to 1008.61000000
2020-03-30 19:19:57.899 [ome.event.ItemCommandEvent] - Item 'roleta_salonOK_close_switch' received command OFF
2020-03-30 19:19:57.929 [nt.ItemStatePredictedEvent] - roleta_salonOK_close_switch predicted to become OFF
2020-03-30 19:19:57.948 [ome.event.ItemCommandEvent] - Item 'roleta_kuchnia_close_switch' received command OFF
2020-03-30 19:19:57.978 [ome.event.ItemCommandEvent] - Item 'roleta_gosc_close_switch' received command OFF
2020-03-30 19:19:58.002 [vent.ItemStateChangedEvent] - roleta_salonOK_close_switch changed from ON to OFF
2020-03-30 19:19:58.005 [nt.ItemStatePredictedEvent] - roleta_kuchnia_close_switch predicted to become OFF
2020-03-30 19:19:58.016 [nt.ItemStatePredictedEvent] - roleta_gosc_close_switch predicted to become OFF
2020-03-30 19:19:58.029 [vent.ItemStateChangedEvent] - roleta_kuchnia_close_switch changed from ON to OFF
2020-03-30 19:19:58.031 [vent.ItemStateChangedEvent] - roleta_gosc_close_switch changed from ON to OFF
2020-03-30 19:19:59.899 [ome.event.ItemCommandEvent] - Item 'roleta_salonT_close_switch' received command OFF
2020-03-30 19:19:59.925 [nt.ItemStatePredictedEvent] - roleta_salonT_close_switch predicted to become OFF
2020-03-30 19:19:59.944 [vent.ItemStateChangedEvent] - roleta_salonT_close_switch changed from ON to OFF
2020-03-30 19:20:01.160 [vent.ItemStateChangedEvent] - CPU_Load1 changed from 0.1 to 0.2
5

Okay, the rule cannot run until it is triggered by the command being received, So there doesn’t appear to be any delay in running the rule.

How are you measuring when the command is issued?

6

Waiting from the moment I clicked on the device with habpanel / basic ui. Other functions perform immediately.

7

Okay, so when you click in BasicUI the command does not appear in your events.log until 8 seconds later? But when you click some other button, it appears immediately?
Could you press your sample two buttons one after the other fairly quickly, and show us the results?

8

I did as you wrote. I turned on the roller shutter opening (roleta_gosc), a second later “podbitka” OFF and then “sonoff2” ON. “podbitka” and “sonoff2” were made immediately and the blind after few seconds.

2020-04-01 17:34:03.357 [vent.ItemStateChangedEvent] - CPU_Load1 changed from 0.3 to 0.2
2020-04-01 17:34:06.701 [ome.event.ItemCommandEvent] - Item 'roleta_gosc' received command UP
2020-04-01 17:34:09.225 [ome.event.ItemCommandEvent] - Item 'podbitka' received command OFF
2020-04-01 17:34:09.257 [nt.ItemStatePredictedEvent] - podbitka predicted to become OFF
2020-04-01 17:34:09.284 [vent.ItemStateChangedEvent] - podbitka changed from ON to OFF
2020-04-01 17:34:14.456 [ome.event.ItemCommandEvent] - Item 'sonoff_2' received command ON
2020-04-01 17:34:14.477 [nt.ItemStatePredictedEvent] - sonoff_2 predicted to become ON
2020-04-01 17:34:14.500 [vent.ItemStateChangedEvent] - sonoff_2 changed from OFF to ON
2020-04-01 17:34:14.553 [vent.ItemStateChangedEvent] - mqtt_topic_Sonoff_2_Przekaznik2 changed from OFF to ON
2020-04-01 17:34:18.554 [ome.event.ItemCommandEvent] - Item 'roleta_gosc_open_switch' received command ON
2020-04-01 17:34:18.572 [nt.ItemStatePredictedEvent] - roleta_gosc_open_switch predicted to become ON
2020-04-01 17:34:18.587 [vent.ItemStateChangedEvent] - roleta_gosc_open_switch changed from OFF to ON
2020-04-01 17:34:20.111 [ome.event.ItemCommandEvent] - Item 'sonoff_2' received command OFF
2020-04-01 17:34:20.129 [nt.ItemStatePredictedEvent] - sonoff_2 predicted to become OFF
2020-04-01 17:34:20.165 [vent.ItemStateChangedEvent] - sonoff_2 changed from ON to OFF
2020-04-01 17:34:20.217 [vent.ItemStateChangedEvent] - mqtt_topic_Sonoff_2_Przekaznik2 changed from ON to OFF
2020-04-01 17:34:22.551 [ome.event.ItemCommandEvent] - Item 'podbitka' received command ON
2020-04-01 17:34:22.563 [nt.ItemStatePredictedEvent] - podbitka predicted to become ON
2020-04-01 17:34:22.583 [vent.ItemStateChangedEvent] - podbitka changed from OFF to ON
2020-04-01 17:34:39.557 [ome.event.ItemCommandEvent] - Item 'roleta_gosc_open_switch' received command OFF
2020-04-01 17:34:39.579 [nt.ItemStatePredictedEvent] - roleta_gosc_open_switch predicted to become OFF
2020-04-01 17:34:39.600 [vent.ItemStateChangedEvent] - roleta_gosc_open_switch changed from ON to OFF
9

Okay, so that’s you poking the UI over the course of a few seconds.

Looking at your rules, the first evidence that the expected rule is running is

2020-04-01 17:34:18.554 [ome.event.ItemCommandEvent] - Item 'roleta_gosc_open_switch' received command ON

which is some 12 seconds after the command trigger.
That does not tie in with your previous claim the command was issued 8 seconds before it was seen in the log, so that’s a step forward, this way makes more sense.

In the few minutes after you have used a rule like this, does another use suffer the same delay or work normally?
I’m wondering that because the log from your post 4

2020-03-30 19:19:36.843 [ome.event.ItemCommandEvent] - Item 'roleta_all' received command DOWN
2020-03-30 19:19:36.858 [ome.event.ItemCommandEvent] - Item 'roleta_salonOK' received command DOWN

shows only a 15mS delay, which seems perfectly reasonable to me.

I would still like to see an events.log for your “nbox” rule, around 00:30, to see if all rules in that file are delayed.

Do either of those other Items you poked in the UI trigger any rules, for a comparison?

Have you taken out the unwanted imports yet?

10

The next use of the rule in a few minutes works normally.
Log for the “nbox” rule below.
I have only removed unwanted imports but haven’t tested yet.

2020-03-31 00:30:14.146 [vent.ItemStateChangedEvent] - Weatherstation_Pressure changed from 1009.58000000 to 1009.64000000
2020-03-31 00:30:14.149 [ome.event.ItemCommandEvent] - Item 'nbox' received command OFF
2020-03-31 00:30:14.197 [nt.ItemStatePredictedEvent] - nbox predicted to become OFF
2020-03-31 00:30:14.215 [vent.ItemStateChangedEvent] - nbox changed from ON to OFF
2020-03-31 00:30:14.253 [vent.ItemStateChangedEvent] - mqtt_topic_Sonoff_1_Przekaznik1 changed from ON to OFF
2020-03-31 00:30:14.256 [GroupItemStateChangedEvent] - ile_wlaczonych changed from ON to OFF through Salon_kanapa
2020-03-31 00:30:14.258 [vent.ItemStateChangedEvent] - Salon_kanapa changed from ON to OFF
11

That’s what I was expecting to see. The nbox rule is 14seconds “late” too.

See here -

12

This is another thing corrected in the new rule engine. Your rules would take all of a few minutes to do a straight conversion to Jython and about 30 minutes to remove the repeated code.

13

Hey. For several days I have been testing the operation with the addition of such a role. It seemed to help, but sometimes the role is delayed. Can he use a different code every minute?

```
rule "keep this thing in memory"
//use the compiled code in this rule file every minute
when
    Time cron "0 0/1 * 1/1 * ? *"
then
    return;
end
```
14

I wouldn’t assume every delay has the same cause. A Pi is pretty stretched to handle the load here.

15

I think there is still the same problem. Only applies to the role. Now the delay was 11 seconds. Other non-role functions work immediately.

2020-04-05 19:38:55.012 [ome.event.ItemCommandEvent] - Item 'roleta_all' received command DOWN
2020-04-05 19:38:57.855 [vent.ItemStateChangedEvent] - humidity_out changed from 30.799999237060547 to 30.700000762939453
2020-04-05 19:39:05.177 [vent.ItemStateChangedEvent] - temperature_out changed from 24.600000381469727 to 
2020-04-05 19:39:06.625 [ome.event.ItemCommandEvent] - Item 'roleta_salonOK' received command DOWN
2020-04-05 19:39:06.637 [vent.ItemStateChangedEvent] - roleta_salonOK changed from 0 to 100
2020-04-05 19:39:06.641 [ome.event.ItemCommandEvent] - Item 'roleta_salonT' received command DOWN
2020-04-05 19:39:06.646 [ome.event.ItemCommandEvent] - Item 'roleta_gosc' received command DOWN
2020-04-05 19:39:06.654 [ome.event.ItemCommandEvent] - Item 'roleta_kuchnia' received command DOWN
16

I think it’s okay. It helped to change the role to this:

```
rule "keep this thing in memory"
//use the compiled code in this rule file every minute
when
    Time cron "0 0/1 * 1/1 * ? *"
then
    logInfo("Motionrules","cron execution to prevent gargabe collection of compiled rules")
end
```