[Solved] Hub slowness/delays in rule processing and web UI

Collisionc · November 4, 2018, 5:59am

So I finally got my hubitat system setup after sitting in the box waiting for multiple hue bridge support (Thanks! ) , and I'm having some very odd response time problems with simple lighting.

I'm running all stock drivers/apps at the moment, with the following apps enabled/used:

Amazon Echo Skill
Hubitat Simple Lighting
-- 16 different rules setup under this.
-- Most rules are "When door opens, turn on lights, and then turn them off when the door shuts."
Hue Bridge Integration - 45 lights hooked up to this hub
Hue Bridge Integration - 40 lights hooked up to this hub
Life360 Connector
Sonos Integration

Devices currently hooked up:
Generic Z-Wave Motion Sensor - Enerwave Ceiling Mounted
Generic Z-Wave Switch - x2 GE + 1 Fortrezz MIMO for toggling fireplace
Generic Zigbee Dimmer - x2 GE/Jasco
Generic Zigbee Moisture Sensor - x1 - Samsung
Generic Zigbee Outlet - x2 Centralite Smart Outlet + x3 Samsung 2017 outlets
Generic Zigbee Switch - x24 GE/Jasco
hueBridgeBulb RGBW - x11 bulbs (mostly control hue through groups)
hueBridgeGroup - x23 groups
SmartSense Multi Sensor V4 - x5 2015 models x11 2016 models
Sonos Player - x3
Virtual Presence - x2 life360

Here's what my RF frequency usage looks like right now...

Being the good neighbor that I am, I offered to help my neighbor setup his internet/wifi and stuck him on channel 11 at 20 mhz rather than the auto-channel 40 mhz bullshit that the ISP sets up by default.

The problem: 20-30% of the time when I open a door, the lights do not immediately turn on. The delay for the lights turning on can be anywhere from 2-13 seconds, which is just enough to be annoying.

Logs show the following when this occurs:
Example 1: 2.4 seconds for lights to turn on

dev:3532018-11-04 00:45:05.565 info garage light switch was turned on [digital]
app:1962018-11-04 00:45:04.149 info Turn On garage light switch when Garage Door 1, garage door 2, Garage Entry Door Opened Turn On
dev:2542018-11-04 00:45:04.022 info Garage Entry Door battery is 90%
dev:2542018-11-04 00:45:03.196 info Garage Entry Door was opened

Example 2: 6~ seconds for lights to turn on

    dev:2462018-11-03 23:59:06.083 info Group Office was turned on
    app:2052018-11-03 23:59:05.840 info Turn On Office when Office Multi Opened Turn On
    dev:2502018-11-03 23:59:03.472 info Office Multi is [x:18,y:1023,z:32]
    dev:2502018-11-03 23:59:03.466 info Office Multi is [x:27,y:1020,z:30]
    dev:2502018-11-03 23:59:00.277 info Office Multi is [x:26,y:1024,z:28]
    dev:2502018-11-03 23:59:00.168 info Office Multi was opened

Example 3: 8 seconds for lights to turn on

dev:2382018-11-03 23:57:18.564 info Group Stairs was turned on
app:2252018-11-03 23:57:13.118 info Turn On Stairs when Server Closet Opened Turn On
dev:2522018-11-03 23:57:10.078 info Server Closet was opened

Example 4: 13! seconds for lights to turn on

dev:4262018-11-03 23:50:15.468 info Pantry lightstrip was turned on
dev:2572018-11-03 23:50:15.025 info Pantry Door is [x:27,y:-1024,z:22]
dev:2572018-11-03 23:50:15.024 info Pantry Door is inactive
app:1942018-11-03 23:50:10.886 info Turn On Pantry lightstrip when Pantry Door Opened Turn On
dev:2572018-11-03 23:50:10.669 info Pantry Door is [x:37,y:-1021,z:24]
dev:2572018-11-03 23:50:09.667 info Pantry Door is [x:38,y:-1017,z:25]
dev:2572018-11-03 23:50:08.892 info Pantry Door is [x:130,y:-1018,z:33]
dev:2572018-11-03 23:50:08.599 info Pantry Door is [x:-9,y:-1019,z:13]
dev:2572018-11-03 23:50:08.239 info Pantry Door is [x:17,y:-1020,z:28]
dev:2572018-11-03 23:50:06.123 info Pantry Door is [x:29,y:-1017,z:26]
dev:2572018-11-03 23:50:05.990 info Pantry Door is [x:8,y:-1024,z:33]
dev:2572018-11-03 23:50:05.713 info Pantry Door is [x:53,y:-1021,z:24]
dev:2572018-11-03 23:50:05.652 info Pantry Door is [x:-11,y:-1018,z:91]
dev:2572018-11-03 23:50:02.940 info Pantry Door is [x:224,y:-1018,z:52]
dev:2572018-11-03 23:50:02.925 info Pantry Door is active
dev:2572018-11-03 23:50:02.827 info Pantry Door was opened

Example 5 - 7 seconds of latency in between the sensor telling hubitat that the door is open until hubitat realizes that the door was opened so it needs to send a command for the entry light group to turn on.

dev:2292018-11-04 01:41:21.371:infoGroup Entry was turned on
dev:2292018-11-04 01:41:21.369:infoGroup Entry was turned on
app:2302018-11-04 01:41:21.157:infoTurn On Entry when Front Door Opened Turn On
app:1972018-11-04 01:41:21.155:infoTurn On Entry when Front Door Opened Turn On
dev:2532018-11-04 01:41:14.184:infoFront Door was opened

With ST hub these same rules were near-instant (<1 second) 99% of the time even though I was running a custom driver for the hue lights which forced it to run on cloud processing.

Naturally when their servers are down the rules didn't work at all, but with the local rules such as my garage entry door turning on the zigbee light switch for the non-hue garage light, the light was turning on so quickly it made me think that the light was never turned off, even though it had been.

I've done some searching on here and found a few related threads such as: Slow Lighting Response Times - but the issue here is not the zigbee mesh as the sensors are nearly immediately reporting doors being opened to the hub. After this information has been sent to the hub, it is taking far too long for it to process that input and react to a rule.

Any ideas? I'm 100% willing to help troubleshoot, I've got a Digi XU-Z11 stick as seen on FAQ: Mapping your ZigBee network with Digi's XCTU - FAQ - SmartThings Community and have a SDR device for troubleshooting possible RF interference.

Thanks!

Cobra · November 4, 2018, 10:21am

Ok, a couple of things here
I would not rely too much on the log timings as things like: ‘the light has turned on’ may only be reported once the light has ‘told’ the hub it is on.
I actually use one automation that relies on a hue bulb telling the hub it is on.
I can watch the light coming on but it can take 5 seconds before it reports this correctly to the hub and runs the automation.
So,
1st things 1st.
The device page of one of the ‘slow’ bulbs
If you turn it on/off from there is the response the same or is it quicker?

If it is instantaneous (or near) then it points to the app or configuration being wrong.
If it is slow here too then the app is probably ok but it’s either a driver issue or possibly a network issue (lan or zigbee)

When you are troubleshooting an issue like this it’s best to start with the basics before going too far.

Edit: Looking at your graphic.. Am I right in saying that you have ST on channel 25 and Hubita on channel 26?

Andy

Collisionc · November 4, 2018, 3:08pm

Yes, ST on 25 and Hubitat on 26. I will eventually remove ST, but for now it still has a few devices that aren't supported on Hubitat. I have tried unplugging the ST hub to see if it made a difference, and it did not.

If I turn it on/off manually it is much quicker. Just in case it matters -- The Garage Light Switch is a Z-wave Plus GE switch and it has the same random delays that my hue bulbs have randomly.

Thanks

Cobra · November 4, 2018, 3:37pm

There has been some suggestions that Zigbee devices don’t work so well on channel 26 and that lower channels work better.
Mine is on 21 and I have no problems
Most people seem to put the Hubitat hub on 20/21 it seems

If you find that within the device page it switches on/off quickly and reliably then it less likely to be your zigbee network and more likely to be the app or the way that it is configured.

I personally don’t use simple lighting (never have) so can’t really comment on the way you have it configured.

I would reach out to @bravenel or @patrick (tagging them for advice)
Or contact support for advice on the best configuration.

One thing that we all expect (and mostly get) is pretty much instant response with hue lighting connected to Hubitat so if you have long response delays it is unusual and should be investigeted.
Support have access to logs that we don’t so may be the best port of call for this issue.

Andy

patrick · November 4, 2018, 3:49pm

Congrats on have a big zigbee system. Troubleshooting zigbee issues can be a challenge.

First, I don't recommend using Zigbee channel 26, ideally 25 is the best (not surprising ST picked it). Since it has no overlap with wifi. As long as your ST hub and hubitat hub are far enough apart 3-6ft or more, you can have them both on 25. Or you can pick another channel for Hubitat for now.

The unknown here is what is causing the delay. So we need to isolate what's going on.

The delays you are mentioning could be from a variety of things. Two different meshes, two different command queues, etc. LAN (to both Hue bridges) and Zigbee.

Let's isolate the Hue bridges with some test rules and virtual switches. Remove zigbee from the equation for the time being and lets make sure there isn't an issue with the large amount of bulbs (and data we have to process each refresh / poll) on each hue bridge.

Set up a similar rule that turns on / off your hue bulbs using virtual switches and see if you see the delays.

Assuming this isn't the issue... We can do the same thing for Zigbee. Setup virtual devices and test the other side.

Assuming both tests work, then we have to then look at what's going on between them.

My guess is you have 1 or more zigbee devices that aren't responding causing the queue to back up somewhere waiting for the request to time out.

Collisionc · November 4, 2018, 11:35pm

I swapped hubitat over to channel 25 and disconnected the ST hub for testing.

Ok, setup a virtual switch that turns on/off the hue light group in my office. Turned it on/off every 10 seconds until it hit a noticeable delay:

dev:2462018-11-04 18:17:23.672 info Group Office was turned off
app:2432018-11-04 18:17:13.160 info Turn On Office when Huetest  turns on anti-Turn On
dev:4492018-11-04 18:17:06.894 info Huetest  was turned off

I then changed the rule to turn on/off a GE Zigbee Switch in the bathroom.

dev:2772018-11-04 18:22:16.781:infoDownstairs Bathroom Light Switch was turned on
app:2432018-11-04 18:22:13.908:infoTurn On Downstairs Bathroom Light Switch when Huetest  turns on Turn On
dev:4492018-11-04 18:22:07.289:infoHuetest  was turned on

So in this case, both tests fail? As far as the responsiveness goes, I can click the button on/off 10 times in a row for 15-20 seconds and it'll instantly turn on/off the devices in question, but then on the 11th click it feels as if the CPU gets hit with some large task that requires a few seconds to process before getting to checking the rules and turning on/off the light.

If it helps at all, the web interface for the hubitat also has periods where it will stall and not go to a page for a few seconds after being clicked.

How often does hubitat poll the hue bridges? If it's somewhere around 20 seconds that might be it if it's polling both bridges at the same time. Also, when I look at my device list, the only 2 inactive/"offline" devices are my hue bridges.

Collisionc · November 5, 2018, 3:06am

After doing some refreshing/F5 at the /device/list page and checking "Last Activity" for the hue bulbs/groups, the slowdown occurs everytime one of the bridges is refreshed so that the groups last activity time is updated.

The json response (once formatted all nice and pretty) is nearly 4900 lines long when doing a refresh command on one of my hubs. Without knowing how things are programmed inside the hubitat, my guess is that it is choking on large json responses from the hue bridges.

Collisionc · November 6, 2018, 12:41am

Ok, after doing a little more testing, it's definitely the refresh on the hue bridges that is causing problems. I removed one of the bridges, paused all rules except for 1 where the virtual button turns on a non-hue light switch, and the delay now happens less often, but every 60 seconds there is a 5 second period where all rules are effectively on hold while the hub is parsing the hue refresh.

Adding the 2nd bridge increases this 5 second period to 10~ seconds, and kinda randomizes when the lag happens.

I'm going to strip out all apps (not devices other than hue, because yeah... that's a pain), remove both bridges, re-add them and see if anything changes.

patrick · November 6, 2018, 12:44am

Our next release will have a change to groups that should solve this issue.

patrick · November 6, 2018, 1:14am

Just to follow up, if you avoid using hue groups in rules, you should see an improvement. Not ideal, but should improve performance.

Collisionc · November 6, 2018, 1:55am

Thanks! Glad to hear it.

Collisionc · November 13, 2018, 11:04pm

The 2.0 release doesn't seem to have resolved this.

ex:
dev:2342018-11-13 05:58:12.338 pm infoGroup Laundry was turned off
app:2562018-11-13 05:58:09.681 pm infoTurn On Laundry when Laundry Room Door Opened anti-Turn On
dev:2622018-11-13 05:58:02.687 pm infoLaundry Room Door was closed

patrick · November 13, 2018, 11:40pm

Ok, well, we will need to dig in and see what else is going on, Was this right after you updated to 2.0?

Can you screenshot the settings for the rule that handles this and the event logs for each device involved?

Collisionc · November 14, 2018, 2:22am

No problem. It was about an hour after I updated to 2.0.

As I mentioned before, it seems to line up with when the information for my hue hubs is updated every minute.

patrick · November 14, 2018, 2:46am

Can you also post the event table for the contact sensor and the hue group?

And please clarify what did happen vs what should happen.

Door opens, light turns on. (How long did this take?)

Door closes, light turns off (looks like 10 seconds later, but possibly 2 seconds after the anti-turn part was fired)

Need to see when the door actually reported closed and when the off command was actually sent.

Collisionc · November 14, 2018, 3:06am

On the open event, the light turned on nearly instantly. On the close event, it was around a 5-7 second delay between closing the door and the laundry group turning off.

Sensor event log:

Laundry group event log:

As you can see in the group event log, hubitat refreshes the status of the hub/groups/lights at 05:58:00.243 PM EST, and the door sensor event log shows closed at 05:58:05.594 PM EST. I've found that almost every instance of delay in rules firing over the last week is within 10~ seconds after the clock ticks over to the next minute.

I haven't tried connecting to my hubitat with ssh or telnet yet, but if I could get to a command line prompt (assuming some version of linux runs under the hood), I could get you guys way more information.

patrick · November 14, 2018, 3:17am

There is nothing command line to connect to.

The issue I'm seeing here is determining if Simple lighting is actually working off the door closed vs contact inactive. There is a 10 second delay, but if you line up the inactive report and the hue group turning off they are in the same second.

Is this the only delay you are seeing? Or are there other delays you are dealing with?

Also, can you screen shot the contact sensor reporting? Did you enable this:

If so, it would explain things... The door isn't closed until the xyz events stop, aka inactive.

Collisionc · November 14, 2018, 3:23am

As we've tried before, even setting up a virtual button to turn on/off a Jasco Zwave Light switch will result in noticeable delay between pressing the button to turn off/on the switch, and the light switch turning off/on. This delay occurs every minute, roughly 5-10 seconds after the new minute has started.

I haven't setup any of my contact sensors as garage door sensors.

patrick · November 14, 2018, 3:33am

Can you confirm that your hue bridge integration apps status page has this at the bottom:

or at least similar, want to confirm that both are scheduled at the same time every minute.

And to confirm, even though the times above are not on the minute, the 10 second delay did occur or not? In other words, is there a different delay on the minute vs at 52 seconds?

I'm tagging @bobbyD to reach out and see what we can see from a support standpoint.

Collisionc · November 14, 2018, 3:51am

It's running every minute, not every hour. They are both scheduled at the same time every minute. That's what your picture shows as well.

The delay is always occurring on the minute till (rough guess) 10 seconds after the minute. There has never been a noticeable delay before the minute, ex: 52 seconds.