From f99b95cae8d25a54d8d175c6e5bc6a30a8ce7fa5 Mon Sep 17 00:00:00 2001 From: Steve Gilberd Date: Sun, 26 Oct 2025 19:11:08 +1300 Subject: [PATCH 1/2] Add routing stats module --- src/mesh/MeshPacketQueue.cpp | 3 + src/mesh/RadioLibInterface.cpp | 7 ++ src/modules/Modules.cpp | 3 + src/modules/RoutingStatsModule.cpp | 120 +++++++++++++++++++++++++++++ src/modules/RoutingStatsModule.h | 32 ++++++++ 5 files changed, 165 insertions(+) create mode 100644 src/modules/RoutingStatsModule.cpp create mode 100644 src/modules/RoutingStatsModule.h diff --git a/src/mesh/MeshPacketQueue.cpp b/src/mesh/MeshPacketQueue.cpp index cbea85c62..8c08181f7 100644 --- a/src/mesh/MeshPacketQueue.cpp +++ b/src/mesh/MeshPacketQueue.cpp @@ -1,6 +1,7 @@ #include "MeshPacketQueue.h" #include "NodeDB.h" #include "configuration.h" +#include "modules/RoutingStatsModule.h" #include #include @@ -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; } diff --git a/src/mesh/RadioLibInterface.cpp b/src/mesh/RadioLibInterface.cpp index 80e51b8bc..fc4c90b5f 100644 --- a/src/mesh/RadioLibInterface.cpp +++ b/src/mesh/RadioLibInterface.cpp @@ -8,6 +8,7 @@ #include "error.h" #include "main.h" #include "mesh-pb-constants.h" +#include "modules/RoutingStatsModule.h" #include #include @@ -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); } diff --git a/src/modules/Modules.cpp b/src/modules/Modules.cpp index e477574dd..6c44f3e9e 100644 --- a/src/modules/Modules.cpp +++ b/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(); diff --git a/src/modules/RoutingStatsModule.cpp b/src/modules/RoutingStatsModule.cpp new file mode 100644 index 000000000..9e288564f --- /dev/null +++ b/src/modules/RoutingStatsModule.cpp @@ -0,0 +1,120 @@ +#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 + +/** + * 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(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 (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; +} diff --git a/src/modules/RoutingStatsModule.h b/src/modules/RoutingStatsModule.h new file mode 100644 index 000000000..26dae90af --- /dev/null +++ b/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, 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; \ No newline at end of file From b840af98db4648f2742384366b9f2e00cdd1e38c Mon Sep 17 00:00:00 2001 From: Steve Gilberd Date: Mon, 27 Oct 2025 18:46:42 +1300 Subject: [PATCH 2/2] Periodically reset window if not configured to broadcast stats --- src/modules/RoutingStatsModule.cpp | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/modules/RoutingStatsModule.cpp b/src/modules/RoutingStatsModule.cpp index 9e288564f..ba5043ff7 100644 --- a/src/modules/RoutingStatsModule.cpp +++ b/src/modules/RoutingStatsModule.cpp @@ -6,6 +6,7 @@ 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 @@ -102,6 +103,11 @@ int32_t RoutingStatsModule::runOnce() 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)