From 90ea065cff59bd60cf63c94118027de1641babf3 Mon Sep 17 00:00:00 2001 From: azogue Date: Mon, 29 May 2017 10:06:11 +0200 Subject: [PATCH 1/2] log time delay of domain setup in info level * when setup problems appear, it's difficult to debug which are the components that took a lot to set up. This minimal change goes further than the 'slow setup warning' and measures the setup time interval for each domain. --- homeassistant/setup.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index e3a520fff0ed93..a6a7fdc49b5fee 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -3,6 +3,7 @@ import logging import logging.handlers import os +from time import time from types import ModuleType from typing import Optional, Dict @@ -175,6 +176,7 @@ def log_error(msg, link=True): async_comp = hasattr(component, 'async_setup') + tic = time() _LOGGER.info("Setting up %s", domain) warn_task = hass.loop.call_later( SLOW_SETUP_WARNING, _LOGGER.warning, @@ -191,6 +193,8 @@ def log_error(msg, link=True): async_notify_setup_error(hass, domain, True) return False finally: + _LOGGER.info("Setup of domain %s took %.1f seconds.", + domain, time() - tic) warn_task.cancel() if result is False: From 8d6293e63a43f675b228fbd6271852eae7e9bb33 Mon Sep 17 00:00:00 2001 From: azogue Date: Mon, 29 May 2017 16:06:48 +0200 Subject: [PATCH 2/2] use timer as in helpers/entity --- homeassistant/setup.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/homeassistant/setup.py b/homeassistant/setup.py index a6a7fdc49b5fee..285a5755145132 100644 --- a/homeassistant/setup.py +++ b/homeassistant/setup.py @@ -3,7 +3,7 @@ import logging import logging.handlers import os -from time import time +from timeit import default_timer as timer from types import ModuleType from typing import Optional, Dict @@ -176,7 +176,7 @@ def log_error(msg, link=True): async_comp = hasattr(component, 'async_setup') - tic = time() + start = timer() _LOGGER.info("Setting up %s", domain) warn_task = hass.loop.call_later( SLOW_SETUP_WARNING, _LOGGER.warning, @@ -193,9 +193,9 @@ def log_error(msg, link=True): async_notify_setup_error(hass, domain, True) return False finally: - _LOGGER.info("Setup of domain %s took %.1f seconds.", - domain, time() - tic) + end = timer() warn_task.cancel() + _LOGGER.info("Setup of domain %s took %.1f seconds.", domain, end - start) if result is False: log_error("Component failed to initialize.")