ESP32-S2: Very slow startup time compared to ESP32 (IDFGH-8609)

ProjectProcrastinator commented 1 year ago

Answers checklist.

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

General issue report

I use an ESP32-S2-Solo module on a battery powered custom PCB to read sensor data and send the data with ESP-NOW. Therefore I desire a fast boot and code execution time to preserve battery life. My project works but the boot time of the ESP32-S2 seems really slow. I measured both the total time for code execution including startup and the time just for the execution of my code using millis(). On my initial try using Arduino-framework with PlatformIO I got ~510ms total, ~60ms for code execution. So 450ms just for startup from deep sleep. Seems very long for me. So I tried to improve it and therefore migrated the code to ESP-IDF using Arduino as a component with PlatformIO. I used all suggested options by Espressif in https://docs.espressif.com/projects/esp-idf/en/latest/esp32/api-guides/performance/speed.html to speed up startup and overall performance. Without edits in menuconfig the startup time was even higher. With the suggested edits I got the same time. Still slow. So I wrote a simple sketch just to test startup speed:

#include <Arduino.h>

void setup() {
    int start = millis();
    Serial.begin(115200);
    Serial.println("Starting");
    esp_sleep_enable_timer_wakeup(10 * 1000000);
    Serial.println((String)"Time from boot = " + millis() + (String)"ms");
    int stop = millis();
    int time = stop - start;
    Serial.println((String)"Time for code execution = " + time + (String)"ms");
    Serial.println();
    esp_deep_sleep_start();
}

void loop()  {}

Results for ESP32-S2 without menuconfig edits: 678ms total, 1ms for code execution Results for ESP32-S2 with menuconfig edits: 443ms total, 1ms for code execution

Then I used the same code with an ESP32-Module, but with [board = esp32doit-devkit-v1] in platformio.ini instead of [board = esp32-s2-saola-1]. That was the only difference.

Results with ESP32 without menuconfig edits: 47ms total, 1ms for code execution Results with ESP32 with menuconfig edits: 27ms total, 1ms for code execution.

So it seems to me that ESP32 has a way faster startup than ESP32-S2.

Later I tried some more things. I ditched the Arduino-code and just used ESP-IDF with that code:

#include <stdio.h>
#include "esp_timer.h"
#include "esp_sleep.h"

void app_main(void)
{
    printf("\n");
    printf("Time since boot: %lld us\n", esp_timer_get_time());

    esp_sleep_enable_timer_wakeup(10 * 1000000);    
    esp_deep_sleep_start(); 
}

I tried that code with PlatformIO and with ESP-IDF VSCode Extension. With the latter I tried various versions of ESP-IDF, including the current stable version, some earlier versions, version 5.0 and the current master. Startup time varied from version to version but it was never better than above, rather worse, like 600-700ms.

The ESP32-S2-Solo Module was bought from Digikey and the PCB uses the exact layout and peripheral components as suggested in the official datasheet. I don't see a reason why ESP32-S2 should be that much slower than ESP32. Am I doing something wrong or might that be a bug of some sort?

chipweinberger commented 1 year ago

the bootloader logs what it is doing during boot.

you should compare the two devices logs

ProjectProcrastinator commented 1 year ago

Thanks for the advice. I have used this code:

#include <Arduino.h>

void setup() {
    int start = millis();
    Serial.begin(115200);
    Serial.println("Starting");
    esp_sleep_enable_timer_wakeup(10 * 1000000);
    Serial.println((String)"Time from boot = " + millis() + (String)"ms");
    int stop = millis();
    int time = stop - start;
    Serial.println((String)"Time for code execution = " + time + (String)"ms");
    Serial.println();
    esp_deep_sleep_start(); 
}

void loop()  {}

for ESP32 and ESP32-S2. In menuconfig i have set both to: Bootloader log verbosity = Verbose and Default log verbosity = Verbose. Boot ROM output is permanently disabled for ESP32-S2.

Result for ESP32:

ets Jun  8 2016 00:22:57

rst:0x5 (DEEPSLEEP_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:10544
load:0x40078000,len:18836
ho 0 tail 12 room 4
load:0x40080400,len:5228
entry 0x40080720
␛[0;32mI (29) boot: ESP-IDF 4.4.2 2nd stage bootloader␛[0m
␛[0;32mI (29) boot: compile time 13:40:21␛[0m
D (29) bootloader_flash: non-XMC chip detected by SFDP Read (00), skip.␛[0m
D (35) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)␛[0m
␛[0;32mI (42) boot: chip revision: 1␛[0m
␛[0;32mI (45) boot_comm: chip revision: 1, min. bootloader chip revision: 0␛[0m
D (52) qio_mode: Probing for QIO mode enable...␛[0m
D (57) qio_mode: Raw SPI flash chip id 0x5e4016␛[0m
D (62) qio_mode: Manufacturer ID 0x5e chip ID 0x4016␛[0m
␛[0;32mI (67) qio_mode: Enabling default flash chip QIO␛[0m
D (72) qio_mode: Initial flash chip status 0x2␛[0m
D (76) qio_mode: QIO mode already enabled in flash␛[0m
D (81) qio_mode: Enabling QIO mode...␛[0m
D (85) boot.esp32: magic e9␛[0m
D (88) boot.esp32: segments 03␛[0m
D (91) boot.esp32: spi_mode 02␛[0m
D (94) boot.esp32: spi_speed 0f␛[0m
D (97) boot.esp32: spi_size 02␛[0m
␛[0;32mI (101) boot.esp32: SPI Speed      : 80MHz␛[0m
␛[0;32mI (105) boot.esp32: SPI Mode       : QIO␛[0m
␛[0;32mI (110) boot.esp32: SPI Flash Size : 4MB␛[0m
D (114) boot: Enabling RTCWDT(9000 ms)␛[0m
␛[0;32mI (118) boot: Enabling RNG early entropy source...␛[0m
D (124) esp_image: reading image header @ 0x20000␛[0m
D (129) bootloader_flash: mmu set block paddr=0x00020000 (was 0x00000000)␛[0m
V (135) esp_image: loading segment header 0 at offset 0x20018␛[0m
V (141) esp_image: segment data length 0xae30 data starts 0x20020␛[0m
V (147) esp_image: segment 0 map_segment 1 segment_data_offs 0x20020 load_addr 0x3f400020␛[0m
␛[0;32mI (156) esp_image: segment 0: paddr=00020020 vaddr=3f400020 size=0ae30h ( 44592) map␛[0m
D (164) esp_image: free data page_count 0x00000032␛[0m
D (169) esp_image: skipping checksum for segment␛[0m
V (174) esp_image: loading segment header 1 at offset 0x2ae50␛[0m
V (179) esp_image: segment data length 0x22c4 data starts 0x2ae58␛[0m
V (186) esp_image: segment 1 map_segment 0 segment_data_offs 0x2ae58 load_addr 0x3ffb0000␛[0m
␛[0;32mI (194) esp_image: segment 1: paddr=0002ae58 vaddr=3ffb0000 size=022c4h (  8900) load␛[0m
D (202) esp_image: free data page_count 0x00000032␛[0m
D (207) bootloader_flash: mmu set paddr=00020000 count=1 size=22c4 src_addr=2ae58 src_addr_aligned=20000␛[0m
V (217) esp_image: loading segment header 2 at offset 0x2d11c␛[0m
D (223) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)␛[0m
V (229) esp_image: segment data length 0x2ef4 data starts 0x2d124␛[0m
V (236) esp_image: segment 2 map_segment 0 segment_data_offs 0x2d124 load_addr 0x40080000␛[0m
␛[0;32mI (244) esp_image: segment 2: paddr=0002d124 vaddr=40080000 size=02ef4h ( 12020) load␛[0m
D (252) esp_image: free data page_count 0x00000032␛[0m
D (257) bootloader_flash: mmu set paddr=00020000 count=2 size=2ef4 src_addr=2d124 src_addr_aligned=20000␛[0m
V (268) esp_image: loading segment header 3 at offset 0x30018␛[0m
D (273) bootloader_flash: mmu set block paddr=0x00030000 (was 0xffffffff)␛[0m
V (279) esp_image: segment data length 0x1c10c data starts 0x30020␛[0m
V (286) esp_image: segment 3 map_segment 1 segment_data_offs 0x30020 load_addr 0x400d0020␛[0m
␛[0;32mI (294) esp_image: segment 3: paddr=00030020 vaddr=400d0020 size=1c10ch (114956) map␛[0m
D (302) esp_image: free data page_count 0x00000032␛[0m
D (307) esp_image: skipping checksum for segment␛[0m
V (312) esp_image: loading segment header 4 at offset 0x4c12c␛[0m
D (318) bootloader_flash: mmu set block paddr=0x00040000 (was 0x00030000)␛[0m
V (325) esp_image: segment data length 0x9db8 data starts 0x4c134␛[0m
V (331) esp_image: segment 4 map_segment 0 segment_data_offs 0x4c134 load_addr 0x40082ef4␛[0m
␛[0;32mI (339) esp_image: segment 4: paddr=0004c134 vaddr=40082ef4 size=09db8h ( 40376) load␛[0m
D (347) esp_image: free data page_count 0x00000032␛[0m
D (352) bootloader_flash: mmu set paddr=00040000 count=2 size=9db8 src_addr=4c134 src_addr_aligned=40000␛[0m
V (365) esp_image: loading segment header 5 at offset 0x55eec␛[0m
D (368) bootloader_flash: mmu set block paddr=0x00050000 (was 0xffffffff)␛[0m
V (375) esp_image: segment data length 0x64 data starts 0x55ef4␛[0m
V (381) esp_image: segment 5 map_segment 0 segment_data_offs 0x55ef4 load_addr 0x400c0000␛[0m
D (389) esp_image: Skipping RTC fast memory segment at 0x400c0000␛[0m
␛[0;32mI (395) esp_image: segment 5: paddr=00055ef4 vaddr=400c0000 size=00064h (   100) ␛[0m
D (403) esp_image: free data page_count 0x00000032␛[0m
D (408) esp_image: skipping checksum for segment␛[0m
V (413) esp_image: loading segment header 6 at offset 0x55f58␛[0m
V (418) esp_image: segment data length 0x10 data starts 0x55f60␛[0m
V (424) esp_image: segment 6 map_segment 0 segment_data_offs 0x55f60 load_addr 0x50000000␛[0m
D (433) esp_image: Skipping RTC slow memory segment at 0x50000000␛[0m
␛[0;32mI (439) esp_image: segment 6: paddr=00055f60 vaddr=50000000 size=00010h (    16) ␛[0m
D (447) esp_image: free data page_count 0x00000032␛[0m
D (452) esp_image: skipping checksum for segment␛[0m
V (457) esp_image: image start 0x00020000 end of last section 0x00055f70␛[0m
␛[0;32mI (463) boot: Fast booting app from partition at offset 0x20000␛[0m
␛[0;32mI (470) boot: Disabling RNG early entropy source...␛[0m
D (476) boot: Mapping segment 0 as DROM␛[0m
D (479) boot: Mapping segment 3 as IROM␛[0m
D (483) boot: calling set_cache_and_start_app␛[0m
D (488) boot: configure drom and irom and start␛[0m
V (492) boot: d mmu set paddr=00020000 vaddr=3f400000 size=44592 n=1␛[0m
V (499) boot: rc=0␛[0m
V (501) boot: rc=0␛[0m
V (503) boot: i mmu set paddr=00030000 vaddr=400d0000 size=114956 n=2␛[0m
V (509) boot: rc=0␛[0m
V (512) boot: rc=0␛[0m
D (514) boot: start: 0x40081d34␛[0m
␛[0;32mI (528) cpu_start: Pro cpu up.␛[0m
D (528) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 15 bit␛[0m
D (528) efuse: In EFUSE_BLK0__DATA5_REG is used 1 bits starting with 20 bit␛[0m
D (535) efuse: In EFUSE_BLK0__DATA3_REG is used 3 bits starting with 9 bit␛[0m
D (542) efuse: In EFUSE_BLK0__DATA3_REG is used 1 bits starting with 2 bit␛[0m
␛[0;32mI (549) cpu_start: Starting app cpu, entry point is 0x40081c7c␛[0m
␛[0;32mID(0)56p clta R: _pp c_u Kpc␛[imration value: 3495253␛[0m
␛[0;32mI (572) cpu_start: Pro cpu start user code␛[0m
␛[0;32mI (572) cpu_start: cpu freq: 160000000␛[0m
␛[0;32mI (572) cpu_start: Application information:␛[0m
␛[0;32mI (577) cpu_start: Project name:     ESP32_Test_Boot-Time_2␛[0m
␛[0;32mI (583) cpu_start: App version:      1␛[0m
␛[0;32mI (588) cpu_start: Compile time:     Oct 29 2022 13:39:35␛[0m
␛[0;32mI (594) cpu_start: ELF file SHA256:  c77603b83594477e...␛[0m
␛[0;32mI (600) cpu_start: ESP-IDF:          4.4.2␛[0m
V (605) memory_layout: reserved range is 0x3f40ae10 - 0x3f40ae50␛[0m
D (611) memory_layout: Checking 8 reserved memory ranges:␛[0m
D (616) memory_layout: Reserved memory range 0x3ff81ff0 - 0x3ff82000␛[0m
D (623) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0␛[0m
D (629) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb2d38␛[0m
D (635) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440␛[0m
D (642) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350␛[0m
D (648) memory_layout: Reserved memory range 0x40070000 - 0x40078000␛[0m
D (655) memory_layout: Reserved memory range 0x40078000 - 0x40080000␛[0m
D (661) memory_layout: Reserved memory range 0x40080000 - 0x4008ccac␛[0m
D (667) memory_layout: Building list of available memory regions:␛[0m
V (674) memory_layout: Examining memory region 0x3ffae000 - 0x3ffb0000␛[0m
V (680) memory_layout: Start of region 0x3ffae000 - 0x3ffb0000 overlaps reserved 0x3ffae000 - 0x3ffae6e0␛[0m
D (690) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000␛[0m
V (696) memory_layout: Examining memory region 0x3ffb0000 - 0x3ffb8000␛[0m
V (703) memory_layout: Start of region 0x3ffb0000 - 0x3ffb8000 overlaps reserved 0x3ffb0000 - 0x3ffb2d38␛[0m
D (713) memory_layout: Available memory region 0x3ffb2d38 - 0x3ffb8000␛[0m
V (719) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffc0000␛[0m
D (726) memory_layout: Available memory region 0x3ffb8000 - 0x3ffc0000␛[0m
V (732) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc2000␛[0m
D (739) memory_layout: Available memory region 0x3ffc0000 - 0x3ffc2000␛[0m
V (746) memory_layout: Examining memory region 0x3ffc2000 - 0x3ffc4000␛[0m
D (752) memory_layout: Available memory region 0x3ffc2000 - 0x3ffc4000␛[0m
V (759) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc6000␛[0m
D (765) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000␛[0m
V (772) memory_layout: Examining memory region 0x3ffc6000 - 0x3ffc8000␛[0m
D (779) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000␛[0m
V (785) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffca000␛[0m
D (792) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000␛[0m
V (798) memory_layout: Examining memory region 0x3ffca000 - 0x3ffcc000␛[0m
D (805) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000␛[0m
V (811) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffce000␛[0m
D (818) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000␛[0m
V (825) memory_layout: Examining memory region 0x3ffce000 - 0x3ffd0000␛[0m
D (831) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000␛[0m
V (838) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd2000␛[0m
D (844) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000␛[0m
V (851) memory_layout: Examining memory region 0x3ffd2000 - 0x3ffd4000␛[0m
D (858) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000␛[0m
V (864) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd6000␛[0m
D (871) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000␛[0m
V (877) memory_layout: Examining memory region 0x3ffd6000 - 0x3ffd8000␛[0m
D (884) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000␛[0m
V (891) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffda000␛[0m
D (897) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000␛[0m
V (904) memory_layout: Examining memory region 0x3ffda000 - 0x3ffdc000␛[0m
D (910) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000␛[0m
V (917) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffde000␛[0m
D (924) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000␛[0m
V (930) memory_layout: Examining memory region 0x3ffde000 - 0x3ffe0000␛[0m
D (937) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000␛[0m
V (943) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000␛[0m
V (950) memory_layout: Start of region 0x3ffe0000 - 0x3ffe4000 overlaps reserved 0x3ffe0000 - 0x3ffe0440␛[0m
V (960) memory_layout: End of region 0x3ffe0440 - 0x3ffe4000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350␛[0m
D (969) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20␛[0m
V (976) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000␛[0m
V (982) memory_layout: Start of region 0x3ffe4000 - 0x3ffe8000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350␛[0m
D (992) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000␛[0m
V (998) memory_layout: Examining memory region 0x3ffe8000 - 0x3fff0000␛[0m
D (1005) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000␛[0m
V (1012) memory_layout: Examining memory region 0x3fff0000 - 0x3fff8000␛[0m
D (1018) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000␛[0m
V (1025) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000␛[0m
D (1032) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000␛[0m
V (1038) memory_layout: Examining memory region 0x3fffc000 - 0x40000000␛[0m
D (1045) memory_layout: Available memory region 0x3fffc000 - 0x40000000␛[0m
V (1052) memory_layout: Examining memory region 0x40070000 - 0x40078000␛[0m
V (1058) memory_layout: Region 0x40070000 - 0x40078000 inside of reserved 0x40070000 - 0x40078000␛[0m
V (1067) memory_layout: Examining memory region 0x40078000 - 0x40080000␛[0m
V (1074) memory_layout: Region 0x40078000 - 0x40080000 inside of reserved 0x40078000 - 0x40080000␛[0m
V (1083) memory_layout: Examining memory region 0x40080000 - 0x40082000␛[0m
V (1090) memory_layout: Region 0x40080000 - 0x40082000 inside of reserved 0x40080000 - 0x4008ccac␛[0m
V (1099) memory_layout: Examining memory region 0x40082000 - 0x40084000␛[0m
V (1105) memory_layout: Region 0x40082000 - 0x40084000 inside of reserved 0x40080000 - 0x4008ccac␛[0m
V (1114) memory_layout: Examining memory region 0x40084000 - 0x40086000␛[0m
V (1121) memory_layout: Region 0x40084000 - 0x40086000 inside of reserved 0x40080000 - 0x4008ccac␛[0m
V (1130) memory_layout: Examining memory region 0x40086000 - 0x40088000␛[0m
V (1136) memory_layout: Region 0x40086000 - 0x40088000 inside of reserved 0x40080000 - 0x4008ccac␛[0m
V (1145) memory_layout: Examining memory region 0x40088000 - 0x4008a000␛[0m
V (1152) memory_layout: Region 0x40088000 - 0x4008a000 inside of reserved 0x40080000 - 0x4008ccac␛[0m
V (1161) memory_layout: Examining memory region 0x4008a000 - 0x4008c000␛[0m
V (1168) memory_layout: Region 0x4008a000 - 0x4008c000 inside of reserved 0x40080000 - 0x4008ccac␛[0m
V (1177) memory_layout: Examining memory region 0x4008c000 - 0x4008e000␛[0m
V (1183) memory_layout: Start of region 0x4008c000 - 0x4008e000 overlaps reserved 0x40080000 - 0x4008ccac␛[0m
D (1193) memory_layout: Available memory region 0x4008ccac - 0x4008e000␛[0m
V (1200) memory_layout: Examining memory region 0x4008e000 - 0x40090000␛[0m
D (1206) memory_layout: Available memory region 0x4008e000 - 0x40090000␛[0m
V (1213) memory_layout: Examining memory region 0x40090000 - 0x40092000␛[0m
D (1220) memory_layout: Available memory region 0x40090000 - 0x40092000␛[0m
V (1226) memory_layout: Examining memory region 0x40092000 - 0x40094000␛[0m
D (1233) memory_layout: Available memory region 0x40092000 - 0x40094000␛[0m
V (1240) memory_layout: Examining memory region 0x40094000 - 0x40096000␛[0m
D (1246) memory_layout: Available memory region 0x40094000 - 0x40096000␛[0m
V (1253) memory_layout: Examining memory region 0x40096000 - 0x40098000␛[0m
D (1260) memory_layout: Available memory region 0x40096000 - 0x40098000␛[0m
V (1267) memory_layout: Examining memory region 0x40098000 - 0x4009a000␛[0m
D (1273) memory_layout: Available memory region 0x40098000 - 0x4009a000␛[0m
V (1280) memory_layout: Examining memory region 0x4009a000 - 0x4009c000␛[0m
D (1287) memory_layout: Available memory region 0x4009a000 - 0x4009c000␛[0m
V (1293) memory_layout: Examining memory region 0x4009c000 - 0x4009e000␛[0m
D (1300) memory_layout: Available memory region 0x4009c000 - 0x4009e000␛[0m
V (1307) memory_layout: Examining memory region 0x4009e000 - 0x400a0000␛[0m
D (1313) memory_layout: Available memory region 0x4009e000 - 0x400a0000␛[0m
␛[0;32mI (1320) heap_init: Initializing. RAM available for dynamic allocation:␛[0m
D (1327) heap_init: New heap initialised at 0x3ffae6e0␛[0m
␛[0;32mI (1332) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM␛[0m
D (1339) heap_init: New heap initialised at 0x3ffb2d38␛[0m
␛[0;32mI (1344) heap_init: At 3FFB2D38 len 0002D2C8 (180 KiB): DRAM␛[0m
␛[0;32mI (1350) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM␛[0m
␛[0;32mI (1357) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM␛[0m
D (1363) heap_init: New heap initialised at 0x4008ccac␛[0m
␛[0;32mI (1368) heap_init: At 4008CCAC len 00013354 (76 KiB): IRAM␛[0m
V (1375) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1381) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE␛[0m
D (1389) intr_alloc: Connected src 46 to int 2 (cpu 0)␛[0m
D (1395) FLASH_HAL: extra_dummy: 2␛[0m
V (1398) memspi: raw_chip_id: 16405E
␛[0m
V (1402) memspi: chip_id: 5E4016
␛[0m
V (1405) memspi: raw_chip_id: 16405E
␛[0m
V (1409) memspi: chip_id: 5E4016
␛[0m
D (1412) spi_flash: trying chip: issi␛[0m
D (1416) spi_flash: trying chip: gd␛[0m
D (1420) spi_flash: trying chip: mxic␛[0m
D (1423) spi_flash: trying chip: winbond␛[0m
D (1427) spi_flash: trying chip: generic␛[0m
␛[0;32mI (1431) spi_flash: detected chip: generic␛[0m
␛[0;32mI (1436) spi_flash: flash io: qio␛[0m
D (1440) chip_generic: set_io_mode: status before 0x200␛[0m
V (1445) chip_generic: set_io_mode: status update 0x200␛[0m
D (1451) cpu_start: calling init function: 0x400ddedc␛[0m
D (1456) cpu_start: calling init function: 0x400dd4f0␛[0m
D (1461) cpu_start: calling init function: 0x400dd2c8␛[0m
D (1466) cpu_start: calling init function: 0x400d7284␛[0m
D (1471) cpu_start: calling init function: 0x400d6a58␛[0m
D (1477) cpu_start: calling init function: 0x400d28c4␛[0m
D (1481) cpu_start: calling init function: 0x400d24e8␛[0m
D (1487) cpu_start: calling init function: 0x400d1f50␛[0m
V (1492) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1498) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC02␛[0m
D (1506) intr_alloc: Connected src 17 to int 3 (cpu 0)␛[0m
V (1512) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1518) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E␛[0m
D (1526) intr_alloc: Connected src 24 to int 9 (cpu 0)␛[0m
␛[0;32mI (1531) cpu_start: Starting scheduler on PRO CPU.␛[0m
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args␛[0m
V (6) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E␛[0m
D (14) intr_alloc: Connected src 25 to int 2 (cpu 1)␛[0m
␛[0;32mI (19) cpu_start: Starting scheduler on APP CPU.␛[0m
D (1585) heap_init: New heap initialised at 0x3ffe0440␛[0m
D (1590) heap_init: New heap initialised at 0x3ffe4350␛[0m
V (1595) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1595) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE␛[0m
D (1595) intr_alloc: Connected src 16 to int 12 (cpu 0)␛[0m
D (1615) partition: Loading the partition table␛[0m
V (1620) calculated md5: 0x3ffb59e8   16 5f 84 4e 94 27 08 e7  7e 2c 2b 99 ca 96 49 4f  |._.N.'..~,+...IO|␛[0m
V (1630) stored md5: 0x3f410070   16 5f 84 4e 94 27 08 e7  7e 2c 2b 99 ca 96 49 4f  |._.N.'..~,+...IO|␛[0m
D (1639) partition: Partition table MD5 verified␛[0m
␛[0;32mI (1646) uart: queue free spaces: 20␛[0m
V (1648) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args␛[0m
V (1654) intr_alloc: esp_Starting
Time from boot = 269ms
Time for code execution = 21ms

D (1668) sleep: RTC_PERIPH: AUTO(OFF)␛[0m
D (1668) sleep: RTC_SLOW_MEM: ON␛[0m
D (1668) sleep: RTC_FAST_MEM: ON␛[0m

Result for ESP32-S2:

␛[0;32mI (21) boot: ESP-IDF 4.4.2 2nd stage bootloader␛[0m
␛[0;32mI (21) boot: compile time 12:22:38␛[0m
D (21) bootloader_flash: non-XMC chip detected by SFDP Read (00), skip.␛[0m
D (26) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)␛[0m
␛[0;32mI (32) boot: chip revision: 0␛[0m
D (36) qio_mode: Probing for QIO mode enable...␛[0m
D (41) qio_mode: Raw SPI flash chip id 0x5e4016␛[0m
D (45) qio_mode: Manufacturer ID 0x5e chip ID 0x4016␛[0m
␛[0;32mI (50) qio_mode: Enabling default flash chip QIO␛[0m
D (56) qio_mode: Initial flash chip status 0x2␛[0m
D (60) qio_mode: QIO mode already enabled in flash␛[0m
D (65) qio_mode: Enabling QIO mode...␛[0m
D (69) boot.esp32s2: magic e9␛[0m
D (72) boot.esp32s2: segments 03␛[0m
D (75) boot.esp32s2: spi_mode 02␛[0m
D (78) boot.esp32s2: spi_speed 0f␛[0m
D (82) boot.esp32s2: spi_size 02␛[0m
␛[0;32mI (85) boot.esp32s2: SPI Speed      : 80MHz␛[0m
␛[0;32mI (90) boot.esp32s2: SPI Mode       : QIO␛[0m
␛[0;32mI (95) boot.esp32s2: SPI Flash Size : 4MB␛[0m
D (99) boot: Enabling RTCWDT(9000 ms)␛[0m
␛[0;32mI (103) boot: Enabling RNG early entropy source...␛[0m
D (108) esp_image: reading image header @ 0x10000␛[0m
D (113) bootloader_flash: mmu set block paddr=0x00010000 (was 0x00000000)␛[0m
V (120) esp_image: loading segment header 0 at offset 0x10018␛[0m
V (126) esp_image: segment data length 0xa3d0 data starts 0x10020␛[0m
V (132) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3f000020␛[0m
␛[0;32mI (140) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=0a3d0h ( 41936) map␛[0m
D (149) esp_image: free data page_count 0x0000003f␛[0m
D (154) esp_image: skipping checksum for segment␛[0m
V (158) esp_image: loading segment header 1 at offset 0x1a3f0␛[0m
V (164) esp_image: segment data length 0x1f20 data starts 0x1a3f8␛[0m
V (170) esp_image: segment 1 map_segment 0 segment_data_offs 0x1a3f8 load_addr 0x3ffbfd40␛[0m
␛[0;32mI (178) esp_image: segment 1: paddr=0001a3f8 vaddr=3ffbfd40 size=01f20h (  7968) load␛[0m
D (187) esp_image: free data page_count 0x0000003f␛[0m
D (192) bootloader_flash: mmu set paddr=00010000 count=1 size=1f20 src_addr=1a3f8 src_addr_aligned=10000␛[0m
V (202) esp_image: loading segment header 2 at offset 0x1c318␛[0m
D (207) bootloader_flash: mmu set block paddr=0x00010000 (was 0xffffffff)␛[0m
V (214) esp_image: segment data length 0x3cf8 data starts 0x1c320␛[0m
V (220) esp_image: segment 2 map_segment 0 segment_data_offs 0x1c320 load_addr 0x40022000␛[0m
␛[0;32mI (228) esp_image: segment 2: paddr=0001c320 vaddr=40022000 size=03cf8h ( 15608) load␛[0m
D (237) esp_image: free data page_count 0x0000003f␛[0m
D (242) bootloader_flash: mmu set paddr=00010000 count=2 size=3cf8 src_addr=1c320 src_addr_aligned=10000␛[0m
V (253) esp_image: loading segment header 3 at offset 0x20018␛[0m
D (257) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)␛[0m
V (264) esp_image: segment data length 0x1d668 data starts 0x20020␛[0m
V (270) esp_image: segment 3 map_segment 1 segment_data_offs 0x20020 load_addr 0x40080020␛[0m
␛[0;32mI (279) esp_image: segment 3: paddr=00020020 vaddr=40080020 size=1d668h (120424) map␛[0m
D (287) esp_image: free data page_count 0x0000003f␛[0m
D (292) esp_image: skipping checksum for segment␛[0m
V (297) esp_image: loading segment header 4 at offset 0x3d688␛[0m
D (302) bootloader_flash: mmu set block paddr=0x00030000 (was 0x00020000)␛[0m
V (309) esp_image: segment data length 0xa03c data starts 0x3d690␛[0m
V (315) esp_image: segment 4 map_segment 0 segment_data_offs 0x3d690 load_addr 0x40025cf8␛[0m
␛[0;32mI (324) esp_image: segment 4: paddr=0003d690 vaddr=40025cf8 size=0a03ch ( 41020) load␛[0m
D (332) esp_image: free data page_count 0x0000003f␛[0m
D (337) bootloader_flash: mmu set paddr=00030000 count=2 size=a03c src_addr=3d690 src_addr_aligned=30000␛[0m
V (350) esp_image: loading segment header 5 at offset 0x476cc␛[0m
D (352) bootloader_flash: mmu set block paddr=0x00040000 (was 0xffffffff)␛[0m
V (359) esp_image: segment data length 0x2c data starts 0x476d4␛[0m
V (365) esp_image: segment 5 map_segment 0 segment_data_offs 0x476d4 load_addr 0x40070000␛[0m
D (373) esp_image: Skipping RTC fast memory segment at 0x40070000␛[0m
␛[0;32mI (380) esp_image: segment 5: paddr=000476d4 vaddr=40070000 size=0002ch (    44) ␛[0m
D (388) esp_image: free data page_count 0x0000003f␛[0m
D (393) esp_image: skipping checksum for segment␛[0m
V (397) esp_image: loading segment header 6 at offset 0x47700␛[0m
V (403) esp_image: segment data length 0x10 data starts 0x47708␛[0m
V (409) esp_image: segment 6 map_segment 0 segment_data_offs 0x47708 load_addr 0x50000000␛[0m
D (417) esp_image: Skipping RTC slow memory segment at 0x50000000␛[0m
␛[0;32mI (424) esp_image: segment 6: paddr=00047708 vaddr=50000000 size=00010h (    16) ␛[0m
D (432) esp_image: free data page_count 0x0000003f␛[0m
D (437) esp_image: skipping checksum for segment␛[0m
V (441) esp_image: image start 0x00010000 end of last section 0x00047718␛[0m
␛[0;32mI (448) boot: Fast booting app from partition at offset 0x10000␛[0m
␛[0;32mI (455) boot: Disabling RNG early entropy source...␛[0m
D (460) boot: Mapping segment 0 as DROM␛[0m
D (464) boot: Mapping segment 3 as IROM␛[0m
D (468) boot: calling set_cache_and_start_app␛[0m
D (472) boot: configure drom and irom and start␛[0m
V (477) boot: d mmu set paddr=00010000 vaddr=3f000000 size=41936 n=1␛[0m
V (483) boot: rc=0␛[0m
V (485) boot: i mmu set paddr=00020000 vaddr=40080000 size=120424 n=2␛[0m
V (492) boot: rc=0␛[0m
D (494) boot: start: 0x40024244␛[0m
␛[0;32mI (508) cache: Instruction cache         : size 8KB, 4Ways, cache line size 32Byte␛[0m
␛[0;32mI (509) cpu_start: Pro cpu up.␛[0m
D (509) clk: RTC_SLOW_CLK calibration value: 5825422␛[0m
␛[0;32mI (525) cpu_start: Pro cpu start user code␛[0m
␛[0;32mI (525) cpu_start: cpu freq: 160000000␛[0m
␛[0;32mI (525) cpu_start: Application information:␛[0m
␛[0;32mI (530) cpu_start: Project name:     ESP32-S2_IDF_Bootup_Time_Test␛[0m
␛[0;32mI (537) cpu_start: App version:      1␛[0m
␛[0;32mI (541) cpu_start: Compile time:     Oct 29 2022 12:21:57␛[0m
␛[0;32mI (547) cpu_start: ELF file SHA256:  fc90a54762408b8d...␛[0m
␛[0;32mI (553) cpu_start: ESP-IDF:          4.4.2␛[0m
V (558) memory_layout: reserved range is 0x3f00a3c8 - 0x3f00a3f0␛[0m
D (564) memory_layout: Checking 5 reserved memory ranges:␛[0m
D (570) memory_layout: Reserved memory range 0x3ff9e000 - 0x3ff9e02c␛[0m
D (576) memory_layout: Reserved memory range 0x3ff9fff0 - 0x3ffa0000␛[0m
D (583) memory_layout: Reserved memory range 0x3ffb2000 - 0x3ffbfd34␛[0m
D (589) memory_layout: Reserved memory range 0x3ffbfd40 - 0x3ffc2630␛[0m
D (595) memory_layout: Reserved memory range 0x3ffffa10 - 0x40000000␛[0m
D (602) memory_layout: Building list of available memory regions:␛[0m
V (608) memory_layout: Examining memory region 0x3ffb2000 - 0x3ffb4000␛[0m
V (615) memory_layout: Region 0x3ffb2000 - 0x3ffb4000 inside of reserved 0x3ffb2000 - 0x3ffbfd34␛[0m
V (623) memory_layout: Examining memory region 0x3ffb4000 - 0x3ffb6000␛[0m
V (630) memory_layout: Region 0x3ffb4000 - 0x3ffb6000 inside of reserved 0x3ffb2000 - 0x3ffbfd34␛[0m
V (639) memory_layout: Examining memory region 0x3ffb6000 - 0x3ffb8000␛[0m
V (645) memory_layout: Region 0x3ffb6000 - 0x3ffb8000 inside of reserved 0x3ffb2000 - 0x3ffbfd34␛[0m
V (654) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffbc000␛[0m
V (661) memory_layout: Region 0x3ffb8000 - 0x3ffbc000 inside of reserved 0x3ffb2000 - 0x3ffbfd34␛[0m
V (670) memory_layout: Examining memory region 0x3ffbc000 - 0x3ffc0000␛[0m
V (676) memory_layout: Start of region 0x3ffbc000 - 0x3ffc0000 overlaps reserved 0x3ffb2000 - 0x3ffbfd34␛[0m
V (686) memory_layout: End of region 0x3ffbfd34 - 0x3ffc0000 overlaps reserved 0x3ffbfd40 - 0x3ffc2630␛[0m
V (695) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc4000␛[0m
V (702) memory_layout: Start of region 0x3ffc0000 - 0x3ffc4000 overlaps reserved 0x3ffbfd40 - 0x3ffc2630␛[0m
D (711) memory_layout: Available memory region 0x3ffc2630 - 0x3ffc4000␛[0m
V (718) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc8000␛[0m
D (725) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc8000␛[0m
V (731) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffcc000␛[0m
D (738) memory_layout: Available memory region 0x3ffc8000 - 0x3ffcc000␛[0m
V (744) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffd0000␛[0m
D (751) memory_layout: Available memory region 0x3ffcc000 - 0x3ffd0000␛[0m
V (758) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd4000␛[0m
D (764) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd4000␛[0m
V (771) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd8000␛[0m
D (777) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd8000␛[0m
V (784) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffdc000␛[0m
D (791) memory_layout: Available memory region 0x3ffd8000 - 0x3ffdc000␛[0m
V (797) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffe0000␛[0m
D (804) memory_layout: Available memory region 0x3ffdc000 - 0x3ffe0000␛[0m
V (810) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000␛[0m
D (817) memory_layout: Available memory region 0x3ffe0000 - 0x3ffe4000␛[0m
V (824) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000␛[0m
D (830) memory_layout: Available memory region 0x3ffe4000 - 0x3ffe8000␛[0m
V (837) memory_layout: Examining memory region 0x3ffe8000 - 0x3ffec000␛[0m
D (843) memory_layout: Available memory region 0x3ffe8000 - 0x3ffec000␛[0m
V (850) memory_layout: Examining memory region 0x3ffec000 - 0x3fff0000␛[0m
D (857) memory_layout: Available memory region 0x3ffec000 - 0x3fff0000␛[0m
V (863) memory_layout: Examining memory region 0x3fff0000 - 0x3fff4000␛[0m
D (870) memory_layout: Available memory region 0x3fff0000 - 0x3fff4000␛[0m
V (876) memory_layout: Examining memory region 0x3fff4000 - 0x3fff8000␛[0m
D (883) memory_layout: Available memory region 0x3fff4000 - 0x3fff8000␛[0m
V (890) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000␛[0m
D (896) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000␛[0m
V (903) memory_layout: Examining memory region 0x3fffc000 - 0x40000000␛[0m
V (909) memory_layout: End of region 0x3fffc000 - 0x40000000 overlaps reserved 0x3ffffa10 - 0x40000000␛[0m
D (919) memory_layout: Available memory region 0x3fffc000 - 0x3ffffa10␛[0m
V (925) memory_layout: Examining memory region 0x3ff9e000 - 0x3ffa0000␛[0m
V (932) memory_layout: Start of region 0x3ff9e000 - 0x3ffa0000 overlaps reserved 0x3ff9e000 - 0x3ff9e02c␛[0m
V (941) memory_layout: End of region 0x3ff9e02c - 0x3ffa0000 overlaps reserved 0x3ff9fff0 - 0x3ffa0000␛[0m
D (951) memory_layout: Available memory region 0x3ff9e02c - 0x3ff9fff0␛[0m
␛[0;32mI (957) heap_init: Initializing. RAM available for dynamic allocation:␛[0m
D (965) heap_init: New heap initialised at 0x3ffc2630␛[0m
␛[0;32mI (970) heap_init: At 3FFC2630 len 000399D0 (230 KiB): DRAM␛[0m
␛[0;32mI (976) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM␛[0m
D (982) heap_init: New heap initialised at 0x3ff9e02c␛[0m
␛[0;32mI (987) heap_init: At 3FF9E02C len 00001FC4 (7 KiB): RTCRAM␛[0m
D (994) FLASH_HAL: extra_dummy: 0␛[0m
V (997) memspi: raw_chip_id: 16405E
␛[0m
V (1001) memspi: chip_id: 5E4016
␛[0m
V (1004) memspi: raw_chip_id: 16405E
␛[0m
V (1008) memspi: chip_id: 5E4016
␛[0m
D (1011) spi_flash: trying chip: issi␛[0m
D (1015) spi_flash: trying chip: gd␛[0m
D (1019) spi_flash: trying chip: mxic␛[0m
D (1023) spi_flash: trying chip: winbond␛[0m
D (1027) spi_flash: trying chip: boya␛[0m
D (1030) spi_flash: trying chip: th␛[0m
D (1034) spi_flash: trying chip: generic␛[0m
␛[0;32mI (1038) spi_flash: detected chip: generic␛[0m
␛[0;32mI (1043) spi_flash: flash io: qio␛[0m
D (1047) chip_generic: set_io_mode: status before 0x200␛[0m
V (1052) chip_generic: set_io_mode: status update 0x200␛[0m
D (1057) cpu_start: calling init function: 0x4008dd38␛[0m
D (1062) cpu_start: calling init function: 0x4008d8dc␛[0m
D (1067) cpu_start: calling init function: 0x4008d7f8␛[0m
D (1072) cpu_start: calling init function: 0x4008d698␛[0m
D (1078) cpu_start: calling init function: 0x400879d4␛[0m
D (1083) cpu_start: calling init function: 0x400827d8␛[0m
D (1088) cpu_start: calling init function: 0x40082514␛[0m
D (1093) cpu_start: calling init function: 0x40081e9c␛[0m
V (1098) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1105) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE02␛[0m
D (1113) intr_alloc: Connected src 73 to int 10 (cpu 0)␛[0m
V (1118) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1125) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E␛[0m
D (1133) intr_alloc: Connected src 28 to int 2 (cpu 0)␛[0m
␛[0;32mI (1138) cpu_start: Starting scheduler on PRO CPU.␛[0m
D (1144) heap_init: New heap initialised at 0x3fffc000␛[0m
V (1149) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1149) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE␛[0m
D (1149) intr_alloc: Connected src 17 to int 3 (cpu 0)␛[0m
D (1169) partition: Loading the partition table␛[0m
V (1173) calculated md5: 0x3ffc5478   f4 ad 4f 45 38 56 4b 5d  74 35 b6 2c 75 b6 95 24  |..OE8VK]t5.,u..$|␛[0m
V (1183) stored md5: 0x3f018070   f4 ad 4f 45 38 56 4b 5d  74 35 b6 2c 75 b6 95 24  |..OE8VK]t5.,u..$|␛[0m
D (1192) partition: Partition table MD5 verified␛[0m
␛[0;32mI (1201) uart: queue free spaces: 20␛[0m
V (1202) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args␛[0m
V (1207) intr_alloc: espStarting
Time from boot = 1625ms
Time for code execution = 19ms

D (1221) sleep: RTC_PERIPH: AUTO(OFF)␛[0m
D (1221) sleep: RTC_SLOW_MEM: ON␛[0m
D (1221) sleep: RTC_FAST_MEM: ON␛[0m

To be honest, I don't understand most of this, so help would be greatly appreciated. Notable is the huge difference in time needed. 269ms (ESP32) vs 1625ms (ESP32-S2). The additional logs seem to have a much greater effect on ESP32-S2 compared to ESP32.

espressif / esp-idf

ESP32-S2: Very slow startup time compared to ESP32 (IDFGH-8609) #10056

Answers checklist.

General issue report