log time delay of domain setup in info level

[azogue]

Description:

When setup problems appear in a complex config, 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.

Example entry for configuration.yaml (if applicable):

logger:
  default: warn
  logs:
    homeassistant.setup: info

[mention-bot]

@azogue, thanks for your PR! By analyzing the history of the files in this pull request, we identified @balloob and @fabaff to be potential reviewers.

[azogue]

Origin of this PR:
In a RPI3 which is the main controller at home, I have setup times of 30-50 secs, and at least 3 domains that take more than 10 secs (the warning msg).

After some changes and a big update, I went from 40secs to 750 secs!! of setup time, with no clues and a lot of 'slow' domain setups, and I missed some info about the time needed for each domain.

It turned out to be the recorder, which was a mysql db in other machine (a NAS). Changing to a local mysql fixed my setup time to 30s.

[pvizeli]

I'm not sure how helpfull that is. We have no controll over the asnyc loop, so you timestamp is not realy correct. The same problem is with the warnings.

You had track that problem with this change? Look also into helper/entity.py to see how messure need to look for work correct.

[azogue]

@pvizeli, you mean like this?

from timeit import default_timer as timer

start = timer()
...
...
finally:
    warn_task.cancel()
end = timer()
_LOGGER.info("Setup of domain %s took %.1f seconds.", domain, end - start)

I know it is not a good measure, and the time consumed by each domain is going to be variable, but in my experience with the headache I described, this pseudo-measure helped me to see where the problem was. As you are now logging the starting point of each domain setup in the info level, I thought it could be useful for other people to log also the end point, so has it be for me.

I normally don't use the info level with components.setup, but when making changes, or upgrading, I usually activate some more logging.

[pvizeli]

For me is okay, @balloob ?

[balloob]

It's fine with me but I think that the info about component setup time might not be as interesting compared to the info on a per platform basis? https://github.com/home-assistant/home-assistant/blob/dev/homeassistant/helpers/entity_component.py#L147-L173

[azogue]

@balloob, I could do the same per platform, or only per platform, as requested.
As I understand it, the logging added in the PR affects the components.setup logging 'channel', but doing the same in entity_component will affect each platform in its info level, isn't it?
So the yaml config requested for seeing the log msg would be:

logger:
  default: warn
  logs:
    # for the per-domain msg:
    homeassistant.setup: info
    # for the per-platform msg:
    components.XXXX.YYYY: info

[balloob]

We always print info and higher (error etc). Only debug is not printed to the console.