Rules are blocking

Setup, Configuration and Use Scripts & Rules
1
  • Platform information: RPi 3B, openHABian, openHAB 2.5.10, HABpanel

I have the following setup

  • Various bindings incl. Z-Wave, MagentaTV, Shelly, Sony, DreamScreen
  • more than 200 Things/Items
  • Most things/items are defined via PaperUI, only some textual config
  • Standard Rules (DSL)

Config

  • various things/item mappings are define to control my multimedia stuff
  • HABpanel defines the UI and process access to singular items or trigger scenes/rues
  • The rule includes a series of actions (switch on TV and receiver, select HDMI, set Ambilight…)

So just plain scenario: HABpanel triggers an items, a rule gets triggered, rule is executed

Problem

  • I had a setup based on OH 2.5.4, whiich worked pretty well. In some rare cases I saw a delay of 15s before the sceen got executed
  • After upgrading to 2.5.6 I noticed that delay has increaed to 15-30s, but number of issues was still acceptable
  • with 2.5.7 it got worth and 2.5.10 even doesn’t fixed it. Now I see most times a 15-60sec delay and only sometimes the rule is triggered straight

Example:

  • command is triggered at 21:19:52
  • rule execution starts at 21:19:54
    = 12secs of “nothing” before the rule executes
==> /var/log/openhab2/events.log <==
2020-11-23 21:19:42.530 [ome.event.ItemCommandEvent] - Item 'AVR_Program' received command ENTERTAIN
2020-11-23 21:19:42.539 [vent.ItemStateChangedEvent] - AVR_Program changed from OFF to ENTERTAIN

==> /var/log/openhab2/openhab.log <==
2020-11-23 21:19:54.604 [INFO ] [g.eclipse.smarthome.model.script.AVR] - Activate Program: ENTERTAIN
2020-11-23 21:19:54.606 [INFO ] [g.eclipse.smarthome.model.script.AVR] -   switch AVR ON

==> /var/log/openhab2/events.log <==
2020-11-23 21:19:54.612 [ome.event.ItemCommandEvent] - Item 'DenonPower' received command ON

==> /var/log/openhab2/openhab.log <==
2020-11-23 21:19:54.620 [INFO ] [g.eclipse.smarthome.model.script.AVR] -   switch to Entertain

==> /var/log/openhab2/events.log <==
2020-11-23 21:19:54.649 [ome.event.ItemCommandEvent] - Item 'DreamScreenTV_Power' received command ON

==> /var/log/openhab2/openhab.log <==
2020-11-23 21:19:54.649 [INFO ] [g.eclipse.smarthome.model.script.AVR] -   done

==> /var/log/openhab2/events.log <==
2020-11-23 21:19:54.668 [ome.event.ItemCommandEvent] - Item 'DreamScreenTV_InputSource' received command 1
2020-11-23 21:19:54.685 [ome.event.ItemCommandEvent] - Item 'TVWohnzimmer_MainSource' received command extInput:hdmi?port=3
2020-11-23 21:19:54.701 [ome.event.ItemCommandEvent] - Item 'DreamScreenTV_Mode' received command 0
2020-11-23 21:19:54.707 [ome.event.ItemCommandEvent] - Item 'DenonInput' received command SAT/CBL
2020-11-23 21:19:54.712 [ome.event.ItemCommandEvent] - Item 'DenonVolume' received command 55.0
2020-11-23 21:19:54.714 [nt.ItemStatePredictedEvent] - DreamScreenTV_Power predicted to become ON
2020-11-23 21:19:54.725 [ome.event.ItemCommandEvent] - Item 'DenonCommand' received command MSSTANDARD
2020-11-23 21:19:54.735 [ome.event.ItemCommandEvent] - Item 'RadioKitchen_Power' received command OFF
2020-11-23 21:19:54.748 [ome.event.ItemCommandEvent] - Item 'Plug_WonZ_TVL' received command ON
2020-11-23 21:19:54.760 [ome.event.ItemCommandEvent] - Item 'TVWohnzimmer_Power' received command ON
2020-11-23 21:19:54.763 [nt.ItemStatePredictedEvent] - DreamScreenTV_InputSource predicted to become 1
2020-11-23 21:19:54.770 [nt.ItemStatePredictedEvent] - TVWohnzimmer_MainSource predicted to become extInput:hdmi?port=3
2020-11-23 21:19:54.778 [nt.ItemStatePredictedEvent] - DreamScreenTV_Mode predicted to become 0
2020-11-23 21:19:54.789 [vent.ItemStateChangedEvent] - DreamScreenTV_Power changed from OFF to ON
2020-11-23 21:19:54.792 [nt.ItemStatePredictedEvent] - RadioKitchen_Power predicted to become OFF
2020-11-23 21:19:54.798 [nt.ItemStatePredictedEvent] - Plug_WonZ_TVL predicted to become ON
2020-11-23 21:19:54.806 [nt.ItemStatePredictedEvent] - TVWohnzimmer_Power predicted to become ON
2020-11-23 21:19:54.812 [vent.ItemStateChangedEvent] - Plug_WonZ_TVL changed from OFF to ON
2020-11-23 21:20:00.016 [vent.ItemStateChangedEvent] - PondPump2_PumpTotalWatts changed from 4.893 kWh to 4.894 kWh

==> /var/log/openhab2/openhab.log <==
2020-11-23 21:20:00.026 [INFO ] [lipse.smarthome.model.script.DayTime] - nNow=2120,nSunset=0,nSunrise=0isNight=false,isWeekend=false

This is the beginning of the rule:

val String source_tv = "tv:dvbs"
val String source_hdmi1 = "extInput:hdmi?port=1"
val String source_hdmi2 = "extInput:hdmi?port=2"
val String source_hdmi3 = "extInput:hdmi?port=3"
val String source_hdmi4 = "extInput:hdmi?port=4"

//
// AV Reveiver Programs
//
rule "AVR Program"
when
	Item AVR_Program received command
then
	logInfo("AVR", "Activate Program: " + AVR_Program.state.toString())

	if (receivedCommand.toString() == "OFF") {
		logInfo("AVR", "  switch TV+AVR OFF")
		sendCommand(DreamScreenTV_Power, OFF)
		sendCommand(DenonPower, OFF)
		if (EntertainTV_Power.state != OFF) {
			sendCommand(EntertainTV_Power, OFF)
		}
		sendCommand(TVWohnzimmer_Power, OFF)
		//callScript("tv_off")
		gAVR_Modes?.members.forEach([sw|
			logInfo("AVR-OFF", "  set " + sw.name + " to OFF (old state=" + sw.state.toString() + ")")
			sw.postUpdate(OFF)
		])
	}
	else {
		logInfo("AVR", "  switch AVR ON")
		sendCommand(DenonPower, ON)
	}

	if ((receivedCommand.toString() == "TV") ||
	    (receivedCommand.toString() == "ON"))
	    {
		//sendCommand(AmazonEchoDot_Speak, "Fernsehn wird eingeschaltet")
		sendCommand(TVWohnzimmer_Power, ON)
		sendCommand(DenonInput, "TV")
		sendCommand(RadioKitchen_Power, OFF)
		sendCommand(TVWohnzimmer_MainSource, source_tv)
		sendCommand(TVWohnzimmer_VolumeSpeaker, 60.0)
		sendCommand(DenonCommand, "MSMCH STEREO")	
		sendCommand(DenonVolume, 55.0)
		sendCommand(DreamScreenTV_Power, OFF)
		postUpdate(AVR_TV, ON)
		}
...

Looking to openhab.log I see

  • The command is send when I “click” the action in HABpanel
  • then nothing happens for about 10-30sec
  • then the rule gets executed and performs as expected

I already checked

  • there are no sleeps or executeCommandLins, I don’t use any reentrant lock prevention (no this in this scenario)
  • no errors or exceptions in the log, which could explain the behaviour
  • I’m not aware of any 30sec timeouts (tried grep 30000/15000/10000)

It just blocks between item receiving the command and execution of the rule

Question: How could I debug the event bus or rule engine to get some more details? You know: If there is a wife and the automation is not working… :crazy_face:

2

You give some log snippets with no configuration information of the Items, Thongs, & binding(s) involved with the example.

Perhaps you should focus on trying to resolve one thing instead of several at ones.

3

Are there any other rules running at the same time?

4

maybe if rules haven’t run for a long while but only on first run

5

There are more rules, but nothing at the same time

6

Any rules using timers? You can run out of threads with too many timers running.

7

You mean things like

		createTimer(now.plusSeconds(5), [| 
			logInfo("AVR", "Start NETFLIX App")
			sendCommand(EntertainTV_Key, "ENTER")
			postUpdate(AVR_NETFLIX, ON)
		])

?

8

Item definition is

Group	All
Group   Home							(All)
Group	System		"System"			(All)
Group	Scenes						(Home, All)

String AVR_Program			"AVR Programm"
Number	Scene_Wohnzimmer	"Programm_Wohnzimmer"	<scene>		(Scenes)

I don’t think that it helps when I upload my JSON DB or provide all config details. My installation is grown over the last 2 years.

9

Yes. I do not use timers but I understand a timer can tie up ar rule thread and OH has a very limited number of them. I think @rlkoshak is more of a timer expert since I do not use them.

10

There is no indication of what binding the Items use though.

11

This is just a proxy item. It gets trigged in the UI, sends a command value to Scene_Wohnzimmer, which then triggers the rule - stupid simple, but causing this issue

The rule sends commands to Z-Wave, Shelly, MagentaTV, DreamScreen items - this parts works, it’s the statt of the sequence, which gets delayed for 10-60sec (mostly around 30s).

Thanks for help

12

I just noticed my group definitions

Group	All
Group   Home							(All)
Group	Scenes						(Home, All)

String AVR_Program			"AVR Programm"
Number	Scene_Wohnzimmer	"Programm_Wohnzimmer"	<scene>		(Scenes)

That means, Scene_Wohnzimmer is part of Scenes, which includes groups All and Home. Those groups contains other items. Could the group hierarchy impacts rule execution?

13

I followed this advise and added the rule

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

and it seems that it provides the expected improvements.

1 Like
14

no. There is an unlimited number of times you can have, within the confines of ram at least. Where trouble happens is when you have long running rules. Rules with sleeps, calls to executeCommandLine with a timeout, sendHttpXRequest. These cause the rule to pause but not return, consuming one of the rules threads. If this happens too often you may run out of the 10 threads available causing all rules to stop.

if you are using long running commands anywhere they can and will impact all your rules of you end up with 10 rules blocked at the same time waiting for something.

no

I’m glad Andrew got you points in what appears to be the right direction.

I’ll note that this is not a problem in OH 3. There is an unlimited number of rules threads available.

1 Like
15

thanks for the background

So far I could report: Just switch on my TV (HABpanel->Proxy Item->rule) and rule got triggerd instantly. It seems that I have a work around :slight_smile:

1 Like
16

That last sentence is definitely an incentive to do an OH 3 build over Christmas!
<“I’ll note that this is not a problem in OH 3. There is an unlimited number of rules threads available.”>

17

fyi: I have no issues anymore since I put in the dummy rule, so the problem was not the number of rule threads

18

Unfortunately, as of yesterday a thread pool may have been reintroduced. I don’t have any details on it yet.

19

:crazy_face: That’s crazy talk…

In any event, I am looking forwards to running up a version 3.

20

Hi All,

Just to close this off, ever since upgrading to OH 3, the problem has disappeared. The platform has been very stable and responsive.

Many thanks to all the devs for their hard work and dedication :slight_smile:

1 Like