more time

esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp

@@ -17,6 +17,10 @@
 #include <nvs_flash.h>
 #include <cinttypes>
 
+#ifdef USE_BLUETOOTH_PROXY
+#include "esphome/components/bluetooth_proxy/bluetooth_proxy.h"
+#endif
+
 #ifdef USE_OTA
 #include "esphome/components/ota/ota_backend.h"
 #endif
@@ -75,7 +79,90 @@ void ESP32BLETracker::setup() {
 #endif
 }
 
+void ESP32BLETracker::log_timing_stats_() {
+  // Only log if we have data to report
+  if (this->timing_stats_.loop_processing_count == 0)
+    return;
+
+  ESP_LOGI(TAG, "BLE Tracker Timing Statistics (last %dms):", this->timing_stats_.log_interval_ms);
+
+  if (this->timing_stats_.loop_processing_count > 0) {
+    float avg_loop_time = this->timing_stats_.loop_processing_time / (float) this->timing_stats_.loop_processing_count;
+    ESP_LOGI(TAG, "  BLE Scan Processing: count=%d, avg=%.2fms, total=%dms", this->timing_stats_.loop_processing_count,
+             avg_loop_time, this->timing_stats_.loop_processing_time);
+
+    // Log scan results processed
+    ESP_LOGI(TAG, "  BLE Scan Results Processed: count=%d", this->timing_stats_.scan_result_count);
+  }
+
+  // Log raw advertisement processing statistics
+  if (this->timing_stats_.raw_adv_count > 0) {
+    float avg_raw_time = this->timing_stats_.raw_adv_time / (float) this->timing_stats_.raw_adv_count;
+    ESP_LOGI(TAG, "  Raw Advertisement Processing: count=%d, avg=%.2fms, total=%dms", this->timing_stats_.raw_adv_count,
+             avg_raw_time, this->timing_stats_.raw_adv_time);
+  }
+
+  // Log parsed advertisement processing statistics
+  if (this->timing_stats_.parse_adv_count > 0) {
+    float avg_parse_time = this->timing_stats_.parse_adv_time / (float) this->timing_stats_.parse_adv_count;
+    ESP_LOGI(TAG, "  Parsed Advertisement Processing: count=%d, avg=%.2fms, total=%dms",
+             this->timing_stats_.parse_adv_count, avg_parse_time, this->timing_stats_.parse_adv_time);
+  }
+
+  // Log individual device parsing statistics
+  if (this->timing_stats_.parse_device_count > 0) {
+    float avg_device_time = this->timing_stats_.parse_device_time / (float) this->timing_stats_.parse_device_count;
+    ESP_LOGI(TAG, "  Device Parsing: count=%d, avg=%.2fms, total=%dms", this->timing_stats_.parse_device_count,
+             avg_device_time, this->timing_stats_.parse_device_time);
+  }
+
+  // Log component-specific timings
+  if (this->timing_stats_.bluetooth_proxy_count > 0) {
+    float avg_proxy_time = this->timing_stats_.bluetooth_proxy_time / (float) this->timing_stats_.bluetooth_proxy_count;
+    ESP_LOGI(TAG, "  Bluetooth Proxy: count=%d, avg=%.2fms, total=%dms", this->timing_stats_.bluetooth_proxy_count,
+             avg_proxy_time, this->timing_stats_.bluetooth_proxy_time);
+  }
+
+  if (this->timing_stats_.client_listeners_count > 0) {
+    float avg_client_time =
+        this->timing_stats_.client_listeners_time / (float) this->timing_stats_.client_listeners_count;
+    ESP_LOGI(TAG, "  Client Listeners: count=%d, avg=%.2fms, total=%dms", this->timing_stats_.client_listeners_count,
+             avg_client_time, this->timing_stats_.client_listeners_time);
+  }
+
+  // Log gap scan result processing statistics
+  if (this->timing_stats_.gap_scan_result_count > 0) {
+    float avg_gap_time = this->timing_stats_.gap_scan_result_time / (float) this->timing_stats_.gap_scan_result_count;
+    ESP_LOGI(TAG, "  GAP Scan Result Processing: count=%d, avg=%.2fms, total=%dms",
+             this->timing_stats_.gap_scan_result_count, avg_gap_time, this->timing_stats_.gap_scan_result_time);
+  }
+
+  // Reset timers for next period
+  this->timing_stats_.loop_processing_time = 0;
+  this->timing_stats_.loop_processing_count = 0;
+  this->timing_stats_.bluetooth_proxy_time = 0;
+  this->timing_stats_.bluetooth_proxy_count = 0;
+  this->timing_stats_.client_listeners_time = 0;
+  this->timing_stats_.client_listeners_count = 0;
+  this->timing_stats_.scan_result_count = 0;
+  this->timing_stats_.raw_adv_time = 0;
+  this->timing_stats_.raw_adv_count = 0;
+  this->timing_stats_.parse_adv_time = 0;
+  this->timing_stats_.parse_adv_count = 0;
+  this->timing_stats_.parse_device_time = 0;
+  this->timing_stats_.parse_device_count = 0;
+  this->timing_stats_.gap_scan_result_time = 0;
+  this->timing_stats_.gap_scan_result_count = 0;
+}
+
 void ESP32BLETracker::loop() {
+  // Check if we need to log stats first
+  uint32_t now = millis();
+  if (now - this->timing_stats_.last_log_time >= this->timing_stats_.log_interval_ms) {
+    this->log_timing_stats_();
+    this->timing_stats_.last_log_time = now;
+  }
+
   if (!this->parent_->is_active()) {
     this->ble_was_disabled_ = true;
     return;
@@ -123,25 +210,75 @@ 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)) {
+    // Start timing the BLE scan processing
+    uint32_t processing_start = millis();
+
     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.");
     }
 
     if (this->raw_advertisements_) {
+      this->timing_stats_.scan_result_count += this->scan_result_index_;
+
+      // Track overall raw advertisement processing time
+      uint32_t raw_adv_start = millis();
+
+      // Time each listener type separately
       for (auto *listener : this->listeners_) {
+        // Check if this is the bluetooth_proxy component
+        bool is_bluetooth_proxy = false;
+
+#ifdef USE_BLUETOOTH_PROXY
+        // Since RTTI is disabled (typeid can't be used), check if the address is the global bluetooth proxy
+        // This is a safe pointer comparison since we're not calling any methods on it
+        if (esphome::bluetooth_proxy::global_bluetooth_proxy != nullptr) {
+          is_bluetooth_proxy =
+              (listener == static_cast<ESPBTDeviceListener *>(esphome::bluetooth_proxy::global_bluetooth_proxy));
+        }
+#endif
+
+        uint32_t listener_start = millis();
         listener->parse_devices(this->scan_result_buffer_, this->scan_result_index_);
+        uint32_t listener_time = millis() - listener_start;
+
+        // Track times for specific components
+        if (is_bluetooth_proxy) {
+          this->timing_stats_.bluetooth_proxy_time += listener_time;
+          this->timing_stats_.bluetooth_proxy_count++;
+        }
       }
+
+      // Time the client listeners
+      uint32_t clients_start = millis();
       for (auto *client : this->clients_) {
         client->parse_devices(this->scan_result_buffer_, this->scan_result_index_);
       }
+      uint32_t clients_time = millis() - clients_start;
+      this->timing_stats_.client_listeners_time += clients_time;
+      this->timing_stats_.client_listeners_count++;
+
+      // Calculate total raw advertisement processing time
+      uint32_t raw_adv_time = millis() - raw_adv_start;
+      this->timing_stats_.raw_adv_time += raw_adv_time;
+      this->timing_stats_.raw_adv_count++;
     }
 
     if (this->parse_advertisements_) {
+      // Track overall time for parsed advertisements
+      uint32_t parse_adv_start = millis();
+
       for (size_t i = 0; i < index; i++) {
+        // Time individual device parsing
+        uint32_t device_start = millis();
+
         ESPBTDevice device;
         device.parse_scan_rst(this->scan_result_buffer_[i]);
 
+        uint32_t device_parse_time = millis() - device_start;
+        this->timing_stats_.parse_device_time += device_parse_time;
+        this->timing_stats_.parse_device_count++;
+
         bool found = false;
         for (auto *listener : this->listeners_) {
           if (listener->parse_device(device))
@@ -161,9 +298,19 @@ void ESP32BLETracker::loop() {
           this->print_bt_device_info(device);
         }
       }
+
+      // Record total time for parsed advertisements processing
+      uint32_t parse_adv_time = millis() - parse_adv_start;
+      this->timing_stats_.parse_adv_time += parse_adv_time;
+      this->timing_stats_.parse_adv_count++;
     }
     this->scan_result_index_ = 0;
     xSemaphoreGive(this->scan_result_lock_);
+
+    // Record timing for the BLE scan processing
+    uint32_t processing_time = millis() - processing_start;
+    this->timing_stats_.loop_processing_time += processing_time;
+    this->timing_stats_.loop_processing_count++;
   }
   if (this->scanner_state_ == ScannerState::STOPPED) {
     this->end_of_scan_();  // Change state to IDLE
@@ -445,6 +592,8 @@ 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) {
+  uint32_t start_time = millis();
+
   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)) {
@@ -470,6 +619,18 @@ void ESP32BLETracker::gap_scan_result_(const esp_ble_gap_cb_param_t::ble_scan_re
     }
     this->set_scanner_state_(ScannerState::STOPPED);
   }
+
+  // Record timing statistics
+  uint32_t duration = millis() - start_time;
+  this->timing_stats_.gap_scan_result_time += duration;
+  this->timing_stats_.gap_scan_result_count++;
+
+  // Periodically log statistics
+  uint32_t now = millis();
+  if (now - this->timing_stats_.last_log_time >= this->timing_stats_.log_interval_ms) {
+    this->log_timing_stats_();
+    this->timing_stats_.last_log_time = now;
+  }
 }
 
 void ESP32BLETracker::gattc_event_handler(esp_gattc_cb_event_t event, esp_gatt_if_t gattc_if,

esphome/components/esp32_ble_tracker/esp32_ble_tracker.h

@@ -247,6 +247,9 @@ class ESP32BLETracker : public Component,
   }
   ScannerState get_scanner_state() const { return this->scanner_state_; }
 
+  // Logs timing statistics for BLE operations
+  void log_timing_stats_();
+
  protected:
   void stop_scan_();
   /// Start a single scan by setting up the parameters and doing some esp-idf calls.
@@ -299,6 +302,39 @@ class ESP32BLETracker : public Component,
   int discovered_{0};
   int searching_{0};
   int disconnecting_{0};
+
+  // Timing statistics
+  struct {
+    // Loop processing timing
+    uint32_t loop_processing_time{0};
+    uint32_t loop_processing_count{0};
+
+    // Detailed component-level timings
+    uint32_t bluetooth_proxy_time{0};
+    uint32_t bluetooth_proxy_count{0};
+    uint32_t client_listeners_time{0};
+    uint32_t client_listeners_count{0};
+    uint32_t scan_result_count{0};
+
+    // Raw advertisement processing stats
+    uint32_t raw_adv_time{0};
+    uint32_t raw_adv_count{0};
+
+    // Parsed advertisement processing stats
+    uint32_t parse_adv_time{0};
+    uint32_t parse_adv_count{0};
+    uint32_t parse_device_time{0};
+    uint32_t parse_device_count{0};
+
+    // Gap scan result stats
+    uint32_t gap_scan_result_time{0};
+    uint32_t gap_scan_result_count{0};
+
+    // Logging control
+    uint32_t last_log_time{0};
+    uint32_t log_interval_ms{30000};  // 30 seconds
+  } timing_stats_;
+
 #ifdef USE_ESP32_BLE_SOFTWARE_COEXISTENCE
   bool coex_prefer_ble_{false};
 #endif