I’m running OH3 in a Debian GNU/Linux 10 (buster) VM. I added some items to a group and run a rule on the member of group received a command trigger. Unfortunately the rule fire 6s after an item of the group receives a command. Therefore I created a rule, which triggers only if a specific item of the group receives a command to find out the reason of the lack.
21:06:28.367 [INFO ] [.openhab.core.model.script.bottleneck] - kitchenlight receive command
21:06:34.069 [INFO ] [g.openhab.core.model.script.cp2e_item] - crestron controller item light_kitchen changed to ON on command ON
I assume the difference is based on the complexity of the group rule, because if I create a group rule which logs only one line, both rules be fired instant.
21:20:55.790 [INFO ] [ab.core.model.script.bottleneck group] - cp2e item received a command
21:20:55.803 [INFO ] [.openhab.core.model.script.bottleneck] - kitchenlight receive command
21:21:01.305 [INFO ] [g.openhab.core.model.script.cp2e_item] - crestron controller item light_kitchen changed to OFF on command OFF
I use DSL rules. Maybe javascript rules are more performant? Do anyone have I link, where I could find a complete docu for the javascript rule engine? I will need the item which triggers the group rule.
You do understand that an Item may or may not respond to a command with a state change? And if it ever does change, it could be some time later?
How much time depends on the technology of the target device and/or your configuration of the Item as regards autoupdate.
Having got the basics out of the way…
These logs are only a part of the flow of group command → item command → item state response
To help isolate the problem area, find your events.log entries corresponding to the commands to group and item to get a better understanding of timings.
If you’re using a group to command a lot of Items at once, that may create a traffic jam in whatever communications technology your devices use.
I understand the event flow. Therefore I use receive command instead of receive update or change state. The items are all created via “Add Item” and are not assigned to any technology. The technology come into play within the rule as the last command by sending a command to another item. Everything is openhab only. Besides only one item is triggered at once.
The event log is the same but w/o the log entries from the rule
2021-04-19 22:28:12.576 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'light_kitchen' received command ON
2021-04-19 22:28:12.597 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'light_kitchen' changed from OFF to ON
2021-04-19 22:28:18.861 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'toggle_port' received command 7
2021-04-19 22:28:12.650 [INFO ] [b.core.model.script.bottleneck group] - cp2e item received a command
2021-04-19 22:28:12.689 [INFO ] [openhab.core.model.script.bottleneck] - kitchenlight receive command
2021-04-19 22:28:18.834 [INFO ] [.openhab.core.model.script.cp2e_item] - crestron controller item light_kitchen changed to ON on command ON
2021-04-19 22:28:18.844 [INFO ] [.openhab.core.model.script.cp2e_item] - item light_kitchen change result in trigger of port 7
‘toggle_port’ is the resulting call of the rule. For a better understanding the instant triggered rules only contains a log line. The rule which have a lack of 6s looks like this. As you can see the first line of the rule is the log line which occurs 6s “too late” in the original post.
var itmStr = triggeringItem.name.toString
var cmd = receivedCommand
logInfo("cp2e_item", "crestron controller item {} changed to {} on command {}", itmStr, triggeringItem.state, cmd)
var portToToggle = ""
switch ( itmStr ) {
case "light_couch" : { portToToggle = "1" }
case "light_eat" : { portToToggle = "2" }
case "outlet_tv" : { portToToggle = "3" }
case "light_entry" : { portToToggle = "4" }
case "light_stack" : { portToToggle = "5" }
case "light_tv" : { portToToggle = "6" }
case "light_kitchen" : { portToToggle = "7" }
case "light_out_star" : { portToToggle = "8" }
case "light_house" : { portToToggle = "9" }
case "light_way" : { portToToggle = "10" }
case "outlet_stack" : { portToToggle = "11" }
case "outlet_tree" : { portToToggle = "12" }
case "outlet_stairs" : { portToToggle = "13" }
case "outlet_work" : { portToToggle = "14" }
case "outlet_garden" : { portToToggle = "15" }
case "light_patio" : { portToToggle = "16" }
//case "unkonwn_1" : { portToToggle = "17" }
//case "unknown_2" : { portToToggle = "18" }
//case "unknown_3" : { portToToggle = "19" }
case "shutter_eat" : {
switch ( cmd ) {
case UP : { portToToggle = "20" }
case 0 : { portToToggle = "20" }
case DOWN : { portToToggle = "21" }
case 100 : { portToToggle = "21" }
case STOP : { portToToggle = "22" }
}
}
case "shutter_couch" : {
switch ( cmd ) {
case UP : { portToToggle = "23" }
case DOWN : { portToToggle = "24" }
case STOP : { portToToggle = "25" }
}
}
case "shutter_tree" : {
switch ( cmd ) {
case UP : { portToToggle = "26" }
case DOWN : { portToToggle = "27" }
case STOP : { portToToggle = "28" }
}
}
case "shutter_kitchen" : {
switch ( cmd ) {
case UP : { portToToggle = "29" }
case DOWN : { portToToggle = "30" }
case STOP : { portToToggle = "31" }
}
}
case "shadow_patio" : {
switch ( cmd ) {
case UP : { portToToggle = "32" }
case DOWN : { portToToggle = "33" }
case STOP : { portToToggle = "34" }
}
}
case "temp_living_inc" : { portToToggle = "35" }
case "temp_living_dec" : { portToToggle = "36" }
case "temp_guest_inc" : { portToToggle = "37" }
case "temp_guest_dec" : { portToToggle = "38" }
case "temp_corridor_inc" : { portToToggle = "39" }
case "temp_corridor_dec" : { portToToggle = "40" }
case "shutter_bath" : {
switch ( cmd ) {
case UP : { portToToggle = "41" }
case DOWN : { portToToggle = "42" }
case STOP : { portToToggle = "43" }
}
}
case "shutter_hwr" : {
switch ( cmd ) {
case UP : { portToToggle = "44" }
case DOWN : { portToToggle = "45" }
case STOP : { portToToggle = "46" }
}
}
case "shutter_guest" : {
switch ( cmd ) {
case UP : { portToToggle = "47" }
case DOWN : { portToToggle = "48" }
case STOP : { portToToggle = "49" }
}
}
case "shutter_emilia" : {
switch ( cmd ) {
case UP : { portToToggle = "50" }
case DOWN : { portToToggle = "51" }
case STOP : { portToToggle = "52" }
}
}
case "shutter_work" : {
switch ( cmd ) {
case UP : { portToToggle = "53" }
case DOWN : { portToToggle = "54" }
case STOP : { portToToggle = "55" }
}
}
case "scene_work_morning" : { portToToggle = "56" }
case "scene_all_up" : { portToToggle = "57" }
case "scene_good_night" : { portToToggle = "58" }
case "scene_cinema" : { portToToggle = "59" }
case "scene_leave_home" : { portToToggle = "60" }
}
logInfo("cp2e_item", "item {} change result in trigger of port {}", itmStr, portToToggle)
if (portToToggle != "") {
toggle_port.sendCommand(portToToggle)
}
I’m assuming the rule is parsed everytime before it’s fired and this is the bottleneck.
EDIT:
Changing the rule to only one if statement results in the same…
So far, so good … ish.
Autoupdate has taken 20mS to make the state update.
That’s not very good performance, I’d expect this to happen in nearer 5mS, but it’s not a disaster. I mention this because it may hint at a general illness.
Or, I’m assuming it was autoupdate at at work. There was talk of groups, but we don’t know which Items are groups. If ‘light_kitchen’ is a Group then it is aggregation at work instead, and the longer delay is to be expected because of the longer chain involving members.
So, what actually are the triggers that you are inviting us to compare? The six second delay is plain enough to see.
Are these UI entered rules?
Thinks; are you sending a command to Group X, and have a rule triggered by ‘member of X received command’?
The Group will propagate the command to each member.
If the Group has N members, the rule will run N times, one after the other,in an orderly queue.
I have one group called “Crestron Items” which contains about 20 items (among other the light_kitchen item). Both group and items are created via “Add Item” respectivly “Add Group”. None of the items is linked to a channel, bridge or whatever. Just plain, direct openHAB items.
I will create a new VM from the snapshot I have made after the installation of openHAB3, add a group and some items to it. This should reproduce the behaviour.
There are a lot of string constants in your “slow” rule, and a lot of switch-case elements. Might be relevant,just commenting.
I would make another really simple rule with “hello world” message only, but with same member-of triggering. This can be tested both alongside your other rule, and on its own, to determine if delay has anything to do with script content.
There is some weird timing around group state aggregation for some people, but his does not look directly related at this stage. The fingerprint there is an ever-increasing delay, not a consistent time.
Hi, I run openHAB 3.1.0.M3 in a container, add a group and two items. Everything happened istant. But I do not install any addon or binding. For now I am not able to determine if my issue with 3.0.1 is fixed within 3.1.0.M3 or the system is as fast as expected because I do not install any additional stuff. I will keep searching
Now, I change the rule to use if-else-if statements instead of switch. It makes it even worse… therefore I assume the DSL rule engine is not working as fast as I expect. Do you have a link to a good documentation for the JavaScript rule engine. Especially I‘m looking for an equivalent for triggeringItem instance?
You told us before that you had tried a simple rule with just a “hello world” and it was “the same”, so changing out switch-case would not be expected to fix anything.
Oh. I interpreted your last -
as meaning there was no delay. I don’t know what is happening now, what you are doing, or what you are seeing.
No. The web is full of guides for javascript.
The openHAB rule engine uses the same rule triggering mechanism, no matter what language you write your script block in, and triggering is still amongst the suspects here.
It was, but I had the rule with the switch content still enabled. When I disabled this rule, the “hello world” rule executed within millisecond. Sorry that I did not expect, that two undepended defined rules will be influenced by eachother…
Sorry for asking… I am able to write JS code that is not the point. But the official rule documentation, which you could find here https://www.openhab.org/docs/configuration/jsr223.html
is not as informative as the documentation for the DSL engine. After visiting some google results and some try’n’error, I found what I need
var itmNme = event.itemName;
var logger = Java.type("org.slf4j.LoggerFactory").getLogger("org.openhab.model.script.Rules.Experiments");
logger.info("item {} triggered", itmNme);
switch( itmNme ) {
case "light_eat":
logger.info("worked out");
break;
default:
logger.info("no matching item found");
break;
}
It is working, but I do not want to use a logger from a lib which is called Rules.Experiments. But it seems that I have to, because calling print("some log"), as it is documented in the previous link, do not produce any log.
Big step forward - looks like group-based rules triggering is not implicated here.
My suspicions are back on DSL’s handling of a large number of string constants.
Well, if one is getting mired down doing whatever there would be a lot of pot luck involved about it holding up parts of the other’s processing, so we must do both experiments.
You’re not, you are choosing to name your new logger Rules.Experiments (and not unreasonably so, in the circumstances)
