JNSwanson / ESP-Home-iBoost

ESPHOME Marlec iboost integration
MIT License
20 stars 2 forks source link

Component <unknown> took a long time for an operation (0.08 s). #7

Open no1knows opened 1 year ago

no1knows commented 1 year ago

After updating the firmware to the latest version it doesn't appear to be trying to initiate the radio anymore:

INFO ESPHome 2023.8.1
INFO Reading configuration /config/esphome/iBoost.yaml...
INFO Starting log output from iboostesphome.local using esphome API
INFO Successfully connected to iboostesphome.local
[17:14:10][I][app:102]: ESPHome version 2023.8.1 compiled on Aug 19 2023, 14:16:52
[17:14:10][C][wifi:543]: WiFi:
[17:14:10][C][wifi:379]:   Local MAC: C4:5B:BE:4C:CB:12
[17:14:10][C][wifi:380]:   SSID: [redacted]
[17:14:10][C][wifi:381]:   IP Address: 192.168.1.173
[17:14:10][C][wifi:382]:   BSSID: [redacted]
[17:14:10][C][wifi:384]:   Hostname: 'iboostesphome'
[17:14:10][C][wifi:386]:   Signal strength: -74 dB ▂▄▆█
[17:14:10][C][wifi:390]:   Channel: 11
[17:14:10][C][wifi:391]:   Subnet: 255.255.255.0
[17:14:10][C][wifi:392]:   Gateway: 192.168.1.1
[17:14:10][C][wifi:393]:   DNS1: 192.168.1.1
[17:14:10][C][wifi:394]:   DNS2: 0.0.0.0
[17:14:10][C][logger:301]: Logger:
[17:14:10][C][logger:302]:   Level: DEBUG
[17:14:10][C][logger:303]:   Log Baud Rate: 115200
[17:14:10][C][logger:305]:   Hardware UART: UART0
[17:14:10][C][template.number:050]: Template Number 'iBoost Manual Boost Time'
[17:14:10][C][template.number:050]:   Icon: 'mdi:solar-power'
[17:14:10][C][template.number:050]:   Unit of Measurement: 'Minutes'
[17:14:10][C][template.number:051]:   Optimistic: YES
[17:14:10][C][template.number:052]:   Update Interval: 60.0s
[17:14:10][C][captive_portal:088]: Captive Portal:
[17:14:10][C][mdns:112]: mDNS:
[17:14:10][C][mdns:113]:   Hostname: iboostesphome
[17:14:10][C][ota:093]: Over-The-Air Updates:
[17:14:10][C][ota:094]:   Address: iboostesphome.local:8266
[17:14:10][C][ota:097]:   Using Password.
[17:14:10][C][api:138]: API Server:
[17:14:10][C][api:139]:   Address: iboostesphome.local:6053
[17:14:10][C][api:141]:   Using noise encryption: YES
[17:15:25][I][ota:113]: Boot seems successful, resetting boot loop counter.

It just sits here, no mention of SPI, radios etc.... anyone else seeing this?

JNSwanson commented 1 year ago

You did update the network name and password in the yaml file?

no1knows commented 1 year ago

Thanks, I did. I also tried to do a fresh update in Home Assistant per the issue above, which works. It still doesn't seem to kick off any radio-related stuff:

INFO ESPHome 2023.8.1
INFO Reading configuration /config/esphome/iBoost.yaml...
INFO Generating C++ source...
INFO Compiling app...
Processing iboostesphome (board: d1_mini; framework: arduino; platform: platformio/espressif8266@3.2.0)
--------------------------------------------------------------------------------
HARDWARE: ESP8266 80MHz, 80KB RAM, 4MB Flash
Dependency Graph
|-- ESPAsyncTCP-esphome @ 1.2.3
|-- SPI @ 1.0
|-- ESPAsyncWebServer-esphome @ 2.1.0
|-- DNSServer @ 1.1.1
|-- ESP8266WiFi @ 1.0
|-- ESP8266mDNS @ 1.2
|-- noise-c @ 0.1.4
Compiling /data/iboostesphome/.pioenvs/iboostesphome/src/CC1101_RFx.cpp.o
Linking /data/iboostesphome/.pioenvs/iboostesphome/firmware.elf
RAM:   [====      ]  42.7% (used 34988 bytes from 81920 bytes)
Flash: [=====     ]  48.5% (used 506405 bytes from 1044464 bytes)
Building /data/iboostesphome/.pioenvs/iboostesphome/firmware.bin
esp8266_copy_factory_bin(["/data/iboostesphome/.pioenvs/iboostesphome/firmware.bin"], ["/data/iboostesphome/.pioenvs/iboostesphome/firmware.elf"])
========================= [SUCCESS] Took 29.12 seconds =========================
INFO Successfully compiled program.
INFO Resolving IP address of iboostesphome.local
INFO  -> 192.168.1.173
INFO Uploading /data/iboostesphome/.pioenvs/iboostesphome/firmware.bin (510560 bytes)
INFO Compressed to 355828 bytes
Uploading: [============================================================] 100% Done...

INFO Waiting for result...
INFO OTA successful
INFO Successfully uploaded program.
INFO Starting log output from iboostesphome.local using esphome API
WARNING Can't connect to ESPHome API for iboostesphome.local: Error resolving IP address: [Errno -5] No address associated with hostname (APIConnectionError)
INFO Trying to connect to iboostesphome.local in the background
INFO Successfully connected to iboostesphome.local
[07:53:14][I][app:102]: ESPHome version 2023.8.1 compiled on Aug 19 2023, 14:04:48
[07:53:14][C][wifi:543]: WiFi:
[07:53:14][C][wifi:379]:   Local MAC: C4:5B:BE:4C:CB:12
[07:53:14][C][wifi:380]:   SSID: [redacted]
[07:53:14][C][wifi:381]:   IP Address: 192.168.1.173
[07:53:14][C][wifi:382]:   BSSID: [redacted]
[07:53:14][C][wifi:384]:   Hostname: 'iboostesphome'
[07:53:14][C][wifi:386]:   Signal strength: -75 dB ▂▄▆█
[07:53:14][C][wifi:390]:   Channel: 1
[07:53:14][C][wifi:391]:   Subnet: 255.255.255.0
[07:53:14][C][wifi:392]:   Gateway: 192.168.1.1
[07:53:14][C][wifi:393]:   DNS1: 192.168.1.1
[07:53:14][C][wifi:394]:   DNS2: 0.0.0.0
[07:53:14][C][logger:301]: Logger:
[07:53:14][C][logger:302]:   Level: DEBUG
[07:53:14][C][logger:303]:   Log Baud Rate: 115200
[07:53:14][C][logger:305]:   Hardware UART: UART0
[07:53:14][C][template.number:050]: Template Number 'iBoost Manual Boost Time'
[07:53:14][C][template.number:050]:   Icon: 'mdi:solar-power'
[07:53:14][C][template.number:050]:   Unit of Measurement: 'Minutes'
[07:53:14][C][template.number:051]:   Optimistic: YES
[07:53:14][C][template.number:052]:   Update Interval: 60.0s
[07:53:14][C][captive_portal:088]: Captive Portal:
[07:53:14][C][mdns:112]: mDNS:
[07:53:14][C][mdns:113]:   Hostname: iboostesphome
[07:53:14][C][ota:093]: Over-The-Air Updates:
[07:53:14][C][ota:094]:   Address: iboostesphome.local:8266
[07:53:14][C][ota:097]:   Using Password.
[07:53:14][C][api:138]: API Server:
[07:53:14][C][api:139]:   Address: iboostesphome.local:6053
[07:53:14][C][api:141]:   Using noise encryption: YES
[07:53:29][D][api:102]: Accepted 192.168.1.99
[07:53:29][W][component:204]: Component api took a long time for an operation (0.29 s).
[07:53:29][W][component:205]: Components should block for at most 20-30ms.
[07:53:30][D][api.connection:1031]: Home Assistant 2023.8.3 (192.168.1.99): Connected successfully
[07:58:03][I][ota:113]: Boot seems successful, resetting boot loop counter.
JNSwanson commented 1 year ago

I compiled form the command line (windows) using Version: 2023.6.5 and it works ok.

no1knows commented 1 year ago

Thanks! Turns out it was just a logging issue - it works fine now that I've turned the iBoost on and it has begun transmitting, but with the iBoost off the esp wasn't showing the radio-related log entries that the first version did, so I assumed there was an issue. (I tend to leave the iBoost off until my solar batteries are nearly full to avoid it triggering unnecessarily).

There's still a repeating error referring to an unknown component (any ideas what might be causing that?), but doesn't seem to impact operation:

INFO ESPHome 2023.8.2
INFO Reading configuration /config/esphome/iBoost.yaml...
INFO Starting log output from iboostesphome.local using esphome API
INFO Successfully connected to iboostesphome.local
[09:40:58][I][app:102]: ESPHome version 2023.8.2 compiled on Aug 21 2023, 23:12:45
[09:40:58][C][wifi:543]: WiFi:
[09:40:58][C][wifi:379]:   Local MAC: C4:5B:BE:4C:CB:12
[09:40:58][C][wifi:380]:   SSID: [redacted]
[09:40:58][C][wifi:381]:   IP Address: 192.168.1.173
[09:40:58][C][wifi:382]:   BSSID: [redacted]
[09:40:58][C][wifi:384]:   Hostname: 'iboostesphome'
[09:40:58][C][wifi:386]:   Signal strength: -91 dB ▂▄▆█
[09:40:58][C][wifi:390]:   Channel: 1
[09:40:58][C][wifi:391]:   Subnet: 255.255.255.0
[09:40:58][C][wifi:392]:   Gateway: 192.168.1.1
[09:40:58][C][wifi:393]:   DNS1: 192.168.1.1
[09:40:58][C][wifi:394]:   DNS2: 0.0.0.0
[09:40:58][C][logger:301]: Logger:
[09:40:58][C][logger:302]:   Level: DEBUG
[09:40:58][C][logger:303]:   Log Baud Rate: 115200
[09:40:58][C][logger:305]:   Hardware UART: UART0
[09:40:58][C][template.number:050]: Template Number 'iBoost Manual Boost Time'
[09:40:58][C][template.number:050]:   Icon: 'mdi:solar-power'
[09:40:58][C][template.number:050]:   Unit of Measurement: 'Minutes'
[09:40:58][C][template.number:051]:   Optimistic: YES
[09:40:58][C][template.number:052]:   Update Interval: 60.0s
[09:40:58][C][captive_portal:088]: Captive Portal:
[09:40:58][C][mdns:112]: mDNS:
[09:40:58][C][mdns:113]:   Hostname: iboostesphome
[09:40:58][C][ota:093]: Over-The-Air Updates:
[09:40:58][C][ota:094]:   Address: iboostesphome.local:8266
[09:40:58][C][ota:097]:   Using Password.
[09:40:58][C][api:138]: API Server:
[09:40:58][C][api:139]:   Address: iboostesphome.local:6053
[09:40:58][C][api:141]:   Using noise encryption: YES
[09:41:04][D][text_sensor:064]: 'iBoost Mode': Sending state 'Water Heating OFF'
[09:41:04][D][text_sensor:064]: 'iBoost Warn': Sending state ''
[09:41:04][D][sensor:093]: 'iBoost Import': Sending state -34.00000 W with 0 decimals of accuracy
[09:41:04][D][sensor:093]: 'iBoost Power': Sending state 0.00000 W with 0 decimals of accuracy
[09:41:04][D][sensor:093]: 'iBoost Today': Sending state 12.00000 Wh with 0 decimals of accuracy
[09:41:04][D][sensor:093]: 'iBoost Yesterday': Sending state 0.00000 Wh with 0 decimals of accuracy
[09:41:04][D][sensor:093]: 'iBoost Last 7 Days': Sending state 2158.00000 Wh with 0 decimals of accuracy
[09:41:04][D][sensor:093]: 'iBoost Boost Time Remaining': Sending state 0.00000 Min with 0 decimals of accuracy
[09:41:04][W][component:204]: Component <unknown> took a long time for an operation (0.08 s).
[09:41:04][W][component:205]: Components should block for at most 20-30ms.
[09:41:14][D][text_sensor:064]: 'iBoost Mode': Sending state 'Water Heating OFF'
[09:41:14][D][text_sensor:064]: 'iBoost Warn': Sending state ''
[09:41:14][D][sensor:093]: 'iBoost Import': Sending state 67.00000 W with 0 decimals of accuracy
[09:41:14][D][sensor:093]: 'iBoost Power': Sending state 0.00000 W with 0 decimals of accuracy
[09:41:14][D][sensor:093]: 'iBoost Today': Sending state 12.00000 Wh with 0 decimals of accuracy
[09:41:14][D][sensor:093]: 'iBoost Yesterday': Sending state 0.00000 Wh with 0 decimals of accuracy
[09:41:14][D][sensor:093]: 'iBoost Last 7 Days': Sending state 2158.00000 Wh with 0 decimals of accuracy
[09:41:14][D][sensor:093]: 'iBoost Last 28 days': Sending state 19953.00000 Wh with 0 decimals of accuracy
[09:41:14][D][sensor:093]: 'iBoost Boost Time Remaining': Sending state 0.00000 Min with 0 decimals of accuracy
[09:41:14][W][component:204]: Component <unknown> took a long time for an operation (0.09 s).
[09:41:14][W][component:205]: Components should block for at most 20-30ms.
[09:41:35][D][text_sensor:064]: 'iBoost Mode': Sending state 'Water Heating OFF'
[09:41:35][D][text_sensor:064]: 'iBoost Warn': Sending state ''
[09:41:35][D][sensor:093]: 'iBoost Import': Sending state -81.00000 W with 0 decimals of accuracy
[09:41:35][D][sensor:093]: 'iBoost Power': Sending state 43.00000 W with 0 decimals of accuracy
[09:41:35][D][sensor:093]: 'iBoost Today': Sending state 12.00000 Wh with 0 decimals of accuracy
[09:41:35][D][sensor:093]: 'iBoost Yesterday': Sending state 0.00000 Wh with 0 decimals of accuracy
[09:41:35][D][sensor:093]: 'iBoost Last 7 Days': Sending state 2158.00000 Wh with 0 decimals of accuracy
[09:41:35][D][sensor:093]: 'iBoost Last 28 days': Sending state 19953.00000 Wh with 0 decimals of accuracy
[09:41:35][D][sensor:093]: 'iBoost Boost Time Remaining': Sending state 0.00000 Min with 0 decimals of accuracy
[09:41:35][W][component:204]: Component <unknown> took a long time for an operation (0.09 s).
[09:41:35][W][component:205]: Components should block for at most 20-30ms.
jfdawson commented 5 months ago

I'm also seeing the "took a long time message". Is it the speed of the SPI? If so can anyone point me to where I can adjust the SPI speed? I saw similar behaviour with an I2C OLED display, where increasing the I2C speed was sufficient to solve the problem. I guess the final question would be: does it matter ?

srchild commented 5 months ago

I'm also seeing Component took a long time for an operation (0.11s).

I've ignored it because everything is working OK