Running some unity tests with weird memory leak.

[uC_Jon]

In the included stack heap trace created using heap_trace_start(HEAP_TRACE_ALL), heap_trace_stop(), and heap_trace_dump() I have noticed some strange allocations.

The start/stop/dump are around each test (in startUp and tearDown).

I also use of heap_caps_get_free_size(MALLOC_CAP_32BIT | MALLOC_CAP_8BIT) at the start of the setUp and the end of the tearDown to see if there is any change (which in theory should always be 0).

On the whole I can see the odd allocation that doesn't get freed, and after removing a bug in my code where I allocated a buffer and didn't free it, but I'm ok with those minor losses. They are all deep within the esp-idf and seem to happen the very first time a component such as i2c_new_master_bus is called but on subsequent calls (after say calling i2c_del_master_bus) there are no new losses.

And in most tests I'm down to 0 differences in the free_size.

That said, there is one run that logs some very strange allocations that are not freed.

There is no call stack related to my application... rather the memory is grabbed by some task outside of everything running from the ROM!

Does anyone have any clues?

Should I just chalk this up to "don't worry about it".

I get the feeling that its possibly "the chip" loading code or pre-initializing storage of my program or maybe doing its own thing entirely separate! Changing the heap trace type (no stack, just blocks) doesn't seem to make any difference.

Code: Select all

    16 bytes (@ 0x4087dda4, Internal) allocated CPU 0 ccount 0x053da180 caller 0x4080125a:0x408012ce:0x40800966:0x408009ce:0x4080c2fa:0x400283ec:
--- 0x4080125a: trace_malloc at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:138
0x408012ce: __wrap_heap_caps_malloc_base at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:190
0x40800966: heap_caps_malloc at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:84
0x408009ce: heap_caps_malloc_default at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:110
0x4080c2fa: _malloc_r at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:68
0x400283ec: malloc in ROM

   132 bytes (@ 0x4087ddc4, Internal) allocated CPU 0 ccount 0x053dabc0 caller 0x4080125a:0x408012ce:0x40800966:0x408009ce:0x4080c298:0x4080c312:0x40028208:
--- 0x4080125a: trace_malloc at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:138
0x408012ce: __wrap_heap_caps_malloc_base at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:190
0x40800966: heap_caps_malloc at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:84
0x408009ce: heap_caps_malloc_default at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:110
0x4080c298: calloc at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:46
0x4080c312: _calloc_r at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:73
0x40028208: _calloc_r in ROM

    28 bytes (@ 0x4087de58, Internal) allocated CPU 0 ccount 0x053db840 caller 0x4080125a:0x408012ce:0x40800966:0x408009ce:0x4080c298:0x4080c312:0x40028208:
--- 0x4080125a: trace_malloc at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:138
0x408012ce: __wrap_heap_caps_malloc_base at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:190
0x40800966: heap_caps_malloc at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:84
0x408009ce: heap_caps_malloc_default at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:110
0x4080c298: calloc at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:46
0x4080c312: _calloc_r at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:73
0x40028208: _calloc_r in ROM

    24 bytes (@ 0x4087de84, Internal) allocated CPU 0 ccount 0x053dc794 caller 0x4080125a:0x408012ce:0x40800966:0x408009ce:0x4080c298:0x4080c312:0x40028208:
--- 0x4080125a: trace_malloc at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:138
0x408012ce: __wrap_heap_caps_malloc_base at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:190
0x40800966: heap_caps_malloc at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:84
0x408009ce: heap_caps_malloc_default at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:110
0x4080c298: calloc at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:46
0x4080c312: _calloc_r at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:73
0x40028208: _calloc_r in ROM

     6 bytes (@ 0x4087deac, Internal) allocated CPU 0 ccount 0x05403388 caller 0x4080125a:0x408012ce:0x40800966:0x408009ce:0x4080c298:0x42010146:0x42010312:0x42010558:0x42010dd6:0x42000324:0x4200c5a6:0x4200c7da:0x4200c856:0x420112aa:0x42018178:0x408076f4:
--- 0x4080125a: trace_malloc at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:138
0x408012ce: __wrap_heap_caps_malloc_base at /home/wilsonj/esp/esp-idf/components/heap/include/heap_trace.inc:190
0x40800966: heap_caps_malloc at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:84
0x408009ce: heap_caps_malloc_default at /home/wilsonj/esp/esp-idf/components/heap/heap_caps.c:110
0x4080c298: calloc at /home/wilsonj/esp/esp-idf/components/newlib/src/heap.c:46
0x42010146: s_mcp9808_log_register_blocks at /home/wilsonj/Documents/foldered/vscode/esp-idf/i400s__/i2c-mcp9808/components/i2c-mcp9808/i2c_mcp9808.c:25
0x42010312: s_mcp9808_register_block_write at /home/wilsonj/Documents/foldered/vscode/esp-idf/i400s__/i2c-mcp9808/components/i2c-mcp9808/i2c_mcp9808.c:83
0x42010558: s_mcp9808_bounds_temperature_set at /home/wilsonj/Documents/foldered/vscode/esp-idf/i400s__/i2c-mcp9808/components/i2c-mcp9808/i2c_mcp9808.c:152
0x42010dd6: mcp9808_critical_temperature_set at /home/wilsonj/Documents/foldered/vscode/esp-idf/i400s__/i2c-mcp9808/components/i2c-mcp9808/i2c_mcp9808.c:278
0x42000324: test_func_124 at /home/wilsonj/Documents/foldered/vscode/esp-idf/i400s__/i2c-mcp9808/components/i2c-mcp9808/test/test_i2c_mcp9808.c:127
0x4200c5a6: unity_default_test_run at /home/wilsonj/esp/esp-idf/components/unity/unity_runner.c:70
0x4200c7da: unity_run_single_test at /home/wilsonj/esp/esp-idf/components/unity/unity_runner.c:135
0x4200c856: unity_run_all_tests at /home/wilsonj/esp/esp-idf/components/unity/unity_runner.c:182 (discriminator 3)
0x420112aa: app_main at /home/wilsonj/Documents/foldered/vscode/esp-idf/i400s__/i2c-mcp9808/test-apps/i2c-mcp9808/main/test_app_main.c:18
0x42018178: main_task at /home/wilsonj/esp/esp-idf/components/freertos/app_startup.c:209 (discriminator 10)
0x408076f4: vPortTaskWrapper at /home/wilsonj/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/riscv/port.c:258

freed by 0x408010ee:0x408012a2:0x4080c270:0x42010234:0x42010312:0x42010558:0x42010dd6:0x42000324:0x4200c5a6:0x4200c7da:0x4200c856:0x420112aa:0x42018178:0x408076f4:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000:0x00000000

[uC_Jon]

Some more information...

I noticed that the "odd" allocations of memory would seemingly move location if I changed the order of the tests so initially I assumed it was possibly something to do with the "chip" loading/caching parts of my program but for the life of me I could not figure out why no matter how much I moved the tests around...

So I then I wondered if it was something to do with the order of the code being tested within the component code under test and not the test order... so I physically moved the prototype of the function within the header but that didn't do anything...

Then I moved the physical code of the function all the way up to near the front of the source file (you never know, I'm still wondering if its some strange code loading thing!) and nope, that still didn't do anything...

So then I started adding heap_trace_dump() in my code as the first thing after the function declaration and that started to narrow down where the issue was happening... once I'd narrowed it down to somewhere within a couple of functions I then started adding dumps around each line of code one after the other, compiled, checked the output and moved on to the next line... I didn't want to just add a whole heap of dumps in one go because I was still convinced it was something to do with some kind of code loading thing and adding a lot of dumps would make a large change to the code generated (even though I'd already moved the entirety of code up within the source file, hey I'm self learning C and esp-idf at the same time!) so I figured go slow... line by line... until I found the exact line... which was like 100's of other lines within my code... the last line I checked as I have them scatted all over the code... What The Actual!

The code line in question:

Code: Select all

    heap_trace_dump();
    ESP_LOGD(TAG, "convert %.04f adjusted %.04f temperature to register format: %04X", temperature, temperature_twos, reg_format);
    heap_trace_dump();

I have lots of LOGI and LOGD messages within my code as I'm trying to make it as close to a normal Espressif component as possible, so when I say a lot, I mean a lot.

So then I wondered if it was something to do with the data, maybe I'd mucked up and done some daft allocation or I'd corrupted some data or I'd actually managed to do some buffer overrun and I'd corrupted the code...

The bug moved its location to a different function when I removed the line entirely... the same when I LOGD'd the reg_format... it came back to this function when I just logged the temperature_twos... and it came back when I just LOGD'd the temperature... that's odd I thought!

Was it some odd bug in the ESP_LOGD expansion with floats, because it seemed that the float was the issue so I did a bog standard printf("convert %.04f", temperature); and that did the "odd" allocations...

And finally....

I made the code as simple as it possibly could be just in case I'd some how mucked up a float variable (you never know):

Code: Select all

    heap_trace_dump();
    printf("%.04f", 1.5);
    heap_trace_dump();

That's it.

That's the code that triggers the strange allocations malloc/_calloc_r "in ROM".

I'm speculating that the routine that does the nice formatting of floats is stored in ROM and to do the nice formatting it requires the allocation of some work memory (or it copies itself into ram? or requires some pointers to the code in ROM so they can be called and those locations might move depending on chip model?) so it just goes ahead and does that without a by your leave and then doesn't bother to clean it up afterwards as it might be needed again. Pure speculation on my part.

So I'm going to count this as closed now as whatever is happening is so outside of both my knowledge and my actual code that I can't do anything about it.

Although it would be nice if someone could confirm what was actually happening because I really like closure; especially after wearing out the flash hunting this down .

[MicroController]

I'm speculating that the routine that does the nice formatting [...] requires the allocation of some work memory [...] and then doesn't bother to clean it up afterwards as it might be needed again.

That's my guess too.

[uC_Jon]

That's my guess too.

Thanks for that. Sets my mind more at ease.