Merge pull request #63 from cjkas/feat/loop-health

feat: report main-loop health in memStatus

src/ESPNetwork.cpp

@@ -28,6 +28,7 @@ extern MqttConnection mqtt;
 extern rebootDelay_t rebootDelay;
 extern ESPNetwork net;
 extern SomfyShadeController somfy;
+extern LoopStats loopStats;
 
 static unsigned long _lastHeapEmit = 0;
 
@@ -680,8 +681,15 @@ void ESPNetwork::emitHeap(uint8_t num) {
   json->addElem("min", minHeap);
   json->addElem("total", ESP.getHeapSize());
   json->addElem("uptime", (uint64_t)millis());
+  // The window in progress.  Only a broadcast closes it, so a client
+  // connecting doesn't wipe a slow pass before Home Assistant has seen it.
+  json->addElem("loopRate", loopStats.rate(millis()));
+  json->addElem("loopMaxUs", loopStats.maxUs());
   json->endObject();
   if(target == heap_emit_t::room) sockEmit.endEmitRoom(0);
   else sockEmit.endEmit(num);
-  if(target == heap_emit_t::broadcast) _lastHeapEmit = millis();
+  if(target == heap_emit_t::broadcast) {
+    _lastHeapEmit = millis();
+    loopStats.publish(_lastHeapEmit);
+  }
 }

src/SomfyController.ino

@@ -41,6 +41,7 @@ SomfyShadeOps shadeOps;
 ShadeRequests shadeRequests(shadeOps);
 LoopQueue loopQueue;
 SnapshotSlots snapshotSlots;
+LoopStats loopStats;
 
 uint32_t oldheap = 0;
 
@@ -141,6 +142,9 @@ void setup() {
 void loop() {
   // put your main code here, to run repeatedly:
   //uint32_t heap = ESP.getFreeHeap();
+  // Times the whole pass for memStatus, including any time the loop task was
+  // pre-empted, since that delays the loop too.
+  ElapsedTimer pass;
   if(rebootDelay.reboot && millis() > rebootDelay.rebootTime) {
     ESP_LOGI(TAG, "Rebooting after %lums", rebootDelay.rebootTime);
     net.end();
@@ -180,4 +184,5 @@ void loop() {
     ESP.restart();
   }
   esp_task_wdt_reset();
+  loopStats.record(pass.us());
 }

src/Utils.cpp

@@ -152,3 +152,20 @@ heap_emit_t heapEmitTarget(uint8_t num, uint32_t sinceLastMs, uint32_t intervalM
   if(sinceLastMs >= intervalMs) return heap_emit_t::broadcast;
   return roomHasClients ? heap_emit_t::room : heap_emit_t::none;
 }
+void LoopStats::record(uint32_t passUs) {
+  _passes++;
+  if(passUs > _maxUs) _maxUs = passUs;
+}
+uint32_t LoopStats::rate(uint32_t nowMs) const {
+  // The unsigned subtraction keeps the window right across a millis() wrap.
+  const uint32_t elapsedMs = nowMs - _startMs;
+  if(elapsedMs == 0) return 0;
+  return (uint32_t)((uint64_t)_passes * 1000 / elapsedMs);
+}
+void LoopStats::publish(uint32_t nowMs) {
+  _publishedRate.store(this->rate(nowMs), std::memory_order_relaxed);
+  _publishedMaxUs.store(_maxUs, std::memory_order_relaxed);
+  _passes = 0;
+  _maxUs = 0;
+  _startMs = nowMs;
+}

src/Utils.h

@@ -1,6 +1,7 @@
 #ifndef utils_h
 #define utils_h
 #include <Arduino.h>
+#include <atomic>
 
 
 #define DEBUG_SOMFY Serial
@@ -78,6 +79,26 @@ enum class heap_emit_t : uint8_t { none, client, broadcast, room };
 // num is the socket client asked for, 255 for everyone.  A broadcast goes out
 // every intervalMs; in between only the clients in room 0 get one.
 heap_emit_t heapEmitTarget(uint8_t num, uint32_t sinceLastMs, uint32_t intervalMs, bool roomHasClients);
+// How well loop() keeps up: the passes it made per second and its longest
+// pass, over the window since the last memStatus broadcast.  Only the loop
+// task calls record(), rate(), maxUs() and publish().  publish() closes the
+// window and keeps its figures where another task (the /discovery response)
+// can read them without seeing a half reset window.
+class LoopStats {
+  uint32_t _passes = 0;
+  uint32_t _maxUs = 0;
+  uint32_t _startMs = 0;
+  std::atomic<uint32_t> _publishedRate{0};
+  std::atomic<uint32_t> _publishedMaxUs{0};
+  public:
+    void record(uint32_t passUs);
+    // Passes per second since the window started, 0 for an empty window.
+    uint32_t rate(uint32_t nowMs) const;
+    uint32_t maxUs() const { return _maxUs; }
+    void publish(uint32_t nowMs);
+    uint32_t publishedRate() const { return _publishedRate.load(std::memory_order_relaxed); }
+    uint32_t publishedMaxUs() const { return _publishedMaxUs.load(std::memory_order_relaxed); }
+};
 
 class Timestamp {
   char _timeBuffer[128];

src/entryPoints/Web.cpp

@@ -28,6 +28,7 @@
 extern ConfigSettings settings;
 extern SSDPClass SSDP;
 extern rebootDelay_t rebootDelay;
+extern LoopStats loopStats;
 extern SomfyShadeController somfy;
 extern Web webServer;
 extern MqttConnection mqtt;
@@ -276,6 +277,10 @@ static void discoveryHeader(JsonFormatter &json, const model_snapshot_t &snap) {
   json.addElem("min", ESP.getMinFreeHeap());
   json.addElem("total", ESP.getHeapSize());
   json.addElem("uptime", (uint64_t)millis());
+  // This runs on the web server's task, so it reports the last window the
+  // loop task closed rather than reading the one it is still filling.
+  json.addElem("loopRate", loopStats.publishedRate());
+  json.addElem("loopMaxUs", loopStats.publishedMaxUs());
   json.endObject();
 }
 

test/test_utils/test_utils.cpp

@@ -272,6 +272,64 @@ static void test_heapEmitTarget_broadcasts_once_per_interval() {
 static void test_heapEmitTarget_room_in_between() {
   TEST_ASSERT_TRUE(heap_emit_t::room == heapEmitTarget(255, 1000, 30000, true));
 }
+
+/*********************************************************************
+ * LoopStats
+ ********************************************************************/
+static void test_loopStats_rate_is_passes_per_second() {
+  LoopStats stats;
+  for(int i = 0; i < 4500; i++) stats.record(100);
+  TEST_ASSERT_EQUAL_UINT32(1500, stats.rate(3000));
+}
+static void test_loopStats_empty_window_has_no_rate() {
+  LoopStats stats;
+  stats.record(100);
+  TEST_ASSERT_EQUAL_UINT32(0, stats.rate(0));
+}
+static void test_loopStats_keeps_the_longest_pass() {
+  LoopStats stats;
+  stats.record(120);
+  stats.record(4800);
+  stats.record(90);
+  TEST_ASSERT_EQUAL_UINT32(4800, stats.maxUs());
+}
+static void test_loopStats_nothing_published_before_the_first_window() {
+  LoopStats stats;
+  stats.record(4800);
+  TEST_ASSERT_EQUAL_UINT32(0, stats.publishedRate());
+  TEST_ASSERT_EQUAL_UINT32(0, stats.publishedMaxUs());
+}
+static void test_loopStats_publish_keeps_the_window_and_starts_a_new_one() {
+  LoopStats stats;
+  for(int i = 0; i < 300; i++) stats.record(100);
+  stats.record(4800);
+  stats.publish(1000);
+  TEST_ASSERT_EQUAL_UINT32(301, stats.publishedRate());
+  TEST_ASSERT_EQUAL_UINT32(4800, stats.publishedMaxUs());
+  TEST_ASSERT_EQUAL_UINT32(0, stats.rate(1000));
+  TEST_ASSERT_EQUAL_UINT32(0, stats.maxUs());
+  for(int i = 0; i < 50; i++) stats.record(200);
+  // The new window started at the publish, not at boot.
+  TEST_ASSERT_EQUAL_UINT32(100, stats.rate(1500));
+  TEST_ASSERT_EQUAL_UINT32(200, stats.maxUs());
+  TEST_ASSERT_EQUAL_UINT32(301, stats.publishedRate());
+}
+static void test_loopStats_reading_does_not_reset_the_window() {
+  LoopStats stats;
+  stats.record(4800);
+  (void)stats.rate(500);
+  (void)stats.maxUs();
+  stats.record(100);
+  TEST_ASSERT_EQUAL_UINT32(4800, stats.maxUs());
+  TEST_ASSERT_EQUAL_UINT32(2, stats.rate(1000));
+}
+static void test_loopStats_window_across_millis_wrap() {
+  LoopStats stats;
+  stats.publish(0xFFFFFE00);
+  for(int i = 0; i < 1024; i++) stats.record(100);
+  // 0x200 ms before the wrap plus 0x200 after it is 1024 ms.
+  TEST_ASSERT_EQUAL_UINT32(1000, stats.rate(0x00000200));
+}
 int main(int argc, char **argv) {
   (void)argc;
   (void)argv;
@@ -314,5 +372,12 @@ int main(int argc, char **argv) {
   RUN_TEST(test_heapEmitTarget_one_client_always_gets_it);
   RUN_TEST(test_heapEmitTarget_broadcasts_once_per_interval);
   RUN_TEST(test_heapEmitTarget_room_in_between);
+  RUN_TEST(test_loopStats_rate_is_passes_per_second);
+  RUN_TEST(test_loopStats_empty_window_has_no_rate);
+  RUN_TEST(test_loopStats_keeps_the_longest_pass);
+  RUN_TEST(test_loopStats_nothing_published_before_the_first_window);
+  RUN_TEST(test_loopStats_publish_keeps_the_window_and_starts_a_new_one);
+  RUN_TEST(test_loopStats_reading_does_not_reset_the_window);
+  RUN_TEST(test_loopStats_window_across_millis_wrap);
   return UNITY_END();
 }