Merge pull request #772 from SignalK/instrumentation

Improve instrumentation

README.md

@@ -76,6 +76,9 @@
   leaks or crashes due to dangling pointers. It is also possible, but not
   mandatory, to use smart pointers in your own code.
 
+- Internal instrumentation has been improved. Web user interface status page
+  now shows memory usage and event loop statistics.
+
 ### Migrating Existing Projects
 
 - Update your project's `platformio.ini` file to use the new version of SensESP:

library.json

@@ -28,7 +28,7 @@
     {
       "owner": "mairas",
       "name": "ReactESP",
-      "version": "^3.0.1"
+      "version": "^3.1.0"
     },
     {
       "owner": "bblanchon",

platformio.ini

@@ -30,7 +30,7 @@ upload_speed = 2000000
 monitor_speed = 115200
 
 lib_deps =
-  mairas/ReactESP @ ^3.0.0
+  mairas/ReactESP @ ^3.1.0
   bblanchon/ArduinoJson @ ^7.0.0
   pfeerick/elapsedMillis @ ^1.0.6
   bxparks/AceButton @ ^1.10.1

src/sensesp/sensors/digital_input.h

@@ -57,7 +57,8 @@ class DigitalInputState : public DigitalInput, public Sensor<bool> {
         triggered_{false} {
     load();
 
-    event_loop()->onRepeat(read_delay_, [this]() { emit(digitalRead(pin_)); });
+    event_loop()->onRepeat(read_delay_,
+                           [this]() { this->emit(digitalRead(pin_)); });
   }
 
  private:

src/sensesp/sensors/system_info.cpp

@@ -8,17 +8,17 @@
 
 namespace sensesp {
 
-void SystemHz::tick() { tick_count_++; }
-
 void SystemHz::update() {
   // getting sporadic divide by 0 exceptions, no harm in skipping a loop.
   if (elapsed_millis_ == 0) {
     return;
   }
 
-  output_ = (tick_count_ * 1000) / elapsed_millis_;
+  uint32_t current_tick_count_ = event_loop()->getTickCount();
+  output_ =
+      (current_tick_count_ - last_tick_count_) / (elapsed_millis_ / 1000.);
 
-  tick_count_ = 0;
+  last_tick_count_ = current_tick_count_;
   elapsed_millis_ = 0;
 
   this->notify();

src/sensesp/sensors/system_info.h

@@ -48,16 +48,13 @@ class SystemHz : public ValueProducer<float> {
  public:
   SystemHz() {
     elapsed_millis_ = 0;
-
-    event_loop()->onTick([this]() { this->tick(); });
     event_loop()->onRepeat(1000, [this]() { this->update(); });
   }
   String get_value_name() { return "systemhz"; }
 
  protected:
-  uint32_t tick_count_ = 0;
+  uint32_t last_tick_count_ = 0;
   elapsedMillis elapsed_millis_;
-  void tick();
   void update();
 };
 

src/sensesp/system/semaphore_value.h

@@ -3,7 +3,7 @@
 
 #include "sensesp.h"
 
-#include <freeRTOS/semphr.h>
+#include <freertos/semphr.h>
 
 namespace sensesp {
 

src/sensesp/transforms/curveinterpolator.h

@@ -88,7 +88,7 @@ class CurveInterpolator : public FloatTransform {
   friend const char* ConfigSchema(const CurveInterpolator& obj);
 };
 
-const char* ConfigSchema(const CurveInterpolator& obj) {
+inline const char* ConfigSchema(const CurveInterpolator& obj) {
   static const char schema[] = R"({"type":"object","properties":{"samples":{"title":"Sample values","type":"array","format":"table","items":{"type":"object","properties":{"input":{"type":"number","title":"%s"},"output":{"type":"number","title":"%s"}}}}}})";
   static char buf[sizeof(schema) + 160];
   snprintf(buf, sizeof(buf), schema, obj.input_title_.c_str(),

src/sensesp/transforms/repeat.h

@@ -3,8 +3,8 @@
 
 #include <elapsedMillis.h>
 
-#include "sensesp_base_app.h"
 #include "sensesp/types/nullable.h"
+#include "sensesp_base_app.h"
 #include "transform.h"
 
 namespace sensesp {
@@ -27,16 +27,20 @@ namespace sensesp {
 template <typename FROM, typename TO>
 class Repeat : public Transform<FROM, TO> {
  public:
-  Repeat(unsigned long interval) : Transform<FROM, TO>(), interval_{interval} {}
+  Repeat(unsigned long interval) : Transform<FROM, TO>(), interval_{interval} {
+    if (interval_ == 0) {
+      ESP_LOGW("Repeat", "Interval is 0. This will cause a busy loop.");
+    }
+  }
 
   virtual void set(const FROM& input) override {
     this->emit(input);
     if (repeat_event_ != nullptr) {
       // Delete the old repeat event
       repeat_event_->remove(event_loop());
     }
-    repeat_event_ = event_loop()->onRepeat(
-        interval_, [this]() { this->notify(); });
+    repeat_event_ =
+        event_loop()->onRepeat(interval_, [this]() { this->notify(); });
   }
 
  protected:
@@ -107,8 +111,11 @@ class RepeatStopping : public Repeat<T, T> {
 template <typename T>
 class RepeatExpiring : public Repeat<T, Nullable<T>> {
  public:
-    RepeatExpiring(unsigned long interval, unsigned long max_age)
+  RepeatExpiring(unsigned long interval, unsigned long max_age)
       : Repeat<T, Nullable<T>>(interval), max_age_{max_age} {
+    ESP_LOGD("RepeatExpiring", "interval: %lu, max_age: %lu", interval,
+             max_age);
+
     age_ = max_age;
 
     if (this->repeat_event_ != nullptr) {
@@ -167,8 +174,8 @@ class RepeatConstantRate : public RepeatExpiring<T> {
       this->repeat_event_->remove();
     }
 
-    this->repeat_event_ = event_loop()->onRepeat(
-        interval, [this]() { this->repeat_function(); });
+    this->repeat_event_ =
+        event_loop()->onRepeat(interval, [this]() { this->repeat_function(); });
   }
 
   void set(T input) override {

src/sensesp_app.h

@@ -219,21 +219,74 @@ class SensESPApp : public SensESPBaseApp {
     connect_status_page_items();
   }
 
+  // Collect metrics for the status page
   void connect_status_page_items() {
     this->hostname_->connect_to(&this->hostname_ui_output_);
-    this->event_loop_.onRepeat(
-        4999, [this]() { wifi_ssid_ui_output_.set(WiFi.SSID()); });
-    this->event_loop_.onRepeat(
-        4998, [this]() { free_memory_ui_output_.set(ESP.getFreeHeap()); });
-    this->event_loop_.onRepeat(
-        4997, [this]() { wifi_rssi_ui_output_.set(WiFi.RSSI()); });
-    this->event_loop_.onRepeat(4996, [this]() {
+    this->event_loop_.onRepeat(4999, [this]() {
+      wifi_ssid_ui_output_.set(WiFi.SSID());
+      free_memory_ui_output_.set(ESP.getFreeHeap());
+      wifi_rssi_ui_output_.set(WiFi.RSSI());
+
+      // Uptime
+      uptime_ui_output_.set(millis() / 1000);
+
+      // Event loop queue sizes
+      int event_loop_queue_size = event_loop_.getEventQueueSize();
+      int event_loop_timed_queue_size = event_loop_.getTimedEventQueueSize();
+      int event_loop_untimed_queue_size =
+          event_loop_.getUntimedEventQueueSize();
+
+      // Total tick count
+      uint64_t current_tick_count = event_loop_.getTickCount();
+      total_tick_count_ui_output_.set(current_tick_count);
+
+      // Event counts
+      uint64_t current_event_count = event_loop_.getEventCount();
+      uint64_t current_timed_event_count = event_loop_.getTimedEventCount();
+      uint64_t current_untimed_event_count = event_loop_.getUntimedEventCount();
+      event_count_ui_output_.set(current_event_count);
+      timed_event_count_ui_output_.set(current_timed_event_count);
+      untimed_event_count_ui_output_.set(current_untimed_event_count);
+
+      // Ticks and events per second during last interval
+      static uint64_t last_tick_count = 0;
+      static uint64_t last_event_count = 0;
+      static uint64_t last_timed_event_count = 0;
+      static uint64_t last_untimed_event_count = 0;
+      static uint64_t last_millis = 0;
+      uint64_t current_millis = millis();
+      float interval_seconds = (current_millis - last_millis) / 1000.0;
+
+      uint64_t ticks_diff = current_tick_count - last_tick_count;
+      uint64_t events_diff = current_event_count - last_event_count;
+      uint64_t timed_events_diff =
+          current_timed_event_count - last_timed_event_count;
+      uint64_t untimed_events_diff =
+          current_untimed_event_count - last_untimed_event_count;
+
+      // Set outputs
+      event_loop_queue_size_ui_output_.set(event_loop_queue_size);
+      event_loop_timed_queue_ui_output_.set(event_loop_timed_queue_size);
+      event_loop_untimed_queue_ui_output_.set(event_loop_untimed_queue_size);
+      event_loop_interrupt_queue_ui_output_.set(
+          event_loop_.getISREventQueueSize());
+
+      ticks_per_second_ui_output_.set(int(ticks_diff / interval_seconds));
+      events_per_second_ui_output_.set(int(events_diff / interval_seconds));
+      timed_events_per_second_ui_output_.set(
+          int(timed_events_diff / interval_seconds));
+      untimed_events_per_second_ui_output_.set(
+          int(untimed_events_diff / interval_seconds));
+
+      // Update last values
+      last_tick_count = current_tick_count;
+      last_event_count = current_event_count;
+      last_timed_event_count = current_timed_event_count;
+      last_untimed_event_count = current_untimed_event_count;
+      last_millis = current_millis;
+
       sk_server_address_ui_output_.set(ws_client_->get_server_address());
-    });
-    this->event_loop_.onRepeat(4995, [this]() {
       sk_server_port_ui_output_.set(ws_client_->get_server_port());
-    });
-    this->event_loop_.onRepeat(4994, [this]() {
       sk_server_connection_ui_output_.set(ws_client_->get_connection_status());
     });
     ws_client_->get_delta_tx_count_producer().connect_to(
@@ -265,35 +318,66 @@ class SensESPApp : public SensESPBaseApp {
   std::shared_ptr<SKDeltaQueue> sk_delta_queue_;
   std::shared_ptr<SKWSClient> ws_client_;
 
-  StatusPageItem<String> sensesp_version_ui_output_{
-      "SenseESP version", kSensESPVersion, "Software", 1900};
-  StatusPageItem<String> build_info_ui_output_{
-      "Build date", __DATE__ " " __TIME__, "Software", 2000};
-  StatusPageItem<String> hostname_ui_output_{"Hostname", "", "Network", 500};
-  StatusPageItem<String> mac_address_ui_output_{
-      "MAC Address", WiFi.macAddress(), "Network", 1100};
-  StatusPageItem<String> wifi_ssid_ui_output_{"SSID", "", "Network", 1200};
   StatusPageItem<int> free_memory_ui_output_{"Free memory (bytes)", 0, "System",
-                                             1250};
+                                             1000};
+  StatusPageItem<int> uptime_ui_output_{"Uptime (s)", 0, "System", 1100};
+
+  StatusPageItem<String> hostname_ui_output_{"Hostname", "", "Network", 1200};
+  StatusPageItem<String> mac_address_ui_output_{
+      "MAC Address", WiFi.macAddress(), "Network", 1300};
+  StatusPageItem<String> wifi_ssid_ui_output_{"SSID", "", "Network", 1400};
+
   StatusPageItem<int8_t> wifi_rssi_ui_output_{"WiFi signal strength (dB)", -128,
-                                              "Network", 1300};
+                                              "Network", 1500};
+
   StatusPageItem<String> sk_server_address_ui_output_{"Signal K server address",
-                                                      "", "Signal K", 1400};
+                                                      "", "Signal K", 1600};
   StatusPageItem<uint16_t> sk_server_port_ui_output_{"Signal K server port", 0,
-                                                     "Signal K", 1500};
+                                                     "Signal K", 1700};
   StatusPageItem<String> sk_server_connection_ui_output_{"SK connection status",
-                                                         "", "Signal K", 1600};
+                                                         "", "Signal K", 1800};
   StatusPageItem<int> delta_tx_count_ui_output_{"SK Delta TX count", 0,
-                                                "Signal K", 1700};
+                                                "Signal K", 1900};
   StatusPageItem<int> delta_rx_count_ui_output_{"SK Delta RX count", 0,
-                                                "Signal K", 1800};
-
-// Placeholders for system status sensors in case they are created
-std::shared_ptr<ValueProducer<float>> system_hz_sensor_;
-std::shared_ptr<ValueProducer<uint32_t>> free_mem_sensor_;
-std::shared_ptr<ValueProducer<float>> uptime_sensor_;
-std::shared_ptr<ValueProducer<String>> ip_address_sensor_;
-std::shared_ptr<ValueProducer<int>> wifi_signal_sensor_;
+                                                "Signal K", 2000};
+
+  StatusPageItem<int> event_loop_queue_size_ui_output_{
+      "Event Loop queue size", 0, "Event Loop Queues", 2100};
+  StatusPageItem<int> event_loop_timed_queue_ui_output_{
+      "Event Loop timed queue size", 0, "Event Loop Queues", 2200};
+  StatusPageItem<int> event_loop_untimed_queue_ui_output_{
+      "Event Loop untimed queue size", 0, "Event Loop Queues", 2300};
+  StatusPageItem<int> event_loop_interrupt_queue_ui_output_{
+      "Event Loop interrupt queue size", 0, "Event Loop Queues", 2400};
+
+  StatusPageItem<uint64_t> total_tick_count_ui_output_{
+      "Total ticks processed", 0, "Event Loop Lifetime", 2500};
+  StatusPageItem<uint64_t> event_count_ui_output_{"Events processed", 0,
+                                                  "Event Loop Lifetime", 2600};
+  StatusPageItem<uint64_t> timed_event_count_ui_output_{
+      "Timed events processed", 0, "Event Loop Lifetime", 2700};
+  StatusPageItem<uint64_t> untimed_event_count_ui_output_{
+      "Untimed events processed", 0, "Event Loop Lifetime", 2800};
+  StatusPageItem<float> ticks_per_second_ui_output_{
+      "Ticks per second", 0, "Event Loop Performance", 2900};
+  StatusPageItem<float> events_per_second_ui_output_{
+      "Events per second", 0, "Event Loop Performance", 3000};
+  StatusPageItem<float> timed_events_per_second_ui_output_{
+      "Timed events per second", 0, "Event Loop Performance", 3100};
+  StatusPageItem<float> untimed_events_per_second_ui_output_{
+      "Untimed events per second", 0, "Event Loop Performance", 3200};
+
+  StatusPageItem<String> sensesp_version_ui_output_{
+      "SenseESP version", kSensESPVersion, "Software", 3300};
+  StatusPageItem<String> build_info_ui_output_{
+      "Build date", __DATE__ " " __TIME__, "Software", 3400};
+
+  // Placeholders for system status sensors in case they are created
+  std::shared_ptr<ValueProducer<float>> system_hz_sensor_;
+  std::shared_ptr<ValueProducer<uint32_t>> free_mem_sensor_;
+  std::shared_ptr<ValueProducer<float>> uptime_sensor_;
+  std::shared_ptr<ValueProducer<String>> ip_address_sensor_;
+  std::shared_ptr<ValueProducer<int>> wifi_signal_sensor_;
 
   friend class WebServer;
   friend class SensESPAppBuilder;