diff --git a/components/bt/common/ble_log/Kconfig.in b/components/bt/common/ble_log/Kconfig.in index aeee0f11059..8888ab70559 100644 --- a/components/bt/common/ble_log/Kconfig.in +++ b/components/bt/common/ble_log/Kconfig.in @@ -2,6 +2,7 @@ config BLE_LOG_ENABLED bool "Enable BT Log Async Output (Dev Only)" select BLE_COMPRESSED_LOG_ENABLE select BLE_HOST_COMPRESSED_LOG_ENABLE if BT_BLUEDROID_ENABLED + select ESP_TIMER_IN_IRAM default n help Enable BT Log Async Output @@ -15,14 +16,6 @@ if BLE_LOG_ENABLED 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 - default 2048 if IDF_TARGET_ARCH_XTENSA - default 1024 - help - Stack size for BLE Log Task - config BLE_LOG_LBM_TRANS_BUF_SIZE int "Total buffer memory per common LBM (bytes)" default 2048 @@ -259,6 +252,12 @@ if BLE_LOG_ENABLED int default 512 + config BLE_LOG_TASK_STACK_SIZE + int + default 1024 if IDF_TARGET_ARCH_RISCV + default 2048 if IDF_TARGET_ARCH_XTENSA + default 1024 + config BLE_LOG_TS_TRIGGER_TIMEOUT_MS int depends on BLE_LOG_TS_ENABLED diff --git a/components/bt/common/ble_log/README.md b/components/bt/common/ble_log/README.md index c24f1b862f9..eb049112cde 100644 --- a/components/bt/common/ble_log/README.md +++ b/components/bt/common/ble_log/README.md @@ -22,7 +22,7 @@ The BLE Log module is an efficient logging system specifically designed for the ### Main Components - **BLE Log Core** (`ble_log.c`): Module core responsible for initialization and coordination of sub-modules -- **Runtime Manager** (`ble_log_rt.c`): Runtime task management for log transmission scheduling +- **Runtime Manager** (`ble_log_rt.c`): One-shot ESP Timer dispatch for log transmission scheduling - **Log Buffer Manager** (`ble_log_lbm.c`): Log buffer management supporting multiple locking mechanisms - **Peripheral Interface** (`ble_log_prph_*.c`): Peripheral interface abstraction layer supporting various transmission methods - **Timestamp Sync** (`ble_log_ts.c`): Timestamp synchronization module @@ -34,7 +34,7 @@ The BLE Log module is an efficient logging system specifically designed for the - **Multi-source Log Collection**: Supports multiple log sources including Link Layer, Host, HCI, UART redirection, etc. - **High Concurrency Processing**: Uses atomic and spin lock mechanisms for multi-task concurrent writing -- **Real-time Transmission**: Asynchronous transmission mechanism based on FreeRTOS tasks +- **Real-time Transmission**: Asynchronous transmission through ESP Timer task dispatch - **Data Integrity**: Checksum mechanism ensures data integrity (always enabled) - **Multi-buffer Transport**: Each LBM manages multiple transport buffers (default 4) for improved throughput over the legacy ping-pong design - **Cross-pool Buffer Fallback**: LBM acquire attempts all atomic LBMs before falling back to spinlock LBMs, improving buffer availability under contention @@ -162,6 +162,9 @@ Cleanup the BLE Log module and release all resources. **Note**: - All pending logs will be lost after calling this function - Peripheral interface will be cleaned up first to avoid DMA transmission issues during memory release +- This function may run concurrently with BLE Log write APIs. New writes are + rejected after shutdown begins, and deinit waits for in-progress writers + before releasing their buffers. #### `bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len)` @@ -185,8 +188,10 @@ 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. +**Note**: This operation is blocking and must run in an ordinary caller-owned +FreeRTOS task. Do not call it from an ISR or a system callback such as an ESP +Timer callback. If BLE Log was enabled before the call, it remains enabled +after the flush completes. #### `void ble_log_dump_to_console(void)` @@ -447,9 +452,6 @@ if (!initialized) { // Increase baud rate (default is now 3000000) // CONFIG_BLE_LOG_PRPH_UART_DMA_BAUD_RATE=3000000 - -// Adjust task priority -#define BLE_LOG_TASK_PRIO configMAX_PRIORITIES-3 ``` ### Debugging Techniques diff --git a/components/bt/common/ble_log/include/ble_log.h b/components/bt/common/ble_log/include/ble_log.h index e66441e7a2b..0a358a34f34 100644 --- a/components/bt/common/ble_log/include/ble_log.h +++ b/components/bt/common/ble_log/include/ble_log.h @@ -59,6 +59,7 @@ typedef enum { bool ble_log_init(void); void ble_log_deinit(void); bool ble_log_enable(bool enable); +/* Blocking; call only from a caller-owned task, not an ISR or system callback. */ void ble_log_flush(void); bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len); void ble_log_dump_to_console(void); diff --git a/components/bt/common/ble_log/src/ble_log.c b/components/bt/common/ble_log/src/ble_log.c index 6d5b18692c1..6a4e1936515 100644 --- a/components/bt/common/ble_log/src/ble_log.c +++ b/components/bt/common/ble_log/src/ble_log.c @@ -102,14 +102,14 @@ void ble_log_deinit(void) * already inside the gate keep a reference until they finish; later * writers are rejected. * - * 2. Runtime task must be stopped FIRST to prevent it from sending - * transports to an already-destroyed peripheral driver. The queue - * is drained and pending transports are discarded. + * 2. Runtime dispatch must be stopped FIRST to prevent it from sending + * transports to an already-destroyed peripheral driver. Active + * submissions and callbacks finish before the timers are deleted; + * the queue is then drained and pending transports are discarded. * - * 3. Peripheral interface is deinitialized SECOND. It waits for any - * in-flight DMA operations (started before the task was killed) to - * complete, then destroys the driver. This is safe because no new - * DMA operations can be started (the task is already dead). + * 3. Peripheral interface is deinitialized SECOND. It waits for DMA + * operations started before runtime dispatch stopped, then destroys + * the driver. No new DMA operations can start after runtime teardown. * * 4. LBM is deinitialized LAST. At this point all DMA has completed * (ensured by step 3) and all queued transports have been drained 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 a15c5f4782b..3e5d2566094 100644 --- a/components/bt/common/ble_log/src/ble_log_lbm.c +++ b/components/bt/common/ble_log/src/ble_log_lbm.c @@ -176,7 +176,12 @@ BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void) } } - /* Wait for transportation to finish */ + /* Dispatch anything still waiting on the defer alarm, then + * wait for transportation to finish */ + if (!ble_log_rt_drain()) { + return false; + } + do { in_progress = false; for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { diff --git a/components/bt/common/ble_log/src/ble_log_rt.c b/components/bt/common/ble_log/src/ble_log_rt.c index a425034b6ed..b085468be0a 100644 --- a/components/bt/common/ble_log/src/ble_log_rt.c +++ b/components/bt/common/ble_log/src/ble_log_rt.c @@ -14,10 +14,12 @@ #include "ble_log_lbm.h" #include "esp_log.h" +#include "esp_timer.h" #include "esp_chip_info.h" /* MACRO */ #define TAG "ble_log_rt" +#define BLE_LOG_RT_DEFER_TIMEOUT_US (1000) #if CONFIG_BT_CONTROLLER_ENABLED #if CONFIG_IDF_TARGET_ESP32 || CONFIG_IDF_TARGET_ESP32C3 || CONFIG_IDF_TARGET_ESP32S3 @@ -50,16 +52,19 @@ _Static_assert(sizeof(ble_log_version_info_t) == 58, /* VARIABLE */ BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_inited = 0; BLE_LOG_STATIC BLE_LOG_DRAM_ATTR volatile uint32_t rt_ref_count = 0; -BLE_LOG_STATIC TaskHandle_t rt_task_handle = NULL; BLE_LOG_STATIC BLE_LOG_DRAM_ATTR QueueHandle_t rt_queue_handle = NULL; +BLE_LOG_STATIC BLE_LOG_DRAM_ATTR esp_timer_handle_t rt_defer_timer = NULL; +BLE_LOG_STATIC uint32_t rt_last_hook_os_ts = 0; #if CONFIG_BLE_LOG_TS_ENABLED BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_ts_enabled = 0; BLE_LOG_STATIC esp_timer_handle_t rt_ts_timer = NULL; #endif /* CONFIG_BLE_LOG_TS_ENABLED */ /* PRIVATE FUNCTION DECLARATION */ +BLE_LOG_STATIC void ble_log_rt_defer_cb(void *arg); +BLE_LOG_STATIC bool ble_log_rt_dispatch(QueueHandle_t queue, UBaseType_t pending); +BLE_LOG_STATIC void ble_log_rt_run_hook(void); #if CONFIG_BLE_LOG_TS_ENABLED -BLE_LOG_STATIC void ble_log_rt_task(void *pvParameters); BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg); #endif /* CONFIG_BLE_LOG_TS_ENABLED */ @@ -70,66 +75,89 @@ BLE_LOG_STATIC void ble_log_commit_copy(uint8_t *dst, const char *src, size_t le BLE_LOG_MEMCPY(dst, src, strnlen(src, len)); } -BLE_LOG_STATIC void ble_log_rt_task(void *pvParameters) +BLE_LOG_STATIC void ble_log_rt_run_hook(void) { - (void)pvParameters; - ble_log_prph_trans_t *trans = NULL; - uint32_t curr_os_ts = 0; - uint32_t last_hook_os_ts = 0; - while (1) - { - /* CRITICAL: - * Blocking queue receive is mandatory for light sleep support */ - if (xQueueReceive(rt_queue_handle, &trans, portMAX_DELAY) == pdTRUE) { - ble_log_prph_send_trans(trans); - } + uint32_t now = pdTICKS_TO_MS(xTaskGetTickCount()); + if ((uint32_t)(now - rt_last_hook_os_ts) < BLE_LOG_TS_TRIGGER_TIMEOUT_MS) { + return; + } + rt_last_hook_os_ts = now; - /* Task hook */ - curr_os_ts = pdTICKS_TO_MS(xTaskGetTickCount()); - if ((curr_os_ts - last_hook_os_ts) < BLE_LOG_TS_TRIGGER_TIMEOUT_MS) { - continue; - } - last_hook_os_ts = curr_os_ts; - - /* Write version info: BLE Log version, idf commit (build-time), - * linked-in BLE lib commits, chip model/revision (efuse, runtime-only). - * Libs absent from the build leave their fields zero. */ - ble_log_version_info_t version_info = { - .int_src_code = BLE_LOG_INT_SRC_VERSION_INFO, - .version = BLE_LOG_VERSION, - }; + /* Write version info: BLE Log version, idf commit (build-time), + * linked-in BLE lib commits, chip model/revision (efuse, runtime-only). + * Libs absent from the build leave their fields zero. */ + ble_log_version_info_t version_info = { + .int_src_code = BLE_LOG_INT_SRC_VERSION_INFO, + .version = BLE_LOG_VERSION, + }; #ifdef BLE_LOG_IDF_COMMIT - BLE_LOG_MEMCPY(version_info.idf_commit, BLE_LOG_IDF_COMMIT, BLE_LOG_IDF_COMMIT_LEN); + BLE_LOG_MEMCPY(version_info.idf_commit, BLE_LOG_IDF_COMMIT, BLE_LOG_IDF_COMMIT_LEN); #endif #if CONFIG_BT_CONTROLLER_ENABLED && defined(BLE_LOG_CONTROLLER_GET_COMMIT) - ble_log_commit_copy(version_info.controller_commit, BLE_LOG_CONTROLLER_GET_COMMIT(), - BLE_LOG_LIB_COMMIT_LEN); + ble_log_commit_copy(version_info.controller_commit, BLE_LOG_CONTROLLER_GET_COMMIT(), + BLE_LOG_LIB_COMMIT_LEN); #endif #if CONFIG_BT_CONTROLLER_ENABLED && defined(BLE_LOG_BTDM_COMMON_GET_COMMIT) - ble_log_commit_copy(version_info.btdm_common_commit, BLE_LOG_BTDM_COMMON_GET_COMMIT(), - BLE_LOG_LIB_COMMIT_LEN); + ble_log_commit_copy(version_info.btdm_common_commit, BLE_LOG_BTDM_COMMON_GET_COMMIT(), + BLE_LOG_LIB_COMMIT_LEN); #endif #if CONFIG_BLE_MESH && CONFIG_BLE_MESH_V11_SUPPORT - /* The hash is the substring after the last space of the lib string */ - const char *mesh_commit = strrchr(bt_mesh_v11_commit_str, ' '); - if (mesh_commit) { - ble_log_commit_copy(version_info.mesh_commit, mesh_commit + 1, - BLE_LOG_LIB_COMMIT_LEN); - } + /* The hash is the substring after the last space of the lib string */ + const char *mesh_commit = strrchr(bt_mesh_v11_commit_str, ' '); + if (mesh_commit) { + ble_log_commit_copy(version_info.mesh_commit, mesh_commit + 1, + BLE_LOG_LIB_COMMIT_LEN); + } #endif #if CONFIG_BT_AUDIO && CONFIG_SOC_BLE_AUDIO_SUPPORTED - ble_log_commit_copy(version_info.audio_commit, lib_audio_commit_get(), - BLE_LOG_LIB_COMMIT_LEN); + ble_log_commit_copy(version_info.audio_commit, lib_audio_commit_get(), + BLE_LOG_LIB_COMMIT_LEN); #endif - esp_chip_info_t chip_info; - esp_chip_info(&chip_info); - version_info.chip_model = (uint16_t)chip_info.model; - version_info.chip_revision = chip_info.revision; - ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&version_info, - sizeof(version_info)); + esp_chip_info_t chip_info; + esp_chip_info(&chip_info); + version_info.chip_model = (uint16_t)chip_info.model; + version_info.chip_revision = chip_info.revision; + ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&version_info, + sizeof(version_info)); - ble_log_write_enh_stat(); - ble_log_write_buf_util(); + ble_log_write_enh_stat(); + ble_log_write_buf_util(); +} + +BLE_LOG_STATIC bool ble_log_rt_dispatch(QueueHandle_t queue, UBaseType_t pending) +{ + ble_log_prph_trans_t *trans = NULL; + bool processed = false; + while (pending-- && xQueueReceive(queue, &trans, 0) == pdTRUE) { + ble_log_prph_send_trans(trans); + processed = true; + } + return processed; +} + +BLE_LOG_STATIC void ble_log_rt_defer_cb(void *arg) +{ + (void)arg; + + if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_inited)) { + return; + } + + QueueHandle_t queue = rt_queue_handle; + if (!queue) { + return; + } + + UBaseType_t pending = uxQueueMessagesWaiting(queue); + if (ble_log_rt_dispatch(queue, pending)) { + ble_log_rt_run_hook(); + } + + pending = uxQueueMessagesWaiting(queue); + if (pending && + ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) { + (void)esp_timer_start_once(rt_defer_timer, BLE_LOG_RT_DEFER_TIMEOUT_US); + BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count); } } @@ -141,6 +169,7 @@ BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg) !BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_ts_enabled)) { return; } + ble_log_ts_info_t *ts_info = NULL; ble_log_ts_info_update(&ts_info); if (ts_info) { @@ -156,36 +185,39 @@ bool ble_log_rt_init(void) return true; } - /* CRITICAL: - * Queue must be initialized before creating task */ rt_queue_handle = xQueueCreate(BLE_LOG_TRANS_TOTAL_CNT, sizeof(ble_log_prph_trans_t *)); if (!rt_queue_handle) { goto exit; } - /* Initialize task */ - if (xTaskCreate(ble_log_rt_task, "ble_log", BLE_LOG_TASK_STACK_SIZE, NULL, - BLE_LOG_TASK_PRIO, &rt_task_handle) != pdTRUE) { + esp_timer_create_args_t defer_timer_args = { + .callback = ble_log_rt_defer_cb, + .dispatch_method = ESP_TIMER_TASK, + .name = "ble_log_rt", + /* One-shot dispatch delay must remain a light-sleep wake source. */ + .skip_unhandled_events = false, + }; + if (esp_timer_create(&defer_timer_args, &rt_defer_timer) != ESP_OK) { goto exit; } #if CONFIG_BLE_LOG_TS_ENABLED BLE_LOG_ATOMIC_STORE_RELAXED(rt_ts_enabled, false); - /* Initialize ESP Timer Trigger */ esp_timer_create_args_t ts_timer_args = { .callback = ble_log_rt_ts_trigger, .arg = NULL, + .dispatch_method = ESP_TIMER_TASK, .name = "ble_log_ts_timer", + /* Do not wake light sleep or replay every missed periodic callback. */ .skip_unhandled_events = true, }; - if (esp_timer_create(&ts_timer_args, &rt_ts_timer) != ESP_OK) { - goto exit; - } - if (esp_timer_start_periodic(rt_ts_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_MS * 1000) != ESP_OK) { + if (esp_timer_create(&ts_timer_args, &rt_ts_timer) != ESP_OK || + esp_timer_start_periodic(rt_ts_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_US) != ESP_OK) { goto exit; } #endif /* CONFIG_BLE_LOG_TS_ENABLED */ + rt_last_hook_os_ts = 0; BLE_LOG_ATOMIC_STORE_RELEASE(rt_inited, true); return true; @@ -196,9 +228,9 @@ exit: void ble_log_rt_deinit(void) { - /* Closing gate: seq_cst on both sides (see also submit) so a submitter - * either sees rt_inited == false and bails, or its reference is visible - * to the ref-count wait before the task and queue are torn down. */ + /* Closing gate: seq_cst on both sides (see also submit/drain) so a + * submitter either sees rt_inited == false and bails, or its reference + * is visible to the ref-count wait before the handles are deleted. */ BLE_LOG_ATOMIC_STORE_SEQ_CST(rt_inited, false); while (!ble_log_ref_count_wait(&rt_ref_count, 0)) { ESP_LOGE(TAG, "Timed out waiting for BLE Log runtime references"); @@ -213,14 +245,12 @@ void ble_log_rt_deinit(void) } #endif /* CONFIG_BLE_LOG_TS_ENABLED */ - /* CRITICAL: - * Task must be deinitialized before deinitializing queue */ - if (rt_task_handle) { - vTaskDelete(rt_task_handle); - rt_task_handle = NULL; + if (rt_defer_timer) { + esp_timer_stop_blocking(rt_defer_timer, portMAX_DELAY); + esp_timer_delete(rt_defer_timer); + rt_defer_timer = NULL; } - /* Drain remaining queue items to clean up transport state */ if (rt_queue_handle) { ble_log_prph_trans_t *trans = NULL; while (xQueueReceive(rt_queue_handle, &trans, 0) == pdTRUE) { @@ -232,16 +262,42 @@ void ble_log_rt_deinit(void) } } +bool ble_log_rt_drain(void) +{ + bool drained = false; + if (!ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) { + return false; + } + if (!rt_defer_timer || !rt_queue_handle) { + goto exit; + } + + if (esp_timer_stop_blocking(rt_defer_timer, portMAX_DELAY) != ESP_OK) { + goto exit; + } + QueueHandle_t queue = rt_queue_handle; + (void)ble_log_rt_dispatch(queue, uxQueueMessagesWaiting(queue)); + drained = true; + +exit: + BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count); + return drained; +} + BLE_LOG_IRAM_ATTR void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans) { if (!ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) { ble_log_lbm_recycle_trans(trans); return; } - /* Queue depth == total transport buffer count, so a timeout-0 send cannot - * fail for a valid transport; recycling on failure keeps submitters from - * blocking while they hold a lifetime reference. */ - BaseType_t queued = BLE_LOG_IN_ISR() + if (!rt_queue_handle) { + BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count); + ble_log_lbm_recycle_trans(trans); + return; + } + + bool in_isr = BLE_LOG_IN_ISR(); + BaseType_t queued = in_isr ? xQueueSendFromISR(rt_queue_handle, &trans, NULL) : xQueueSend(rt_queue_handle, &trans, 0); if (queued != pdTRUE) { @@ -249,6 +305,9 @@ BLE_LOG_IRAM_ATTR void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans) ble_log_lbm_recycle_trans(trans); return; } + + /* An active timer keeps the deadline anchored to the first submission. */ + (void)esp_timer_start_once(rt_defer_timer, BLE_LOG_RT_DEFER_TIMEOUT_US); BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count); } diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_rt.h b/components/bt/common/ble_log/src/internal_include/ble_log_rt.h index f6295692763..28d1018ce55 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_rt.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_rt.h @@ -17,16 +17,15 @@ #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "freertos/queue.h" -#include "esp_task.h" /* MACRO */ -#define BLE_LOG_TASK_PRIO (ESP_TASK_PRIO_MAX - 1) -#define BLE_LOG_TASK_STACK_SIZE CONFIG_BLE_LOG_TASK_STACK_SIZE #define BLE_LOG_TS_TRIGGER_TIMEOUT_MS (1000) +#define BLE_LOG_TS_TRIGGER_TIMEOUT_US (BLE_LOG_TS_TRIGGER_TIMEOUT_MS * 1000ULL) /* INTERFACE */ bool ble_log_rt_init(void); void ble_log_rt_deinit(void); +bool ble_log_rt_drain(void); void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans); #endif /* __BLE_LOG_RT_H__ */