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

[v5.1] memory being leaked in cJSON_Print() despite calling cJSON_free(jStr) (IDFGH-10250) #11512

Closed
chipweinberger opened this issue May 26, 2023 · 17 comments
Labels
Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Type: Bug bugs in IDF

Comments

@chipweinberger
Copy link
Contributor

chipweinberger commented May 26, 2023

IDF version.

release/v5.1

Development Kit.

ESP32-S3 Dev Kit C

What is the expected behavior?

No memory should be leaked.

What is the actual behavior?

The more I run my api, the more I see this specific leak grow. I don't understand why. Why is sprintf allocating memory in the first place?

I've tripled checked that I am calling cJSON_free(jStr) ;

0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160d9d: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x42160fda: __i2b at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:320

0x42160025: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:655

0x42156f70: _svfprintf_r at ??:?

0x421516c8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b6318: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:571
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1406

0x420b6571: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1779
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1433

0x420b6571: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1779
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1433

0x420b6680: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1202

0x420b6ddd: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1254

0x42051bf3: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x42018784: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018934: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x42018aac: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015463: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164

Steps to reproduce.

Ill need to get a better reproduction details.

  1. call cJSON_Print()
@chipweinberger chipweinberger added the Type: Bug bugs in IDF label May 26, 2023
@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 26, 2023

I am completely open to the idea of this being a false positive. But I've yet to be able to conclude that. It just grows and grows. I'll try and rule out bugs in my code, and bugs in HEAP_TRACE_STANDALONE more.

ChatGPT is pretty helpful about this stacktrace.

The stack trace shows a call to the sprintf function, which then results in several other calls within the newlib standard library, and eventually ends up in a call to _calloc_r, which is a function that allocates memory.

sprintf is a function used to format data into a string. When formatting certain types of data, particularly floating-point numbers, the library may need to perform computations that require the allocation of temporary memory. In this case, the _dtoa_r function (which converts a double to a string) appears to be making a call to __lshift (which performs a left shift operation on a multi-precision number), and __lshift is in turn calling _Balloc to allocate memory for a multi-precision number.

In other words, the memory allocation is not directly due to the sprintf call, but rather due to the specific operations that are necessary to format the data you're trying to print. This is a normal part of how the standard library works.

It's also worth noting that this does not necessarily mean that sprintf is "leaking" memory -- the memory that is allocated should be freed once it is no longer needed. However, if you're seeing unexpected memory usage, it could be a sign of a bug in the library or in your code, and you may want to investigate further.

For instance, if you're seeing a high rate of memory allocation when calling sprintf in a loop, it might be due to the repeated creation and destruction of temporary multi-precision numbers. In such cases, you might want to consider whether there are alternative ways to accomplish what you're trying to do that would not require as much dynamic memory allocation.

@espressif-bot espressif-bot added the Status: Opened Issue is new label May 26, 2023
@github-actions github-actions bot changed the title [v5.1] memory being leaked in cJSON_Print() despite calling cJSON_free(jStr) [v5.1] memory being leaked in cJSON_Print() despite calling cJSON_free(jStr) (IDFGH-10250) May 26, 2023
@igrr
Copy link
Member

igrr commented May 26, 2023

This is a lazy allocation in newlib C library. In this case, _dtoa_r allocates temporary storage and keeps the resulting pointer inside _REENT structure. Subsequent calls to sprintf will reuse the same buffer.

If you call sprintf again, no additional memory will be allocated.

We have an internal non-thread-safe function esp_reent_cleanup() (in esp_newlib.h) which implements best-effort cleanup of lazily-allocated newlib data. (It is not guaranteed to clean up everything, for instance static locks are not deallocated.)

@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 26, 2023

Appreciate the response Ivan!

If you call sprintf again, no additional memory will be allocated.

In my case, this is not the case. Every time I run my Bluetooth API call I leak another instance of this object. I am still investigating it.

@chipweinberger
Copy link
Contributor Author

Ivan, are there any cases where _dtoa_r would continue to allocate? I see this being allocated again and again, on the same task.

@igrr
Copy link
Member

igrr commented May 26, 2023

No, I can't think of any such case. Calling sprintf in a loop results in a stable value of heap_caps_get_free_size as far as I can tell.

@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 26, 2023

Here are all the objects. They're of various sizes (why...?), and slightly different stack traces.

bytes, address
16, 0x3fcb6f40, Internal
132, 0x3c320d44,   SPIRAM
28, 0x3fcb6f60, Internal,
24, 0x3fcb6f8c, Internal,
28, 0x3fcb6fb4, Internal,
36, 0x3fcb6fe0, Internal
36, 0x3fcb7014, Internal
36, 0x3fcb7048, Internal,
stack traces
// this is the format of the data!
bytes,  address  , location, cpu,    time      ,  allocBy0 ,  allocBy1 ,  allocBy2 ,  allocBy3 ,  allocBy4 ,  allocBy5 ,  allocBy6 ,  allocBy7 ,  allocBy8 ,  allocBy9 ,  allocBy10 ,  allocBy11 ,  allocBy12 ,  allocBy13 ,  allocBy14 ,  allocBy15 ,  allocBy16 ,  allocBy17 ,  allocBy18 ,  allocBy19 ,  allocBy20 ,  allocBy21 ,  allocBy22 ,  allocBy23 ,  freeBy0 ,  freeBy1 ,  freeBy2 ,  freeBy3 ,  freeBy4 ,  freeBy5 ,  freeBy6 ,  freeBy7 ,  freeBy8 ,  freeBy9 ,  freeBy10 ,  freeBy11 ,  freeBy12 ,  freeBy13 ,  freeBy14 ,  freeBy15 ,  freeBy16 ,  freeBy17 ,  freeBy18 ,  freeBy19 ,  freeBy20 ,  freeBy21 ,  freeBy22 ,  freeBy23 

    16, 0x3fcb6f40, Internal,   0,     842749200, 0x4215f765, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4215f765: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:234 (discriminator 1)

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164


  132, 0x3c320d44,   SPIRAM,   0,     842765808, 0x4038e152, 0x42160d82, 0x42161598, 0x4215f83a, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160d82: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:106

0x42161598: __d2b at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:778

0x4215f83a: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:287

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164



  28, 0x3fcb6f60, Internal,   0,     842777792, 0x4038e152, 0x42160dad, 0x42161598, 0x4215f83a, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160dad: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x42161598: __d2b at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:778

0x4215f83a: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:287

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164



     24, 0x3fcb6f8c, Internal,   0,     842800736, 0x4038e152, 0x42160dad, 0x4215fa55, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160dad: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x4215fa55: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:426

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164



    28, 0x3fcb6fb4, Internal,   0,     842814652, 0x4038e152, 0x42160dad, 0x42160fea, 0x42160035, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160dad: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x42160fea: __i2b at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:320

0x42160035: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:655

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164



     36, 0x3fcb6fe0, Internal,   0,     842835880, 0x4038e152, 0x42160dad, 0x42161249, 0x421600f8, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160dad: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x42161249: __lshift at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:473

0x421600f8: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:706

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164



    36, 0x3fcb7014, Internal,   0,     842848448, 0x4038e152, 0x42160dad, 0x42161249, 0x4216010e, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160dad: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x42161249: __lshift at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:473

0x4216010e: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:708

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164



     36, 0x3fcb7048, Internal,   0,     842871136, 0x4038e152, 0x42160dad, 0x42161249, 0x421603d0, 0x42156f80, 0x421516d8, 0x420b609d, 0x420b62f1, 0x420b62f1, 0x420b6400, 0x420b6b55, 0x420518c7, 0x420184b4, 0x42018664, 0x420187dc, 0x42015193, 0x40386ca9, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e152: _calloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:65

0x42160dad: _Balloc at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:127

0x42161249: __lshift at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/mprec.c:473

0x421603d0: _dtoa_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdlib/dtoa.c:825

0x42156f80: _svfprintf_r at ??:?

0x421516d8: sprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-apple-darwin12/xtensa-esp32s3-elf/src/newlib/newlib/libc/stdio/sprintf.c:620

0x420b609d: print_number at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:578
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1410

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b62f1: print_object at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1783
 (inlined by) print_value at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1437

0x420b6400: print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1210

0x420b6b55: cJSON_Print at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/json/cJSON/cJSON.c:1259

0x420518c7: cJSON2_Print(cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/utils/cJSON_utils.cpp:55

0x420184b4: pd_xtrans_resp_json_success(pd_xtrans_t*, cJSON*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xtrans.cpp:727 (discriminator 4)

0x42018664: _ZL22pd_xhandler_voidToJsonP11pd_xtrans_t18pd_xhandler_args_tP10pd_error_t$isra$0 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:147

0x420187dc: pd_xhandler_call_api_generic(pd_xtrans_t*, pd_error_t*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_xhandlers.cpp:461

0x42015193: bthttp_task(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_bthttp_server.cpp:231

0x40386ca9: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:164

@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 26, 2023

And the heap-trace-standalone summary count continues to go up,

{
        "mode": "leaks",
        "totalAllocs":  1041,
        "totalFrees":   1163,
        "count":        12, // this continues to increase, due to these objects
        "capacity":     2250,
        "highWaterMark":        164,
        "overflowed":   0
}

Note: the heap_trace_standalone tool is only ever enabled, never disabled, to make sure I don't miss any frees.

@chipweinberger
Copy link
Contributor Author

Also, where is _dtoa_r implemented? I have not been able to find the source code for it.

@igrr
Copy link
Member

igrr commented May 26, 2023

What about the actual heap size (rather than the heap trace records), does it increase? If yes, please try to create a code snippet which reproduces the issue and which you can share.

The implementation of dtoa is here.

@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 26, 2023

Here are my findings:

the cJSON "leak" seems fine

It takes a few calls but eventually heap_caps_get_free_size does stabilize. This is good.

_malloc_r: A different actual leak looks like a problem

heap_caps_get_free_size continues to down due to leaking _malloc_r.

  • it occurs when I alternate calling between different command line interface (linenoise) commands
  • it does not occur with repeated calls to the same cli (linenoise) command
  • it has almost no backtrace. It just says _malloc_r, and nothing else. barely useful.
 4, 0x3fcccd3c, Internal,   0,    1746480696, 0x4038e0c4, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0
0x4038e0c4: _malloc_r at /esp-idf/components/newlib/heap.c:45

.. and so on, grows by 1 each time...

Edit: I'm calling esp_backtrace_print in _malloc_r and the backtrace says its corrupted. Not sure if I believe that.

Backtrace: 0x4038E0C9:0x3FCC27B0 0x400509E2:0x3FCC27E0 |<-CORRUPTED
0x4038e0c9: _malloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:48

@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 27, 2023

I was able to get a full backtrace using STACKMIRROR #11519.

Backtrace: 0x403AAD17:0x3FCDD9A0 0x400509E2:0x3FCDD9D0 |<-CORRUPTED
0x403aad17: _malloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:51

Backtrace (Mirror): 0x403780C0 0x403799A4 0x403AACD4 0x420A5B6C 0x420A6FD4 0x420A7774 0x420A7860 0x4202C314 0x40396ED4
0x403aacd4: _malloc_r at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/newlib/heap.c:47

0x420a5b6c: linenoise2HistoryAdd at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/linenoise2/linenoise2.c:1389

0x420a6fd4: linenoise2Edit at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/linenoise2/linenoise2.c:976

0x420a7774: linenoise2Raw at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/linenoise2/linenoise2.c:1259

0x420a7860: linenoise2 at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/linenoise2/linenoise2.c:1322

0x4202c314: pd_console_task_enter_loop(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/api/xcoms/pd_console_task.cpp:306

0x40396ed4: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:161

Given that stack trace, THIS IS A FALSE POSITIVE =)

Linenoise has a history of 100 items. I would have needed to run my test 100 times before seeing the memory stabilize.

There are still some remaining questions tho, in order or importance:

  • why is the backtrace corrupt? THIS IS SUPER ANNOYING!
  • why have we not merged stack mirror yet? =) so useful....
  • do we really need newlibc functions in ROM during debug? It's very annoying not being able to "show definition" in an IDE
  • why does the cJSON "leak" continue to grow in heap-trace-standalone
  • imo, we should try to allocate more things up front, i.e. linenoise history

@igrr
Copy link
Member

igrr commented May 27, 2023

Backtrace: 0x403AAD17:0x3FCDD9A0 0x400509E2:0x3FCDD9D0 |<-CORRUPTED
why is the backtrace corrupt? THIS IS SUPER ANNOYING!

The backtrace is shown as corrupted because the backtracing code considers the address 0x400509E2 as non-executable. This is a bug caused by an incorrect value of SOC_IROM_MASK_HIGH define for ESP32-S3. The executable portion of ESP32-S3 mask ROM goes at least up to 0x40057d28, but SOC_IROM_MASK_HIGH is defined to 0x4001a100.

why have we not merged stack mirror yet? =) so useful....

As I understand, #10984 still contains some unresolved discussions/questions.

do we really need newlibc functions in ROM during debug? It's very annoying not being able to "show definition" in an IDE

There are two parts to this question:

  1. Can we link newlib functions into the application instead of taking them from ROM?
    • Not easily/trivially. There are a bunch of places in IDF where we rely on the fact that certain libc functions are in ROM, thus can be called from ISRs / when cache is disabled. If newlib is linked into the application, instead, we would have to revisit all these places and possibly move these functions into IRAM, manually. Not that this can't be done, but it is more involved than just removing a linker script from the linker arguments list. What you can do in a debugging scenario is to manually remove the function you are interested in from components/esp_rom/esp32s3/ld/esp32s3.rom.newlib.ld. Note that _dtoa_r is not in ROM.
  2. If we link newlib functions into the application instead of taking them from ROM, will the IDE be able to "go to definition"?
    • Not by default. Newlib code linked into the application still comes from a pre-compiled libc.a library, which is part of the toolchain. So the IDE won't show the source code of newlib functions, anyway.

With regards to the last question, you might wonder, how do we debug the code which involves newlib? Typically, using the following steps:

  1. Make sure you have newlib source code downloaded (from the repo linked above). Check out the branch with the version used by the toolchain release you have. For instance, for toolchain release esp-12.2.0_20230208 the newlib version can be found here: https://github.com/espressif/crosstool-NG/blob/esp-12.2.0_20230208/samples/xtensa-esp32s3-elf/crosstool.config#L27
  2. In the debugger, make sure the ROM ELF file is loaded. This happens automatically when you run idf.py gdb, bug if you are using an IDE you have to do this manually. The ELF files can be found in $HOME/.espressif/tools/esp-rom-elfs/<VERSION>/.
  3. Newlib pre-compiled libraries are built from source located at a different absolute path than it is located on your computer. Therefore we have to use set substitute-path command in GDB to map from the build path to the actual source path on your computer. For example, for me the command is gdb set substitute-path /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/1/idf/crosstool-NG/.build/xtensa-esp32s3-elf/src/newlib /Users/ivan/e/newlib-cygwin. The first path is where the source was located when libc.a was built. The second one is the path on my computer. Just like with step 2, it is handy to keep this command in your gdbinit script.
  4. Now you should be able to step through newlib functions and see the source code.

why does the cJSON "leak" continue to grow in heap-trace-standalone

I'm not sure. TBH after the last set of changes to heap-trace-standalone you probably know more about how it works than I do :) Someone will have to reproduce and debug this issue, I suppose.

imo, we should try to allocate more things up front, i.e. linenoise history

This is debatable. Why pay the cost of allocating linenoise history up front, when much of the allocated space might not end up being used? If we end up running out of heap and fail to allocate a linenoise history entry, that's fine — linenoise tolerates that and will simply not write the item into the history. On the other hand, the space saved by not allocating all the history entries could be used to allocate something more important.

@chipweinberger
Copy link
Contributor Author

chipweinberger commented May 27, 2023

Ivan, thank you for your incredible insightful and thoughtful response.

This is a bug caused by an incorrect value of SOC_IROM_MASK_HIGH

Great =) I'm glad this is an easy fix


and possibly move these functions into IRAM, manually

In a debugging scenario, I was thinking just place all of newlib in IRAM, under some kconfig. But your steps for debugging newlib probably remove the need for this.

"go to definition"

understood. If there is some way to enable "goto definition" and not precompile it into .a it would be a very nice debug feature. Maybe I should file an issue if you think it is practical.


how do we debug the code that involves newlib

This information is so useful! I will have to refer back to this next time I need to do this. A proper debug guide of this would be great. Perhaps even some tooling to simplify it.


TBH after the last set of changes to heap-trace-standalone you probably know more about how it works than I do :)

Indeed. I did look for bugs there! but nothing obvious. My current belief is that this is not a bug in heap-trace-standalone. But it could be. I should try adding esp_rom_printf to _calloc_r, _free_r, etc to narrow this down.


This is debatable.

Personal taste I suppose! It sure did make debugging this "leak" annoying tho haha. Slow growing heap in general. It would be useful if we could label certain callsites as "this is not a leak", but that might be impractical.


@espressif-bot espressif-bot added Status: In Progress Work is in progress Status: Reviewing Issue is being reviewed and removed Status: Opened Issue is new Status: In Progress Work is in progress labels May 29, 2023
@chipweinberger chipweinberger closed this as not planned Won't fix, can't repro, duplicate, stale May 29, 2023
@igrr igrr reopened this May 29, 2023
@igrr
Copy link
Member

igrr commented May 29, 2023

Going to close when the commit fixing SOC_IROM_MASK_HIGH gets pushed.

@chipweinberger
Copy link
Contributor Author

chipweinberger commented Jun 2, 2023

Make sure 0x400559DD is considered a valid executable address. See: #9708 (comment)

0x400559DD needs to be considered valid for backtraces to print correctly. Perhaps this is an assembly function? There is no function name printed by idf.py monitor for it.

usbHost

Backtrace: 0x400559DD:0x3C30A0C0 0x403873DD:0x3C30A0D0 0x40386C4F:0x3C30A100 0x420908CA:0x3C30A140 0x4204B15F:0x3C30A180 0x40387082:0x3C30A1B0
0x403873dd: vPortClearInterruptMaskFromISR at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:574
 (inlined by) vPortExitCritical at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:532

0x40386c4f: xQueueSemaphoreTake at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/queue.c:1796

0x420908ca: usb_host_lib_handle_events at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/usb/usb_host.c:498

0x4204b15f: usbHostTaskLoop(void*) at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/jamcorder-firmware/jamcorder_common/jcommon/usb/pd_usbh_service.cpp:70

0x40387082: vPortTaskWrapper at /Volumes/User/MBP-Google-Drive/jamcorder/firmware/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

@chipweinberger
Copy link
Contributor Author

Going to close when the commit fixing SOC_IROM_MASK_HIGH gets pushed.

Any updates? Would be great to close this issue.

@chipweinberger
Copy link
Contributor Author

chipweinberger commented Aug 10, 2023

closing this issue. Not sure if SOC_IROM_MASK_HIGH was triaged & fixed.

But the original issue turned out to be a red-herring (caused by console command history)

@espressif-bot espressif-bot added Status: Done Issue is done internally Resolution: NA Issue resolution is unavailable and removed Status: Reviewing Issue is being reviewed labels Sep 23, 2023
espressif-bot pushed a commit that referenced this issue Sep 27, 2023
Fixes corrupted backtraces on S3 when a function is in ROM.

Closes #11512
espressif-bot pushed a commit that referenced this issue Nov 21, 2023
Fixes corrupted backtraces on S3 when a function is in ROM.

Closes #11512
movsb pushed a commit to movsb/esp-idf that referenced this issue Dec 1, 2023
Fixes corrupted backtraces on S3 when a function is in ROM.

Closes espressif#11512
espressif-bot pushed a commit that referenced this issue Dec 13, 2023
Fixes corrupted backtraces on S3 when a function is in ROM.

Closes #11512
espressif-bot pushed a commit that referenced this issue Dec 20, 2023
Fixes corrupted backtraces on S3 when a function is in ROM.

Closes #11512
hathach pushed a commit to adafruit/esp-idf that referenced this issue Mar 27, 2024
Fixes corrupted backtraces on S3 when a function is in ROM.

Closes espressif#11512
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Type: Bug bugs in IDF
Projects
None yet
Development

No branches or pull requests

3 participants