ESP32S3 Espressif sysview with FreeRTOS multicore does not work (IDFGH-11368) (OCD-871)

[TiboDevC]

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.

General issue report

General issue report

I try to use the Espressif sysview to debug a memory leak. Here is the Espressif documentation about sysview:
https://docs.espressif.com/projects/esp-idf/en/v5.1.1/esp32s3/api-reference/system/heap_debug.html#host-based-mode

This example works well when FreeRTOS is configured to run on a single core but does not work when it runs on dual core.

Environment

• ESP32S3
• Espressif SDK v5.1.1
• openocd v0.12.0-esp32-20230921 (2023-09-21-13:41)
• xtensa-esp32s3-elf-gdb 12.1_20221002

Demo code

Working example

The Espressif example works well, here is an example code:
https://github.com/TiboDevC/esp32_heap_tracing/tree/master

Non-working example

The only difference with the working one is Run FreeRTOS only on first core is unchecked in menuconfig
https://github.com/TiboDevC/esp32_heap_tracing/tree/freertos_multi_core

Steps to reproduce

Flash one of the above example code, then:

# Run openocd
openocd -f board/esp32s3-builtin.cfg

# In another terminal, run gdb with the `gdbinit` described as above in github links
xtensa-esp32s3-elf-gdb -x gdbinit ./build/heap-trace-host-example.elf

logs when it works

$ xtensa-esp32s3-elf-gdb -x gdbinit ./build/heap-trace-host-example.elf 
GNU gdb (esp-gdb) 12.1_20221002
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-linux-gnu --target=xtensa-esp-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./build/heap-trace-host-example.elf...
warning: multi-threaded target stopped without sending a thread-id, using first non-exited thread
[Switching to Thread 1070174560]
0x40379b46 in esp_cpu_wait_for_intr () at /home/myUserName/esp/esp-idf/components/esp_hw_support/cpu.c:121
121 }
JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
[esp32s3.cpu0] requesting target halt and executing a soft reset
[esp32s3.cpu0] Debug controller was reset.
[esp32s3.cpu0] Core was reset.
[esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
[esp32s3.cpu0] Reset cause (3) - (Software core reset)
[esp32s3.cpu1] requesting target halt and executing a soft reset
[esp32s3.cpu0] Core was reset.
[esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
[esp32s3.cpu1] Debug controller was reset.
[esp32s3.cpu1] Core was reset.
[esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
[esp32s3.cpu1] Reset cause (3) - (Software core reset)
[esp32s3.cpu0] Reset cause (3) - (Software core reset)
Temporary breakpoint 1 at 0x420063cc: file /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c, line 36.
Note: automatically using hardware breakpoints for read-only addresses.
Temporary breakpoint 2 at 0x420063e4: file /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c, line 48.
[esp32s3.cpu0] Target halted, PC=0x420063CC, debug_reason=00000001
Set GDB target to 'esp32s3.cpu0'
[esp32s3.cpu1] Target halted, PC=0x40043A3B, debug_reason=00000000
[New Thread 1070171712]
[New Thread 1070174876]
[New Thread 1070167172]
[Switching to Thread 1070171712]

Thread 4 "main" hit Temporary breakpoint 1, heap_trace_start (mode_param=(HEAP_TRACE_LEAKS | unknown: 0x2)) at /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c:36
36  {
Total trace memory: 16384 bytes
Open file /tmp/heap_cpu0.svdat
Open file /tmp/heap_cpu1.svdat
App trace params: from 2 cores, size 4294967295 bytes, stop_tmo -1 s, poll period 0 ms, wait_rst 0, skip 0 bytes
Connect targets...
Targets connected.
243 
488 
732 
965

[...]

144365 
144620 
[esp32s3.cpu0] Target halted, PC=0x420063E4, debug_reason=00000001
Set GDB target to 'esp32s3.cpu0'
[esp32s3.cpu1] Target halted, PC=0x40043A3B, debug_reason=00000000

Thread 4 "main" hit Temporary breakpoint 2, heap_trace_stop () at /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c:48
48  {
Resume targets
144875 
145130 
145385 

[...]

159473 
Disconnect targets...
[esp32s3.cpu0] Target halted, PC=0x40379B46, debug_reason=00000000
Set GDB target to 'esp32s3.cpu0'
[esp32s3.cpu1] Target halted, PC=0x40043A3B, debug_reason=00000000
Targets disconnected.
Tracing is STOPPED. Size is 159473 of -1 @ 16.663260 (15.229976) KiB/s
Data: blocks incomplete 0, lost bytes: 0
Block read time [107.640999..125.821991] ms
Block proc time [0.076000..0.101000] ms

logs when it does not work

10:11:22 myUserName@myUserName-pc:~/esp32_heap_tracing (freertos_multi_core)
$ xtensa-esp32s3-elf-gdb -x gdbinit ./build/heap-trace-host-example.elf 
GNU gdb (esp-gdb) 12.1_20221002
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-linux-gnu --target=xtensa-esp-elf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./build/heap-trace-host-example.elf...
warning: multi-threaded target stopped without sending a thread-id, using first non-exited thread
[Switching to Thread 1070174876]
0x4037ac3a in esp_cpu_wait_for_intr () at /home/myUserName/esp/esp-idf/components/esp_hw_support/cpu.c:121
121	}
JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
[esp32s3.cpu0] requesting target halt and executing a soft reset
[esp32s3.cpu0] Debug controller was reset.
[esp32s3.cpu0] Core was reset.
[esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
[esp32s3.cpu0] Reset cause (3) - (Software core reset)
[esp32s3.cpu1] requesting target halt and executing a soft reset
[esp32s3.cpu0] Core was reset.
[esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
[esp32s3.cpu1] Debug controller was reset.
[esp32s3.cpu1] Core was reset.
[esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
[esp32s3.cpu1] Reset cause (3) - (Software core reset)
[esp32s3.cpu0] Reset cause (3) - (Software core reset)
Temporary breakpoint 1 at 0x42006a78: file /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c, line 36.
Note: automatically using hardware breakpoints for read-only addresses.
Temporary breakpoint 2 at 0x42006a90: file /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c, line 48.
[esp32s3.cpu0] Target halted, PC=0x42006A78, debug_reason=00000001
Set GDB target to 'esp32s3.cpu0'
[esp32s3.cpu1] Target halted, PC=0x4037AC3A, debug_reason=00000000
[New Thread 1070187388]
[New Thread 1070193716]
[New Thread 1070190552]
[New Thread 1070178296]
[New Thread 1070182740]
[New Thread 1070175900]
[Switching to Thread 1070187388]

Thread 4 "main" hit Temporary breakpoint 1, heap_trace_start (mode_param=(HEAP_TRACE_LEAKS | unknown: 0x2)) at /home/myUserName/esp/esp-idf/components/app_trace/heap_trace_tohost.c:36
36	{
Total trace memory: 16384 bytes
Open file /tmp/heap_cpu0.svdat
Open file /tmp/heap_cpu1.svdat
App trace params: from 2 cores, size 4294967295 bytes, stop_tmo -1 s, poll period 0 ms, wait_rst 0, skip 0 bytes
Connect targets...
Targets connected.

It is stuck here. When I break with gdb:

^C[esp32s3.cpu0] Target halted, PC=0x4037EBE8, debug_reason=00000000
Set GDB target to 'esp32s3.cpu0'
[esp32s3.cpu1] Target halted, PC=0x4037EBFA, debug_reason=00000000

Thread 4 "main" received signal SIGINT, Interrupt.
spinlock_acquire (timeout=-1, lock=0x3fc9409c <xKernelLock>) at /home/myUserName/esp/esp-idf/components/esp_hw_support/include/spinlock.h:112
112	        lock_set = esp_cpu_compare_and_set(&lock->owner, SPINLOCK_FREE, core_id);

it seems to be stuck in this function.

I tried also with Espressif v5.2-dev but same result.

Is it a bug or a miss-configuration?

[erhankur]

@TiboDevC It should work. I will test it and turn back.

But one thing strange to me, you started sysview in both modes with the below command, right?

mon esp sysview start file:///tmp/heap_cpu0.svdat file:///tmp/heap_cpu1.svdat

For the single mode it should be like mon esp sysview start file:///tmp/heap_cpu0.svdat

[erhankur]

OK looks like we have an issue with double core sysview. Also, we have an issue in OpenOCD to understand if 2nd core is disabled or not.

In single core mode, you can run OpenOCD like this

openocd -c "set ESP32_S3_ONLYCPU 1" -f board/esp32s3-builtin.cfg

and then no need to mention about 2nd file

mon esp sysview start file:///tmp/heap_cpu.svdat

I will have a look both issues and let you know.

[TiboDevC]

@TiboDevC It should work. I will test it and turn back.

But one thing strange to me, you started sysview in both modes with the below command, right?

mon esp sysview start file:///tmp/heap_cpu0.svdat file:///tmp/heap_cpu1.svdat

For the single mode it should be like mon esp sysview start file:///tmp/heap_cpu0.svdat

yes, I could have started it with a single file for the single core, right.
Thanks for having a look!

[erhankur]

@TiboDevC can you try again with the latest idf-master branch and openocd master branch?

I gave another try now and looks like it works.

I (179) cpu_start: Multicore app
I (189) cpu_start: Pro cpu start user code
I (189) cpu_start: cpu freq: 160000000 Hz
I (189) app_init: Application information:
I (189) app_init: Project name:     sysview_tracing_heap_log
I (194) app_init: App version:      v5.3-dev-2032-g4d90eedb6e-dirty
I (200) app_init: Compile time:     Feb 13 2024 21:48:23
I (205) app_init: ELF file SHA256:  3448a2978...
I (210) app_init: ESP-IDF:          v5.3-dev-2032-g4d90eedb6e-dirty
I (216) app_init: Min chip rev:     v0.0
I (219) app_init: Max chip rev:     v0.99 
I (223) app_init: Chip rev:         v0.1
I (227) heap_init: Initializing. RAM available for dynamic allocation:

Open On-Chip Debugger v0.12.0-esp32-20230921-271-gc400745e-dirty (2024-02-13-19:18)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
0
Info : only one transport option; autoselecting 'jtag'
Info : esp_usb_jtag: VID set to 0x303a and PID to 0x1001
Info : esp_usb_jtag: capabilities descriptor set to 0x2000
WARNING!!! OpenOCD binary version (Open On-Chip Debugger v0.12.0-esp32-20230921-271-gc400745e-dirty (2024-02-13-19:18)) doesn't match the .cfg file version (v0.12.0-esp32-20230419)
WARNING: ESP flash support is disabled!
WARNING: ESP flash support is disabled!
force hard breakpoints
Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : esp_usb_jtag: serial (7C:DF:A1:E1:19:00)
Info : esp_usb_jtag: Device found. Base speed 40000KHz, div range 1 to 255
Info : clock speed 40000 kHz
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] Examination succeed
Info : [esp32s3.cpu1] Examination succeed
Info : starting gdb server for esp32s3.cpu0 on 3333
Info : Listening on port 3333 for gdb connections
Info : [esp32s3.cpu0] Target halted, PC=0x4037AD52, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (21) - (USB UART reset)
Info : [esp32s3.cpu1] Target halted, PC=0x4037AD52, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (21) - (USB UART reset)
Info : accepting 'telnet' connection on tcp/4444
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Target halted, PC=0x4037AD52, debug_reason=00000000
Info : Set GDB target to 'esp32s3.cpu0'
Info : [esp32s3.cpu1] Target halted, PC=0x4037AD52, debug_reason=00000000
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x403CD669, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] Target halted, PC=0x40043A3B, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : accepting 'gdb' connection on tcp/3333
Info : [esp32s3.cpu0] Target halted, PC=0x4037AD52, debug_reason=00000000
Info : [esp32s3.cpu1] Target halted, PC=0x4037AD52, debug_reason=00000000
Warn : No symbols for FreeRTOS!
Info : New GDB Connection: 1, Target esp32s3.cpu0, state: halted
Warn : Prefer GDB command "target extended-remote :3333" instead of "target remote :3333"
Info : Detected FreeRTOS version: (10.5.1)
Info : JTAG tap: esp32s3.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32s3.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : [esp32s3.cpu0] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Debug controller was reset.
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x500000EF, debug_reason=00000000
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu1] requesting target halt and executing a soft reset
Info : [esp32s3.cpu0] Core was reset.
Info : [esp32s3.cpu0] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Debug controller was reset.
Info : [esp32s3.cpu1] Core was reset.
Info : [esp32s3.cpu1] Target halted, PC=0x40000400, debug_reason=00000000
Info : [esp32s3.cpu1] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Reset cause (3) - (Software core reset)
Info : [esp32s3.cpu0] Target halted, PC=0x420080D0, debug_reason=00000001
Info : Set GDB target to 'esp32s3.cpu0'
Info : [esp32s3.cpu1] Target halted, PC=0x4037AD52, debug_reason=00000000
Info : Detected FreeRTOS version: (10.5.1)
Info : Total trace memory: 16384 bytes
Info : Open file /tmp/heap_cpu0.svdat
Info : Open file /tmp/heap_cpu1.svdat
App trace params: from 2 cores, size 4294967295 bytes, stop_tmo -1 s, poll period 0 ms, wait_rst 0, skip 0 bytes
Connect targets...
Info : Targets connected.
Info : [esp32s3.cpu0] Target halted, PC=0x4037D298, debug_reason=00000000
Info : Set GDB target to 'esp32s3.cpu0'
Info : [esp32s3.cpu1] Target halted, PC=0x400559E0, debug_reason=00000000
Info : dropped 'gdb' connection