Merge branch 'socket_latency' into socket_latency_loop_runtime_stats

esphome/components/runtime_stats/__init__.py

@@ -0,0 +1,26 @@
+"""
+Runtime statistics component for ESPHome.
+"""
+
+import esphome.codegen as cg
+import esphome.config_validation as cv
+
+DEPENDENCIES = []
+
+CONF_ENABLED = "enabled"
+CONF_LOG_INTERVAL = "log_interval"
+
+CONFIG_SCHEMA = cv.Schema(
+    {
+        cv.Optional(CONF_ENABLED, default=True): cv.boolean,
+        cv.Optional(
+            CONF_LOG_INTERVAL, default=60000
+        ): cv.positive_time_period_milliseconds,
+    }
+)
+
+
+async def to_code(config):
+    """Generate code for the runtime statistics component."""
+    cg.add(cg.App.set_runtime_stats_enabled(config[CONF_ENABLED]))
+    cg.add(cg.App.set_runtime_stats_log_interval(config[CONF_LOG_INTERVAL]))

esphome/components/socket/__init__.py

@@ -35,5 +35,7 @@ async def to_code(config):
         cg.add_define("USE_SOCKET_IMPL_LWIP_TCP")
     elif impl == IMPLEMENTATION_LWIP_SOCKETS:
         cg.add_define("USE_SOCKET_IMPL_LWIP_SOCKETS")
+        cg.add_define("USE_SOCKET_SELECT_SUPPORT")
     elif impl == IMPLEMENTATION_BSD_SOCKETS:
         cg.add_define("USE_SOCKET_IMPL_BSD_SOCKETS")
+        cg.add_define("USE_SOCKET_SELECT_SUPPORT")

esphome/components/socket/bsd_sockets_impl.cpp

@@ -42,6 +42,7 @@ std::string format_sockaddr(const struct sockaddr_storage &storage) {
 class BSDSocketImpl : public Socket {
  public:
   BSDSocketImpl(int fd, bool monitor_loop = false) : fd_(fd) {
+#ifdef USE_SOCKET_SELECT_SUPPORT
     // Register new socket with the application for select() if monitoring requested
     if (monitor_loop && fd_ >= 0) {
       // Only set loop_monitored_ to true if registration succeeds
@@ -49,6 +50,10 @@ class BSDSocketImpl : public Socket {
     } else {
       loop_monitored_ = false;
     }
+#else
+    // Without select support, ignore monitor_loop parameter
+    (void) monitor_loop;
+#endif
   }
   ~BSDSocketImpl() override {
     if (!closed_) {
@@ -57,14 +62,14 @@ class BSDSocketImpl : public Socket {
   }
   int connect(const struct sockaddr *addr, socklen_t addrlen) override { return ::connect(fd_, addr, addrlen); }
   std::unique_ptr<Socket> accept(struct sockaddr *addr, socklen_t *addrlen) override {
-    return accept_impl(addr, addrlen, false);
+    return accept_impl_(addr, addrlen, false);
   }
   std::unique_ptr<Socket> accept_loop_monitored(struct sockaddr *addr, socklen_t *addrlen) override {
-    return accept_impl(addr, addrlen, true);
+    return accept_impl_(addr, addrlen, true);
   }
 
  private:
-  std::unique_ptr<Socket> accept_impl(struct sockaddr *addr, socklen_t *addrlen, bool loop_monitored) {
+  std::unique_ptr<Socket> accept_impl_(struct sockaddr *addr, socklen_t *addrlen, bool loop_monitored) {
     int fd = ::accept(fd_, addr, addrlen);
     if (fd == -1)
       return {};
@@ -75,10 +80,12 @@ class BSDSocketImpl : public Socket {
   int bind(const struct sockaddr *addr, socklen_t addrlen) override { return ::bind(fd_, addr, addrlen); }
   int close() override {
     if (!closed_) {
+#ifdef USE_SOCKET_SELECT_SUPPORT
       // Unregister from select() before closing if monitored
       if (loop_monitored_) {
         App.unregister_socket_fd(fd_);
       }
+#endif
       int ret = ::close(fd_);
       closed_ = true;
       return ret;

esphome/components/socket/lwip_sockets_impl.cpp

@@ -35,6 +35,7 @@ std::string format_sockaddr(const struct sockaddr_storage &storage) {
 class LwIPSocketImpl : public Socket {
  public:
   LwIPSocketImpl(int fd, bool monitor_loop = false) : fd_(fd) {
+#ifdef USE_SOCKET_SELECT_SUPPORT
     // Register new socket with the application for select() if monitoring requested
     if (monitor_loop && fd_ >= 0) {
       // Only set loop_monitored_ to true if registration succeeds
@@ -42,6 +43,10 @@ class LwIPSocketImpl : public Socket {
     } else {
       loop_monitored_ = false;
     }
+#else
+    // Without select support, ignore monitor_loop parameter
+    (void) monitor_loop;
+#endif
   }
   ~LwIPSocketImpl() override {
     if (!closed_) {
@@ -50,14 +55,14 @@ class LwIPSocketImpl : public Socket {
   }
   int connect(const struct sockaddr *addr, socklen_t addrlen) override { return lwip_connect(fd_, addr, addrlen); }
   std::unique_ptr<Socket> accept(struct sockaddr *addr, socklen_t *addrlen) override {
-    return accept_impl(addr, addrlen, false);
+    return accept_impl_(addr, addrlen, false);
   }
   std::unique_ptr<Socket> accept_loop_monitored(struct sockaddr *addr, socklen_t *addrlen) override {
-    return accept_impl(addr, addrlen, true);
+    return accept_impl_(addr, addrlen, true);
   }
 
  private:
-  std::unique_ptr<Socket> accept_impl(struct sockaddr *addr, socklen_t *addrlen, bool loop_monitored) {
+  std::unique_ptr<Socket> accept_impl_(struct sockaddr *addr, socklen_t *addrlen, bool loop_monitored) {
     int fd = lwip_accept(fd_, addr, addrlen);
     if (fd == -1)
       return {};
@@ -68,10 +73,12 @@ class LwIPSocketImpl : public Socket {
   int bind(const struct sockaddr *addr, socklen_t addrlen) override { return lwip_bind(fd_, addr, addrlen); }
   int close() override {
     if (!closed_) {
+#ifdef USE_SOCKET_SELECT_SUPPORT
       // Unregister from select() before closing if monitored
       if (loop_monitored_) {
         App.unregister_socket_fd(fd_);
       }
+#endif
       int ret = lwip_close(fd_);
       closed_ = true;
       return ret;

esphome/components/socket/socket.cpp

@@ -12,6 +12,7 @@ namespace socket {
 Socket::~Socket() {}
 
 bool Socket::ready() const {
+#ifdef USE_SOCKET_SELECT_SUPPORT
   if (!loop_monitored_) {
     // Non-monitored sockets always return true (assume data may be available)
     return true;
@@ -25,6 +26,11 @@ bool Socket::ready() const {
   }
 
   return App.is_socket_ready(fd);
+#else
+  // Without select() support, we can't monitor sockets in the loop
+  // Always return true (assume data may be available)
+  return true;
+#endif
 }
 
 std::unique_ptr<Socket> socket_ip(int type, int protocol) {

esphome/components/socket/socket.h

@@ -59,7 +59,9 @@ class Socket {
   bool ready() const;
 
  protected:
+#ifdef USE_SOCKET_SELECT_SUPPORT
   bool loop_monitored_{false};  ///< Whether this socket is monitored by the event loop
+#endif
 };
 
 /// Create a socket of the given domain, type and protocol.

esphome/core/application.cpp

@@ -2,25 +2,29 @@
 #include "esphome/core/log.h"
 #include "esphome/core/version.h"
 #include "esphome/core/hal.h"
+#include <algorithm>
 
 #ifdef USE_STATUS_LED
 #include "esphome/components/status_led/status_led.h"
 #endif
 
-#ifdef FD_SETSIZE
+#ifdef USE_SOCKET_SELECT_SUPPORT
 #include <cerrno>
-#ifdef USE_ESP32
-#include <sys/select.h>
-#elif defined(USE_ESP8266)
-#include <sys/time.h>
-#include <sys/types.h>
-extern "C" {
+
+#ifdef USE_SOCKET_IMPL_LWIP_SOCKETS
+// LWIP sockets implementation
+#include <lwip/sockets.h>
+#elif defined(USE_SOCKET_IMPL_BSD_SOCKETS)
+// BSD sockets implementation
+#ifdef USE_ESP32
+// ESP32 "BSD sockets" are actually LWIP under the hood
 #include <lwip/sockets.h>
-}
 #else
+// True BSD sockets (e.g., host platform)
 #include <sys/select.h>
 #endif
 #endif
+#endif
 
 namespace esphome {
 
@@ -122,7 +126,7 @@ void Application::loop() {
     next_schedule = std::max(next_schedule, delay_time / 2);
     delay_time = std::min(next_schedule, delay_time);
 
-#ifdef FD_SETSIZE
+#ifdef USE_SOCKET_SELECT_SUPPORT
     if (!this->socket_fds_.empty()) {
       // Use select() with timeout when we have sockets to monitor
 
@@ -143,10 +147,18 @@ void Application::loop() {
       // Convert delay_time (milliseconds) to timeval
       struct timeval tv;
       tv.tv_sec = delay_time / 1000;
-      tv.tv_usec = (delay_time % 1000) * 1000;
+      tv.tv_usec = (delay_time - tv.tv_sec * 1000) * 1000;
 
       // Call select with timeout
+#if defined(USE_SOCKET_IMPL_LWIP_SOCKETS) || (defined(USE_ESP32) && defined(USE_SOCKET_IMPL_BSD_SOCKETS))
+      // Use lwip_select() on platforms with lwIP - it's faster
+      // Note: On ESP32 with BSD sockets, select() is already mapped to lwip_select() via macros,
+      // but we explicitly call lwip_select() for clarity and to ensure we get the optimized version
+      int ret = lwip_select(this->max_fd_ + 1, &this->read_fds_, nullptr, nullptr, &tv);
+#else
+      // Use standard select() on other platforms (e.g., host/native builds)
       int ret = ::select(this->max_fd_ + 1, &this->read_fds_, nullptr, nullptr, &tv);
+#endif
 
       if (ret < 0) {
         if (errno == EINTR) {
@@ -232,21 +244,20 @@ void Application::calculate_looping_components_() {
   }
 }
 
+#ifdef USE_SOCKET_SELECT_SUPPORT
 bool Application::register_socket_fd(int fd) {
   // WARNING: This function is NOT thread-safe and must only be called from the main loop
   // It modifies socket_fds_ and related variables without locking
   if (fd < 0)
     return false;
 
-#ifdef FD_SETSIZE
   if (fd >= FD_SETSIZE) {
     ESP_LOGE(TAG, "Cannot monitor socket fd %d: exceeds FD_SETSIZE (%d)", fd, FD_SETSIZE);
     ESP_LOGE(TAG, "Socket will not be monitored for data - may cause performance issues!");
     return false;
   }
-#endif
 
-  this->socket_fds_.insert(fd);
+  this->socket_fds_.push_back(fd);
   this->socket_fds_changed_ = true;
 
   if (fd > this->max_fd_) {
@@ -262,14 +273,24 @@ void Application::unregister_socket_fd(int fd) {
   if (fd < 0)
     return;
 
-  this->socket_fds_.erase(fd);
-  this->socket_fds_changed_ = true;
+  auto it = std::find(this->socket_fds_.begin(), this->socket_fds_.end(), fd);
+  if (it != this->socket_fds_.end()) {
+    // Swap with last element and pop - O(1) removal since order doesn't matter
+    if (it != this->socket_fds_.end() - 1) {
+      std::swap(*it, this->socket_fds_.back());
+    }
+    this->socket_fds_.pop_back();
+    this->socket_fds_changed_ = true;
 
-  // Recalculate max_fd if necessary
-  if (fd == this->max_fd_ && !this->socket_fds_.empty()) {
-    this->max_fd_ = *this->socket_fds_.rbegin();
-  } else if (this->socket_fds_.empty()) {
-    this->max_fd_ = -1;
+    // Only recalculate max_fd if we removed the current max
+    if (fd == this->max_fd_) {
+      if (this->socket_fds_.empty()) {
+        this->max_fd_ = -1;
+      } else {
+        // Find new max using std::max_element
+        this->max_fd_ = *std::max_element(this->socket_fds_.begin(), this->socket_fds_.end());
+      }
+    }
   }
 }
 
@@ -277,16 +298,12 @@ bool Application::is_socket_ready(int fd) const {
   // This function is thread-safe for reading the result of select()
   // However, it should only be called after select() has been executed in the main loop
   // The read_fds_ is only modified by select() in the main loop
-#ifdef FD_SETSIZE
   if (fd < 0 || fd >= FD_SETSIZE)
     return false;
 
   return FD_ISSET(fd, &this->read_fds_);
-#else
-  // If we don't have select support, assume socket is always ready
-  return true;
-#endif
 }
+#endif
 
 Application App;  // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
 

esphome/core/application.h

@@ -2,14 +2,18 @@
 
 #include <string>
 #include <vector>
-#include <set>
 #include "esphome/core/component.h"
 #include "esphome/core/defines.h"
 #include "esphome/core/hal.h"
 #include "esphome/core/helpers.h"
 #include "esphome/core/preferences.h"
+#include "esphome/core/runtime_stats.h"
 #include "esphome/core/scheduler.h"
 
+#ifdef USE_SOCKET_SELECT_SUPPORT
+#include <sys/select.h>
+#endif
+
 #ifdef USE_BINARY_SENSOR
 #include "esphome/components/binary_sensor/binary_sensor.h"
 #endif
@@ -74,12 +78,6 @@
 #include "esphome/components/update/update_entity.h"
 #endif
 
-#ifdef USE_BSD_SOCKETS
-#include <sys/select.h>
-#elif defined(USE_LWIP_SOCKETS) || defined(USE_SOCKET_IMPL_LWIP_SOCKETS)
-#include "lwip/sockets.h"
-#endif
-
 namespace esphome {
 
 class Application {
@@ -244,6 +242,18 @@ class Application {
 
   uint32_t get_loop_interval() const { return this->loop_interval_; }
 
+  /** Enable or disable runtime statistics collection.
+   *
+   * @param enable Whether to enable runtime statistics collection.
+   */
+  void set_runtime_stats_enabled(bool enable) { runtime_stats.set_enabled(enable); }
+
+  /** Set the interval at which runtime statistics are logged.
+   *
+   * @param interval The interval in milliseconds between logging of runtime statistics.
+   */
+  void set_runtime_stats_log_interval(uint32_t interval) { runtime_stats.set_log_interval(interval); }
+
   void schedule_dump_config() { this->dump_config_at_ = 0; }
 
   void feed_wdt(uint32_t time = 0);
@@ -475,6 +485,7 @@ class Application {
   Scheduler scheduler;
 
   /// Register/unregister a socket file descriptor to be monitored for read events.
+#ifdef USE_SOCKET_SELECT_SUPPORT
   /// These functions update the fd_set used by select() in the main loop.
   /// WARNING: These functions are NOT thread-safe. They must only be called from the main loop.
   /// NOTE: File descriptors >= FD_SETSIZE (typically 10 on ESP) will be rejected with an error.
@@ -484,6 +495,7 @@ class Application {
   /// Check if there's data available on a socket without blocking
   /// This function is thread-safe for reading, but should be called after select() has run
   bool is_socket_ready(int fd) const;
+#endif
 
  protected:
   friend Component;
@@ -568,19 +580,19 @@ class Application {
   const char *compilation_time_{nullptr};
   bool name_add_mac_suffix_;
   uint32_t last_loop_{0};
-  uint32_t loop_interval_{16};
+  uint32_t loop_interval_{16};  // Standard interval for platforms without select()
   size_t dump_config_at_{SIZE_MAX};
   uint32_t app_state_{0};
   Component *current_component_{nullptr};
   uint32_t loop_component_start_time_{0};
 
+#ifdef USE_SOCKET_SELECT_SUPPORT
   // Socket select management
-  std::set<int> socket_fds_;        // Set of all monitored socket file descriptors
+  std::vector<int> socket_fds_;     // Vector of all monitored socket file descriptors
   bool socket_fds_changed_{false};  // Flag to rebuild base_read_fds_ when socket_fds_ changes
   int max_fd_{-1};                  // Highest file descriptor number for select()
-#ifdef FD_SETSIZE
-  fd_set base_read_fds_{};  // Cached fd_set rebuilt only when socket_fds_ changes
-  fd_set read_fds_{};       // Working fd_set for select(), copied from base_read_fds_
+  fd_set base_read_fds_{};          // Cached fd_set rebuilt only when socket_fds_ changes
+  fd_set read_fds_{};               // Working fd_set for select(), copied from base_read_fds_
 #endif
 };
 

esphome/core/component.cpp

@@ -246,6 +246,9 @@ uint32_t WarnIfComponentBlockingGuard::finish() {
   uint32_t curr_time = millis();
 
   uint32_t blocking_time = curr_time - this->started_;
+
+  // Record component runtime stats
+  runtime_stats.record_component_time(this->component_, blocking_time, curr_time);
   bool should_warn;
   if (this->component_ != nullptr) {
     should_warn = this->component_->should_warn_of_blocking(blocking_time);

esphome/core/component.h

@@ -6,6 +6,7 @@
 #include <string>
 
 #include "esphome/core/optional.h"
+#include "esphome/core/runtime_stats.h"
 
 namespace esphome {
 

esphome/core/runtime_stats.cpp

@@ -0,0 +1,28 @@
+#include "esphome/core/runtime_stats.h"
+#include "esphome/core/component.h"
+
+namespace esphome {
+
+RuntimeStatsCollector runtime_stats;
+
+void RuntimeStatsCollector::record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time) {
+  if (!this->enabled_ || component == nullptr)
+    return;
+
+  const char *component_source = component->get_component_source();
+  this->component_stats_[component_source].record_time(duration_ms);
+
+  // If next_log_time_ is 0, initialize it
+  if (this->next_log_time_ == 0) {
+    this->next_log_time_ = current_time + this->log_interval_;
+    return;
+  }
+
+  if (current_time >= this->next_log_time_) {
+    this->log_stats_();
+    this->reset_stats_();
+    this->next_log_time_ = current_time + this->log_interval_;
+  }
+}
+
+}  // namespace esphome

esphome/core/runtime_stats.h

@@ -0,0 +1,161 @@
+#pragma once
+
+#include <map>
+#include <string>
+#include <vector>
+#include <cstdint>
+#include <algorithm>
+#include "esphome/core/helpers.h"
+#include "esphome/core/log.h"
+
+namespace esphome {
+
+static const char *const RUNTIME_TAG = "runtime";
+
+class Component;  // Forward declaration
+
+class ComponentRuntimeStats {
+ public:
+  ComponentRuntimeStats()
+      : period_count_(0),
+        total_count_(0),
+        period_time_ms_(0),
+        total_time_ms_(0),
+        period_max_time_ms_(0),
+        total_max_time_ms_(0) {}
+
+  void record_time(uint32_t duration_ms) {
+    // Update period counters
+    this->period_count_++;
+    this->period_time_ms_ += duration_ms;
+    if (duration_ms > this->period_max_time_ms_)
+      this->period_max_time_ms_ = duration_ms;
+
+    // Update total counters
+    this->total_count_++;
+    this->total_time_ms_ += duration_ms;
+    if (duration_ms > this->total_max_time_ms_)
+      this->total_max_time_ms_ = duration_ms;
+  }
+
+  void reset_period_stats() {
+    this->period_count_ = 0;
+    this->period_time_ms_ = 0;
+    this->period_max_time_ms_ = 0;
+  }
+
+  // Period stats (reset each logging interval)
+  uint32_t get_period_count() const { return this->period_count_; }
+  uint32_t get_period_time_ms() const { return this->period_time_ms_; }
+  uint32_t get_period_max_time_ms() const { return this->period_max_time_ms_; }
+  float get_period_avg_time_ms() const {
+    return this->period_count_ > 0 ? this->period_time_ms_ / static_cast<float>(this->period_count_) : 0.0f;
+  }
+
+  // Total stats (persistent until reboot)
+  uint32_t get_total_count() const { return this->total_count_; }
+  uint32_t get_total_time_ms() const { return this->total_time_ms_; }
+  uint32_t get_total_max_time_ms() const { return this->total_max_time_ms_; }
+  float get_total_avg_time_ms() const {
+    return this->total_count_ > 0 ? this->total_time_ms_ / static_cast<float>(this->total_count_) : 0.0f;
+  }
+
+ protected:
+  // Period stats (reset each logging interval)
+  uint32_t period_count_;
+  uint32_t period_time_ms_;
+  uint32_t period_max_time_ms_;
+
+  // Total stats (persistent until reboot)
+  uint32_t total_count_;
+  uint32_t total_time_ms_;
+  uint32_t total_max_time_ms_;
+};
+
+// For sorting components by run time
+struct ComponentStatPair {
+  std::string name;
+  const ComponentRuntimeStats *stats;
+
+  bool operator>(const ComponentStatPair &other) const {
+    // Sort by period time as that's what we're displaying in the logs
+    return stats->get_period_time_ms() > other.stats->get_period_time_ms();
+  }
+};
+
+class RuntimeStatsCollector {
+ public:
+  RuntimeStatsCollector() : log_interval_(60000), next_log_time_(0), enabled_(true) {}
+
+  void set_log_interval(uint32_t log_interval) { this->log_interval_ = log_interval; }
+  uint32_t get_log_interval() const { return this->log_interval_; }
+
+  void set_enabled(bool enabled) { this->enabled_ = enabled; }
+  bool is_enabled() const { return this->enabled_; }
+
+  void record_component_time(Component *component, uint32_t duration_ms, uint32_t current_time);
+
+ protected:
+  void log_stats_() {
+    ESP_LOGI(RUNTIME_TAG, "Component Runtime Statistics");
+    ESP_LOGI(RUNTIME_TAG, "Period stats (last %" PRIu32 "ms):", this->log_interval_);
+
+    // First collect stats we want to display
+    std::vector<ComponentStatPair> stats_to_display;
+
+    for (const auto &it : this->component_stats_) {
+      const ComponentRuntimeStats &stats = it.second;
+      if (stats.get_period_count() > 0) {
+        ComponentStatPair pair = {it.first, &stats};
+        stats_to_display.push_back(pair);
+      }
+    }
+
+    // Sort by period runtime (descending)
+    std::sort(stats_to_display.begin(), stats_to_display.end(), std::greater<ComponentStatPair>());
+
+    // Log top components by period runtime
+    for (const auto &it : stats_to_display) {
+      const std::string &source = it.name;
+      const ComponentRuntimeStats *stats = it.stats;
+
+      ESP_LOGI(RUNTIME_TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms",
+               source.c_str(), stats->get_period_count(), stats->get_period_avg_time_ms(),
+               stats->get_period_max_time_ms(), stats->get_period_time_ms());
+    }
+
+    // Log total stats since boot
+    ESP_LOGI(RUNTIME_TAG, "Total stats (since boot):");
+
+    // Re-sort by total runtime for all-time stats
+    std::sort(stats_to_display.begin(), stats_to_display.end(),
+              [](const ComponentStatPair &a, const ComponentStatPair &b) {
+                return a.stats->get_total_time_ms() > b.stats->get_total_time_ms();
+              });
+
+    for (const auto &it : stats_to_display) {
+      const std::string &source = it.name;
+      const ComponentRuntimeStats *stats = it.stats;
+
+      ESP_LOGI(RUNTIME_TAG, "  %s: count=%" PRIu32 ", avg=%.2fms, max=%" PRIu32 "ms, total=%" PRIu32 "ms",
+               source.c_str(), stats->get_total_count(), stats->get_total_avg_time_ms(), stats->get_total_max_time_ms(),
+               stats->get_total_time_ms());
+    }
+  }
+
+  void reset_stats_() {
+    for (auto &it : this->component_stats_) {
+      it.second.reset_period_stats();
+    }
+  }
+
+  std::map<std::string, ComponentRuntimeStats> component_stats_;
+  uint32_t log_interval_;
+  uint32_t next_log_time_;
+  bool enabled_;
+};
+
+// Global instance for runtime stats collection
+extern RuntimeStatsCollector runtime_stats;
+
+}  // namespace esphome