search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.08k stars 30.18k forks source link

Platforms that do I/O inside properties #4210

Closed balloob closed 4 years ago

balloob commented 7 years ago

If you came here because of a warning in your Home Assistant logs, please check if it is in the list below. If it is not, please add a reply with the brand of the product / platform and the time that it took to execute. Thanks

Platforms that have been reported as slow:

Reported but no suspicious behavior found:

Backstory

When we moved to async we started writing the state of entities to the state machine from within the event loop. This can only work correctly if no platforms or components do any I/O within any property of an entity. Instead, that work should be done inside the update method.

Bad

@property
def is_on(self):
    """Return if device is on."""
    return self._device.query_is_on()

Good

@property
def is_on(self):
    """Return if device is on."""
    return self._is_on

def update(self):
    """Update state of device."""
    self._is_on = self._device.query_is_on()

Although we cannot detect directly if I/O is happening inside a property, we can measure the time it takes us to fetch the properties. If this takes too long, it's probably bad and needs more research. In #4208 I implemented this warning which will redirect users to this issue.

w1ll1am23 commented 7 years ago

Fixed via #4219 Thanks @pvizeli Component: Nest Platform: Climate Time to update (average of three): 0.474

Took a look at the python-nest platform and it is calling the nest API every X minutes it looks like (appears to be 5 minutes). So I am only seeing this issue logged once for every 5 updates.

The same code is used to update all Nest platforms so I assume this would be an issue with any of them.

xehn commented 7 years ago

Reporting as requested.

I noticed this with the climate.radiotherm component. Delays vary between the two captures below. Hardware is a Radio Thermostat CT50. No idea if the time taken is being caused by the issue mentioned above, or just slow hardware. Functionality seems unaffected.

WARNING (MainThread) [homeassistant.helpers.entity] Updating state for climate.thermostat took 24.439 seconds. Please report platform to the developers at https://goo.gl/Nvioub WARNING (MainThread) [homeassistant.helpers.entity] Updating state for climate.thermostat took 4.149 seconds. Please report platform to the developers at https://goo.gl/Nvioub

bjw-s commented 7 years ago

Seeing this behaviour as well with the media_player.sonos component, reporting as requested:

16-11-05 19:24:31 homeassistant.helpers.entity: Updating state for media_player.kitchen took 0.537 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-05 19:25:32 homeassistant.helpers.entity: Updating state for media_player.kitchen took 0.399 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-05 19:26:11 homeassistant.helpers.entity: Updating state for media_player.kitchen took 0.314 seconds. Please report platform to the developers at https://goo.gl/Nvioub

dap35 commented 7 years ago

I am also seeing this with the media_player.sonos component on HA 0.32. I am also seeing the message below which is for the sonos controller package, not sure if it is at all related to this issue.. It does not appear to be updating the component.

Nov 05 14:57:44 rpi01.home.int hass[24265]: INFO:homeassistant.util.package:Attempting install of https://github.com/SoCo/SoCo/archive/cf8c2701165562eccbf1ecc879bf7060ceb0993e.zip#SoCo==0.12

olines commented 7 years ago

Here you go - reporting per log request:

16-11-06 03:28:16 homeassistant.helpers.entity: Updating state for cover.garagedoor took 1.176 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-06 03:28:32 homeassistant.helpers.entity: Updating state for cover.garagedoor took 1.428 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-06 03:28:46 homeassistant.helpers.entity: Updating state for cover.garagedoor took 1.167 seconds. Please report platform to the developers at https://goo.gl/Nvioub
balloob commented 7 years ago

Which platform is this?

On Sat, Nov 5, 2016, 20:56 olines notifications@github.com wrote:

Here you go - reporting per log request:

16-11-06 03:28:16 homeassistant.helpers.entity: Updating state for cover.garagedoor took 1.176 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-06 03:28:32 homeassistant.helpers.entity: Updating state for cover.garagedoor took 1.428 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-06 03:28:46 homeassistant.helpers.entity: Updating state for cover.garagedoor took 1.167 seconds. Please report platform to the developers at https://goo.gl/Nvioub

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/home-assistant/home-assistant/issues/4210#issuecomment-258658865, or mute the thread https://github.com/notifications/unsubscribe-auth/ABYJ2iIevk0Q3KCaVdLtK6aQUULeWWMLks5q7U_TgaJpZM4KpMod .

raccettura commented 7 years ago

I'm getting 16-11-06 01:29:01 homeassistant.helpers.entity: Updating state for climate.bedroom took 0.371 seconds. Please report platform to the developers at https://goo.gl/Nvioub

when connecting to my Honeywell thermostat API.

frelev commented 7 years ago

I´m getting homeassistant.helpers.entity: Updating state for switch.kitchen_lamp took 0.563 seconds. Please report platform to the developers at https://goo.gl/Nvioub

When trying to turn on a lamp using emulated hue

(lamp didn't turn on but I think there is an issue with emulated hue in latest version)

balloob commented 7 years ago

@frelev what platform is the lamp?

TeeSeePeeEyePea commented 7 years ago

I am getting the warning on cover.garage_door - it is the "myq" platform, from: http://pastebin.com/qVszax1t

balloob commented 7 years ago

@Teeseepeeeyepea that component is indeed wrong. However, it is not part of Home Assistant so you'll have to find the author and have him fix it (the get_status call should be moved to a new update method) like done here: https://github.com/home-assistant/home-assistant/pull/4244/files

frelev commented 7 years ago

@balloob It´s a tellstick (not Net) switch

resoai commented 7 years ago

I have a huge number of KNX switches and I'm getting following in the error log (truncated):

16-11-06 20:54:28 homeassistant.helpers.entity: Updating state for switch.master_bedroom_spotlights took 1.022 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:29 homeassistant.helpers.entity: Updating state for switch.bathroom_shower_spotlights took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:30 homeassistant.helpers.entity: Updating state for switch.toilet_extractor_fan took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:31 homeassistant.helpers.entity: Updating state for switch.toilet_spotlight took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:32 homeassistant.helpers.entity: Updating state for switch.bathroom_spotlights took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:33 homeassistant.helpers.entity: Updating state for switch.hallway_ff_wall_lights took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:34 homeassistant.helpers.entity: Updating state for switch.kitchen_centre_pendant took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:35 homeassistant.helpers.entity: Updating state for switch.rear_gate took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:36 homeassistant.helpers.entity: Updating state for switch.master_bedroom_wardrobe_spotlights took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:37 homeassistant.helpers.entity: Updating state for switch.external_porch_wall_light took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:38 homeassistant.helpers.entity: Updating state for switch.external_side_wall_lights took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:39 homeassistant.helpers.entity: Updating state for switch.av_room_exctractor_fan took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:40 homeassistant.helpers.entity: Updating state for switch.bathroom_extractor_fan took 1.003 seconds. Please report platform to the developers at https://goo.gl/Nvioub
kylerw commented 7 years ago

@TeeSeePeeEyePea I made submitted a pull request for https://github.com/arraylabs/myq that updates to handle multipe doors (using name from the app) as well as resolving the error here. Have a look (may need to check my fork) and let me know if you see any problems.

MichaelMuir commented 7 years ago

I am seeing lots of errors for pyW215 when I am using the D-Link DSP-W215 Switch, here is one example:

16-11-07 20:27:29 homeassistant.helpers.entity: Updating state for switch.patio_audio took 1.037 seconds. Please report platform to the developers at https://goo.gl/Nvioub

tim-devel commented 7 years ago

I am getting the warning message on the dark sky weather platform

bestlibre commented 7 years ago

I'm also getting this warning for the new openweathermap component (weather platform)

homeassistant.helpers.entity: Updating state for weather.openweathermap took 0.241 seconds. Please report platform to the developers at https://goo.gl/Nvioub

tim-devel commented 7 years ago

I just got the message on a template sensor too:

Nov 7 20:19:01 pi2 hass[524]: WARNING:homeassistant.helpers.entity:Updating state for sensor.back_room_temp_update_timer took 0.547 seconds. Please report platform to the developers at https://goo.gl/Nvioub

- platform: template
   sensors:
     back_room_temp_update_timer:
       value_template: '{% if is_state("input_boolean.boot_delay", "off") %} {{ (as_timestamp(now()) - as_timestamp(states.sensor.back_room.last_updated)) / 60 }} {% else %} {{ 0 | int }} {% endif %}'
       entity_id: sensor.time
       unit_of_measurement: 'minutes'
lwis commented 7 years ago

@bestlibre could you try against #4298 ? @MichaelMuir could you try against #4301 ?

bestlibre commented 7 years ago

No more warning after I applied the patch

tim-devel commented 7 years ago

Am getting the warning on the date_time platform now too

tim-devel commented 7 years ago

Just got the warning Transmission sensor platform too

lwis commented 7 years ago

@balloob Transmission doesn't look to be doing anything bad, maybe this is producing some misnomers?

balloob commented 7 years ago

@lwis I think that you might be right. I'm seeing some that just cannot be there, like template and time date.

balloob commented 7 years ago

Let's increase it to 0.4 seconds in 0.32.3

tim-devel commented 7 years ago

@balloob The majority of the warnings I receive are 0.5 secs plus so, at least in my case, increasing to 0.4 seconds would not stop the warnings.

I have attached my log below. sensor.time is date_time platform, the two temp_update_timers are templates and the weather sensor is dark sky

16-11-10 01:06:01 homeassistant.helpers.entity: Updating state for sensor.time took 0.553 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 01:35:01 homeassistant.helpers.entity: Updating state for sensor.front_room_temp_update_timer took 0.567 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 03:27:01 homeassistant.helpers.entity: Updating state for sensor.front_room_temp_update_timer took 0.576 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 03:54:01 homeassistant.helpers.entity: Updating state for sensor.time took 0.557 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 04:17:01 homeassistant.helpers.entity: Updating state for sensor.transmission_status took 0.536 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 05:27:01 homeassistant.helpers.entity: Updating state for sensor.weather_temperature took 0.544 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 05:47:01 homeassistant.helpers.entity: Updating state for sensor.back_room_temp_update_timer took 0.528 seconds. Please report platform to the developers at https://goo.gl/Nvioub
nathanm412 commented 7 years ago

I'm receiving this warning for alarm.com. I get the alert every 30 seconds. It seems to vary between 0.66 seconds and 1.4 seconds.

16-11-10 10:30:01 WARNING (MainThread) [homeassistant.helpers.entity] Updating state for alarm_control_panel.alarm took 1.361 seconds. Please report platform to the developers at https://goo.gl/Nvioub

16-11-10 10:30:31 WARNING (MainThread) [homeassistant.helpers.entity] Updating state for alarm_control_panel.alarm took 0.985 seconds. Please report platform to the developers at https://goo.gl/Nvioub

deegs commented 7 years ago

Looks like a fix is incoming but still reporting in. Running HA 32.2.

This is a Panasonic Viera TV. As I understand, Viera's have iffy-support as it is but just wanted to check in. Alert every 20-40 seconds. 

16-11-10 21:46:01 homeassistant.helpers.entity: Updating state for media_player.unnamed_device took 0.245 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 21:46:20 homeassistant.helpers.entity: Updating state for media_player.unnamed_device took 0.250 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 21:46:40 homeassistant.helpers.entity: Updating state for media_player.unnamed_device took 0.257 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 21:47:00 homeassistant.helpers.entity: Updating state for media_player.unnamed_device took 0.265 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 21:47:40 homeassistant.helpers.entity: Updating state for media_player.unnamed_device took 0.274 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-10 21:47:51 homeassistant.helpers.entity: Updating state for media_player.unnamed_device took 1.095 seconds. Please report platform to the developers at https://goo.gl/Nvioub
resoai commented 7 years ago

Sorry for the delayed reply, unfortunately KNX issues are still there. 

16-11-06 20:54:28 homeassistant.helpers.entity: Updating state for switch.master_bedroom_spotlights took 1.022 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:29 homeassistant.helpers.entity: Updating state for switch.bathroom_shower_spotlights took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:30 homeassistant.helpers.entity: Updating state for switch.toilet_extractor_fan took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-06 20:54:31 homeassistant.helpers.entity: Updating state for switch.toilet_spotlight took 1.002 seconds. Please report platform to the developers at https://goo.gl/Nvioub

There is also a huge delay updating value of the switch.

balloob commented 7 years ago

@resoai are you running 0.32.3 ?

resoai commented 7 years ago

@balloob yes

resoai commented 7 years ago

It takes about 15-20 seconds for the switch to update it's value in the UI (when switching it off)? although the actual light turns on/off immediately.

lwis commented 7 years ago

Sounds like we should be updating the state after we change the lights, rather than waiting for update to be called?

resoai commented 7 years ago

I don't think so, it used to work fine before this major async movement.

tim-devel commented 7 years ago

Upgraded to 0.32.3, no warnings for 24 hours, was getting at least half a dozen a day on 0.32.2

resoai commented 7 years ago

@lwis there is a different KNX address for status changes so we actually need to wait for it to send something. Besides, lights could be triggered via physical buttons. As I said, the issue only started after this major async rewrite. Also it looks like the thermostat (climate component) is not reporting temperature.

I can confirm that the actual error messages are gone. There was a weird cache bug in Google Chrome which was displaying the old page.

mestafin commented 7 years ago

KNX Problem

I have a working KNX-based system which I am trying to control via Home-Assistant, but there is still an issue with KNX driver.

HA is not able to switch lights on and off, nothing happens.

On HA screen in the browser, it correctly reads the state of the lights, but when I try and switch a light, nothing happens.

In the log file, there is a message about the time it takes - 3.2 secs

I have attached the log file to this post.

In the log file, around 17:11:54, I switched the a light, which is reflected in the log file, but the actual light did not switch

I have also attached my configuration file for your info.

configuration_and_logfile.zip

hendrikb commented 7 years ago

Hello! I am owning this Edimax SP-2101W smart plug. And now my home-assistant log is full of this:

16-11-22 18:46:01 homeassistant.helpers.entity: Updating state for switch.edimax_smart_plug took 0.801 seconds. Please report platform to the developers at https://goo.gl/Nvioub

I am running home-assistant on a latest gen raspberry pi.

Thanks for your awesome work, people! I'll gladly provide more information.

lwis commented 7 years ago

@hendrikb looks like the edimax switch isn't caching it's state;

https://github.com/home-assistant/home-assistant/blob/dev/homeassistant/components/switch/edimax.py#L81

That should be in an update function.

pilot33 commented 7 years ago

On the media_player.yamaha platform with HA 0.33.3 I get

16-11-25 01:05:32 homeassistant.helpers.entity: Updating state for media_player.yamaha_receiver took 0.413 seconds. Please report platform to the developers at https://goo.gl/Nvioub 16-11-25 01:06:04 homeassistant.helpers.entity: Updating state for media_player.yamaha_receiver_zone_2 took 0.993 seconds. Please report platform to the developers at https://goo.gl/Nvioub

resoai commented 7 years ago

After recent rewrite to async KNX switches take between 12 and 25 seconds to update it's values when switching lights off. Very strange thing is that switching lights on updates very fast both via hass and via physical buttons. The actual command gets executed momentarily i.e. turn on/off without delay.

balloob commented 7 years ago

@sdague See previous comment. I have looked at the Yamaha component but I cannot find any I/O inside properties. Could you verify that this is not happening? (Home Assistant sometimes warns about the wrong platform)

balloob commented 7 years ago

@hendrikb @lwis Edimax fix is here: #4584

Tommatheussen commented 7 years ago

Hi guys, I setup Google Calendar a few days ago, and today I got these messages:

16-11-30 02:06:04 homeassistant.helpers.entity: Updating state for calendar.facebook_events took 0.433 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-30 02:06:12 homeassistant.helpers.entity: Updating state for calendar.my_first_calendar took 0.833 seconds. Please report platform to the developers at https://goo.gl/Nvioub
16-11-30 02:06:17 homeassistant.helpers.entity: Updating state for calendar.work_calendar took 0.512 seconds. Please report platform to the developers at https://goo.gl/Nvioub
frelev commented 7 years ago

I still have issues with Tellstick switches in the latest DEV: Updating state for switch.outdoor_switch took 0.828 seconds. Please report platform to the developers at https://goo.gl/Nvioub

vrishabkakade commented 7 years ago

I have a Yamaha RX-V775 16-12-01 20:30:31 homeassistant.helpers.entity: Updating state for media_player.yamaha_receiver took 1.113 seconds. Please report platform to the developers at https://goo.gl/Nvioub

jschroeck commented 7 years ago

I'm using the Synology DSM Sensor: 16-12-04 14:09:17 homeassistant.helpers.entity: Updating state for sensor.memory_usage_real took 1.261 seconds. Please report platform to the developers at https://goo.gl/Nvioub

ghost commented 7 years ago

I've just seen this in the logs: 16-12-04 19:12:03 homeassistant.helpers.entity: Updating state for sensor.living_room_thermostat_target took 2.590 seconds. Please report platform to the developers at https://goo.gl/Nvioub

balloob commented 7 years ago

@bk86a what platform is it?

ghost commented 7 years ago

@balloob Raspberry Pi 2 Model B + raspbian 4.4.32-v7