From f1cbd78aa0441fc26c4a9ff22fe4060a2c3f069b Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Tue, 13 May 2025 01:59:40 -0500 Subject: [PATCH] log --- .../esp32_ble_tracker/esp32_ble_tracker.cpp | 139 ++++++++++++++++++ .../esp32_ble_tracker/esp32_ble_tracker.h | 32 ++++ 2 files changed, 171 insertions(+) diff --git a/esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp b/esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp index be45b177ff..91069a5d75 100644 --- a/esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp +++ b/esphome/components/esp32_ble_tracker/esp32_ble_tracker.cpp @@ -75,7 +75,81 @@ 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); + } + + // 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; +} + 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 +197,66 @@ 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_) { + // Detect if this is the bluetooth_proxy component by name + bool is_bluetooth_proxy = (strcmp(listener->get_component_source(), "bluetooth_proxy") == 0); + + 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 +276,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 +570,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 ¶m) { + 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 +597,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, diff --git a/esphome/components/esp32_ble_tracker/esp32_ble_tracker.h b/esphome/components/esp32_ble_tracker/esp32_ble_tracker.h index 2e45d9602c..1f1453378f 100644 --- a/esphome/components/esp32_ble_tracker/esp32_ble_tracker.h +++ b/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,35 @@ 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}; + + // 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