diff --git a/components/bt/common/ble_log/Kconfig.in b/components/bt/common/ble_log/Kconfig.in index 1255c725df0..d4ddc3c0dfc 100644 --- a/components/bt/common/ble_log/Kconfig.in +++ b/components/bt/common/ble_log/Kconfig.in @@ -7,6 +7,14 @@ config BLE_LOG_ENABLED Enable BT Log Async Output if BLE_LOG_ENABLED + config BLE_LOG_LBM_AUTO_FLUSH + bool "Enable automatic BLE Log LBM buffer flush" + default n + help + Periodically flush partially-filled BLE Log LBM transport buffers + that remain pending, reducing latency for low-volume or + intermittent logging. + config BLE_LOG_TASK_STACK_SIZE int "Stack size for BLE Log Task" default 1024 if IDF_TARGET_ARCH_RISCV diff --git a/components/bt/common/ble_log/README.md b/components/bt/common/ble_log/README.md index 8d7df6e98e9..c24f1b862f9 100644 --- a/components/bt/common/ble_log/README.md +++ b/components/bt/common/ble_log/README.md @@ -80,7 +80,7 @@ void app_main() { uint8_t data[] = {0x01, 0x02, 0x03, 0x04}; ble_log_write_hex(BLE_LOG_SRC_CUSTOM, data, sizeof(data)); - // Force flush buffers + // End session and flush buffers ble_log_flush(); // Cleanup resources @@ -178,9 +178,15 @@ Write hexadecimal log data. #### `void ble_log_flush(void)` -Force flush all buffers and send pending logs immediately. +End the current logging session and flush pending logs immediately. -**Note**: This operation is blocking and will pause module operation until all buffers are cleared. +This API temporarily suspends ordinary log writes, waits for in-progress +writers to exit, emits a final statistics internal frame, flushes pending +transport buffers, resets statistics, and then restores the enable state that +was in effect before the call. + +**Note**: This operation is blocking. If BLE Log was enabled before the call, +it remains enabled after the flush completes. #### `void ble_log_dump_to_console(void)` @@ -272,7 +278,7 @@ void example_basic_logging() { uint8_t host_data[] = {0x02, 0x00, 0x20, 0x0B, 0x00, 0x07, 0x00, 0x04, 0x00, 0x10, 0x01, 0x00, 0xFF, 0xFF, 0x00, 0x28}; ble_log_write_hex(BLE_LOG_SRC_HOST, host_data, sizeof(host_data)); - // Force send + // End session and flush buffers ble_log_flush(); // Cleanup @@ -334,6 +340,7 @@ void example_performance_test() { ble_log_write_hex(BLE_LOG_SRC_CUSTOM, test_data, sizeof(test_data)); } + // End session and flush buffers ble_log_flush(); uint32_t end_time = esp_timer_get_time(); diff --git a/components/bt/common/ble_log/src/ble_log.c b/components/bt/common/ble_log/src/ble_log.c index 4e6ce25838d..83ac2fcbd40 100644 --- a/components/bt/common/ble_log/src/ble_log.c +++ b/components/bt/common/ble_log/src/ble_log.c @@ -1,5 +1,5 @@ /* - * SPDX-FileCopyrightText: 2025 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 */ @@ -13,12 +13,22 @@ #include "ble_log_lbm.h" #include "ble_log_prph.h" #include "ble_log_util.h" +#include "esp_log.h" +#include "esp_system.h" #if CONFIG_BLE_LOG_TS_ENABLED #include "ble_log_ts.h" #endif /* CONFIG_BLE_LOG_TS_ENABLED */ /* VARIABLE */ +#define TAG "ble_log" + BLE_LOG_STATIC bool ble_log_inited = false; +BLE_LOG_STATIC bool shutdown_handler_registered = false; + +BLE_LOG_STATIC void ble_log_shutdown_handler(void) +{ + ble_log_flush(); +} /* INTERFACE */ bool ble_log_init(void) @@ -53,6 +63,12 @@ bool ble_log_init(void) /* Initialization done */ ble_log_inited = true; ble_log_enable(true); + esp_err_t ret = esp_register_shutdown_handler(ble_log_shutdown_handler); + if (ret == ESP_OK) { + shutdown_handler_registered = true; + } else { + ESP_LOGW(TAG, "Register shutdown handler failed, ret = 0x%x", ret); + } /* Write initialization done log */ ble_log_info_t ble_log_info = { @@ -69,6 +85,14 @@ exit: void ble_log_deinit(void) { + if (shutdown_handler_registered) { + esp_err_t ret = esp_unregister_shutdown_handler(ble_log_shutdown_handler); + if (ret == ESP_OK) { + shutdown_handler_registered = false; + } else { + ESP_LOGW(TAG, "Unregister shutdown handler failed, ret = 0x%x", ret); + } + } ble_log_enable(false); ble_log_inited = false; diff --git a/components/bt/common/ble_log/src/ble_log_lbm.c b/components/bt/common/ble_log/src/ble_log_lbm.c index db673c80be8..932c20d134e 100644 --- a/components/bt/common/ble_log/src/ble_log_lbm.c +++ b/components/bt/common/ble_log/src/ble_log_lbm.c @@ -11,15 +11,20 @@ #include "ble_log.h" #include "ble_log_lbm.h" #include "ble_log_rt.h" +#include "esp_log.h" #if CONFIG_SOC_ESP_NIMBLE_CONTROLLER #include "os/os_mbuf.h" #endif /* CONFIG_SOC_ESP_NIMBLE_CONTROLLER */ /* VARIABLE */ +#define TAG "ble_log" +#define BLE_LOG_LBM_WAIT_TIMEOUT_MS (1000) + BLE_LOG_STATIC volatile uint32_t lbm_ref_count = 0; BLE_LOG_STATIC bool lbm_inited = false; BLE_LOG_STATIC bool lbm_enabled = false; +BLE_LOG_STATIC volatile bool flush_in_progress = false; BLE_LOG_STATIC ble_log_lbm_ctx_t *lbm_ctx = NULL; BLE_LOG_STATIC ble_log_stat_mgr_t *stat_mgr_ctx[BLE_LOG_SRC_MAX] = {0}; @@ -30,10 +35,14 @@ bool ble_log_lbm_acquire_trans(size_t log_len, ble_log_lbm_t **out_lbm, BLE_LOG_STATIC void ble_log_lbm_release(ble_log_lbm_t *lbm); BLE_LOG_STATIC ble_log_prph_trans_t **ble_log_lbm_get_trans(ble_log_lbm_t *lbm, size_t log_len); +BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void); +BLE_LOG_STATIC void ble_log_lbm_reset_stats(void); BLE_LOG_STATIC void ble_log_lbm_write_trans(ble_log_prph_trans_t **trans, ble_log_src_t src_code, const uint8_t *addr, uint16_t len, const uint8_t *addr_append, uint16_t len_append, bool omdata); +BLE_LOG_STATIC +bool ble_log_write_hex_core(ble_log_src_t src_code, const uint8_t *addr, size_t len); #if BLE_LOG_UART_REDIR_ENABLED BLE_LOG_STATIC void ble_log_lbm_stream_seal(ble_log_prph_trans_t **trans, ble_log_src_t src_code); @@ -110,6 +119,66 @@ void ble_log_lbm_release(ble_log_lbm_t *lbm) } } +BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void) +{ + ble_log_lbm_t *lbm; + ble_log_prph_trans_t **trans; + bool in_progress; + TickType_t start_tick = xTaskGetTickCount(); + + /* Queue transports with logs */ + for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { + lbm = &(lbm_ctx->lbm_pool[i]); + int trans_idx = lbm->trans_idx; + for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) { + trans = &(lbm->trans[trans_idx]); + if (!__atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE) && + (*trans)->pos) { + ble_log_rt_queue_trans(trans); + } + trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1); + } + } + + /* Wait for transportation to finish */ + do { + in_progress = false; + for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { + lbm = &(lbm_ctx->lbm_pool[i]); + for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) { + trans = &(lbm->trans[j]); + in_progress |= __atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE); + } + } + if (in_progress) { + if ((xTaskGetTickCount() - start_tick) >= + pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) { + ESP_LOGE(TAG, "Timed out waiting for BLE Log transports"); + return false; + } + vTaskDelay(1); + } + } while (in_progress); + + return true; +} + +BLE_LOG_STATIC void ble_log_lbm_reset_stats(void) +{ + ble_log_lbm_t *lbm; + + for (int i = 0; i < BLE_LOG_SRC_MAX; i++) { + BLE_LOG_MEMSET(stat_mgr_ctx[i], 0, sizeof(ble_log_stat_mgr_t)); + } + + for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { + lbm = &(lbm_ctx->lbm_pool[i]); + __atomic_store_n(&lbm->trans_inflight, 0, __ATOMIC_RELAXED); + __atomic_store_n(&lbm->trans_inflight_peak, 0, __ATOMIC_RELAXED); + } + ble_log_prph_reset_util_counters(); +} + BLE_LOG_IRAM_ATTR BLE_LOG_STATIC void ble_log_lbm_write_trans(ble_log_prph_trans_t **trans, ble_log_src_t src_code, const uint8_t *addr, uint16_t len, @@ -203,6 +272,35 @@ void ble_log_stat_mgr_update(ble_log_src_t src_code, uint32_t len, bool lost) } } +BLE_LOG_IRAM_ATTR BLE_LOG_STATIC +bool ble_log_write_hex_core(ble_log_src_t src_code, const uint8_t *addr, size_t len) +{ + /* Get transport from the best available pool */ + size_t payload_len = len + sizeof(uint32_t); + ble_log_lbm_t *lbm; + ble_log_prph_trans_t **trans; + if (!ble_log_lbm_acquire_trans(payload_len, &lbm, &trans)) { + goto failed; + } + + /* Write transport */ + uint32_t os_ts = pdTICKS_TO_MS(BLE_LOG_IN_ISR()? + xTaskGetTickCountFromISR(): + xTaskGetTickCount()); + ble_log_lbm_write_trans(trans, src_code, (const uint8_t *)&os_ts, + sizeof(uint32_t), addr, len, false); + + /* Release */ + ble_log_lbm_release(lbm); + return true; + +failed: + if (lbm_inited) { + ble_log_stat_mgr_update(src_code, payload_len, true); + } + return false; +} + /* -------------------------- */ /* INTERNAL INTERFACE */ /* -------------------------- */ @@ -289,10 +387,15 @@ void ble_log_lbm_deinit(void) lbm_enabled = false; /* Disable module and wait for all references to be released */ - uint32_t time_waited = 0; + TickType_t start_tick = xTaskGetTickCount(); while (__atomic_load_n(&lbm_ref_count, __ATOMIC_ACQUIRE) > 0) { - vTaskDelay(pdMS_TO_TICKS(1)); - BLE_LOG_ASSERT(time_waited++ < 1000); + if ((xTaskGetTickCount() - start_tick) >= + pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) { + ESP_LOGE(TAG, "Timed out waiting for BLE Log references during deinit"); + } + BLE_LOG_ASSERT((xTaskGetTickCount() - start_tick) < + pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)); + vTaskDelay(1); } /* Release statistic manager context */ @@ -501,6 +604,33 @@ deref: BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); } +void ble_log_write_final_stat(void) +{ + BLE_LOG_REF_COUNT_ACQUIRE(&lbm_ref_count); + if (!lbm_inited) { + goto deref; + } + + ble_log_final_stat_t final_stat; + final_stat.int_src_code = BLE_LOG_INT_SRC_FINAL_STAT; + final_stat.src_cnt = BLE_LOG_SRC_MAX; + + BLE_LOG_ENTER_CRITICAL(); + for (int i = 0; i < BLE_LOG_SRC_MAX; i++) { + ble_log_final_stat_entry_t *entry = &final_stat.entries[i]; + entry->src_code = i; + BLE_LOG_MEMCPY(&entry->written_frame_cnt, + &stat_mgr_ctx[i]->written_frame_cnt, + 4 * sizeof(uint32_t)); + } + BLE_LOG_EXIT_CRITICAL(); + + ble_log_write_internal((const uint8_t *)&final_stat, sizeof(final_stat)); + +deref: + BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); +} + /* ------------------------ */ /* PUBLIC INTERFACE */ /* ------------------------ */ @@ -518,7 +648,6 @@ void ble_log_flush(void) /* Prevent concurrent flush — two concurrent callers would deadlock on * the ref_count spin-wait (both hold a ref, both wait for ref_count <= 1). * Second caller returns immediately instead of deadlocking. */ - static volatile bool flush_in_progress = false; if (__atomic_test_and_set(&flush_in_progress, __ATOMIC_ACQUIRE)) { return; } @@ -527,8 +656,6 @@ void ble_log_flush(void) if (!lbm_inited) { goto deref; } - - /* Write enhanced statistics before module disable */ ble_log_write_enh_stat(); ble_log_write_buf_util(); @@ -541,64 +668,32 @@ void ble_log_flush(void) /* Disable module and wait for all other references to release */ bool lbm_enabled_copy = lbm_enabled; + lbm_enabled = false; - uint32_t time_waited = 0; + TickType_t start_tick = xTaskGetTickCount(); while (__atomic_load_n(&lbm_ref_count, __ATOMIC_ACQUIRE) > 1) { - vTaskDelay(pdMS_TO_TICKS(1)); - BLE_LOG_ASSERT(time_waited++ < 1000); - } - - /* Queue transports with logs */ - ble_log_lbm_t *lbm; - ble_log_prph_trans_t **trans; - - /* Flush pools */ - for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { - lbm = &(lbm_ctx->lbm_pool[i]); - int trans_idx = lbm->trans_idx; - for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) { - trans = &(lbm->trans[trans_idx]); - if (!__atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE) && - (*trans)->pos) { - ble_log_rt_queue_trans(trans); - } - trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1); + if ((xTaskGetTickCount() - start_tick) >= + pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) { + ESP_LOGE(TAG, "Timed out waiting for BLE Log writers"); + goto fail; } + vTaskDelay(1); } - /* Wait for transportation to finish */ - time_waited = 0; - bool in_progress; - do { - in_progress = false; - for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { - lbm = &(lbm_ctx->lbm_pool[i]); - for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) { - trans = &(lbm->trans[j]); - in_progress |= __atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE); - } - } - if (in_progress) { - vTaskDelay(pdMS_TO_TICKS(1)); - BLE_LOG_ASSERT(time_waited++ < 1000); - } - } while (in_progress); - - /* Reset statistics manager after all operations complete */ - for (int i = 0; i < BLE_LOG_SRC_MAX; i++) { - BLE_LOG_MEMSET(stat_mgr_ctx[i], 0, sizeof(ble_log_stat_mgr_t)); + if (!ble_log_lbm_flush_all_trans()) { + goto fail; } - for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { - lbm = &(lbm_ctx->lbm_pool[i]); - __atomic_store_n(&lbm->trans_inflight, 0, __ATOMIC_RELAXED); - __atomic_store_n(&lbm->trans_inflight_peak, 0, __ATOMIC_RELAXED); - } - ble_log_prph_reset_util_counters(); + ble_log_write_final_stat(); - /* Resume enable status */ + if (!ble_log_lbm_flush_all_trans()) { + goto fail; + } + ble_log_lbm_reset_stats(); + +fail: + /* Resume enable status after a completed or failed flush. */ lbm_enabled = lbm_enabled_copy; - deref: BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); __atomic_clear(&flush_in_progress, __ATOMIC_RELEASE); @@ -607,38 +702,33 @@ deref: BLE_LOG_IRAM_ATTR bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len) { + bool ret = false; + BLE_LOG_REF_COUNT_ACQUIRE(&lbm_ref_count); if (!lbm_enabled) { goto exit; } - /* Get transport from the best available pool */ - size_t payload_len = len + sizeof(uint32_t); - ble_log_lbm_t *lbm; - ble_log_prph_trans_t **trans; - if (!ble_log_lbm_acquire_trans(payload_len, &lbm, &trans)) { - goto failed; - } - - /* Write transport */ - uint32_t os_ts = pdTICKS_TO_MS(BLE_LOG_IN_ISR()? - xTaskGetTickCountFromISR(): - xTaskGetTickCount()); - ble_log_lbm_write_trans(trans, src_code, (const uint8_t *)&os_ts, - sizeof(uint32_t), addr, len, false); - - /* Release */ - ble_log_lbm_release(lbm); - BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); - return true; - -failed: - if (lbm_inited) { - ble_log_stat_mgr_update(src_code, payload_len, true); - } + ret = ble_log_write_hex_core(src_code, addr, len); exit: BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); - return false; + return ret; +} + +BLE_LOG_IRAM_ATTR +bool ble_log_write_internal(const uint8_t *addr, size_t len) +{ + bool ret = false; + + BLE_LOG_REF_COUNT_ACQUIRE(&lbm_ref_count); + if (!lbm_inited) { + goto exit; + } + + ret = ble_log_write_hex_core(BLE_LOG_SRC_INTERNAL, addr, len); +exit: + BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); + return ret; } #if CONFIG_BLE_LOG_LL_ENABLED diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_lbm.h b/components/bt/common/ble_log/src/internal_include/ble_log_lbm.h index 1d1e7042705..e63e6ff3a6e 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_lbm.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_lbm.h @@ -13,6 +13,7 @@ /* ---------------- */ /* Includes */ /* ---------------- */ +#include "ble_log.h" #include "ble_log_prph.h" #include "freertos/FreeRTOS.h" @@ -174,6 +175,25 @@ typedef struct { uint32_t lost_bytes_cnt; } __attribute__((packed)) ble_log_enh_stat_t; +/* -------------------------------- */ +/* Final Statistics Defines */ +/* -------------------------------- */ +typedef struct { + uint8_t src_code; + uint32_t written_frame_cnt; + uint32_t lost_frame_cnt; + uint32_t written_bytes_cnt; + uint32_t lost_bytes_cnt; +} __attribute__((packed)) ble_log_final_stat_entry_t; + +typedef struct { + uint8_t int_src_code; + uint8_t src_cnt; + ble_log_final_stat_entry_t entries[BLE_LOG_SRC_MAX]; +} __attribute__((packed)) ble_log_final_stat_t; + +#define BLE_LOG_FINAL_STAT_LEN sizeof(ble_log_final_stat_t) + /* -------------------------------------- */ /* Log Statistics Manager Context */ /* -------------------------------------- */ @@ -220,6 +240,8 @@ _Static_assert(CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE % BLE_LOG_TRANS_BUF_CNT == 0 #endif _Static_assert(CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE / BLE_LOG_TRANS_BUF_CNT >= BLE_LOG_FRAME_OVERHEAD, "Common LBM per-buffer size too small for a single frame"); +_Static_assert(BLE_LOG_TRANS_SIZE >= BLE_LOG_FINAL_STAT_LEN + sizeof(uint32_t) + BLE_LOG_FRAME_OVERHEAD, + "Common LBM per-buffer size too small for final statistics frame"); _Static_assert((BLE_LOG_TRANS_BUF_CNT & (BLE_LOG_TRANS_BUF_CNT - 1)) == 0, "BLE_LOG_TRANS_BUF_CNT must be a power of 2"); _Static_assert(1 + BLE_LOG_LBM_ATOMIC_TASK_CNT <= 16, @@ -235,6 +257,8 @@ _Static_assert(BLE_LOG_TRANS_BUF_CNT <= 255, bool ble_log_lbm_init(void); void ble_log_lbm_deinit(void); void ble_log_lbm_enable(bool enable); +bool ble_log_write_internal(const uint8_t *addr, size_t len); +void ble_log_write_final_stat(void); void ble_log_write_enh_stat(void); void ble_log_write_buf_util(void); #if BLE_LOG_UART_REDIR_ENABLED diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_util.h b/components/bt/common/ble_log/src/internal_include/ble_log_util.h index 7f79c45e64d..28d19308550 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_util.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_util.h @@ -144,6 +144,7 @@ typedef enum { BLE_LOG_INT_SRC_INFO, BLE_LOG_INT_SRC_FLUSH, BLE_LOG_INT_SRC_BUF_UTIL, + BLE_LOG_INT_SRC_FINAL_STAT, BLE_LOG_INT_SRC_MAX, } ble_log_int_src_t;