Skip to content
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

Higher CPU continues in 0.118 #40292

Closed
gieljnssns opened this issue Sep 19, 2020 · 278 comments · Fixed by #40272, #40250, #40075, #40453 or #40345
Closed

Higher CPU continues in 0.118 #40292

gieljnssns opened this issue Sep 19, 2020 · 278 comments · Fixed by #40272, #40250, #40075, #40453 or #40345
Assignees
Labels

Comments

@gieljnssns
Copy link
Contributor

The problem

I don't know if it is a core or frontend problem or something else. But I'm seeing a higher CPU use in generally, but especially when clicking on a card in the Lovelace view.
My normal CPU use was 2 a 3 % now it is at 6 to 8 %
When I want to show the history the fans of my NUC immediately start to blow and I see always a turning circle.
Schermafbeelding 2020-09-19 om 10 24 13
And the CPU use peaks at about 18%

This are some screenshots from Glances when clicking on history in Lovelace
Schermafbeelding 2020-09-19 om 10 30 15
Schermafbeelding 2020-09-19 om 10 30 20
Schermafbeelding 2020-09-19 om 10 30 29

I had debug on for

logs:
  homeassistant.event: debug
  homeassistant.components.logger: debug
  homeassistant.components.history: debug
  homeassistant.components.recorder: debug

But not seeing anything special

I've tried the Py-Spy way, but I can not get it installed

   Compiling addr2line v0.11.0
     Running `rustc --crate-name addr2line /root/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/addr2line-0.11.0/src/lib.rs --error-format=json --json=diagnostic-rendered-ansi,artifacts --crate-type lib --emit=dep-info,metadata,link -C opt-level=3 --cfg 'feature="cpp_demangle"' --cfg 'feature="default"' --cfg 'feature="object"' --cfg 'feature="rustc-demangle"' --cfg 'feature="std"' --cfg 'feature="std-object"' -C metadata=361484a7c1298d46 -C extra-filename=-361484a7c1298d46 --out-dir /tmp/cargo-installWui9CK/release/deps -L dependency=/tmp/cargo-installWui9CK/release/deps --extern cpp_demangle=/tmp/cargo-installWui9CK/release/deps/libcpp_demangle-eb3cfddebaa342f3.rmeta --extern fallible_iterator=/tmp/cargo-installWui9CK/release/deps/libfallible_iterator-a4123992588425b5.rmeta --extern gimli=/tmp/cargo-installWui9CK/release/deps/libgimli-7d5edb096fedfa90.rmeta --extern lazycell=/tmp/cargo-installWui9CK/release/deps/liblazycell-ea0ac196d0b3629c.rmeta --extern object=/tmp/cargo-installWui9CK/release/deps/libobject-477a467cbf075a12.rmeta --extern rustc_demangle=/tmp/cargo-installWui9CK/release/deps/librustc_demangle-1fe779301a7b7227.rmeta --extern smallvec=/tmp/cargo-installWui9CK/release/deps/libsmallvec-9bd83c2162524722.rmeta --cap-lints allow`
     Running `rustc --crate-name remoteprocess /root/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/remoteprocess-0.3.4/src/lib.rs --error-format=json --json=diagnostic-rendered-ansi,artifacts --crate-type lib --emit=dep-info,metadata,link -C opt-level=3 --cfg 'feature="default"' --cfg 'feature="unwind"' -C metadata=2427f6658e4e467c -C extra-filename=-2427f6658e4e467c --out-dir /tmp/cargo-installWui9CK/release/deps -L dependency=/tmp/cargo-installWui9CK/release/deps --extern addr2line=/tmp/cargo-installWui9CK/release/deps/libaddr2line-361484a7c1298d46.rmeta --extern benfred_read_process_memory=/tmp/cargo-installWui9CK/release/deps/libbenfred_read_process_memory-e58b01e0194ad895.rmeta --extern goblin=/tmp/cargo-installWui9CK/release/deps/libgoblin-f7d9a003d2b2b860.rmeta --extern lazy_static=/tmp/cargo-installWui9CK/release/deps/liblazy_static-dda545747076ca2e.rmeta --extern libc=/tmp/cargo-installWui9CK/release/deps/liblibc-d6a517a54d66530e.rmeta --extern log=/tmp/cargo-installWui9CK/release/deps/liblog-33247e2f897fd775.rmeta --extern memmap=/tmp/cargo-installWui9CK/release/deps/libmemmap-d558b4e09fe43210.rmeta --extern nix=/tmp/cargo-installWui9CK/release/deps/libnix-003b039a35e9d039.rmeta --extern object=/tmp/cargo-installWui9CK/release/deps/libobject-477a467cbf075a12.rmeta --extern proc_maps=/tmp/cargo-installWui9CK/release/deps/libproc_maps-af79a59c980f3ade.rmeta --extern regex=/tmp/cargo-installWui9CK/release/deps/libregex-bc89e9f6ea47428c.rmeta --cap-lints allow -L native=/usr/local/lib -l static=unwind -l static=unwind-ptrace -l static=unwind-x86_64`
     Running `rustc --crate-name py_spy /root/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/py-spy-0.3.3/src/lib.rs --error-format=json --json=diagnostic-rendered-ansi --crate-type lib --emit=dep-info,metadata,link -C opt-level=3 -C metadata=ff12da3be12bb5c3 -C extra-filename=-ff12da3be12bb5c3 --out-dir /tmp/cargo-installWui9CK/release/deps -L dependency=/tmp/cargo-installWui9CK/release/deps --extern clap=/tmp/cargo-installWui9CK/release/deps/libclap-f6bf72e393cc38bc.rmeta --extern console=/tmp/cargo-installWui9CK/release/deps/libconsole-f112d37c0f47569f.rmeta --extern cpp_demangle=/tmp/cargo-installWui9CK/release/deps/libcpp_demangle-eb3cfddebaa342f3.rmeta --extern ctrlc=/tmp/cargo-installWui9CK/release/deps/libctrlc-aad786bac40b3a9d.rmeta --extern env_logger=/tmp/cargo-installWui9CK/release/deps/libenv_logger-e27ea58ddced9d00.rmeta --extern failure=/tmp/cargo-installWui9CK/release/deps/libfailure-3335c4e883f54b39.rmeta --extern goblin=/tmp/cargo-installWui9CK/release/deps/libgoblin-f7d9a003d2b2b860.rmeta --extern indicatif=/tmp/cargo-installWui9CK/release/deps/libindicatif-225faf62a9b3f910.rmeta --extern inferno=/tmp/cargo-installWui9CK/release/deps/libinferno-d5bd4adb491d743b.rmeta --extern lazy_static=/tmp/cargo-installWui9CK/release/deps/liblazy_static-dda545747076ca2e.rmeta --extern libc=/tmp/cargo-installWui9CK/release/deps/liblibc-d6a517a54d66530e.rmeta --extern log=/tmp/cargo-installWui9CK/release/deps/liblog-33247e2f897fd775.rmeta --extern lru=/tmp/cargo-installWui9CK/release/deps/liblru-7c22ae3502192a2e.rmeta --extern memmap=/tmp/cargo-installWui9CK/release/deps/libmemmap-d558b4e09fe43210.rmeta --extern proc_maps=/tmp/cargo-installWui9CK/release/deps/libproc_maps-af79a59c980f3ade.rmeta --extern rand=/tmp/cargo-installWui9CK/release/deps/librand-3b4eb2183b20dcb0.rmeta --extern rand_distr=/tmp/cargo-installWui9CK/release/deps/librand_distr-9984e8ecbf04f38f.rmeta --extern regex=/tmp/cargo-installWui9CK/release/deps/libregex-bc89e9f6ea47428c.rmeta --extern remoteprocess=/tmp/cargo-installWui9CK/release/deps/libremoteprocess-2427f6658e4e467c.rmeta --extern serde=/tmp/cargo-installWui9CK/release/deps/libserde-64b415a5891575a4.rmeta --extern serde_derive=/tmp/cargo-installWui9CK/release/deps/libserde_derive-87637e81ef141bef.so --extern serde_json=/tmp/cargo-installWui9CK/release/deps/libserde_json-8b40eb8bd5b4f85c.rmeta --extern tempfile=/tmp/cargo-installWui9CK/release/deps/libtempfile-2085f7c84ee47d2e.rmeta --extern termios=/tmp/cargo-installWui9CK/release/deps/libtermios-776eb0ed1fc2710a.rmeta --cap-lints allow --cfg unwind -L native=/usr/local/lib`
error: could not find native static library `unwind`, perhaps an -L flag is missing?

error: aborting due to previous error

error: could not compile `remoteprocess`.

Caused by:
  process didn't exit successfully: `rustc --crate-name remoteprocess /root/.cargo/registry/src/github.aaakk.us.kg-1ecc6299db9ec823/remoteprocess-0.3.4/src/lib.rs --error-format=json --json=diagnostic-rendered-ansi,artifacts --crate-type lib --emit=dep-info,metadata,link -C opt-level=3 --cfg 'feature="default"' --cfg 'feature="unwind"' -C metadata=2427f6658e4e467c -C extra-filename=-2427f6658e4e467c --out-dir /tmp/cargo-installWui9CK/release/deps -L dependency=/tmp/cargo-installWui9CK/release/deps --extern addr2line=/tmp/cargo-installWui9CK/release/deps/libaddr2line-361484a7c1298d46.rmeta --extern benfred_read_process_memory=/tmp/cargo-installWui9CK/release/deps/libbenfred_read_process_memory-e58b01e0194ad895.rmeta --extern goblin=/tmp/cargo-installWui9CK/release/deps/libgoblin-f7d9a003d2b2b860.rmeta --extern lazy_static=/tmp/cargo-installWui9CK/release/deps/liblazy_static-dda545747076ca2e.rmeta --extern libc=/tmp/cargo-installWui9CK/release/deps/liblibc-d6a517a54d66530e.rmeta --extern log=/tmp/cargo-installWui9CK/release/deps/liblog-33247e2f897fd775.rmeta --extern memmap=/tmp/cargo-installWui9CK/release/deps/libmemmap-d558b4e09fe43210.rmeta --extern nix=/tmp/cargo-installWui9CK/release/deps/libnix-003b039a35e9d039.rmeta --extern object=/tmp/cargo-installWui9CK/release/deps/libobject-477a467cbf075a12.rmeta --extern proc_maps=/tmp/cargo-installWui9CK/release/deps/libproc_maps-af79a59c980f3ade.rmeta --extern regex=/tmp/cargo-installWui9CK/release/deps/libregex-bc89e9f6ea47428c.rmeta --cap-lints allow -L native=/usr/local/lib -l static=unwind -l static=unwind-ptrace -l static=unwind-x86_64` (exit code: 1)
warning: build failed, waiting for other jobs to finish...
error: failed to compile `py-spy v0.3.3`, intermediate artifacts can be found at `/tmp/cargo-installWui9CK`

Caused by:
  build failed
bash-5.0# # pip install py-spy
/bin/ash: pip: not found

Environment

  • Home Assistant Core release with the issue: 0.115
  • Last working Home Assistant Core release (if known): 0.114.x
  • Operating environment (OS/Container/Supervised/Core): OS
  • Integration causing this issue: ?
  • Link to integration documentation on our website: ?

arch | x86_64
-- | --
chassis | embedded
dev | false
docker | true
docker_version | 19.03.11
hassio | true
host_os | HassOS 4.13
installation_type | Home Assistant OS
os_name | Linux
os_version | 5.4.63
python_version | 3.8.5
supervisor | 245
timezone | Europe/Brussels
version | 0.115.1
virtualenv | false

Problem-relevant configuration.yaml

I don't know

Traceback/Error logs

None

Additional information

If you need some more info, ask...

@gieljnssns
Copy link
Contributor Author

When not using the frontend, once a 50-60 second the fans of my NUC are blowing fast.
This is a screenshot of glances the moment this happens.
Schermafbeelding 2020-09-19 om 11 25 48

@springstan
Copy link
Member

Could be related to this issue #39890

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

There isn't much we can do to help without a py-spy or interesting logs.

@gieljnssns
Copy link
Contributor Author

Maybe you can tell me how to install....

@gieljnssns
Copy link
Contributor Author

I've tried
https://developers.home-assistant.io/docs/operating-system/debugging/#ssh-access-to-the-host
and then

apk add cargo
cargo install py-spy

@gieljnssns
Copy link
Contributor Author

There isn't much we can do to help without a py-spy or interesting logs.

Which Debug you need?
I've tried

logs:
  homeassistant.event: debug
  homeassistant.components.logger: debug
  homeassistant.components.history: debug
  homeassistant.components.recorder: debug

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

Try turning on full debug mode. (default: debug) and seeing if there is anything interesting. Without a py-spy to narrow the issue down, its not possible to give any more guidance for which area to look.

@gieljnssns
Copy link
Contributor Author

gieljnssns commented Sep 19, 2020

Is there a way to send you this debug log?
Btw I've tried another 2 times to install Py-Spy, always

error: could not find native static library `unwind`, perhaps an -L flag is missing?

error: aborting due to previous error

error: could not compile `remoteprocess`.

To learn more, run the command again with --verbose.
warning: build failed, waiting for other jobs to finish...
error: failed to compile `py-spy v0.3.3`, intermediate artifacts can be found at `/tmp/cargo-installNtWBUG`

Caused by:
  build failed

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020 via email

@gieljnssns
Copy link
Contributor Author

I've send you a wetransfer link because .log is 100MB

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

2020-09-19 16:16:05 DEBUG (MainThread) [homeassistant.helpers.event] Template update {% if states('sensor.uptime_in_uren')|float > 0.05|float %}
  {{states|selectattr('state', 'in', ['unavailable','unknown','none'])
    |reject('in', expand('group.entity_blacklist'))
    |reject('eq', states.group.entity_blacklist)
    |list|length}}
{% else %}
  0
{% endif %}

Try disabling this template as its watching all states and you have a massive amount of state changed events happening.

You could replace it with an automation to only happen every few seconds and it should help

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

Also change

{{ states.sensor | list | length }}
to
{{ states.sensor | count }}

This will avoid creating a list every time a sensor updates

@gieljnssns
Copy link
Contributor Author

gieljnssns commented Sep 19, 2020

2020-09-19 16:16:05 DEBUG (MainThread) [homeassistant.helpers.event] Template update {% if states('sensor.uptime_in_uren')|float > 0.05|float %}
  {{states|selectattr('state', 'in', ['unavailable','unknown','none'])
    |reject('in', expand('group.entity_blacklist'))
    |reject('eq', states.group.entity_blacklist)
    |list|length}}
{% else %}
  0
{% endif %}

I've had tried that yesterday, there was no difference. So I turned it back on...

But I will make an automation of that...

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

{{ states.device_tracker | list | length }} as well

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

I can tell you what I see is inefficient, but I'm pretty much shooting in the dark without a py-spy.

@gieljnssns
Copy link
Contributor Author

I'll try to change that all.
Py-Spy, I did try to install another 2 times....

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

bdraco@Js-MacBook-Pro-3 ~ % grep 'state_changed' home-assistant\ \(1\).log | grep '16:14:40'|wc
     315   10547  187923
bdraco@Js-MacBook-Pro-3 ~ % grep 'state_changed' home-assistant\ \(1\).log | grep '16:14:41'|wc
     241    7817  135811
bdraco@Js-MacBook-Pro-3 ~ % grep 'state_changed' home-assistant\ \(1\).log | grep '16:14:42'|wc
     355   16331  251219
bdraco@Js-MacBook-Pro-3 ~ % grep 'state_changed' home-assistant\ \(1\).log | grep '16:14:43'|wc
     259    8447  146329
bdraco@Js-MacBook-Pro-3 ~ % grep 'state_changed' home-assistant\ \(1\).log | grep '16:14:44'|wc
     291    9860  176954

It looks like you are getting about 300 state changed events per second 😮

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

I'd focus on reducing the state change events to only what you need.

@gieljnssns
Copy link
Contributor Author

I'd focus on reducing the state change events to only what you need.

How do you mean? Delete some sensors?

In 0.114.x I haven't seen these problems...

@gieljnssns
Copy link
Contributor Author

I have disabled my unavailable sensor and replaced all | list | length }} by | count }} and

When not using the frontend, once a 50-60 second the fans of my NUC are blowing fast.

this appears to be less frequent

@gieljnssns
Copy link
Contributor Author

I have found this

2020-09-19 16:42:46 23 [Warning] Aborted connection 23 to db: 'homeassistant' user: 'hass' host: '172.30.32.1' (Got an error reading communication packets)
2020-09-19 17:58:12 35 [Warning] Aborted connection 35 to db: 'homeassistant' user: 'hass' host: '172.30.32.1' (Got an error reading communication packets)

in the logs from the MariaDB addon

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

I'd focus on reducing the state change events to only what you need.

How do you mean? Delete some sensors?

In 0.114.x I haven't seen these problems...

If you disable all your template entities, does the issue go away?

@gieljnssns
Copy link
Contributor Author

gieljnssns commented Sep 19, 2020

I think I removed all template sensors and template binary sensors
The restart off HA takes still a lot of time
Schermafbeelding 2020-09-19 om 18 34 52
CPU is still higher then 0.114.x
And when I click something in the frontend
Schermafbeelding 2020-09-19 om 18 36 13

So I restore all my templates...

@bdraco
Copy link
Member

bdraco commented Sep 19, 2020

It is likely the mysql load is caused by the processing of all those state changed events.

I'm not sure what has changed between 0.114 and 0.115 that would cause that increase. It may be caused by a change in the integration that is generating these events.

@amelchio
Copy link
Contributor

error: could not find native static library unwind, perhaps an -L flag is missing?

I get the same error with cargo. However, this worked for me inside a 0.115.1 Container install:

echo 'manylinux1_compatible = True' > /usr/local/lib/python3.8/site-packages/_manylinux.py
pip install py-spy
py-spy record --pid $(pidof python3) --duration 120 --output /config/www/spy.svg

(I did have to add the SYS_PTRACE capability to the container but I assume this is handled already in the OS setup.)

@gieljnssns
Copy link
Contributor Author

@gieljnssns
Copy link
Contributor Author

Schermafbeelding 2020-09-20 om 12 13 41

@gieljnssns
Copy link
Contributor Author

bash-5.0# py-spy dump --pid 232
Process 232: python3 -m homeassistant --config /config
Python v3.8.5 (/usr/local/bin/python3.8)

Thread 232 (idle): "MainThread"
    select (selectors.py:468)
    _run_once (asyncio/base_events.py:1823)
    run_forever (asyncio/base_events.py:570)
    run_until_complete (asyncio/base_events.py:603)
    run (asyncio/runners.py:43)
    run (homeassistant/runner.py:133)
    main (homeassistant/__main__.py:312)
    <module> (homeassistant/__main__.py:320)
    _run_code (runpy.py:87)
    _run_module_as_main (runpy.py:194)
Thread 254 (idle): "Thread-1"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 255 (idle): "SyncWorker_0"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 256 (idle): "SyncWorker_1"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 257 (idle): "SyncWorker_2"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 258 (idle): "SyncWorker_3"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 259 (idle): "SyncWorker_4"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 260 (idle): "SyncWorker_5"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 263 (idle): "SyncWorker_6"
    query (MySQLdb/connections.py:259)
    _query (MySQLdb/cursors.py:319)
    execute (MySQLdb/cursors.py:206)
    do_execute (sqlalchemy/engine/default.py:593)
    _execute_context (sqlalchemy/engine/base.py:1276)
    _execute_clauseelement (sqlalchemy/engine/base.py:1124)
    _execute_on_connection (sqlalchemy/sql/elements.py:298)
    execute (sqlalchemy/engine/base.py:1011)
    _execute_and_instances (sqlalchemy/orm/query.py:3533)
    __iter__ (sqlalchemy/orm/query.py:3508)
    yield_events (homeassistant/components/logbook/__init__.py:418)
    humanify (homeassistant/components/logbook/__init__.py:251)
    _get_events (homeassistant/components/logbook/__init__.py:516)
    json_events (homeassistant/components/logbook/__init__.py:228)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 264 (idle): "SyncWorker_7"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 265 (idle): "SyncWorker_8"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 266 (idle): "SyncWorker_9"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 267 (idle): "SyncWorker_10"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 268 (idle): "SyncWorker_11"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 269 (idle): "SyncWorker_12"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 270 (idle): "SyncWorker_13"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 271 (idle): "SyncWorker_14"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 272 (idle): "SyncWorker_15"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 273 (idle): "SyncWorker_16"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 274 (idle): "SyncWorker_17"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 275 (idle): "SyncWorker_18"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 276 (idle): "SyncWorker_19"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 277 (idle): "SyncWorker_20"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 278 (idle): "SyncWorker_21"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 279 (idle): "SyncWorker_22"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 280 (idle): "Recorder"
    run (homeassistant/components/recorder/__init__.py:346)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 281 (idle): "Thread-2"
    dequeue (logging/handlers.py:1427)
    _monitor (logging/handlers.py:1478)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 284 (idle): "zeroconf-Engine-284"
    run (zeroconf/__init__.py:1325)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 285 (idle): "zeroconf-Reaper_285"
    wait (threading.py:306)
    run (zeroconf/__init__.py:1451)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 286 (idle): "SyncWorker_23"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 287 (idle): "SyncWorker_24"
    query (MySQLdb/connections.py:259)
    _query (MySQLdb/cursors.py:319)
    execute (MySQLdb/cursors.py:206)
    do_execute (sqlalchemy/engine/default.py:593)
    _execute_context (sqlalchemy/engine/base.py:1276)
    _execute_clauseelement (sqlalchemy/engine/base.py:1124)
    _execute_on_connection (sqlalchemy/sql/elements.py:298)
    execute (sqlalchemy/engine/base.py:1011)
    _execute_and_instances (sqlalchemy/orm/query.py:3533)
    __iter__ (sqlalchemy/orm/query.py:3508)
    yield_events (homeassistant/components/logbook/__init__.py:418)
    humanify (homeassistant/components/logbook/__init__.py:251)
    _get_events (homeassistant/components/logbook/__init__.py:516)
    json_events (homeassistant/components/logbook/__init__.py:228)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 288 (idle): "SyncWorker_25"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 289 (idle): "SyncWorker_26"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 290 (idle): "SyncWorker_27"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 291 (idle): "SyncWorker_28"
    query (MySQLdb/connections.py:259)
    _query (MySQLdb/cursors.py:319)
    execute (MySQLdb/cursors.py:206)
    do_execute (sqlalchemy/engine/default.py:593)
    _execute_context (sqlalchemy/engine/base.py:1276)
    _execute_clauseelement (sqlalchemy/engine/base.py:1124)
    _execute_on_connection (sqlalchemy/sql/elements.py:298)
    execute (sqlalchemy/engine/base.py:1011)
    _execute_and_instances (sqlalchemy/orm/query.py:3533)
    __iter__ (sqlalchemy/orm/query.py:3508)
    yield_events (homeassistant/components/logbook/__init__.py:418)
    humanify (homeassistant/components/logbook/__init__.py:251)
    _get_events (homeassistant/components/logbook/__init__.py:516)
    json_events (homeassistant/components/logbook/__init__.py:228)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 292 (idle): "SyncWorker_29"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 294 (idle): "SyncWorker_30"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 295 (idle): "SyncWorker_31"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 296 (idle): "SyncWorker_32"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 297 (idle): "SyncWorker_33"
    query (MySQLdb/connections.py:259)
    _query (MySQLdb/cursors.py:319)
    execute (MySQLdb/cursors.py:206)
    do_execute (sqlalchemy/engine/default.py:593)
    _execute_context (sqlalchemy/engine/base.py:1276)
    _execute_clauseelement (sqlalchemy/engine/base.py:1124)
    _execute_on_connection (sqlalchemy/sql/elements.py:298)
    execute (sqlalchemy/engine/base.py:1011)
    _execute_and_instances (sqlalchemy/orm/query.py:3533)
    __iter__ (sqlalchemy/orm/query.py:3508)
    yield_events (homeassistant/components/logbook/__init__.py:418)
    humanify (homeassistant/components/logbook/__init__.py:251)
    _get_events (homeassistant/components/logbook/__init__.py:516)
    json_events (homeassistant/components/logbook/__init__.py:228)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 298 (idle): "SyncWorker_34"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 299 (idle): "SyncWorker_35"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 300 (idle): "SyncWorker_36"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 301 (idle): "SyncWorker_37"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 302 (idle): "SyncWorker_38"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 303 (idle): "SyncWorker_39"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 304 (idle): "SyncWorker_40"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 305 (idle): "SyncWorker_41"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 306 (idle): "SyncWorker_42"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 307 (idle): "SyncWorker_43"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 308 (idle): "SyncWorker_44"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 309 (idle): "SyncWorker_45"
    query (MySQLdb/connections.py:259)
    _query (MySQLdb/cursors.py:319)
    execute (MySQLdb/cursors.py:206)
    do_execute (sqlalchemy/engine/default.py:593)
    _execute_context (sqlalchemy/engine/base.py:1276)
    _execute_clauseelement (sqlalchemy/engine/base.py:1124)
    _execute_on_connection (sqlalchemy/sql/elements.py:298)
    execute (sqlalchemy/engine/base.py:1011)
    _execute_and_instances (sqlalchemy/orm/query.py:3533)
    __iter__ (sqlalchemy/orm/query.py:3508)
    yield_events (homeassistant/components/logbook/__init__.py:418)
    humanify (homeassistant/components/logbook/__init__.py:251)
    _get_events (homeassistant/components/logbook/__init__.py:516)
    json_events (homeassistant/components/logbook/__init__.py:228)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 310 (idle): "SyncWorker_46"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 311 (idle): "SyncWorker_47"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 312 (idle): "SyncWorker_48"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 313 (idle): "SyncWorker_49"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 314 (idle): "SyncWorker_50"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 315 (idle): "SyncWorker_51"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 320 (idle): "Thread-5"
    loop (paho/mqtt/client.py:1163)
    loop_forever (paho/mqtt/client.py:1782)
    _thread_main (paho/mqtt/client.py:3428)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 326 (idle): "Thread-6"
    select (selectors.py:415)
    handle_request (socketserver.py:294)
    run (pysonos/events.py:149)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 327 (idle): "Thread-7"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 328 (idle): "Thread-8"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 329 (idle): "Thread-9"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 331 (idle): "Thread-11"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 334 (idle): "Thread-14"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 336 (idle): "Thread-16"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 337 (idle): "Thread-17"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 340 (idle): "Thread-20"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 342 (idle): "Thread-22"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 343 (idle): "Thread-23"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 344 (idle): "Thread-24"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 346 (idle): "Thread-26"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 347 (idle): "Thread-27"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 348 (idle): "Thread-28"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 349 (idle): "Thread-29"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 353 (idle): "Thread-33"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 354 (idle): "Thread-34"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 356 (idle): "Thread-36"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 358 (idle): "Thread-38"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 360 (idle): "Thread-40"
    wait (threading.py:306)
    wait (threading.py:558)
    run (pysonos/events.py:362)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 377 (idle): "SyncWorker_52"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 378 (idle): "SyncWorker_53"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 379 (idle): "SyncWorker_54"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 380 (idle): "SyncWorker_55"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 381 (idle): "SyncWorker_56"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 382 (idle): "SyncWorker_57"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 383 (idle): "SyncWorker_58"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 384 (idle): "SyncWorker_59"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 385 (idle): "SyncWorker_60"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 386 (idle): "SyncWorker_61"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 387 (idle): "SyncWorker_62"
    query (MySQLdb/connections.py:259)
    _query (MySQLdb/cursors.py:319)
    execute (MySQLdb/cursors.py:206)
    do_execute (sqlalchemy/engine/default.py:593)
    _execute_context (sqlalchemy/engine/base.py:1276)
    _execute_clauseelement (sqlalchemy/engine/base.py:1124)
    _execute_on_connection (sqlalchemy/sql/elements.py:298)
    execute (sqlalchemy/engine/base.py:1011)
    _execute_and_instances (sqlalchemy/orm/query.py:3533)
    __iter__ (sqlalchemy/orm/query.py:3508)
    yield_events (homeassistant/components/logbook/__init__.py:418)
    humanify (homeassistant/components/logbook/__init__.py:251)
    _get_events (homeassistant/components/logbook/__init__.py:516)
    json_events (homeassistant/components/logbook/__init__.py:228)
    run (concurrent/futures/thread.py:57)
    _worker (concurrent/futures/thread.py:80)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 388 (idle): "SyncWorker_63"
    _worker (concurrent/futures/thread.py:78)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 827 (idle): "zeroconf-ServiceBrowser__printer._tcp.local.-_nut._tcp.local.-_miio._udp.local.-_esphomelib._tcp.local.-_ipps._tcp.local.-_plugwise._tcp.local.-_ssh._tcp.local.-_Volumio._tcp.local.-_elg._tcp.local.-_ipp._tcp.local.-_bond._tcp.local.-_googlecast._tcp.local.-_http._tcp.local.-_hap._tcp.local.-_axis-video._tcp.local.-_dkapi._tcp.local.-_api._udp.local.-_daap._tcp.local.-_viziocast._tcp.local.-_wled._tcp.local.-_xbmc-jsonrpc-h._tcp.local.-_spotify-connect._tcp.local._827"
    wait (threading.py:306)
    wait (zeroconf/__init__.py:2407)
    run (zeroconf/__init__.py:1701)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 828 (idle): "Thread-48"
    send_events (pyhap/accessory_driver.py:483)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 829 (idle): "Thread-49"
    select (selectors.py:415)
    serve_forever (socketserver.py:232)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 831 (idle): "Thread-51"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 832 (idle): "Thread-52"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 6015 (idle): "Thread-81"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 25348 (idle): "Thread-170"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 164849 (idle): "stream_worker"
    _stream_worker_internal (homeassistant/components/stream/worker.py:205)
    stream_worker (homeassistant/components/stream/worker.py:48)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 259889 (idle): "Thread-624"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
Thread 260522 (idle): "Thread-625"
    recv (pyhap/hap_server.py:779)
    recv_into (pyhap/hap_server.py:758)
    readinto (socket.py:669)
    handle_one_request (http/server.py:395)
    handle (http/server.py:429)
    __init__ (socketserver.py:720)
    __init__ (pyhap/hap_server.py:164)
    finish_request (pyhap/hap_server.py:943)
    process_request_thread (socketserver.py:650)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)
bash-5.0#

@bdraco
Copy link
Member

bdraco commented Sep 20, 2020

Do you have something that is constantly gathering logbook data? There are at least 5 separate logbook api requests running in your py-spy.

@gieljnssns
Copy link
Contributor Author

Did the higher cpu persist past the initial restart period?

My Core CPU is now in between 0.1% and 6%

Schermafbeelding 2020-11-13 om 09 00 38

@bdraco
Copy link
Member

bdraco commented Nov 13, 2020

The next thing to watch for is the hacs update. There was some talk about coalescing the inserts in zigpy, however I don't have a handle on where that went.

@Spirituss
Copy link

Top callbacks:

814x mqtt https://www.home-assistant.io/integrations/mqtt/
325x utility meter sensor https://www.home-assistant.io/integrations/utility_meter/
350x integration sensors https://www.home-assistant.io/integrations/integration/
352x template sensors https://www.home-assistant.io/integrations/template/

It corresponds to my subjective perception - utility meters + integration eat a huge of resources.

@gieljnssns
Copy link
Contributor Author

utility meters + integration eat a huge of resources.

And I have a lot of them
integration 23x and more coming
utility_meter 75x and more coming

@gieljnssns
Copy link
Contributor Author

Sometimes seeing warnings from integration sensor in my log

Logger: homeassistant.components.integration.sensor
Source: components/integration/sensor.py:170
Integration: integration (documentation, issues)
First occurred: 12:22:02 (4 occurrences)
Last logged: 12:43:03

Invalid state (2.0 > ): [<class 'decimal.ConversionSyntax'>]
Invalid state ( > 1.0): [<class 'decimal.ConversionSyntax'>]
Invalid state (0.0 > ): [<class 'decimal.ConversionSyntax'>]
Invalid state ( > 0.0): [<class 'decimal.ConversionSyntax'>]

@bdraco
Copy link
Member

bdraco commented Nov 13, 2020

Sometimes seeing warnings from integration sensor in my log

Logger: homeassistant.components.integration.sensor
Source: components/integration/sensor.py:170
Integration: integration (documentation, issues)
First occurred: 12:22:02 (4 occurrences)
Last logged: 12:43:03

Invalid state (2.0 > ): [<class 'decimal.ConversionSyntax'>]
Invalid state ( > 1.0): [<class 'decimal.ConversionSyntax'>]
Invalid state (0.0 > ): [<class 'decimal.ConversionSyntax'>]
Invalid state ( > 0.0): [<class 'decimal.ConversionSyntax'>]

Would you please open a new issue for that one.

@gieljnssns
Copy link
Contributor Author

Will do tomorrow....

@bdraco
Copy link
Member

bdraco commented Nov 14, 2020

Screen Shot 2020-11-13 at 6 45 54 PM

Not 100% sure what is going on here yet, but it seems unexpected that so many of these get called later.

Edit: I guess there really are that many updates happening in 60 seconds. I think we can bypass some of this for groups though since they will never be slow and shouldn't ever throw.

@gieljnssns
Copy link
Contributor Author

Now I see this in my logs

Logger: aiohttp.server
Source: components/websocket_api/http.py:81
First occurred: 12:24:31 (1 occurrences)
Last logged: 12:24:31

Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_protocol.py", line 422, in _handle_request
    resp = await self._request_handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_app.py", line 499, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_middlewares.py", line 118, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 71, in forwarded_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 18, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 72, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 127, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 129, in handle
    result = await result
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 42, in get
    return await WebSocketHandler(request.app["hass"], request).async_handle()
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 233, in async_handle
    await self._writer_task
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 81, in _writer
    await self.wsock.send_str(message)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_ws.py", line 300, in send_str
    await self._writer.send(data, binary=False, compress=compress)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/http_websocket.py", line 687, in send
    await self._send_frame(message, WSMsgType.TEXT, compress)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/http_websocket.py", line 656, in _send_frame
    await self.protocol._drain_helper()
  File "/usr/local/lib/python3.8/site-packages/aiohttp/base_protocol.py", line 87, in _drain_helper
    await waiter
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 935, in _write_ready
    n = self._sock.send(self._buffer)
BrokenPipeError: [Errno 32] Broken pipe

Do I have to open a new issue?

@bdraco
Copy link
Member

bdraco commented Nov 14, 2020

Now I see this in my logs

Logger: aiohttp.server
Source: components/websocket_api/http.py:81
First occurred: 12:24:31 (1 occurrences)
Last logged: 12:24:31

Error handling request
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_protocol.py", line 422, in _handle_request
    resp = await self._request_handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_app.py", line 499, in _handle
    resp = await handler(request)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_middlewares.py", line 118, in impl
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 71, in forwarded_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 18, in request_context_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 72, in ban_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 127, in auth_middleware
    return await handler(request)
  File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 129, in handle
    result = await result
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 42, in get
    return await WebSocketHandler(request.app["hass"], request).async_handle()
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 233, in async_handle
    await self._writer_task
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/http.py", line 81, in _writer
    await self.wsock.send_str(message)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/web_ws.py", line 300, in send_str
    await self._writer.send(data, binary=False, compress=compress)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/http_websocket.py", line 687, in send
    await self._send_frame(message, WSMsgType.TEXT, compress)
  File "/usr/local/lib/python3.8/site-packages/aiohttp/http_websocket.py", line 656, in _send_frame
    await self.protocol._drain_helper()
  File "/usr/local/lib/python3.8/site-packages/aiohttp/base_protocol.py", line 87, in _drain_helper
    await waiter
  File "/usr/local/lib/python3.8/asyncio/selector_events.py", line 935, in _write_ready
    n = self._sock.send(self._buffer)
BrokenPipeError: [Errno 32] Broken pipe

Do I have to open a new issue?

Yes please. It likely just means the connection wasn't closed cleanly. I doubt it actually affects anything.

@mudape
Copy link

mudape commented Nov 14, 2020

This component is using a bit more time than I would expect.

https://github.com/mudape/iphonedetect/blob/master/custom_components/iphonedetect/device_tracker.py

It would be much faster if it switched to using something pyroute2 since there wouldn't be any fork/exec() overhead.

Thanks @bdraco
Long thread this, don't know who have high cpu usage with iphonedetect.
I've released a beta with pyroute2, please test :)

@bdraco
Copy link
Member

bdraco commented Nov 14, 2020

@gieljnssns Can you give the above a shot ^

@gieljnssns
Copy link
Contributor Author

@bdraco
0.118.0b2 with beta from iphonedetect https://www.dropbox.com/s/ip9w1fucavrmq5k/spy-0.118b2-10min.svg?dl=0
Profile send with mail

@gieljnssns
Copy link
Contributor Author

Schermafbeelding 2020-11-15 om 11 27 29

@bdraco
Copy link
Member

bdraco commented Nov 15, 2020

Thanks. The latency in the event loop is better because it doesn't have to suspend to execute the subprocess.

Unfortunately the overhead of parsing the the netlink messages is using more cpu time since the python version is slower than the c version as there must be a large number of neighbors on your host. The overall result was likely better for me since I don't have as many neighbors on my host.

pyroute2 has filtering https://docs.pyroute2.org/iproute.html#pyroute2.iproute.IPRouteMixin.get_neighbors so we may be able to use that to avoid some of the parse overhead for a net win.

Potentially something like this might be faster:
ip.get_neighbours(dst=xxxx, match=lambda x: x['state'] == 2)

I'll do some testing today if I don't run out of time.

cc @mudape

@bdraco
Copy link
Member

bdraco commented Nov 15, 2020

from pyroute2 import IPRoute
import cProfile

ip = IPRoute()
pr = cProfile.Profile()
pr.enable()
ip.neigh("dump", dst="192.168.208.5")
pr.disable()
pr.create_stats()
pr.dump_stats("pyroute.cprof")

For testing

@bdraco
Copy link
Member

bdraco commented Nov 15, 2020

It looks like this is what we need to limit the query svinota/pyroute2#723

@bdraco
Copy link
Member

bdraco commented Nov 15, 2020

Well it looks like that is only supported on newer kernels so there is no way to get a single record on older kernels which means the only way is to dump the whole table and filter. That is unfortunate, as I don't think we have a way to make this faster without a kernel upgrade.

Even on 4.4.59, get isn't implemented

root@ha-dev:~/pyroute2# ip neigh get 192.168.208.1
Sorry, "neigh get" is not implemented :-(

@bdraco
Copy link
Member

bdraco commented Nov 15, 2020

I did find some more polling that shouldn't be happening in the latest profiles. I've cleaned that up in 0.119dev.

@bdraco
Copy link
Member

bdraco commented Nov 16, 2020

HACS beta 1.8.0 has been tagged https://github.com/hacs/integration/releases with the performance cleanups I mentioned above.

@gieljnssns
Copy link
Contributor Author

py-spy with Hacs beta https://www.dropbox.com/s/jbujvcr5z80prot/spy-0.118b2-10min-hacs_beta.svg?dl=0
Profile is send

@bdraco
Copy link
Member

bdraco commented Nov 16, 2020

Screen Shot 2020-11-16 at 8 23 18 AM

There are still a lot of calls to async_add_job that don't pre-check the callable type.

Its likely this block in mqtt

    def _mqtt_on_message(self, _mqttc, _userdata, msg) -> None:
        """Message received callback."""
        self.hass.add_job(self._mqtt_handle_message, msg)

@github-actions
Copy link

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

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