MHI-AC-Ctrl-ESPHome icon indicating copy to clipboard operation
MHI-AC-Ctrl-ESPHome copied to clipboard

Component <unknown> took a long time for an operation

Open JoepWi opened this issue 1 year ago • 13 comments

I have a SRF35ZS-W connected and all automations and scripts work fine with it, but I see this very often in the log:

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

With the other 3 units SRK25ZS-W I see the same messages also, but not as often as with the SRF35ZS-W

Any idea where this warnings comes from and if there is a way to solve this?

JoepWi avatar Jul 24 '23 09:07 JoepWi

Must be the (newest) esphome version i think...

Different code (brink modbus) same result: 2023.7.0 https://tweakers.net/fotoalbum/image/zH0EflCZgqmE4BkrncqOtkQL.jpg

2023.4.4 https://tweakers.net/fotoalbum/image/Jgu447nRuFHXPu4W6mLGHN0o.jpg

See also: https://github.com/esphome/issues/issues/4717

fonske avatar Jul 24 '23 17:07 fonske

I'm getting repeat: [19:26:52][W][component:204]: Component took a long time for an operation (0.10 s). [19:26:52][W][component:205]: Components should block for at most 20-30ms. [19:26:52][W][mhi_ac_ctrl:138]: mhi_ac_ctrl_core.loop error: -4

Is this a similar issue or something else? For me I'm not getting any response from the SRK50ZJX-S when sending commands.

rphenix avatar Aug 22 '23 10:08 rphenix

I found this issue in the Esphome GitHub, I guess this is the reason for the appearance of these messages?

link

The only think I am not sure about, is in my case, the component in my logs is 'unknown'.

acfnews avatar Sep 16 '23 20:09 acfnews

Bonjour AFCNEWS, est ce que tu as trouvé la solution au probleme car j'ai le même probleme ? logs_lr_mhi_ac_ctrl_logs.txt

mauriceazrak avatar Sep 30 '23 07:09 mauriceazrak

Bonjour AFCNEWS, est ce que tu as trouvé la solution au probleme car j'ai le même probleme ? logs_lr_mhi_ac_ctrl_logs.txt

No I have not solved it. Maybe you can put your log also in the esp home GitHub, the more bugs reported the marrier?

acfnews avatar Oct 01 '23 19:10 acfnews

These messages are normal for components that poll stuff/process a lot of values. ESPHome runs everything single-threaded (developers don't think multi-threading is necessary as the ESP generally has more than enough processing power) - and as such any delays in component code will stall the main loop and with it everything else. Which is probably why they put this warning in.

In reality, it will not do any harm if communication with the AC is the only thing your ESP does. It is just a ways for the devs to make other devs more conscious of the effects stalls have on the general loop. Safe to say, if it reports the message now, it has always been this way. The only thing that has changed over the past couple of versions is the addition of the warning message.

The error messages some of you are seeing (error -4, error -3) typically indicate an error with SPI communication. You probably have some sort of wiring issue or your ESP is faulty. It's not something you will be able to fix by changing config or code. Inspect your wiring.

Ergo;

Especially if you see the warning about the long delays (0.10s) - this kind of indicates your ESP is not getting any response by the AC unit and gives up waiting after 100ms.

The warning about 0.06s delay is probably benign and the actual time required for the ESP and AC to communicate with each other.

arpiecodes avatar Oct 02 '23 10:10 arpiecodes

Ok, Merci pour ton explication. Je pense que c'est donc mon circuit electronique qui a un probleme (je ne suis pas sûr de la valeur des condensateurs C1 C2......) peut etre à cause de cela que le delai de réponse est long... J'ai commandé un module quasiment pret sur Nodo Shop, il n'y a que quelques soudure à faire, je te tiens au courant dès que je l'ai reçu et essayé....

https://www.nodo-shop.nl/en/our-products/228-espac-wifi-mitsubishi-heavy-industries-interface.html

Bonne journée

mauriceazrak avatar Oct 02 '23 11:10 mauriceazrak

https://www.nodo-shop.nl/en/our-products/228-espac-wifi-mitsubishi-heavy-industries-interface.html

Good choice! That should work much better. Let us know how it fares and if it solved your issues.

arpiecodes avatar Oct 02 '23 11:10 arpiecodes

Bonsoir à vous tous, je viens de faire les quelques soudures, connecté le module, tout fonctionne maintenant, enfin !! Je pense effectivepment que cela venait de mes soudure/composants electroniques..... Par contre, quelqu'un sait comment controler le MHI CTRL à partir d'un capteur de température externeen zigbee sous homeassistant au lieu du controleur de température interne à l'appareil ?

mauriceazrak avatar Oct 03 '23 17:10 mauriceazrak

Same here with SRK35ZM-S

Lieta2 avatar Mar 11 '24 18:03 Lieta2

getting the same. I can block the errors with the following but a fix would be sweet

logger: level: DEBUG baud_rate: 0 logs: component: ERROR

[11:59:43][D][mhi_ac_ctrl:158]: received status=70 value=178 power=1 [11:59:43][D][climate:396]: 'Lounge Room Aircon' - Sending state: [11:59:43][D][climate:399]: Mode: HEAT_COOL [11:59:43][D][climate:404]: Fan Mode: AUTO [11:59:43][D][climate:416]: Swing Mode: OFF [11:59:43][D][climate:419]: Current Temperature: 29.25°C [11:59:43][D][climate:425]: Target Temperature: 24.00°C [11:59:43][W][component:232]: Component took a long time for an operation (68 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:43][W][component:232]: Component took a long time for an operation (64 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:43][W][component:232]: Component took a long time for an operation (64 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:43][W][component:232]: Component took a long time for an operation (63 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (63 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (62 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (65 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (64 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (59 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (69 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (67 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (64 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (62 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (64 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (65 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (65 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (71 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (65 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (61 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (61 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (62 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (63 ms). [11:59:48][W][component:233]: Components should block for at most 30 ms. [11:59:48][W][component:232]: Component took a long time for an operation (60 ms). [11:59:48][W][component:233]: Components should block for at most 30 ms. [11:59:48][W][component:232]: Component took a long time for an operation (53 ms). [11:59:48][W][component:233]: Components should block for at most 30 ms. [11:59:48][W][component:232]: Component took a long time for an operation (56 ms).

EvoSems avatar Mar 23 '24 02:03 EvoSems

getting the same. I can block the errors with the following but a fix would be sweet

logger: level: DEBUG baud_rate: 0 logs: component: ERROR

[11:59:43][D][mhi_ac_ctrl:158]: received status=70 value=178 power=1 [11:59:43][D][climate:396]: 'Lounge Room Aircon' - Sending state: [11:59:43][D][climate:399]: Mode: HEAT_COOL [11:59:43][D][climate:404]: Fan Mode: AUTO [11:59:43][D][climate:416]: Swing Mode: OFF [11:59:43][D][climate:419]: Current Temperature: 29.25°C [11:59:43][D][climate:425]: Target Temperature: 24.00°C [11:59:43][W][component:232]: Component took a long time for an operation (68 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:43][W][component:232]: Component took a long time for an operation (64 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:43][W][component:232]: Component took a long time for an operation (64 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:43][W][component:232]: Component took a long time for an operation (63 ms). [11:59:43][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (63 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (62 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (65 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (64 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (59 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (69 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (67 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (64 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (61 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (62 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (64 ms). [11:59:45][W][component:233]: Components should block for at most 30 ms. [11:59:45][W][component:232]: Component took a long time for an operation (65 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (65 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (71 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (65 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (61 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (61 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (62 ms). [11:59:46][W][component:233]: Components should block for at most 30 ms. [11:59:46][W][component:232]: Component took a long time for an operation (63 ms). [11:59:48][W][component:233]: Components should block for at most 30 ms. [11:59:48][W][component:232]: Component took a long time for an operation (60 ms). [11:59:48][W][component:233]: Components should block for at most 30 ms. [11:59:48][W][component:232]: Component took a long time for an operation (53 ms). [11:59:48][W][component:233]: Components should block for at most 30 ms. [11:59:48][W][component:232]: Component took a long time for an operation (56 ms).

Thank you! Fixed it for me.

jamhos avatar Mar 30 '24 09:03 jamhos

This is not really a bug; it's just the ESPHome devs that decided to put in a notice when anything causes the mainloop to be busy for more than 30ms (as you can read). The communication code of the component needs more than 30ms do to it's thing and is dependant on the AC unit to respond (sometimes with a slight delay).

That's just how it is, and it will not be fixed or improved.

So if you want to hide it (no idea why though, as you're not really using the console anyways if not for debugging);

logger:
  logs:
    component: ERROR

arpiecodes avatar Mar 30 '24 09:03 arpiecodes

There is nothing we can do about this, as the airco units are "slow" to esphome standards. a work-around is described, and #99 will have an FaQ item on this

RobertJansen1 avatar Aug 30 '24 12:08 RobertJansen1