Why is update of media_player component executed in the MainThread?

Cdnf · August 26, 2018, 3:01pm

Hello,

I started implementing support for the Pioneer VSX-932 AVR.

I did some work in preparation (see: https://github.com/CodingSpiderFox/home-assistant/commit/b51f905a3689a2b0367933e07265aaa22b8238ca) but did not adapt the update method to be working with both the old an new models. Then, I started home assistant python3 -m homeassistant -c ./homeassistant . The logs show the following:

2018-08-26 16:33:34 ERROR (MainThread) [homeassistant.config] Could not detect location information
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_off>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=turn_on>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=toggle>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=stop>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=restart>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=check_config>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=homeassistant, service=reload_core_config>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=create>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=persistent_notification, service=dismiss>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.bootstrap] Home Assistant core initialized
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.loader] Loaded media_player from homeassistant.components.media_player
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.loader] Loaded http from homeassistant.components.http
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.loader] Loaded media_player.pioneer from homeassistant.components.media_player.pioneer
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.setup] Setting up http
2018-08-26 16:33:34 WARNING (MainThread) [homeassistant.components.http] You have been advised to set http.api_password.
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.setup] Setup of domain http took 0.0 seconds.
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=http>
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.setup] Setting up media_player
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.loader] Loaded websocket_api from homeassistant.components.websocket_api
2018-08-26 16:33:34 INFO (MainThread) [homeassistant.components.media_player] Setting up media_player.pioneer
2018-08-26 16:33:44 WARNING (MainThread) [homeassistant.components.media_player] Setup of platform pioneer is taking over 10 seconds.
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=media_player.pioneer_avr, old_state=None, new_state=<state media_player.pioneer_avr=off; friendly_name=Pioneer AVR, supported_features=18829 @ 2018-08-26T14:34:13.216567+00:00>>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=turn_on>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=turn_off>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=toggle>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=volume_up>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=volume_down>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_play_pause>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_play>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_pause>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_stop>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_next_track>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_previous_track>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=clear_playlist>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=volume_set>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=volume_mute>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=media_seek>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=select_source>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=select_sound_mode>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=play_media>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event service_registered[L]: domain=media_player, service=shuffle_set>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.setup] Setup of domain media_player took 38.5 seconds.
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=media_player>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 39.57s
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Starting Home Assistant core loop
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Starting Home Assistant
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Bus:Handling <Event homeassistant_start[L]>
2018-08-26 16:34:13 INFO (MainThread) [homeassistant.core] Timer:starting
2018-08-26 16:34:33 WARNING (MainThread) [homeassistant.helpers.entity] Update of media_player.pioneer_avr is taking over 10 seconds
2018-08-26 16:34:34 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:34:45 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:34:56 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:35:16 WARNING (MainThread) [homeassistant.helpers.entity] Update of media_player.pioneer_avr is taking over 10 seconds
2018-08-26 16:35:17 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:35:28 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:35:39 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:36:00 WARNING (MainThread) [homeassistant.helpers.entity] Update of media_player.pioneer_avr is taking over 10 seconds
2018-08-26 16:36:01 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:36:11 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10
2018-08-26 16:36:22 WARNING (MainThread) [homeassistant.components.media_player] Updating pioneer media_player took longer than the scheduled update interval 0:00:10

The warnings start to repeat and it never finishes because the implementation does not work yet.

So the question came to my mind: why should everything else stop working because the communication with one device does not work at startup of home assistant?
Why not execute the update method for all devices in separate threads?

danielperna84 · August 26, 2018, 3:11pm

Have a look at the development documentation: https://developers.home-assistant.io/docs/en/asyncio_working_with_async.html

Cdnf · August 26, 2018, 6:35pm

Hello Daniel,

thank you for the quick response

So I would simply need to implement all the async_ methods in an remove the non async update method, is that right?

Have a nice day

danielperna84 · August 26, 2018, 7:06pm

I’m not really deep into the async-topic, so I’m not sure what the right advice is. I just knew that async is an important keyword and wanted to point you into the right direction. Hope there’s somebody else here who can help. Or reach out to the devs at the discord chat. I believe you’ll get responses there quicker than here.

amelchio · August 26, 2018, 7:18pm

The update method is actually executed in a separate thread even if the warning that it was slow is logged from the main thread.

Cdnf · August 27, 2018, 6:24pm

Ok, thanks