Add warning for slow platforms/components (#6467)

* Add warning for slow platforms/components

* Add test for slow component setup.

* Add test for slow platform setup

* Fix tests on Py34

homeassistant/helpers/entity_component.py

@@ -18,6 +18,7 @@ from homeassistant.util.async import (
     run_callback_threadsafe, run_coroutine_threadsafe)
 
 DEFAULT_SCAN_INTERVAL = timedelta(seconds=15)
+SLOW_SETUP_WARNING = 10
 
 
 class EntityComponent(object):
@@ -134,8 +135,13 @@ class EntityComponent(object):
                 self, platform_type, scan_interval, entity_namespace)
         entity_platform = self._platforms[key]
 
+        self.logger.info("Setting up %s.%s", self.domain, platform_type)
+        warn_task = self.hass.loop.call_later(
+            SLOW_SETUP_WARNING, self.logger.warning,
+            'Setup of platform %s is taking over %s seconds.', platform_type,
+            SLOW_SETUP_WARNING)
+
         try:
-            self.logger.info("Setting up %s.%s", self.domain, platform_type)
             if getattr(platform, 'async_setup_platform', None):
                 yield from platform.async_setup_platform(
                     self.hass, platform_config,
@@ -154,6 +160,8 @@ class EntityComponent(object):
         except Exception:  # pylint: disable=broad-except
             self.logger.exception(
                 'Error while setting up platform %s', platform_type)
+        finally:
+            warn_task.cancel()
 
     def add_entity(self, entity, platform=None, update_before_add=False):
         """Add entity to component."""

homeassistant/setup.py

@@ -21,6 +21,8 @@ ATTR_COMPONENT = 'component'
 DATA_SETUP = 'setup_tasks'
 DATA_PIP_LOCK = 'pip_lock'
 
+SLOW_SETUP_WARNING = 10
+
 
 def setup_component(hass: core.HomeAssistant, domain: str,
                     config: Optional[Dict]=None) -> bool:
@@ -172,8 +174,12 @@ def _async_setup_component(hass: core.HomeAssistant,
 
     async_comp = hasattr(component, 'async_setup')
 
+    _LOGGER.info("Setting up %s", domain)
+    warn_task = hass.loop.call_later(
+        SLOW_SETUP_WARNING, _LOGGER.warning,
+        'Setup of %s is taking over %s seconds.', domain, SLOW_SETUP_WARNING)
+
     try:
-        _LOGGER.info("Setting up %s", domain)
         if async_comp:
             result = yield from component.async_setup(hass, processed_config)
         else:
@@ -183,6 +189,8 @@ def _async_setup_component(hass: core.HomeAssistant,
         _LOGGER.exception('Error during setup of component %s', domain)
         async_notify_setup_error(hass, domain, True)
         return False
+    finally:
+        warn_task.cancel()
 
     if result is False:
         log_error('Component failed to initialize.')

tests/helpers/test_entity_component.py

@@ -4,7 +4,7 @@ import asyncio
 from collections import OrderedDict
 import logging
 import unittest
-from unittest.mock import patch, Mock
+from unittest.mock import patch, Mock, MagicMock
 from datetime import timedelta
 
 import homeassistant.core as ha
@@ -12,7 +12,7 @@ import homeassistant.loader as loader
 from homeassistant.components import group
 from homeassistant.helpers.entity import Entity, generate_entity_id
 from homeassistant.helpers.entity_component import (
-    EntityComponent, DEFAULT_SCAN_INTERVAL)
+    EntityComponent, DEFAULT_SCAN_INTERVAL, SLOW_SETUP_WARNING)
 
 from homeassistant.helpers import discovery
 import homeassistant.util.dt as dt_util
@@ -410,3 +410,30 @@ class TestHelpersEntityComponent(unittest.TestCase):
             return entity
 
         component.add_entities(create_entity(i) for i in range(2))
+
+
+@asyncio.coroutine
+def test_platform_warn_slow_setup(hass):
+    """Warn we log when platform setup takes a long time."""
+    platform = MockPlatform()
+
+    loader.set_component('test_domain.platform', platform)
+
+    component = EntityComponent(_LOGGER, DOMAIN, hass)
+
+    with patch.object(hass.loop, 'call_later', MagicMock()) \
+            as mock_call:
+        yield from component.async_setup({
+            DOMAIN: {
+                'platform': 'platform',
+            }
+        })
+        assert mock_call.called
+        assert len(mock_call.mock_calls) == 2
+
+        timeout, logger_method = mock_call.mock_calls[0][1][:2]
+
+        assert timeout == SLOW_SETUP_WARNING
+        assert logger_method == _LOGGER.warning
+
+        assert mock_call().cancel.called

tests/test_setup.py

@@ -407,3 +407,23 @@ def test_component_cannot_depend_config(hass):
     result = yield from setup._async_process_dependencies(
         hass, None, 'test', ['config'])
     assert not result
+
+
+@asyncio.coroutine
+def test_component_warn_slow_setup(hass):
+    """Warn we log when a component setup takes a long time."""
+    loader.set_component('test_component1', MockModule('test_component1'))
+    with mock.patch.object(hass.loop, 'call_later', mock.MagicMock()) \
+            as mock_call:
+        result = yield from setup.async_setup_component(
+            hass, 'test_component1', {})
+        assert result
+        assert mock_call.called
+        assert len(mock_call.mock_calls) == 2
+
+        timeout, logger_method = mock_call.mock_calls[0][1][:2]
+
+        assert timeout == setup.SLOW_SETUP_WARNING
+        assert logger_method == setup._LOGGER.warning
+
+        assert mock_call().cancel.called