search

ginkage / MHI-AC-Ctrl-ESPHome

ESPHome integration for MHI-AC-Ctrl project
MIT License
112 stars 39 forks source link

Component <unknown> took a long time for an operation #61

Closed JoepWi closed 2 months ago

JoepWi commented 1 year ago

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?

fonske commented 1 year ago

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

rphenix commented 1 year ago

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.

acfnews commented 1 year ago

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'.

mauriceazrak commented 1 year ago

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

acfnews commented 1 year ago

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?

arpiecodes commented 1 year ago

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.

mauriceazrak commented 1 year ago

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

arpiecodes commented 1 year ago

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.

mauriceazrak commented 1 year ago

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 ?

Lieta2 commented 8 months ago

Same here with SRK35ZM-S

EvoSems commented 8 months ago

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).

jamhos commented 7 months ago

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.

arpiecodes commented 7 months ago

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
RobertJansen1 commented 2 months ago

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