MAC-layer stats instrumentation

docs/cli_commands.md

@@ -139,21 +139,50 @@ This document provides an overview of CLI commands that can be sent to MeshCore
 **Usage:** 
 - `stats-core`
 
-**Serial Only:** Yes
+**Serial Only:** No
 
 ---
 
 ### Radio Stats - Noise floor, Last RSSI/SNR, Airtime, Receive errors
 **Usage:** `stats-radio`
 
-**Serial Only:** Yes
+**Serial Only:** No
 
 ---
 
 ### Packet stats - Packet counters: Received, Sent
 **Usage:** `stats-packets`
 
-**Serial Only:** Yes
+**Serial Only:** No
+
+---
+
+### MAC CAD stats - CAD deferral and timeout counters
+**Usage:** `stats-mac-cad`
+
+**Serial Only:** No
+
+Returns JSON with:
+- `busy`: local radio/CAD busy deferrals before the timeout threshold
+- `timeouts`: times local CAD busy state exceeded the maximum busy duration
+- `forced_tx`: CAD timeout events that force-transmitted because fail-open mode was selected
+
+---
+
+### MAC TX stats - TX, retransmit and queue counters
+**Usage:** `stats-mac-tx`
+
+**Serial Only:** No
+
+Returns JSON with:
+- `started`: transmit attempts started by the dispatcher
+- `completed`: transmit completions reported by the radio
+- `start_fail`: transmit attempts that failed to start
+- `timeouts`: transmit operations that timed out
+- `rx_delay`: received packets delayed before local processing
+- `retransmits`: packets scheduled for retransmit or forward
+- `pool_full`: packet allocation failures caused by pool exhaustion
+- `bad_queue`: invalid queued packets dropped before transmit
 
 ---
 

examples/simple_repeater/MyMesh.cpp

@@ -535,6 +535,32 @@ void MyMesh::logTxFail(mesh::Packet *pkt, int len) {
   }
 }
 
+void MyMesh::logMacEvent(const char* event, mesh::Packet* pkt, int len, uint8_t priority,
+                         uint32_t delay_millis, uint32_t airtime_millis, uint32_t value) {
+  if (_logging) {
+    File f = openAppend(PACKET_LOG_FILE);
+    if (f) {
+      f.print(getLogDateTime());
+      f.printf(": MAC, ms=%lu event=%s len=%d pri=%u delay=%lu airtime=%lu value=%lu q=%d free=%d nf=%d rssi=%d snr=%d",
+               _ms->getMillis(), event, len, (uint32_t)priority, (unsigned long)delay_millis,
+               (unsigned long)airtime_millis, (unsigned long)value,
+               _mgr->getOutboundTotal(), _mgr->getFreeCount(), (int)_radio->getNoiseFloor(),
+               (int)radio_driver.getLastRSSI(), (int)(radio_driver.getLastSNR() * 4));
+
+      if (pkt) {
+        uint8_t packet_hash[MAX_HASH_SIZE];
+        pkt->calculatePacketHash(packet_hash);
+        f.printf(" type=%d route=%s payload_len=%d path_count=%d path_hash_size=%d hash=",
+                 pkt->getPayloadType(), pkt->isRouteDirect() ? "D" : "F", pkt->payload_len,
+                 pkt->getPathHashCount(), pkt->getPathHashSize());
+        mesh::Utils::printHex(f, packet_hash, 4);
+      }
+      f.printf("\n");
+      f.close();
+    }
+  }
+}
+
 int MyMesh::calcRxDelay(float score, uint32_t air_time) const {
   if (_prefs.rx_delay_base <= 0.0f) return 0;
   return (int)((pow(_prefs.rx_delay_base, 0.85f - score) - 1.0) * air_time);
@@ -1152,6 +1178,14 @@ void MyMesh::formatPacketStatsReply(char *reply) {
                                        getNumRecvFlood(), getNumRecvDirect());
 }
 
+void MyMesh::formatMacCadStatsReply(char *reply) {
+  StatsFormatHelper::formatMacCadStats(reply, getMacStats());
+}
+
+void MyMesh::formatMacTxStatsReply(char *reply) {
+  StatsFormatHelper::formatMacTxStats(reply, getMacStats());
+}
+
 void MyMesh::saveIdentity(const mesh::LocalIdentity &new_id) {
 #if defined(NRF52_PLATFORM) || defined(STM32_PLATFORM)
   IdentityStore store(*_fs, "");

examples/simple_repeater/MyMesh.h

@@ -142,6 +142,8 @@ class MyMesh : public mesh::Mesh, public CommonCLICallbacks {
   void logRx(mesh::Packet* pkt, int len, float score) override;
   void logTx(mesh::Packet* pkt, int len) override;
   void logTxFail(mesh::Packet* pkt, int len) override;
+  void logMacEvent(const char* event, mesh::Packet* pkt, int len, uint8_t priority,
+                   uint32_t delay_millis, uint32_t airtime_millis, uint32_t value) override;
   int calcRxDelay(float score, uint32_t air_time) const override;
 
   uint32_t getRetransmitDelay(const mesh::Packet* packet) override;
@@ -214,6 +216,8 @@ class MyMesh : public mesh::Mesh, public CommonCLICallbacks {
   void formatStatsReply(char *reply) override;
   void formatRadioStatsReply(char *reply) override;
   void formatPacketStatsReply(char *reply) override;
+  void formatMacCadStatsReply(char *reply) override;
+  void formatMacTxStatsReply(char *reply) override;
   void startRegionsLoad() override;
   bool saveRegions() override;
   void onDefaultRegionChanged(const RegionEntry* r) override;

src/Dispatcher.cpp

@@ -19,6 +19,7 @@ namespace mesh {
 void Dispatcher::begin() {
   n_sent_flood = n_sent_direct = 0;
   n_recv_flood = n_recv_direct = 0;
+  memset(&mac_stats, 0, sizeof(mac_stats));
   _err_flags = 0;
   radio_nonrx_start = _ms->getMillis();
 
@@ -105,6 +106,8 @@ void Dispatcher::loop() {
       }
 
       _radio->onSendFinished();
+      mac_stats.tx_done++;
+      logMacEvent("tx_done", outbound, 2 + outbound->getPathByteLen() + outbound->payload_len, 0, 0, t, tx_budget_ms);
       logTx(outbound, 2 + outbound->getPathByteLen() + outbound->payload_len);
       if (outbound->isRouteFlood()) {
         n_sent_flood++;
@@ -117,6 +120,8 @@ void Dispatcher::loop() {
       MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): WARNING: outbound packed send timed out!", getLogDateTime());
 
       _radio->onSendFinished();
+      mac_stats.tx_timeout++;
+      logMacEvent("tx_timeout", outbound, 2 + outbound->getPathByteLen() + outbound->payload_len, 0, 0, 0, 0);
       logTxFail(outbound, 2 + outbound->getPathByteLen() + outbound->payload_len);
 
       releasePacket(outbound);  // return to pool
@@ -138,6 +143,7 @@ void Dispatcher::loop() {
   {
     Packet* pkt = _mgr->getNextInbound(_ms->getMillis());
     if (pkt) {
+      logMacEvent("rx_delay_done", pkt, pkt->getRawLength(), 0, 0, _radio->getEstAirtimeFor(pkt->getRawLength()), 0);
       processRecvPacket(pkt);
     }
   }
@@ -199,6 +205,7 @@ void Dispatcher::checkRecv() {
 
       pkt = _mgr->allocNew();
       if (pkt == NULL) {
+        mac_stats.pool_full++;
         MESH_DEBUG_PRINTLN("%s Dispatcher::checkRecv(): WARNING: received data, no unused packets available!", getLogDateTime());
       } else {
         if (tryParsePacket(pkt, raw, len)) {
@@ -248,6 +255,8 @@ void Dispatcher::checkRecv() {
         if (_delay > MAX_RX_DELAY_MILLIS) {
           _delay = MAX_RX_DELAY_MILLIS;
         }
+        mac_stats.rx_delay++;
+        logMacEvent("rx_delay", pkt, pkt->getRawLength(), 0, _delay, air_time, (uint32_t)(score * 1000));
         _mgr->queueInbound(pkt, futureMillis(_delay)); // add to delayed inbound queue
       }
     } else {
@@ -267,6 +276,8 @@ void Dispatcher::processRecvPacket(Packet* pkt) {
     uint8_t priority = (action >> 24) - 1;
     uint32_t _delay = action & 0xFFFFFF;
 
+    mac_stats.retransmit++;
+    logMacEvent("retransmit", pkt, pkt->getRawLength(), priority, _delay, _radio->getEstAirtimeFor(pkt->getRawLength()), 0);
     _mgr->queueOutbound(pkt, priority, futureMillis(_delay));
   }
 }
@@ -286,18 +297,25 @@ void Dispatcher::checkSend() {
 
   if (!millisHasNowPassed(next_tx_time)) return;
   if (_radio->isReceiving()) {
+    Packet* pending = _mgr->peekNextOutbound(_ms->getMillis());
     if (cad_busy_start == 0) {
       cad_busy_start = _ms->getMillis();   // record when CAD busy state started
     }
 
     if (_ms->getMillis() - cad_busy_start > getCADFailMaxDuration()) {
       _err_flags |= ERR_EVENT_CAD_TIMEOUT;
+      mac_stats.cad_timeout++;
+      mac_stats.cad_forced_tx++;
+      logMacEvent("cad_timeout", pending, pending ? pending->getRawLength() : 0, 0, 0, 0, _ms->getMillis() - cad_busy_start);
 
       MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): CAD busy max duration reached!", getLogDateTime());
       // channel activity has gone on too long... (Radio might be in a bad state)
       // force the pending transmit below...
     } else {
-      next_tx_time = futureMillis(getCADFailRetryDelay());
+      uint32_t retry_delay = getCADFailRetryDelay();
+      mac_stats.cad_busy++;
+      logMacEvent("cad_busy", pending, pending ? pending->getRawLength() : 0, 0, retry_delay, 0, _ms->getMillis() - cad_busy_start);
+      next_tx_time = futureMillis(retry_delay);
       return;
     }
   }
@@ -318,6 +336,8 @@ void Dispatcher::checkSend() {
 
     if (len + outbound->payload_len > MAX_TRANS_UNIT) {
       MESH_DEBUG_PRINTLN("%s Dispatcher::checkSend(): FATAL: Invalid packet queued... too long, len=%d", getLogDateTime(), len + outbound->payload_len);
+      mac_stats.invalid_queue++;
+      logMacEvent("invalid_queue", outbound, len + outbound->payload_len, 0, 0, 0, 0);
       _mgr->free(outbound);
       outbound = NULL;
     } else {
@@ -329,12 +349,16 @@ void Dispatcher::checkSend() {
       if (!success) {
         MESH_DEBUG_PRINTLN("%s Dispatcher::loop(): ERROR: send start failed!", getLogDateTime());
 
+        mac_stats.tx_start_fail++;
+        logMacEvent("tx_start_fail", outbound, outbound->getRawLength(), 0, 0, max_airtime, 0);
         logTxFail(outbound, outbound->getRawLength());
 
         releasePacket(outbound);  // return to pool
         outbound = NULL;
         return;
       }
+      mac_stats.tx_start++;
+      logMacEvent("tx_start", outbound, len, 0, 0, max_airtime, tx_budget_ms);
       outbound_expiry = futureMillis(max_airtime);
 
     #if MESH_PACKET_LOGGING
@@ -356,6 +380,7 @@ Packet* Dispatcher::obtainNewPacket() {
   auto pkt = _mgr->allocNew();  // TODO: zero out all fields
   if (pkt == NULL) {
     _err_flags |= ERR_EVENT_FULL;
+    mac_stats.pool_full++;
   } else {
     pkt->payload_len = pkt->path_len = 0;
     pkt->_snr = 0;
@@ -370,8 +395,11 @@ void Dispatcher::releasePacket(Packet* packet) {
 void Dispatcher::sendPacket(Packet* packet, uint8_t priority, uint32_t delay_millis) {
   if (!Packet::isValidPathLen(packet->path_len) || packet->payload_len > MAX_PACKET_PAYLOAD) {
     MESH_DEBUG_PRINTLN("%s Dispatcher::sendPacket(): ERROR: invalid packet... path_len=%d, payload_len=%d", getLogDateTime(), (uint32_t) packet->path_len, (uint32_t) packet->payload_len);
+    mac_stats.invalid_queue++;
+    logMacEvent("invalid_queue", packet, packet->getRawLength(), priority, delay_millis, 0, 0);
     _mgr->free(packet);
   } else {
+    logMacEvent("queue_tx", packet, packet->getRawLength(), priority, delay_millis, _radio->getEstAirtimeFor(packet->getRawLength()), _mgr->getOutboundTotal());
     _mgr->queueOutbound(packet, priority, futureMillis(delay_millis));
   }
 }
@@ -386,4 +414,4 @@ unsigned long Dispatcher::futureMillis(int millis_from_now) const {
   return _ms->getMillis() + millis_from_now;
 }
 
-}
+}

src/Dispatcher.h

@@ -89,6 +89,7 @@ class PacketManager {
 
   virtual void queueOutbound(Packet* packet, uint8_t priority, uint32_t scheduled_for) = 0;
   virtual Packet* getNextOutbound(uint32_t now) = 0;    // by priority
+  virtual Packet* peekNextOutbound(uint32_t now) { return NULL; }
   virtual int getOutboundCount(uint32_t now) const = 0;
   virtual int getOutboundTotal() const = 0;
   virtual int getFreeCount() const = 0;
@@ -109,6 +110,20 @@ typedef uint32_t  DispatcherAction;
 #define ERR_EVENT_CAD_TIMEOUT       (1 << 1)
 #define ERR_EVENT_STARTRX_TIMEOUT   (1 << 2)
 
+struct MacStats {
+  uint32_t cad_busy;
+  uint32_t cad_timeout;
+  uint32_t cad_forced_tx;
+  uint32_t tx_start;
+  uint32_t tx_done;
+  uint32_t tx_start_fail;
+  uint32_t tx_timeout;
+  uint32_t rx_delay;
+  uint32_t retransmit;
+  uint32_t pool_full;
+  uint32_t invalid_queue;
+};
+
 /**
  * \brief  The low-level task that manages detecting incoming Packets, and the queueing
  *      and scheduling of outbound Packets.
@@ -126,6 +141,7 @@ class Dispatcher {
   unsigned long tx_budget_ms;
   unsigned long last_budget_update;
   unsigned long duty_cycle_window_ms;
+  MacStats mac_stats;
 
   void processRecvPacket(Packet* pkt);
   void updateTxBudget();
@@ -159,6 +175,8 @@ class Dispatcher {
   virtual void logRx(Packet* packet, int len, float score) { }   // hooks for custom logging
   virtual void logTx(Packet* packet, int len) { }
   virtual void logTxFail(Packet* packet, int len) { }
+  virtual void logMacEvent(const char* event, Packet* packet, int len, uint8_t priority,
+                           uint32_t delay_millis, uint32_t airtime_millis, uint32_t value) { }
   virtual const char* getLogDateTime() { return ""; }
 
   virtual float getAirtimeBudgetFactor() const;
@@ -184,8 +202,10 @@ class Dispatcher {
   uint32_t getNumSentDirect() const { return n_sent_direct; }
   uint32_t getNumRecvFlood() const { return n_recv_flood; }
   uint32_t getNumRecvDirect() const { return n_recv_direct; }
+  const MacStats& getMacStats() const { return mac_stats; }
   void resetStats() {
     n_sent_flood = n_sent_direct = n_recv_flood = n_recv_direct = 0;
+    memset(&mac_stats, 0, sizeof(mac_stats));
     _err_flags = 0;
   }
 

src/helpers/CommonCLI.cpp

@@ -467,12 +467,16 @@ void CommonCLI::handleCommand(uint32_t sender_timestamp, char* command, char* re
     } else if (sender_timestamp == 0 && memcmp(command, "log", 3) == 0) {
       _callbacks->dumpLogFile();
       strcpy(reply, "   EOF");
-    } else if (sender_timestamp == 0 && memcmp(command, "stats-packets", 13) == 0 && (command[13] == 0 || command[13] == ' ')) {
+    } else if (memcmp(command, "stats-packets", 13) == 0 && (command[13] == 0 || command[13] == ' ')) {
       _callbacks->formatPacketStatsReply(reply);
-    } else if (sender_timestamp == 0 && memcmp(command, "stats-radio", 11) == 0 && (command[11] == 0 || command[11] == ' ')) {
+    } else if (memcmp(command, "stats-radio", 11) == 0 && (command[11] == 0 || command[11] == ' ')) {
       _callbacks->formatRadioStatsReply(reply);
-    } else if (sender_timestamp == 0 && memcmp(command, "stats-core", 10) == 0 && (command[10] == 0 || command[10] == ' ')) {
+    } else if (memcmp(command, "stats-core", 10) == 0 && (command[10] == 0 || command[10] == ' ')) {
       _callbacks->formatStatsReply(reply);
+    } else if (memcmp(command, "stats-mac-cad", 13) == 0 && (command[13] == 0 || command[13] == ' ')) {
+      _callbacks->formatMacCadStatsReply(reply);
+    } else if (memcmp(command, "stats-mac-tx", 12) == 0 && (command[12] == 0 || command[12] == ' ')) {
+      _callbacks->formatMacTxStatsReply(reply);
     } else {
       strcpy(reply, "Unknown command");
     }

src/helpers/CommonCLI.h

@@ -5,6 +5,7 @@
 #include <helpers/SensorManager.h>
 #include <helpers/ClientACL.h>
 #include <helpers/RegionMap.h>
+#include <string.h>
 
 #if defined(WITH_RS232_BRIDGE) || defined(WITH_ESPNOW_BRIDGE)
 #define WITH_BRIDGE
@@ -86,6 +87,12 @@ class CommonCLICallbacks {
   virtual void formatStatsReply(char *reply) = 0;
   virtual void formatRadioStatsReply(char *reply) = 0;
   virtual void formatPacketStatsReply(char *reply) = 0;
+  virtual void formatMacCadStatsReply(char *reply) {
+    strcpy(reply, "unsupported");
+  }
+  virtual void formatMacTxStatsReply(char *reply) {
+    strcpy(reply, "unsupported");
+  }
   virtual mesh::LocalIdentity& getSelfId() = 0;
   virtual void saveIdentity(const mesh::LocalIdentity& new_id) = 0;
   virtual void clearStats() = 0;

src/helpers/StaticPoolPacketManager.cpp

@@ -43,6 +43,19 @@ mesh::Packet* PacketQueue::get(uint32_t now) {
   return top;
 }
 
+mesh::Packet* PacketQueue::peek(uint32_t now) const {
+  uint8_t min_pri = 0xFF;
+  int best_idx = -1;
+  for (int j = 0; j < _num; j++) {
+    if ((int32_t)(_schedule_table[j] - now) > 0) continue;   // scheduled for future... ignore for now
+    if (_pri_table[j] < min_pri) {  // select most important priority amongst non-future entries
+      min_pri = _pri_table[j];
+      best_idx = j;
+    }
+  }
+  return best_idx < 0 ? NULL : _table[best_idx];
+}
+
 mesh::Packet* PacketQueue::removeByIdx(int i) {
   if (i >= _num) return NULL;  // invalid index
 
@@ -95,6 +108,10 @@ mesh::Packet* StaticPoolPacketManager::getNextOutbound(uint32_t now) {
   return send_queue.get(now);
 }
 
+mesh::Packet* StaticPoolPacketManager::peekNextOutbound(uint32_t now) {
+  return send_queue.peek(now);
+}
+
 int  StaticPoolPacketManager::getOutboundCount(uint32_t now) const {
   return send_queue.countBefore(now);
 }