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

https server based project hits a break point right after start up at cpu_ll_get_cycle_count() (IDFGH-7431) #9008

Closed
ralphde opened this issue May 23, 2022 · 8 comments
Assignees
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally

Comments

@ralphde
Copy link

ralphde commented May 23, 2022

@dobairoland

Environment

ESP32-S2 on custom board

  • IDF version (run git describe --tags to find it):
    // 4.4.1

  • Build System: Elipse plugin latest

  • Compiler version (run xtensa-esp32-elf-gcc --version to find it):
    (crosstool-NG esp-2021r2-patch3) 8.4.0

  • Operating System: win10

  • (Windows only) environment type: ESP Command Prompt and Plain Command Prompt and PowerShell].

  • Using an IDE?: Eclipse 2021-09

  • Power Supply: custom board 3.3V

Problem Description

after performing required steps for creating the DFU as described here []#9003
our https server based project does not run at all any more.
It hits a break point right after start up.
cpu_ll_get_cycle_count()
Looking into that, we assume that this may indicate that the ESP goes directly to sleep?

Again, our code was running before without any error or messages. As well this issue appears before any debug or even main() is hit. How to nail this dead end down?

Are we still having version mismatch issues? if so, how can we locate the issue?

We have tried to change a view things in sdkconfig like RTC watchdog etc. but no success

We flash and debug using esp-prog

sdkconfig.zip

@espressif-bot espressif-bot added the Status: Opened Issue is new label May 23, 2022
@github-actions github-actions bot changed the title custom project stops working after preparing for DFU custom project stops working after preparing for DFU (IDFGH-7431) May 23, 2022
@dobairoland
Copy link
Collaborator

DFU is not supported on ESP32 because it requires native USB support and ESP32 doesn't have it.

@ralphde
Copy link
Author

ralphde commented May 23, 2022

@dobairoland we talking about ESP32-S2 on ESP32-WROVER II and DFU is not related to the issue. I said we flash and debug with esp-prog.

The questions is what to do when a program stalls before app_main()

@dobairoland dobairoland changed the title custom project stops working after preparing for DFU (IDFGH-7431) https server based project hits a break point right after start up at cpu_ll_get_cycle_count() (IDFGH-7431) May 23, 2022
@dobairoland
Copy link
Collaborator

I was mislead by

ESP32 on custom board

I've updated the title to attract the right developers for this issue.

@dobairoland
Copy link
Collaborator

Are you getting the same result after flashing with idf.py flash and idf.py dfu-flash?

Could you share the full output? Maybe share the coredump as well if possible?

Can you try one of the https server examples included in ESP-IDF? Are you getting the same issue? Or can you share a minimal not-working example?

Do you own a publicly available board with ESP32-S2? Are you able to run your project on it?

@ralphde
Copy link
Author

ralphde commented May 25, 2022

@dobairoland

Are you getting the same result after flashing with idf.py flash and idf.py dfu-flash?

We flash via Eclipse Plugin and Jtag only, dfu is not of interest and in any involved in this issue.

Can you try one of the https server examples included in ESP-IDF? Are you getting the same issue? Or can you share a minimal not-working example?

All sample projects work seamlessly on our custom board. Even the original simple https server sample works on our board. Even if we roll back in our GIT before this ominous incident with the tool chain the project works.

Do you own a publicly available board with ESP32-S2? Are you able to run your project on it?

Same on Kaluga, the below output is generated on a Kaluga-1 board

Could you share the full output? Maybe share the coredump as well if possible?

will prepare the coredump, but need to be done using idf.py if I understand correctly. I need some time for this. so far never used idf.py. Finally causing the issue using it.

here the output
`Executing action: monitor
Running idf_monitor in directory c:\esp-ws-202109-17-ii\maxill-https
Executing "C:\Users\ralph.espressif\python_env\idf4.4_py3.10_env\Scripts\python.exe C:_esp-idf-v4.4\tools/idf_monitor.py -p \.\COM18 -b 115200 --toolchain-prefix xtensa-esp32s2-elf- --target esp32s2 --print_filter c:\esp-ws-202109-17-ii\maxill-https\build\maxill-https.elf -m 'C:\Users\ralph.espressif\python_env\idf4.4_py3.10_env\Scripts\python.exe' 'C:_esp-idf-v4.4\tools\idf.py'"...
�[0;33m--- idf_monitor on \.\COM18 115200 ---�[0m
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x22e0
load:0x4004c000,len:0xc94
load:0x40050000,len:0x344c
entry 0x4004c280
I (23) boot: ESP-IDF v4.4.1 2nd stage bootloader
I (24) boot: compile time 11:30:47
D (24) bootloader_flash: XMC chip detected by RDID (00204016), skip.
D (29) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (36) boot: chip revision: 0
D (39) boot.esp32s2: magic e9
D (42) boot.esp32s2: segments 03
D (46) boot.esp32s2: spi_mode 02
D (49) boot.esp32s2: spi_speed 0f
D (52) boot.esp32s2: spi_size 01
I (55) boot.esp32s2: SPI Speed : 80MHz
I (60) boot.esp32s2: SPI Mode : DIO
I (65) boot.esp32s2: SPI Flash Size : 2MB
I (70) boot: Enabling RNG early entropy source...
D (75) bootloader_flash: mmu set paddr=00000000 count=1 size=c00 src_addr=8000 src_addr_aligned=0
D (84) boot: mapped partition table 0x8000 at 0x3f008000
D (89) flash_parts: partition table verified, 4 entries
I (95) boot: Partition Table:
I (98) boot: ## Label Usage Type ST Offset Length
D (106) boot: load partition table entry 0x3f008000
D (111) boot: type=1 subtype=2
I (114) boot: 0 nvs WiFi data 01 02 00009000 00006000
D (121) boot: load partition table entry 0x3f008020
D (126) boot: type=1 subtype=1
I (129) boot: 1 phy_init RF data 01 01 0000f000 00001000
D (137) boot: load partition table entry 0x3f008040
D (142) boot: type=0 subtype=0
I (145) boot: 2 factory factory app 00 00 00010000 00177000
I (153) boot: End of partition table
D (157) boot: Trying partition index -1 offs 0x10000 size 0x177000
D (163) esp_image: reading image header @ 0x10000
D (168) bootloader_flash: mmu set block paddr=0x00010000 (was 0xffffffff)
D (175) esp_image: image header: 0xe9 0x06 0x02 0x01 40023348
V (180) esp_image: loading segment header 0 at offset 0x10018
V (186) esp_image: segment data length 0x2a0bc data starts 0x10020
V (193) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3f000020
I (201) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=2a0bch (172220) map
D (209) esp_image: free data page_count 0x0000003f
D (214) bootloader_flash: mmu set paddr=00010000 count=3 size=2a0bc src_addr=10020 src_addr_aligned=10000
V (258) esp_image: loading segment header 1 at offset 0x3a0dc
D (258) bootloader_flash: mmu set block paddr=0x00030000 (was 0xffffffff)
V (259) esp_image: segment data length 0x3cc4 data starts 0x3a0e4
V (265) esp_image: segment 1 map_segment 0 segment_data_offs 0x3a0e4 load_addr 0x3ffcecb0
I (274) esp_image: segment 1: paddr=0003a0e4 vaddr=3ffcecb0 size=03cc4h ( 15556) load
D (282) esp_image: free data page_count 0x0000003f
D (287) bootloader_flash: mmu set paddr=00030000 count=1 size=3cc4 src_addr=3a0e4 src_addr_aligned=30000
V (300) esp_image: loading segment header 2 at offset 0x3dda8
D (302) bootloader_flash: mmu set block paddr=0x00030000 (was 0xffffffff)
V (309) esp_image: segment data length 0x2268 data starts 0x3ddb0
V (315) esp_image: segment 2 map_segment 0 segment_data_offs 0x3ddb0 load_addr 0x40022000
0x40022000: _WindowOverflow4 at C:/_esp-idf-v4.4/components/freertos/port/xtensa/xtensa_vectors.S:1736

I (324) esp_image: segment 2: paddr=0003ddb0 vaddr=40022000 size=02268h ( 8808) load
D (332) esp_image: free data page_count 0x0000003f
D (337) bootloader_flash: mmu set paddr=00030000 count=2 size=2268 src_addr=3ddb0 src_addr_aligned=30000
V (349) esp_image: loading segment header 3 at offset 0x40018
D (352) bootloader_flash: mmu set block paddr=0x00040000 (was 0xffffffff)
V (359) esp_image: segment data length 0xc6760 data starts 0x40020
V (365) esp_image: segment 3 map_segment 1 segment_data_offs 0x40020 load_addr 0x40080020
0x40080020: _stext at ??:?

I (374) esp_image: segment 3: paddr=00040020 vaddr=40080020 size=c6760h (812896) map
D (382) esp_image: free data page_count 0x0000003f
D (387) bootloader_flash: mmu set paddr=00040000 count=13 size=c6760 src_addr=40020 src_addr_aligned=40000
V (556) esp_image: loading segment header 4 at offset 0x106780
D (556) bootloader_flash: mmu set block paddr=0x00100000 (was 0xffffffff)
V (558) esp_image: segment data length 0x1aa44 data starts 0x106788
V (564) esp_image: segment 4 map_segment 0 segment_data_offs 0x106788 load_addr 0x40024268
0x40024268: heap_caps_calloc at C:/_esp-idf-v4.4/components/heap/heap_caps.c:443

I (572) esp_image: segment 4: paddr=00106788 vaddr=40024268 size=1aa44h (109124) load
D (581) esp_image: free data page_count 0x0000003f
D (586) bootloader_flash: mmu set paddr=00100000 count=3 size=1aa44 src_addr=106788 src_addr_aligned=100000
V (623) esp_image: loading segment header 5 at offset 0x1211cc
D (624) bootloader_flash: mmu set block paddr=0x00120000 (was 0xffffffff)
V (625) esp_image: segment data length 0x10 data starts 0x1211d4
V (631) esp_image: segment 5 map_segment 0 segment_data_offs 0x1211d4 load_addr 0x50000000
I (639) esp_image: segment 5: paddr=001211d4 vaddr=50000000 size=00010h ( 16) load
D (648) esp_image: free data page_count 0x0000003f
D (653) bootloader_flash: mmu set paddr=00120000 count=1 size=10 src_addr=1211d4 src_addr_aligned=120000
V (662) esp_image: image start 0x00010000 end of last section 0x001211e4
D (669) bootloader_flash: mmu set block paddr=0x00120000 (was 0xffffffff)
I (693) boot: Loaded app from partition at offset 0x10000
I (693) boot: Disabling RNG early entropy source...
D (694) boot: Mapping segment 0 as DROM
D (698) boot: Mapping segment 3 as IROM
D (701) boot: calling set_cache_and_start_app
D (706) boot: configure drom and irom and start
V (710) boot: d mmu set paddr=00010000 vaddr=3f000000 size=172220 n=3
V (717) boot: rc=0
V (719) boot: i mmu set paddr=00040000 vaddr=40080000 size=812896 n=13
V (726) boot: rc=0
D (728) boot: start: 0x40023348
0x40023348: call_start_cpu0 at C:/_esp-idf-v4.4/components/esp_system/port/cpu_start.c:267

I (742) cache: Instruction cache : size 8KB, 4Ways, cache line size 32Byte
I�0��╚��<ff ����pu_start: Pro cpu up.
D (745) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 4 bit
D (760) clk: RTC_SLOW_CLK calibration value: 6081855
I (768) cpu_start: Pro cpu start user code
I (768) cpu_start: cpu freq: 160000000
I (768) cpu_start: Application information:
I (773) cpu_start: Project name: maxill-https
I (778) cpu_start: App version: 459a847-dirty
I (784) cpu_start: Compile time: May 25 2022 11:30:31
I (790) cpu_start: ELF file SHA256: deab5843036eb395...
I (796) cpu_start: ESP-IDF: v4.4.1
V (801) memory_layout: reserved range is 0x3f02a0bc - 0x3f02a0dc
D (807) memory_layout: Checking 4 reserved memory ranges:
D (812) memory_layout: Reserved memory range 0x3ff9e000 - 0x3ff9e000
D (819) memory_layout: Reserved memory range 0x3ffb2000 - 0x3ffcecac
D (825) memory_layout: Reserved memory range 0x3ffcecb0 - 0x3ffd7bf8
D (831) memory_layout: Reserved memory range 0x3ffffa10 - 0x40000000
D (838) memory_layout: Building list of available memory regions:
V (844) memory_layout: Examining memory region 0x3ffb2000 - 0x3ffb4000
V (851) memory_layout: Region 0x3ffb2000 - 0x3ffb4000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (859) memory_layout: Examining memory region 0x3ffb4000 - 0x3ffb6000
V (866) memory_layout: Region 0x3ffb4000 - 0x3ffb6000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (875) memory_layout: Examining memory region 0x3ffb6000 - 0x3ffb8000
V (881) memory_layout: Region 0x3ffb6000 - 0x3ffb8000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (890) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffbc000
V (897) memory_layout: Region 0x3ffb8000 - 0x3ffbc000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (906) memory_layout: Examining memory region 0x3ffbc000 - 0x3ffc0000
V (912) memory_layout: Region 0x3ffbc000 - 0x3ffc0000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (921) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc4000
V (928) memory_layout: Region 0x3ffc0000 - 0x3ffc4000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (937) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc8000
V (943) memory_layout: Region 0x3ffc4000 - 0x3ffc8000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (952) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffcc000
V (959) memory_layout: Region 0x3ffc8000 - 0x3ffcc000 inside of reserved 0x3ffb2000 - 0x3ffcecac
V (968) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffd0000
V (974) memory_layout: Start of region 0x3ffcc000 - 0x3ffd0000 overlaps reserved 0x3ffb2000 - 0x3ffcecac
V (984) memory_layout: End of region 0x3ffcecac - 0x3ffd0000 overlaps reserved 0x3ffcecb0 - 0x3ffd7bf8
V (993) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd4000
V (1000) memory_layout: Region 0x3ffd0000 - 0x3ffd4000 inside of reserved 0x3ffcecb0 - 0x3ffd7bf8
V (1009) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd8000
V (1015) memory_layout: Start of region 0x3ffd4000 - 0x3ffd8000 overlaps reserved 0x3ffcecb0 - 0x3ffd7bf8
D (1025) memory_layout: Available memory region 0x3ffd7bf8 - 0x3ffd8000
V (1032) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffdc000
D (1038) memory_layout: Available memory region 0x3ffd8000 - 0x3ffdc000
V (1045) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffe0000
D (1052) memory_layout: Available memory region 0x3ffdc000 - 0x3ffe0000
V (1058) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
D (1065) memory_layout: Available memory region 0x3ffe0000 - 0x3ffe4000
V (1072) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
D (1078) memory_layout: Available memory region 0x3ffe4000 - 0x3ffe8000
V (1085) memory_layout: Examining memory region 0x3ffe8000 - 0x3ffec000
D (1092) memory_layout: Available memory region 0x3ffe8000 - 0x3ffec000
V (1098) memory_layout: Examining memory region 0x3ffec000 - 0x3fff0000
D (1105) memory_layout: Available memory region 0x3ffec000 - 0x3fff0000
V (1112) memory_layout: Examining memory region 0x3fff0000 - 0x3fff4000
D (1119) memory_layout: Available memory region 0x3fff0000 - 0x3fff4000
V (1125) memory_layout: Examining memory region 0x3fff4000 - 0x3fff8000
D (1132) memory_layout: Available memory region 0x3fff4000 - 0x3fff8000
V (1139) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (1145) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (1152) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
V (1159) memory_layout: End of region 0x3fffc000 - 0x40000000 overlaps reserved 0x3ffffa10 - 0x40000000
D (1168) memory_layout: Available memory region 0x3fffc000 - 0x3ffffa10
V (1175) memory_layout: Examining memory region 0x3ff9e000 - 0x3ffa0000
D (1181) memory_layout: Available memory region 0x3ff9e000 - 0x3ffa0000
I (1188) heap_init: Initializing. RAM available for dynamic allocation:
D (1196) heap_init: New heap initialised at 0x3ffd7bf8
I (1201) heap_init: At 3FFD7BF8 len 00024408 (145 KiB): DRAM
I (1207) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
D (1213) heap_init: New heap initialised at 0x3ff9e000
I (1218) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
D (1225) FLASH_HAL: extra_dummy: 0
Guru Meditation Error: Core 0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40146758: 000000f0 7d006136 03ea2001
0x40146758: should_output at C:/_esp-idf-v4.4/components/log/log.c:289

Setting breakpoint at 0x4014675e and returning...
0x4014675e: cpu_ll_get_cycle_count at C:/_esp-idf-v4.4/components/hal/esp32s2/include/hal/cpu_ll.h:37
`

@ESP-Marius
Copy link
Collaborator

ESP-Marius commented May 26, 2022

@ralphde I think I see what's happening here.

In memspi_host_read_id_hs it tries to print some status due to you having specified verbose logging and while logging it tries to use cpu_ll_get_cycle_count to timestamp the message.

The issue is that during memspi_host_read_id_hs the cache is disabled, so flash cannot be accessed. Normally this wouldnt be an issue since cpu_ll_get_cycle_count gets inlined, but since we are compiling with -O0 this optimization is not done and the function ends up in flash, therefor causing a crash when accessed.

You can try to change static inline uint32_t cpu_ll_get_cycle_count(void) to static inline uint32_t IRAM_ATTR cpu_ll_get_cycle_count(void) in components/hal/esp32s2/include/hal/cpu_ll.h (or apply the patch I attached). This seemed to have solved the issue on my end at least.

I'll submit a bugfix for this.

0001-Place-cpu_ll_get_cycle_count-in-IRAM.txt

@espressif-bot espressif-bot added Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Opened Issue is new Resolution: NA Issue resolution is unavailable labels May 27, 2022
@ralphde
Copy link
Author

ralphde commented May 27, 2022

@ESP-Marius it worked for me. However, if I understand right it should work as well when I change compiler optimization level back to -Os or -Og and log level to 'info'. But that does not work and has the same effect. So this I don't understand.
And can you confirm that this will be notified as a bug and will be fixed in future releases?
I also don't understand why there are not more users affected by this bug.

@ESP-Marius
Copy link
Collaborator

Yes, changing to -Og should fix it if my analysis is correct. Just tested it again myself, and as far as I could tell compiling with -Og does fix it. Maybe the new setting wasn't applied properly when you tested it?

The fix has already been merged to our internal master branch (9177e9f) and it will be backported to v4.4 and v4.3. This topic should be automatically update and closed as soon as this commit is synced to Github (happens when our internal CI passes all tests)

As for why nobody else noticed this: my guess is that the combination of of verbose logging (too noisy for most people) and -O0 is pretty rare.

@ralphde ralphde closed this as completed May 28, 2022
espressif-bot pushed a commit that referenced this issue May 30, 2022
espressif-bot pushed a commit that referenced this issue Jun 22, 2022
espressif-bot pushed a commit that referenced this issue Jun 26, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally
Projects
None yet
Development

No branches or pull requests

4 participants