Merge b840af98db into 13c4c2037d

src/mesh/MeshPacketQueue.cpp

@@ -1,6 +1,7 @@
 #include "MeshPacketQueue.h"
 #include "NodeDB.h"
 #include "configuration.h"
+#include "modules/RoutingStatsModule.h"
 #include <assert.h>
 
 #include <algorithm>
@@ -76,6 +77,7 @@ bool MeshPacketQueue::enqueue(meshtastic_MeshPacket *p, bool *dropped)
         if (dropped) {
             *dropped = true;
         }
+        routingStats->logEvent(RoutingEvent::TX_DROP);
         return replaced;
     }
 
@@ -86,6 +88,7 @@ bool MeshPacketQueue::enqueue(meshtastic_MeshPacket *p, bool *dropped)
     // Find the correct position using upper_bound to maintain a stable order
     auto it = std::upper_bound(queue.begin(), queue.end(), p, CompareMeshPacketFunc);
     queue.insert(it, p); // Insert packet at the found position
+    routingStats->logEvent(RoutingEvent::TX_HWM, NULL, queue.size());
     return true;
 }
 

src/mesh/RadioLibInterface.cpp

@@ -8,6 +8,7 @@
 #include "error.h"
 #include "main.h"
 #include "mesh-pb-constants.h"
+#include "modules/RoutingStatsModule.h"
 #include <pb_decode.h>
 #include <pb_encode.h>
 
@@ -362,6 +363,7 @@ void RadioLibInterface::clampToLateRebroadcastWindow(NodeNum from, PacketId id)
         bool dropped = false;
         if (txQueue.enqueue(p, &dropped)) {
             LOG_DEBUG("Move existing queued packet to the late rebroadcast window %dms from now", p->tx_after - millis());
+            routingStats->logEvent(RoutingEvent::TX_DEFER);
         } else {
             packetPool.release(p);
         }
@@ -417,6 +419,8 @@ void RadioLibInterface::completeSending()
             txRelay++;
         printPacket("Completed sending", p);
 
+        routingStats->logEvent(RoutingEvent::TX_OK, p, xmitMsec);
+
         // We are done sending that packet, release it
         packetPool.release(p);
     }
@@ -458,6 +462,7 @@ void RadioLibInterface::handleReceiveInterrupt()
         rxBad++;
 
         airTime->logAirtime(RX_ALL_LOG, rxMsec);
+        routingStats->logEvent(RoutingEvent::RX_BAD, NULL, rxMsec);
 
     } else {
         // Skip the 4 headers that are at the beginning of the rxBuf
@@ -468,6 +473,7 @@ void RadioLibInterface::handleReceiveInterrupt()
             LOG_WARN("Ignore received packet too short");
             rxBad++;
             airTime->logAirtime(RX_ALL_LOG, rxMsec);
+            routingStats->logEvent(RoutingEvent::RX_BAD, NULL, rxMsec);
         } else {
             rxGood++;
             // altered packet with "from == 0" can do Remote Node Administration without permission
@@ -506,6 +512,7 @@ void RadioLibInterface::handleReceiveInterrupt()
             printPacket("Lora RX", mp);
 
             airTime->logAirtime(RX_LOG, rxMsec);
+            routingStats->logEvent(RoutingEvent::RX_OK, mp, rxMsec);
 
             deliverToReceiver(mp);
         }

src/modules/Modules.cpp

@@ -8,6 +8,7 @@
 #include "input/SerialKeyboardImpl.h"
 #include "input/UpDownInterruptImpl1.h"
 #include "input/i2cButton.h"
+#include "modules/RoutingStatsModule.h"
 #include "modules/SystemCommandsModule.h"
 #if HAS_TRACKBALL
 #include "input/TrackballInterruptImpl1.h"
@@ -112,6 +113,8 @@
  */
 void setupModules()
 {
+    routingStats = new RoutingStatsModule();
+
 #if (HAS_BUTTON || ARCH_PORTDUINO) && !MESHTASTIC_EXCLUDE_INPUTBROKER
     if (config.display.displaymode != meshtastic_Config_DisplayConfig_DisplayMode_COLOR) {
         inputBroker = new InputBroker();

src/modules/RoutingStatsModule.cpp

@@ -0,0 +1,126 @@
+#include "RoutingStatsModule.h"
+#include "MeshService.h"
+#include "NodeDB.h"
+#include "airtime.h"
+
+RoutingStatsModule *routingStats;
+
+#define PRINT_STATS_INTERVAL_MS (60 * 1000) // Print our own stats every 60 seconds
+#define PRINT_STATS_WINDOW_SECS 900         // If not transmitting stats, reset the window every 15 minutes
+
+/**
+ * Log a routing event
+ */
+void RoutingStatsModule::logEvent(RoutingEvent event, meshtastic_MeshPacket *p, uint32_t detail)
+{
+    switch (event) {
+    case RoutingEvent::TX_OK:
+        stats.tx_total++;
+        stats.tx_total_ms += detail;
+        if (isFromUs(p)) {
+            stats.tx_mine++;
+            if (!p->hop_start)
+                stats.tx_zero++;
+        } else
+            stats.tx_relayed++;
+        break;
+    case RoutingEvent::TX_DROP:
+        stats.tx_dropped++;
+        break;
+    case RoutingEvent::TX_DEFER:
+        stats.tx_deferred++;
+        break;
+    case RoutingEvent::TX_HWM:
+        if (detail > stats.tx_hwm)
+            stats.tx_hwm = detail;
+        break;
+    case RoutingEvent::RX_OK:
+        stats.rx_total++;
+        stats.rx_total_ms += detail;
+        if (p) {
+            if (p->hop_limit == p->hop_start) {
+                if (!p->hop_start)
+                    stats.rx_zero++;
+                else
+                    stats.rx_direct++;
+            } else if (!p->hop_limit)
+                stats.rx_eol++;
+        }
+        break;
+    case RoutingEvent::RX_BAD:
+        stats.rx_bad++;
+        stats.rx_total_ms += detail;
+        break;
+    default:
+        LOG_WARN("Unknown routing event %d", static_cast<int>(event));
+        break;
+    }
+}
+
+/**
+ * Print routing stats to the console
+ */
+void RoutingStatsModule::printStats(meshtastic_RoutingStats *stats, NodeNum src)
+{
+    const meshtastic_NodeInfoLite *node = nodeDB->getMeshNode(src);
+    const char *short_name = (node && node->has_user) ? node->user.short_name : "????";
+
+    LOG_INFO("Routing stats from %s (0x%08x), last %lu seconds", short_name, src, stats->window_secs);
+    LOG_INFO("  Airtime: chutil=%lu%% duty=%lu%% rx=%lums tx=%lums", stats->channel_util_pct, stats->tx_duty_pct,
+             stats->rx_total_ms, stats->tx_total_ms);
+    LOG_INFO("  TX: packets=%lu relayed=%lu mine=%lu zero-hop=%lu dropped=%lu hwm=%lu", stats->tx_total, stats->tx_relayed,
+             stats->tx_mine, stats->tx_zero, stats->tx_dropped, stats->tx_hwm);
+    LOG_INFO("  RX: packets=%lu bad=%lu direct=%lu zero-hop=%lu eol=%lu", stats->rx_total, stats->rx_bad, stats->rx_direct,
+             stats->rx_zero, stats->rx_eol);
+}
+
+/**
+ * Handle an incoming routing stats protobuf
+ */
+bool RoutingStatsModule::handleReceivedProtobuf(const meshtastic_MeshPacket &mp, meshtastic_RoutingStats *decoded)
+{
+    printStats(decoded, getFrom(&mp));
+    return true;
+}
+
+/**
+ * Periodic thread wakeup
+ */
+int32_t RoutingStatsModule::runOnce()
+{
+    unsigned long now = millis();
+    unsigned long next_tx_millis = config.device.routing_stats_broadcast_secs
+                                       ? (last_tx_millis + config.device.routing_stats_broadcast_secs * 1000)
+                                       : INT32_MAX;
+    unsigned long next_print_millis = last_print_millis + PRINT_STATS_INTERVAL_MS;
+
+    // Update 'now' fields
+    stats.window_secs = (now - last_tx_millis) / 1000;
+    stats.channel_util_pct = airTime->channelUtilizationPercent();
+    stats.tx_duty_pct = airTime->utilizationTXPercent();
+
+    if (now >= next_print_millis) {
+        printStats(&stats, nodeDB->getNodeNum());
+        last_print_millis = now;
+        next_print_millis = last_print_millis + PRINT_STATS_INTERVAL_MS;
+        if (!config.device.routing_stats_broadcast_secs && (last_tx_millis + PRINT_STATS_WINDOW_SECS * 1000) < now) {
+            // Reset stats window if we're not configured to broadcast stats
+            stats = {};
+            last_tx_millis = now;
+        }
+    }
+
+    if (next_tx_millis > now)
+        return (next_tx_millis > next_print_millis ? next_print_millis : next_tx_millis) - now;
+
+    LOG_DEBUG("Broadcast routing stats for last %d seconds", stats.window_secs);
+    meshtastic_MeshPacket *p = allocDataProtobuf(stats);
+    p->to = NODENUM_BROADCAST;
+    service->sendToMesh(p);
+
+    stats = {};
+    last_tx_millis = now;
+    next_tx_millis = last_tx_millis + config.device.routing_stats_broadcast_secs * 1000;
+
+    return (next_tx_millis > next_print_millis ? next_print_millis : next_tx_millis) - now;
+}

src/modules/RoutingStatsModule.h

@@ -0,0 +1,32 @@
+#pragma once
+#include "ProtobufModule.h"
+
+typedef enum class RoutingEvent {
+    TX_OK = 1,    // Successfully transmitted a packet. Detail = transmission time in ms
+    TX_DROP = 2,  // Packet dropped from TX queue.
+    TX_DEFER = 3, // Packet deferred to late contention window.
+    TX_HWM = 4,   // High water mark of TX queue. Detail = current TX queue length
+    RX_OK = 5,    // Successfully received a packet. Detail = reception time in ms
+    RX_BAD = 6,   // Failed to receive a packet. Detail = reception time in ms
+} RoutingEvent;
+
+class RoutingStatsModule : public ProtobufModule<meshtastic_RoutingStats>, public concurrency::OSThread
+{
+  public:
+    RoutingStatsModule()
+        : ProtobufModule("RoutingStats", meshtastic_PortNum_ROUTING_STATS_APP, meshtastic_RoutingStats_fields),
+          concurrency::OSThread("RoutingStats")
+    {
+    }
+    void logEvent(RoutingEvent event, meshtastic_MeshPacket *p = NULL, uint32_t detail = 0);
+
+  private:
+    unsigned long last_tx_millis = 0;
+    unsigned long last_print_millis = 0;
+    meshtastic_RoutingStats stats{};
+    void printStats(meshtastic_RoutingStats *stats, NodeNum src = 0);
+    bool handleReceivedProtobuf(const meshtastic_MeshPacket &mp, meshtastic_RoutingStats *decoded) override;
+    int32_t runOnce() override;
+};
+
+extern RoutingStatsModule *routingStats;