Delay between sensor and actor since OH2.5

Hi,
i have a strange delay between sensor and actors since upgrade from 2.4 to 2.5

i’m using Fibaro Z-wave motion sensors and KNX actors (My friend is using homematic and Philips having same issues)

OH is running on Raspi3 with z-wave stick and ABB EIB-IP gateway

2020-02-24 10:07:44.927 [vent.ItemStateChangedEvent] - Bewegung_EG_Flur1 changed from OFF to ON

2020-02-24 10:07:55.726 [ome.event.ItemCommandEvent] - Item 'Bewegung_EG_Flur' received command ON

2020-02-24 10:07:55.846 [vent.ItemStateChangedEvent] - Bewegung_EG_Flur changed from OFF to ON

2020-02-24 10:07:56.021 [GroupItemStateChangedEvent] - AlleLichter changed from OFF to ON through Light_EG_Flur_Garderobe

2020-02-24 10:07:56.025 [vent.ItemStateChangedEvent] - Light_EG_Flur_Garderobe changed from OFF to ON

as you can see there is a delay of almost 9 seconds 10.07.44-55 ?!?!

here the configuration

items:
Switch  Bewegung_EG_Flur1   "Bewegungsmelder EG Flur [MAP(de.map):%s]"     (EG_Flur,Status)     { channel="zwave:device:36569a7a:node3:alarm_motion" }
Switch  Bewegung_EG_Flur    "Bewegungsmelder EG Flur [MAP(de.map):%s]"                          { channel="knx:device:bridge:generic:Bewegung_EG_Flur", autoupdate="true" }            

Thing:	
Type switch        : Bewegung_EG_Flur               	"Bewegungsmelder EG Flur"                       [ ga="<11/0/21" ]
Type switch        : Light_EG_Flur_Garderobe        	"EG Flur"               						[ ga="<1/0/210" ]
	
Rules:	
rule "Bewegung_EG_Flur1 an"
when 
Item Bewegung_EG_Flur1 changed to ON
then{
sendCommand(Bewegung_EG_Flur,ON)
sendCommand(eib_backlight,ON)
	Display = createTimer(now.plusMinutes(5)) [ |
					if( Bewegung_EG_Flur.state == OFF ) {
						sendCommand(eib_backlight,OFF)
			}]
	}
end

rule "Bewegung_EG_Flur1 aus"
when 
Item Bewegung_EG_Flur1 changed to OFF
then
sendCommand(Bewegung_EG_Flur,OFF)
end

hope someone can help here since this is not usable :frowning:
thanks
Thomas

Looking at just these two events to begin with.
Item Bewegung_EG_Flur has autoupdate enabled.
So the Item state change is by autoupdate, in response to the command.
Typically you’d expect to see a 5-10mS delay between.
You’ve got 120mS delay - it’s huge.

I think you should be looking at this as a whole system performance problem,
Are you making lots of persistence traffic to an SD card, things like that?

Hi,
i have M2 SSD attached (no SD card) iostat shows very low iowait times 0.00 - 0.03
The problem came after 2.5 upgrade, never had this before.
In addition the problem is not every time, sometimes the delay is there sometimes not.
any idea how to debug this ?
thanks
Thomas

I’m not sure where to start, just pointing out I think you’ll need to look further than just rules and binding performance.

Probably unrelated - your timer rule is badly managed. It just blindly makes a new timer at each trigger (orphaning any existing timer, which continues to run), never checks to see if one is already running. Have you many rules with this structure?

yes, i know this timer is bad managed, have only 2 of them, let me fix them.
but i don’t think this is causing the issue.
thanks
Thomas

I wouldn’t think so either, unless you had a lot of rules and sensors going crazy. A dozen Timers just waiting consume no resources.

ok, have update all my timers (5) like the following example, hope this is fine.

rule "Bewegung_EG_Flur1 an"
when 
Item Bewegung_EG_Flur1 changed to ON
then{
sendCommand(Bewegung_EG_Flur,ON)
sendCommand(eib_backlight,ON)
	if (Display === null)  {
		Display = createTimer(now.plusMinutes(5)) [ |
					if( Bewegung_EG_Flur.state == OFF ) {
						sendCommand(eib_backlight,OFF)
					Display = null
			}]
	}}
end

Look close at your logs. Lots of folks have found after the upgrade, an add-on is reloading repeatedly. Also, one bad zwave node can slow the whole system down, swapping the controller and causing delays.

Not really. If the timer expires and the Item happens to be already off, the timer does not null the handle (so you will never create a new timer afterwards).

I think I’d want to reschedule an already running timer if a new trigger arrives.
This is all standard stuff and off-topic really

ok, had only this timer with wrong configuration, changed now to

rule "Bewegung_EG_Flur1 an"
when 
Item Bewegung_EG_Flur1 changed to ON
then{
sendCommand(Bewegung_EG_Flur,ON)
sendCommand(eib_backlight,ON)
	if (Display === null)  {
		Display = createTimer(now.plusMinutes(5)) [ |
					if( Bewegung_EG_Flur.state == OFF ) {
						sendCommand(eib_backlight,OFF)
					Display = null
			}]
		Display = null	
	}}
end

thanks
Thomas

Look at the if() in your timer code.
If the timer runs, and the Item happens to be already off, your handle Display will not be set to null.
Now think about what happens when the next trigger comes along later.

But that doesn’t really matter … because as soon as you have created your timer you immediately set Display back to null anyway.

The stuff following an if() in curly brackets { } is what gets executed when the if() is true.
The stuff following a createTimer() in square brackets [ ] is what gets executed when the timer expires.

	if (Display === null)  {
		Display = createTimer(now.plusMinutes(5)) [ |
					if( Bewegung_EG_Flur.state == OFF ) {
						sendCommand(eib_backlight,OFF)
					Display = null  // this is wrongly indented which confuses you
                                    // this is inside the if()
			}]
		Display = null	// this is executed immediately after createTimer
	}}
1 Like

ok, have changed the rule in the following way and OH was restarted, still issues with delays…
is there any way to see the timer resources in use ?
thanks
Thomas

rule "Bewegung_EG_Flur1 an"
when 
Item Bewegung_EG_Flur1 changed to ON
then	{
logInfo("Bewegung_EG_Flur1 an","Rule running!")
sendCommand(Bewegung_EG_Flur,ON)
sendCommand(eib_backlight,ON)
	if (Display === null)	{
		logInfo("Bewegung_EG_Flur1 an","Light ON Timer start")
		Display = createTimer(now.plusMinutes(5)) [ |
					if( Bewegung_EG_Flur.state == OFF ) {
					sendCommand(eib_backlight,OFF)
					logInfo("Bewegung_EG_Flur1 an","5 Min Timer expired OFF")
					Display = null}
					if( Bewegung_EG_Flur.state == ON ) {
					logInfo("Bewegung_EG_Flur1 an","5 Min Timer expired ON")
					Display = null}
	]
							}
		}
end

There is an else clause for use with if(), which would seem appropriate there.
If you want to set Display = null whatever the if() does, then do so. Move it outside the if() containing curly brackets { }.

Have you defined Display somewhere else? It seems an odd name for a light timer handle. Does it get used in other rules?

As we agreed earlier, this likely has nothing at all to do with general performance issues,
Have you followed @Andrew_Rowe advice yet?

Hi,
yes display is defined on top of the rules file (not used somewhere else)
i have checked the logs and z-wave, no reloads no z-wave issues :smirk:
i did top, iostat and sar check and didn’t find any resource issue.
Since i have a spare SSD i will setup OH2.4 with same configuration to check.
The stange thing is that my friend having the same issues since upgrade to 2.5… and he is using different hardware.
thanks
Thomas

Good morning, short update:

have update the PI from pi3 1gb to Pi4 4gb, still same issue :unamused:

any other idea how to debug this issue ?

thanks
Thomas

another example with 4 sec delay

2020-02-27 13:06:05.323 [vent.ItemStateChangedEvent] - Bewegung_EG_Flur1 changed from OFF to ON

2020-02-27 13:06:09.567 [INFO ] [me.model.script.Bewegung_EG_Flur1 an] - Rule running!

2020-02-27 13:06:09.575 [INFO ] [me.model.script.Bewegung_EG_Flur1 an] - Light ON Timer start

2020-02-27 13:06:09.585 [ome.event.ItemCommandEvent] - Item 'Bewegung_EG_Flur' received command ON

2020-02-27 13:06:09.630 [vent.ItemStateChangedEvent] - Bewegung_EG_Flur changed from OFF to ON

2020-02-27 13:06:09.763 [vent.ItemStateChangedEvent] - Light_EG_Flur_Garderobe changed from OFF to ON

Comment - you seem to be missing the command to eib_backlight expected from the rule you have shown.
Sure you don’t have duplicate rules or something? (the rule “name” must be unique for every rule)

More comment - the delay between Bewegung_EG_Flur command and changed events still seems very sluggish for autoupdate action.
I still suggst this is a general system slowdown, not rules specific. You’ve got a resource hog somewhere.

You’ll need to rummage in other performance or “rule stopped” message threads for tools for your system for performance monitoring.

hi, no the eib_backlight is not missing, i just didn’t post the full log.
The Rule name is uniq, just checked. Just one note, might be this is a probem ?
have 2 rules with the following names “Bewegung_EG_Flur1 an” and “Bewegung_EG_Flur1 aus”
is the space ok or should i replace by “_” ??
How can i monitor the OH resources ?
thanks
Thomas

the space is fine