Component xxxxxx took a long time for an operation

jesserockz commented 1 year ago

Do not report new issues related to this message, instead please comment on this issue with the logs that you see and the config for that component.

The problem

[00:00:00][W][component:204]: Component xxxxxx took a long time for an operation (x.xx s).
[00:00:00][W][component:205]: Components should block for at most 20-30ms.

These 2 log lines may show up in the most recent version of ESPHome due to the log level being changed from verbose to warning. I made this change because changing the device log level to verbose just to see if these lines show up significantly slowed down the device due to all the extra logging it had to do.

Which version of ESPHome has the issue?

2023.7.0

Can I hide this message?

Yes you can hide the message, but it wont change the fact that the component is taking a long time.

logger:
  logs:
    component: ERROR

Is it expected?

For some components this is actually expected like displays which have a lot of drawing and pixel/data moving. For the majority of sensors, it means that they are doing too much processing or waiting for responses instead of letting ESPHome get on with business until the data is ready.

PhilippeLRQ commented 1 year ago

Hello, thanks to all developers to work so hard on this marvelous project.

I have the same issue but with a brand new esp32 connected to SM300D2 Air Quality Sensor.

" [18:20:46][D][sm300d2:045]: Successfully read SM300D2 data [18:20:46][D][sm300d2:058]: Received CO₂: 403 ppm [18:20:46][D][sensor:094]: 'SM300D2 CO2': Sending state 403.00000 ppm with 0 decimals of accuracy [18:20:46][D][sm300d2:062]: Received Formaldehyde: 0 µg/m³ [18:20:47][D][sensor:094]: 'SM300D2 Formaldehyde': Sending state 0.00000 µg/m³ with 0 decimals of accuracy [18:20:47][D][sm300d2:066]: Received TVOC: 2 µg/m³ [18:20:47][D][sensor:094]: 'SM300D2 TVOC': Sending state 2.00000 µg/m³ with 0 decimals of accuracy [18:20:47][D][sm300d2:070]: Received PM2.5: 33 µg/m³ [18:20:47][D][sensor:094]: 'SM300D2 PM2.5': Sending state 33.00000 µg/m³ with 0 decimals of accuracy [18:20:47][D][sm300d2:074]: Received PM10: 59 µg/m³ [18:20:47][D][sensor:094]: 'SM300D2 PM10': Sending state 59.00000 µg/m³ with 0 decimals of accuracy [18:20:47][D][sm300d2:078]: Received Temperature: 27.80 °C [18:20:47][D][sensor:094]: 'SM300D2 Temperature': Sending state 27.80000 °C with 1 decimals of accuracy [18:20:47][D][sm300d2:082]: Received Humidity: 52.30 percent [18:20:47][D][sensor:094]: 'SM300D2 Humidity': Sending state 52.30000 % with 1 decimals of accuracy [18:20:47][W][component:204]: Component sm300d2.sensor took a long time for an operation (0.08 s). [18:20:47][W][component:205]: Components should block for at most 20-30ms. "

My configuration is the one included in the dedicated page for this sensor, and it looks to work fine.

" uart: rx_pin: number: 3 mode: INPUT_PULLDOWN tx_pin: 1 baud_rate: 9600

Ssensor:

platform: sm300d2 co2: name: "SM300D2 CO2" formaldehyde: name: "SM300D2 Formaldehyde" tvoc: name: "SM300D2 TVOC" pm_2_5: name: "SM300D2 PM2.5" pm_10_0: name: "SM300D2 PM10" temperature: name: "SM300D2 Temperature" humidity: name: "SM300D2 Humidity" update_interval: 60s "

Thanks again.

Philippe

Protoncek commented 1 year ago

Hi guys! As all of you, i also have same problem with PN532, running on esp32. But that's not why i'm writing - it's because these messages noticeably slow down PN532. When i move card to a reader it reads it and it should respond with 3 beeps. Sometimes these beeps are "funny" - either one is lost, or second or third is played after small delay, or one of them is longer than it should be... when looking log output it's clear that this delay or corruption is caused by above message. Hiding these messages in logger (with component: error) doesn't help. So, pn532 is unusable at this moment. Changing bus speed doesn't help - i tried from 10kHz to 800kHz - message always appears. Are there any solutions other than throwing pn532 to the drawer and waiting for better times?

RC522 works flawlessly, though.

nielsnl68 commented 1 year ago

I don't belief this is mentioned before so i will add this as well:

[VV][api.service:324]: send_media_player_state_response: MediaPlayerStateResponse {
  key: 1433258598
  state: MEDIA_PLAYER_STATE_PLAYING
  volume: 1
  muted: NO
}
[W][component:204]: Component i2s_audio.media_player took a long time for an operation (0.57 s).
[W][component:205]: Components should block for at most 20-30ms.
[W][component:204]: Component i2s_audio.media_player took a long time for an operation (0.34 s).
[W][component:205]: Components should block for at most 20-30ms.

[VV][api.service:324]: send_media_player_state_response: MediaPlayerStateResponse {
  key: 1433258598
  state: MEDIA_PLAYER_STATE_IDLE
  volume: 1
  muted: NO
}
[W][component:204]: Component i2s_audio.media_player took a long time for an operation (0.35 s).
[W][component:205]: Components should block for at most 20-30ms.

arqtron commented 1 year ago

My two esp32 with displays are reporting this after the update:

Waveshare E-Paper 2.13in (TTGO) 122px x 250px
TTGO T-Display 135x240 (ST7789V )

descipher commented 1 year ago

Hi guys! As all of you, i also have same problem with PN532, running on esp32. But that's not why i'm writing - it's because these messages noticeably slow down PN532. When i move card to a reader it reads it and it should respond with 3 beeps. Sometimes these beeps are "funny" - either one is lost, or second or third is played after small delay, or one of them is longer than it should be... when looking log output it's clear that this delay or corruption is caused by above message. Hiding these messages in logger (with component: error) doesn't help. So, pn532 is unusable at this moment. Changing bus speed doesn't help - i tried from 10kHz to 800kHz - message always appears. Are there any solutions other than throwing pn532 to the drawer and waiting for better times?

RC522 works flawlessly, though.

With an Esp32 try setting the logger to

baud_rate: 921600

Protoncek commented 1 year ago

Sadly it's no difference. I tried 921600, i tried zero, i tried log level "error", i even tried with logger disabled, but lag is still present. my beeper code is this:

output: 
  - platform: template
    id: tag_yes
    type: binary
    write_action:
      - switch.turn_on: buzzer
      - delay: 50ms
      - switch.turn_off: buzzer
      - delay: 50ms
      - switch.turn_on: buzzer
      - delay: 50ms
      - switch.turn_off: buzzer
      - delay: 50ms
      - switch.turn_on: buzzer
      - delay: 50ms
      - switch.turn_off: buzzer

but in real these 3 short beeps are mostly like "bep beeeeep bep", or "bep (1s pause) bep bep" etc. So something is seriously causing lagging.

BTW - this is in arduino environment. I tried with esp-idf, but on 400kHz reader is not even found, at 100kHz is found but it's not working - nothing happens when tag should be read, like it's not there.

descipher commented 1 year ago

Yikes, clearly the 50ms delay is not compatible with the blocking check routine. Bring it down to 40ms and see what happens.

Protoncek commented 1 year ago

Tried, unsuccesfull. I uploaded video on my youtube channel how thing works. It can happen that it's ok a few times, but not constantly: _https://youtube.com/shorts/4KYrt_ZMZDo?feature=share_

PaFcio commented 1 year ago

Sadly it's no difference. I tried 921600, i tried zero, i tried log level "error", i even tried with logger disabled, but lag is still present. my beeper code is this:
output: 
  - platform: template
    id: tag_yes
    type: binary
    write_action:
      - switch.turn_on: buzzer
      - delay: 50ms
      - switch.turn_off: buzzer
      - delay: 50ms
      - switch.turn_on: buzzer
      - delay: 50ms
      - switch.turn_off: buzzer
      - delay: 50ms
      - switch.turn_on: buzzer
      - delay: 50ms
      - switch.turn_off: buzzer
but in real these 3 short beeps are mostly like "bep beeeeep bep", or "bep (1s pause) bep bep" etc. So something is seriously causing lagging.

BTW - this is in arduino environment. I tried with esp-idf, but on 400kHz reader is not even found, at 100kHz is found but it's not working - nothing happens when tag should be read, like it's not there.

Not sure that it would fix the issue but you might try to run the buzzer with RTTTL Buzzer component.

Edit: nevermind, I have realised that you are most likely using active buzzer not a passive one.

Batzi1967 commented 1 year ago

the same with the media_player:

[20:57:52][D][media_player:059]: 'ESP32 Assistant03Media Player' - Setting
[20:57:52][D][media_player:066]:   Media URL: http://192.168.178.101:8123/media/local/03%20AliBabo.mp3?authSig=eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJpc3MiOiI4MWFiZGQ2NWFlYmE0MGMyOTI3NmFjOWMyMWM1YTM4YyIsInBhdGgiOiIvbWVkaWEvbG9jYWwvMDMgQWxpQmFiby5tcDMiLCJwYXJhbXMiOltdLCJpYXQiOjE2OTA3NDM0NzIsImV4cCI6MTY5MDgyOTg3Mn0.eQ4SQq0OSmakp084fzlBXFz_VknqM_gVs0Hbn4octck
[20:57:52][W][component:204]: Component i2s_audio.media_player took a long time for an operation (0.54 s).
[20:57:52][W][component:205]: Components should block for at most 20-30ms.

mrc1600 commented 1 year ago

I'm seeing this:

[23:36:21][W][component:204]: Component esphome.coroutine took a long time for an operation (0.10 s).
[23:36:21][W][component:205]: Components should block for at most 20-30ms.
[23:36:23][W][component:204]: Component esphome.coroutine took a long time for an operation (0.10 s).
[23:36:23][W][component:205]: Components should block for at most 20-30ms.

When using the component:

external_components:
  - source: github://geoffdavis/esphome-mitsubishiheatpump@develop

climate:
  - platform: mitsubishi_heatpump
    name: "${name}"
    id: ${device_id}_climate
    hardware_uart: UART1
    tx_pin: 12
    rx_pin: 13
    visual:
      temperature_step: 1.0

Also using Geoff Davis' Mitsubishi heat pump custom component, and seeing the same issue since the update.

Editing for more details.

The Geoff Davis Mitsubishi Heat Pump issues are being seen on an ESP8266 board. I'm also getting an error for the sensor component running on that board (I'm patching in a Home Assistant external temperature to override the heat pump's internal temperature sensor).

I just updated a test ESP32 board that I'm using several different hardware components on for testing. I have a rotary encoder, RTTTL buzzer, and an ssd1306 display. I'm getting the "took a long time" error for the ssd1306_base component, but none of the others. Per the update release notes, this may be anticipated behavior, as per the original post:

"For some components this is actually expected like displays which have a lot of drawing and pixel/data moving. "For the majority of sensors, it means that they are doing too much processing or waiting for responses instead of letting ESPHome get on with business until the data is ready."

Not sure if this is actually a problem in either of these scenarios, as the devices to appear to work, but contributing to the discussion per the dev's request in the changelogs. Can provide more details with log snippets if needed.

zoomtronicOR commented 1 year ago

After update to 2023.7.0 everything just goes nuts! pzem reports Component modbus took a long time for an operation (0.06 s). Components should block for at most 20-30ms LCD reports Component lcd_base took a long time for an operation (0.40 s). Components should block for at most 20-30ms. DHT reports Component dallas took a long time for an operation (0.05 s). MPU6050 reports Component mpu6050.sensor took a long time for an operation (0.07 s). Components should block for at most 20-30ms. SGP30 reports Component sgp30.sensor took a long time for an operation (0.05 s). Components should block for at most 20-30ms.

so rolling back to version 2023.5.5 which works fine There is a major flaw in version 2023.7.0 Not updating to new version until is fixed properly

alexruffell commented 1 year ago

so rolling back to version 2023.5.5 which works fine There is a major flaw in version 2023.7.0 Not updating to new version until is fixed properly

From what I've read the issue is there regardless, just not reported. Unless you are saying that your ESP stopped working with 2023.7, then it should make no difference other than busier logs. I am guessing the developers are trying to see how widespread the issue is, which is likely why this issue was created with a request to report components with that warning.

descipher commented 1 year ago

After update to 2023.7.0 everything just goes nuts! pzem reports Component modbus took a long time for an operation (0.06 s). Components should block for at most 20-30ms LCD reports Component lcd_base took a long time for an operation (0.40 s). Components should block for at most 20-30ms. DHT reports Component dallas took a long time for an operation (0.05 s). MPU6050 reports Component mpu6050.sensor took a long time for an operation (0.07 s). Components should block for at most 20-30ms. SGP30 reports Component sgp30.sensor took a long time for an operation (0.05 s). Components should block for at most 20-30ms.

so rolling back to version 2023.5.5 which works fine There is a major flaw in version 2023.7.0 Not updating to new version until is fixed properly

The blocking report was always there b4, we would only see it if we set the logging level to VERY_VERBOSE. I tend to agree that there is some additional issue that has surfaced and it needs to be isolated out. I did do a revert and enabled VERY_VERBOSE where I observed the same blocking reports. The issue with doing that is VERY_VERBOSE log output also takes more time and adds to the blocking time total. Will do some addition investigation tonight, I saw some strange json memory resource errors on one of my modules which made me suspicious of a possible logging output relation.

descipher commented 1 year ago

Did some more investigation. I reverted to 2023.6.5 and set the logging to VERBOSE (I was incorrect on VERY_VERBOSE it was previously VERBOSE to see the blocking message.) Then I updated to 2023.7.0 and did the same logging output, the blocking message is exactly the same but is now a warning. It reports 0.18s for both 2023.6.5 and 2023.7.0. I then set the logging level to DEBUG which is the default. It reports 0.05s and thats expected without the extra verbose logs. So this confirms that there are no differences in the time it takes to return back from a component callback of the loop() interval process in 2023.6.5 or 2023.7.0. The memory error I observed never occurred again and is not repeatable so I suspect it was corrected by a simple restart.

What would be different is the additional time the WARNING log output adds on to loop() processing.

2023.6.5 - level: VERBOSE

[22:23:47][V][sensor:043]: 'PM1 Volts': Received new state 118.290001
[22:23:47][D][sensor:093]: 'PM1 Volts': Sending state 118.29000 V with 1 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 76 bytes
[22:23:47][V][sensor:043]: 'PM1 CT1 Amps': Received new state 3.137000
[22:23:47][D][sensor:093]: 'PM1 CT1 Amps': Sending state 3.13700 A with 2 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 76 bytes
[22:23:47][V][sensor:043]: 'PM1 CT2 Amps': Received new state 4.192000
[22:23:47][D][sensor:093]: 'PM1 CT2 Amps': Sending state 4.19200 A with 2 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 76 bytes
[22:23:47][V][sensor:043]: 'PM1 CT1 Watts': Received new state 324.288300
[22:23:47][D][sensor:093]: 'PM1 CT1 Watts': Sending state 324.28830 W with 1 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 80 bytes
[22:23:47][V][sensor:043]: 'PM1 CT2 Watts': Received new state 444.003510
[22:23:47][D][sensor:093]: 'PM1 CT2 Watts': Sending state 444.00351 W with 1 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 80 bytes
[22:23:47][V][sensor:043]: 'PM1 Freq': Received new state 60.020000
[22:23:47][D][sensor:093]: 'PM1 Freq': Sending state 60.02000 Hz with 1 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 72 bytes
[22:23:47][V][sensor:043]: 'PM1 IC Temperature': Received new state 51.000000
[22:23:47][D][sensor:093]: 'PM1 IC Temperature': Sending state 51.00000 °C with 1 decimals of accuracy
[22:23:47][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:23:47][V][json:056]: Size after shrink 84 bytes
[22:23:47][V][component:204]: Component atm90e32.sensor took a long time for an operation (0.18 s).
[22:23:47][V][component:205]: Components should block for at most 20-30ms.

2023.7.0 level: VERBOSE

[22:47:23][V][sensor:043]: 'PM1 Volts': Received new state 118.150002
[22:47:23][D][sensor:093]: 'PM1 Volts': Sending state 118.15000 V with 1 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 76 bytes
[22:47:23][V][sensor:043]: 'PM1 CT1 Amps': Received new state 3.127000
[22:47:23][D][sensor:093]: 'PM1 CT1 Amps': Sending state 3.12700 A with 2 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 76 bytes
[22:47:23][V][sensor:043]: 'PM1 CT2 Amps': Received new state 4.084000
[22:47:23][D][sensor:093]: 'PM1 CT2 Amps': Sending state 4.08400 A with 2 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 76 bytes
[22:47:23][V][sensor:043]: 'PM1 CT1 Watts': Received new state 319.595520
[22:47:23][D][sensor:093]: 'PM1 CT1 Watts': Sending state 319.59552 W with 1 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 80 bytes
[22:47:23][V][sensor:043]: 'PM1 CT2 Watts': Received new state 446.189117
[22:47:23][D][sensor:093]: 'PM1 CT2 Watts': Sending state 446.18912 W with 1 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 80 bytes
[22:47:23][V][sensor:043]: 'PM1 Freq': Received new state 60.020000
[22:47:23][D][sensor:093]: 'PM1 Freq': Sending state 60.02000 Hz with 1 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 72 bytes
[22:47:23][V][sensor:043]: 'PM1 IC Temperature': Received new state 51.000000
[22:47:23][D][sensor:093]: 'PM1 IC Temperature': Sending state 51.00000 °C with 1 decimals of accuracy
[22:47:23][V][json:036]: Attempting to allocate 512 bytes for JSON serialization
[22:47:23][V][json:056]: Size after shrink 84 bytes
[22:47:23][W][component:204]: Component atm90e32.sensor took a long time for an operation (0.18 s).
[22:47:23][W][component:205]: Components should block for at most 20-30ms.

2030.7.0 - level: DEBUG

[22:57:40][D][sensor:093]: 'PM1 Volts': Sending state 117.96000 V with 1 decimals of accuracy
[22:57:40][D][sensor:093]: 'PM1 CT1 Amps': Sending state 3.10900 A with 2 decimals of accuracy
[22:57:40][D][sensor:093]: 'PM1 CT2 Amps': Sending state 6.88300 A with 2 decimals of accuracy
[22:57:40][D][sensor:093]: 'PM1 CT1 Watts': Sending state 317.21631 W with 1 decimals of accuracy
[22:57:40][D][sensor:093]: 'PM1 CT2 Watts': Sending state 782.50781 W with 1 decimals of accuracy
[22:57:40][D][sensor:093]: 'PM1 Freq': Sending state 60.03000 Hz with 1 decimals of accuracy
[22:57:40][D][sensor:093]: 'PM1 IC Temperature': Sending state 51.00000 °C with 1 decimals of accuracy
[22:57:40][W][component:204]: Component atm90e32.sensor took a long time for an operation (0.05 s).
[22:57:40][W][component:205]: Components should block for at most 20-30ms.

r0bb10 commented 1 year ago

[12:53:06][W][component:204]: Component pn532 took a long time for an operation (0.11 s).
[12:53:06][W][component:205]: Components should block for at most 20-30ms.

i confirm that happens with the pn532 on wemos d1 mini.

descipher commented 1 year ago

Tried, unsuccesfull. I uploaded video on my youtube channel how thing works. It can happen that it's ok a few times, but not constantly: _https://youtube.com/shorts/4KYrt_ZMZDo?feature=share_

Interesting that it has instances of correct timing, what happens when we keep the entire binary buzzer subset below 50ms in total. e.g. set the buzzer delay to 5ms. That would keep that total time down to 25ms.

Protoncek commented 1 year ago

I tried with 5ms timings: it's the same: beeping is erratic - sometimes very fast (almost like it should be), sometimes slower, it happened that there was pause almost 1s between two beeps (but it should be 5ms).

descipher commented 1 year ago

@Protoncek

I tried with 5ms timings: it's the same: beeping is erratic - sometimes very fast (almost like it should be), sometimes slower, it happened that there was pause almost 1s between two beeps (but it should be 5ms).

Can you send up the log output for a couple of tag events? I can create a branch that reverts the blocking warn back to verbose to rule it out if your interested in checking that out.

Protoncek commented 1 year ago

I don’t think that it will help, because i went back to esphome 2023.6 where these messages were still “hidden” (shown only with verbose) but hiccups still happen. So, it seems that it’s a global problem with delays somewhere in the code and it’s present for a while…

descipher commented 1 year ago

@Protoncek True, logs will be useful at the VERBOSE or VERY_VERBOSE level. Have you tried setting the interval to 2s?

Protoncek commented 1 year ago

Hm… I can try 2s tomorrow, sure. But i’m getting to see that logger is not the culprit and it merely lists problem, which lies elsewhere in the code. If logger would be the issue then the problem would be gone when i disable logger, but it doesn’t.

descipher commented 1 year ago

@Protoncek I was able to address the blocking problem by reducing logging time on the atm90e32 component so it has an effect but it's not the only element here. The reason for the 2s is to give the component more time making sure we are not polling it in the middle of an operation that has yet to be completed. It gives us more insight to whats happening e.g. the component is polled faster than it can handle it processing.

alexruffell commented 1 year ago

@descipher I have a 6ch CircuitSetup system that uses the 4 atm90e32 and have noticed that there appears to be an issue related to timing between "channels". While a small delay is normal, the delay between when the various channels are sampled appears significant enough to introduce a relatively large skew between channels (voltage measurements). There is an open issue related to this... I am just mentioning it to you as it sounded like you were reviewing the component's code to see what was causing the warnings and was hoping you might be able to confirm the above issue.

Of course, I took have these:

[17:07:27][W][component:204]: Component atm90e32.sensor took a long time for an operation (0.07 s).
[17:07:27][W][component:205]: Components should block for at most 20-30ms.

and

[17:08:04][W][component:204]: Component atm90e32.sensor took a long time for an operation (0.10 s).
[17:08:04][W][component:205]: Components should block for at most 20-30ms.

Interesting they bounce back and forth between 0.07 and 0.10s - could it be related to the issue I mentioned?

descipher commented 1 year ago

@descipher I have a 6ch CircuitSetup system that uses the 4 atm90e32 and have noticed that there appears to be an issue related to timing between "channels". While a small delay is normal, the delay between when the various channels are sampled appears significant enough to introduce a relatively large skew between channels (voltage measurements). There is an open issue related to this... I am just mentioning it to you as it sounded like you were reviewing the component's code to see what was causing the warnings and was hoping you might be able to confirm the above issue.

Of course, I took have these:
[17:07:27][W][component:204]: Component atm90e32.sensor took a long time for an operation (0.07 s).
[17:07:27][W][component:205]: Components should block for at most 20-30ms.
and
[17:08:04][W][component:204]: Component atm90e32.sensor took a long time for an operation (0.10 s).
[17:08:04][W][component:205]: Components should block for at most 20-30ms.
Interesting they bounce back and forth between 0.07 and 0.10s - could it be related to the issue I mentioned?

The SPI clock rate in the original code is set to 200KHz, it can go much faster on all esp devices. The ATM90E32 can go up to 4M so not sure why such a low value was chosen. Based on the closed issue you mentioned and the yaml provided its polling every 3s and thats very frequent. the Home Assistant DB will be slower due to the high number of entries, I would suggest 15s.

Set your logging baud_rate to 921600, this will help shorten the blocking time. If you want to test a SPI rate of 1MHz then add this the first lines of your device yaml file.

external_components:

source: github://descipher/esphome@component.atm90e32 components: [ atm90e32 ] refresh: 0s

If this makes it work correctly then reopen the issue.

wangeris commented 1 year ago

happening here as well. Using ESP32 as a BLE relay to home assistant.

[10:05:32][W][component:204]: Component esp32_ble_tracker took a long time for an operation (0.07 s).
[10:05:32][W][component:205]: Components should block for at most 20-30ms.

my config

esphome:
  name: "esp-relay"
  platform: ESP32
  board: nodemcu-32s

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "ESP Sleeping Fallback Hotspot"
    password: "VHKlUt5l6dzq"

captive_portal:

# Enable logging
logger:

# Enable Home Assistant API
api:

ota:

# Example configuration entry
esp32_ble_tracker:

sensor:
  - platform: atc_mithermometer
    mac_address: "A4:C1:38:6E:CD:1F"
    temperature:
      name: "Outside Temperature"
    humidity:
      name: "Outside Humidity"
    battery_level:
      name: "Outside Battery-Level"
    battery_voltage:
      name: "Outside Battery-Voltage"

Newspaperman57 commented 1 year ago

[12:10:44][W][component:204]: Component api took a long time for an operation (0.35 s).
[12:10:44][W][component:205]: Components should block for at most 20-30ms.

The device is riiiight on the edge of wifi-range and often completely looses connection when it's raining (like today), i would not be surprised that a simple ping would take 350ms to get through. This was on the first boot-up after an OTA-update.

lock:
  - platform: template
    name: Ledåbner
    optimistic: True
    lock_action:
      then:
        - servo.write:
            id: lockservo_hvid
            level: !lambda 'return -1;'
    unlock_action:
      then:
        - servo.write:
            id: lockservo_hvid
            level: !lambda 'return 1;'

servo:
  - id: lockservo_hvid
    output: servooutput_hvid
    idle_level: 9%
    min_level: 5%
    max_level: 8%
    restore: true
    auto_detach_time:  1s

output:
  - platform: esp8266_pwm
    id: servooutput_hvid
    pin: GPIO5
    frequency: 50 Hz

api:
  encryption:
    key: "<key>"

descipher commented 1 year ago

@jesserockz Observed the json memory resource error again:

[08:41:11][E][json:039]: Could not allocate memory for JSON document! Requested 440 bytes, largest free heap block: 440 bytes [08:41:11][D][sensor:093]: 'PM1 CT1 Watts': Sending state 315.84958 W with 1 decimals of accuracy [08:41:11][E][json:039]: Could not allocate memory for JSON document! Requested 176 bytes, largest free heap block: 176 bytes [08:41:11][D][sensor:093]: 'PM1 CT2 Watts': Sending state 564.16705 W with 1 decimals of accuracy [08:41:11][E][json:039]: Could not allocate memory for JSON document! Requested 176 bytes, largest free heap block: 176 bytes [08:41:11][D][sensor:093]: 'PM1 Freq': Sending state 59.96000 Hz with 1 decimals of accuracy [08:41:11][E][json:039]: Could not allocate memory for JSON document! Requested 176 bytes, largest free heap block: 176 bytes

Will need to revert back to 2023.6.5 to verifiy it was not there b4.

I suspect there is an issue with:

mqtt_component.cpp char friendly_name_hash[9]; sprintf(friendly_name_hash, "%08x", fnv1_hash(this->friendly_name())); sprintf(friendly_name_hash, "%08" PRIx32, fnv1_hash(this->friendly_name()));

I believe sprintf needs a specifier with "%08?" and PRIx32 seems out of place. e.g.

the value returned by this function should be usedC/C++cert-err33-c mqtt_component.cpp(121, 13): cast the expression to void to silence this warning int sprintf(char , const char , ...)

and

the value returned by this function should be usedC/C++cert-err33-c ota_component.cpp(194, 5): cast the expression to void to silence this warning int sprintf(char , const char , ...)

edwardtfn commented 1 year ago

I'm also having this with a Sonoff NSPanel flashed with this ESPHome.

[09:52:33][W][component:204]: Component adc.sensor took a long time for an operation (0.05 s).
[09:52:33][W][component:205]: Components should block for at most 20-30ms.

Sometimes I also get a similar message related to the display (Nextion).

rcblackwell commented 1 year ago

I'm using an lcd_pcf8574 with a 4 line LCD panel. I tried several i2c frequency settings. The errors remained.

[08:52:36][D][status_led:049]: 'led_status_light': Setting state ON [08:52:36][D][status_led:049]: 'led_status_light': Setting state OFF > [08:52:37][W][component:204]: Component lcd_base took a long time for an operation (0.06 s). [08:52:37][W][component:205]: Components should block for at most 20-30ms. [08:52:38][W][component:204]: Component lcd_base took a long time for an operation (0.06 s). [08:52:38][W][component:205]: Components should block for at most 20-30ms. [08:52:38][D][status_led:049]: 'led_status_light': Setting state ON [08:52:38][D][status_led:049]: 'led_status_light': Setting state OFF > [08:52:39][W][component:204]: Component lcd_base took a long time for an operation (0.06 s). [08:52:39][W][component:205]: Components should block for at most 20-30ms. [08:52:40][W][component:204]: Component lcd_base took a long time for an operation (0.06 s). [08:52:40][W][component:205]: Components should block for at most 20-30ms. [08:52:40][D][status_led:049]: 'led_status_light': Setting state ON [08:52:40][D][status_led:049]: 'led_status_light': Setting state OFF [08:52:41][D][sensor:094]: 'WiFi RSSI dBm': Sending state -59.00000 dBm with 0 decimals of accuracy > [08:52:41][W][component:204]: Component lcd_base took a long time for an operation (0.06 s). [08:52:41][W][component:205]: Components should block for at most 20-30ms. [08:52:42][W][component:204]: Component lcd_base took a long time for an operation (0.06 s). [08:52:42][W][component:205]: Components should block for at most 20-30ms.

morris2009 commented 1 year ago

Same issue here with DSMR I tried setting the i2c frequency to 400khz but that didn't make any difference for me.

Config:

substitutions:
  name: dsmr-reader
  friendly_name: DSMR Reader

esphome:
  name: ${name}
  platform: ESP8266
  board: d1_mini

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "Dsmr-Reader Fallback Hotspot"
    password: XXXXXXXXXXXXXXX

captive_portal:

# Enable Home Assistant API
api:
  #password: !secret api_password
  encryption:
    key: !secret api_key

ota:
  password: !secret ota_password

logger:
  # Serial logging is disabled by setting the logger baud rate to 0.
  # Otherwise the logger will occupy the hardware UART, making it unavailable
  # for receiving smart meter data on pin D7 (GPIO13).
  baud_rate: 0
  level: VERBOSE

uart:
  rx_pin: D7
  baud_rate: 115200
  rx_buffer_size: 1500

dsmr:
  request_pin: D5
  request_interval: 10s

sensor:
  - platform: dsmr
    energy_delivered_tariff1:
      name: ${friendly_name} Energy Delivered Tariff 1
      state_class: total_increasing
    energy_delivered_tariff2:
      name: ${friendly_name} Energy Delivered Tariff 2
      state_class: total_increasing
    energy_returned_tariff1:
      name: ${friendly_name} Energy Returned Tariff 1
      id: e_return_t1
    energy_returned_tariff2:
      name: ${friendly_name} Energy Returned Tariff 2
      id: e_return_t2
    power_delivered:
      name: ${friendly_name} Power Consumed
    power_returned:
      name: ${friendly_name} Power Returned
    electricity_failures:
      name: ${friendly_name} Electricity Failures
    electricity_long_failures:
      name: ${friendly_name} Electricity Long Failures
    voltage_l1:
      name: ${friendly_name} Voltage L1
    voltage_l2:
      name: ${friendly_name} Voltage L2
    voltage_l3:
      name: ${friendly_name} Voltage L3
    current_l1:
      name: ${friendly_name} Current L1
    current_l2:
      name: ${friendly_name} Current L2
    current_l3:
      name: ${friendly_name} Current L3
    power_delivered_l1:
      name: ${friendly_name} Power Delivered L1
    power_delivered_l2:
      name: ${friendly_name} Power Delivered L2
    power_delivered_l3:
      name: ${friendly_name} Power Delivered L3
    power_returned_l1:
      name: ${friendly_name} Power Returned L1
    power_returned_l2:
      name: ${friendly_name} Power Returned L2
    power_returned_l3:
      name: ${friendly_name} Power Returned L3
    gas_delivered:
      name: ${friendly_name} Gas Delivered

text_sensor:
  - platform: dsmr
    identification:
      name: ${friendly_name} Identification
    p1_version:
      name: ${friendly_name} Version
    electricity_tariff:
      name: ${friendly_name} Electricity Tariff
    gas_equipment_id:
      name: ${friendly_name} Gas Equipment ID

i2c:
  sda: D2
  scl: D1
  frequency: 100khz

font:
    # gfonts://family[@weight]
  - file: "gfonts://Roboto"
    id: roboto
    size: 12

display:
  - platform: ssd1306_i2c
    model: "SSD1306 128x64"
    #reset_pin: D0
    address: 0x3C
    update_interval: 10s
    lambda: |-
        it.print(0, 10, id(roboto), "Energy returned"); 
        it.printf(0, 25, id(roboto), "tariff1: %.1f", id(e_return_t1).state);
        it.printf(0, 45, id(roboto), "tariff2: %.1f", id(e_return_t2).state);

And a snippet of the log:

INFO ESPHome 2023.7.1
INFO Reading configuration /config/dsmr-reader.yaml...
INFO Starting log output from dsmr-reader.local using esphome API
INFO Successfully connected to dsmr-reader.local
[23:28:50][I][app:102]: ESPHome version 2023.7.1 compiled on Aug  2 2023, 23:03:21
[23:28:50][C][wifi:543]: WiFi:

..

[23:30:52][V][text_sensor:013]: 'DSMR Reader Electricity Tariff': Received new state 0001
[23:30:52][D][text_sensor:064]: 'DSMR Reader Electricity Tariff': Sending state '0001'
[23:30:52][V][text_sensor:013]: 'DSMR Reader Gas Equipment ID': Received new state 4730303431303031383231383333393138
[23:30:52][D][text_sensor:064]: 'DSMR Reader Gas Equipment ID': Sending state '4730303431303031383231383333393138'
[23:30:52][W][component:204]: Component dsmr took a long time for an operation (0.08 s).
[23:30:52][W][component:205]: Components should block for at most 20-30ms.
[23:31:01][V][dsmr:102]: Start requesting data from P1 port
[23:31:01][V][dsmr:142]: Header of telegram found
[23:31:02][V][dsmr:176]: Footer of telegram found

jipp commented 1 year ago

the same log messages I see for SML:

basement    | [09:55:59][W][component:204]: Component sml took a long time for an operation (0.06 s).
basement    | [09:55:59][W][component:205]: Components should block for at most 20-30ms.
basement    | [09:56:00][W][component:204]: Component sml took a long time for an operation (0.06 s).
basement    | [09:56:00][W][component:205]: Components should block for at most 20-30ms.
basement    | [09:56:01][W][component:204]: Component sml took a long time for an operation (0.06 s).
basement    | [09:56:01][W][component:205]: Components should block for at most 20-30ms.
basement    | [09:56:02][W][component:204]: Component sml took a long time for an operation (0.07 s).
basement    | [09:56:02][W][component:205]: Components should block for at most 20-30ms.

example snippet form the code:

- platform: sml
  name: Summe der Momentan-Leistungen in allen Phasen
  obis_code: 1-0:16.7.0
  unit_of_measurement: W
  accuracy_decimals: 2
  device_class: power
  state_class: measurement
  filters:
  - multiply: 0.01
  - throttle_average: 60s
  disabled_by_default: false
  force_update: false
  server_id: ''

vrees commented 1 year ago

Same problem using display st7735 connected to SPI:

log output:

[10:20:59][W][component:204]: Component st7735.display took a long time for an operation (0.13 s).
[10:20:59][W][component:205]: Components should block for at most 20-30ms.

configuration:

esphome:
  name: ds18b20-thermo-display

esp32:
  board: esp32dev

<<: !include ../base.yaml

spi:
  clk_pin: GPIO18
  mosi_pin: GPIO23
  # miso_pin: GPIO12

font:
  - file: 'BebasNeue-Regular.ttf'
    id: bebasfont
    size: 36
  - file: 'arial.ttf'
    id: arialfont
    size: 20

display:
  - platform: st7735
    model: "INITR_18BLACKTAB"
    reset_pin: GPIO4
    cs_pin: GPIO5
    dc_pin: GPIO2
    rotation: 0
    device_width: 128
    device_height: 160
    col_start: 0
    row_start: 0
    eight_bit_color: true
    update_interval: 5s

    lambda: |-
      auto red = Color(255, 30, 30);
      auto green = Color(0, 255, 0);
      auto blue = Color(100, 100, 255);
      auto white = Color(255, 255, 255);
      auto lila = Color(255, 0, 255);
      auto yellow = Color(255, 255, 0);

      it.print(14, 0, id(bebasfont), "DS18B20");  
      it.printf(0, 40, id(arialfont), red,     "T1:          %3.1f", id(temperature_1).state);  
      it.printf(0, 65, id(arialfont), green,   "T2:          %3.1f", id(temperature_2).state);  
      it.printf(0, 90, id(arialfont), blue,    "T3:          %3.1f", id(temperature_3).state);  
      it.printf(0, 115, id(arialfont), yellow, "T4:          %3.1f", id(temperature_4).state);  
      it.printf(0, 140, id(arialfont), lila,   "T5:          %3.1f", id(temperature_5).state);  `

gb0101010101 commented 1 year ago

[04:04:19][W][component:204]: Component ina3221.sensor took a long time for an operation (0.12 s).
[04:04:19][W][component:205]: Components should block for at most 20-30ms.

Can the units of measurement between warnings be consistent? First warning reports in unit seconds (s) and second reports milliseconds (ms). Would be cleaner if they used same unit.

Specifying "at most" and providing a range "20-30ms" is unclear. Suggest definitive statement such as Components should block for at most 30ms.

geiseri commented 1 year ago

I see this for the following:

 aqi-1 component [W][component:204]: Component hm3301.sensor took a long time for an operation (0.06 s).
 aqi-1 component [W][component:204]: Component interval took a long time for an operation (0.14 s).
 aqi-1 component [W][component:204]: Component ssd1306_base took a long time for an operation (0.14 s).

Notes:

The hm3301 seems to only show this warning if I have it publish all 4 values. If I only publish any two of them I no longer see the warning.
Interval updates the current page on the display every 5 seconds.
The display will always give this warning on every draw operation. This is a known issue though
I think the hm3301 and interval are not directly blocking, but the underlying actions performed are causing that.

 inkplate10 component [W][component:204]: Component status.binary_sensor took a long time for an operation (4.32 s).

Notes:

This device spends most of its time in deep sleep. It will wake up once every 30min, download new information to display and then go back to sleep. Status is published first, I noticed if I removed it and only did the Wifi metrics, then it would warn on those. So maybe this is because it's the first one and blocks until the API to become ready.

 magtag component [W][component:204]: Component waveshare_epaper.display took a long time for an operation (0.14 s).

Notes:

It's eInk.... It would be faster to draw by hand 🤣

 sleep-sensor component [W][component:204]: Component api took a long time for an operation (0.35 s).

 wio-link component [W][component:204]: Component api took a long time for an operation (0.35 s).

Notes:

These two are interesting, they are both ESP8266 devices. They might just be slow in general.

@jesserockz TL;DR: Using WarnIfComponentBlockingGuard inside of Application::loop lacks context to give meaningful warnings.

To be honest the "be less than Xms" approach will always be flawed in some way. While it's a noble goal to reduce the time spent on a task in a cooperative operating system scheduler, not all tasks are the same. You could also argue that if the overall performance is not impacted does it really matter?

As you said some will block on inherently slow operations (eInk screen update, waiting for HomeAssistant api, etc). Along with those cases, running automation or publishing to home assistant can also cause the same situation. If I understand the code correctly all automation callbacks and sending information to the API will block the component when publish_state is performed. Those could be good places to actually provide a warning, since then the user would know more specifically the issue exists. Barring a more exotic trace system as part of or similar to the debug component I do not see the utility of the warning to help diagnose and address performance issues. Otherwise, I fear the warning is just noise to users that will cause them to become numb to real issues.

mwolter805 commented 1 year ago

Occasionally receiving these warnings

Component mhz19.sensor took a long time for an operation (0.05 s).
11:42:25    [W] [component:205] 
Components should block for at most 20-30ms.


uart:  
  - rx_pin: GPIO1
    tx_pin: GPIO3
    baud_rate: 9600
    id: mh

# MH-Z19 CO2 Sensor  
  - platform: mhz19
    co2:
      name: "${friendly_name} CO2"
      id: co2
      filters:
        - median:
            window_size: 5
            send_every: 1
        - or:
          - throttle: 1min
          - delta: 5
      on_value:
        - if:
            condition:
              sensor.in_range:
                id: co2
                below: 700
            then: 
              - light.control:
                  id: led3
                  red: 0
                  green: 90%
                  blue: 0
        - if:
            condition:
              sensor.in_range:
                id: co2
                above: 700
                below: 1000
            then: 
              - light.control:
                  id: led3
                  red: 100%
                  green: 100%
                  blue: 0
        - if:
            condition:
              sensor.in_range:
                id: co2
                above: 1000
                below: 1500
            then: 
              - light.control:
                  id: led3
                  red: 100%
                  green: 50%
                  blue: 0
        - if:
            condition:
              sensor.in_range:
                id: co2
                above: 1500
                below: 2100
            then: 
              - light.control:
                  id: led3
                  red: 90%
                  green: 0
                  blue: 0
        - if:
            condition:
              sensor.in_range:
                id: co2
                above: 2100
            then: 
              - light.control:
                  id: led3
                  red: 56%
                  green: 25%
                  blue: 60%
        - lambda: |-
            if(id(co2).state > id(co_max)) { id(co_max) = id(co2).state; }
            if(id(co2).state < id(co_min)) { id(co_min) = id(co2).state; }
    temperature:
      name: "${friendly_name} MH-Z19 Temperature"
      filters:
        - or:
          - throttle: 1min
          - delta: .5
    update_interval: 10s
    automatic_baseline_calibration: false
    uart_id: mh
    id: mh_sensor

hwstar commented 1 year ago

I'm seeing the same thing with the tmp102 sensor:

As mentioned by ssieb on Discord, the tm102 sensor has a 50mS delay in its update method:

void TMP102Component::update() {
  uint16_t raw_temperature;
  if (this->write(&TMP102_REGISTER_TEMPERATURE, 1) != i2c::ERROR_OK) {
    this->status_set_warning();
    return;
  }
  delay(50);  // NOLINT <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
  if (this->read(reinterpret_cast<uint8_t *>(&raw_temperature), 2) != i2c::ERROR_OK) {
    this->status_set_warning();
    return;
  }
  raw_temperature = i2c::i2ctohs(raw_temperature);

What would really be cool is to have a way to give up the processor when doing delays, or waiting for I/O to complete. This would probably generate a lot of complexity in ESPHome though.

hellcry37 commented 1 year ago

2023.7.1 still has this issue

hapklaar commented 1 year ago

Also seeing this behavior every second (all 0.06 s) with an external component:

external_components:
  - source: github://landonr/lilygo-tdisplays3-esphome
    components: [tdisplays3]

[14:09:52][W][component:204]: Component tdisplays3.display took a long time for an operation (0.06 s).
[14:09:52][W][component:205]: Components should block for at most 20-30ms.

Cossid commented 1 year ago

@jesserockz There appears to be a large number of components which do not use callbacks. Seems to be the main reason for the blocking. I did some digging with atm90e32 and its not doing anything heavy but it still runs just under 50ms to do its fundamental outputs, we could certainly lower the amount a serial logging on some of the components. But I would assume the right path is to convert them to use callbacks where possible.

@descipher Is there any documentation or guidance on how to properly implement callbacks? Obviously the point of this issue is to eventually correct all core components, but it would be nice to have documentation explaining what this warning is/why it's happening, and expected solutions for external components as well.

anekinloewe commented 1 year ago

I see the warnings too.

[17:58:45][W][component:205]: Components should block for at most 20-30ms.
[17:58:47][W][component:204]: Component sml took a long time for an operation (0.18 s).
[17:58:47][W][component:205]: Components should block for at most 20-30ms.
[17:58:47][W][component:204]: Component sml took a long time for an operation (0.19 s).
[17:58:47][W][component:205]: Components should block for at most 20-30ms.
[17:58:48][W][component:204]: Component sml took a long time for an operation (0.19 s).
[17:58:48][W][component:205]: Components should block for at most 20-30ms.
[17:58:49][W][component:204]: Component sml took a long time for an operation (0.18 s).

snippet from config:

  - platform: sml`
    name: "Wirkleistung Haus"
    id: leistung_haus
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:16.7.0"
    unit_of_measurement: W
    state_class: measurement
    device_class: power
    accuracy_decimals: 0

  - platform: sml
    name: "U_L1 Haus"
    id: uL1
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:32.7.0"
    unit_of_measurement: V
    accuracy_decimals: 1
    filters:
      - multiply: 0.1

  - platform: sml
    name: "U_L2 Haus"
    id: uL2
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:52.7.0"
    unit_of_measurement: V
    accuracy_decimals: 1
    filters:
      - multiply: 0.1

  - platform: sml
    name: "U_L3 Haus"
    id: uL3
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:72.7.0"
    unit_of_measurement: V
    accuracy_decimals: 1
    filters:
      - multiply: 0.1

  - platform: sml
    name: "I_L1 Haus"
    id: iL1
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:31.7.0"
    unit_of_measurement: A
    accuracy_decimals: 2
    filters:
      - multiply: 0.01

  - platform: sml
    name: "I_L2 Haus"
    id: iL2
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:51.7.0"
    unit_of_measurement: A
    accuracy_decimals: 2
    filters:
      - multiply: 0.01

  - platform: sml
    name: "I_L3 Haus"
    id: iL3
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:71.7.0"
    unit_of_measurement: A
    accuracy_decimals: 2
    filters:
      - multiply: 0.01

  - platform: sml
    name: "Frequenz Haus"
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:14.7.0"
    unit_of_measurement: Hz
    accuracy_decimals: 1
    filters:
      - multiply: 0.1

  - platform: sml
    name: "Phasenwinkel L1 Haus"
    id: cosL1
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:81.7.4"

  - platform: sml
    name: "Phasenwinkel L2 Haus"
    id: cosL2
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:81.7.15"

  - platform: sml
    name: "Phasenwinkel L3 Haus"
    id: cosL3
    sml_id: hausstrom_sml
    server_id: ""
    obis_code: "1-0:81.7.26"

descipher commented 1 year ago

@jesserockz There appears to be a large number of components which do not use callbacks. Seems to be the main reason for the blocking. I did some digging with atm90e32 and its not doing anything heavy but it still runs just under 50ms to do its fundamental outputs, we could certainly lower the amount a serial logging on some of the components. But I would assume the right path is to convert them to use callbacks where possible.

@descipher Is there any documentation or guidance on how to properly implement callbacks? Obviously the point of this issue is to eventually correct all core components, but it would be nice to have documentation explaining what this warning is/why it's happening, and expected solutions for external components as well.

No guides that I am aware of. There are multiple ways to address some of these delays. Some can be solved by using local interval sampling and then when the HA polling event occurs it draws from the last sampled value instead of waiting for it. Also we can process display updates with buffering instead of waiting on realtime completion. Callbacks are similar but still do not guarantee a stable io call when the polling rate is to high.

AlexValery13 commented 1 year ago

23:16:14 | [W] | [component:204] | Component st7920.display took a long time for an operation (0.22 s).
23:16:14 | [W] | [component:205] | Components should block for at most 20-30ms.

spi:
  clk_pin: GPIO12
  mosi_pin: GPIO14

display:
  - platform: st7920
    width: 128
    height: 64
    cs_pin:
      number: GPIO3
      inverted: true
    update_interval: 500ms

AlexValery13 commented 1 year ago

[23:23:36][W][component:204]: Component htu21d.sensor took a long time for an operation (0.12 s).
[23:23:36][W][component:205]: Components should block for at most 20-30ms.

i2c:
  sda: GPIO0
  scl: GPIO2
  scan: true
  frequency: 8khz

jipp commented 1 year ago

the same log messages I see for SML:

basement    | [09:55:59][W][component:204]: Component sml took a long time for an operation (0.06 s).
basement    | [09:55:59][W][component:205]: Components should block for at most 20-30ms.
basement    | [09:56:00][W][component:204]: Component sml took a long time for an operation (0.06 s).
basement    | [09:56:00][W][component:205]: Components should block for at most 20-30ms.
basement    | [09:56:01][W][component:204]: Component sml took a long time for an operation (0.06 s).
basement    | [09:56:01][W][component:205]: Components should block for at most 20-30ms.
basement    | [09:56:02][W][component:204]: Component sml took a long time for an operation (0.07 s).
basement    | [09:56:02][W][component:205]: Components should block for at most 20-30ms.

example snippet form the code:

- platform: sml
  name: Summe der Momentan-Leistungen in allen Phasen
  obis_code: 1-0:16.7.0
  unit_of_measurement: W
  accuracy_decimals: 2
  device_class: power
  state_class: measurement
  filters:
  - multiply: 0.01
  - throttle_average: 60s
  disabled_by_default: false
  force_update: false
  server_id: ''

played around with the throttle and throttle_average settings.

using the following the log messages disappear:

- platform: sml
  name: Zählerstand zu +A, tariflos
  obis_code: 1-0:1.8.0
  unit_of_measurement: Wh
  accuracy_decimals: 2
  device_class: energy
  state_class: total_increasing
  filters:
  - multiply: 0.00001
  - throttle: 1s
  - throttle_average: 60s

KimCarlsen commented 1 year ago

have it on the modbus_controller

juanmijm commented 1 year ago

I'm seeing this:

[23:36:21][W][component:204]: Component esphome.coroutine took a long time for an operation (0.10 s).
[23:36:21][W][component:205]: Components should block for at most 20-30ms.
[23:36:23][W][component:204]: Component esphome.coroutine took a long time for an operation (0.10 s).
[23:36:23][W][component:205]: Components should block for at most 20-30ms.

When using the component:

external_components:
  - source: github://geoffdavis/esphome-mitsubishiheatpump@develop

climate:
  - platform: mitsubishi_heatpump
    name: "${name}"
    id: ${device_id}_climate
    hardware_uart: UART1
    tx_pin: 12
    rx_pin: 13
    visual:
      temperature_step: 1.0

same for me, I am also experiencing continuous wifi connection cuts, does it happen to you too?

jov58 commented 1 year ago

I am also getting these warnings with http_requests. This piece of code:

script
  - id: get_${zone}_${number}_state
    then:
      - http_request.get:
          url: http://${ip}/sensor/state_${zone}_${number}
          on_response:
            then:
              - logger.log:
                  level: ERROR
                  format: 'Response status ${zone}: %d, Duration: %u ms'
                  args:
                    - status_code
                    - duration_ms
              - lambda: |-
                  std::string response_data = id(http_request_data).get_string();

generates the warning on almost every loop. The code above does http_requests on the local network to other ESPHome devices, varying from ESP-01's to ESP32. The duration of most requests is around 300 ms, some are below 100 ms and at most one out of 10 is under 30 ms.

Is it useful to show this warning with http_requests, which almost by definition take longer than 30ms?

MarkoPaasila commented 1 year ago

I had this "took a long time" annoyance on one board communicating to a mitsubishi heatpump. Another board completely failed to communicate to a mitsubishi heatpump and a pzem v3.

Downgrading to 2023.4.4 solved all three issues.

Danifly80 commented 1 year ago

Also Sensirion SGP41 generate this;

[22:40:00][W][component:204]: Component sgp4x.sensor took a long time for an operation (0.06 s).
[22:40:00][W][component:205]: Components should block for at most 20-30ms.

config:


  #Sensor interval time
  sensors_update_interval: 10min

#i2c interface
i2c:
  - id: i2c_1
    sda: 21
    scl: 22
    scan: true

  #SGP41 - VOC and NOx Sensor ------
  - platform: sgp4x
    i2c_id: i2c_1
    voc:
      name: "${friendly_name} - VOC Index"
      id: voc
      icon: mdi:air-filter
    nox:
      name: "${friendly_name} - NOx Index"
      id: nox
      icon: mdi:fire
    compensation:
      humidity_source: rel_hum
      temperature_source: air_temp
    update_interval: '${sensors_update_interval}'

esphome / issues