0.40.0 Setup of [X] is taking over 10 seconds and slow startup

Configuration
1

After upgrading to 0.40.0 my startup takes forever and it seems like every component is throwing this warning:

17-03-11 18:36:51 WARNING (MainThread) [homeassistant.setup] Setup of sensor is taking over 10 seconds.
17-03-11 18:36:51 WARNING (MainThread) [homeassistant.setup] Setup of switch is taking over 10 seconds.
17-03-11 18:36:51 WARNING (MainThread) [homeassistant.setup] Setup of cover is taking over 10 seconds.
17-03-11 18:36:51 WARNING (MainThread) [homeassistant.setup] Setup of notify is taking over 10 seconds.
17-03-11 18:36:51 WARNING (MainThread) [homeassistant.setup] Setup of light is taking over 10 seconds.
17-03-11 18:36:52 WARNING (MainThread) [homeassistant.setup] Setup of automation is taking over 10 seconds.
17-03-11 18:36:52 WARNING (MainThread) [homeassistant.setup] Setup of input_select is taking over 10 seconds.
17-03-11 18:36:52 WARNING (MainThread) [homeassistant.setup] Setup of binary_sensor is taking over 10 seconds.
17-03-11 18:36:52 WARNING (MainThread) [homeassistant.setup] Setup of input_slider is taking over 10 seconds.
17-03-11 18:36:52 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform template is taking over 10 seconds.
17-03-11 18:36:52 WARNING (MainThread) [homeassistant.setup] Setup of device_tracker is taking over 10 seconds.
17-03-11 18:36:54 WARNING (MainThread) [homeassistant.setup] Setup of media_player is taking over 10 seconds.
17-03-11 18:37:01 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform speedtest is taking over 10 seconds.

Is this normal? I would say a startup takes 2x as long now as it did in 0.39.3.

1 Like
2

That is a good question.
I have the same problem just reboot and there continue to receive the warnings although not all of them.
I will love to know that answer too.

3

First run after an upgrade takes much longer. See if it still takes a long time to restart after the first startup.

4

same problem here

[homeassistant.setup] Setup of device_tracker is taking over 10 seconds

Also

[SSL: CERTIFICATE_VERIFY_FAILED] certificate verify failed

But i do not use SSL

Im getting alot of errors after upgrade

5

It’s really worth reading the release notes when you upgrade.

We have also continued with adding warnings for components and platforms that are slowing down Home Assistant.

Some people have interpreted our recent added warnings as if 0.39 introduced the issues that caused the warning. This is not the case, the platforms and components have been misbehaving for a while but now we are adding warnings so we are able to track down the culprits.

As Sam said, the first post-upgrade start takes a lot longer than normal. After that it’ll be quicker. For me it now takes under 40 seconds to start, but the first start after upgrade took about 8 minutes.

6

@Tinkerer I do read the release notes, thanks. Every release. But they didn’t explain:

  1. What I was going to see in the logs (this?)
  2. What to do about it.

Furthermore some of them don’t even make any sense. input_slider? I think I have 2 of them.

As for the startup time, just clocked it at 3.5 minutes. :frowning: AT LEAST twice as long as 0.39.3. Probably more like 3 times as long.

2 Likes
7

Well, there’s nothing to do about it. What you’re seeing are the added warnings that are referred to. The only way to fix them is to remove them, or wait for the devs to resolve the underlying issues.

Now, if every startup is taking 3.5 minutes, you’ll want to post an entire startup log, so that others can help you identify which components are causing you issues.

8

Ahhh ok, that helps, thanks! I was thinking there was something I needed to do.

As for the startup, this is the last one I just had. Didn’t time it but judging by the timestamps I’m going to say it was about the same:

17-03-12 12:12:01 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=442 from 2017-03-12 16:05:02)
17-03-12 12:12:06 WARNING (Thread-6) [homeassistant.components.emulated_hue] Alexa type is deprecated and will be removed in a future version
17-03-12 12:12:12 WARNING (MainThread) [homeassistant.setup] Setup of light is taking over 10 seconds.
17-03-12 12:12:12 WARNING (MainThread) [homeassistant.setup] Setup of input_slider is taking over 10 seconds.
17-03-12 12:12:12 WARNING (MainThread) [homeassistant.setup] Setup of input_select is taking over 10 seconds.
17-03-12 12:12:13 WARNING (MainThread) [homeassistant.setup] Setup of sensor is taking over 10 seconds.
17-03-12 12:12:13 WARNING (MainThread) [homeassistant.setup] Setup of cover is taking over 10 seconds.
17-03-12 12:12:13 WARNING (MainThread) [homeassistant.setup] Setup of switch is taking over 10 seconds.
17-03-12 12:12:13 WARNING (MainThread) [homeassistant.setup] Setup of notify is taking over 10 seconds.
17-03-12 12:12:14 WARNING (MainThread) [homeassistant.setup] Setup of automation is taking over 10 seconds.
17-03-12 12:12:14 WARNING (MainThread) [homeassistant.setup] Setup of binary_sensor is taking over 10 seconds.
17-03-12 12:12:14 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform template is taking over 10 seconds.
17-03-12 12:12:15 WARNING (Thread-5) [homeassistant.components.light.hue] Connected to Hue at 192.168.9.204 but not registered.
17-03-12 12:12:15 WARNING (MainThread) [homeassistant.setup] Setup of device_tracker is taking over 10 seconds.
17-03-12 12:12:18 WARNING (MainThread) [homeassistant.setup] Setup of media_player is taking over 10 seconds.
17-03-12 12:12:23 WARNING (MainThread) [homeassistant.setup] Setup of wink is taking over 10 seconds.
17-03-12 12:12:27 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform speedtest is taking over 10 seconds.
17-03-12 12:15:26 WARNING (Thread-11) [homeassistant.components.zwave] zwave not ready after 30 seconds, continuing anyway
17-03-12 12:15:50 ERROR (MainThread) [homeassistant.core] Timer got out of sync. Resetting
9

That presumably is from home-assistant.log, which doesn’t show the detail needed. What does your console log show (if you used the AIO it’ll be using systemd, so journalctl -u home-assistant is the command you need)?

Here’s the relevant lines from mine:

Mar 12 10:15:59 jarvis systemd[1]: Starting Home Assistant...
Mar 12 10:15:59 jarvis systemd[1]: Started Home Assistant.
....
Mar 12 10:16:35 jarvis hass[21248]: INFO:homeassistant.components.http:Serving /api/websocket to a.b.c.d (auth: True)

That line with Serving /api/... is where it shows that HA has started.

10

Ahh ok. I have ~1300 lines of log file up to this point:

Mar 12 13:49:29 raspberrypi hass[3939]: INFO:homeassistant.components.http:Serving /api/websocket to 192.168.9.1 (auth: False)

The address shown is my gateway so not sure if that’s normal. Anyway do you want me to post the full 1300 lines of log file to like pastebin or something? Or is there something specific I should be looking for?

11

Just the snippet I had - basically the pair of Starting lines, followed by the first occurrence of INFO:homeassistant.components.http:Serving. Best to take a fresh set by restarting HA, so that any post upgrade processes aren’t the cause.

That will show how long it’s taking to start up. After that, if it’s still many minutes long, it may well be worth posting the full log to Pastebin or similar, having redacted anything you want hidden.

12

Yeah, still seeing about 3.5 minutes to start now almost 24 hours post upgrade (and at least a half-dozen restarts since - been working on some changes today). And still ~1000 lines from the pair of starting lines to the line I posted. Full dump can be found here: http://pastebin.com/qr8DaaJS (took me a bit to redact everything, lol)

13

So, a quick skim of that hints that you’ve a “not small” config. Posting a redacted version of that may help others diagnose the issues.

I do note though that in that example, there are still package installs going on:

Mar 12 17:43:04 raspberrypi hass[9979]: INFO:homeassistant.util.package:Attempting install of https://github.com/arraylabs/pymyq/archive/v0.0.7.zip#pymyq==0.0.7

Wink takes a long time, from first to last:

Mar 12 17:42:58 raspberrypi hass[9979]: INFO:homeassistant.setup:Setting up wink
...
Mar 12 17:45:47 raspberrypi hass[9979]: INFO:homeassistant.components.sensor:Setting up sensor.wink

What if, for the purposes of testing, you disable Wink and restart? Does that help the startup time?

14

There seams to be a bug in the pymyq library that makes it reinstall each time you restart HA.
This line


should be version='0.0.7',

You should report the issue here https://github.com/arraylabs/pymyq/issues/new

1 Like
15

@Tinkerer disabling of Wink didn’t change anything. Still about 3.5 minutes. I also not long ago went through and moved anything super-sensitive to the secret file so this is a good version of my config: http://pastebin.com/3ynevj2D

I did flip through the log and found this ~2 minute delay maybe with the speedtest platform?

Mar 13 15:06:40 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=clear_playlist>
Mar 13 15:06:40 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=media_play_pause>
Mar 13 15:06:40 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=media_previous_track>
Mar 13 15:06:40 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event component_loaded[L]: component=media_player>
Mar 13 15:06:40 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=None, new_state=<state sensor.x=7; friendly_name=USPS, departed_shipping_partner_facility=2, icon=mdi:package-variant-closed, attribution=Information provided by www.usps.com, preshipment_info_sent_to_usps=1, delivered=4 @ 2017-03-13T15:06:40.626728-04:00>, entity_id=sensor.x>
Mar 13 15:06:42 raspberrypi hass[17980]: WARNING:homeassistant.components.sensor:Setup of platform speedtest is taking over 10 seconds.
Mar 13 15:08:55 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=None, new_state=<state input_slider.dr_off_delay=1.0; friendly_name=DR Off Delay, step=0.5, min=0.0, max=20.0 @ 2017-03-13T15:08:55.858517-04:00>, entity_id=input_slider.dr_off_delay>
Mar 13 15:08:55 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=None, new_state=<state input_slider.random_minute=41.0; friendly_name=Random Minute, step=1.0, min=0.0, max=59.0 @ 2017-03-13T15:08:55.864681-04:00>, entity_id=input_slider.random_minute>
Mar 13 15:08:55 raspberrypi hass[17980]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: old_state=None, new_state=<state input_slider.random_hour=22.0; friendly_name=Random Hour, step=1.0, min=0.0, max=23.0 @ 2017-03-13T15:08:55.870709-04:00>, entity_id=input_slider.random_hour>
Mar 13 15:08:55 raspberrypi hass[17980]: INFO:homeassistant.components.automation:Initialized trigger Turn on humidifier and such school/work night

HOWEVER after disabling THAT the startup times are still ~3.5 minutes. So looking again maybe the media player?

Mar 13 15:15:46 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=volume_set>
Mar 13 15:15:46 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=media_previous_track>
Mar 13 15:15:46 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=toggle>
Mar 13 15:15:46 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=media_seek>
Mar 13 15:15:46 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event service_registered[L]: domain=media_player, service=turn_off>
Mar 13 15:15:46 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event component_loaded[L]: component=media_player>
Mar 13 15:18:00 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: new_state=<state input_slider.random_hour=22.0; max=23.0, friendly_name=Random Hour, min=0.0, step=1.0 @ 2017-03-13T15:18:00.185551-04:00>, entity_id=input_slider.random_hour, old_state=None>
Mar 13 15:18:00 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: new_state=<state input_slider.random_minute=41.0; max=59.0, friendly_name=Random Minute, min=0.0, step=1.0 @ 2017-03-13T15:18:00.189658-04:00>, entity_id=input_slider.random_minute, old_state=None>
Mar 13 15:18:00 raspberrypi hass[18286]: INFO:homeassistant.core:Bus:Handling <Event state_changed[L]: new_state=<state input_slider.dr_off_delay=1.0; max=20.0, friendly_name=DR Off Delay, min=0.0, step=0.5 @ 2017-03-13T15:18:00.194125-04:00>, entity_id=input_slider.dr_off_delay, old_state=None>
Mar 13 15:18:00 raspberrypi hass[18286]: INFO:homeassistant.components.automation:Initialized trigger Turn on humidifier and such school/work night

I feel like I’m chasing a ghost here and that there is a larger underlying issue. Any thoughts?

@Danielhiversen I’ll make sure I do that when I get home, thanks!

16

Sadly no, in this case the most effective way of identifying the problem is always to disable everything, and then roll forwards.

  1. First pass, disable everything and start.
  2. Select half of your additions, re-enable them.
  3. If that works, repeat the process. If it fails, disable half and repeat

Basically, it’s an iterative process. If you’re lucky, it’ll still misbehave at the first step, in which case it’s either a problem with the database, or the hardware you’re running on.

17

When you said database I thought perhaps I would go and check MySQL. I added a few energy monitors like 3 weeks ago and even with the “purge_days” set at 7 the database was still 12GB o.O (a 32GB microSD card in a Pi3 isn’t meant for that, lol) I nuked the DB (nothing in there I really needed) and startup is now ~45 seconds. :smiley: Now to figure out how I want to deal with all the data coming from those energy monitors.

Still seeing the “setup of bla is taking over 10 seconds” though it doesn’t appear to be an actual issue at this point. Thanks for your assistance!

17-03-13 15:52:22 WARNING (Thread-11) [homeassistant.components.emulated_hue] Alexa type is deprecated and will be removed in a future version
17-03-13 15:52:26 WARNING (MainThread) [homeassistant.setup] Setup of sensor is taking over 10 seconds.
17-03-13 15:52:27 WARNING (MainThread) [homeassistant.setup] Setup of light is taking over 10 seconds.
17-03-13 15:52:27 WARNING (MainThread) [homeassistant.setup] Setup of binary_sensor is taking over 10 seconds.
17-03-13 15:52:27 WARNING (MainThread) [homeassistant.setup] Setup of cover is taking over 10 seconds.
17-03-13 15:52:27 WARNING (MainThread) [homeassistant.setup] Setup of notify is taking over 10 seconds.
17-03-13 15:52:27 WARNING (MainThread) [homeassistant.setup] Setup of switch is taking over 10 seconds.
17-03-13 15:52:29 WARNING (MainThread) [homeassistant.setup] Setup of media_player is taking over 10 seconds.
17-03-13 15:53:22 WARNING (Thread-10) [homeassistant.components.zwave] zwave not ready after 30 seconds, continuing anyway
18

Glad you made progress.

Yeah, running a database of that size on an SD card is going to be a problem. Maybe a second Pi running from an SSD to host it if you need that kind of retention?

19

I have a VM stack I can always put a a database on, just preferred the Pi for HA since USB passthrough can be finicky in ESXi. I just don’t know if I actually need that retention. Thanks for your help!

20

I updated the file and submitted a pull request. Good catch!

1 Like