How to explain these delays?

[anne.hubitat]

TLDR: Is there a known two-second delay when an RM5.1 rule calls "Run Actions" on another RM5.1 rule? Is there a known delay upon returning from such a call? And is there a reason why it could take an RM5.1 rule several seconds to perform a handful of numerical comparisons in IF-THEN rules? (Note: none of these rules contain any wait or delay actions). FWIW this is on a C-8 Pro version 2.4.0.145.

Okay, here's the long version... Note that if you can answer the questions above, no need to read through all of the below! If I can understand WHY the delays are happening, I can figure out workarounds...

So I wrote a bunch of rules to cycle through lighting "scenes" (which for now I've implemented as Rule Machine 5.1 rules, because I need to set state at the end and "real" Scenes don't allow that) at the touch of a button, and I was all proud of myself until I realized that it could take up to 8 seconds between the button press and the lights changing!

I've instrumented my rules with logging, so I can tell where the delays occur, but I'd like to understand why they occur before I decide on a new approach to implementing my design.

• The first type of delay is when an RM rule calls "Run Actions" on another rule: between the caller making the call and the callee starting up, there's a delay of just over two seconds, which I interpret as likely exactly two seconds plus the time it takes to write my log line. Is this a known issue? (Note that when a button controller rule calls "Run Actions", as opposed to when another RM rule does it, I don't see a delay.)

• The second type of delay is on returning from a "Run Actions" call, again between two RM rules. This one's less constant: my return from level 3 to level 2 "subroutine" is almost instantaneous, but from the level 2 rule logging its end to the level 1 rule logging the return from the "subroutine" call takes just over 4 seconds.

• The third type of delay is within one of the rules, where a series of IF-THEN, ELSE-IF statements matches a numerical state to the correct rule call to set the scene I want next. It seems to me that numerical comparisons ought to take no time at all, but the rule takes longer the further it has to go through the series of conditionals - up to 3 seconds to fall through to ELSE after going through three tests. I was originally testing against a hub variable, then when I read that the oldstyle "global" variables could be slow, I changed the code to read the hub variable into a local variable once at the top, then test against this local variable - no change. Why would it take several seconds to perform a bunch of integer comparisons?

The structure of my set of rules is (indented by call level):

• (BC) Test button
  • (RM) SCENE-TOGGLE: UP kitchen lights
  • (RM) SCENE-TOGGLE: DOWN kitchen lights
    • (RM) SCENE-SET: kitchen lights per Kitchen_scene_requested
      • (RM) SCENE: kitchen lights 0: off
      • (RM) SCENE: kitchen lights 1: full on
      • (RM) SCENE: kitchen lights 2: mood lighting
      • (RM) SCENE: kitchen lights 3: mood + dishwasher bright

The test button triggers a button controller which calls one of "SCENE-TOGGLE UP" or "SCENE-TOGGLE DOWN" depending on which button was pressed. The button press is received quickly, and the appropriate SCENE-TOGGLE rule starts up quickly. That SCENE-TOGGLE rule reads the current state from a hub variable, calculates the desired next state, stores that in a hub variable, and calls SCENE-SET. I see a two second delay between the parent (SCENE-TOGGLE) logging that it's about to call the child, and the child (SCENE-SET) logging its start.

SCENE-SET copies the desired next scene number from the hub variable to a local variable, and using a series of IF-THEN, ELSE-IF, ELSE tests on that local variable, it decides which "SCENE" rule to call, and calls it. Oddly, the numerical tests are taking a non-trivial amount of time to perform. And again I see a two-second start-up delay on the "Run Actions" call to the child.

I've left the following log extract in reverse chronological order just as it appears in the live log, but I've split the times to make it easier to see the seconds go by, and I've inserted asterisks where there are large delays:

  app:156 2025-01-14 20:07:   08.198 info DEBUG: END RULE: SCENE-TOGGLE: UP kitchen lights
  app:156 2025-01-14 20:07: * 08.194 info DEBUG: RETURN FROM RULE: SCENE-SET: kitchen lights per Kitchen_scene_requested
  dev:62  2025-01-14 20:07:   04.218 info Kitchen undercabinet lights (right of sink) was turned off [digital]
  dev:61  2025-01-14 20:07:   04.166 info Kitchen undercabinet lights (left of stove) was turned off [digital]
  app:157 2025-01-14 20:07:   04.146 info DEBUG: END RULE: SCENE-SET: kitchen lights per Kitchen_scene_requested
  app:157 2025-01-14 20:07:   04.141 info DEBUG: RETURN FROM RULE: SCENE: kitchen lights 0: off
  app:153 2025-01-14 20:07:   04.125 info DEBUG: END RULE: SCENE: kitchen lights 0: off
  dev:50  2025-01-14 20:07:   04.115 info Kitchen undercabinet lights (left of sink) was turned off [digital]
  app:153 2025-01-14 20:07:   04.065 info Setting scene: kitchen lights off
  app:153 2025-01-14 20:07: * 04.062 info DEBUG: START RULE: SCENE: kitchen lights 0: off
  app:157 2025-01-14 20:07: * 02.036 info DEBUG: CALLING RULE: SCENE: kitchen lights 0: off
  app:157 2025-01-14 20:06:   58.997 info Selecting scene: kitchen scene #0
  app:157 2025-01-14 20:06:   58.992 info DEBUG: END READING GLOBAL: Kitchen_scene_requested
  app:157 2025-01-14 20:06:   58.980 info DEBUG: START READING GLOBAL: Kitchen_scene_requested
  app:157 2025-01-14 20:06: * 58.976 info DEBUG: START RULE: SCENE-SET: kitchen lights per Kitchen_scene_requested
  app:156 2025-01-14 20:06:   56.915 info DEBUG: CALLING RULE: SCENE-SET: kitchen lights per Kitchen_scene_requested
  app:156 2025-01-14 20:06:   56.901 info Toggling kitchen lighting scene: 3 -> 0
  app:156 2025-01-14 20:06:   56.859 info DEBUG: START RULE: SCENE-TOGGLE: UP kitchen lights
  dev:60  2025-01-14 20:06:   56.768 info Test button button 1 (•) was pushed [physical]

Here is a sample of each type of rule:

Any insights?

Anne.

[bertabcd1234]

@anne.hubitat

C-8 Pro version 2.4.0.145

While I'm not aware of any specific changes that might affect your outcome, it's notable that you are a couple releases behind. I'd upgrade to 2.4.0.147 and see if anything changes for you, at least (a good thing to try when troubleshooting a problem on an older version).

As for your actual issue, even if it persists, I'm not sure what could be causing it. But is there a reason you're doing so much "nesting"? I didn't study your automations enough to recall what each piece does, but a Button Controller rule is nearly identical to a Rule Machine rule (they share a lot of code), and you should be able to do almost anything there that you can do in RM. This might save you some complexity and "delays." In general, a purpose-built app like Room Lighting is also going to be a bit faster than a large, general-purpose app like RM (or even BC), to name some alternatives you might consider if you haven't already. But again, can't say much about this.

@anne.hubitat

I was originally testing against a hub variable, then when I read that the oldstyle "global" variables could be slow, I changed the code to read the hub variable into a local variable

FYI, "global variables" are not "hub variables" (global variables were a Rule Machine, now Rule Machine Legacy, feature that lived in the parent app, and the only "slowness" would have resulted from the parent app needing to wake to change these values; hub variables are a platform-level feature that are more lightweight). So, this is unlikely to change anything.

[anne.hubitat]

I'd upgrade to 2.4.0.147 and see if anything changes for you,

Done, no change; I still see:

• 2 seconds for SCENE-TOGGLE to call SCENE-SET
• 3 seconds to traverse the IF tests in SCENE-SET
• 2 seconds for SCENE-SET to call SCENE 0
• 4 seconds to return from SCENE-SET to SCENE-TOGGLE

"global variables" are not "hub variables" [...] hub variables are a platform-level feature that are more lightweight). So, this is unlikely to change anything.

As indeed it didn't when I switched, and as you may have noticed from my debug log lines, I timed the access to the hub variable, and the time was very short. That's good in that it means I can use hub variables without worrying about performance, and bad in that it doesn't solve my problem.

But is there a reason you're doing so much "nesting"?

Because it's there? Seriously, as a coder I'm used to encapsulating functionality in subroutines both to keep the code clean and readable, and to make as much of it reusable as possible. It never occurred to me that there'd be such a huge performance penalty for (a) nesting, and (b) a series of IF-THEN statements.

If possible I'd still like to confirm with someone knowledgeable about the O/S implementation whether multi-second delays for nested calls are expected, and whether the slow (IMHO) performance of a series of IF-THEN statements is expected. I can try some other approaches for the current problem, but I'd like to understand the trade-offs.

In general, a purpose-built app like Room Lighting is also going to be a bit faster than a large, general-purpose app like RM (or even BC),

Okay, I took a look at Room Lighting, and I had previously looked at Scenes. My problem with them is that they keep no state, and if I want to cycle through scenes, I do need to keep state (the "scene number"). In the absence of data structures in the "actions language" (such as an associative array where I could keep a list of scenes), I thought to keep the current state and the desired next state in "number"-type hub variables, and write a single "subroutine" (RM rule) that would map the desired state number to a scene implemented by another rule, which would update the current state after performing the lighting changes.

Yes, I could save two seconds by moving the "toggle " code up into the BC directly, and another two seconds if I replace the "set" rules with Scenes (or Room Lighting scenes) and put the state change into the (current) "middle" rule, but it would still take three seconds to traverse the IF-THEN code that maps the desired scene number to the actual scene, which is nuts.

Another post has given me the idea of using a virtual button device to map state numbers (button numbers) to scenes, but that will help only if I can code pressing a virtual button whose number I calculate; I'll give that a shot.

[a.mcdear]

I am seeing similar delay when performing actions on the Private Boolean of another rule. Hubitat couldn't duplicate my issue. I suspect I have some sort of unrecoverable corruption relating to these rules that I can't seem to detect. My next course of action is to rebuild all these rules from scratch, but I haven't had the time to devote to that task yet..

I posted about it in the beta forum under Built-in Apps section. I'm not sure if I can link to a post in the beta forum.

[bertabcd1234]

@anne.hubitat

if I want to cycle through scenes, I

Are you, by any chance, trying to do the same thing I wrote this custom app to solve? Maybe it would work for you, too:

[RELEASE] Dimmer Button Controller (configure Pico to emulate Hue Dimmer or any button device to easily control lights)

Inspired by this thread and this post in particular, I have created an app that (I think) easily allows button devices to be configured to control bulbs, switches, and dimmers. This app allows you to: choose a button device (I wrote this with 5-button Picos with the "fast Pico" driver in mind and expanded it to work with the "held" events from the Osram/Lightify dimmer and later the "double tapped" events from other devices, but any button device should work) choose one or more bulbs/dimmers o…

@a.mcdear

I'm not sure if I can link to a post in the beta forum.

You can link, but the post will only be accessible if you have access to that category in the forum.

[mattias]

@a.mcdear

I am seeing similar delay when performing actions on the Private Boolean of another rule. Hubitat couldn't duplicate my issue.

I just set up a quick test on my hub and I could immediately replicate your issue. I have two RM 5.1 rules - “Test Rule 1” and “Test Rule 2”. Rule 1 just calls rule 2 and rule 2 sets the private Boolean of rule 1 a couple of times:

What I found was that when running rule 2 it would take it just over 1 second to set the Private Boolean of rule 1.

But, if I ran rule 1 which in turn calls rule 2, then the Private Boolean operation took over 3 seconds to run!

@anne.hubitat As you can see in my log, I was unable to replicate your delay when calling a rule from another, however, I will try to replicate your if else issue. I’m just going to move from doing this on my phone (which is slow and tedious) to starting my laptop

[anne.hubitat]

@mattias

As you can see in my log, I was unable to replicate your delay when calling a rule from another, however, I will try to replicate your if else issue.

Thanks for working on this, @mattias! With respect to delays when calling a rule, it would be helpful if in rule 1 you could log "about to call" and "returned from calling" rule 2. I look forward to learning more about your results.

[anne.hubitat]

@bertabcd1234

Are you, by any chance, trying to do the same thing I wrote this custom app to solve? Maybe it would work for you, too:

If I understand your description correctly, I'm trying to do something similar. What I'm trying to code is a system that remembers the current state (in terms of "scene number for last scene we set"), and where each button press advances through a bunch of scenes, cycling back to the first after the last one is reached. In my scenario, each button press results in a change of lighting, and also, a further button press some time later carries on from that point.

My understanding of your description is that rather than storing the state long-term, you count the number of presses that occur together within a certain timeout, and once the timeout expires, then you activate the scene corresponding to that number of presses. Is that right?

That's a bit different, but it could work for me. I'll give it some thought.

If I use a button device that's capable of sending doubleTaps, I assume that I have to perform the multiple presses more slowly than the doubleTap timeout but fast enough for your timeout, correct? (Or use a non-doubleTap capable button for this purpose.)

[mattias]

Sure. I’ve done that and rule 1 now looks like this:

Rule 2 is unchanged from above. Running this shows that it takes HE 2 seconds to resume rule 1 from the time rule 2 has finished running.

So, in all, it takes RM 5.1 over 10 seconds to call one rule from another, set another Private Boolean twice and then return to the original rule. Doesn’t sound right, does it?

[anne.hubitat]

@mattias

Running this shows that it takes HE 2 seconds to resume rule 1 from the time rule 2 has finished running.

Your screenshot is missing the log line "About to call test rule 2"; can you show that one, please?

[mattias]

Sorry about that. I was still on my phone and couldn't fit more lines onto the screen. I've replaced the log entry in my post above with the full one now

[mattias]

@a.mcdear I'm pretty sure I saw your post about these delays the other day, but I cannot find it now (I haven't got access to the Beta section). If my memory serves me right, you were saying that these delays were not there in 2.3.9. Well, I think you're right. I created the same test rules 1 and 2 on a 2.3.9.200 hub and I have very small delays on that version for the same test:

[anne.hubitat]

A few hours ago I wrote:

Another post has given me the idea of using a virtual button device to map state numbers (button numbers) to scenes, but that will help only if I can code pressing a virtual button whose number I calculate; I'll give that a shot.

Nope; sadly when I set up a button press action, I must submit an actual number for the number of the button to press; there's no way to refer to a variable there.

So (aside from coding an app or using the one proposed by @bertabcd1234), I have to use an IF-THEN sequence to map a state to an action. Interestingly, I just created a very minimal example, and it runs instantaneously. I made a three-button virtual button whose actions change a light's colour between red (button 1), green (button 2), and blue (button 3), and a button controller on a physical button so that doubleTaps advance/cycle the scene number in a local variable and then an IF-THEN sequence sends the appropriate button press to the virtual button.

No hub variables, no nested calls, no logging, but instant response. I'm going to try slowly modifying this towards what I want, and see where it bogs down, or if I can get all the effects I want without slowing it down appreciably.

[anne.hubitat]

@mattias

I've replaced the log entry in my post above with the full one now

So there's no delay between the caller calling the rule, and the child rule running, but you do get a 2-second delay on the return to the parent rule. Interesting.

My tests showed no delay between the button press and the first rule called (from the button controller), but delays upon further nested calls. Would you be willing to add a nesting level (rule 3 called from rule 2) with the same call-and-return and rule start-and-end logging, and see whether an additional nesting level triggers the start delay?

[bertabcd1234]

@anne.hubitat

My understanding of your description is that rather than storing the state long-term, you count the number of presses that occur together within a certain timeout, and once the timeout expires, then you activate the scene corresponding to that number of presses. Is that right?

Sounds like you've got it right. The intent was to emulate the behavior of the Hue Dimmer (which I was used to; the "On" or "1" button on the original model and the scene button on the second generation), and this is how that works.

@anne.hubitat

If I use a button device that's capable of sending doubleTaps, I assume that I have to perform the multiple presses more slowly than the doubleTap timeout but fast enough for your timeout, correct? (Or use a non-doubleTap capable button for this purpose.)

Yes, or you can set up the doubleTapped event in the app if you want to actually use it, too.

[a.mcdear]

@mattias

. If my memory serves me right, you were saying that these delays were not there in 2.3.9. Well, I think you're right. I created the same test rules 1 and 2 on a 2.3.9.200 hub and I have very small delays on that version for the same test:

No, I don't think it happened on 2.3.9. I did 2 things the day after Xmas: I migrated from C-5 to C-8 Pro and I upgraded to 2.4.0 on the same day. I started actually noticing the delay/lag in automations a couple days after being on 2.4.0. I can replicate the same lag when processing Booleans on other rules on both hubs, both on 2.4.0 now.

I'll copy and paste my OP from the beta section to here when I get home to a PC. Maybe it will help us figure it out together.

[anne.hubitat]

(i.e. choirs of angels!!!!)

Today I wrote:

Another post has given me the idea of using a virtual button device to map state numbers (button numbers) to scenes, but that will help only if I can code pressing a virtual button whose number I calculate; I'll give that a shot.

and then:

Nope; sadly when I set up a button press action, I must submit an actual number for the number of the button to press; there's no way to refer to a variable there.

Well, this post shows how to do the equivalent:

Button Push with Variables

mluckGives Back

Sep 2020

TL;DR It appears that a Button Push in RM4 won't take a variable as its button number. Is that correct? If so, is there a workaround?
[rest removed]

ogiewonAmbassador

Sep 2020

Instead of using RM’s Button push or held action, try using a Custom Action to call the virtual button device’s push() or hold() command, as you should be able to pass in an argument to those commands this way.
[rest removed]

It works! I can now dispense with the ludicrous series of IF-THEN statements to match a number variable to a scene, and use the virtual device as an associative array.

[mattias]

@anne.hubitat

Would you be willing to add a nesting level (rule 3 called from rule 2) with the same call-and-return and rule start-and-end logging, and see whether an additional nesting level triggers the start delay?

Done. I've run these tests several times and the delays seem to be consistent. However, the delays jumping through the nesting is not consistent from rule to rule. That is, calling rule 2 from rule 1 is almost instant, but calling rule 3 from rule 2 takes about 1 second. Then returning from rule 3 to rule 2 is almost instant but returning from rule 2 to rule 1 takes 3 seconds.

So the rules I have now are:
Rule 1: Call Rule 2
Rule 2: Set the private boolean of rule 1 to false then true and then call rule 3
Rule 3: Run through an IF/ELSE statement using a local variable

It takes over 13 seconds to run this sequence on 2.4.0.147 (C8) compared to 300ms on 2.3.9.200 (C5).

2.4.0.147 logs:

2.3.9.200 logs:

So, unable to replicate your issue with IF/ELSE @anne.hubitat, but there is definitely something fishy going on either with C5 vs C8 or 2.3.9 vs 2.4.0 when it comes to calling other RM rules or performing private boolean operations on other rules @a.mcdear @bravenel

Edit: I created and ran the same rules on a C7 2.3.9.200 as well, and that one took 350ms to run through the whole sequence. So maybe it is more pointing towards a change that was introduced with 2.4.0 rather than with C8.

[anne.hubitat]

@mattias

I've run these tests several times and the delays seem to be consistent. [...] That is, calling rule 2 from rule 1 is almost instant, but calling rule 3 from rule 2 takes about 1 second. Then returning from rule 3 to rule 2 is almost instant but returning from rule 2 to rule 1 takes 3 seconds.

I think there's pattern here, though I'm not sure exactly what it is. Clearly the size of the delays is related to the number of nesting levels. If I number my rules as:

1. Button controller
2. SCENE-TOGGLE
3. SCENE-SET
4. SCENE 0

(where 1 calls 2 calls 3 calls 4), then I see:

• 1 -> 2: no delay
• 2 -> 3: 2-second delay
• 3-> 4: 2-second delay
• return from 4 to 3: no delay
• return from 3 to 2: 4 seconds
• return from 2 to 1: no delay

It takes over 13 seconds to run this sequence on 2.4.0.147 (C8) compared to 300ms on 2.3.9.200 (C5).

That's insane! Thank you so much, @mattias, for doing the work to replicate the delays, and nailing it down to the OS revision.

[bravenel]

I'm going to look into one aspect of RM's internal plumbing for Run Actions. I suspect it could be improved. I don't know if this would impact this or not, but it seems worth a shot.