PSRAM decreases in do_global_ctors

[jumjum123]

Forgot to answer to this:

Something is calling esp_get_free_heap_size() in its global constructor and helping itself to 25% of the available heap.
Something is corrupting memory in a freakish way which causes the heap implementation to lose 1MB of space

esp_get_free_heap_size() is used in one place only, to log available heap
the number 1280kb is used in partitions table, but I already changed this to other values, that didn't change anything
The freakish way, yes, thats something, hmmmm, no idea how to find this.

[ESP_Angus]

That is all quite strange...

How about if you call heap_caps_dump(MALLOC_CAP_SPIRAM) after do_global_ctors?

Also, it'd be interesting to see output from heap_caps_get_free_size(MALLOC_CAP_SPIRAM), heap_caps_get_free_size(MALLOC_CAP_8BIT), and heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT).

[jumjum123]

Code: Select all

ESP_ERROR_CHECK( heap_trace_init_standalone(trace_record, NUM_RECORDS) );
ESP_EARLY_LOGI(TAG, "trace initialised\n"); 
ESP_ERROR_CHECK( heap_trace_start(HEAP_TRACE_ALL)); 
ESP_EARLY_LOGI(TAG, "trace started\n");
    do_global_ctors();
ESP_ERROR_CHECK( heap_trace_stop());
ESP_EARLY_LOGI(TAG, "trace stopped\n");
heap_trace_dump();
heap_caps_dump(MALLOC_CAP_SPIRAM);
ESP_EARLY_LOGI(TAG,"heap_caps_get_free_size(MALLOC_CAP_SPIRAM):%d\n",heap_caps_get_free_size(MALLOC_CAP_SPIRAM));
ESP_EARLY_LOGI(TAG,"heap_caps_get_free_size(MALLOC_CAP_8BIT):%d\n",heap_caps_get_free_size(MALLOC_CAP_8BIT));
ESP_EARLY_LOGI(TAG,"heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT):%d\n",heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT));

I (1430) cpu_start: heap after reserving pool:4206140
I (105) cpu_start: trace initialised
I (105) cpu_start: trace started
I (106) cpu_start: do_global:1061313156(4011790c) = (4205388)
I (107) cpu_start: do_global:1061313152(40117114) = (2894568)
I (113) cpu_start: trace stopped
0 allocations trace (100 entry buffer)
0 bytes alive in trace (0/0 allocations)
total allocations 0 total frees 0
Heap start 0x3f800010 end 0x3fbffff4
First free block 0x3f94001c
Block 0x3f800010 data size 0x00000004 bytes next block 0x3f800018 FREE. Next free 0x3f94001c
Block 0x3f800018 data size 0x00140000 bytes next block 0x3f94001c
Block 0x3f94001c data size 0x002bffd4 bytes next block 0x3fbffff4 FREE. Next free 0x3fbffff4
Block 0x3fbffff4 data size 0x00000000 bytes next block 0x00000000 FREE. Next free 0x00000000
I (162) cpu_start: heap_caps_get_free_size(MALLOC_CAP_SPIRAM):2883540
I (169) cpu_start: heap_caps_get_free_size(MALLOC_CAP_8BIT):2906248
I (175) cpu_start: heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT):22708

[jumjum123]

there is something wrong with heap tracing
I've added an malloc after starting trace, but it's not in heap_trace_dump

Code: Select all

ESP_ERROR_CHECK( heap_trace_init_standalone(trace_record, NUM_RECORDS) );
ESP_EARLY_LOGI(TAG, "trace initialised\n"); 
ESP_ERROR_CHECK( heap_trace_start(HEAP_TRACE_ALL)); 
ESP_EARLY_LOGI(TAG, "trace started\n");
      int x = malloc(131072);
ESP_EARLY_LOGI(TAG, "heap after malloc:%d(%d)\n",esp_get_free_heap_size(),x);
heap_caps_dump(MALLOC_CAP_SPIRAM);
    do_global_ctors();
ESP_ERROR_CHECK( heap_trace_stop());
ESP_EARLY_LOGI(TAG, "trace stopped\n");
heap_trace_dump();
heap_caps_dump(MALLOC_CAP_SPIRAM);
ESP_EARLY_LOGI(TAG,"heap_caps_get_free_size(MALLOC_CAP_SPIRAM):%d\n",heap_caps_get_free_size(MALLOC_CAP_SPIRAM));
ESP_EARLY_LOGI(TAG,"heap_caps_get_free_size(MALLOC_CAP_8BIT):%d\n",heap_caps_get_free_size(MALLOC_CAP_8BIT));
ESP_EARLY_LOGI(TAG,"heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT):%d\n",heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT));

[jumjum123]

ok, found the reason, why heap dump is empty.
I had to add some flags to my linker file.

WRAP_FUNCTIONS = calloc malloc free realloc heap_caps_malloc heap_caps_free heap_caps_realloc
WRAP_ARGUMENT := -Wl,--wrap=

LDFLAGS+= -lheap $(addprefix $(WRAP_ARGUMENT),$(WRAP_FUNCTIONS))

Now I get this:

4 allocations trace (100 entry buffer)
12 bytes (@ 0x3ffddd38) allocated CPU 0 ccount 0x032267c8 caller 0x40114f50:0x40117805:0x400d0af2:0x40081213
8 bytes (@ 0x3ffddd54) allocated CPU 0 ccount 0x0322a8c4 caller 0x40114e14:0x40117008:0x400d0af2:0x40081213
80 bytes (@ 0x3ffddd6c) allocated CPU 0 ccount 0x0322b684 caller 0x4008aca6:0x4008aee7:0x40114e33:0x40117008
1310720 bytes (@ 0x3f800024) allocated CPU 0 ccount 0x0322d350 caller 0x4011701e:0x400d0af2:0x40081213:0x4008144a
1310820 bytes alive in trace (4/4 allocations)
total allocations 4 total frees 0
Heap start 0x3f800010 end 0x3fbffff4
First free block 0x3f940028
Block 0x3f800010 data size 0x00000004 bytes next block 0x3f800018 FREE. Next free 0x3f940028
Block 0x3f800018 data size 0x0014000c bytes next block 0x3f940028
Block 0x3f940028 data size 0x002bffc8 bytes next block 0x3fbffff4 FREE. Next free 0x3fbffff4
Block 0x3fbffff4 data size 0x00000000 bytes next block 0x00000000 FREE. Next free 0x00000000
I (492) cpu_start: heap_caps_get_free_size(MALLOC_CAP_SPIRAM):2883516
I (498) cpu_start: heap_caps_get_free_size(MALLOC_CAP_8BIT):2903844
I (504) cpu_start: heap_caps_get_free_size(MALLOC_CAP_INTERNAL|MALLOC_CAP_8BIT):20328

In lst file I find this for caller of last alloc (0x4011701e)

Code: Select all

40116ff8 <_GLOBAL__sub_I___cxa_allocate_exception>:
40116ff8:	004136        	entry	a1, 32
40116ffb:	c71b41        	l32r	a4, 40108c68 <lwip_listen+0x9ac>
40116ffe:	0b0c      	movi.n	a11, 0
40117000:	04ad      	mov.n	a10, a4
40117002:	201110        	or	a1, a1, a1
40117005:	fdde65        	call8	40114dec <pthread_mutex_init>
40117008:	020c      	movi.n	a2, 0
4011700a:	2429      	s32i.n	a2, a4, 8
4011700c:	201110        	or	a1, a1, a1
4011700f:	fff5e5        	call8	40116f6c <__cxx_eh_arena_size_get>
40117012:	34a9      	s32i.n	a10, a4, 12
40117014:	0a2d      	mov.n	a2, a10
40117016:	6a8c      	beqz.n	a10, 40117020 <_GLOBAL__sub_I___cxa_allocate_exception+0x28>
40117018:	c4e581        	l32r	a8, 401083ac <lwip_listen+0xf0>
4011701b:	0008e0        	callx8	a8
4011701e:	24a9      	s32i.n	a10, a4, 8
40117020:	2488      	l32i.n	a8, a4, 8
40117022:	48cc      	bnez.n	a8, 4011702a <_GLOBAL__sub_I___cxa_allocate_exception+0x32>
40117024:	3489      	s32i.n	a8, a4, 12
40117026:	1489      	s32i.n	a8, a4, 4
40117028:	f01d      	retw.n
4011702a:	1489      	s32i.n	a8, a4, 4
4011702c:	0829      	s32i.n	a2, a8, 0
4011702e:	020c      	movi.n	a2, 0
40117030:	1829      	s32i.n	a2, a8, 4
40117032:	f01d      	retw.n
40117034:	04ad      	mov.n	a10, a4
40117036:	201110        	or	a1, a1, a1
40117039:	fde625        	call8	40114e9c <pthread_mutex_destroy>
4011703c:	02ad      	mov.n	a10, a2
4011703e:	201110        	or	a1, a1, a1
40117041:	012165        	call8	40118258 <_Unwind_Resume>

[ESP_Angus]

ok, found the reason, why heap dump is empty.
I had to add some flags to my linker file.

WRAP_FUNCTIONS = calloc malloc free realloc heap_caps_malloc heap_caps_free heap_caps_realloc
WRAP_ARGUMENT := -Wl,--wrap=

LDFLAGS+= -lheap $(addprefix $(WRAP_ARGUMENT),$(WRAP_FUNCTIONS))

I see. When using an external build system, making sure you have the same linker flags as the ESP-IDF build system is very important.

We have some ideas to make this easier in the future.

In lst file I find this for caller of last alloc (0x4011701e)

Code: Select all

40116ff8 <_GLOBAL__sub_I___cxa_allocate_exception>:
40116ff8:	004136        	entry	a1, 32
40116ffb:	c71b41        	l32r	a4, 40108c68 <lwip_listen+0x9ac>
40116ffe:	0b0c      	movi.n	a11, 0
40117000:	04ad      	mov.n	a10, a4
40117002:	201110        	or	a1, a1, a1
40117005:	fdde65        	call8	40114dec <pthread_mutex_init>
40117008:	020c      	movi.n	a2, 0
4011700a:	2429      	s32i.n	a2, a4, 8
4011700c:	201110        	or	a1, a1, a1
4011700f:	fff5e5        	call8	40116f6c <__cxx_eh_arena_size_get>
40117012:	34a9      	s32i.n	a10, a4, 12
40117014:	0a2d      	mov.n	a2, a10
40117016:	6a8c      	beqz.n	a10, 40117020 <_GLOBAL__sub_I___cxa_allocate_exception+0x28>
40117018:	c4e581        	l32r	a8, 401083ac <lwip_listen+0xf0>
4011701b:	0008e0        	callx8	a8
4011701e:	24a9      	s32i.n	a10, a4, 8
40117020:	2488      	l32i.n	a8, a4, 8
40117022:	48cc      	bnez.n	a8, 4011702a <_GLOBAL__sub_I___cxa_allocate_exception+0x32>
40117024:	3489      	s32i.n	a8, a4, 12
40117026:	1489      	s32i.n	a8, a4, 4
40117028:	f01d      	retw.n
4011702a:	1489      	s32i.n	a8, a4, 4
4011702c:	0829      	s32i.n	a2, a8, 0
4011702e:	020c      	movi.n	a2, 0
40117030:	1829      	s32i.n	a2, a8, 4
40117032:	f01d      	retw.n
40117034:	04ad      	mov.n	a10, a4
40117036:	201110        	or	a1, a1, a1
40117039:	fde625        	call8	40114e9c <pthread_mutex_destroy>
4011703c:	02ad      	mov.n	a10, a2
4011703e:	201110        	or	a1, a1, a1
40117041:	012165        	call8	40118258 <_Unwind_Resume>

Make sure you're linking -lcxx and passing the linker flags mentioned here:
https://github.com/espressif/esp-idf/bl ... mponent.mk

[jumjum123]

hip hip hooray !!!
That made it, ESP_ANGUS, thanks a lot.

I see. When using an external build system, making sure you have the same linker flags as the ESP-IDF build system is very important.
We have some ideas to make this easier in the future.

Please do this. Its always to figure out, how to get it running with "last minor changes"
Working with ESP-IDF by its own works like a charm.
But this is not the case for porting projects, running on multiple platforms.