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
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?
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
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
}}
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
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
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