Annoying delay in turning on light with motion

AustinA · 2020-08-06 01:56:06 UTC

1) Give a description of the problem
I am trying to turn on a Zooz Zen22 V3 dimmer with a motion sensor at a dim setting based on the time of day via a SmartThings hub. The piston works reliably but it takes a little over 1 second from when you trigger the motion sensor and it blinks to when the light comes on. I am using a cloud DTH for the Zooz dimmer and a generic local DTH for the motion sensor.

When I keep everything the same but assign the piston’s actions to a HomeSeer WD-200+ dimmer using a cloud DTH in the same room, I get a much faster response (.SetLevel delays typically less than 100ms).

2) What is the expected behaviour?
I would like the light to come on in around 200ms so the delay is much less noticeable.

3) What is happening/not happening?
The piston works correctly, but there is an unexpected ~800ms delay when the dimmer.setlevel command is executed

**4) Post a Green Snapshot of the piston!

5) Attach logs after turning logging level to Full
8/5/2020, 8:20:29 PM +114ms
+1ms ╔Received event [Main Bath Motion Zooz ZSE18].motion = active with a delay of 73ms
+64ms ║RunTime Analysis CS > 21ms > PS > 6ms > PE > 37ms > CE
+67ms ║Runtime (41622 bytes) successfully initialized in 6ms (v0.3.110.20191009) (65ms)
+68ms ║╔Execution stage started
+75ms ║║Comparison (enum) active changes_to (string) active = true (1ms)
+77ms ║║Cancelling condition #2’s schedules…
+78ms ║║Condition #2 evaluated true (5ms)
+86ms ║║Comparison (enum) off is (string) off = true (1ms)
+87ms ║║Condition #3 evaluated true (9ms)
+88ms ║║Cancelling condition #1’s schedules…
+89ms ║║Condition group #1 evaluated true (state changed) (17ms)
+127ms ║║Comparison (time) 73229205 is_between (time) 1596676260000 … (time) 1596627840000 = false (9ms)
+129ms ║║Condition #16 evaluated false (38ms)
+130ms ║║Condition group #4 evaluated false (state did not change) (39ms)
+132ms ║║Cancelling statement #5’s schedules…
+834ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([100]) (698ms)
+835ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (700ms)
+843ms ║║Comparison (enum) active stays (string) inactive = false (2ms)
+845ms ║║Cancelling any timed trigger schedules for condition 12
+846ms ║║Cancelling statement #12’s schedules…
+847ms ║║Condition #12 evaluated false (7ms)
+848ms ║║Condition group #11 evaluated false (state did not change) (9ms)
+855ms ║║Comparison (enum) on is (string) off = false (2ms)
+856ms ║║Cancelling condition #25’s schedules…
+857ms ║║Condition #25 evaluated false (7ms)
+858ms ║║Condition group #20 evaluated false (state did not change) (8ms)
+861ms ║╚Execution stage complete. (793ms)
+862ms ╚Event processed successfully (862ms)

WCmore · 2020-08-06 02:21:16 UTC

Not sure why it took 704ms to process that command…

+130ms ║║Condition group #4 evaluated false (state did not change) 
+834ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([100])

It is usually under 100ms for this. Perhaps your home network had a lot of chatter at the time?

AustinA · 2020-08-06 03:22:30 UTC

When you say home network chatter are you talking about the Z Wave network or my LAN/internet network?

The process time seems to be pretty consistent for that device’s .setLevel command around the 650-850ms range.

Here is another example I just took that shows a similar amount of time for the first .setLevel command to process:

8/5/2020, 10:15:03 PM +926ms
+2ms ╔Received event [Main Bath Motion Zooz ZSE18].motion = active with a delay of 71ms
+85ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 5ms &gt; PE &gt; 57ms &gt; CE
+88ms ║Runtime (41615 bytes) successfully initialized in 5ms (v0.3.110.20191009) (85ms)
+89ms ║╔Execution stage started
+96ms ║║Comparison (enum) active changes_to (string) active = true (0ms)
+98ms ║║Cancelling condition #2's schedules...
+98ms ║║Condition #2 evaluated true (5ms)
+105ms ║║Comparison (enum) off is (string) off = true (1ms)
+107ms ║║Cancelling condition #3's schedules...
+108ms ║║Condition #3 evaluated true (8ms)
+108ms ║║Cancelling condition #1's schedules...
+109ms ║║Condition group #1 evaluated true (state changed) (17ms)
+151ms ║║Comparison (time) 80104037 is_between (time) 1596676260000 .. (time) 1596627840000 = true (10ms)
+152ms ║║Time restriction check passed
+154ms ║║Condition #16 evaluated true (43ms)
+155ms ║║Condition group #4 evaluated true (state did not change) (44ms)
+157ms ║║Cancelling statement #8's schedules...
+889ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([12]) (728ms)
+890ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (730ms)
+893ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (1ms)
+894ms ║║Waiting for 1000ms
+1936ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([7]) (38ms)
+1937ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (40ms)
+1944ms ║║Comparison (enum) active stays (string) inactive = false (1ms)
+1946ms ║║Cancelling any timed trigger schedules for condition 12
+1947ms ║║Cancelling statement #12's schedules...
+1948ms ║║Cancelling condition #12's schedules...
+1949ms ║║Condition #12 evaluated false (8ms)
+1949ms ║║Cancelling condition #11's schedules...
+1950ms ║║Condition group #11 evaluated false (state changed) (10ms)
+1957ms ║║Comparison (enum) on is (string) off = false (1ms)
+1959ms ║║Condition #25 evaluated false (6ms)
+1960ms ║║Condition group #20 evaluated false (state did not change) (7ms)
+1962ms ║╚Execution stage complete. (1873ms)
+1963ms ╚Event processed successfully (1962ms)

I have a few other Zooz Zen22 dimmers using the same DTH that are typically better about this, usually in the 100-200ms range, but sometimes they do all have a longer delay ~700ms like this one does consistently. The other dimmers I have (HomeSeer) do not seem to ever have this problem and process their commands in less than 100ms every time.

WCmore · 2020-08-06 04:08:38 UTC

I re-read your original post:

To help pinpoint the ‘weakest link’, you can make a new test piston.
This one focuses on just the dimmer. Something like:

execute
    with
        Dimmer 4
    do
        set level to 18%
        wait 1 sec
        set level to 41%
        wait 1 sec
        set level to 23%
    END WITH
END EXECUTE

Turn Log Level to Full, and press Test.
This totally removes all elements except the final commands.
We can compare the ms in the log to better see what is going on.

Note: If you have any other pistons that are triggering on Dimmer 4’s level changes,
I would pause those pistons before testing.

If this new log is all that same crappy delay, (an acceptable delay would be 1100 ms or less), my first thought is to try a different DH for the dimmer… but before you do that, read on…

This bit sounds like it could be location, location, location… LOL

Perhaps that one slow device is going thru extra Mesh hops trying to get data to/from the hub.

Can you relocate the dimmer closer to the hub, and give it a few tests to see if it learns a better Mesh path? (I would allow +30 minutes, with at least a dozen button presses during that time)

This bit sounds like a Device Handler (or network chatter) issue…

I am not for sure on the Zooz, specifically… but there are some device handlers that are a bit slow to respond and/or reply back to the hub. It is often seen on devices that were originally meant to work with proprietary software (in house app)… but then later on, the CEO decided to try to connect their device with other brands. (meaning the ‘in house’ data transfer will be more responsive, with more capabilities, with the ST access added as an after thought)

I mean everything that passes data over the same modem/router. All computers, tablets, phones on WiFi, Roku, RPi, CCTV cams, Xbox/PlayStation, Voice over IP telephones, Smart TVs, Kodi, Netflix, Hulu… The list goes on and on… Now, in all honesty, some online devices hardly pass any data (IE: smart dishwasher)… but some devices like a gaming console or CCTV can pass GB worth of data in a very short period of time. Heck, even a cellphone with auto update can easily śuck half of my bandwidth, if I allowed it. (One reason why I always disable auto-updates)

… and, just so I leave no stone uncovered…

I do not know which DH you are using, but keep in mind that there are many device handlers that are made by regular Joes… Like you and me. They saw a need, and gave it their best to create a solution. I tip my hat to them, but as always, no programming is ever perfect. Often, on popular devices, a mini-community forms around certain brand names, while the ‘locals’ work together to improve the DH capabilities even further. Seeking out the specific forum for that handler is usually one of the first steps I take with 3rd party DHs.

TL;DR

In your case, it’s probably the mesh network (location), and/or the device handler.
If other devices start responding slowly as well, then I would look towards network chatter.

AustinA · 2020-08-11 23:26:26 UTC

WCmore,

Thank you so much for the thoughtful and through reply.

Per your recommendation I went ahead and created a simple test piston to send the set level command, wait 1s, send another, wait 1s, and then send a final set level. Here are the logs from that:

8/11/2020, 5:01:44 PM +30ms
+1ms ╔Received event [Arnett Home].test = 1597183304029 with a delay of 0ms
+49ms ║RunTime Analysis CS &gt; 23ms &gt; PS &gt; 6ms &gt; PE &gt; 20ms &gt; CE
+52ms ║Runtime (36261 bytes) successfully initialized in 6ms (v0.3.110.20191009) (50ms)
+53ms ║╔Execution stage started
+59ms ║║Cancelling statement #5's schedules...
+861ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([100]) (793ms)
+926ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (858ms)
+930ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (1ms)
+932ms ║║Waiting for 1000ms
+2010ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([50]) (72ms)
+2011ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (73ms)
+2015ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (1ms)
+2016ms ║║Waiting for 1000ms
+3092ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([20]) (72ms)
+3094ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (74ms)
+3099ms ║╚Execution stage complete. (3046ms)
+3101ms ╚Event processed successfully (3101ms)
8/11/2020, 5:00:17 PM +523ms
+0ms ╔Received event [Arnett Home].test = 1597183217522 with a delay of 1ms
+47ms ║RunTime Analysis CS &gt; 25ms &gt; PS &gt; 6ms &gt; PE &gt; 15ms &gt; CE
+50ms ║Runtime (36261 bytes) successfully initialized in 6ms (v0.3.110.20191009) (49ms)
+51ms ║╔Execution stage started
+56ms ║║Cancelling statement #5's schedules...
+240ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([100]) (175ms)
+242ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (177ms)
+245ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (0ms)
+246ms ║║Waiting for 1000ms
+1322ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([50]) (72ms)
+1323ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (73ms)
+1327ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (1ms)
+1329ms ║║Waiting for 1000ms
+2399ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([20]) (65ms)
+2400ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (68ms)
+2405ms ║╚Execution stage complete. (2353ms)
+2406ms ╚Event processed successfully (2406ms)
8/11/2020, 4:59:40 PM +257ms
+0ms ╔Received event [Arnett Home].test = 1597183180256 with a delay of 0ms
+49ms ║RunTime Analysis CS &gt; 24ms &gt; PS &gt; 6ms &gt; PE &gt; 20ms &gt; CE
+51ms ║Runtime (36253 bytes) successfully initialized in 6ms (v0.3.110.20191009) (50ms)
+53ms ║╔Execution stage started
+57ms ║║Cancelling statement #5's schedules...
+756ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([100]) (692ms)
+758ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (693ms)
+761ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (1ms)
+762ms ║║Waiting for 1000ms
+1829ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([50]) (61ms)
+1831ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (63ms)
+1834ms ║║Executed virtual command [Main Bath Overhead Dimmer Zooz Zen22].wait (1ms)
+1835ms ║║Waiting for 1000ms
+2897ms ║║Executed physical command [Main Bath Overhead Dimmer Zooz Zen22].setLevel([20]) (57ms)
+2898ms ║║Executed [Main Bath Overhead Dimmer Zooz Zen22].setLevel (60ms)
+2903ms ║╚Execution stage complete. (2850ms)
+2904ms ╚Event processed successfully (2904ms)

As you can see, on the first and third tests there was a pretty long delay in the first set level command and the following 2 commands in each test were pretty fast. The second test followed the same trend but didn’t have as long of a delay on the first set level command.

I then tried another dimmer of the same type and DTH that is much closer to the hub (~3’ through a wall) and it showed a very similar behavior. Finally, I tried a different brand of dimmer I have that is also using a custom (cloud) DTH and got similar results (typically not as much delay but occasionally >500ms and inconsistent).

Finally I switched the dimmer to the generic DTH so it would run local. Once I did this, I got consistent results for the set level command in the 15ms or so range, much faster and makes my automation useful again. I put my motion based piston back into service and it ran so much faster.

Is there a reason my cloud DTH are so slow? I have Gig fiber from AT&T and the hub is plugged into the router via hardwired ethernet cable. I don’t have a lot of issues with speed or congestion on my home LAN and don’t have a large amount of wifi or ethernet devices. Any suggestions or troubleshooting tips on slow cloud DTH?

WCmore · 2020-08-11 23:55:17 UTC

Let’s take a closer look at the key elements of your log:

4:59:40 PM

0.756 = 1st command = 0.699 sec to process = Kind of long, but not horrible
1.829 = 2nd command = 0.073 sec to process = acceptable
2.897 = 3rd command = 0.068 sec to process = acceptable

5:00:17 PM

0.240 = 1st command = 0.184 sec to process = somewhat acceptable
1.322 = 2nd command = 0.082 sec to process = acceptable
2.399 = 3rd command = 0.077 sec to process = acceptable

5:01:44 PM

0.861 = 1st command = 0.802 sec to process = Kind of long, but not horrible
2.010 = 2nd command = 0.149 sec to process = somewhat acceptable
3.092 = 3rd command = 0.082 sec to process = acceptable

(Note: In the ‘process’ column, I subtracted 1000 ms for each WAIT)

From these three tests, it appears that it takes about 0.6 seconds for the device path to “wake up”, but then all subsequent commands are fairly fast (for a custom handler).

As with all things network related, it only takes one slow link to affect the speed of the entire path.
(although, with all the delays at the beginning, it could also be an authorization/connection delay)