refactor(ble_log): move runtime dispatch to esp_timer

Replace the dedicated BLE Log FreeRTOS task with a deferred esp_timer
batch dispatch. The first submission anchors a one-shot 1 ms deadline;
the callback drains the queue depth captured at entry and schedules the
next fixed defer only for arrivals left behind. Later submissions cannot
move the current deadline, and no fixed batch-size cap limits throughput.

Protect queue and timer lifetime with runtime references. Drain queued
submissions before ble_log_lbm_flush_all_trans waits for transport
ownership to return, so synchronous flush does not depend on the deferred
alarm firing.

Keep the defer alarm as a light-sleep wake source and select
ESP_TIMER_IN_IRAM. Timestamp synchronization uses the shared ESP timer task
with skipped unhandled events, so it neither wakes light sleep nor replays
missed periods. Retain legacy task and trigger symbols as hidden no-op
sdkconfig compatibility options.
This commit is contained in:
Zhou Xiao
2026-08-27 16:16:38 +08:00
parent ca7bd0d183
commit 620a3c90a9
7 changed files with 163 additions and 98 deletions
+7 -8
View File
@@ -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
+9 -7
View File
@@ -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
@@ -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);
+7 -7
View File
@@ -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
@@ -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++) {
+131 -72
View File
@@ -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);
}
@@ -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__ */