Cannot esp_partition_mmap() on ESP32-S3 code from a partition, but can do it as data (IDFGH-8961)

[vincentdupaquis]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v4.4.3

Operating System used.

Linux

How did you build your project?

Command line with idf.py

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

None

Development Kit.

ESP32-S3-DevKitC-1 v1.0

Power Supply used.

USB

What is the expected behavior?

I have a partition containing code that I would like to map into the memory space. I use esp_partition_mmap() for doing so on an existing project using ESP32 (ESP-WROVER-KIT), and I wanted to port my code on a ESP32-S3 chip.
The expected behaviour is simply that I expect my code partition to be loaded.
Effectivelly, when I ask the same partition to be loaded as data (SPI_FLASH_MMAP_DATA instead of SPI_FLASH_MMAP_INST), the code works (but my code cannot be executed).``

What is the actual behavior?

When exiting from esp_partition_mmap(), I get a ESP_ERR_NO_MEM error, and the code is not loaded.

Steps to reproduce.

1. Create a partition on the chip (custom partition.csv, and then I create a partition with IDs 0x40, 1 of any size (mine is 128K)
2. Call esp_partition_find_first() to get the partition handler
3. Call esp_partition_mmap(), having the 4th parameter to be SPI_FLASH_MMAP_INST
4. The return code of the last function is ESP_ERR_NO_MEM in my case

Debug Logs.

I (149) esp_image: segment 4: paddr=00037b7c vaddr=403788ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x40374283
0x40374283: _DebugExceptionVector at /home/vdupaquis/Dev/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:438

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3808,len:0x1660
load:0x403c9700,len:0xbb8
load:0x403cc700,len:0x2e8c
entry 0x403c9954
I (24) boot: ESP-IDF v4.4.3 2nd stage bootloader
I (24) boot: compile time 16:33:46
I (25) boot: chip revision: 0
I (26) boot.esp32s3: Boot SPI Speed : 80MHz
I (31) boot.esp32s3: SPI Mode       : DIO
I (36) boot.esp32s3: SPI Flash Size : 2MB
I (40) boot: Enabling RNG early entropy source...
I (46) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (72) boot:  2 factory          factory app      00 00 00010000 00080000
I (79) boot:  3 to-protect       unknown          40 01 00090000 00040000
I (87) boot:  4 secure-storage   unknown          41 01 000d0000 00004000
I (94) boot: End of partition table
I (98) esp_image: segment 0: paddr=00010020 vaddr=3c020020 size=08640h ( 34368) map
I (113) esp_image: segment 1: paddr=00018668 vaddr=3fc91ca0 size=0313ch ( 12604) load
I (118) esp_image: segment 2: paddr=0001b7ac vaddr=40374000 size=0486ch ( 18540) load
I (128) esp_image: segment 3: paddr=00020020 vaddr=42000020 size=17b54h ( 97108) map
I (149) esp_image: segment 4: paddr=00037b7c vaddr=4037886c size=0942ch ( 37932) load
I (158) esp_image: segment 5: paddr=00040fb0 vaddr=50000000 size=00010h (    16) load
I (164) boot: Loaded app from partition at offset 0x10000
I (164) boot: Disabling RNG early entropy source...
I (178) cpu_start: Pro cpu up.
I (178) cpu_start: Starting app cpu, entry point is 0x4037522c
0x4037522c: call_start_cpu1 at /home/vdupaquis/Dev/esp-idf/components/esp_system/port/cpu_start.c:148

1 (0) cpu_startD : (1A79p)p  efcuspeu:  uIpn. EFS[E_0BLK
_DATA3_REG is used 3 bits starting with 24 bit
D (186) efuse: In EFUSE_BLK2__DATA4_REG is used 2 bits starting with 0 bit
D (193) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit
D (200) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit
D (207) efuse: In EFUSE_BLK1__DATA5_REG is used 5 bits starting with 11 bit
D (214) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit
D (221) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit
D (228) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit
D (235) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit
D (242) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit
D (249) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 13 bit
D (256) efuse: In EFUSE_BLK1__DATA4_REG is used 7 bits starting with 20 bit
D (263) efuse: In EFUSE_BLK1__DATA4_REG is used 5 bits starting with 27 bit
D (270) efuse: In EFUSE_BLK1__DATA5_REG is used 3 bits starting with 0 bit
D (277) efuse: In EFUSE_BLK1__DATA5_REG is used 8 bits starting with 3 bit
D (292) clk: RTC_SLOW_CLK calibration value: 3885286
I (301) cpu_start: Pro cpu start user code
I (301) cpu_start: cpu freq: 80000000
I (301) cpu_start: Application information:
I (303) cpu_start: Project name:     hello_world
I (309) cpu_start: App version:      v4.4.3
I (314) cpu_start: Compile time:     Dec 14 2022 16:33:43
I (320) cpu_start: ELF file SHA256:  dc0dba6d4cee8a26...
I (326) cpu_start: ESP-IDF:          v4.4.3
V (331) memory_layout: reserved range is 0x3c028630 - 0x3c028660
D (337) memory_layout: Checking 7 reserved memory ranges:
D (342) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc91c98
D (348) memory_layout: Reserved memory range 0x3fc91ca0 - 0x3fc957e8
D (355) memory_layout: Reserved memory range 0x3fcd0000 - 0x3fcd4000
D (361) memory_layout: Reserved memory range 0x3fcd4000 - 0x3fcd8000
D (368) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (374) memory_layout: Reserved memory range 0x40374000 - 0x40381c98
0x40374000: _WindowOverflow4 at /home/vdupaquis/Dev/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

D (381) memory_layout: Reserved memory range 0x600fe000 - 0x600fe000
D (387) memory_layout: Building list of available memory regions:
V (393) memory_layout: Examining memory region 0x40374000 - 0x40378000
0x40374000: _WindowOverflow4 at /home/vdupaquis/Dev/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

0x40378000: spi1_flash_os_check_yield at /home/vdupaquis/Dev/esp-idf/components/spi_flash/spi_flash_os_func_app.c:118

V (400) memory_layout: Region 0x40374000 - 0x40378000 inside of reserved 0x40374000 - 0x40381c98
0x40374000: _WindowOverflow4 at /home/vdupaquis/Dev/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

0x40378000: spi1_flash_os_check_yield at /home/vdupaquis/Dev/esp-idf/components/spi_flash/spi_flash_os_func_app.c:118

0x40374000: _WindowOverflow4 at /home/vdupaquis/Dev/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1736

V (409) memory_layout: Examining memory region 0x3fc88000 - 0x3fc90000
V (415) memory_layout: Region 0x3fc88000 - 0x3fc90000 inside of reserved 0x3fc84000 - 0x3fc91c98
V (424) memory_layout: Examining memory region 0x3fc90000 - 0x3fca0000
V (431) memory_layout: Start of region 0x3fc90000 - 0x3fca0000 overlaps reserved 0x3fc84000 - 0x3fc91c98
V (440) memory_layout: Region 0x3fc91c98 - 0x3fca0000 contains reserved 0x3fc91ca0 - 0x3fc957e8
V (449) memory_layout: Examining memory region 0x3fc957e8 - 0x3fca0000
D (456) memory_layout: Available memory region 0x3fc957e8 - 0x3fca0000
V (462) memory_layout: Examining memory region 0x3fca0000 - 0x3fcb0000
D (469) memory_layout: Available memory region 0x3fca0000 - 0x3fcb0000
V (475) memory_layout: Examining memory region 0x3fcb0000 - 0x3fcc0000
D (482) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
V (489) memory_layout: Examining memory region 0x3fcc0000 - 0x3fcd0000
D (495) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
V (502) memory_layout: Examining memory region 0x3fcd0000 - 0x3fce0000
V (508) memory_layout: Start of region 0x3fcd0000 - 0x3fce0000 overlaps reserved 0x3fcd0000 - 0x3fcd4000
V (518) memory_layout: Start of region 0x3fcd4000 - 0x3fce0000 overlaps reserved 0x3fcd4000 - 0x3fcd8000
D (527) memory_layout: Available memory region 0x3fcd8000 - 0x3fce0000
V (534) memory_layout: Examining memory region 0x3fce0000 - 0x3fce9710
D (541) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
V (547) memory_layout: Examining memory region 0x3fce9710 - 0x3fcf0000
V (554) memory_layout: End of region 0x3fce9710 - 0x3fcf0000 overlaps reserved 0x3fceee34 - 0x3fcf0000
D (563) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
V (570) memory_layout: Examining memory region 0x3fcf0000 - 0x3fcf8000
D (576) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
V (583) memory_layout: Examining memory region 0x600fe000 - 0x60100000
D (590) memory_layout: Available memory region 0x600fe000 - 0x60100000
I (596) heap_init: Initializing. RAM available for dynamic allocation:
D (603) heap_init: New heap initialised at 0x3fc957e8
I (609) heap_init: At 3FC957E8 len 0003A818 (234 KiB): D/IRAM
D (615) heap_init: New heap initialised at 0x3fcd8000
I (620) heap_init: At 3FCD8000 len 00011710 (69 KiB): D/IRAM
I (626) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
D (633) heap_init: New heap initialised at 0x3fcf0000
I (638) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (644) heap_init: New heap initialised at 0x600fe000
I (649) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
D (656) FLASH_HAL: extra_dummy: 0
V (659) memspi: raw_chip_id: 174020

V (663) memspi: chip_id: 204017

V (666) memspi: raw_chip_id: 174020

V (670) memspi: chip_id: 204017

D (673) spi_flash: trying chip: issi
D (677) spi_flash: trying chip: gd
D (681) spi_flash: trying chip: mxic
D (684) spi_flash: trying chip: winbond
D (688) spi_flash: trying chip: boya
D (692) spi_flash: trying chip: th
D (695) spi_flash: trying chip: mxic (opi)
D (700) spi_flash: trying chip: generic
I (703) spi_flash: detected chip: generic
I (708) spi_flash: flash io: dio
W (712) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
D (725) cpu_start: calling init function: 0x4200602c
0x4200602c: esp_ipc_init at /home/vdupaquis/Dev/esp-idf/components/esp_ipc/src/esp_ipc.c:105

D (730) cpu_start: calling init function: 0x42000f9c
0x42000f9c: esp_ota_init_app_elf_sha256 at /home/vdupaquis/Dev/esp-idf/components/app_update/esp_app_desc.c:68

V (735) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (741) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC02
D (750) intr_alloc: Connected src 59 to int 2 (cpu 0)
I (755) sleep: Configure to isolate all GPIO pins in sleep state
I (762) sleep: Enable automatic switching of GPIO sleep configuration
D (769) esp_apptrace: HW interface 0x3fc92f7c
V (773) esp_apptrace: Select block 0 @ 0x3fcd0000 (bits 0x15020)
I (779) esp_apptrace: Initialized TRAX on CPU0
V (784) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (790) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (799) intr_alloc: Connected src 79 to int 3 (cpu 0)
I (804) cpu_start: Starting scheduler on PRO CPU.
V (809) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (809) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x402
D (809) intr_alloc: Connected src 57 to int 9 (cpu 0)
I (649) esp_apptrace: Initialized TRAX on CPU1
V (819) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (819) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (829) intr_alloc: Connected src 80 to int 2 (cpu 1)
I (829) cpu_start: Starting scheduler on APP CPU.
V (839) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (849) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x402
D (849) intr_alloc: Connected src 58 to int 3 (cpu 1)
D (859) heap_init: New heap initialised at 0x3fce9710
V (859) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (859) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (859) intr_alloc: Connected src 52 to int 12 (cpu 0)
Hello world!
This is esp32s3 chip with 2 CPU core(s), WiFi/BLE, silicon revision 0, 2MB external flash
Minimum free heap size: 345168 bytes
before esp_partition_find_first()
D (899) partition: Loading the partition table
V (909) calculated md5: 0x3fcf4158   35 a9 3f 61 03 dd cd bd  99 8b d8 e7 9c 48 71 00  |5.?a.........Hq.|
V (909) stored md5: 0x3c0380b0   35 a9 3f 61 03 dd cd bd  99 8b d8 e7 9c 48 71 00  |5.?a.........Hq.|
D (919) partition: Partition table MD5 verified
esp_partition_find_first() returned 0x3fcea000
before esp_partition_read()
esp_partition_find_first() returned ESP_OK
Data are 23 a0 01 00 13 f5 08 00 05 01 00 00 90 00 00 00
before esp_partition_read()
spi_flash_mmap() returned ESP_ERR_NO_MEM
before esp_partition_read()
esp_partition_mmap() returned ESP_ERR_NO_MEM
V (975) esp_apptrace: esp_apptrace_flush_nolock(): enter
V (991) esp_apptrace: esp_apptrace_flush_nolock(): enter

More Information.

I tried to call esp_partition_read() to read and dump the partition to check if it can be accessed correctly. After verifying the first 16 bytes, it appears that the data I am expecting are there.
I also tried to call spi_flash_mmap() with the 3rd parameter being either SPI_FLASH_MMAP_INST or SPI_FLASH_MMAP_DATA. The partition is maped when using SPI_FLASH_MMAP_DATA, not when using SPI_FLASH_MMAP_INST.
Last, I tried to debug the function, and it appears that the error code is generated at the last steps of the debug when trying to find a place in the MMU pages or something like that.
Effectively the error comes from function spi_flash_mmap_pages() after the call to heap_caps_malloc()

[Icarus113]

It's a bug in flash_mmap.c, the available vaddrs for instruction is only 2 pages I think. Could you please help do a

uint32_t pages = spi_flash_mmap_get_free_pages(SPI_FLASH_MMAP_INST);

and let me know the pages? @vincentdupaquis

[vincentdupaquis]

I've added the line you've requested, and the available pages are 0.
BTW, I had made some tests asking for the mapping of a single 4 bytes area, and it was failing too ...
for the other request you sent me, the line you pointed-out (line 878 in bootloader_utility.c) does not matches what I see in my v4.4.3 version.

[Icarus113]

Thanks. The behaviour verifies this bug already. The returned 0 page is because the project image takes around 2 pages (and then rounded up to 2 pages).

We'll fix this bug, and bring the bugfix to v4.4 later. Thanks for your report~ @vincentdupaquis

[vincentdupaquis]

Thanks for being so reactive !

[vincentdupaquis]

I'm eagerly waiting for this update to pursue