Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[TW#27580] strange behavior on reset #2731

Closed
chegewara opened this issue Nov 23, 2018 · 4 comments
Closed

[TW#27580] strange behavior on reset #2731

chegewara opened this issue Nov 23, 2018 · 4 comments

Comments

@chegewara
Copy link
Contributor

chegewara commented Nov 23, 2018

I just end with OTA over BLE example and it is running fine, but after ota flashing i have very strange behavior. As first app to ota flash i have hello-world from esp-idf examples. No modifications at all. After updating esp32 code is running fine and after 10 seconds loop esp32 restart but not always is starting again. Here is log:

Hello world!
This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, silicon revision 0, 4MB external flash
Restarting in 10 seconds...
Restarting in 9 seconds...
Restarting in 8 seconds...
Restarting in 7 seconds...
Restarting in 6 seconds...
Restarting in 5 seconds...
Restarting in 4 seconds...
Restarting in 3 seconds...
Restarting in 2 seconds...
Restarting in 1 seconds...
Restarting in 0 seconds...
Restarting now.
ets Jun  8 2016 00:22:57

rst:0xc (SW_CPU_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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6304
ho 0 tail 12 room 4
load:0x40078000,len:10168
ho 0 tail 12 room 4
load:0x40080400,len:6612
entry 0x40080764
I (32) boot: ESP-IDF v3.2-beta1-34-gfb7ba1baa-dirty 2nd stage bootloader
I (32) boot: compile time 13:43:57
I (34) boot: Enabling RNG early entropy source...
I (39) boot: SPI Speed      : 40MHz
I (43) boot: SPI Mode       : DIO
I (47) boot: SPI Flash Size : 4MB
I (52) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (70) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (77) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (85) boot:  3 ota_0            OTA app          00 10 00010000 001c2000
I (92) boot:  4 ota_1            OTA app          00 11 001e0000 001c2000
I (100) boot: End of partition table
I (104) esp_image: segment 0: paddr=0x001e0020 vaddr=0x3f400020 size=0x07574 ( 30068) map
I (119) esp_image: segment 1: paddr=0x001e759c vaddr=0x3ff80000 size=0x00000 (     0) load
I (122) esp_image: segment 2: paddr=0x001e75a4 vaddr=0x3ff80000 size=0x00000 (     0) load
I (131) esp_image: segment 3: paddr=0x001e75ac vaddr=0x3ffb0000 size=0x01e94 (  7828) load
I (141) esp_image: segment 4: paddr=0x001e9448 vaddr=0x3ffb1e94 size=0x00000 (     0) load
I (149) esp_image: segment 5: paddr=0x001e9450 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at D:/msys32/home/imper/esp/esp-idf/components/freertos/xtensa_ve
ctors.S:1685

I (158) esp_image: segment 6: paddr=0x001e9858 vaddr=0x40080400 size=0x067b8 ( 26552) load
I (172) esp_image: segment 7: paddr=0x001f0018 vaddr=0x400d0018 size=0x1240c ( 74764) map
0x400d0018: _flash_cache_start at ??:?

I (190) esp_image: segment 8: paddr=0x0020242c vaddr=0x40086bb8 size=0x028e0 ( 10464) load
0x40086bb8: spi_flash_phys2cache at D:/msys32/home/imper/esp/esp-idf/components/spi_flash/flas
h_mmap.c:319

I (193) esp_image: segment 9: paddr=0x00204d14 vaddr=0x400c0000 size=0x00000 (     0) load
I (197) esp_image: segment 10: paddr=0x00204d1c vaddr=0x50000000 size=0x00000 (     0) load
I (206) esp_image: segment 11: paddr=0x00204d24 vaddr=0x50000000 size=0x00000 (     0) load
I (217) boot: Loaded app from partition at offset 0x1e0000
I (221) boot: Disabling RNG early entropy source...
I (227) cpu_start: Pro cpu up.
I (230) cpu_start: Starting app cpu, entry point is 0x40080ea4
I (210) cpu_start: App cpu up.
I (241) heap_init: Initializing. RAM available for dynamic allocation:
I (248) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (254) heap_init: At 3FFB2EE0 len 0002D120 (180 KiB): DRAM
I (260) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (266) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (273) heap_init: At 40089498 len 00016B68 (90 KiB): IRAM
I (279) cpu_start: Pro cpu start user code
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6304
ho 0 tail 12 room 4
load:0x40078000,len:10168
ho 0 tail 12 room 4
load:0x40080400,len:6612
entry 0x40080764
I (32) boot: ESP-IDF v3.2-beta1-34-gfb7ba1baa-dirty 2nd stage bootloader
I (32) boot: compile time 13:43:57
I (34) boot: Enabling RNG early entropy source...
I (39) boot: SPI Speed      : 40MHz
I (43) boot: SPI Mode       : DIO
I (47) boot: SPI Flash Size : 4MB
I (51) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (70) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (77) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  3 ota_0            OTA app          00 10 00010000 001c2000
I (92) boot:  4 ota_1            OTA app          00 11 001e0000 001c2000
I (99) boot: End of partition table
I (104) esp_image: segment 0: paddr=0x001e0020 vaddr=0x3f400020 size=0x07574 ( 30068) map
I (118) esp_image: segment 1: paddr=0x001e759c vaddr=0x3ff80000 size=0x00000 (     0) load
I (121) esp_image: segment 2: paddr=0x001e75a4 vaddr=0x3ff80000 size=0x00000 (     0) load
I (130) esp_image: segment 3: paddr=0x001e75ac vaddr=0x3ffb0000 size=0x01e94 (  7828) load
I (141) esp_image: segment 4: paddr=0x001e9448 vaddr=0x3ffb1e94 size=0x00000 (     0) load
I (148) esp_image: segment 5: paddr=0x001e9450 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at D:/msys32/home/imper/esp/esp-idf/components/freertos/xtensa_ve
ctors.S:1685

I (157) esp_image: segment 6: paddr=0x001e9858 vaddr=0x40080400 size=0x067b8 ( 26552) load
I (172) esp_image: segment 7: paddr=0x001f0018 vaddr=0x400d0018 size=0x1240c ( 74764) map
0x400d0018: _flash_cache_start at ??:?

I (190) esp_image: segment 8: paddr=0x0020242c vaddr=0x40086bb8 size=0x028e0 ( 10464) load
0x40086bb8: spi_flash_phys2cache at D:/msys32/home/imper/esp/esp-idf/components/spi_flash/flas
h_mmap.c:319

I (192) esp_image: segment 9: paddr=0x00204d14 vaddr=0x400c0000 size=0x00000 (     0) load
I (196) esp_image: segment 10: paddr=0x00204d1c vaddr=0x50000000 size=0x00000 (     0) load
I (205) esp_image: segment 11: paddr=0x00204d24 vaddr=0x50000000 size=0x00000 (     0) load
I (216) boot: Loaded app from partition at offset 0x1e0000
I (221) boot: Disabling RNG early entropy source...
I (226) cpu_start: Pro cpu up.
I (230) cpu_start: Starting app cpu, entry point is 0x40080ea4
I (0) cpu_start: App cpu up.
I (240) heap_init: Initializing. RAM available for dynamic allocation:
I (247) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (253) heap_init: At 3FFB2EE0 len 0002D120 (180 KiB): DRAM
I (259) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (266) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (272) heap_init: At 40089498 len 00016B68 (90 KiB): IRAM
I (278) cpu_start: Pro cpu start user code
ets Jun  8 2016 00:22:57

rst:0x10 (RTCWDT_RTC_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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:6304
ho 0 tail 12 room 4
load:0x40078000,len:10168
ho 0 tail 12 room 4
load:0x40080400,len:6612
entry 0x40080764
I (32) boot: ESP-IDF v3.2-beta1-34-gfb7ba1baa-dirty 2nd stage bootloader
I (32) boot: compile time 13:43:57
I (34) boot: Enabling RNG early entropy source...
I (39) boot: SPI Speed      : 40MHz
I (43) boot: SPI Mode       : DIO
I (47) boot: SPI Flash Size : 4MB
I (51) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (69) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (77) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  3 ota_0            OTA app          00 10 00010000 001c2000
I (92) boot:  4 ota_1            OTA app          00 11 001e0000 001c2000
I (99) boot: End of partition table
I (104) esp_image: segment 0: paddr=0x001e0020 vaddr=0x3f400020 size=0x07574 ( 30068) map
I (118) esp_image: segment 1: paddr=0x001e759c vaddr=0x3ff80000 size=0x00000 (     0) load
I (121) esp_image: segment 2: paddr=0x001e75a4 vaddr=0x3ff80000 size=0x00000 (     0) load
I (130) esp_image: segment 3: paddr=0x001e75ac vaddr=0x3ffb0000 size=0x01e94 (  7828) load
I (141) esp_image: segment 4: paddr=0x001e9448 vaddr=0x3ffb1e94 size=0x00000 (     0) load
I (148) esp_image: segment 5: paddr=0x001e9450 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at D:/msys32/home/imper/esp/esp-idf/components/freertos/xtensa_ve
ctors.S:1685

I (157) esp_image: segment 6: paddr=0x001e9858 vaddr=0x40080400 size=0x067b8 ( 26552) load
I (172) esp_image: segment 7: paddr=0x001f0018 vaddr=0x400d0018 size=0x1240c ( 74764) map
0x400d0018: _flash_cache_start at ??:?

I (190) esp_image: segment 8: paddr=0x0020242c vaddr=0x40086bb8 size=0x028e0 ( 10464) load
0x40086bb8: spi_flash_phys2cache at D:/msys32/home/imper/esp/esp-idf/components/spi_flash/flas
h_mmap.c:319

I (192) esp_image: segment 9: paddr=0x00204d14 vaddr=0x400c0000 size=0x00000 (     0) load
I (196) esp_image: segment 10: paddr=0x00204d1c vaddr=0x50000000 size=0x00000 (     0) load
I (205) esp_image: segment 11: paddr=0x00204d24 vaddr=0x50000000 size=0x00000 (     0) load
I (216) boot: Loaded app from partition at offset 0x1e0000
I (221) boot: Disabling RNG early entropy source...
I (226) cpu_start: Pro cpu up.
I (230) cpu_start: Starting app cpu, entry point is 0x40080ea4
I (0) cpu_start: App cpu up.
I (240) heap_init: Initializing. RAM available for dynamic allocation:
I (247) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (253) heap_init: At 3FFB2EE0 len 0002D120 (180 KiB): DRAM
I (259) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (266) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (272) heap_init: At 40089498 len 00016B68 (90 KiB): IRAM
I (278) cpu_start: Pro cpu start user code
I (73) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
Hello world!
This is ESP32 chip with 2 CPU cores, WiFi/BT/BLE, silicon revision 0, 4MB external flash
Restarting in 10 seconds...
Restarting in 9 seconds...
Restarting in 8 seconds...
Restarting in 7 seconds...
Restarting in 6 seconds...
Restarting in 5 seconds...
Restarting in 4 seconds...
Restarting in 3 seconds...
Restarting in 2 seconds...
Restarting in 1 seconds...
Restarting in 0 seconds...

Usually its only one "empty" restart and next time is running fine (no interaction from my side). In this log we can see 2 "empty"restarts, First SW_CPU_RESET and then RTCWDT_RTC_RESET.

my esp32 is devKitC v2

@Alvin1Zhang Alvin1Zhang changed the title strange behavior on reset [TW#27580] strange behavior on reset Nov 23, 2018
@KonstantinKondrashov
Copy link
Collaborator

Hi @chegewara. This behavior is not right. I can assume that this is happening due to some kind of settings in sdkconfig.
Could you send two sdkconfig:

  • for bootloader (first application)
  • for hello_world

Also, I have some question:

  1. Does this happen only in the first boot or randomly after first boot?
  2. In 3 ota_0 00010000 have app which downloaded hello_world to 4 ota_1 001e0000. Is it right?
  3. How much time between these two logs? (approximately)
I (279) cpu_start: Pro cpu start user code
ets Jun  8 2016 00:22:57
<------Time?------->
rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)

@chegewara
Copy link
Contributor Author

  1. It does happen every time on first boot.
  2. Yes.
  3. I dont remember.

if i remember hello-world was compiled with release/v3.1 branch with default config

https://gist.github.com/chegewara/9fed4a6fdc2678c4cd3f6a0bfba10093

@KonstantinKondrashov
Copy link
Collaborator

Thank @chegewara for your report. I was able to reproduce your error. I will try to find a solution. The reason is different CPU frequency in two configurations.

  • hello_world - CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ=160
  • bootloader - CONFIG_ESP32_DEFAULT_CPU_FREQ_MHZ=240

It reproduced on master branch as well.

@chegewara
Copy link
Contributor Author

Good catch, i wouldnt find it myself.

@igrr igrr closed this as completed in 178e5b2 Feb 28, 2019
igrr added a commit that referenced this issue Feb 28, 2019
In the situation when bootloader was compiled for 240MHz, and app was
compiled for 160MHz, and the chip is a revision 0 chip, the
bootloader will assume that the application has also been running at
240MHz. This will cause the chip to lock up later. Modify this to use
a run time check of DPORT_CPUPERIOD_SEL, which indicates which of the
PLL frequencies was used.

Closes #2731.
igrr added a commit that referenced this issue Mar 1, 2019
In the situation when bootloader was compiled for 240MHz, and app was
compiled for 160MHz, and the chip is a revision 0 chip, the
bootloader will assume that the application has also been running at
240MHz. This will cause the chip to lock up later. Modify this to use
a run time check of DPORT_CPUPERIOD_SEL, which indicates which of the
PLL frequencies was used.

Closes #2731.
catalinio pushed a commit to catalinio/pycom-esp-idf that referenced this issue Jun 28, 2019
In the situation when bootloader was compiled for 240MHz, and app was
compiled for 160MHz, and the chip is a revision 0 chip, the
bootloader will assume that the application has also been running at
240MHz. This will cause the chip to lock up later. Modify this to use
a run time check of DPORT_CPUPERIOD_SEL, which indicates which of the
PLL frequencies was used.

Closes espressif/esp-idf#2731.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants