espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.67k stars 7.29k forks source link

ledc_set_fade_time_and_start causes "Cache disabled but cached memory region accessed" if used while accessing flash via SPIFFS (IDFGH-12743) #13725

Closed MrSurly closed 5 months ago

MrSurly commented 6 months ago

Answers checklist.

IDF version.

5.2.1

Espressif SoC revision.

ESP32-S3

Operating System used.

Linux

How did you build your project?

Other (please specify in More Information)

If you are using Windows, please specify command line type.

None

Development Kit.

Generic ESP32-S3 dev board

Power Supply used.

USB

What is the expected behavior?

When using ledc_set_fade_time_and_start in one task while another task is doing fread of a file stored in SPIFFS, that it runs without crashing

What is the actual behavior?

Crashes when I do that:

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x4202c1ae  PS      : 0x00060034  A0      : 0x40378864  A1      : 0x3fc95770  
A2      : 0x00000000  A3      : 0x3fc95078  A4      : 0x00000000  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x00000000  A8      : 0x80375570  A9      : 0x130e320c  
A10     : 0x3fc95784  A11     : 0x3fc95784  A12     : 0x8037580a  A13     : 0x3fc997d0  
A14     : 0x3fc9478c  A15     : 0x1304120c  SAR     : 0x00000004  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace: 0x4202c1ab:0x3fc95770 0x40378861:0x3fc957d0 0x4037766e:0x3fc99810 0x40375dcf:0x3fc99830 0x4037e645:0x3fc99860

Steps to reproduce.

  1. Use the [LEDC](https://docs.espressif.com/projects/esp-idf/en/stable/esp32/api-reference/peripherals/ledc.html) API to do LED fading in one task via ledc_set_fade_time_and_start (called repeatedly every few seconds)
  2. Use the SPIFFS filesystem in another task which reads heavily
  3. After a short while, it will crash with Cache disabled but cached memory region accessed

The code is large and complicated, and not yet public. If necessary I can generate something that can reliably reproduce.

Debug Logs.

Rebooting...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x403767c0
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3810,len:0x178c
load:0x403c9700,len:0x4
load:0x403c9704,len:0xcbc
load:0x403cc700,len:0x2da0
entry 0x403c990c
I (31) boot: ESP-IDF 5.2.1 2nd stage bootloader
I (31) boot: compile time Apr 29 2024 21:34:21
I (31) boot: Multicore bootloader
I (34) boot: chip revision: v0.1
I (38) boot.esp32s3: Boot SPI Speed : 80MHz
I (43) boot.esp32s3: SPI Mode       : DIO
I (48) boot.esp32s3: SPI Flash Size : 8MB
I (52) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (76) boot:  1 efuse            efuse            01 05 0000d000 00001000
I (83) boot:  2 otadata          OTA data         01 00 0000e000 00002000
I (91) boot:  3 phy_init         RF data          01 01 00010000 00001000
I (98) boot:  4 ota_0            OTA app          00 10 00020000 00100000
I (106) boot:  5 ota_1            OTA app          00 11 00120000 00100000
I (113) boot:  6 spiffs           Unknown data     01 82 00220000 00400000
I (121) boot: End of partition table
I (125) esp_image: segment 0: paddr=00020020 vaddr=3c030020 size=11f50h ( 73552) map
I (147) esp_image: segment 1: paddr=00031f78 vaddr=3fc94700 size=02c4ch ( 11340) load
I (150) esp_image: segment 2: paddr=00034bcc vaddr=40374000 size=0b44ch ( 46156) load
I (163) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=2e0f0h (188656) map
I (197) esp_image: segment 4: paddr=0006e118 vaddr=4037f44c size=051f0h ( 20976) load
I (209) boot: Loaded app from partition at offset 0x20000
I (209) boot: Disabling RNG early entropy source...
I (220) cpu_start: Multicore app
I (230) cpu_start: Pro cpu start user code
I (230) cpu_start: cpu freq: 160000000 Hz
I (230) cpu_start: Application information:
I (233) cpu_start: Project name:     dragonfly-supervisor
I (239) cpu_start: App version:      934987d-dirty
I (245) cpu_start: Compile time:     Apr 29 2024 21:34:07
I (251) cpu_start: ELF file SHA256:  e6d84e43819a6611...
I (257) cpu_start: ESP-IDF:          5.2.1
I (261) cpu_start: Min chip rev:     v0.0
I (266) cpu_start: Max chip rev:     v0.99 
I (271) cpu_start: Chip rev:         v0.1
I (276) heap_init: Initializing. RAM available for dynamic allocation:
I (283) heap_init: At 3FC984B8 len 00051258 (324 KiB): RAM
I (289) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (295) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (301) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (309) spi_flash: detected chip: winbond
I (312) spi_flash: flash io: dio
W (316) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.
I (330) sleep: Configure to isolate all GPIO pins in sleep state
I (336) sleep: Enable automatic switching of GPIO sleep configuration
I (344) main_task: Started on CPU0
I (354) main_task: Calling app_main()
E (724) main: SPIFFS ok
serialCmdTask start
fd: 0, events: 01
I (1734) STEP: step: 4
I (1734) STEP: dir: 5
I (1734) STEP: step: 6
I (1734) STEP: dir: 7
I (1734) GAUGE: Gauge instance is 0x3fca0668
E (1744) SFX: dma_frame_num = 480
E (1744) SFX: auto_clear = 1
!
I (2784) GAUGE: started
I (2784) SFX: started

k96

b50

.
I (12704) GAUGE: terminated
I (14244) SFX: terminated
All joined

!
I (15894) GAUGE: started
I (15894) SFX: started

t

I (16964) SerialCmd: test started
I (16964) SerialCmd: -RANDOM-
I (17654) SerialCmd: command: k101.084
I (17654) SerialCmd: command: b59.7405
I (17654) SerialCmd: command: s2
I (17654) SerialCmd: command: B3.02743
I (17924) SerialCmd: command: k41.4764
I (17924) SerialCmd: command: b63.2525
I (17924) SerialCmd: command: s1
I (17924) SerialCmd: command: B6.75081
I (18004) SerialCmd: command: k81.9814
I (18654) SerialCmd: command: b88.8794
I (18664) SerialCmd: command: s1
I (18664) SerialCmd: command: B7.84455
I (18744) SerialCmd: command: k181.526
I (19634) SerialCmd: command: b10.3535
I (19634) SerialCmd: command: s3
I (19634) SerialCmd: command: B4.06041
I (20504) SerialCmd: command: k66.6519
Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x4202c1ae  PS      : 0x00060034  A0      : 0x40378864  A1      : 0x3fc95770  
A2      : 0x00000000  A3      : 0x3fc95078  A4      : 0x00000000  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x00000000  A8      : 0x80375570  A9      : 0x130e320c  
A10     : 0x3fc95784  A11     : 0x3fc95784  A12     : 0x8037580a  A13     : 0x3fc997d0  
A14     : 0x3fc9478c  A15     : 0x1304120c  SAR     : 0x00000004  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace: 0x4202c1ab:0x3fc95770 0x40378861:0x3fc957d0 0x4037766e:0x3fc99810 0x40375dcf:0x3fc99830 0x4037e645:0x3fc99860

ELF file SHA256: e6d84e43819a6611

Rebooting...
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x403767c0
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3810,len:0x178c
load:0x403c9700,len:0x4
load:0x403c9704,len:0xcbc
load:0x403cc700,len:0x2da0
entry 0x403c990c
I (31) boot: ESP-IDF 5.2.1 2nd stage bootloader
I (31) boot: compile time Apr 29 2024 21:34:21
I (31) boot: Multicore bootloader
I (34) boot: chip revision: v0.1
I (38) boot.esp32s3: Boot SPI Speed : 80MHz
I (43) boot.esp32s3: SPI Mode       : DIO
I (48) boot.esp32s3: SPI Flash Size : 8MB
I (52) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (61) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (76) boot:  1 efuse            efuse            01 05 0000d000 00001000
I (83) boot:  2 otadata          OTA data         01 00 0000e000 00002000
I (91) boot:  3 phy_init         RF data          01 01 00010000 00001000
I (98) boot:  4 ota_0            OTA app          00 10 00020000 00100000
I (106) boot:  5 ota_1            OTA app          00 11 00120000 00100000
I (113) boot:  6 spiffs           Unknown data     01 82 00220000 00400000
I (121) boot: End of partition table
I (125) esp_image: segment 0: paddr=00020020 vaddr=3c030020 size=11f50h ( 73552) map
I (147) esp_image: segment 1: paddr=00031f78 vaddr=3fc94700 size=02c4ch ( 11340) load
I (150) esp_image: segment 2: paddr=00034bcc vaddr=40374000 size=0b44ch ( 46156) load
I (163) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=2e0f0h (188656) map
I (197) esp_image: segment 4: paddr=0006e118 vaddr=4037f44c size=051f0h ( 20976) load
I (209) boot: Loaded app from partition at offset 0x20000
I (209) boot: Disabling RNG early entropy source...
I (220) cpu_start: Multicore app
I (230) cpu_start: Pro cpu start user code
I (230) cpu_start: cpu freq: 160000000 Hz
I (230) cpu_start: Application information:
I (233) cpu_start: Project name:     dragonfly-supervisor
I (239) cpu_start: App version:      934987d-dirty
I (245) cpu_start: Compile time:     Apr 29 2024 21:34:07
I (251) cpu_start: ELF file SHA256:  e6d84e43819a6611...
I (257) cpu_start: ESP-IDF:          5.2.1
I (261) cpu_start: Min chip rev:     v0.0
I (266) cpu_start: Max chip rev:     v0.99 
I (271) cpu_start: Chip rev:         v0.1
I (276) heap_init: Initializing. RAM available for dynamic allocation:
I (283) heap_init: At 3FC984B8 len 00051258 (324 KiB): RAM
I (289) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
I (295) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (301) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (309) spi_flash: detected chip: winbond
I (312) spi_flash: flash io: dio
W (316) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.
I (330) sleep: Configure to isolate all GPIO pins in sleep state
I (336) sleep: Enable automatic switching of GPIO sleep configuration
I (344) main_task: Started on CPU0
I (354) main_task: Calling app_main()
E (724) main: SPIFFS ok
serialCmdTask start

More Information.

suda-morris commented 6 months ago

@MrSurly Are you calling ledc_set_fade_time_and_start in the LEDC's fade callback function?

MrSurly commented 6 months ago

@suda-morris I'm not using a callback.

igrr commented 6 months ago

@MrSurly Could you please also run the same test with IDF Monitor, so that the backtrace gets decoded into function names?

Backtrace: 0x4202c1ab:0x3fc95770 0x40378861:0x3fc957d0 0x4037766e:0x3fc99810 0x40375dcf:0x3fc99830 0x4037e645:0x3fc99860

If you are using PlatformIO, there is a similar feature (monitor_filters = esp32_exception_decoder), it gets enabled in debug profile (https://github.com/platformio/platform-espressif32/issues/393)

MrSurly commented 6 months ago

@igrr

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x4202c18a  PS      : 0x00060034  A0      : 0x40378864  A1      : 0x3fc95770  
A2      : 0x00000000  A3      : 0x60002000  A4      : 0x00000001  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x0000001f  A8      : 0x80375570  A9      : 0xfffffffe  
A10     : 0x3fc95784  A11     : 0x3fc95784  A12     : 0x8037839e  A13     : 0x3fca6e20  
A14     : 0x00000000  A15     : 0x00000080  SAR     : 0x00000017  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x40056f5c  LEND    : 0x40056f72  LCOUNT  : 0x00000000  

Backtrace: 0x4202c187:0x3fc95770 0x40378861:0x3fc957d0 0x40380a37:0x3fca6e70 0x40378f25:0x3fca6e90 0x40377e89:0x3fca6eb0 0x42011c36:0x3fca6ef0 0x420050fb:0x3fca6f20 0x42008ba7:0x3fca6f50 0x42006871:0x3fca6f80 0x42006ca7:0x3fca6fd0 0x420085f1:0x3fca7020 0x42005378:0x3fca7070 0x420058c3:0x3fca70a0 0x42004f2e:0x3fca70c0 0x42016c93:0x3fca70e0 0x4202377b:0x3fca7100 0x42023642:0x3fca7120 0x42022ffa:0x3fca7140 0x42023089:0x3fca7180 0x420038f1:0x3fca71a0 0x4202bb2b:0x3fca71d0 0x4200354d:0x3fca7210 0x42003c85:0x3fca7230 0x42003306:0x3fca7250 0x4037e645:0x3fca7690

./addr2line.sh 0x4202c187:0x3fc95770 0x40378861:0x3fc957d0 0x40380a37:0x3fca6e70 0x40378f25:0x3fca6e90 0x40377e89:0x3fca6eb0 0x42011c36:0x3fca6ef0 0x420050fb:0x3fca6f20 0x42008ba7:0x3fca6f50 0x42006871:0x3fca6f80 0x42006ca7:0x3fca6fd0 0x420085f1:0x3fca7020 0x42005378:0x3fca7070 0x420058c3:0x3fca70a0 0x42004f2e:0x3fca70c0 0x42016c93:0x3fca70e0 0x4202377b:0x3fca7100 0x42023642:0x3fca7120 0x42022ffa:0x3fca7140 0x42023089:0x3fca7180 0x420038f1:0x3fca71a0 0x4202bb2b:0x3fca71d0 0x4200354d:0x3fca7210 0x42003c85:0x3fca7230 0x42003306:0x3fca7250 0x4037e645:0x3fca7690
??:?
/home/epoulsen/.platformio/packages/framework-espidf/components/xtensa/xtensa_vectors.S:1240
/home/epoulsen/.platformio/packages/framework-espidf/components/hal/esp32s3/include/hal/spimem_flash_ll.h:620
/home/epoulsen/.platformio/packages/framework-espidf/components/spi_flash/esp_flash_api.c:193
/home/epoulsen/.platformio/packages/framework-espidf/components/spi_flash/esp_flash_api.c:888
/home/epoulsen/.platformio/packages/framework-espidf/components/esp_partition/partition_target.c:38
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs_api.c:27
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_cache.c:161
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_nucleus.c:166
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_nucleus.c:537 (discriminator 4)
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_nucleus.c:2013
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_hydrogen.c:414
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_hydrogen.c:426
/home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/esp_spiffs.c:567
/home/epoulsen/.platformio/packages/framework-espidf/components/vfs/vfs.c:508 (discriminator 3)
/builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/stdio.c:47
/builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/refill.c:115
/builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/fread.c:228
/builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/fread.c:266 (discriminator 1)
/home/epoulsen/workspaces/dragonfly-supervisor/firmware/src/driver/cmixer/cmixer.c:674 (discriminator 2)
/home/epoulsen/workspaces/dragonfly-supervisor/firmware/src/driver/cmixer/cmixer.c:157
/home/epoulsen/workspaces/dragonfly-supervisor/firmware/src/driver/cmixer/cmixer.c:183
/home/epoulsen/workspaces/dragonfly-supervisor/firmware/src/driver/cmixer/cmixer.c:258
/home/epoulsen/workspaces/dragonfly-supervisor/firmware/src/display/sfx/SFX.cpp:192
/home/epoulsen/.platformio/packages/framework-espidf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134

For context:

cmixer.c is an audio mixer library; the line in question is calling fread to read data from the SPIFFs system

igrr commented 6 months ago

./addr2line.sh 0x4202c187:0x3fc95770 ... ??:?

It looks like the most "interesting" part (i.e. the last frame) didn't get translated for some reason. Could you please check the .map file (located in the build directory) and see which function contains this address (0x4202c187)? Or upload the .map file here if you are unsure.

MrSurly commented 6 months ago

dragonfly-supervisor.map.zip

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x4202c18a  PS      : 0x00060034  A0      : 0x40378864  A1      : 0x3fc95770  
A2      : 0x00000000  A3      : 0x3fc9e6c4  A4      : 0x00040000  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x60002098  A8      : 0x80375570  A9      : 0x3fca6e74  
A10     : 0x3fc95784  A11     : 0x3fc95784  A12     : 0x00000000  A13     : 0x00800000  
A14     : 0x00000000  A15     : 0x3fc982ac  SAR     : 0x00000018  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x400570e8  LEND    : 0x400570f3  LCOUNT  : 0x00000000  

Backtrace: 0x4202c187:0x3fc95770 0x40378861:0x3fc957d0 0x40380ae3:0x3fca6df0 0x4038051e:0x3fca6e10 0x4038400f:0x3fca6e30 0x40377eab:0x3fca6eb0 0x42011c36:0x3fca6ef0 0x420050fb:0x3fca6f20 0x42008ba7:0x3fca6f50 0x42006871:0x3fca6f80 0x42006ca7:0x3fca6fd0 0x420085f1:0x3fca7020 0x42005378:0x3fca7070 0x420058c3:0x3fca70a0 0x42004f2e:0x3fca70c0 0x42016c93:0x3fca70e0 0x4202377b:0x3fca7100 0x42023642:0x3fca7120 0x42022ffa:0x3fca7140 0x42023089:0x3fca7180 0x420038f1:0x3fca71a0 0x4202bb2b:0x3fca71d0 0x4200354d:0x3fca7210 0x42003c85:0x3fca7230 0x42003306:0x3fca7250 0x4037e645:0x3fca7690
  #0  0x4202c187 in ledc_hal_get_duty at ??:?
  #1  0x3fc95770 in _xt_exception_table at ??:?
  #2  0x40378861 in _xt_lowint1 at /home/epoulsen/.platformio/packages/framework-espidf/components/xtensa/xtensa_vectors.S:1240
  #3  0x3fc957d0 in _xt_exception_table at ??:?
  #4  0x40380ae3 in spimem_flash_ll_cmd_is_done at /home/epoulsen/.platformio/packages/framework-espidf/components/hal/esp32s3/include/hal/spimem_flash_ll.h:63
      (inlined by) spi_flash_hal_poll_cmd_done at /home/epoulsen/.platformio/packages/framework-espidf/components/hal/spi_flash_hal_common.inc:38
  #5  0x4038051e in spi_flash_hal_read at /home/epoulsen/.platformio/packages/framework-espidf/components/hal/spi_flash_hal_common.inc:194
  #6  0x4038400f in spi_flash_chip_winbond_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spi_flash/spi_flash_chip_winbond.c:61
  #7  0x40377eab in esp_flash_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spi_flash/esp_flash_api.c:899
  #8  0x42011c36 in esp_partition_read at /home/epoulsen/.platformio/packages/framework-espidf/components/esp_partition/partition_target.c:38
  #9  0x420050fb in spiffs_api_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs_api.c:27
  #10 0x42008ba7 in spiffs_phys_rd at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_cache.c:161
  #11 0x42006871 in spiffs_obj_lu_find_entry_visitor at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_nucleus.c:166
  #12 0x42006ca7 in spiffs_obj_lu_find_id_and_span at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_nucleus.c:537 (discriminator 4)
  #13 0x420085f1 in spiffs_object_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_nucleus.c:2013
  #14 0x42005378 in spiffs_hydro_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_hydrogen.c:414
  #15 0x420058c3 in SPIFFS_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/spiffs/src/spiffs_hydrogen.c:426
  #16 0x42004f2e in vfs_spiffs_read at /home/epoulsen/.platformio/packages/framework-espidf/components/spiffs/esp_spiffs.c:567
  #17 0x42016c93 in esp_vfs_read at /home/epoulsen/.platformio/packages/framework-espidf/components/vfs/vfs.c:508 (discriminator 3)
  #18 0x4202377b in __sread at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/stdio.c:47
  #19 0x42023642 in __srefill_r at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/refill.c:115
  #20 0x42022ffa in _fread_r at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/fread.c:228
  #21 0x42023089 in fread at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/newlib/newlib/libc/stdio/fread.c:266 (discriminator 1)
  #22 0x420038f1 in wav_handler at src/driver/cmixer/cmixer.c:674 (discriminator 2)
  #23 0x4202bb2b in fill_source_buffer at src/driver/cmixer/cmixer.c:157
  #24 0x4200354d in process_source at src/driver/cmixer/cmixer.c:183
  #25 0x42003c85 in cm_process at src/driver/cmixer/cmixer.c:258
  #26 0x42003306 in SFXTask(void*) at src/display/sfx/SFX.cpp:192
  #27 0x4037e645 in vPortTaskWrapper at /home/epoulsen/.platformio/packages/framework-espidf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134
igrr commented 6 months ago

Looks like this is related to PlatformIO build system generating different object file names from IDF build system. This results in linker script rules not having desired effect.

It seems like this was resolved in IDF via this PR: https://github.com/espressif/esp-idf/pull/13039. But we didn't understand the impact and so didn't backport the fix to older release branches. Could you please try making that change locally to your copy of IDF and see if that resolves the issue? We'll backport that PR then.

MrSurly commented 6 months ago

Post change:

    def _match_obj(self, archive, obj):
        objs = self.get_objects(archive)
        match_objs = (fnmatch.filter(objs, obj + '.o')
                      + fnmatch.filter(objs, obj + '.*.obj')
                      + fnmatch.filter(objs, obj + '.*.o')
                      + fnmatch.filter(objs, obj + '.obj'))

        if len(match_objs) > 1:
            raise ValueError("Multiple matches for object: '%s: %s': %s" % (archive, obj, str(match_objs)))

        try:
            return match_objs[0]
        except IndexError:
            return None

After clean/rebuild with above:

Guru Meditation Error: Core  0 panic'ed (Cache disabled but cached memory region accessed). 

Core  0 register dump:
PC      : 0x4202c18a  PS      : 0x00060034  A0      : 0x40378864  A1      : 0x3fc95770  
A2      : 0x00000000  A3      : 0x3fc95078  A4      : 0x00000000  A5      : 0x00000000  
A6      : 0x00000000  A7      : 0x00000000  A8      : 0x80375570  A9      : 0x130e320c  
A10     : 0x3fc95784  A11     : 0x3fc95784  A12     : 0x8037580a  A13     : 0x3fc997d0  
A14     : 0x3fc9478c  A15     : 0x1304120c  SAR     : 0x00000004  EXCCAUSE: 0x00000007  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace: 0x4202c187:0x3fc95770 0x40378861:0x3fc957d0 0x4037766e:0x3fc99810 0x40375dcf:0x3fc99830 0x4037e645:0x3fc99860
  #0  0x4202c187 in ledc_hal_get_duty at ??:?
  #1  0x3fc95770 in _xt_exception_table at ??:?
  #2  0x40378861 in _xt_lowint1 at /home/epoulsen/.platformio/packages/framework-espidf/components/xtensa/xtensa_vectors.S:1240
  #3  0x3fc957d0 in _xt_exception_table at ??:?
  #4  0x4037766e in spi_flash_op_block_func at /home/epoulsen/.platformio/packages/framework-espidf/components/spi_flash/cache_utils.c:137
  #5  0x40375dcf in ipc_task at /home/epoulsen/.platformio/packages/framework-espidf/components/esp_system/esp_ipc.c:83
  #6  0x4037e645 in vPortTaskWrapper at /home/epoulsen/.platformio/packages/framework-espidf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:134
igrr commented 6 months ago

It looks like that change didn't have effect, ledc_hal_get_duty was still placed into Flash instead of IRAM.

I have tried reproducing the issue, with the following platformio.ini:

platform = espressif32
board = esp32-s3-devkitm-1
framework = espidf

and

 - framework-espidf @ 3.50102.0 (5.1.2)

After calling a bunch of LEDC driver functions from main.c, I got the following in the map file:

.text.ledc_hal_get_duty
                0x000000004037ced0       0x27 .pio/build/esp32s3/esp-idf/hal/libhal.a(ledc_hal_iram.o)
                0x000000004037ced0                ledc_hal_get_duty

so ledc_hal_get_duty got correctly placed into IRAM...

Could you please try narrowing the issue down to a simpler project you could share with us?

MrSurly commented 5 months ago

@igrr

Here ya go:

https://gitlab.com/MrSurly/idf_issue_13725

igrr commented 5 months ago

Thank you for the reproducer!

The issue is that PlatformIO doesn't make use of all the linker fragment files. Here is an excerpt from the verbose build log:

"/Users/ivan/.platformio/penv/.espidf-5.2.1/bin/python" "/Users/ivan/.platformio/packages/framework-espidf/tools/ldgen/ldgen.py" \
    --input /Users/ivan/.platformio/packages/framework-espidf/components/esp_system/ld/esp32s3/sections.ld.in \
    --config "/Users/ivan/e/pio/idf_issue_13725/sdkconfig.esp32dev" \
    --fragments "/Users/ivan/.platformio/packages/framework-espidf/components/app_trace/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/bt/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/driver/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_adc/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_coex/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_eth/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_event/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_gdbstub/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_hw_support/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_lcd/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_mm/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_netif/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_phy/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_pm/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_psram/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_ringbuf/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_rom/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_system/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_wifi/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/espcoredump/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/freertos/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/hal/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/heap/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/ieee802154/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/log/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/lwip/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/openthread/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/soc/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/spi_flash/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/vfs/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/wpa_supplicant/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/xtensa/linker.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_system/app.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_common/common.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/esp_common/soc.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/newlib/system_libs.lf" \
        "/Users/ivan/.platformio/packages/framework-espidf/components/newlib/newlib.lf" \
    --output .pio/build/esp32dev/sections.ld \
    --kconfig "/Users/ivan/.platformio/packages/framework-espidf/Kconfig" \
    --env-file "/Users/ivan/e/pio/idf_issue_13725/.pio/build/esp32dev/config.env" \
    --libraries-file "/Users/ivan/e/pio/idf_issue_13725/.pio/build/esp32dev/ldgen_libraries_pio" \
    --objdump "/Users/ivan/.platformio/packages/toolchain-xtensa-esp-elf/bin/xtensa-esp32s3-elf-objdump"

Here at least one of the linker fragment files is missing: components/driver/ledc/linker.lf. Since this file is not passed to the linker script generator, the rule to place ledc_hal_iram.o into IRAM isn't there and all the functions get placed into Flash instead.

Looking at platformio/platform-esp32 repo, I'm guessing this is the code responsible for getting the list of linker fragment files. Since the list of linker fragment files is hardcoded, it is prone to such issues: when new files are added or when existing files are renamed, this code needs to be updated on PlatformIO side so that the list stays in sync.

There are probably a few ways to improve this, here is one option which might be the easiest to implement. PlatformIO already generates a custom component called __pio_env in IDF components directory. If the following instructions are added to that component's CMakeLists.txt

idf_build_get_property(ldgen_fragment_files __LDGEN_FRAGMENT_FILES GENERATOR_EXPRESSION)
idf_build_get_property(build_dir BUILD_DIR)
file(GENERATE OUTPUT ${build_dir}/ldgen_fragment_files.txt CONTENT "${ldgen_fragment_files}")

then ldgen_fragment_files.txt file in the build directory will contain a semicolon-separated list of all the linker fragment files. This option is still not perfect, as it relies on a private build property __LDGEN_FRAGMENT_FILES which might change in the future. However, it is still less likely to change than the list of the linker fragment files!

(cc @valeros)

@MrSurly as a workaround for this issue, you can find espidf.py under .platformio directory, and edit the extract_linker_script_fragments function, adding driver/ledc/linker.lf to the list of files being considered.

MrSurly commented 5 months ago

@igrr Much thanks -- you really nailed this. Since this seems to be PIO specific, I'm going to close this issue. Thanks again.

@valeros Is this something that an issue should be opened w/ PIO?

valeros commented 5 months ago

hi @MrSurly,

Is this something that an issue should be opened w/ PIO?

No need, I'm working on a fix, it will be available in the next stable release.