New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Optimize Ring Sensors platform setup #16886

Merged
merged 1 commit into from Sep 26, 2018

Conversation

@awarecan
Contributor

awarecan commented Sep 26, 2018

Description:

Could reduce few seconds startup time for Ring users

Follow up of #16866
CC @arsaboo

Related issue (if applicable): fixes #

Pull request in home-assistant.io with documentation (if applicable): home-assistant/home-assistant.io#<home-assistant.io PR number goes here>

Example entry for configuration.yaml (if applicable):

Checklist:

  • The code change is tested and works locally.
  • Local tests pass with tox. Your PR cannot be merged unless tests pass
@balloob

Oh wow that was inefficient!

@dshokouhi

This comment has been minimized.

Contributor

dshokouhi commented Sep 26, 2018

so I had staged these commits in my own dev environment and I received the following warnings:

2018-09-26 09:16:17 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform ring is taking over 10 seconds.
2018-09-26 09:16:25 WARNING (MainThread) [homeassistant.components.camera] Setup of platform ring is taking over 10 seconds.

I have a Ring doorbell and a ring floodlight camera

@awarecan

This comment has been minimized.

Contributor

awarecan commented Sep 26, 2018

@dshokouhi you need first apply PR #16866

@dshokouhi

This comment has been minimized.

Contributor

dshokouhi commented Sep 26, 2018

@awarecan I am running dev and I do indeed have that PR applied before I staged this PR. Before I applied this PR I got the following error, and I can confirm that only this error comes back when I revert this PR.

2018-09-26 10:09:01 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform ring is taking over 10 seconds.

I have confirmed this with several HA restarts as well to make sure only this warning shows up when this PR is reverted.

@awarecan

This comment has been minimized.

Contributor

awarecan commented Sep 26, 2018

I am still confused, so you have

sensor.ring taking over 10 secs before the PR

And you have

sensor.ring and camera.ring both taking over 10 secs after the PR.

Is that correct?

@dshokouhi

This comment has been minimized.

Contributor

dshokouhi commented Sep 26, 2018

@awarecan yes that is correct, I know it sounds very odd

@arsaboo

This comment has been minimized.

Contributor

arsaboo commented Sep 26, 2018

I applied both the PRs and the warnings are gone.

@dshokouhi Are you getting the warnings on every restart?

@awarecan

This comment has been minimized.

Contributor

awarecan commented Sep 26, 2018

I don't have better way to measure platform setup performance (maybe worth a PR to improve), but I found ring_doorbell lib has a debug option can output some detail debug logs, therefore we can measure from the first ring API HTTP call to the last ring API HTTP call before the system fully start.

By enabled it, you need change

ring = Ring(username=username, password=password, cache_file=cache)

to

ring = Ring(debug=True, username=username, password=password, cache_file=cache)

Then enable ring_doorbell debug logging

logger:
  default: info
  logs:
    ring_doorbell: debug
@dshokouhi

This comment has been minimized.

Contributor

dshokouhi commented Sep 26, 2018

@arsaboo yes just about every restart I do, here is an example of the logging:

2018-09-26 11:45:31 INFO (MainThread) [homeassistant.setup] Setup of domain ring took 0.9 seconds.
2018-09-26 11:45:31 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ring
2018-09-26 11:45:31 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ring
2018-09-26 11:45:31 INFO (MainThread) [homeassistant.components.camera] Setting up camera.ring
2018-09-26 11:45:34 INFO (MainThread) [homeassistant.setup] Setup of domain binary_sensor took 4.5 seconds.
2018-09-26 11:45:41 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform ring is taking over 10 seconds.
2018-09-26 11:45:41 WARNING (MainThread) [homeassistant.components.camera] Setup of platform ring is taking over 10 seconds.
2018-09-26 11:45:43 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 13.3 seconds.
2018-09-26 11:45:44 INFO (MainThread) [homeassistant.setup] Setup of domain camera took 13.7 seconds.

@awarecan I just enabled debugging and I see a lot of errors actually, I see this repeated hundreds of times if not more:

2018-09-26 11:49:32 DEBUG (SyncWorker_1) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:32 DEBUG (SyncWorker_12) [ring_doorbell] Querying https://api.ring.com/clients_api/ring_devices
2018-09-26 11:49:32 DEBUG (SyncWorker_12) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Querying https://api.ring.com/clients_api/doorbots/SECRET/health
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Querying https://api.ring.com/clients_api/doorbots/SECRET/history
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] Querying https://api.ring.com/clients_api/ring_devices
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 INFO (Thread-2) [pychromecast.socket_client] Stopped while reading message, disconnecting.
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] Querying https://api.ring.com/clients_api/doorbots/SECRET/health
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_13) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_6) [ring_doorbell] Querying https://api.ring.com/clients_api/ring_devices
2018-09-26 11:49:33 DEBUG (SyncWorker_6) [ring_doorbell] running query loop 0
2018-09-26 11:49:34 DEBUG (SyncWorker_6) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:34 DEBUG (SyncWorker_6) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:34 DEBUG (SyncWorker_6) [ring_doorbell] Querying https://api.ring.com/clients_api/doorbots/SECRET/health
2018-09-26 11:49:34 DEBUG (SyncWorker_6) [ring_doorbell] running query loop 0
2018-09-26 11:49:34 DEBUG (SyncWorker_6) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:34 DEBUG (SyncWorker_6) [ring_doorbell] Sorry.. Something went wrong...

these particular errors begin showing up during and after setup, they don't seem to stop at the level of frequency they go.

@awarecan

This comment has been minimized.

Contributor

awarecan commented Sep 26, 2018

@dshokouhi

2018-09-26 11:45:43 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 13.3 seconds.
2018-09-26 11:45:44 INFO (MainThread) [homeassistant.setup] Setup of domain camera took 13.7 seconds.

Since sensor.ring and camera.ring both taking over 10 seconds, I think it is safe to say ring platform spent majority of those 13 seconds to setup.

So, if you can compare with the record before this PR, we can have conclusion if we got performance improve.

Regarding the debug information, it was a bug in ring_doorbell lib, when it write a "Sorry.. Something went wrong..." log in debug mode, which actually means "Everything is good"

2018-09-26 11:49:32 DEBUG (SyncWorker_12) [ring_doorbell] Querying https://api.ring.com/clients_api/ring_devices
2018-09-26 11:49:32 DEBUG (SyncWorker_12) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Querying https://api.ring.com/clients_api/doorbots/SECRET/health
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Sorry.. Something went wrong...
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Querying https://api.ring.com/clients_api/doorbots/SECRET/history
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] running query loop 0
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] _query 1 ret 200
2018-09-26 11:49:33 DEBUG (SyncWorker_12) [ring_doorbell] Sorry.. Something went wrong...

This is three API call in same thread, they are mapping to one update() method call, you can find, it can only finish 2 update() call in 1 seconds. If my calculation is right, 2 ring device need at least 16 update() call to add all sensors, that means 8 seconds.

The same calculation gave me 28 update() for previous logic, that means 14 seconds, so plus other overhead, I will bet if you switch back the previous logic, sensor domain need 20 seconds to complete setup.

Even for current logic, I still think there is a big room to improve, IMO, add two device, we should only call update() twice. But it will beyond this pull request's scope.

@dshokouhi

This comment has been minimized.

Contributor

dshokouhi commented Sep 26, 2018

@awarecan here are the results with the PR reverted, you are correct the average is 25 seconds for the sensor domain....even binary_sensor had a 50% increase in time on average

2018-09-26 14:39:19 INFO (MainThread) [homeassistant.setup] Setup of domain ring took 1.0 seconds.
2018-09-26 14:39:19 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ring
2018-09-26 14:39:19 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ring
2018-09-26 14:39:19 INFO (MainThread) [homeassistant.components.camera] Setting up camera.ring
2018-09-26 14:39:24 INFO (MainThread) [homeassistant.setup] Setup of domain binary_sensor took 6.2 seconds.
2018-09-26 14:39:28 INFO (MainThread) [homeassistant.setup] Setup of domain camera took 9.9 seconds.
2018-09-26 14:39:29 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform ring is taking over 10 seconds.
2018-09-26 14:39:44 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 26.3 seconds.

With that said during one of my tests with the PR reverted I still saw the camera domain taking 13 seconds. So 10-13 seconds is the correct amount of time to setup for that domain:

2018-09-26 14:36:44 INFO (MainThread) [homeassistant.setup] Setup of domain ring took 0.9 seconds.
2018-09-26 14:36:44 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.ring
2018-09-26 14:36:44 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.ring
2018-09-26 14:36:44 INFO (MainThread) [homeassistant.components.camera] Setting up camera.ring

2018-09-26 14:36:50 INFO (MainThread) [homeassistant.setup] Setup of domain binary_sensor took 6.2 seconds.
2018-09-26 14:36:54 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform ring is taking over 10 seconds.
2018-09-26 14:36:54 WARNING (MainThread) [homeassistant.components.camera] Setup of platform ring is taking over 10 seconds.
2018-09-26 14:36:57 INFO (MainThread) [homeassistant.setup] Setup of domain camera took 13.1 seconds.
2018-09-26 14:37:08 INFO (MainThread) [homeassistant.setup] Setup of domain sensor took 24.6 seconds.

great improvement :)

@awarecan awarecan merged commit 96e5acd into home-assistant:dev Sep 26, 2018

5 checks passed

Hound No violations found. Woof!
WIP ready for review
Details
cla-bot Everyone involved has signed the CLA
continuous-integration/travis-ci/pr The Travis CI build passed
Details
coverage/coveralls Coverage increased (+0.0005%) to 93.505%
Details

@wafflebot wafflebot bot removed the in progress label Sep 26, 2018

@balloob balloob added this to the 0.79.1 milestone Sep 28, 2018

balloob added a commit that referenced this pull request Sep 30, 2018

@balloob balloob referenced this pull request Sep 30, 2018

Merged

0.79.1 #16988

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment