ESP32 启动时间过长分析

1、问题描述 

正常启动:1555ms

[2019-03-14 15:42:29.183]# RECV ASCII>
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x17 (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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6288
ho 0 tail 12 room 4
load:0x40078000,len:10168
ho 0 tail 12 room 4
load:0x40080400,len:6552
entry 0x40080764
[0;32mI (32) boot: ESP-IDF v3.3-dev-337-g1cffc90e5-dirty 2nd stage bootloader[0m
[0;32mI (32) boot: compile time 10:58:05[0m
[0;32mI (33

[2019-03-14 15:42:29.227]# RECV ASCII>
) boot: Enabling RNG early entropy source...[0m
[0;32mI (39) boot: SPI Speed      : 40MHz[0m
[0;32mI (43) boot: SPI Mode       : DIO[0m
[0;32mI (47) boot: SPI Flash Size : 8MB[0m
[0;32mI (51) boot: Partition Table:[0m
[0;32mI (55) boot: ## Label            Usage          Type ST Offset   Length[0m
[0;32mI (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000[0m
[0;32mI (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000[0m
[0;32mI (77) boot:  2 f

[2019-03-14 15:42:29.285]# RECV ASCII>
actory          factory app      00 00 00010000 00200000[0m
[0;32mI (84) boot: End of partition table[0m
[0;32mI (88) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x609ac (395692) map[0m


[2019-03-14 15:42:29.416]# RECV ASCII>
[0;32mI (236) esp_image: segment 1: paddr=0x000709d4 vaddr=0x3ff80000 size=0x00000 (     0) load[0m
[0;32mI (236) esp_image: segment 2: paddr=0x000709dc vaddr=0x3ff80000 size=0x00000 (     0) load[0m
[0;32mI (243) esp_image: segment 3: paddr=0x000709e4 vaddr=0x3ffbdb60 size=0x02f44 ( 12100) load[0m
[0;32mI (256) esp_image: segment 4: paddr=0x00073930 vaddr=0x3ffc0aa4 size=0x00000 (     0) load[0m
[0;32mI (261) esp_image: segment 5: paddr=0x00073938 vaddr=0x40080000 size=0x00400 (  1024) load[0

[2019-03-14 15:42:29.492]# RECV ASCII>
m
[0;32mI (270) esp_image: segment 6: paddr=0x00073d40 vaddr=0x40080400 size=0x0c2d0 ( 49872) load[0m
[0;32mI (299) esp_image: segment 7: paddr=0x00080018 vaddr=0x400d0018 size=0xaefa0 (716704) map[0m


[2019-03-14 15:42:29.752]# RECV ASCII>
[0;32mI (550) esp_image: segment 8: paddr=0x0012efc0 vaddr=0x4008c6d0 size=0x0e168 ( 57704) load[0m
[0;32mI (575) esp_image: segment 9: paddr=0x0013d130 vaddr=0x400c0000 size=0x00000 (     0) load[0m
[0;32mI (575) esp_image: segment 10: paddr=0x0013d138 vaddr=0x50000000 size=0x00000 (     0) load[0m
[0;32mI (581) esp_image: segment 11: paddr=0x0013d140 vaddr=0x50000000 size=0x00000 (     0) load[0m
[0;32mI (605) boot: Loaded app from partition at offset 0x10000[0m
[0;32mI (605) boot: Disabli

[2019-03-14 15:42:29.826]# RECV ASCII>
ng RNG early entropy source...[0m
[0;32mI (608) spiram: Found 64MBit SPI RAM device[0m
[0;32mI (611) spiram: SPI RAM mode: flash 40m sram 40m[0m
[0;32mI (616) spiram: PSRAM initialized, cache is in low/high (2-core) mode.[0m
[0;32mI (623) cpu_start: Pro cpu up.[0m
[0;32mI (627) cpu_start: Starting app cpu, entry point is 0x400814cc[0m
[0;32mI (0) cpu_start: App cpu up.[0m


[2019-03-14 15:42:30.688]# RECV ASCII>
[0;32mI (1508) spiram: SPI SRAM memory test OK[0m
[0;32mI (1509) heap_init: Initializing. RAM available for dynamic allocation:[0m
[0;32mI (1509) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM[0m
[0;32mI (1515) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM[0m
[0;32mI (1521) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM[0m
[0;32mI (1527) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM[0m
[0;32mI (1534) heap_init: At 3FFCF538 len 00010AC8 (66 KiB): DRAM[0m
[0;32mI (1540) he

[2019-03-14 15:42:30.738]# RECV ASCII>
ap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM[0m
[0;32mI (1546) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[0;32mI (1553) heap_init: At 4009A838 len 000057C8 (21 KiB): IRAM[0m
[0;32mI (1559) cpu_start: Pro cpu start user code[0m
[0;32mI (1564) spiram: Adding pool of 4096K of external SPI memory to heap allocator[0m
[0;32mI (243) cpu_start: Starting scheduler on PRO CPU.[0m
[0;32mI (0) cpu_start: Starting scheduler on APP CPU.[0m
[0;32mI (245) spiram: Reserving pool of

[2019-03-14 15:42:30.841]# RECV ASCII>
 32K of internal memory for DMA/internal allocations[0m

问题LOG

[2019-03-14 15:12:04.858]# RECV ASCII>
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x17 (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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6288
ho 0 tail 12 room 4
load:0x40078000,len:10168
ho 0 tail 12 room 4
load:0x40080400,len:6552
entry 0x40080764
[0;32mI (32) boot: ESP-IDF v3.3-dev-337-g1cffc90e5-dirty 2nd stage bootloader[0m
[0;32mI (32) boot: compile time 19:38:03[0m
[0;32mI (33

[2019-03-14 15:12:04.902]# RECV ASCII>
) boot: Enabling RNG early entropy source...[0m
[0;32mI (39) boot: SPI Speed      : 40MHz[0m
[0;32mI (43) boot: SPI Mode       : DIO[0m
[0;32mI (47) boot: SPI Flash Size : 4MB[0m
[0;32mI (51) boot: Partition Table:[0m
[0;32mI (54) boot: ## Label            Usage          Type ST Offset   Length[0m
[0;32mI (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000[0m
[0;32mI (69) boot:  1 phy_init         RF data          01 01 0000f000 00001000[0m
[0;32mI (77) boot:  2 f

[2019-03-14 15:12:04.961]# RECV ASCII>
actory          factory app      00 00 00010000 00200000[0m
[0;32mI (84) boot: End of partition table[0m
[0;32mI (88) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0xdd074 (905332) map[0m


[2019-03-14 15:12:05.286]# RECV ASCII>
[0;32mI (414) esp_image: segment 1: paddr=0x000ed09c vaddr=0x3ffbdb60 size=0x02f74 ( 12148) load[0m
[0;32mI (419) esp_image: segment 2: paddr=0x000f0018 vaddr=0x400d0018 size=0xcddb8 (843192) map[0m


[2019-03-14 15:12:05.609]# RECV ASCII>
[0;32mI (716) esp_image: segment 3: paddr=0x001bddd8 vaddr=0x3ffc0ad4 size=0x001b8 (   440) load[0m
[0;32mI (717) esp_image: segment 4: paddr=0x001bdf98 vaddr=0x3ffc0c8c size=0x00000 (     0) load[0m
[0;32mI (723) esp_image: segment 5: paddr=0x001bdfa0 vaddr=0x40080000 size=0x00400 (  1024) load[0m
[0;32mI (732) esp_image: segment 6: paddr=0x001be3a8 vaddr=0x40080400 size=0x1b1fc (111100) load[0m
[0;32mI (787) esp_image: segment 7: paddr=0x001d95ac vaddr=0x400c0000 size=0x0006c (   108) load[0

[2019-03-14 15:12:05.657]# RECV ASCII>
m
[0;32mI (787) esp_image: segment 8: paddr=0x001d9620 vaddr=0x50000000 size=0x00000 (     0) load[0m
[0;32mI (794) esp_image: segment 9: paddr=0x001d9628 vaddr=0x50000000 size=0x00000 (     0) load[0m
[0;32mI (818) boot: Loaded app from partition at offset 0x10000[0m
[0;32mI (818) boot: Disabling RNG early entropy source...[0m
[0;32mI (820) spiram: Found 64MBit SPI RAM device[0m
[0;32mI (823) spiram: SPI RAM mode: flash 40m sram 40m[0m
[0;32mI (829) spiram: PSRAM initialized, cache is i

[2019-03-14 15:12:05.716]# RECV ASCII>
n low/high (2-core) mode.[0m
[0;32mI (836) cpu_start: Pro cpu up.[0m
[0;32mI (839) cpu_start: Starting app cpu, entry point is 0x400815a0[0m
[0;32mI (0) cpu_start: App cpu up.[0m


[2019-03-14 15:12:06.576]# RECV ASCII>
[0;32mI (1721) spiram: SPI SRAM memory test OK[0m
[0;32mI (1721) heap_init: Initializing. RAM available for dynamic allocation:[0m
[0;32mI (1722) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM[0m
[0;32mI (1728) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM[0m
[0;32mI (1734) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM[0m
[0;32mI (1740) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM[0m
[0;32mI (1746) heap_init: At 3FFD08F0 len 0000F710 (61 KiB): DRAM[0m
[0;32mI (1753) he

[2019-03-14 15:12:06.626]# RECV ASCII>
ap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM[0m
[0;32mI (1759) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM[0m
[0;32mI (1765) heap_init: At 4009B5FC len 00004A04 (18 KiB): IRAM[0m
[0;32mI (1772) cpu_start: Pro cpu start user code[0m
[0;32mI (1777) spiram: Adding pool of 4096K of external SPI memory to heap allocator[0m
[0;32mI (120) cpu_start: Starting scheduler on PRO CPU.[0m
[0;32mI (0) cpu_start: Starting scheduler on