FYI I've changed my approach to solving my problem: my physical button controller rules now calculate the next desired scene number by incrementing/cycling a hub variable directly, then use a custom action to push the appropriate button on my virtual button. The virtual button controller issues the light-changing commands that implement each scene in the group of related scenes, updates the current scene number, and logs the operation. All appears to occur instantaneously now.
I looked at Room Lighting, but since it doesn't allow me to log information or change variables, there was no point in introducing it as an extra level of indirection. Also, I didn't see a mechanism to define a group of related scenes that "cancel each other out" like radio buttons. So in the end, using a virtual button device and its controller to implement such a set of scenes works well.
My immediate problem is solved, but I'll definitely follow this topic to find out what happens to the performance of nested commands, as I may still want them someday! Thanks, all, for pointing me in the right direction.
After the update to 2.4.0 I started experiencing an issue with one rule. I had this same rule in 2.3.9 and it worked flawlessly. The breakdown in the rule was a wait event. The rule waited for a contact sensor to open, then after it was open for 3 seconds, the light turned off. With the update it started not turning off the light. Looking at the logs the rule would run flawlessly up to the wait event. It would show the wait event but then the log would never show the rule giving the command to turn off the light. This was not a constant occurrence. Sometimes the rule would give the command to turn off the light and when it did so the light would turn off. I have similar rules in other areas of my home that continued to work as normal.
I updated to .148 (newest release) hoping the fix would take care of this. It did not. The rule still intermittently (actually most often) will not issue the command to turn off the light after the three second wait period.
I've updated to 2.4.0.148 and run the same test with 3 rules as before (How to explain these delays? - #18 by mattias). Calling another rule and the return to the original rule now appears to run as quickly as it did in 2.3.9.200:
However, setting the private boolean of another rule is still slow. My test scenario still takes 4.5 seconds to run on 2.4.0.148 when it takes only 300-350ms on 2.3.9.200. @bravenel - Is the private boolean delay something you've already got on the radar to have a look at?
I guess, this should be moved to a separate/dedicated discussion.
But anyway, "wait for event" in the middle of the rule is nothing more than a secondary trigger event for the same rule. Therefore it is a very good starting point for splitting one complex rule into few multiple rules. In this case first rule should stop right before "wait for event" statement. Following (second rule) rule should have a conditional trigger "contact is open only if light is on" and the rest whatever it was after "wait for event" statement.
This is all about the internal timing and potential race conditions.
PS.
Initially I myself was using complex rules only because maintainability for the single rule vs multiple rules looked easier. However HE RM stability is far more better with set of simple rules vs one complex. My complex rules worked hear 100% of times but occasionally did fail without apparent reason. After splitting complex rule into set of multiple rules random failures basically stopped.
I confirm that the update from 2.4.0.147 to 2.4.0.148 fixes the performance problem with nested rules:
2.4.0.147
app:186 2025-01-19 13:56: 38.629 info Test 1 ENDS
app:186 2025-01-19 13:56: * 38.627 info Test 1 CONTINUES after return from Test 2
app:185 2025-01-19 13:56: 37.609 info Test 2 ENDS
app:185 2025-01-19 13:56: 37.607 info Test 2 CONTINUES after return from Test 3
app:184 2025-01-19 13:56: 37.579 info Test 3 ENDS
app:184 2025-01-19 13:56: 37.578 info End of variable setting tests
app:184 2025-01-19 13:56: 37.566 info About to set local variable from global (3)
app:184 2025-01-19 13:56: 37.553 info About to set local variable from global (2)
app:184 2025-01-19 13:56: 37.537 info About to set local variable from global (1)
app:184 2025-01-19 13:56: * 37.535 info Test 3 STARTS
app:185 2025-01-19 13:56: 35.509 info Test 2 CALLING Test 3
app:185 2025-01-19 13:56: 35.507 info Test 2 STARTS
app:186 2025-01-19 13:56: 35.482 info Test 1 CALLING Test 2
app:186 2025-01-19 13:56: 35.480 info Test 1 STARTS
2.4.0.148
app:186 2025-01-19 14:10: 52.054 info Test 1 ENDS
app:186 2025-01-19 14:10: 52.052 info Test 1 CONTINUES after return from Test 2
app:185 2025-01-19 14:10: 52.036 info Test 2 ENDS
app:185 2025-01-19 14:10: 52.034 info Test 2 CONTINUES after return from Test 3
app:184 2025-01-19 14:10: 51.986 info Test 3 ENDS
app:184 2025-01-19 14:10: 51.984 info End of variable setting tests
app:184 2025-01-19 14:10: 51.966 info About to set local variable from global (3)
app:184 2025-01-19 14:10: 51.948 info About to set local variable from global (2)
app:184 2025-01-19 14:10: 51.929 info About to set local variable from global (1)
app:184 2025-01-19 14:10: 51.927 info Test 3 STARTS
app:185 2025-01-19 14:10: 51.861 info Test 2 CALLING Test 3
app:185 2025-01-19 14:10: 51.859 info Test 2 STARTS
app:186 2025-01-19 14:10: 51.833 info Test 1 CALLING Test 2
app:186 2025-01-19 14:10: 51.831 info Test 1 STARTS
The call and return delays are gone, and the total runtime of this particular example (rule 1 calls rule 2 calls rule 3, which doesn't do much of anything) goes from 3.149 to 0.223 seconds.
