Thanks for your assistance. I tried different things and was able to stop core faster but there is still some unknown delay in it. Following is the description what I did.
I see that after restart event only the websocket stream to the browser stops immediately but I still see most sensors sending data to the MainThread. I inititated restart via homeassistant.restart service. I removed some integrations (like tracker) to keep log for myself a little bit shorter.
I think this is normal that between restart service call and homeassistant_stop event it takes couple of seconds if there are multiple events in the queue that still needs to be processed.
I often see long time between homeassistant_stop and homeassistant_final_write and random state_changed events during this time. This is where most time goes.
Here it takes 28 sec while first 3 sec goes from service call to homeassistant_stop event.
2020-08-21 08:26:24 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L] domain=homeassistant, service=restart, service_data=>
ā¦ many Bus:Handling <Event state_changed[L] from other sensors ā¦
2020-08-21 08:26:27 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_stop[L]
2020-08-21 08:26:35 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.influxdb_bme280_temperature, old_state=<state sensor.influxdb_bme280_temperature=19.4; unit_of_measurement=Ā°C, friendly_name=Temperatuur vƤljas @ 2020-08-21T11:25:35.262676+03:00>, new_state=<state sensor.influxdb_bme280_temperature=19.6; unit_of_measurement=Ā°C, friendly_name=Temperatuur vƤljas @ 2020-08-21T11:26:35.285844+03:00>>
2020-08-21 08:26:38 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=binary_sensor.iss, old_state=<state binary_sensor.iss=off; number_of_people_in_space=3, next_rise=2020-08-21T11:58:30+03:00, long=-106.4767, lat=-36.5395, friendly_name=ISS, device_class=visible @ 2020-08-21T11:25:36.779790+03:00>, new_state=<state binary_sensor.iss=off; number_of_people_in_space=3, next_rise=2020-08-21T11:58:30+03:00, long=-102.9810, lat=-33.9159, friendly_name=ISS, device_class=visible @ 2020-08-21T11:25:36.779790+03:00>>
2020-08-21 08:26:52 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_final_write[L]
2020-08-21 08:26:52 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_close[L]
Home Assistant attempting to restart.
In another run the homeassistant_stop happens almost immediately but then it still takes 22 sec before homeassistant_final_write gets fired:
2020-08-21 08:29:53 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L] domain=homeassistant, service=restart, service_data=>
2020-08-21 08:29:56 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_stop[L]
2020-08-21 08:30:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.time_utc, old_state=<state sensor.time_utc=08:29; friendly_name=Time (UTC), icon=mdi:clock @ 2020-08-21T11:29:00.179148+03:00>, new_state=<state sensor.time_utc=08:30; friendly_name=Time (UTC), icon=mdi:clock @ 2020-08-21T11:30:00.180158+03:00>>
2020-08-21 08:30:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.time, old_state=<state sensor.time=11:29; friendly_name=Time, icon=mdi:clock @ 2020-08-21T11:29:00.179555+03:00>, new_state=<state sensor.time=11:30; friendly_name=Time, icon=mdi:clock @ 2020-08-21T11:30:00.180555+03:00>>
2020-08-21 08:30:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.date_time_utc, old_state=<state sensor.date_time_utc=2020-08-21, 08:29; friendly_name=Date & Time (UTC), icon=mdi:calendar-clock @ 2020-08-21T11:29:00.179856+03:00>, new_state=<state sensor.date_time_utc=2020-08-21, 08:30; friendly_name=Date & Time (UTC), icon=mdi:calendar-clock @ 2020-08-21T11:30:00.181839+03:00>>
2020-08-21 08:30:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.date_time_iso, old_state=<state sensor.date_time_iso=2020-08-21T11:29:00; friendly_name=Date & Time (ISO), icon=mdi:calendar-clock @ 2020-08-21T11:29:00.180137+03:00>, new_state=<state sensor.date_time_iso=2020-08-21T11:30:00; friendly_name=Date & Time (ISO), icon=mdi:calendar-clock @ 2020-08-21T11:30:00.182265+03:00>>
2020-08-21 08:30:00 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.last_power_update, old_state=<state sensor.last_power_update=3; unit_of_measurement=sec, friendly_name=Last power update from CC128 via MQTT, icon=mdi:refresh @ 2020-08-21T11:28:00.181929+03:00>, new_state=<state sensor.last_power_update=9; unit_of_measurement=sec, friendly_name=Last power update from CC128 via MQTT, icon=mdi:refresh @ 2020-08-21T11:30:00.189377+03:00>>
2020-08-21 08:30:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_final_write[L]
2020-08-21 08:30:18 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_close[L]
Home Assistant attempting to restart.
Then I disabled time_date sensor (because I almost every time see its events after reload) and now log is almost empty but still half of minute goes to int homeassistant_stop event
2020-08-21 08:41:34 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L] domain=homeassistant, service=restart, service_data=>
2020-08-21 08:41:37 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_stop[L]
2020-08-21 08:41:37 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L] entity_id=sensor.cc128_sensor_3185_ch1_power, old_state=<state sensor.cc128_sensor_3185_ch1_power=676; unit_of_measurement=W, friendly_name=1. faasi hetkevƵimsus, device_class=power @ 2020-08-21T11:41:31.593262+03:00>, new_state=<state sensor.cc128_sensor_3185_ch1_power=663; unit_of_measurement=W, friendly_name=1. faasi hetkevƵimsus, device_class=power @ 2020-08-21T11:41:37.546394+03:00>>
2020-08-21 08:42:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_final_write[L]
2020-08-21 08:42:06 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_close[L]
Home Assistant attempting to restart.
I changed logging for task waiting in core.py to show waiting tasks every second (by default only tasks takeng more than 60 sec will be logged).
@@ -423,12 +423,14 @@ class HomeAssistant:
async def _await_and_log_pending(self, pending: Iterable[Awaitable[Any]]) -> None:
"""Await and log tasks that take a long time."""
wait_time = 0
while pending:
- _, pending = await asyncio.wait(pending, timeout=BLOCK_LOG_TIMEOUT)
+ _, pending = await asyncio.wait(pending, timeout=1)
if not pending:
return
- wait_time += BLOCK_LOG_TIMEOUT
+ wait_time += 1
for task in pending:
_LOGGER.debug("Waited %s seconds for task: %s", wait_time, task)
And there was only one task that took more to 2 sec to finish and the last logline was following:
2020-08-21 09:30:17 DEBUG (MainThread) [homeassistant.core] Waited 24 seconds for task: <Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/local/lib/python3.8/asyncio/futures.py:360, _wait.<locals>._on_completion() at /usr/local/lib/python3.8/asyncio/tasks.py:507]>
Here Iām a little bit stuck now. I donāt know how to figure out what task is this one, that is waiting there so long. Any hints, how to find that?
