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

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.

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.

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.

Typo, meant minute. Corrected above.

Unrelated to this particular issue, but I think the process of adding bridges is broken as of 2.0. I removed my bridges to test something, only to find out that I can no longer add them back.

It sits at this page:

I've pressed the button numerous times on the bridge, as well as disconnecting one of them to see if it was a problem with multiple bridges. Restarted hubitat and the hue hub. The page used to refresh after I pressed the button and then take me to the spot where I could add bulbs/groups/etc, now it just sits there. Pressing done does not do anything either.

Just out of curiosity, what happens if you refresh the page after you press the button on the Hue Bridge?

Should have thought to try that. :smiley:

Refreshing after pushing the button allows me to proceed.

Will log a ticket on it.

Just to add more information, when I removed both hubs the delay completely disappeared -- I open/shut a door not tied to hue lights for about 3 minutes without any delays on the rule processing to turn on/off the garage light. I re-added the bridges and the delay returned every minute.

edit I didn't see if the delay appeared even with 1 bridge, but I really don't feel like setting up all my apps/rules again to try that now. :slight_smile:

Is there anymore information/data I can give to help with this?

When using [PORT] Hue B Smart [Updated 18/11/2018] - the delay when the hub polls my bridges is reduced by quite a bit.

Hubitat built-in: anywhere from 1-10~ seconds of delay every minute on polling.
Xaps: 1-4~ seconds of delay every 5 minutes. Admittedly with a much smaller sample size (5).

He has both bridges polling at the same time, and not only that, but it is also grabbing scenes. I think if the poll times were shifted so bridge #1 polls at 00 and bridge #2 polls at 30 every 5 minutes, that would help with hubitat's built in drivers.

Ok, after some troubleshooting, I think I've figured it out. When I used the hue b smart driver I noticed that a ridiculous amount of the json response from the bridge when it used GET on /api/(USERNAME) -- easily 75% -- was the bridge sending information about every damn scene that it has for every room, and what bulbs are included in the scene in each room.

I had 7-8 scenes for each of my 23 groups, and I've never used a scene in my life except for by accident. After removing them all, adding back the hubitat hue app, it's all good now. No lag, no issues every minute.

I'm going to bet that hubitat is querying the /api/$username$ endpoint, just like hue b smart was doing, and then discarding the information about scenes. Normally that's fine, but whenever you make a room in the hue app, there's a checkbox to "add default scenes" to the room, and I'm probably not the only one who opted in thinking "oh, well, I never use them, but maybe one day... what harm could it cause?"

A potential solution to this would be to query the following endpoints instead:
/api/$username$/lights - get the bulb info
/api/$username$/groups - get the group info

We only query the /lights and /groups endpoints.

Yeah, I leapt to a conclusion that ended up not being true. :frowning: Didn't test it enough last night as I was dead tired, woke up this morning and opened the closet to get a shirt and it was delayed for about 8 seconds. The Hue B Smart implementation seems to be significantly faster than hubitats.

1 Like

Ok, setup my cisco switch to use SPAN to intercept all packets being sent to/from the hub in wireshark. There's something interesting happening around the same time that my system lags, and I've starred below. These logs are in reverse order from my previous logs, as it makes more sense to sort them oldest ---> newest.


2018-11-22 01:09:56.639 Server Closet was opened
2018-11-22 01:09:56.669 Turn On Stairs when Server Closet Opened Turn On
2018-11-22 01:09:56.787 Group Stairs was turned on - Stairs is on bridge #1.
2018-11-22 01:09:56.901 - Wireshark - Shows that hubitat sends PUT command to turn on group

**2018-11-22 01:09:56.923 - Wireshark - A stream of packets that are sent/received from IP 52.84.77.192, initiated from hubitat - which seems to be an AWS cloudfront CDN. All of the data is encrypted and I didn't have a MITM proxy running at the time to decrypt it.**
**2018-11-22 01:09:57.139 - Wireshark - Packet stream from 52.84.77.192 momentarily stops.**

2018-11-22 01:09:57.697 - Wireshark - Hubitat polls lights on bridge #2 using GET  /api/user/lights
2018-11-22 01:09:57.700 - Wireshark - Hubitat polls groups on bridge #2 using GET /api/user/groups
2018-11-22 01:09:57.726 - Wireshark - Hubitat polls lights on bridge #1 using GET /api/user/lights
2018-11-22 01:09:57.728 - Wireshark - Hubitat polls groups on bridge #1 using GET /api/user/groups
2018-11-22 01:09:57.799 - Wireshark - Hue has finished responding to those requests on both hubs.

**2018-11-22 01:09:57.923 - Wireshark - The encrypted traffic to/from 52.84.77.192 starts up again.**

2018-11-22 01:09:57.942 Server Closet was closed
2018-11-22 01:09:57.990 Turn On Stairs when Server Closet Opened anti-Turn On
2018-11-22 01:09:58.099 Group Stairs was turned off

2018-11-22 01:09:59.185 Server Closet was opened
2018-11-22 01:09:59.216 Turn On Stairs when Server Closet Opened Turn On
2018-11-22 01:09:59.288 Group Stairs was turned on
2018-11-22 01:10:00.654 Server Closet was closed

**2018-11-22 01:10:01.115 - Wireshark - Encrypted traffic to/from 52.84.77.192 stops**

2018-11-22 01:10:01.127 - Wireshark - Hubitat sends a PUT command to turn on the group
2018-11-22 01:10:01.137 - Wireshark - Hubitat sends a PUT command to turn off the group 

**2018-11-22 01:10:01.230 - Wireshark - Encrypted traffic 52.84.77.192 starts**
**2018-11-22 01:10:01.499 - Wireshark - Encrypted traffic 52.84.77.192 stops**

2018-11-22 01:10:01.809 - Wireshark - Hubitat sends a PUT command to turn off the group

**2018-11-22 01:10:01.834 - Wireshark - Encrypted traffic 52.84.77.192 starts**
**2018-11-22 01:10:02.360 - Wireshark - Encrypted traffic stops**

2018-11-22 01:10:02.835 Server Closet was opened
2018-11-22 01:10:03.261 Turn On Stairs when Server Closet Opened Turn On
2018-11-22 01:10:03.372 Turn On Stairs when Server Closet Opened anti-Turn On
2018-11-22 01:10:03.509 Group Stairs was turned on
2018-11-22 01:10:03.518 Group Stairs was turned off
2018-11-22 01:10:03.665 - Wireshark - Hubitat sends PUT command to turn on group

**2018-11-22 01:10:03.690 - Wireshark - encrypted traffic starts**
**2018-11-22 01:10:03.968 - Wireshark - Encrypted traffic ends**

2018-11-22 01:10:04.083 Server Closet was closed
2018-11-22 01:10:04.118 Turn On Stairs when Server Closet Opened anti-Turn On
2018-11-22 01:10:04.196 Group Stairs was turned off
2018-11-22 01:10:05.447 - Wireshark - Hubitat sends PUT command to turn off group

**2018-11-22 01:10:05.480 - Wireshark - Encrypted traffic starts**
**2018-11-22 01:10:05.729 - Wireshark - Encrypted traffic ends**

2018-11-22 01:10:05.930 Server Closet was opened
2018-11-22 01:10:05.960 Turn On Stairs when Server Closet Opened Turn On
2018-11-22 01:10:06.052 Group Stairs was turned on
2018-11-22 01:10:07.635 - Wireshark - Hubitat sends PUT command to turn off group

**2018-11-22 01:10:07.659 - Encrypted traffic starts**
**2018-11-22 01:10:07.879 - Encrypted traffic stops**

(Stopped wireshark logging here) 

While hubitat is communicating with 52.84.77.192 it never sends out any hue bridge commands (It doesn't seem to send ANY network connections out at this point, including zigbee/zwave commands) -- which means that hubitat may not be using async with that particular connection. The rules seem to be firing fairly quickly while this traffic is happening from 01:09:57.139 till 01:10:01.115, it's just that hubitat doesn't send the command to turn on/off the lights until after this connection has completed.

Which leads to scenarios where these commands backup and get sent out in a strange order, as in my case where it sent 3 commands within 1 second to first turn on the group, then it sent 2 commands to turn the group off.

Do you have the hue devices / groups syncing to the amazon skill?

I could see a loop being created by the poll every minute then syncing device updates to aws.

This is why we have this option:

Did you, by chance, turn that off?

I did because Alexa's integration of hue does not support hue groups, it only supports hue rooms. It doesn't pickup the extra groups that I've created - ex: "Everything" includes all bulbs attached to one of the bridges.

Why have it pause other events from firing? I'd rather a rule be processed on time than make sure that Alexa has an up to date status on my bulbs.

Additionally, I think that Hubitat is sending too much information to Amazon every minute. I'm comparing wireshark traffic differences between Hubitat and ST, and ST is vastly less chatty about updating amazon on the status of hue.

I think the difference could be that Hubitat devices are automatically discovered when I add them to Alexa, while Samsung requires that I tell Alexa "Discover my devices". Hubitat must be sending the "Discover" information every minute even though no additional devices are found.

Just thought I'd update you all that the latency issues have gone away with the newest updates, thanks! :slight_smile:

3 Likes

Indeed, and that is not acceptable, in my opinion...

1 Like