`Bug on dev` pages stashing

bkbartk commented 8 months ago

TFT Version

4.3.1

ESPHome Version

4.3.2d1

Blueprint Version

4.3.2d1

Panel Model

EU

What is the bug?

I don't know how to describe, but performance on dev is worse, espacially browsing through the button pages. then when you are back to home suddenly a button page pops up, en descriptions overlap.

I can add logging later if needed.

Steps to Reproduce

No response

Your Panel's YAML

No response

ESPHome Logs

No response

Home Assistant Logs

No response

edwardtfn commented 8 months ago

On your blueprint, what is selected as "Command Delay to Prevent Overload"?

bkbartk commented 8 months ago

it's 1

edwardtfn commented 8 months ago

Ok, so then it is something else. I will investigate this.

edwardtfn commented 8 months ago

Anything in your logs when that happens? I'm thinking about a stack overflow on the Nextion serial comms, which will be reported on ESPHome logs.

bkbartk commented 8 months ago

unfortunately when I try to reproduce the issue doesn't occur. but I found somthing else, the homepage flashes when going to detail page.

https://github.com/Blackymas/NSPanel_HA_Blueprint/assets/17070805/18f576e7-1e67-4e4d-aaf2-c7bdcbf32dba

I also captured this in the log

[09:24:18][D][debug:079]: ESPHome version 2024.3.0
[09:24:18][D][debug:083]: Free Heap Size: 112540 bytes
[09:24:18][D][debug:113]: Flash Chip: Size=4096kB Speed=40MHz Mode=DIO
[09:24:18][D][debug:162]: Chip: Model=ESP32, Features=WIFI_BGN,BLE,BT, Cores=2, Revision=3
[09:24:18][D][debug:170]: ESP-IDF Version: v4.4.2
[09:24:18][D][debug:175]: EFuse MAC: 80:64:6F:C4:CE:10
[09:24:18][D][debug:275]: Reset Reason: Software Reset CPU
[09:24:18][D][debug:320]: Wakeup Reason: Unknown
[09:24:18][D][text_sensor:064]: 'Reset Reason': Sending state 'Software Reset CPU'
[09:24:24][D][sensor:094]: 'ntc_source': Sending state 1.86200 V with 2 decimals of accuracy
[09:24:24][D][resistance:039]: 'resistance_sensor' - Resistance 14502.4Ω
[09:24:24][D][sensor:094]: 'resistance_sensor': Sending state 14502.36523 Ω with 1 decimals of accuracy
[09:24:24][D][ntc:026]: 'Temperature' - Temperature: 16.9°C
[09:24:24][D][sensor:094]: 'Temperature': Sending state 16.86273 °C with 1 decimals of accuracy
[09:24:25][D][nextion:446]: Got touch event:
[09:24:25][D][nextion:447]:   page_id:      1
[09:24:25][D][nextion:448]:   component_id: 0
[09:24:25][D][nextion:449]:   event type:   PRESS
[09:24:25][D][script.timer_dim:2829]: Waking up on page: home
[09:24:25][D][sensor:094]: 'Display Current brightness': Sending state 7.00000 % with 0 decimals of accuracy
[09:24:25][D][nextion:446]: Got touch event:
[09:24:25][D][nextion:447]:   page_id:      1
[09:24:25][D][nextion:448]:   component_id: 0
[09:24:25][D][nextion:449]:   event type:   RELEASE
[09:24:25][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[09:24:25][D][script.timer_dim:2829]: Waking up on page: home
[09:24:25][D][script:077]: Script 'set_brightness' restarting (mode: restart)
[09:24:25][D][text_sensor:064]: 'Current Page': Sending state 'buttonpage01'
[09:24:25][D][script.page_changed:2213]: New page: buttonpage01
[09:24:25][D][text_sensor:064]: 'Detailed Entity': Sending state ''
[09:24:25][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[09:24:25][D][script.timer_dim:2829]: Waking up on page: buttonpage01
[09:24:25][D][script:077]: Script 'set_brightness' restarting (mode: restart)
[09:24:25][D][nextion_textsensor:014]: Processed text_sensor "current_page" state "buttonpage01"
[09:24:25][D][sensor:094]: 'Display Current brightness': Sending state 8.00000 % with 0 decimals of accuracy
[09:24:25][D][sensor:094]: 'Display Current brightness': Sending state 8.00000 % with 0 decimals of accuracy
[09:24:25][W][component:232]: Component display took a long time for an operation (161 ms).
[09:24:25][W][component:233]: Components should block for at most 30 ms.
[09:24:26][D][dgr:735]: Sending bulbkamerachter message to network: seq=12, flags=64
[09:24:26][D][nextion:446]: Got touch event:
[09:24:27][D][nextion:447]:   page_id:      12
[09:24:27][D][nextion:448]:   component_id: 50
[09:24:27][D][nextion:449]:   event type:   PRESS
[09:24:27][D][script:077]: Script 'timer_page' restarting (mode: restart)
[09:24:27][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[09:24:27][D][text_sensor:064]: 'NSPanel local event': Sending state '{"page": "buttonpage01", "event": "long_click", "component": "button07"}'
[09:24:27][D][script:077]: Script 'timer_page' restarting (mode: restart)
[09:24:27][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[09:24:27][D][nextion_textsensor:014]: Processed text_sensor "localevent" state "{"page": "buttonpage01", "event": "long_click", "component": "button07"}"
[09:24:27][D][text_sensor:064]: 'Current Page': Sending state 'home'
[09:24:27][D][script.page_changed:2213]: New page: home
[09:24:27][D][text_sensor:064]: 'Detailed Entity': Sending state ''
[09:24:27][D][script:077]: Script 'timer_page' restarting (mode: restart)
[09:24:27][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[09:24:27][D][nextion_textsensor:014]: Processed text_sensor "current_page" state "home"
[09:24:27][W][component:232]: Component display took a long time for an operation (113 ms).
[09:24:27][W][component:233]: Components should block for at most 30 ms.
[09:24:29][D][sensor:094]: 'RSSI': Sending state -58.00000 dBm with 0 decimals of accuracy
[09:24:29][D][dgr:735]: Sending bulbkamervoor message to network: seq=7, flags=64
[09:24:29][D][text_sensor:064]: 'Detailed Entity': Sending state 'light.bulb_kamer_voor_bulb_kamer_voor'
[09:24:29][D][text_sensor:064]: 'Current Page': Sending state 'light'
[09:24:29][D][script.page_changed:2213]: New page: light
[09:24:29][D][script.page_changed:2238]: Entity shown: light.bulb_kamer_voor_bulb_kamer_voor
[09:24:29][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[09:24:29][D][nextion_textsensor:014]: Processed text_sensor "current_page" state "light"
[09:24:29][W][component:232]: Component display took a long time for an operation (57 ms).
[09:24:29][W][component:233]: Components should block for at most 30 ms.
[09:24:30][D][sensor:094]: 'Display Current brightness': Sending state 15.00000 % with 0 decimals of accuracy
[09:24:40][D][dgr:1194]: bulbkamervoor Member 192.168.180.173 added
[09:24:40][D][dgr:735]: Received bulbkamervoor message from 192.168.180.173: seq=99, flags=64
[09:24:41][D][sensor:094]: 'Heap Free': Sending state 121152.00000 B with 0 decimals of accuracy

(the recording and log are from different occurrences that's shy the time is different. this line here looks strange to my [09:24:27][D][text_sensor:064]: 'Current Page': Sending state 'home' I long pressed the button, so I soudn't expect a redirect to home first.

that might explain my last line then when you are back to home suddenly a button page pops up, en descriptions overlap. if all is really slow this seems suddenly when I might have clicked it in the past.

I will try to capture the initial issue in the log if possible, however when I noticed and reported the issue yesterday I wasn't able to log the report.

edwardtfn commented 8 months ago

We have a few buffers in the system which could be causing the “click from the past” being processed later:

Nextion display itself have a buffer (the one responsible for the overflow message I mentioned earlier) with commands already received from serial but not yet processed.
The uart have also a buffer, but I think it is only in the opposite direction.
The Nextion component in ESPHome have a queue, which will work like a buffer while waiting for uart.
In the end, as some commands are processed in the blueprint side, the info going from the panel to the blueprint, all the queries to entities and then sending a command back to ESPHome will create another buffer in reality.

It would be great if we get some tips pointing for where is the issue, so we can try to mitigate it in the better way. I’m far from my panel today, but will investigate this as soon I’m back.

bkbartk commented 7 months ago

I have some new foundings, but they don't mike the issue clearer to me. as not less clear. The panel running the dev version spontanitously rebooted I got htis messaged url: https://github.com/Blackymas/NSPanel_HA_Blueprint/blob/main/docs/error_initializing.md#blueprint-is-not-detected the panel is disconnected form HA nothing works, yet some icons are there. but not the hw_button_bars, where those once are the only one I would have expected to work. I needed to reboot the panel to have it connected again.

the heap size stays about the same (I'm on arduino) so no memoryleak I think and reset reason is: Software Reset CPU

I have one error form HA which basically says 'Not connected to switch-kamer-achter' which related to the red icon. but I can't explain why suddenly the connection issues.

Logger: homeassistant.components.automation.nspanel_kamer_achter
Source: helpers/script.py:485
integration: Automation (documentation, issues)
First occurred: 18:49:27 (5 occurrences)
Last logged: 18:49:34

NSPanel Kamer Achter: Main choices: NSPanel event: Choose at step 2: Page changed: Choose at step 1: Light settings page: If at step 9: Error executing script. Unexpected error for call_service at pos 13: Not connected to switch-kamer-achter @ 192.168.180.134!
NSPanel Kamer Achter: Main choices: NSPanel event: Choose at step 2: Page changed: Choose at step 1: Light settings page: Error executing script. Unexpected error for if at pos 9: Not connected to switch-kamer-achter @ 192.168.180.134!
NSPanel Kamer Achter: Main choices: NSPanel event: Choose at step 2: Page changed: Error executing script. Unexpected error for choose at pos 1: Not connected to switch-kamer-achter @ 192.168.180.134!
NSPanel Kamer Achter: Main choices: NSPanel event: Error executing script. Unexpected error for choose at pos 2: Not connected to switch-kamer-achter @ 192.168.180.134!
NSPanel Kamer Achter: Error executing script. Unexpected error for choose at pos 3: Not connected to switch-kamer-achter @ 192.168.180.134!
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 485, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 723, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 685, in _async_run_long_action
    return long_task.result()
           ^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2319, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2360, in _execute_service
    return target(service_call)
           ^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/esphome/manager.py", line 695, in execute_service
    entry_data.client.execute_service(service, call.data)
  File "/usr/local/lib/python3.12/site-packages/aioesphomeapi/client.py", line 1193, in execute_service
    self._get_connection().send_message(req)
    ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/aioesphomeapi/client.py", line 370, in _get_connection
    raise APIConnectionError(f"Not connected to {self.log_name}!")
aioesphomeapi.core.APIConnectionError: Not connected to switch-kamer-achter @ 192.168.180.134!

edwardtfn commented 7 months ago

This is interesting, as weather, date, humidity, that value in the top and those icons are provided by the Blueprint, which shouldn't send those values unless the panels reports itself as available. The only condition for this should be the panel losing connection after a successful boot (including communication to the Blueprint). If the communication fails after that, the values will be unchanged in the screen.

Only internal temperature and time should be available if the panel haven't talked to the Blueprint.

But anyways, I will take a look for this crash. There is some areas in the code where we could improve protection... I don't know how ESPHome will react to a division by zero, or other things like this. I won't be surprised if it crashed driving to a reboot. Easy to simulate, but I don't have my panel right now. I will look at this tomorrow.

bkbartk commented 7 months ago

If the communication fails after that, the values will be unchanged in the screen.

https://github.com/Blackymas/NSPanel_HA_Blueprint/assets/17070805/655be55c-c348-43fc-a220-f69a1810f34f

All(at least a few) Sensors are updating, weather, temp, humidity, Icon colors.

My demo demonstrates icon colors changing when the light toggles.

don't mind the presses, I sync them using udp instead of the blueprint so those presses are not reliable for testing. still it shows icons being updated where both HA and the panel itself report a comuncation issue. swiping and pressing the screen doesn't work.

I think the issue is in the esphome part I have 3 panels all running blueprint 4.3.2d1 all running tft 4.3.1 and only one of them runs esphome 4.3.2d1 and that one has this issue.

not sure when the communication issue started but is was around the time my wife went to work so she might has toggled a switch causing something but this is speculating.

edwardtfn commented 7 months ago

The panel should recover from that network issue. I will take a look.

bkbartk commented 7 months ago

[edit] edit at the top I know, but after updating to todays dev the spontaniour bootscreen issue is gone. therefor this post can probably be dismissed and also it seems like the page stashing/lacking thing is way worse now, but is also was bad just after flashing the previous time. after that it became slightly better. Could it be that it still needs to "cache" some stuff? [edit2:] I found: https://github.com/Blackymas/NSPanel_HA_Blueprint/issues/1991

[/edit]

sorry to bother again, but I am able to reproduce an event where suddenly the bootpage shows up and afterwards the panel is sometimes disconnected from HA and never connects again until reboot. when I go to the light page and adjust the brightness this happends. the log is here:

[19:03:42][D][text_sensor:064]: 'Device Name': Sending state 'switch_kamer_achter'
[19:03:44][D][nextion:446]: Got touch event:
[19:03:44][D][nextion:447]:   page_id:      1
[19:03:44][D][nextion:448]:   component_id: 0
[19:03:44][D][nextion:449]:   event type:   PRESS
[19:03:44][D][script.timer_dim:2829]: Waking up on page: home
[19:03:44][D][nextion:770]: Removing old queue type "NO_RESULT" name "set_component_text"
[19:03:44][W][component:232]: Component display took a long time for an operation (52 ms).
[19:03:44][W][component:233]: Components should block for at most 30 ms.
[19:03:44][D][sensor:094]: 'Display Current brightness': Sending state 7.00000 % with 0 decimals of accuracy
[19:03:45][D][nextion:446]: Got touch event:
[19:03:45][D][nextion:447]:   page_id:      1
[19:03:45][D][nextion:448]:   component_id: 0
[19:03:45][D][nextion:449]:   event type:   RELEASE
[19:03:45][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:45][D][script.timer_dim:2829]: Waking up on page: home
[19:03:45][D][script:077]: Script 'set_brightness' restarting (mode: restart)
[19:03:45][W][component:232]: Component display took a long time for an operation (55 ms).
[19:03:45][W][component:233]: Components should block for at most 30 ms.
[19:03:45][D][sensor:094]: 'Display Current brightness': Sending state 10.00000 % with 0 decimals of accuracy
[19:03:46][D][dgr:735]: Sending bulbkamerachter message to network: seq=2, flags=64
[19:03:47][D][nextion:446]: Got touch event:
[19:03:47][D][nextion:447]:   page_id:      1
[19:03:47][D][nextion:448]:   component_id: 37
[19:03:47][D][nextion:449]:   event type:   PRESS
[19:03:47][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:48][D][nextion:446]: Got touch event:
[19:03:48][D][nextion:447]:   page_id:      1
[19:03:48][D][nextion:448]:   component_id: 37
[19:03:48][D][nextion:449]:   event type:   RELEASE
[19:03:48][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:48][D][text_sensor:064]: 'NSPanel local event': Sending state '{"page": "home", "event": "short_click", "component": "button02"}'
[19:03:48][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:48][D][nextion_textsensor:014]: Processed text_sensor "localevent" state "{"page": "home", "event": "short_click", "component": "button02"}"
[19:03:48][W][component:232]: Component display took a long time for an operation (73 ms).
[19:03:48][W][component:233]: Components should block for at most 30 ms.
[19:03:48][D][dgr:735]: Received bulbkamervoor message from 192.168.180.180: seq=100, flags=64
[19:03:49][D][nextion:446]: Got touch event:
[19:03:49][D][nextion:447]:   page_id:      1
[19:03:49][D][nextion:448]:   component_id: 37
[19:03:49][D][nextion:449]:   event type:   PRESS
[19:03:49][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:49][D][nextion:446]: Got touch event:
[19:03:49][D][nextion:447]:   page_id:      1
[19:03:49][D][nextion:448]:   component_id: 37
[19:03:49][D][nextion:449]:   event type:   RELEASE
[19:03:49][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:49][D][text_sensor:064]: 'NSPanel local event': Sending state '{"page": "home", "event": "short_click", "component": "button02"}'
[19:03:49][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:49][D][nextion_textsensor:014]: Processed text_sensor "localevent" state "{"page": "home", "event": "short_click", "component": "button02"}"
[19:03:49][W][component:232]: Component display took a long time for an operation (77 ms).
[19:03:49][W][component:233]: Components should block for at most 30 ms.
[19:03:49][D][text_sensor:064]: 'Detailed Entity': Sending state 'light.bulb_kamer_achter_bulb_kamer_achter'
[19:03:49][D][text_sensor:064]: 'Current Page': Sending state 'light'
[19:03:49][D][script.page_changed:2213]: New page: light
[19:03:49][D][script.page_changed:2238]: Entity shown: light.bulb_kamer_achter_bulb_kamer_achter
[19:03:49][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:49][D][nextion_textsensor:014]: Processed text_sensor "current_page" state "light"
[19:03:49][W][component:232]: Component display took a long time for an operation (60 ms).
[19:03:49][W][component:233]: Components should block for at most 30 ms.
[19:03:50][D][sensor:094]: 'Display Current brightness': Sending state 15.00000 % with 0 decimals of accuracy
[19:03:51][D][nextion:446]: Got touch event:
[19:03:51][D][nextion:447]:   page_id:      10
[19:03:51][D][nextion:448]:   component_id: 3
[19:03:51][D][nextion:449]:   event type:   PRESS
[19:03:51][D][script:077]: Script 'timer_page' restarting (mode: restart)
[19:03:51][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:51][W][component:232]: Component display took a long time for an operation (53 ms).
[19:03:51][W][component:233]: Components should block for at most 30 ms.
[19:03:51][D][nextion:446]: Got touch event:
[19:03:51][D][nextion:447]:   page_id:      10
[19:03:51][D][nextion:448]:   component_id: 3
[19:03:51][D][nextion:449]:   event type:   RELEASE
[19:03:51][D][script:077]: Script 'timer_page' restarting (mode: restart)
[19:03:51][D][script:077]: Script 'timer_dim' restarting (mode: restart)
[19:03:51][D][text_sensor:064]: 'NSPanel local event': Sending state '{"page": "light", "key": "brightness_pct", "value": 100}'
WARNING switch-kamer-achter @ 192.168.180.181: Connection error occurred: [Errno 104] Connection reset by peer
INFO Processing unexpected disconnect from ESPHome API for switch-kamer-achter @ 192.168.180.181
WARNING Disconnected from API
INFO Successfully connected to switch-kamer-achter @ 192.168.180.181 in 0.006s
INFO Successful handshake with switch-kamer-achter @ 192.168.180.181 in 0.110s
[19:04:31][D][sensor:094]: 'ntc_source': Sending state 1.87700 V with 2 decimals of accuracy
[19:04:31][D][resistance:039]: 'resistance_sensor' - Resistance 14773.3Ω
[19:04:31][D][sensor:094]: 'resistance_sensor': Sending state 14773.29492 Ω with 1 decimals of accuracy
[19:04:31][D][ntc:026]: 'Temperature' - Temperature: 16.5°C
[19:04:31][D][sensor:094]: 'Temperature': Sending state 16.46914 °C with 1 decimals of accuracy
[19:04:32][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:32][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:34][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:34][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:35][D][sensor:094]: 'RSSI': Sending state -55.00000 dBm with 0 decimals of accuracy
[19:04:36][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:36][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:38][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:38][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:40][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:40][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:42][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:42][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:44][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:44][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:46][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:46][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:48][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:48][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:50][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.220: seq=2, flags=4, last ack=1
[19:04:50][D][dgr:735]: Sending bulbkamervoor message to 192.168.180.180: seq=2, flags=4, last ack=1
[19:04:50][D][text_sensor:064]: 'Device Name': Sending state 'switch_kamer_achter'
[19:04:52][D][dgr:1340]: bulbkamervoor Member 192.168.180.220 removed
[19:04:52][D][dgr:1340]: bulbkamervoor Member 192.168.180.180 removed
[19:04:53][D][sensor:094]: 'Display Current brightness': Sending state 7.00000 % with 0 decimals of accuracy
[19:04:54][D][script.check_versions:1871]: Versions:
[19:04:54][D][script.check_versions:1872]:   ESPHome:   4.3.2d1
[19:04:54][D][script.check_versions:1873]:   TFT:       4.3.1
[19:04:54][D][script.check_versions:1876]:   Blueprint: 
[19:04:54][E][script.check_versions:1878]: Blueprint version mismatch!
[19:04:57][D][sensor:094]: 'Heap Free': Sending state 124444.00000 B with 0 decimals of accuracy
[19:04:58][D][sensor:094]: 'Display Current brightness': Sending state 7.00000 % with 0 decimals of accuracy

this however is based on the saterday dev release, so maybe something has changd already, but I wanted to at least have the log in here. will updated to the latest dev when I have the time.

bkbartk commented 7 months ago

but then again, I think there is some performance issue with the latest dev bleuprint.

no blueprint enabled 1 automation blueprint enabled 2 enabled 3 enabled

and then even when nothing is triggered or the last trigger was 2 hours ago. the cpu % increases. causing a high load and bad performance over whole HA

so maybe it's the trigger listener or something.

I just disabled all 3 again and 0.2 I think would be normal

[edit] reverting back the blueprint to 4.3.1 doesn't help,

edwardtfn commented 7 months ago

I've made some changes to the blueprint, do you still seeing this overload when using the latest from dev?

edwardtfn commented 7 months ago

I think I can now duplicate this. I have a sensor which is updates very frequently (it is a template sensor with a sum from several other sensors, so if any of those sensors changes, the template sensor will change). When I associate this to my panel, the CPU goes very high. 😞 It's interesting as I have this sensor in entity pages before and have never noticed this. Maybe it was some change on how Home Assistant triggers the automation. Which version of Home Assistant are you using, by the way?

bkbartk commented 7 months ago

I am using

Core 2024.3.3
Supervisor 2024.03.1
Operating System 12.1
Frontend 20240307.0

I indeed added several of those sensors for the energy dashboard, that might be it, But I probably won't be able to test today or tomorrow.

edwardtfn commented 7 months ago

I have conditionals to prevent that running, but looks like the trigger and condition testing is enough for CPU load. I will look more at this.

bkbartk commented 7 months ago

just in case you need it, my utility page config is like this on all my panels

      utilities_enabled: true
      utilities_page01_home_value1: sensor.energy_used_today
      utilities_page01_home_value2: sensor.power_consumed
      utilities_page01_group04_line_inverted: false
      utilities_page01_group01_value1: sensor.grid_fossil_fuel_percentage
      utilities_page01_group01_icon: mdi:leaf
      utilities_page01_group01_color:
      - 15
      - 157
      - 88
      utilities_page01_group02_icon: ''
      utilities_page01_group03_icon: mdi:solar-power
      utilities_page01_group06_icon: mdi:water
      utilities_page01_group05_icon: mdi:fire
      utilities_page01_group03_value1: sensor.solaredge_ac_energy_kwh_today
      utilities_page01_group05_value1: sensor.gas_consumed_today
      utilities_page01_group06_value1: sensor.watermeter_today
      utilities_page01_grid_value2: sensor.energy_consumed_today
      utilities_page01_grid_value1: sensor.energy_produced_today
      utilities_page01_group03_value2: sensor.solaredge_ac_power
      utilities_page01_label: Utilitites
      utilities_page01_home_label: ' '
      utilities_page01_grid_label: ' '
      utilities_page01_group06_color:
      - 0
      - 188
      - 212
      utilities_page01_group05_color:
      - 139
      - 3
      - 27
      utilities_page01_group03_color:
      - 255
      - 152
      - 0
      utilities_page01_group06_value2: sensor.watermeter_pulse
      utilities_page01_main_line_reference: sensor.energy_fromgrid_today
      utilities_page01_group03_line_reference: sensor.solaredge_ac_energy_kwh_today
      utilities_page01_group05_line_reference: sensor.gas_consumed_today
      utilities_page01_group06_line_reference: sensor.watermeter_today
      utilities_page01_group05_line_inverted: true
      utilities_page01_group03_line_inverted: true
      utilities_page01_group06_line_inverted: false
      utilities_page01_group01_line_inverted: true
      utilities_page01_group01_line_reference: sensor.grid_fossil_fuel_percentage
      utilities_page01_grid_color:
      - 71
      - 143
      - 194

and my template sensors:

      - unique_id: energy_consumed_today
        name: energy_consumed_today
        state: "{{ (states('sensor.energy_consumed_tariff_1_today') | float + states('sensor.energy_consumed_tariff_2_today') | float) | round(3) }}"
        unit_of_measurement: kWh
      - unique_id: energy_produced_today
        name: energy_produced_today
        state: "{{ (states('sensor.energy_produced_tariff_1_today') | float + states('sensor.energy_produced_tariff_2_today') | float) | round(3) }}"
        unit_of_measurement: kWh
      - unique_id: energy_used_today
        name: energy_used_today
        state: "{{ (states('sensor.energy_consumed_today') | float + states('sensor.solaredge_ac_energy_kwh_today') | float - states('sensor.energy_produced_today') | float)| round(3) }}"
        unit_of_measurement: kWh
      - unique_id: energy_fromgrid_today
        name: energy_fromgrid_today
        state: "{{ (states('sensor.energy_consumed_today') | float - states('sensor.energy_produced_today') | float) | round(3) }}"
        unit_of_measurement: kWh

some values are updating every second, others every 10 seconds,

bkbartk commented 7 months ago

I just tried the lates dev blueprint, (did not update esphome or the tft and I wanted to let you know. disabling all 3 has a 2% cpu usage

enabling all 3 increases a little, 5% so that's way better then 24%,
the utilities page seems to load faster.
the line from grid to home is gone,
values do not update realtime and the lines are not moving(it can be because I did not update esp), but if the is the trade of which needs to be made for a super better performance I think it's way worth it, but ofc I'm not the only user.

edwardtfn commented 7 months ago

the line from grid to home is gone,

the lines are not moving(it can be because I did not update esp), but if the is the trade of which needs to be made for a super better performance I think it's way worth it, but ofc I'm not the only user.

You must update the other components (ESPHome and TFT) for this.

values do not update realtime

This is an issue. Those should be updating, None of the values are updating live or just some are not updating live?

I've just pushed a change to this, please let me know if it fixes this issue.

bkbartk commented 7 months ago

I just updated everything,

values do not update real time,
- none are updating real time,
- they get a new value when opening the page again.
lines 1,3,5 only move once, and stop when the bullit touches the main line
- the mainline also only moves once
- line 6 movements repeat as expected
- lines 2 and 4 I dot not use.

but.... I do not notice performance issues anymore,

bkbartk commented 7 months ago

I think the last update fixed realtime values

[edit:] however.... with the latest change none of my panels reconnect after they reboot. I reverted to https://github.com/Blackymas/NSPanel_HA_Blueprint/blob/67892fb6edf098528091fa87f9c7ddcf7834816f/nspanel_blueprint.yaml to be able to connect again.

edwardtfn commented 7 months ago

Do you have any error related to this on your Home Assistant logs?

bkbartk commented 7 months ago

Please ignore my last comment

nothing in the log, in HA only the notification,

I installed the latest again and noticed this issue is not always there, then after rebooting it fails 3 times in a row, then it goes well 3 times in a row. So it might depend on external factors. If I notice something else or I have reason to believe it has to do with this project I will try to add more information.

edwardtfn commented 7 months ago

This is being challenging... if you associate one of those high frequency sensor to more than one thing (like the utilities value and the line direction) at the same time, which probably will happen in many cases, the blueprint is triggered the number of times it is associated to, increasing significantly the CPU consumption. 😞 I still trying to find a way around that...

bkbartk commented 7 months ago

and there I was just planning to close this topic as the performance already is way better then it was when I created this one. I do not have any noticeable performance issues any more at this moment.

but if there are still scenarios where this is an issue I will leave this one open .

edwardtfn commented 7 months ago

I still looking at this. I believe there are still some spaces for improvements.

edwardtfn commented 7 months ago

So, we probably still can find some areas for improvement, but I will expose (release) what we have done and try to get some feedback before investing more on this. I will close this for now, but please feel free to reopen if you still can see this issue after the release.

Blackymas / NSPanel_HA_Blueprint