Hikvision sensor component causes high-cpu in multi-sensor setup

[vladm]

Environment: haas 0.39.1 started as a fresh container from official docker image.

Issue: bare configuration with two hikvision sensors defined as shown below causes python process to stick at high-cpu usage (~70%). Removing one of the sensor's from configuration.yaml resolves the issue

Problem-relevant configuration.yaml entries and steps to reproduce:

binary_sensor:
- platform: hikvision
  host: xx.xx.xx.10
  port: 80
  ssl: False
  username: aaa
  password: bbb

- platform: hikvision
  host: xx.xx.xx.20
  port: 80
  ssl: False
  username: aaa
  password: bbb

Additional info: original discussion with hikvision component's maintainer @mezz64 started in issue #6165

[mezz64]

Ok lets try to clear up a few things. Is it correct to say that you didn't have this behavior prior to 0.39.1? Can you test running 0.39.1 with netdisco rolled back as described in #6165 and see if this behavior persists? Does it matter which sensor you disable?

[vladm]

I tested it with 0.38.x and have the same issue. I simply added the second camera into configuration recently, before I had only one.

[mezz64]

Does it matter which camera you disable? I'm trying to rule out that the new camera may be causing some weird condition to occur.

In any case please set the hikvision platforms to debug logging:

pyhik.hikvision: debug
homeassistant.components.binary_sensor.hikvision: debug

and provide a log for when both are defined and you get the high cpu usage. If it ends up being a single camera that's causing it provide a log trace for just that single camera as well.

I actually have a pending PR to update the hass hikvision implementation, but it doesn't change the core operation of the stream processing thread so i'm skeptical it would fix your issue.

[vladm]

OK, so it's really a single camera that's causing the issue. The models are slightly different.

Here is the log from "bad" (DS-2CD2542FWD-IS) camera - that causes high-cpu:

INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_off>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_on>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=toggle>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=stop>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=restart>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=check_config>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=reload_core_config>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=create>
INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
INFO (MainThread) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
INFO (MainThread) [homeassistant.loader] Loaded api from homeassistant.components.api
INFO (MainThread) [homeassistant.loader] Loaded http from homeassistant.components.http
INFO (MainThread) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
INFO (MainThread) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
INFO (MainThread) [homeassistant.loader] Loaded logger from homeassistant.components.logger
INFO (MainThread) [homeassistant.bootstrap] Setting up logger
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logger>
INFO (MainThread) [homeassistant.bootstrap] Setting up http
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
INFO (MainThread) [homeassistant.bootstrap] Setting up api
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=api>
INFO (MainThread) [homeassistant.bootstrap] Setting up websocket_api
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=websocket_api>
INFO (MainThread) [homeassistant.bootstrap] Setting up frontend
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=frontend>
INFO (MainThread) [homeassistant.loader] Loaded binary_sensor.hikvision from homeassistant.components.binary_sensor.hikvision
INFO (MainThread) [homeassistant.bootstrap] Setting up binary_sensor
INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.hikvision
DEBUG (Thread-6) [pyhik.hikvision] Initializing new hikvision device at: http://10.7.7.179
DEBUG (Thread-6) [pyhik.hikvision] Using Namespace: http://www.hikvision.com/ver20/XMLSchema
DEBUG (Thread-6) [pyhik.hikvision] Found events: ['VMD', 'diskfull']
DEBUG (Thread-6) [pyhik.hikvision] Initialized Dictionary: {'Disk Full': [False, 1, 0, datetime.datetime(2017, 3, 2, 16, 44, 1, 411474)], 'Motion': [False, 1, 0, datetime.datetime(2017, 3, 2, 16, 44, 1, 411394)]}
DEBUG (Thread-12) [pyhik.hikvision] Stream Thread Started: CAMERA, 5269afcc-ea79-11b4-8390-a4143724644a
DEBUG (Thread-6) [homeassistant.components.binary_sensor.hikvision] Entity: CAMERA - Disk_Full, Options - Ignore: None, Delay: None
DEBUG (Thread-6) [homeassistant.components.binary_sensor.hikvision] Entity: CAMERA - Motion, Options - Ignore: None, Delay: None
INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.camera_disk_full, new_state=<state binary_sensor.camera_disk_full=off; last_tripped_time=2017-03-02T10:44:01.411474-06:00, friendly_name=CAMERA Disk Full @ 2017-03-02T16:44:01.438357-06:00>, old_state=None>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.camera_motion, new_state=<state binary_sensor.camera_motion=off; last_tripped_time=2017-03-02T10:44:01.411394-06:00, friendly_name=CAMERA Motion, device_class=motion @ 2017-03-02T16:44:01.442973-06:00>, old_state=None>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=binary_sensor>
INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop
INFO (MainThread) [homeassistant.core] Starting Home Assistant
INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
INFO (MainThread) [homeassistant.core] Timer:starting

log with good camera (DS-2CD2142FWD-I), no high-cpu

INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_off>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_on>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=toggle>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=stop>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=restart>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=check_config>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=reload_core_config>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=create>
INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
INFO (MainThread) [homeassistant.loader] Loaded frontend from homeassistant.components.frontend
INFO (MainThread) [homeassistant.loader] Loaded api from homeassistant.components.api
INFO (MainThread) [homeassistant.loader] Loaded http from homeassistant.components.http
INFO (MainThread) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
INFO (MainThread) [homeassistant.loader] Loaded binary_sensor from homeassistant.components.binary_sensor
INFO (MainThread) [homeassistant.loader] Loaded logger from homeassistant.components.logger
INFO (MainThread) [homeassistant.bootstrap] Setting up logger
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=logger>
INFO (MainThread) [homeassistant.bootstrap] Setting up http
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
INFO (MainThread) [homeassistant.bootstrap] Setting up api
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=api>
INFO (MainThread) [homeassistant.bootstrap] Setting up websocket_api
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=websocket_api>
INFO (MainThread) [homeassistant.bootstrap] Setting up frontend
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=frontend>
INFO (MainThread) [homeassistant.loader] Loaded binary_sensor.hikvision from homeassistant.components.binary_sensor.hikvision
INFO (MainThread) [homeassistant.bootstrap] Setting up binary_sensor
INFO (MainThread) [homeassistant.components.binary_sensor] Setting up binary_sensor.hikvision
DEBUG (Thread-6) [pyhik.hikvision] Initializing new hikvision device at: http://10.7.7.178
DEBUG (Thread-6) [pyhik.hikvision] Using Namespace: http://www.hikvision.com/ver20/XMLSchema
DEBUG (Thread-6) [pyhik.hikvision] Found events: ['VMD', 'diskfull']
DEBUG (Thread-6) [pyhik.hikvision] Initialized Dictionary: {'Motion': [False, 1, 0, datetime.datetime(2017, 3, 2, 16, 47, 1, 995383)], 'Disk Full': [False, 1, 0, datetime.datetime(2017, 3, 2, 16, 47, 1, 995460)]}
DEBUG (Thread-12) [pyhik.hikvision] Stream Thread Started: CAMERA, 0024cf00-5aac-11b4-82d9-bcad28dcc7eb
DEBUG (Thread-6) [homeassistant.components.binary_sensor.hikvision] Entity: CAMERA - Motion, Options - Ignore: None, Delay: None
DEBUG (Thread-6) [homeassistant.components.binary_sensor.hikvision] Entity: CAMERA - Disk_Full, Options - Ignore: None, Delay: None
INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state binary_sensor.camera_motion=off; friendly_name=CAMERA Motion, device_class=motion, last_tripped_time=2017-03-02T10:47:01.995383-06:00 @ 2017-03-02T16:47:02.026858-06:00>, old_state=None, entity_id=binary_sensor.camera_motion>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: new_state=<state binary_sensor.camera_disk_full=off; friendly_name=CAMERA Disk Full, last_tripped_time=2017-03-02T10:47:01.995460-06:00 @ 2017-03-02T16:47:02.038794-06:00>, old_state=None, entity_id=binary_sensor.camera_disk_full>
INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=binary_sensor>
INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop
INFO (MainThread) [homeassistant.core] Starting Home Assistant
INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
INFO (MainThread) [homeassistant.core] Timer:starting

[mezz64]

Unfortunately, nothing obvious there. We can work through some more things, but since this is likely a pyHik issue and not a HASS one can you close this and open an issue on the pyHik repository: https://github.com/mezz64/pyHik

A key extra detail at the moment would be what firmware version the cameras are on.