search

esphome / issues

Issue Tracker for ESPHome
https://esphome.io/
290 stars 36 forks source link

ili9xx/ST7796 display needs 4.77s when using framework esp-idf/recommended instead 0,17s with arduino/recommended #4905

Closed fsiek closed 1 year ago

fsiek commented 1 year ago

The problem

Experimenting with a ESP32 Wroom32, 240Mhz, 520kB Ram, 4MB flash, connected to a ST7796 with 320x480.

Due to heap memory restrictions I am experimenting using esp-idf instead of arduino as it gives me ~20kB larger maximum heap block for the display buffer.

Even esp-idf gives me a larger possible display area, the display is running very slow with the esp-idf framework. Setting the data_rate (SPI) for the display in the yaml file has no effect.

It look like the SPI data rate is not set correctly to the possible 40MHz.

Which version of ESPHome has the issue?

2023.8.3

What type of installation are you using?

pip

Which version of Home Assistant has the issue?

2023.9.1

What platform are you using?

ESP32

Board

ESP32-D0WD-V3 (revision v3.1)

Component causing the issue

Display ST7796

Example YAML snippet

esphome:
  name: display1
  friendly_name: Display1

esp32:
  board: az-delivery-devkit-v4
  framework: 
    type: esp-idf
    version: recommended

# Enable logging
logger:

# Enable Home Assistant API
api:
  encryption:
    key: "........"

ota:
  password: "........."

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

color:
  - id: my_red
    red: 100%
    green: 0%
    blue: 0%
  - id: my_yellow
    red: 100%
    green: 100%
    blue: 0%
  - id: my_green
    red: 0%
    green: 100%
    blue: 0%
  - id: my_blue
    red: 0%
    green: 0%
    blue: 100%
  - id: my_gray
    red: 50%
    green: 50%
    blue: 50%  
  - id: my_black
    red: 0%
    green: 0%
    blue: 0%      

spi:
  - id: lcd
    clk_pin: GPIO14
    mosi_pin: GPIO13
    miso_pin: GPIO12

display:
  - platform: ili9xxx
    model: ST7796
    spi_id: lcd
    cs_pin: GPIO15
    dc_pin: GPIO2
    reset_pin: GPIO23
    dimensions: 220x480  #320x480 not possible because of memory limitations
    rotation: 90
    color_palette: GRAYSCALE
    #data_rate: 40MHz
    lambda: |-
      it.strftime(5, 5, id(font1), id(my_red), TextAlign::TOP_LEFT, "%H:%M:%S", id(my_time).now());

font:
  - file: "gfonts://Roboto"
    id: font1
    size: 40

time:
- platform: homeassistant
  id: my_time

output:
  - platform: ledc
    pin: GPIO27
    id: former_led_pin
  - platform: ledc
    id: output_red
    pin: GPIO4
    inverted: true
  - platform: ledc
    id: output_green
    pin: GPIO16
    inverted: true
  - platform: ledc
    id: output_blue
    pin: GPIO17
    inverted: true

# Define a monochromatic, dimmable light for the backlight
light:
  - platform: monochromatic
    output: former_led_pin
    name: "Display Backlight"
    id: back_light
    restore_mode: ALWAYS_ON
  - platform: rgb
    name: LED
    id: led
    red: output_red
    green: output_green
    blue: output_blue
    restore_mode: ALWAYS_OFF

Anything in the logs that might be useful for us?

esptool.py v4.6.2
Serial port COM4
Connecting..............
Chip is ESP32-D0WD-V3 (revision v3.1)
Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None
Crystal is 40MHz
MAC: 00:00:00:00:00:00
Uploading stub...
Running stub...
Stub running...
Changing baud rate to 460800
Changed.
Configuring flash size...
Auto-detected Flash size: 4MB
Flash will be erased from 0x00010000 to 0x000e7fff...
Flash will be erased from 0x00001000 to 0x00007fff...
Flash will be erased from 0x00008000 to 0x00008fff...
Flash will be erased from 0x00009000 to 0x0000afff...
Compressed 882912 bytes to 575613...
Wrote 882912 bytes (575613 compressed) at 0x00010000 in 13.1 seconds (effective 541.0 kbit/s)...
Hash of data verified.
Compressed 25568 bytes to 16070...
Wrote 25568 bytes (16070 compressed) at 0x00001000 in 0.5 seconds (effective 384.5 kbit/s)...
Hash of data verified.
Compressed 3072 bytes to 134...
Wrote 3072 bytes (134 compressed) at 0x00008000 in 0.0 seconds (effective 945.2 kbit/s)...
Hash of data verified.
Compressed 8192 bytes to 31...
Wrote 8192 bytes (31 compressed) at 0x00009000 in 0.0 seconds (effective 1771.3 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
INFO Successfully uploaded program.
INFO Starting log output from COM4 with baud rate 115200
[21:36:01]0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[21:36:01]configsip: 0, SPIWP:0xee
[21:36:01]clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[21:36:01]mode:DIO, clock div:2
[21:36:01]load:0x3fff0030,len:6608
[21:36:01]load:0x40078000,len:15060
[21:36:01]ho 0 tail 12 room 4
[21:36:01]load:0x40080400,len:3816
[21:36:01]entry 0x40080698
[21:36:01]I (29) boot: ESP-IDF 4.4.5 2nd stage bootloader
[21:36:01]I (29) boot: compile time 19:31:01
[21:36:01]I (29) boot: chip revision: v3.1
[21:36:01]I (32) boot.esp32: SPI Speed      : 40MHz
[21:36:01]I (37) boot.esp32: SPI Mode       : DIO
[21:36:01]I (41) boot.esp32: SPI Flash Size : 4MB
[21:36:01]I (46) boot: Enabling RNG early entropy source...
[21:36:01]I (51) boot: Partition Table:
[21:36:01]I (55) boot: ## Label            Usage          Type ST Offset   Length
[21:36:01]I (62) boot:  0 otadata          OTA data         01 00 00009000 00002000
[21:36:01]I (70) boot:  1 phy_init         RF data          01 01 0000b000 00001000
[21:36:01]I (77) boot:  2 app0             OTA app          00 10 00010000 001c0000
[21:36:01]I (85) boot:  3 app1             OTA app          00 11 001d0000 001c0000
[21:36:01]I (92) boot:  4 nvs              WiFi data        01 02 00390000 0006d000
[21:36:01]I (100) boot: End of partition table
[21:36:01]I (104) boot: No factory image, trying OTA 0
[21:36:01]I (109) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=25c50h (154704) map
[21:36:01]I (173) esp_image: segment 1: paddr=00035c78 vaddr=3ffb0000 size=03550h ( 13648) load
[21:36:01]I (179) esp_image: segment 2: paddr=000391d0 vaddr=40080000 size=06e48h ( 28232) load
[21:36:01]I (191) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=953b0h (611248) map
[21:36:01]I (412) esp_image: segment 4: paddr=000d53d8 vaddr=40086e48 size=124dch ( 74972) load
[21:36:01]I (455) boot: Loaded app from partition at offset 0x10000
[21:36:01]I (461) boot: Set actual ota_seq=1 in otadata[0]
[21:36:01]I (461) boot: Disabling RNG early entropy source...
[21:36:02]I (472) psram: This chip is ESP32-D0WD
[21:36:02]E (473) psram: PSRAM ID read error: 0xffffffff
[21:36:02]E (473) spiram: SPI RAM enabled but initialization failed. Bailing out.
[21:36:02]I (480) cpu_start: Failed to init external RAM; continuing without it.
[21:36:02]I (487) cpu_start: Pro cpu up.
[21:36:02]I (491) cpu_start: Starting app cpu, entry point is 0x400821f8
[21:36:02]I (0) cpu_start: App cpu up.
[21:36:02]I (513) cpu_start: Pro cpu start user code
[21:36:02]I (513) cpu_start: cpu freq: 160000000
[21:36:02]I (513) cpu_start: Application information:
[21:36:02]I (517) cpu_start: Project name:     display1
[21:36:02]I (523) cpu_start: App version:      2023.8.3
[21:36:02]I (528) cpu_start: Compile time:     Sep 24 2023 19:28:17
[21:36:02]I (534) cpu_start: ELF file SHA256:  fa2ac886636ceff0...
[21:36:02]I (540) cpu_start: ESP-IDF:          4.4.5
[21:36:02]I (545) cpu_start: Min chip rev:     v0.0
[21:36:02]I (549) cpu_start: Max chip rev:     v3.99
[21:36:02]I (554) cpu_start: Chip rev:         v3.1
[21:36:02]I (559) heap_init: Initializing. RAM available for dynamic allocation:
[21:36:02]I (566) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
[21:36:02]I (572) heap_init: At 3FFB75A8 len 00028A58 (162 KiB): DRAM
[21:36:02]I (578) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
[21:36:02]I (585) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
[21:36:02]I (591) heap_init: At 40099324 len 00006CDC (27 KiB): IRAM
[21:36:02]I (599) spi_flash: detected chip: generic
[21:36:02]I (602) spi_flash: flash io: dio
[21:36:02]I (608) cpu_start: Starting scheduler on PRO CPU.
[21:36:02]I (0) cpu_start: Starting scheduler on APP CPU.
[21:36:02][I][logger:262]: Log initialized
[21:36:02][C][ota:469]: There have been 2 suspected unsuccessful boot attempts.
[21:36:02][D][esp32.preferences:114]: Saving 1 preferences to flash...
[21:36:02][D][esp32.preferences:143]: Saving 1 preferences to flash: 0 cached, 1 written, 0 failed
[21:36:02][I][app:029]: Running through setup()...
[21:36:02][C][spi:023]: Setting up SPI bus...
[21:36:02][D][esp-idf:000]: I (239) gpio: GPIO[14]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
[21:36:02]
[21:36:02][D][esp-idf:000]: I (243) gpio: GPIO[12]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
[21:36:02]
[21:36:02][D][esp-idf:000]: I (253) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
[21:36:02]
[21:36:02][D][esp-idf:000]: I (263) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
[21:36:02]
[21:36:02][D][esp-idf:000]: I (273) gpio: GPIO[23]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
[21:36:02]
[21:36:02][D][esp-idf:000]: I (294) gpio: GPIO[15]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
[21:36:02]
[21:36:02][D][ledc.output:055]: Calculating resolution bit-depth for frequency 1000.000000
[21:36:02][D][ledc.output:060]: Resolution calculated as 16
[21:36:02][D][ledc.output:055]: Calculating resolution bit-depth for frequency 1000.000000
[21:36:02][D][ledc.output:060]: Resolution calculated as 16
[21:36:02][D][ledc.output:055]: Calculating resolution bit-depth for frequency 1000.000000
[21:36:02][D][ledc.output:060]: Resolution calculated as 16
[21:36:02][D][ledc.output:055]: Calculating resolution bit-depth for frequency 1000.000000
[21:36:02][D][ledc.output:060]: Resolution calculated as 16
[21:36:02][C][light:035]: Setting up light 'Display Backlight'...
[21:36:02][D][light:036]: 'Display Backlight' Setting:
[21:36:02][D][light:041]:   Color mode:
[21:36:02][D][light:047]:   State: ON
[21:36:02][D][light:085]:   Transition length: 1.0s
[21:36:02][C][light:035]: Setting up light 'LED'...
[21:36:02][D][light:036]: 'LED' Setting:
[21:36:03][D][light:041]:   Color mode: RGB
[21:36:03][D][light:085]:   Transition length: 1.0s
[21:36:03][C][wifi:038]: Setting up WiFi...
[21:36:03][D][esp-idf:000]: I (858) wifi:
[21:36:03][D][esp-idf:000]: wifi driver task: 3ffde680, prio:23, stack:6656, core=0
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2342) system_api: Base MAC address is not set
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2342) system_api: read default base MAC address from EFUSE
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2354) wifi:
[21:36:03][D][esp-idf:000]: wifi firmware version: 0f80fa0
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2372) wifi:
[21:36:03][D][esp-idf:000]: wifi certification version: v7.0
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2382) wifi:
[21:36:03][D][esp-idf:000]: config NVS flash: enabled
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2392) wifi:
[21:36:03][D][esp-idf:000]: config nano formating: disabled
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2403) wifi:
[21:36:03][D][esp-idf:000]: Init data frame dynamic rx buffer num: 32
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2413) wifi:
[21:36:03][D][esp-idf:000]: Init management frame dynamic rx buffer num: 32
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2433) wifi:
[21:36:03][D][esp-idf:000]: Init management short buffer num: 32
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2443) wifi:
[21:36:03][D][esp-idf:000]: Init dynamic tx buffer num: 32
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2455) wifi:
[21:36:03][D][esp-idf:000]: Init tx cache buffer num: 32
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2464) wifi:
[21:36:03][D][esp-idf:000]: Init static rx buffer size: 1600
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2475) wifi:
[21:36:03][D][esp-idf:000]: Init static rx buffer num: 10
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2495) wifi:
[21:36:03][D][esp-idf:000]: Init dynamic rx buffer num: 32
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2506) wifi_init: rx ba win: 6
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2506) wifi_init: tcpip mbox: 32
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2506) wifi_init: udp mbox: 6
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2515) wifi_init: tcp mbox: 6
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2525) wifi_init: tcp tx win: 5744
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2526) wifi_init: tcp rx win: 5744
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2536) wifi_init: tcp mss: 1440
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2546) wifi_init: WiFi IRAM OP enabled
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2546) wifi_init: WiFi RX IRAM OP enabled
[21:36:03]
[21:36:03][C][wifi:048]: Starting WiFi...
[21:36:03][C][wifi:049]:   Local MAC: 00:00:00:00:00:00
[21:36:03][D][esp-idf:000]: I (2568) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2689) wifi:
[21:36:03][D][esp-idf:000]: mode : sta (64:b7:08:6e:e9:cc)
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2691) wifi:
[21:36:03][D][esp-idf:000]: enable tsf
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][esp-idf:000]: I (2693) wifi:
[21:36:03][D][esp-idf:000]: Set ps type: 1
[21:36:03]
[21:36:03][D][esp-idf:000]:
[21:36:03]
[21:36:03][D][wifi:425]: Starting scan...
[21:36:08][W][component:204]: Component ili9xxx.display took a long time for an operation (4.76 s).
[21:36:08][W][component:205]: Components should block for at most 20-30ms.
[21:36:08][D][esp-idf:000]: I (7468) wifi:
[21:36:08][D][esp-idf:000]: Set ps type: 1
[21:36:08]
[21:36:08][D][esp-idf:000]:
[21:36:08]
[21:36:08][D][wifi:440]: Found networks:
[21:36:08][I][wifi:484]: - 'WLAN1' (00:00:00:00:00:00) ▂▄▆█
[21:36:08][D][wifi:485]:     Channel: 1
[21:36:08][D][wifi:486]:     RSSI: -50 dB
[21:36:08][I][wifi:484]: - 'WLAN1' (00:00:00:00:00:00) ▂▄▆█
[21:36:08][D][wifi:485]:     Channel: 1
[21:36:08][D][wifi:486]:     RSSI: -54 dB
[21:36:08][D][wifi:489]: - 'WLAN2' (00:00:00:00:00:00) ▂▄▆█
[21:36:08][D][wifi:489]: - 'DIRECT-00-HP ENVY 1111 series' (00:00:00:00:00:0) ▂▄▆█
[21:36:08][I][wifi:274]: WiFi Connecting to 'WLAN1'...
[21:36:08][D][esp-idf:000]: I (7539) wifi:
[21:36:08][D][esp-idf:000]: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
[21:36:08][D][esp-idf:000]:
[21:36:08]
[21:36:08][D][esp-idf:000]: I (7547) wifi:
[21:36:08][D][esp-idf:000]: state: init -> auth (b0)
[21:36:08][D][esp-idf:000]:
[21:36:08]
[21:36:12][W][component:204]: Component ili9xxx.display took a long time for an operation (4.77 s).
[21:36:12][W][component:205]: Components should block for at most 20-30ms.
[21:36:13][D][esp-idf:000]: I (13061) wifi:
[21:36:13][D][esp-idf:000]: state: auth -> init (200)
[21:36:13][D][esp-idf:000]:
[21:36:13]
[21:36:13][D][esp-idf:000]: I (13063) wifi:
[21:36:13][D][esp-idf:000]: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
[21:36:13][D][esp-idf:000]:
[21:36:13]

Additional information

I changed display.py to work with color_palette: GRAYSCALE in YAML according to recommended fix from clydebarrow: https://github.com/esphome/esphome/pull/5406 but the problem shows up with color_palette: IMAGE_ADAPTIVE, too.

xdecock commented 1 year ago

The beta version of esphome fixes most of it due to this pr: https://github.com/esphome/esphome/pull/5311

To get the full 40Mhz on esp32 i had to avoid defining the miso pin as there seem to be a limit to 26Mhz for full duplex connections.

fsiek commented 1 year ago

Sorry, not speaking about factor 2 but 25. SPI seems to run at 1.6 Mhz instead of 40Mhz.

nielsnl68 commented 1 year ago

Hi could you run esphome in DEV mode and use PR#5406 to see of your issue will be fixed with that one.

fsiek commented 1 year ago

OK, checked in dev mode and it looks much better now. This time I can see in the log that the data rate is set, which was not the case before. [09:17:11][D][spi_device:354]: mode 0, data_rate 40000kHz

This leads to a much better throughput: [09:17:12][W][component:204]: Component ili9xxx.display took a long time for an operation (0.33 s).

There is still room for improvements but I guess this topic can be marked as resolved with the new SPI component code.