[2.4.0.144-148] Rule Machine Delay when using Cancel Time Actions [C8-Pro]

jsprince3 · December 29, 2024, 7:33pm

I have noticed a delay processing RuleMachine rules that started with the 2.4.0.x branch.
After further testing, it appears to only have a delay if using the "Cancel Time Actions" method. The delay increases if there are multiple items to cancel.
I made a simple rule for testing that only cancels it own timers.

Include Cancel:

  app:5012024-12-29 01:18:38.642 PMinfoAction: Off: Shop Lights --> delayed: 0:00:30(cancelable)
  app:5012024-12-29 01:18:38.534 PMinfoAction: On: Shop Lights
  app:5012024-12-29 01:18:37.379 PMinfoEvent: Actions stopped by Shop Door Open Lights on
  app:5012024-12-29 01:18:35.365 PMinfoAction: Cancel Timed Actions: **This Rule**
  app:5012024-12-29 01:18:34.348 PMinfoTriggered: Door shop house contact open
  app:5012024-12-29 01:18:34.347 PMinfoEvent: Door shop house contact open

Cancel timed action removed:

  app:5012024-12-29 01:16:59.936 PMinfoAction: Off: Shop Lights --> delayed: 0:00:30(cancelable)
  app:5012024-12-29 01:16:59.877 PMinfoAction: On: Shop Lights
  app:5012024-12-29 01:16:59.836 PMinfoTriggered: Door shop house contact open
  app:5012024-12-29 01:16:59.835 PMinfoEvent: Door shop house contact open

Very simple rule:

jsprince3 · December 29, 2024, 8:58pm

A quick fix (bandaid) for me was to place the cancel after the "on".
This works for most of my rules.

SearchWorm · December 31, 2024, 10:50pm

You're not alone!
I have the same problem. Couldn't figure out why it was taking 10-20 secs for the light to turn on.
I used the same Band-aid to solve it.

Edit:
Found another delay with "Set Private Boolean".

If you set the Boolean for other rules, it takes about 5 secs per rule.

In this example, it took 11 secs to run:
Rule Boolean True: 'Kitchen Motion, Reset Internet '

What's weird though, if the Boolean is already set to that value, there isn't any delay!

woodsy · December 31, 2024, 11:13pm

I feel I am experiencing a similar issue with cancel delayed actions.

rob9 · January 2, 2025, 1:38am

Wow. Ever since updating, I've noticed a lot of "very slow starts" to my rules--I bet this is my issue as well. Thx!!

rob9 · January 7, 2025, 4:43am

@bravenel @bobbyD Any thoughts on what might have changed?

Here are some examples on a C-8 Pro...

The issue appears to only involve cancelling RM5 rules, btw.

I created an RM5.1 test app--just two log command. [5 msec]

Then, I added a "Cancel" of the rule's own actions. [2.165 sec]

Then, I tried cancelling 10 RM5 rules (without the rule's own actions). There's quite a noticeable delay. [7.962 sec]

Then, I tried cancelling 10 RM4 (legacy) rules. That ran almost instantly. [21 msec]

rob9 · January 8, 2025, 12:19am

Another thing I discovered in this area has to do with timing of setting Private Booleans.

I had a pair of rules that had been working pretty well, with one calling the other--but they started misbehaving.

The first rule (RM5.1) was setting the PB of the second rule (RM4-Legacy) in one line then, in the next line, running that second rule (I was using the PB in the second rule as an indication that the first rule was what invoked it).

I had expected that the process of setting the PB would have fully completed prior to the "Run Actions" in the next line executing--but, based on the logs & what happened, the second rule was often running before it's PB was set (the "IF PB" test was failing in the second rule).

It's a bit of a hack, but I added a "wait for expression/elapsed time/3 sec" in the first rule after setting the PB and before calling the rule to give the "Set PB" time to fully complete. That at least worked on my first test.

It seems that setting the PB puts enough load on the hub to cause some asynchronous actions to happen in an unexpected order, which the "wait" works around.

I created a test case that reproduces this:

The main/calling rule "000 Test Rule" (App #2140, RM5.1) - It appears that the "activity" generated by the "Run Actions: Garage Door-Close if Open" is relevant (it doesn't do too much--but it is running in the background).

The called rule, "aaTest" (App #53, RM4):

The "Garage Door-Close if Open" rule (App #35, RM4):

And the logs:

vitaliy_kh · January 8, 2025, 2:09am

This is not new.
In my case using PB for synchronizing rules and/or for preventing multiple triggers never worked reliably.

rob9 · January 9, 2025, 2:09am

I'm guessing the basic design issue you encountered may not have changed--but something is seemingly putting a pretty high load on the hub and taking much longer to process Cancels and PB setting. I expect that may be what exacerbated the issue for me and caused enough additional delay to make my rule invocation work unreliably. Thanks for the info!

vitaliy_kh · January 9, 2025, 2:22am

Yes, system is getting more complicated. This requires more processing power which leads to longer delays. Unfortunately system was not designed as a "real time system". Being EE I didn't like all that multythreading/multitasking from the day when it was introduced because timing was not guaranteed and unpredictable.

rob9 · January 9, 2025, 2:54am

Related: I tried looking at the "%device%" and "%value%" variables, but the values are NOT set to the calling rule when it is called from another rule (or directly started from the App). This appears to apply to RM4 and RM5.1 rules. And, indeed, there are also timing issues when one rule calls another (or it invoked from the "Run Actions" button in the editor) with these variables.

The "%device%", "%date%", and "%time%" values seem to be set properly and prior to the rule running when the rule is triggered by a device (e.g., button push) as references to them in the first lines return the expected device/value/time.

However, when invoked from another rule (or from the App Editor button), the values are unchanged for a period of time after the rule starts (any reference to them in the first few lines returns the former values. However, inserting a brief delay (e.g., 2 sec) allows the values to be updated (%device% becomes "null", %value% becomes 0, and the date/time are updated).

jtp10181 · January 20, 2025, 10:34pm

@bravenel I am seeing this issue also on 2.4.0.148. Causing a 2+ second delay on a rule of mine which I thought used to run pretty quick.

I am using the Cancel Timed actions in case the rule is triggered multiple times, so it kills anything from the old instance and starts a fresh run. I think that is the proper use case for this feature?

bravenel · January 20, 2025, 10:53pm

Fix coming for that...