CPU Startup Fails When Using Heap Task Tracking

[NevynSelby]

MCU: ESP32 Pico D4
IDF: 5.5

I am attempting to track a heap issue in the application we develop. I noticed in the recent release we can track heap usage on a per task basis.

I have deployed the example code https://github.com/espressif/esp-idf/tr ... g/advanced to the board and this works fine.

Next step is to enable the trace facility in out application by setting the CONFIG_HEAP_TASK_TRACKING variable and to add code to dump the heap task information.

When I do this I find that the system fails to start crashing almost immediately.

Using the back trace I see the following:

Code: Select all

0x40091d86: xTaskCheckForTimeOut at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4178
0x40090263: xQueueSemaphoreTake at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:1812
0x400d5371: heap_caps_update_per_task_info_alloc at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:279
0x400d5994: heap_caps_aligned_alloc_base at /Users/username/esp/esp-idf/components/heap/heap_caps_base.c:179 (discriminator 2)
0x400d59b9: heap_caps_malloc_base at /Users/username/esp/esp-idf/components/heap/heap_caps_base.c:202
0x400d40e1: heap_caps_malloc at /Users/username/esp/esp-idf/components/heap/heap_caps.c:84
0x40090889: pvPortMalloc at /Users/username/esp/esp-idf/components/freertos/heap_idf.c:55
0x4008feb3: xQueueGenericCreate at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:545
0x40090078: xQueueCreateMutex at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:669
0x4009438f: esp_log_impl_lock_timeout at /Users/username/esp/esp-idf/components/log/src/os/log_lock.c:37
0x401ac963: log_level_get at /Users/username/esp/esp-idf/components/log/src/log_level/tag_log_level/tag_log_level.c:65
0x4009447a: esp_log_level_get_timeout at /Users/username/esp/esp-idf/components/log/src/log_level/tag_log_level/tag_log_level.c:102
0x400d3e95: esp_log_is_tag_loggable at /Users/username/esp/esp-idf/components/log/src/log_level/log_level.c:53
0x40094343: esp_log_va at /Users/username/esp/esp-idf/components/log/src/log.c:41 (discriminator 1)
 (inlined by) esp_log at /Users/username/esp/esp-idf/components/log/src/log.c:88 (discriminator 1)
0x400d5251: create_new_heap_stats_entry at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:118 (discriminator 1)
 (inlined by) create_new_task_stats_entry at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:213 (discriminator 1)
0x400d53a1: heap_caps_update_per_task_info_alloc at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:319
0x400d4593: heap_caps_init at /Users/username/esp/esp-idf/components/heap/heap_caps_init.c:211 (discriminator 2)
0x400d45f3: __esp_system_init_fn_init_heap at /Users/username/esp/esp-idf/components/heap/heap_caps_init.c:27
0x400d34db: do_system_init_fn at /Users/username/esp/esp-idf/components/esp_system/startup.c:132
0x400d350e: do_core_init at /Users/username/esp/esp-idf/components/esp_system/startup.c:170
 (inlined by) start_cpu0_default at /Users/username/esp/esp-idf/components/esp_system/startup.c:203
0x40081121: call_start_cpu0 at /Users/username/esp/esp-idf/components/esp_system/port/cpu_start.c:836 (discriminator 1)
0x40079236: ?? ??:0

The only non-standard thing I have done is to place the heap code into flash as we are running low on IRAM.

Any thoughts on where I go diagnosing this issue?

Regards,
Mark

[MicroController]

crashing almost immediately.

It'd be helpful to know what error/panic/"crash" you are getting...

However, the backtrace indicates that the error is related to this line:

Code: Select all

ESP_LOGE(TAG, "Could not allocate memory to add new task statistics");

This may be a problem for at least 2 reasons:
1) The logging seems to try to allocate some memory on the heap - which isn't a good idea when the log message is trying to convey that there's no more heap memory available.
2) When the heap trace facility, upon a memory allocation, tries to use logging, which then does a memory allocation, we may end up in an infinite recursion, or some kind of deadlock.

So your problem may be that you're still/already out of heap memory at this early stage.

Another thing is the potential recursion between alloc and log via the trace facility. Maybe this could be fixed by using "ESP_EARLY_LOGx: Designed for use in constrained environments during early startup, ..."

[NevynSelby]

what error/panic/"crash" you are getting

Sorry, thought I had included that information, the error is

Code: Select all

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

I'm not sure how much memory is available at that stage but I know when the application starts under normal circumstances we have about 225 Kbytes available on the heap. Looking at the log output we look to have set the heap up:

Code: Select all

I (514) app_init: ESP-IDF:          v5.5-beta1-215-gcf8dad0746
I (520) efuse_init: Min chip rev:     v0.0
I (524) efuse_init: Max chip rev:     v3.99 
I (528) efuse_init: Chip rev:         v1.0
I (532) heap_init: Initializing. RAM available for dynamic allocation:
I (538) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (543) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (548) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (553) heap_init: At 3FFCBBF0 len 00014410 (81 KiB): DRAM
I (558) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (564) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (569) heap_init: At 4009D168 len 00002E98 (11 KiB): IRAM

I know we use the heap intensively but this is indicating that we are in system startup when this error occurs.

Regards,
Mark

[MicroController]

Code: Select all

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Without seeing the register dump, I'd wager a guess that there's a null pointer being used.

Also, the scheduler seems not to be started yet at this stage, so things like xQueueSemaphoreTake() may not yet be operational.

You could try modifying line 118 of heap_task_info.c and replace ESP_LOGE with ESP_EARLY_LOGE to see if that changes anything.

Edit:
Error seems to happen at this line in FreeRTOS, where it tries to access the 'current' task, which apparently doesn't exist because FreeRTOS isn't started yet.

[NevynSelby]

So is this looking like an issue in IDF ?

BTW: Full trace is:

Code: Select all

ELF file SHA256: f9920dd7d9c93279

Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_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:0x3fff0030,len:296
load:0x40078000,len:13240
load:0x40080400,len:2880
--- 0x40080400: _invalid_pc_placeholder at /Users/username/esp/esp-idf/components/xtensa/xtensa_vectors.S:2235
entry 0x40080554
--- 0x40080554: call_start_cpu0 at /Users/username/esp/esp-idf/components/bootloader/subproject/main/bootloader_start.c:25
I (485) cpu_start: Multicore app
I (494) cpu_start: Pro cpu start user code
I (494) cpu_start: cpu freq: 160000000 Hz
I (494) app_init: Application information:
I (494) app_init: Project name:     MeadowComms
I (498) app_init: App version:      2.3.1
I (502) app_init: Compile time:     Jul 28 2025 18:43:57
I (507) app_init: ELF file SHA256:  f9920dd7d9c93279...
I (512) app_init: ESP-IDF:          v5.5-beta1-215-gcf8dad0746
I (517) efuse_init: Min chip rev:     v0.0
I (521) efuse_init: Max chip rev:     v3.99 
I (525) efuse_init: Chip rev:         v3.0
I (529) heap_init: Initializing. RAM available for dynamic allocation:
I (535) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (540) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (546) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (551) heap_init: At 3FFCBBF0 len 00014410 (81 KiB): DRAM
I (556) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (561) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (567) heap_init: At 4009D168 len 00002E98 (11 KiB): IRAM
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40091d89  PS      : 0x00060333  A0      : 0x80090266  A1      : 0x3ffe3370  
--- 0x40091d89: xTaskCheckForTimeOut at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4178
A2      : 0x3ffe3390  A3      : 0x3ffe33a0  A4      : 0x00060123  A5      : 0x3ffb63c0  
A6      : 0x00000100  A7      : 0x0000cdcd  A8      : 0x3ffc3990  A9      : 0x00000100  
A10     : 0x00000000  A11     : 0xffffffff  A12     : 0x00060323  A13     : 0x0000180e  
A14     : 0x00000000  A15     : 0x0000cdcd  SAR     : 0x0000001c  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0000015a  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  
--- 0x4000c2e0: memcpy in ROM
--- 0x4000c2f6: memcpy in ROM


Backtrace: 0x40091d86:0x3ffe3370 0x40090263:0x3ffe3390 0x400d5371:0x3ffe33d0 0x400d5994:0x3ffe33f0 0x400d59b9:0x3ffe3420 0x400d40e1:0x3ffe3440 0x40090889:0x3ffe3460 0x4008feb3:0x3ffe3480 0x40090078:0x3ffe34a0 0x4009438f:0x3ffe34c0 0x401ac963:0x3ffe34e0 0x4009447a:0x3ffe3510 0x400d3e95:0x3ffe3530 0x40094343:0x3ffe3550 0x400d5251:0x3ffe35b0 0x400d53a1:0x3ffe35f0 0x400d4593:0x3ffe3610 0x400d45f3:0x3ffe3bd0 0x400d34db:0x3ffe3bf0 0x400d350e:0x3ffe3c10 0x40081121:0x3ffe3c40 0x40079347:0x3ffe3c90 |<-CORRUPTED
--- 0x40091d86: xTaskCheckForTimeOut at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4178
--- 0x40090263: xQueueSemaphoreTake at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:1812
--- 0x400d5371: heap_caps_update_per_task_info_alloc at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:279
--- 0x400d5994: heap_caps_aligned_alloc_base at /Users/username/esp/esp-idf/components/heap/heap_caps_base.c:179
--- 0x400d59b9: heap_caps_malloc_base at /Users/username/esp/esp-idf/components/heap/heap_caps_base.c:202
--- 0x400d40e1: heap_caps_malloc at /Users/username/esp/esp-idf/components/heap/heap_caps.c:84
--- 0x40090889: pvPortMalloc at /Users/username/esp/esp-idf/components/freertos/heap_idf.c:55
--- 0x4008feb3: xQueueGenericCreate at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:545
--- 0x40090078: xQueueCreateMutex at /Users/username/esp/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:669
--- 0x4009438f: esp_log_impl_lock_timeout at /Users/username/esp/esp-idf/components/log/src/os/log_lock.c:37
--- 0x401ac963: log_level_get at /Users/username/esp/esp-idf/components/log/src/log_level/tag_log_level/tag_log_level.c:65
--- 0x4009447a: esp_log_level_get_timeout at /Users/username/esp/esp-idf/components/log/src/log_level/tag_log_level/tag_log_level.c:102
--- 0x400d3e95: esp_log_is_tag_loggable at /Users/username/esp/esp-idf/components/log/src/log_level/log_level.c:53
--- 0x40094343: esp_log_va at /Users/username/esp/esp-idf/components/log/src/log.c:41
--- (inlined by) esp_log at /Users/username/esp/esp-idf/components/log/src/log.c:88
--- 0x400d5251: create_new_heap_stats_entry at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:118
--- (inlined by) create_new_task_stats_entry at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:213
--- 0x400d53a1: heap_caps_update_per_task_info_alloc at /Users/username/esp/esp-idf/components/heap/heap_task_info.c:319
--- 0x400d4593: heap_caps_init at /Users/username/esp/esp-idf/components/heap/heap_caps_init.c:211
--- 0x400d45f3: __esp_system_init_fn_init_heap at /Users/username/esp/esp-idf/components/heap/heap_caps_init.c:27
--- 0x400d34db: do_system_init_fn at /Users/username/esp/esp-idf/components/esp_system/startup.c:132
--- 0x400d350e: do_core_init at /Users/username/esp/esp-idf/components/esp_system/startup.c:170
--- (inlined by) start_cpu0_default at /Users/username/esp/esp-idf/components/esp_system/startup.c:203
--- 0x40081121: call_start_cpu0 at /Users/username/esp/esp-idf/components/esp_system/port/cpu_start.c:836
--- 0x40079347: set_cache_and_start_app at /Users/username/esp/esp-idf/components/bootloader_support/src/bootloader_utility.c:1155
--- (inlined by) unpack_load_app at /Users/username/esp/esp-idf/components/bootloader_support/src/bootloader_utility.c:890
--- (inlined by) load_image at /Users/username/esp/esp-idf/components/bootloader_support/src/bootloader_utility.c:800

Regards,
Mark

[MicroController]

So is this looking like an issue in IDF ?

Yep, looks like it.

(Not sure though why the allocation in create_new_task_stats_entry() fails in the first place. May be a general (IDF) issue or specific to your application.)

[NevynSelby]

I have run the advanced sample and that works.

Merging the CONFIG entry and the code to print the heap statistics into my app (which works without this code/configuration) causes the issue.

Regards,
Mark

[georgn]

I ran into this problem today moving a project from 4.x to 5.x.

I found that log messages from my `app_main()` worked but log messages in child functions in other modules where I had a different `TAG` value were seeing this panic. Disabling heap task tracing in `menuconfig` made the problem go away.

After finding this conversation, I went back and tried using `ESP_EARLY_LOGE()` and that didn't appear to fix anything.
Adding a `vTaskDelay(1000 / portTICK_PERIOD_MS)` (in the naive hope that something would happen in freeRTOS) did not help.

Going back to disabling heap task tracing.