Merge branch 'feature/use-linked-list-for-heap-trace-records' into 'master'

heap: fix Leaks perf on large records by using doubly linked list

Closes IDFGH-9121 and IDF-1244

See merge request espressif/esp-idf!22009

components/heap/heap_trace_standalone.c

@@ -14,6 +14,7 @@
 #include "freertos/FreeRTOS.h"
 #include "freertos/task.h"
 #include "esp_memory_utils.h"
+#include "sys/queue.h"
 
 
 #define STACK_DEPTH CONFIG_HEAP_TRACING_STACK_DEPTH
@@ -24,15 +25,26 @@ static portMUX_TYPE trace_mux = portMUX_INITIALIZER_UNLOCKED;
 static bool tracing;
 static heap_trace_mode_t mode;
 
+/* Define struct: linked list of records */
+TAILQ_HEAD(heap_trace_record_list_struct_t, heap_trace_record_t);
+typedef struct heap_trace_record_list_struct_t heap_trace_record_list_t;
+
+/* Linked List of Records */
 typedef struct {
 
-    /* Buffer used for records, starting at offset 0 */
+    /* Buffer used for records. */
     heap_trace_record_t *buffer;
 
-    /* capacity of the buffer */
+    /* Linked list of recorded allocations */
+    heap_trace_record_list_t list;
+
+    /* Linked list of available record objects */
+    heap_trace_record_list_t unused;
+
+    /* capacity of 'buffer' */
     size_t capacity;
 
-    /* Count of entries logged in the buffer.*/
+    /* Count of entries in 'list' */
     size_t count;
 
     /* During execution, we remember the maximum
@@ -44,10 +56,14 @@ typedef struct {
     bool has_overflowed;
 } records_t;
 
-
 // Forward Defines
-static void remove_record(records_t *r, int index);
 static void heap_trace_dump_base(bool internal_ram, bool psram);
+static void record_deep_copy(heap_trace_record_t *rDest, const heap_trace_record_t* r_src);
+static void list_setup(void);
+static void list_remove(heap_trace_record_t* r_remove);
+static bool list_add(const heap_trace_record_t* r_append);
+static heap_trace_record_t* list_pop_unused(void);
+static heap_trace_record_t* list_find_address_reverse(void* p);
 
 /* The actual records. */
 static records_t records;
@@ -58,15 +74,22 @@ static size_t total_allocations;
 /* Actual number of frees logged */
 static size_t total_frees;
 
+/* Used to speed up heap_trace_get */
+static heap_trace_record_t* r_get;
+static size_t r_get_idx;
+
 esp_err_t heap_trace_init_standalone(heap_trace_record_t *record_buffer, size_t num_records)
 {
     if (tracing) {
         return ESP_ERR_INVALID_STATE;
     }
 
+    if (record_buffer == NULL || num_records == 0) {
+        return ESP_ERR_INVALID_ARG;
+    }
+
     records.buffer = record_buffer;
     records.capacity = num_records;
-    memset(records.buffer, 0, num_records * sizeof(heap_trace_record_t));
 
     return ESP_OK;
 }
@@ -77,14 +100,17 @@ esp_err_t heap_trace_start(heap_trace_mode_t mode_param)
         return ESP_ERR_INVALID_STATE;
     }
 
-
     portENTER_CRITICAL(&trace_mux);
 
     tracing = false;
     mode = mode_param;
 
+    // clear buffer
+    memset(records.buffer, 0, sizeof(heap_trace_record_t) * records.capacity);
+
     records.count = 0;
     records.has_overflowed = false;
+    list_setup();
 
     total_allocations = 0;
     total_frees = 0;
@@ -118,9 +144,9 @@ size_t heap_trace_get_count(void)
     return records.count;
 }
 
-esp_err_t heap_trace_get(size_t index, heap_trace_record_t *record)
+esp_err_t heap_trace_get(size_t index, heap_trace_record_t *r_out)
 {
-    if (record == NULL) {
+    if (r_out == NULL) {
         return ESP_ERR_INVALID_STATE;
     }
 
@@ -129,9 +155,44 @@ esp_err_t heap_trace_get(size_t index, heap_trace_record_t *record)
     portENTER_CRITICAL(&trace_mux);
 
     if (index >= records.count) {
+
         result = ESP_ERR_INVALID_ARG; /* out of range for 'count' */
+
     } else {
-        memcpy(record, &records.buffer[index], sizeof(heap_trace_record_t));
+
+        // Perf: speed up sequential access
+        if (r_get && r_get_idx == index - 1) {
+
+            r_get = TAILQ_NEXT(r_get, tailq);
+            r_get_idx = index;
+
+        } else {
+
+            // Iterate through through the linked list
+
+            r_get = TAILQ_FIRST(&records.list);
+
+            for (int i = 0; i < index; i++) {
+
+                if (r_get == NULL) {
+                    break;
+                }
+
+                r_get = TAILQ_NEXT(r_get, tailq);
+                r_get_idx = i + 1;
+            }
+        }
+
+        // copy to destination
+        if (r_get) {
+            memcpy(r_out, r_get, sizeof(heap_trace_record_t));
+        } else {
+            // this should not happen since we already
+            // checked that index < records.count,
+            // but could be indicative of memory corruption
+            result = ESP_ERR_INVALID_STATE;
+            memset(r_out, 0, sizeof(heap_trace_record_t));
+        }
     }
 
     portEXIT_CRITICAL(&trace_mux);
@@ -167,84 +228,98 @@ void heap_trace_dump_caps(const uint32_t caps) {
 
 static void heap_trace_dump_base(bool internal_ram, bool psram)
 {
+    portENTER_CRITICAL(&trace_mux);
+
     size_t delta_size = 0;
     size_t delta_allocs = 0;
     size_t start_count = records.count;
 
-    printf("====== Heap Trace: %u records (%u capacity) ======\n",
+    esp_rom_printf("====== Heap Trace: %u records (%u capacity) ======\n",
         records.count, records.capacity);
 
+    // Iterate through through the linked list
+
+    heap_trace_record_t *rCur = TAILQ_FIRST(&records.list);
+
     for (int i = 0; i < records.count; i++) {
 
-        heap_trace_record_t *rec = &records.buffer[i];
+        // check corruption
+        if (rCur == NULL) {
+            esp_rom_printf("\nError: heap trace linked list is corrupt. expected more records.\n");
+            break;
+        }
 
-        bool should_print = rec->address != NULL &&
+        bool should_print = rCur->address != NULL &&
             ((psram && internal_ram) ||
-             (internal_ram && esp_ptr_internal(rec->address)) ||
-             (psram && esp_ptr_external_ram(rec->address)));
+             (internal_ram && esp_ptr_internal(rCur->address)) ||
+             (psram && esp_ptr_external_ram(rCur->address)));
 
         if (should_print) {
 
             const char* label = "";
-            if (esp_ptr_internal(rec->address)) {
+            if (esp_ptr_internal(rCur->address)) {
                 label = ", Internal";
             }
-            if (esp_ptr_external_ram(rec->address)) {
+            if (esp_ptr_external_ram(rCur->address)) {
                 label = ",    PSRAM";
             }
 
-            printf("%6d bytes (@ %p%s) allocated CPU %d ccount 0x%08x caller ",
-                   rec->size, rec->address, label, rec->ccount & 1, rec->ccount & ~3);
+            esp_rom_printf("%6d bytes (@ %p%s) allocated CPU %d ccount 0x%08x caller ",
+                   rCur->size, rCur->address, label, rCur->ccount & 1, rCur->ccount & ~3);
 
-            for (int j = 0; j < STACK_DEPTH && rec->alloced_by[j] != 0; j++) {
-                printf("%p%s", rec->alloced_by[j],
+            for (int j = 0; j < STACK_DEPTH && rCur->alloced_by[j] != 0; j++) {
+                esp_rom_printf("%p%s", rCur->alloced_by[j],
                        (j < STACK_DEPTH - 1) ? ":" : "");
             }
 
-            if (mode != HEAP_TRACE_ALL || STACK_DEPTH == 0 || rec->freed_by[0] == NULL) {
-                delta_size += rec->size;
+            if (mode != HEAP_TRACE_ALL || STACK_DEPTH == 0 || rCur->freed_by[0] == NULL) {
+                delta_size += rCur->size;
                 delta_allocs++;
-                printf("\n");
+                esp_rom_printf("\n");
             } else {
-                printf("\nfreed by ");
+                esp_rom_printf("\nfreed by ");
                 for (int j = 0; j < STACK_DEPTH; j++) {
-                    printf("%p%s", rec->freed_by[j],
+                    esp_rom_printf("%p%s", rCur->freed_by[j],
                            (j < STACK_DEPTH - 1) ? ":" : "\n");
                 }
             }
         }
+
+        rCur = TAILQ_NEXT(rCur, tailq);
     }
 
-    printf("====== Heap Trace Summary ======\n");
+    esp_rom_printf("====== Heap Trace Summary ======\n");
 
     if (mode == HEAP_TRACE_ALL) {
-        printf("Mode: Heap Trace All\n");
-        printf("%u bytes alive in trace (%u/%u allocations)\n",
+        esp_rom_printf("Mode: Heap Trace All\n");
+        esp_rom_printf("%u bytes alive in trace (%u/%u allocations)\n",
                delta_size, delta_allocs, heap_trace_get_count());
     } else {
-        printf("Mode: Heap Trace Leaks\n");
-        printf("%u bytes 'leaked' in trace (%u allocations)\n", delta_size, delta_allocs);
+        esp_rom_printf("Mode: Heap Trace Leaks\n");
+        esp_rom_printf("%u bytes 'leaked' in trace (%u allocations)\n", delta_size, delta_allocs);
     }
 
-    printf("records: %u (%u capacity, %u high water mark)\n",
+    esp_rom_printf("records: %u (%u capacity, %u high water mark)\n",
         records.count, records.capacity, records.high_water_mark);
 
-    printf("total allocations: %u\n", total_allocations);
-    printf("total frees: %u\n", total_frees);
+    esp_rom_printf("total allocations: %u\n", total_allocations);
+    esp_rom_printf("total frees: %u\n", total_frees);
 
     if (start_count != records.count) { // only a problem if trace isn't stopped before dumping
-        printf("(NB: New entries were traced while dumping, so trace dump may have duplicate entries.)\n");
+        esp_rom_printf("(NB: New entries were traced while dumping, so trace dump may have duplicate entries.)\n");
     }
     if (records.has_overflowed) {
-        printf("(NB: Internal Buffer has overflowed, so trace data is incomplete.)\n");
+        esp_rom_printf("(NB: Internal Buffer has overflowed, so trace data is incomplete.)\n");
     }
-    printf("================================\n");
+    esp_rom_printf("================================\n");
+
+    portEXIT_CRITICAL(&trace_mux);
 }
 
 /* Add a new allocation to the heap trace records */
-static IRAM_ATTR void record_allocation(const heap_trace_record_t *record)
+static IRAM_ATTR void record_allocation(const heap_trace_record_t *rAllocation)
 {
-    if (!tracing || record->address == NULL) {
+    if (!tracing || rAllocation->address == NULL) {
         return;
     }
 
@@ -252,34 +327,19 @@ static IRAM_ATTR void record_allocation(const heap_trace_record_t *record)
 
     if (tracing) {
 
+        // If buffer is full, pop off the oldest
+        // record to make more space
         if (records.count == records.capacity) {
 
             records.has_overflowed = true;
 
-            /* Move the whole buffer back one slot.
-
-            This is a bit slow, compared to treating this buffer as a
-            ringbuffer and rotating a head pointer.
-
-            However, ringbuffer code gets tricky when we remove elements
-            in mid-buffer (for leak trace mode) while trying to keep
-            track of an item count that may overflow.
-            */
-            memmove(&records.buffer[0], &records.buffer[1],
-                sizeof(heap_trace_record_t) * (records.capacity -1));
+            heap_trace_record_t *rFirst = TAILQ_FIRST(&records.list);
 
-            records.count--;
+            list_remove(rFirst);
         }
 
-        // Copy new record into place
-        memcpy(&records.buffer[records.count], record, sizeof(heap_trace_record_t));
-
-        records.count++;
-
-        // high water mark
-        if (records.count > records.high_water_mark) {
-            records.high_water_mark = records.count;
-        }
+        // push onto end of list
+        list_add(rAllocation);
 
         total_allocations++;
     }
@@ -291,6 +351,9 @@ static IRAM_ATTR void record_allocation(const heap_trace_record_t *record)
 
    For HEAP_TRACE_ALL, this means filling in the freed_by pointer.
    For HEAP_TRACE_LEAKS, this means removing the record from the log.
+
+   callers is an array of  STACK_DEPTH function pointer from the call stack
+   leading to the call of record_free.
 */
 static IRAM_ATTR void record_free(void *p, void **callers)
 {
@@ -304,25 +367,20 @@ static IRAM_ATTR void record_free(void *p, void **callers)
 
         total_frees++;
 
-        /* search backwards for the allocation record matching this free */
-        int i = -1;
-        for (i = records.count - 1; i >= 0; i--) {
-            if (records.buffer[i].address == p) {
-                break;
-            }
-        }
+        // search backwards for the allocation record matching this free
+        heap_trace_record_t* rFound = list_find_address_reverse(p);
 
-        if (i >= 0) {
+        if (rFound) {
             if (mode == HEAP_TRACE_ALL) {
 
                 // add 'freed_by' info to the record
-                memcpy(records.buffer[i].freed_by, callers, sizeof(void *) * STACK_DEPTH);
+                memcpy(rFound->freed_by, callers, sizeof(void *) * STACK_DEPTH);
 
             } else { // HEAP_TRACE_LEAKS
 
                 // Leak trace mode, once an allocation is freed
                 // we remove it from the list
-                remove_record(&records, i);
+                list_remove(rFound);
             }
         }
     }
@@ -330,18 +388,126 @@ static IRAM_ATTR void record_free(void *p, void **callers)
     portEXIT_CRITICAL(&trace_mux);
 }
 
-/* remove the entry at 'index' from the ringbuffer of saved records */
-static IRAM_ATTR void remove_record(records_t *r, int index)
+// connect all records into a linked list of 'unused' records
+static void list_setup(void)
+{
+    TAILQ_INIT(&records.list);
+    TAILQ_INIT(&records.unused);
+
+    for (int i = 0; i < records.capacity; i++) {
+
+        heap_trace_record_t* rCur = &records.buffer[i];
+
+        TAILQ_INSERT_TAIL(&records.unused, rCur, tailq);
+    }
+}
+
+/* 1. removes record r_remove from records.list,
+   2. places it into records.unused */
+static IRAM_ATTR void list_remove(heap_trace_record_t* r_remove)
+{
+    assert(records.count > 0);
+
+    // remove from records.list
+    TAILQ_REMOVE(&records.list, r_remove, tailq);
+
+    // set as unused
+    r_remove->address = 0;
+    r_remove->size = 0;
+
+    // add to records.unused
+    TAILQ_INSERT_HEAD(&records.unused, r_remove, tailq);
+
+    // decrement
+    records.count--;
+}
+
+
+// pop record from unused list
+static IRAM_ATTR heap_trace_record_t* list_pop_unused(void)
+{
+    // no records left?
+    if (records.count >= records.capacity) {
+        return NULL;
+    }
+
+    // get from records.unused
+    heap_trace_record_t* rUnused = TAILQ_FIRST(&records.unused);
+    assert(rUnused->address == NULL);
+    assert(rUnused->size == 0);
+
+    // remove from records.unused
+    TAILQ_REMOVE(&records.unused, rUnused, tailq);
+
+    return rUnused;
+}
+
+// deep copy a record.
+// Note: only copies the *allocation data*, not the next & prev ptrs
+static IRAM_ATTR void record_deep_copy(heap_trace_record_t *rDest, const heap_trace_record_t *r_src)
+{
+    rDest->ccount  = r_src->ccount;
+    rDest->address = r_src->address;
+    rDest->size    = r_src->size;
+    memcpy(rDest->freed_by,   r_src->freed_by,   sizeof(void *) * STACK_DEPTH);
+    memcpy(rDest->alloced_by, r_src->alloced_by, sizeof(void *) * STACK_DEPTH);
+}
+
+// Append a record to records.list
+// Note: This deep copies r_append
+static IRAM_ATTR bool list_add(const heap_trace_record_t *r_append)
 {
-    if (index < r->count - 1) {
-        // Remove the buffer entry from the list
-        memmove(&r->buffer[index], &r->buffer[index+1],
-                sizeof(heap_trace_record_t) * (r->capacity - index - 1));
+    if (records.count < records.capacity) {
+
+        // get unused record
+        heap_trace_record_t* rDest = list_pop_unused();
+
+        // we checked that there is capacity, so this
+        // should never be null.
+        assert(rDest != NULL);
+
+        // copy allocation data
+        record_deep_copy(rDest, r_append);
+
+        // append to records.list
+        TAILQ_INSERT_TAIL(&records.list, rDest, tailq);
+
+        // increment
+        records.count++;
+
+        // high water mark
+        if (records.count > records.high_water_mark) {
+            records.high_water_mark = records.count;
+        }
+
+        return true;
+
     } else {
-        // For last element, just zero it out to avoid ambiguity
-        memset(&r->buffer[index], 0, sizeof(heap_trace_record_t));
+        records.has_overflowed = true;
+        return false;
+    }
+}
+
+// search records.list backwards for the allocation record matching this address
+static IRAM_ATTR heap_trace_record_t* list_find_address_reverse(void* p)
+{
+    if (records.count == 0) {
+        return NULL;
     }
-    r->count--;
+
+    heap_trace_record_t* rFound = NULL;
+
+    // Perf: We search backwards because new allocations are appended
+    // to the end of the list and most allocations are short lived.
+    heap_trace_record_t *rCur = NULL;
+    TAILQ_FOREACH_REVERSE(rCur, &records.list, heap_trace_record_list_struct_t, tailq) {
+        if (rCur->address == p) {
+            rFound = rCur;
+            break;
+        }
+    }
+
+    return rFound;
 }
 
 #include "heap_trace.inc"

components/heap/include/esp_heap_trace.h

@@ -6,6 +6,7 @@
 #pragma once
 
 #include "sdkconfig.h"
+#include "sys/queue.h"
 #include <stdint.h>
 #include <esp_err.h>
 
@@ -29,12 +30,15 @@ typedef enum {
 /**
  * @brief Trace record data type. Stores information about an allocated region of memory.
  */
-typedef struct {
+typedef struct heap_trace_record_t {
     uint32_t ccount; ///< CCOUNT of the CPU when the allocation was made. LSB (bit value 1) is the CPU number (0 or 1).
-    void *address;   ///< Address which was allocated
+    void *address;   ///< Address which was allocated. If NULL, then this record is empty.
     size_t size;     ///< Size of the allocation
     void *alloced_by[CONFIG_HEAP_TRACING_STACK_DEPTH]; ///< Call stack of the caller which allocated the memory.
     void *freed_by[CONFIG_HEAP_TRACING_STACK_DEPTH];   ///< Call stack of the caller which freed the memory (all zero if not freed.)
+#ifdef CONFIG_HEAP_TRACING_STANDALONE
+    TAILQ_ENTRY(heap_trace_record_t) tailq; ///< Linked list: prev & next records
+#endif // CONFIG_HEAP_TRACING_STANDALONE
 } heap_trace_record_t;
 
 /**

components/heap/test_apps/main/test_heap_main.c

@@ -1,5 +1,5 @@
 /*
- * SPDX-FileCopyrightText: 2022 Espressif Systems (Shanghai) CO LTD
+ * SPDX-FileCopyrightText: 2022-2023 Espressif Systems (Shanghai) CO LTD
  *
  * SPDX-License-Identifier: Apache-2.0
  */
@@ -8,7 +8,7 @@
 #include "unity_test_runner.h"
 #include "esp_heap_caps.h"
 
-#define TEST_MEMORY_LEAK_THRESHOLD_DEFAULT -100
+#define TEST_MEMORY_LEAK_THRESHOLD_DEFAULT -300
 static int leak_threshold = TEST_MEMORY_LEAK_THRESHOLD_DEFAULT;
 void set_leak_threshold(int threshold)
 {

components/heap/test_apps/main/test_heap_trace.c

@@ -1,5 +1,5 @@
 /*
- * SPDX-FileCopyrightText: 2022 Espressif Systems (Shanghai) CO LTD
+ * SPDX-FileCopyrightText: 2022-2023 Espressif Systems (Shanghai) CO LTD
  *
  * SPDX-License-Identifier: Unlicense OR CC0-1.0
  */
@@ -66,9 +66,9 @@ TEST_CASE("heap trace leak check", "[heap-trace]")
     heap_trace_get(0, &trace_b);
     TEST_ASSERT_EQUAL_PTR(b, trace_b.address);
 
-    /* buffer deletes trace_a when freed,
-       so trace_b at head of buffer */
-    TEST_ASSERT_EQUAL_PTR(recs[0].address, trace_b.address);
+    /* trace_a freed and placed back to unused list,
+       so recs[0].address is 0*/
+    TEST_ASSERT_EQUAL_PTR(recs[0].address, 0x00);
 
     heap_trace_stop();
 }

docs/sphinx-known-warnings.txt

@@ -33,3 +33,27 @@ wear-levelling.rst:line: WARNING: Duplicate C++ declaration, also defined at api
 Declaration is '.. cpp:member:: size_t allocation_unit_size'.
 wear-levelling.rst:line: WARNING: Duplicate C++ declaration, also defined at api-reference/storage/fatfs:line.
 Declaration is '.. cpp:member:: bool disk_status_check_enable'.
+esp_heap_trace.inc:line: WARNING: Error when parsing function declaration.
+If the function has no return type:
+  Invalid C++ declaration: Expected end of definition or ;. [error at 34]
+    TAILQ_ENTRY (heap_trace_record_t) tailq
+    ----------------------------------^
+If the function has a return type:
+  Error in declarator
+  If declarator-id with parameters-and-qualifiers:
+    Invalid C++ declaration: Expected identifier in nested name. [error at 12]
+      TAILQ_ENTRY (heap_trace_record_t) tailq
+      ------------^
+  If parenthesis in noptr-declarator:
+    Error in declarator or parameters-and-qualifiers
+    If pointer to member declarator:
+      Invalid C++ declaration: Expected '::' in pointer to member (function). [error at 32]
+        TAILQ_ENTRY (heap_trace_record_t) tailq
+        --------------------------------^
+    If declarator-id:
+      Invalid C++ declaration: Expecting "(" in parameters-and-qualifiers. [error at 32]
+        TAILQ_ENTRY (heap_trace_record_t) tailq
+        --------------------------------^
+
+esp_heap_trace.inc:line: WARNING: Duplicate C++ declaration, also defined at api-reference/system/heap_debug:line.
+Declaration is '.. cpp:type:: struct heap_trace_record_t heap_trace_record_t'.