Merge branch 'improve_ble_batching' into loop_runtime_stats_ble_batching

esphome/components/bluetooth_proxy/bluetooth_proxy.cpp

@@ -51,35 +51,54 @@ bool BluetoothProxy::parse_device(const esp32_ble_tracker::ESPBTDevice &device)
   return true;
 }
 
+// Static buffer to store advertisements between batches
+static constexpr size_t MAX_BATCH_SIZE = 8;
+static std::vector<api::BluetoothLERawAdvertisement> batch_buffer;
+
 bool BluetoothProxy::parse_devices(esp_ble_gap_cb_param_t::ble_scan_result_evt_param *advertisements, size_t count) {
   if (!api::global_api_server->is_connected() || this->api_connection_ == nullptr || !this->raw_advertisements_)
     return false;
 
-  api::BluetoothLERawAdvertisementsResponse resp;
-  // Pre-allocate the advertisements vector to avoid reallocations
-  resp.advertisements.reserve(count);
+  // Reserve additional capacity if needed
+  size_t new_size = batch_buffer.size() + count;
+  if (batch_buffer.capacity() < new_size) {
+    batch_buffer.reserve(new_size);
+  }
 
+  // Add new advertisements to the batch buffer
   for (size_t i = 0; i < count; i++) {
     auto &result = advertisements[i];
-    api::BluetoothLERawAdvertisement adv;
+    uint8_t length = result.adv_data_len + result.scan_rsp_len;
+
+    batch_buffer.emplace_back();
+    auto &adv = batch_buffer.back();
     adv.address = esp32_ble::ble_addr_to_uint64(result.bda);
     adv.rssi = result.rssi;
     adv.address_type = result.ble_addr_type;
+    adv.data.assign(&result.ble_adv[0], &result.ble_adv[length]);
 
-    uint8_t length = result.adv_data_len + result.scan_rsp_len;
-    adv.data.reserve(length);
-    // Use a bulk insert instead of individual push_backs
-    adv.data.insert(adv.data.end(), &result.ble_adv[0], &result.ble_adv[length]);
-
-    resp.advertisements.push_back(std::move(adv));
-
-    ESP_LOGV(TAG, "Proxying raw packet from %02X:%02X:%02X:%02X:%02X:%02X, length %d. RSSI: %d dB", result.bda[0],
+    ESP_LOGV(TAG, "Queuing raw packet from %02X:%02X:%02X:%02X:%02X:%02X, length %d. RSSI: %d dB", result.bda[0],
              result.bda[1], result.bda[2], result.bda[3], result.bda[4], result.bda[5], length, result.rssi);
   }
-  ESP_LOGV(TAG, "Proxying %d packets", count);
-  this->api_connection_->send_bluetooth_le_raw_advertisements_response(resp);
+
+  // Only send if we've accumulated a good batch size to maximize batching efficiency
+  // https://github.com/esphome/backlog/issues/21
+  if (batch_buffer.size() >= MAX_BATCH_SIZE) {
+    this->flush_pending_advertisements();
+  }
+
   return true;
 }
+
+void BluetoothProxy::flush_pending_advertisements() {
+  if (batch_buffer.empty() || !api::global_api_server->is_connected() || this->api_connection_ == nullptr)
+    return;
+
+  api::BluetoothLERawAdvertisementsResponse resp;
+  resp.advertisements.swap(batch_buffer);
+  this->api_connection_->send_bluetooth_le_raw_advertisements_response(resp);
+}
+
 void BluetoothProxy::send_api_packet_(const esp32_ble_tracker::ESPBTDevice &device) {
   api::BluetoothLEAdvertisementResponse resp;
   resp.address = device.address_uint64();
@@ -91,28 +110,28 @@ void BluetoothProxy::send_api_packet_(const esp32_ble_tracker::ESPBTDevice &devi
   // Pre-allocate vectors based on known sizes
   auto service_uuids = device.get_service_uuids();
   resp.service_uuids.reserve(service_uuids.size());
-  for (auto uuid : service_uuids) {
-    resp.service_uuids.push_back(uuid.to_string());
+  for (auto &uuid : service_uuids) {
+    resp.service_uuids.emplace_back(uuid.to_string());
   }
 
   // Pre-allocate service data vector
   auto service_datas = device.get_service_datas();
   resp.service_data.reserve(service_datas.size());
   for (auto &data : service_datas) {
-    api::BluetoothServiceData service_data;
+    resp.service_data.emplace_back();
+    auto &service_data = resp.service_data.back();
     service_data.uuid = data.uuid.to_string();
     service_data.data.assign(data.data.begin(), data.data.end());
-    resp.service_data.push_back(std::move(service_data));
   }
 
   // Pre-allocate manufacturer data vector
   auto manufacturer_datas = device.get_manufacturer_datas();
   resp.manufacturer_data.reserve(manufacturer_datas.size());
   for (auto &data : manufacturer_datas) {
-    api::BluetoothServiceData manufacturer_data;
+    resp.manufacturer_data.emplace_back();
+    auto &manufacturer_data = resp.manufacturer_data.back();
     manufacturer_data.uuid = data.uuid.to_string();
     manufacturer_data.data.assign(data.data.begin(), data.data.end());
-    resp.manufacturer_data.push_back(std::move(manufacturer_data));
   }
 
   this->api_connection_->send_bluetooth_le_advertisement(resp);
@@ -148,6 +167,18 @@ void BluetoothProxy::loop() {
     }
     return;
   }
+
+  // Flush any pending BLE advertisements that have been accumulated but not yet sent
+  if (this->raw_advertisements_) {
+    static uint32_t last_flush_time = 0;
+    uint32_t now = millis();
+
+    // Flush accumulated advertisements every 100ms
+    if (now - last_flush_time >= 100) {
+      this->flush_pending_advertisements();
+      last_flush_time = now;
+    }
+  }
   for (auto *connection : this->connections_) {
     if (connection->send_service_ == connection->service_count_) {
       connection->send_service_ = DONE_SENDING_SERVICES;

esphome/components/bluetooth_proxy/bluetooth_proxy.h

@@ -56,6 +56,7 @@ class BluetoothProxy : public esp32_ble_tracker::ESPBTDeviceListener, public Com
   void dump_config() override;
   void setup() override;
   void loop() override;
+  void flush_pending_advertisements();
   esp32_ble_tracker::AdvertisementParserType get_advertisement_parser_type() override;
 
   void register_connection(BluetoothConnection *connection) {

esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp

@@ -122,7 +122,7 @@ void ESP32BLETracker::loop() {
 
   if (this->scanner_state_ == ScannerState::RUNNING &&
       this->scan_result_index_ &&  // if it looks like we have a scan result we will take the lock
-      xSemaphoreTake(this->scan_result_lock_, 5L / portTICK_PERIOD_MS)) {
+      xSemaphoreTake(this->scan_result_lock_, 0)) {
     uint32_t index = this->scan_result_index_;
     if (index >= ESP32BLETracker::SCAN_RESULT_BUFFER_SIZE) {
       ESP_LOGW(TAG, "Too many BLE events to process. Some devices may not show up.");
@@ -447,7 +447,7 @@ void ESP32BLETracker::gap_scan_stop_complete_(const esp_ble_gap_cb_param_t::ble_
 void ESP32BLETracker::gap_scan_result_(const esp_ble_gap_cb_param_t::ble_scan_result_evt_param &param) {
   ESP_LOGV(TAG, "gap_scan_result - event %d", param.search_evt);
   if (param.search_evt == ESP_GAP_SEARCH_INQ_RES_EVT) {
-    if (xSemaphoreTake(this->scan_result_lock_, 0L)) {
+    if (xSemaphoreTake(this->scan_result_lock_, 0)) {
       if (this->scan_result_index_ < ESP32BLETracker::SCAN_RESULT_BUFFER_SIZE) {
         this->scan_result_buffer_[this->scan_result_index_++] = param;
       }

esphome/components/esp32_ble_tracker/esp32_ble_tracker.h

@@ -290,7 +290,7 @@ class ESP32BLETracker : public Component,
 #ifdef USE_PSRAM
   const static u_int8_t SCAN_RESULT_BUFFER_SIZE = 32;
 #else
-  const static u_int8_t SCAN_RESULT_BUFFER_SIZE = 16;
+  const static u_int8_t SCAN_RESULT_BUFFER_SIZE = 20;
 #endif  // USE_PSRAM
   esp_ble_gap_cb_param_t::ble_scan_result_evt_param *scan_result_buffer_;
   esp_bt_status_t scan_start_failed_{ESP_BT_STATUS_SUCCESS};

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/core/application.h

@@ -7,6 +7,7 @@
 #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_BINARY_SENSOR
@@ -234,6 +235,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();

esphome/core/component.cpp

@@ -243,7 +243,13 @@ void PollingComponent::set_update_interval(uint32_t update_interval) { this->upd
 WarnIfComponentBlockingGuard::WarnIfComponentBlockingGuard(Component *component)
     : started_(millis()), component_(component) {}
 WarnIfComponentBlockingGuard::~WarnIfComponentBlockingGuard() {
-  uint32_t blocking_time = millis() - this->started_;
+  uint32_t current_time = millis();
+  uint32_t blocking_time = current_time - this->started_;
+
+  // Record component runtime stats
+  runtime_stats.record_component_time(this->component_, blocking_time, current_time);
+
+  // Original blocking check logic
   bool should_warn;
   if (this->component_ != nullptr) {
     should_warn = this->component_->should_warn_of_blocking(blocking_time);
@@ -254,7 +260,6 @@ WarnIfComponentBlockingGuard::~WarnIfComponentBlockingGuard() {
     const char *src = component_ == nullptr ? "<null>" : component_->get_component_source();
     ESP_LOGW(TAG, "Component %s took a long time for an operation (%" PRIu32 " ms).", src, blocking_time);
     ESP_LOGW(TAG, "Components should block for at most 30 ms.");
-    ;
   }
 }
 

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