Add LOG_HEAP log type, and more heap debug messages (#7937)

src/DebugConfiguration.h

@@ -23,6 +23,7 @@
 #define MESHTASTIC_LOG_LEVEL_ERROR "ERROR"
 #define MESHTASTIC_LOG_LEVEL_CRIT "CRIT "
 #define MESHTASTIC_LOG_LEVEL_TRACE "TRACE"
+#define MESHTASTIC_LOG_LEVEL_HEAP "HEAP"
 
 #include "SerialConsole.h"
 
@@ -62,6 +63,12 @@
 #endif
 #endif
 
+#if defined(DEBUG_HEAP)
+#define LOG_HEAP(...) DEBUG_PORT.log(MESHTASTIC_LOG_LEVEL_HEAP, __VA_ARGS__)
+#else
+#define LOG_HEAP(...)
+#endif
+
 /// A C wrapper for LOG_DEBUG that can be used from arduino C libs that don't know about C++ or meshtastic
 extern "C" void logLegacy(const char *level, const char *fmt, ...);
 

src/Power.cpp

@@ -851,9 +851,9 @@ void Power::readPowerStatus()
                 running++;
             }
         }
-        LOG_DEBUG(threadlist);
-        LOG_DEBUG("Heap status: %d/%d bytes free (%d), running %d/%d threads", memGet.getFreeHeap(), memGet.getHeapSize(),
-                  memGet.getFreeHeap() - lastheap, running, concurrency::mainController.size(false));
+        LOG_HEAP(threadlist);
+        LOG_HEAP("Heap status: %d/%d bytes free (%d), running %d/%d threads", memGet.getFreeHeap(), memGet.getHeapSize(),
+                 memGet.getFreeHeap() - lastheap, running, concurrency::mainController.size(false));
         lastheap = memGet.getFreeHeap();
     }
 #ifdef DEBUG_HEAP_MQTT

src/concurrency/OSThread.cpp

@@ -86,9 +86,9 @@ void OSThread::run()
 #ifdef DEBUG_HEAP
     auto newHeap = memGet.getFreeHeap();
     if (newHeap < heap)
-        LOG_DEBUG("------ Thread %s leaked heap %d -> %d (%d) ------", ThreadName.c_str(), heap, newHeap, newHeap - heap);
+        LOG_HEAP("------ Thread %s leaked heap %d -> %d (%d) ------", ThreadName.c_str(), heap, newHeap, newHeap - heap);
     if (heap < newHeap)
-        LOG_DEBUG("++++++ Thread %s freed heap %d -> %d (%d) ++++++", ThreadName.c_str(), heap, newHeap, newHeap - heap);
+        LOG_HEAP("++++++ Thread %s freed heap %d -> %d (%d) ++++++", ThreadName.c_str(), heap, newHeap, newHeap - heap);
 #endif
 
     runned();

src/mesh/MemoryPool.h

@@ -84,6 +84,8 @@ template <class T> class MemoryDynamic : public Allocator<T>
     virtual void release(T *p) override
     {
         assert(p);
+        LOG_HEAP("Freeing 0x%x", p);
+
         free(p);
     }
 

src/mesh/MeshService.cpp

@@ -193,8 +193,12 @@ void MeshService::handleToRadio(meshtastic_MeshPacket &p)
                                                  // (so we update our nodedb for the local node)
 
     // Send the packet into the mesh
+    auto heapBefore = memGet.getFreeHeap();
+    auto a = packetPool.allocCopy(p);
+    auto heapAfter = memGet.getFreeHeap();
+    LOG_HEAP("Alloc in MeshService::handleToRadio() pointer 0x%x, size: %u, free: %u", a, heapBefore - heapAfter, heapAfter);
 
-    sendToMesh(packetPool.allocCopy(p), RX_SRC_USER);
+    sendToMesh(a, RX_SRC_USER);
 
     bool loopback = false; // if true send any packet the phone sends back itself (for testing)
     if (loopback) {
@@ -250,7 +254,12 @@ void MeshService::sendToMesh(meshtastic_MeshPacket *p, RxSource src, bool ccToPh
     }
 
     if ((res == ERRNO_OK || res == ERRNO_SHOULD_RELEASE) && ccToPhone) { // Check if p is not released in case it couldn't be sent
-        sendToPhone(packetPool.allocCopy(*p));
+        auto heapBefore = memGet.getFreeHeap();
+        auto a = packetPool.allocCopy(*p);
+        auto heapAfter = memGet.getFreeHeap();
+        LOG_HEAP("Alloc in MeshService::sendToMesh() pointer 0x%x, size: %u, free: %u", a, heapBefore - heapAfter, heapAfter);
+
+        sendToPhone(a);
     }
 
     // Router may ask us to release the packet if it wasn't sent

src/mesh/ReliableRouter.cpp

@@ -2,6 +2,7 @@
 #include "Default.h"
 #include "MeshTypes.h"
 #include "configuration.h"
+#include "memGet.h"
 #include "mesh-pb-constants.h"
 #include "modules/NodeInfoModule.h"
 #include "modules/RoutingModule.h"
@@ -21,8 +22,11 @@ ErrorCode ReliableRouter::send(meshtastic_MeshPacket *p)
         if (p->hop_limit == 0) {
             p->hop_limit = Default::getConfiguredOrDefaultHopLimit(config.lora.hop_limit);
         }
-
+        auto heapBefore = memGet.getFreeHeap();
         auto copy = packetPool.allocCopy(*p);
+        auto heapAfter = memGet.getFreeHeap();
+        LOG_HEAP("Alloc in ReliableRouter::send() pointer 0x%x, size: %u, free: %u", copy, heapBefore - heapAfter, heapAfter);
+
         startRetransmission(copy, NUM_RELIABLE_RETX);
     }
 

src/mesh/Router.cpp

@@ -275,7 +275,12 @@ ErrorCode Router::send(meshtastic_MeshPacket *p)
     // If the packet is not yet encrypted, do so now
     if (p->which_payload_variant == meshtastic_MeshPacket_decoded_tag) {
         ChannelIndex chIndex = p->channel; // keep as a local because we are about to change it
+
+        auto heapBefore = memGet.getFreeHeap();
         meshtastic_MeshPacket *p_decoded = packetPool.allocCopy(*p);
+        auto heapAfter = memGet.getFreeHeap();
+
+        LOG_HEAP("Alloc in Router::send pointer 0x%x, size: %u, free: %u", p_decoded, heapBefore - heapAfter, heapAfter);
 
         auto encodeResult = perhapsEncode(p);
         if (encodeResult != meshtastic_Routing_Error_NONE) {
@@ -608,7 +613,10 @@ void Router::handleReceived(meshtastic_MeshPacket *p, RxSource src)
     // Also, we should set the time from the ISR and it should have msec level resolution
     p->rx_time = getValidTime(RTCQualityFromNet); // store the arrival timestamp for the phone
     // Store a copy of encrypted packet for MQTT
+    auto heapBefore = memGet.getFreeHeap();
     meshtastic_MeshPacket *p_encrypted = packetPool.allocCopy(*p);
+    auto heapAfter = memGet.getFreeHeap();
+    LOG_HEAP("Alloc in Router::handleReceived pointer 0x%x, size: %u, free: %u", p_encrypted, heapBefore - heapAfter, heapAfter);
 
     // Take those raw bytes and convert them back into a well structured protobuf we can understand
     auto decodedState = perhapsDecode(p);

src/modules/NodeInfoModule.cpp

@@ -44,7 +44,11 @@ void NodeInfoModule::sendOurNodeInfo(NodeNum dest, bool wantReplies, uint8_t cha
     if (prevPacketId) // if we wrap around to zero, we'll simply fail to cancel in that rare case (no big deal)
         service->cancelSending(prevPacketId);
     shorterTimeout = _shorterTimeout;
+    auto heapBefore = memGet.getFreeHeap();
     meshtastic_MeshPacket *p = allocReply();
+    auto heapAfter = memGet.getFreeHeap();
+
+    LOG_HEAP("Alloc in NodeInfoModule::sendOurNodeInfo pointer 0x%x, size: %u, free: %u", p, heapBefore - heapAfter, heapAfter);
     if (p) { // Check whether we didn't ignore it
         p->to = dest;
         p->decoded.want_response = (config.device.role != meshtastic_Config_DeviceConfig_Role_TRACKER &&

src/modules/Telemetry/DeviceTelemetry.cpp

@@ -172,7 +172,12 @@ bool DeviceTelemetryModule::sendTelemetry(NodeNum dest, bool phoneOnly)
              telemetry.variant.device_metrics.battery_level, telemetry.variant.device_metrics.voltage,
              telemetry.variant.device_metrics.uptime_seconds);
 
+    auto heapBefore = memGet.getFreeHeap();
     meshtastic_MeshPacket *p = allocDataProtobuf(telemetry);
+    auto heapAfter = memGet.getFreeHeap();
+    LOG_HEAP("Alloc in DeviceTelemetryModule::sendTelemetry() pointer 0x%x, size: %u, free: %u", p, heapBefore - heapAfter,
+             heapAfter);
+
     p->to = dest;
     p->decoded.want_response = false;
     p->priority = meshtastic_MeshPacket_Priority_BACKGROUND;