Merge branch 'refactor/ble-log-esp-timer-rt-migration' into 'master'

refactor: BLE Log Runtime Migration

See merge request espressif/esp-idf!52002
This commit is contained in:
Island
2026-09-01 11:28:59 +08:00
23 changed files with 1338 additions and 111 deletions
+7 -8
View File
@@ -2,6 +2,7 @@ config BLE_LOG_ENABLED
bool "Enable BT Log Async Output (Dev Only)" bool "Enable BT Log Async Output (Dev Only)"
select BLE_COMPRESSED_LOG_ENABLE select BLE_COMPRESSED_LOG_ENABLE
select BLE_HOST_COMPRESSED_LOG_ENABLE if BT_BLUEDROID_ENABLED select BLE_HOST_COMPRESSED_LOG_ENABLE if BT_BLUEDROID_ENABLED
select ESP_TIMER_IN_IRAM
default n default n
help help
Enable BT Log Async Output Enable BT Log Async Output
@@ -15,14 +16,6 @@ if BLE_LOG_ENABLED
that remain pending, reducing latency for low-volume or that remain pending, reducing latency for low-volume or
intermittent logging. 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 config BLE_LOG_LBM_TRANS_BUF_SIZE
int "Total buffer memory per common LBM (bytes)" int "Total buffer memory per common LBM (bytes)"
default 2048 default 2048
@@ -259,6 +252,12 @@ if BLE_LOG_ENABLED
int int
default 512 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 config BLE_LOG_TS_TRIGGER_TIMEOUT_MS
int int
depends on BLE_LOG_TS_ENABLED 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 ### Main Components
- **BLE Log Core** (`ble_log.c`): Module core responsible for initialization and coordination of sub-modules - **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 - **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 - **Peripheral Interface** (`ble_log_prph_*.c`): Peripheral interface abstraction layer supporting various transmission methods
- **Timestamp Sync** (`ble_log_ts.c`): Timestamp synchronization module - **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. - **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 - **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) - **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 - **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 - **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**: **Note**:
- All pending logs will be lost after calling this function - 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 - 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)` #### `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 transport buffers, resets statistics, and then restores the enable state that
was in effect before the call. was in effect before the call.
**Note**: This operation is blocking. If BLE Log was enabled before the call, **Note**: This operation is blocking and must run in an ordinary caller-owned
it remains enabled after the flush completes. 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)` #### `void ble_log_dump_to_console(void)`
@@ -447,9 +452,6 @@ if (!initialized) {
// Increase baud rate (default is now 3000000) // Increase baud rate (default is now 3000000)
// CONFIG_BLE_LOG_PRPH_UART_DMA_BAUD_RATE=3000000 // CONFIG_BLE_LOG_PRPH_UART_DMA_BAUD_RATE=3000000
// Adjust task priority
#define BLE_LOG_TASK_PRIO configMAX_PRIORITIES-3
``` ```
### Debugging Techniques ### Debugging Techniques
@@ -59,6 +59,7 @@ typedef enum {
bool ble_log_init(void); bool ble_log_init(void);
void ble_log_deinit(void); void ble_log_deinit(void);
bool ble_log_enable(bool enable); 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); void ble_log_flush(void);
bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len); 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); 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 * already inside the gate keep a reference until they finish; later
* writers are rejected. * writers are rejected.
* *
* 2. Runtime task must be stopped FIRST to prevent it from sending * 2. Runtime dispatch must be stopped FIRST to prevent it from sending
* transports to an already-destroyed peripheral driver. The queue * transports to an already-destroyed peripheral driver. Active
* is drained and pending transports are discarded. * 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 * 3. Peripheral interface is deinitialized SECOND. It waits for DMA
* in-flight DMA operations (started before the task was killed) to * operations started before runtime dispatch stopped, then destroys
* complete, then destroys the driver. This is safe because no new * the driver. No new DMA operations can start after runtime teardown.
* DMA operations can be started (the task is already dead).
* *
* 4. LBM is deinitialized LAST. At this point all DMA has completed * 4. LBM is deinitialized LAST. At this point all DMA has completed
* (ensured by step 3) and all queued transports have been drained * (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 { do {
in_progress = false; in_progress = false;
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) { for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
+131 -72
View File
@@ -14,10 +14,12 @@
#include "ble_log_lbm.h" #include "ble_log_lbm.h"
#include "esp_log.h" #include "esp_log.h"
#include "esp_timer.h"
#include "esp_chip_info.h" #include "esp_chip_info.h"
/* MACRO */ /* MACRO */
#define TAG "ble_log_rt" #define TAG "ble_log_rt"
#define BLE_LOG_RT_DEFER_TIMEOUT_US (1000)
#if CONFIG_BT_CONTROLLER_ENABLED #if CONFIG_BT_CONTROLLER_ENABLED
#if CONFIG_IDF_TARGET_ESP32 || CONFIG_IDF_TARGET_ESP32C3 || CONFIG_IDF_TARGET_ESP32S3 #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 */ /* VARIABLE */
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_inited = 0; 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 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 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 #if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_ts_enabled = 0; BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_ts_enabled = 0;
BLE_LOG_STATIC esp_timer_handle_t rt_ts_timer = NULL; BLE_LOG_STATIC esp_timer_handle_t rt_ts_timer = NULL;
#endif /* CONFIG_BLE_LOG_TS_ENABLED */ #endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* PRIVATE FUNCTION DECLARATION */ /* 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 #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); BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg);
#endif /* CONFIG_BLE_LOG_TS_ENABLED */ #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_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; uint32_t now = pdTICKS_TO_MS(xTaskGetTickCount());
ble_log_prph_trans_t *trans = NULL; if ((uint32_t)(now - rt_last_hook_os_ts) < BLE_LOG_TS_TRIGGER_TIMEOUT_MS) {
uint32_t curr_os_ts = 0; return;
uint32_t last_hook_os_ts = 0; }
while (1) rt_last_hook_os_ts = now;
{
/* 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);
}
/* Task hook */ /* Write version info: BLE Log version, idf commit (build-time),
curr_os_ts = pdTICKS_TO_MS(xTaskGetTickCount()); * linked-in BLE lib commits, chip model/revision (efuse, runtime-only).
if ((curr_os_ts - last_hook_os_ts) < BLE_LOG_TS_TRIGGER_TIMEOUT_MS) { * Libs absent from the build leave their fields zero. */
continue; ble_log_version_info_t version_info = {
} .int_src_code = BLE_LOG_INT_SRC_VERSION_INFO,
last_hook_os_ts = curr_os_ts; .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 #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 #endif
#if CONFIG_BT_CONTROLLER_ENABLED && defined(BLE_LOG_CONTROLLER_GET_COMMIT) #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_commit_copy(version_info.controller_commit, BLE_LOG_CONTROLLER_GET_COMMIT(),
BLE_LOG_LIB_COMMIT_LEN); BLE_LOG_LIB_COMMIT_LEN);
#endif #endif
#if CONFIG_BT_CONTROLLER_ENABLED && defined(BLE_LOG_BTDM_COMMON_GET_COMMIT) #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_commit_copy(version_info.btdm_common_commit, BLE_LOG_BTDM_COMMON_GET_COMMIT(),
BLE_LOG_LIB_COMMIT_LEN); BLE_LOG_LIB_COMMIT_LEN);
#endif #endif
#if CONFIG_BLE_MESH && CONFIG_BLE_MESH_V11_SUPPORT #if CONFIG_BLE_MESH && CONFIG_BLE_MESH_V11_SUPPORT
/* The hash is the substring after the last space of the lib string */ /* The hash is the substring after the last space of the lib string */
const char *mesh_commit = strrchr(bt_mesh_v11_commit_str, ' '); const char *mesh_commit = strrchr(bt_mesh_v11_commit_str, ' ');
if (mesh_commit) { if (mesh_commit) {
ble_log_commit_copy(version_info.mesh_commit, mesh_commit + 1, ble_log_commit_copy(version_info.mesh_commit, mesh_commit + 1,
BLE_LOG_LIB_COMMIT_LEN); BLE_LOG_LIB_COMMIT_LEN);
} }
#endif #endif
#if CONFIG_BT_AUDIO && CONFIG_SOC_BLE_AUDIO_SUPPORTED #if CONFIG_BT_AUDIO && CONFIG_SOC_BLE_AUDIO_SUPPORTED
ble_log_commit_copy(version_info.audio_commit, lib_audio_commit_get(), ble_log_commit_copy(version_info.audio_commit, lib_audio_commit_get(),
BLE_LOG_LIB_COMMIT_LEN); BLE_LOG_LIB_COMMIT_LEN);
#endif #endif
esp_chip_info_t chip_info; esp_chip_info_t chip_info;
esp_chip_info(&chip_info); esp_chip_info(&chip_info);
version_info.chip_model = (uint16_t)chip_info.model; version_info.chip_model = (uint16_t)chip_info.model;
version_info.chip_revision = chip_info.revision; version_info.chip_revision = chip_info.revision;
ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&version_info, ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&version_info,
sizeof(version_info)); sizeof(version_info));
ble_log_write_enh_stat(); ble_log_write_enh_stat();
ble_log_write_buf_util(); 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)) { !BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_ts_enabled)) {
return; return;
} }
ble_log_ts_info_t *ts_info = NULL; ble_log_ts_info_t *ts_info = NULL;
ble_log_ts_info_update(&ts_info); ble_log_ts_info_update(&ts_info);
if (ts_info) { if (ts_info) {
@@ -156,36 +185,39 @@ bool ble_log_rt_init(void)
return true; 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 *)); rt_queue_handle = xQueueCreate(BLE_LOG_TRANS_TOTAL_CNT, sizeof(ble_log_prph_trans_t *));
if (!rt_queue_handle) { if (!rt_queue_handle) {
goto exit; goto exit;
} }
/* Initialize task */ esp_timer_create_args_t defer_timer_args = {
if (xTaskCreate(ble_log_rt_task, "ble_log", BLE_LOG_TASK_STACK_SIZE, NULL, .callback = ble_log_rt_defer_cb,
BLE_LOG_TASK_PRIO, &rt_task_handle) != pdTRUE) { .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; goto exit;
} }
#if CONFIG_BLE_LOG_TS_ENABLED #if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_ATOMIC_STORE_RELAXED(rt_ts_enabled, false); BLE_LOG_ATOMIC_STORE_RELAXED(rt_ts_enabled, false);
/* Initialize ESP Timer Trigger */
esp_timer_create_args_t ts_timer_args = { esp_timer_create_args_t ts_timer_args = {
.callback = ble_log_rt_ts_trigger, .callback = ble_log_rt_ts_trigger,
.arg = NULL, .arg = NULL,
.dispatch_method = ESP_TIMER_TASK,
.name = "ble_log_ts_timer", .name = "ble_log_ts_timer",
/* Do not wake light sleep or replay every missed periodic callback. */
.skip_unhandled_events = true, .skip_unhandled_events = true,
}; };
if (esp_timer_create(&ts_timer_args, &rt_ts_timer) != ESP_OK) { if (esp_timer_create(&ts_timer_args, &rt_ts_timer) != ESP_OK ||
goto exit; esp_timer_start_periodic(rt_ts_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_US) != ESP_OK) {
}
if (esp_timer_start_periodic(rt_ts_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_MS * 1000) != ESP_OK) {
goto exit; goto exit;
} }
#endif /* CONFIG_BLE_LOG_TS_ENABLED */ #endif /* CONFIG_BLE_LOG_TS_ENABLED */
rt_last_hook_os_ts = 0;
BLE_LOG_ATOMIC_STORE_RELEASE(rt_inited, true); BLE_LOG_ATOMIC_STORE_RELEASE(rt_inited, true);
return true; return true;
@@ -196,9 +228,9 @@ exit:
void ble_log_rt_deinit(void) void ble_log_rt_deinit(void)
{ {
/* Closing gate: seq_cst on both sides (see also submit) so a submitter /* Closing gate: seq_cst on both sides (see also submit/drain) so a
* either sees rt_inited == false and bails, or its reference is visible * submitter either sees rt_inited == false and bails, or its reference
* to the ref-count wait before the task and queue are torn down. */ * is visible to the ref-count wait before the handles are deleted. */
BLE_LOG_ATOMIC_STORE_SEQ_CST(rt_inited, false); BLE_LOG_ATOMIC_STORE_SEQ_CST(rt_inited, false);
while (!ble_log_ref_count_wait(&rt_ref_count, 0)) { while (!ble_log_ref_count_wait(&rt_ref_count, 0)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log runtime references"); 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 */ #endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* CRITICAL: if (rt_defer_timer) {
* Task must be deinitialized before deinitializing queue */ esp_timer_stop_blocking(rt_defer_timer, portMAX_DELAY);
if (rt_task_handle) { esp_timer_delete(rt_defer_timer);
vTaskDelete(rt_task_handle); rt_defer_timer = NULL;
rt_task_handle = NULL;
} }
/* Drain remaining queue items to clean up transport state */
if (rt_queue_handle) { if (rt_queue_handle) {
ble_log_prph_trans_t *trans = NULL; ble_log_prph_trans_t *trans = NULL;
while (xQueueReceive(rt_queue_handle, &trans, 0) == pdTRUE) { 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) 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)) { if (!ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) {
ble_log_lbm_recycle_trans(trans); ble_log_lbm_recycle_trans(trans);
return; return;
} }
/* Queue depth == total transport buffer count, so a timeout-0 send cannot if (!rt_queue_handle) {
* fail for a valid transport; recycling on failure keeps submitters from BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
* blocking while they hold a lifetime reference. */ ble_log_lbm_recycle_trans(trans);
BaseType_t queued = BLE_LOG_IN_ISR() return;
}
bool in_isr = BLE_LOG_IN_ISR();
BaseType_t queued = in_isr
? xQueueSendFromISR(rt_queue_handle, &trans, NULL) ? xQueueSendFromISR(rt_queue_handle, &trans, NULL)
: xQueueSend(rt_queue_handle, &trans, 0); : xQueueSend(rt_queue_handle, &trans, 0);
if (queued != pdTRUE) { 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); ble_log_lbm_recycle_trans(trans);
return; 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); BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
} }
@@ -17,16 +17,15 @@
#include "freertos/FreeRTOS.h" #include "freertos/FreeRTOS.h"
#include "freertos/task.h" #include "freertos/task.h"
#include "freertos/queue.h" #include "freertos/queue.h"
#include "esp_task.h"
/* MACRO */ /* 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_MS (1000)
#define BLE_LOG_TS_TRIGGER_TIMEOUT_US (BLE_LOG_TS_TRIGGER_TIMEOUT_MS * 1000ULL)
/* INTERFACE */ /* INTERFACE */
bool ble_log_rt_init(void); bool ble_log_rt_init(void);
void ble_log_rt_deinit(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); void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans);
#endif /* __BLE_LOG_RT_H__ */ #endif /* __BLE_LOG_RT_H__ */
@@ -16,12 +16,22 @@
/* TYPEDEF */ /* TYPEDEF */
typedef struct { typedef struct {
uint8_t *trans_buf; uint8_t *trans_buf;
int64_t received_at_us;
} ble_log_prph_trans_ctx_t; } ble_log_prph_trans_ctx_t;
/* Reads and releases one pending transport, returning the bytes copied. typedef void (*ble_log_prph_test_auto_recycle_hook_t)(void *ctx);
/* Recycles transports immediately and calls hook instead of queueing them.
* This lets tests model a producer that refills the runtime queue while its
* dispatch callback is still running. */
void ble_log_prph_test_set_auto_recycle_hook(ble_log_prph_test_auto_recycle_hook_t hook,
void *ctx);
/* Reads and releases one pending transport, returning the bytes copied and
* optionally the time when the test peripheral received ownership.
* When bytes_per_second is non-zero the call blocks until the simulated * When bytes_per_second is non-zero the call blocks until the simulated
* link has transmitted the whole transport at that rate. */ * link has transmitted the whole transport at that rate. */
size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout, size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
uint32_t bytes_per_second); uint32_t bytes_per_second, int64_t *received_at_us);
#endif /* __BLE_LOG_PRPH_TEST_H__ */ #endif /* __BLE_LOG_PRPH_TEST_H__ */
@@ -13,6 +13,7 @@
#include "esp_timer.h" #include "esp_timer.h"
#include "freertos/queue.h" #include "freertos/queue.h"
#include "freertos/semphr.h" #include "freertos/semphr.h"
#include "freertos/task.h"
/* VARIABLE */ /* VARIABLE */
static QueueHandle_t s_pending_trans; static QueueHandle_t s_pending_trans;
@@ -21,6 +22,15 @@ static esp_timer_handle_t s_tx_timer;
static int64_t s_tx_deadline_us; static int64_t s_tx_deadline_us;
static uint32_t s_tx_rate; static uint32_t s_tx_rate;
typedef struct {
ble_log_prph_test_auto_recycle_hook_t hook;
void *ctx;
} ble_log_prph_test_hook_reg_t;
static ble_log_prph_test_hook_reg_t s_auto_recycle_slots[2];
static volatile uint32_t s_auto_recycle_idx;
static volatile uint32_t s_auto_recycle_busy;
static void test_tx_done(void *arg) static void test_tx_done(void *arg)
{ {
(void)arg; (void)arg;
@@ -50,6 +60,7 @@ bool ble_log_prph_init(size_t trans_cnt)
void ble_log_prph_deinit(void) void ble_log_prph_deinit(void)
{ {
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
s_tx_deadline_us = 0; s_tx_deadline_us = 0;
s_tx_rate = 0; s_tx_rate = 0;
if (s_tx_timer) { if (s_tx_timer) {
@@ -137,6 +148,21 @@ void ble_log_prph_trans_deinit(ble_log_prph_trans_t **trans)
* equivalent to a real peripheral's asynchronous tx_done callback. */ * equivalent to a real peripheral's asynchronous tx_done callback. */
void ble_log_prph_send_trans(ble_log_prph_trans_t *trans) void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
{ {
ble_log_prph_trans_ctx_t *ctx = trans->ctx;
ctx->received_at_us = esp_timer_get_time();
__atomic_fetch_add(&s_auto_recycle_busy, 1, __ATOMIC_ACQUIRE);
uint32_t idx = __atomic_load_n(&s_auto_recycle_idx, __ATOMIC_ACQUIRE);
ble_log_prph_test_hook_reg_t reg = s_auto_recycle_slots[idx & 1];
if (reg.hook) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
reg.hook(reg.ctx);
__atomic_fetch_sub(&s_auto_recycle_busy, 1, __ATOMIC_RELEASE);
return;
}
__atomic_fetch_sub(&s_auto_recycle_busy, 1, __ATOMIC_RELEASE);
if (xQueueSend(s_pending_trans, &trans, 0) != pdTRUE) { if (xQueueSend(s_pending_trans, &trans, 0) != pdTRUE) {
trans->pos = 0; trans->pos = 0;
ble_log_lbm_recycle_trans(trans); ble_log_lbm_recycle_trans(trans);
@@ -144,9 +170,31 @@ void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
} }
} }
size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout, void ble_log_prph_test_set_auto_recycle_hook(ble_log_prph_test_auto_recycle_hook_t hook,
uint32_t bytes_per_second) void *ctx)
{ {
while (__atomic_load_n(&s_auto_recycle_busy, __ATOMIC_ACQUIRE) != 0) {
vTaskDelay(1);
}
uint32_t next = !__atomic_load_n(&s_auto_recycle_idx, __ATOMIC_RELAXED);
s_auto_recycle_slots[next].hook = hook;
s_auto_recycle_slots[next].ctx = ctx;
__atomic_store_n(&s_auto_recycle_idx, next, __ATOMIC_RELEASE);
if (!hook) {
while (__atomic_load_n(&s_auto_recycle_busy, __ATOMIC_ACQUIRE) != 0) {
vTaskDelay(1);
}
}
}
size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
uint32_t bytes_per_second, int64_t *received_at_us)
{
if (received_at_us) {
*received_at_us = 0;
}
if (!data) { if (!data) {
return 0; return 0;
} }
@@ -179,6 +227,10 @@ size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
s_tx_rate = 0; s_tx_rate = 0;
} }
if (received_at_us) {
ble_log_prph_trans_ctx_t *ctx = trans->ctx;
*received_at_us = ctx->received_at_us;
}
size_t copied = len < trans->pos ? len : trans->pos; size_t copied = len < trans->pos ? len : trans->pos;
BLE_LOG_MEMCPY(data, trans->buf, copied); BLE_LOG_MEMCPY(data, trans->buf, copied);
trans->pos = 0; trans->pos = 0;
@@ -8,6 +8,14 @@ components/bt/common/ble_log/test_apps/ble_log_perf_test:
depends_components: depends_components:
- bt - bt
components/bt/common/ble_log/test_apps/ble_log_rt_test:
disable:
- if: IDF_TARGET != "none"
temporary: true
reason: No BLE Log test runners are available yet
depends_components:
- bt
components/bt/common/ble_log/test_apps/ble_log_test: components/bt/common/ble_log/test_apps/ble_log_test:
disable: disable:
- if: IDF_TARGET != "none" - if: IDF_TARGET != "none"
@@ -11,6 +11,9 @@ ESP32-C6). The transport is replaced by a software model
(`CONFIG_BLE_LOG_PRPH_TEST=y`) that mimics DMA ownership transfer and link (`CONFIG_BLE_LOG_PRPH_TEST=y`) that mimics DMA ownership transfer and link
bandwidth, so the measurements isolate the LBM layer itself. bandwidth, so the measurements isolate the LBM layer itself.
Runtime dispatch behavior and latency are covered by the sibling
`ble_log_rt_test` app.
## What Is Measured ## What Is Measured
| Dimension | Metrics | | Dimension | Metrics |
@@ -57,6 +60,9 @@ python3 tools/parse_perf_log.py capture.log --csv out.csv
Run the same capture twice (old vs new LBM) and diff the CSV. Run the same capture twice (old vs new LBM) and diff the CSV.
The parser also renders the `BLE_LOG_RT_PERF` latency lines printed by the
sibling `ble_log_rt_test` app.
## Supported Targets ## Supported Targets
| Supported Targets | ESP32 | ESP32-C2 | ESP32-C3 | ESP32-C5 | ESP32-C6 | ESP32-C61 | ESP32-H2 | ESP32-H21 | ESP32-H4 | ESP32-P4 | ESP32-S2 | ESP32-S3 | ESP32-S31 | | Supported Targets | ESP32 | ESP32-C2 | ESP32-C3 | ESP32-C5 | ESP32-C6 | ESP32-C61 | ESP32-H2 | ESP32-H21 | ESP32-H4 | ESP32-P4 | ESP32-S2 | ESP32-S3 | ESP32-S31 |
@@ -511,7 +511,7 @@ static void perf_sink_task(void *arg)
while (!sink->stop) { while (!sink->stop) {
size_t len = ble_log_prph_test_read(data, sizeof(data), size_t len = ble_log_prph_test_read(data, sizeof(data),
pdMS_TO_TICKS(PERF_READ_TIMEOUT_MS), pdMS_TO_TICKS(PERF_READ_TIMEOUT_MS),
sink->bytes_per_second); sink->bytes_per_second, NULL);
if (!len) { if (!len) {
sink->drained = true; sink->drained = true;
continue; continue;
@@ -746,7 +746,7 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
TEST_ASSERT_EQUAL(pdTRUE, xSemaphoreTake(sink.done, pdMS_TO_TICKS(1000))); TEST_ASSERT_EQUAL(pdTRUE, xSemaphoreTake(sink.done, pdMS_TO_TICKS(1000)));
uint8_t discard[BLE_LOG_TRANS_SIZE]; uint8_t discard[BLE_LOG_TRANS_SIZE];
while (ble_log_prph_test_read(discard, sizeof(discard), 0, 0)) { while (ble_log_prph_test_read(discard, sizeof(discard), 0, 0, NULL)) {
} }
uint64_t elapsed_us = run_end_us - run_start_us; uint64_t elapsed_us = run_end_us - run_start_us;
@@ -17,6 +17,7 @@ from typing import TypedDict
KV = re.compile(r'(\w+)=(\S+)') KV = re.compile(r'(\w+)=(\S+)')
WRITER_COLS = ('frames', 'failed', 'avg', 'avg_failed', 'p50', 'p95', 'p99', 'max') WRITER_COLS = ('frames', 'failed', 'avg', 'avg_failed', 'p50', 'p95', 'p99', 'max')
RT_COLS = ('mode', 'samples', 'batch', 'payload', 'min', 'avg', 'p50', 'p95', 'max')
class Run(TypedDict): class Run(TypedDict):
@@ -42,8 +43,12 @@ def main() -> int:
lines = f.read().splitlines() lines = f.read().splitlines()
runs: list[Run] = [] runs: list[Run] = []
rt_rows: list[dict[str, str]] = []
cur: Run | None = None cur: Run | None = None
for line in lines: for line in lines:
if line.startswith('BLE_LOG_RT_PERF '):
rt_rows.append(fields(line))
continue
if not line.startswith('BLE_LOG_PERF '): if not line.startswith('BLE_LOG_PERF '):
continue continue
kv = fields(line) kv = fields(line)
@@ -62,8 +67,8 @@ def main() -> int:
else: else:
cur['other'].append(line[len('BLE_LOG_PERF ') :]) cur['other'].append(line[len('BLE_LOG_PERF ') :])
if not runs: if not runs and not rt_rows:
print(f'no BLE_LOG_PERF lines found in {path}') print(f'no BLE_LOG_PERF or BLE_LOG_RT_PERF lines found in {path}')
return 1 return 1
for i, run in enumerate(runs, 1): for i, run in enumerate(runs, 1):
@@ -85,15 +90,39 @@ def main() -> int:
print(f'- `{o}`') print(f'- `{o}`')
print() print()
if rt_rows:
print('## Runtime dispatch')
print('| ' + ' | '.join(RT_COLS) + ' |')
print('|' + '---|' * len(RT_COLS))
for rt_row in rt_rows:
print('| ' + ' | '.join(rt_row.get(c, '-') for c in RT_COLS) + ' |')
print()
if csv_path: if csv_path:
with open(csv_path, 'w', newline='', encoding='utf-8') as f: with open(csv_path, 'w', newline='', encoding='utf-8') as f:
wcsv = csv.writer(f) wcsv = csv.writer(f)
wcsv.writerow(['run', 'mode', 'profile', 'link', 'isolate', 'writer', *WRITER_COLS]) wcsv.writerow(
[
'kind',
'run',
'mode',
'profile',
'link',
'isolate',
'writer',
*WRITER_COLS,
'samples',
'batch',
'payload',
'min',
]
)
for i, run in enumerate(runs, 1): for i, run in enumerate(runs, 1):
h = run['head'] h = run['head']
for w in run['writers']: for w in run['writers']:
wcsv.writerow( wcsv.writerow(
[ [
'perf',
i, i,
h.get('mode', ''), h.get('mode', ''),
h.get('profile', ''), h.get('profile', ''),
@@ -101,8 +130,36 @@ def main() -> int:
h.get('isolate', ''), h.get('isolate', ''),
w.get('writer', ''), w.get('writer', ''),
*(w.get(c, '') for c in WRITER_COLS), *(w.get(c, '') for c in WRITER_COLS),
'',
'',
'',
'',
] ]
) )
for rt_row in rt_rows:
wcsv.writerow(
[
'rt_perf',
'',
rt_row.get('mode', ''),
'',
'',
'',
'runtime',
'',
'',
rt_row.get('avg', ''),
'',
rt_row.get('p50', ''),
rt_row.get('p95', ''),
'',
rt_row.get('max', ''),
rt_row.get('samples', ''),
rt_row.get('batch', ''),
rt_row.get('payload', ''),
rt_row.get('min', ''),
]
)
print(f'CSV written to {csv_path}') print(f'CSV written to {csv_path}')
return 0 return 0
@@ -0,0 +1,13 @@
# SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
#
# SPDX-License-Identifier: CC0-1.0
cmake_minimum_required(VERSION 3.22)
list(PREPEND SDKCONFIG_DEFAULTS
"$ENV{IDF_PATH}/tools/test_apps/configs/sdkconfig.debug_helpers"
"sdkconfig.defaults")
set(COMPONENTS main)
include($ENV{IDF_PATH}/tools/cmake/project.cmake)
project(ble_log_rt_test)
@@ -0,0 +1,67 @@
# BLE Log Runtime Test App
## Overview
On-target regression and latency suite for the BLE Log runtime dispatch layer:
the esp_timer deferred batch dispatch and the submission ownership gate.
The app runs on real hardware (any BLE-capable chip, currently tested on
ESP32-C6 and ESP32-C5). The transport is replaced by a software model
(`CONFIG_BLE_LOG_PRPH_TEST=y`) that mimics DMA ownership transfer and stamps
the hand-over time, so dispatch latency is measured without a real link.
## Test Cases
- `runtime dispatch latency`: 32 single submissions and 32 four-transport
bursts. Verifies exact delivery order/count and prints enqueue-to-receipt
min/avg/p50/p95/max latency (`BLE_LOG_RT_PERF` lines) for the single,
first-in-burst, and last-in-burst paths.
- `runtime` regressions: shared ESP Timer task fairness, periodic timestamp
delivery without light-sleep wakeups, ISR-only submission delivery,
consumer-independent receipt timing, extra-marker detection, exact 1 ms
first-submission defer scheduling, full task-pool snapshot dispatch, deinit
racing submissions (SMP-pinned writer, failure-safe recovery), bounded
inflight-peak statistics, and monotonic millisecond waits at both supported
tick rates.
The first-deadline and full task-pool regressions require dispatch exclusion
while enqueueing, so they run on single-core builds only (they are ignored on
SMP targets). The deinit-race regression pins its writer to the other core on
SMP.
## Build, Flash, Run
```bash
cd components/bt/common/ble_log/test_apps/ble_log_rt_test
idf.py set-target <chip>
idf.py -p <PORT> build flash monitor
```
Timeout regressions are verified at both supported tick rates: the default
build uses the production 100 Hz; the 1000 Hz variant has a dedicated overlay:
```bash
idf.py -B build_1000 -p <PORT> -D SDKCONFIG=sdkconfig.1000 \
-D SDKCONFIG_DEFAULTS="sdkconfig.defaults;sdkconfig.defaults.tick_1000" \
set-target <chip> build flash monitor
```
The app boots into the Unity menu; enter a test number to run it.
## Parsing Results
The latency lines can be rendered into tables/CSV with the parser shipped in
the perf test app:
```bash
idf.py -p <PORT> monitor | tee capture.log
python3 ../ble_log_perf_test/tools/parse_perf_log.py capture.log
python3 ../ble_log_perf_test/tools/parse_perf_log.py capture.log --csv out.csv
```
## Supported Targets
| Supported Targets | ESP32 | ESP32-C2 | ESP32-C3 | ESP32-C5 | ESP32-C6 | ESP32-C61 | ESP32-H2 | ESP32-H21 | ESP32-H4 | ESP32-P4 | ESP32-S2 | ESP32-S3 | ESP32-S31 |
| ----------------- | ----- | -------- | -------- | -------- | -------- | --------- | -------- | --------- | -------- | -------- | -------- | -------- | --------- |
CI builds are temporarily disabled until BLE Log test runners are available.
@@ -0,0 +1,17 @@
# SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
#
# SPDX-License-Identifier: Apache-2.0
idf_component_register(
SRCS "test_ble_log_main.c" "test_ble_log_runtime.c"
INCLUDE_DIRS "."
PRIV_REQUIRES unity bt esp_hw_support esp_timer
WHOLE_ARCHIVE
)
idf_component_get_property(bt_dir bt COMPONENT_DIR)
target_include_directories(${COMPONENT_LIB} PRIVATE
"${bt_dir}/common/ble_log/include"
"${bt_dir}/common/ble_log/src/internal_include"
"${bt_dir}/common/ble_log/src/internal_include/prph"
)
@@ -0,0 +1,70 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <string.h>
#include "unity.h"
#include "unity_test_runner.h"
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_prph_test.h"
#include "test_ble_log_main.h"
bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
test_ble_log_frame_observer_t observer, void *ctx)
{
size_t offset = 0;
while (len - offset >= BLE_LOG_FRAME_OVERHEAD) {
ble_log_frame_head_t head;
memcpy(&head, data + offset, sizeof(head));
size_t frame_len = BLE_LOG_FRAME_OVERHEAD + head.length;
if (frame_len > len - offset) {
return false;
}
uint32_t checksum;
memcpy(&checksum, data + offset + BLE_LOG_FRAME_HEAD_LEN + head.length,
sizeof(checksum));
if (checksum != ble_log_fast_checksum(data + offset,
BLE_LOG_FRAME_HEAD_LEN + head.length)) {
return false;
}
if (observer) {
test_ble_log_frame_t frame = {
.src = head.frame_meta & 0xff,
.sn = head.frame_meta >> 8,
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
.payload_len = head.length,
};
observer(&frame, ctx);
}
offset += frame_len;
}
return offset == len;
}
void setUp(void)
{
}
void tearDown(void)
{
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
#if CONFIG_BLE_LOG_TS_ENABLED
(void)ble_log_sync_enable(false);
#endif
}
void app_main(void)
{
/* The BLE Log module has no automatic system init on this branch; the
* controller normally calls ble_log_init(). Initialize it explicitly. */
TEST_ASSERT_TRUE_MESSAGE(ble_log_init(), "BLE Log init failed");
unity_run_menu();
}
@@ -0,0 +1,27 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#pragma once
#include <stdbool.h>
#include <stddef.h>
#include <stdint.h>
#include "ble_log.h"
typedef struct {
ble_log_src_t src;
uint32_t sn;
const uint8_t *payload;
size_t payload_len;
} test_ble_log_frame_t;
typedef void (*test_ble_log_frame_observer_t)(const test_ble_log_frame_t *frame, void *ctx);
/* Walks a captured transport buffer, validating frame headers and checksums.
* Returns true when the whole buffer consists of valid frames. */
bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
test_ble_log_frame_observer_t observer, void *ctx);
@@ -0,0 +1,817 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <inttypes.h>
#include <stdbool.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_prph_test.h"
#include "ble_log_rt.h"
#include "esp_timer.h"
#include "freertos/FreeRTOS.h"
#include "freertos/semphr.h"
#include "freertos/task.h"
#include "test_ble_log_main.h"
#include "unity.h"
#define RT_SAMPLE_COUNT (32)
#define RT_BURST_SIZE (4)
#define RT_TASK_POOL_TRANS_COUNT ((BLE_LOG_LBM_ATOMIC_TASK_CNT + 1) * BLE_LOG_TRANS_BUF_CNT)
#define RT_READ_TIMEOUT_MS (100)
#define RT_QUIET_TIMEOUT_MS (10)
#define RT_QUIET_DRAIN_DEADLINE_MS (2000)
#define RT_EXPECTED_DEFER_US (1000)
#define RT_MARKER_MAGIC UINT32_C(0x52545046)
#define RT_USER_PAYLOAD_LEN (BLE_LOG_TRANS_SIZE - sizeof(uint32_t) - BLE_LOG_FRAME_OVERHEAD)
#define RT_STARVATION_FEEDBACK (16384)
#define RT_HEARTBEAT_DELAY_US (2000)
#define RT_HEARTBEAT_MAX_ELAPSED_US (10000)
#define RT_CONSUMER_DELAY_MS (30)
#define RT_RECEIVE_MAX_LATENCY_US (10000)
#define RT_BURST_SPAN_MAX_US (500)
#define RT_PEAK_WRITES (8)
#define RT_DEINIT_ROUNDS (200)
#define RT_JOIN_TIMEOUT_MS (5000)
typedef struct {
uint32_t magic;
uint32_t seq;
} rt_marker_t;
typedef struct {
bool found;
uint32_t seq;
uint32_t ts_count;
} rt_marker_observer_t;
typedef struct {
SemaphoreHandle_t done;
uint32_t remaining;
bool stop;
bool write_failed;
int64_t fired_us;
} rt_starvation_ctx_t;
typedef struct {
uint32_t stop;
uint32_t exited;
uint32_t attempts;
} rt_deinit_writer_ctx_t;
typedef struct {
uint32_t buf_util_frames;
uint32_t max_inflight_peak;
bool over_limit;
} rt_peak_observer_t;
_Static_assert(RT_USER_PAYLOAD_LEN >= sizeof(rt_marker_t),
"BLE Log transport is too small for the runtime test marker");
static uint8_t s_payload[RT_USER_PAYLOAD_LEN];
static uint8_t s_capture[BLE_LOG_TRANS_SIZE];
static uint32_t s_single_latency_us[RT_SAMPLE_COUNT];
static uint32_t s_burst_first_latency_us[RT_SAMPLE_COUNT];
static uint32_t s_burst_last_latency_us[RT_SAMPLE_COUNT];
static rt_starvation_ctx_t s_starvation;
/* File-scope so a writer that outlives the test never references a dead
* stack frame (same pattern as s_starvation). */
static rt_deinit_writer_ctx_t s_deinit_race;
static void prepare_payload(uint32_t seq)
{
rt_marker_t marker = {
.magic = RT_MARKER_MAGIC,
.seq = seq,
};
memset(s_payload, (uint8_t)seq, sizeof(s_payload));
memcpy(s_payload, &marker, sizeof(marker));
}
static void observe_runtime_marker(const test_ble_log_frame_t *frame, void *ctx)
{
rt_marker_observer_t *observer = ctx;
if (frame->src == BLE_LOG_SRC_INTERNAL &&
frame->payload_len > sizeof(uint32_t) &&
frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_TS) {
observer->ts_count++;
}
if (frame->src != BLE_LOG_SRC_CUSTOM ||
frame->payload_len < sizeof(uint32_t) + sizeof(rt_marker_t)) {
return;
}
rt_marker_t marker;
memcpy(&marker, frame->payload + sizeof(uint32_t), sizeof(marker));
if (marker.magic == RT_MARKER_MAGIC) {
observer->found = true;
observer->seq = marker.seq;
}
}
static TickType_t runtime_timeout_ticks(uint32_t timeout_ms)
{
uint64_t ticks = ((uint64_t)timeout_ms * configTICK_RATE_HZ + 999) / 1000;
if (ticks == 0) {
ticks = 1;
}
return ticks > portMAX_DELAY ? portMAX_DELAY : (TickType_t)ticks;
}
static bool runtime_deadline_ticks(int64_t deadline_us, TickType_t *ticks)
{
int64_t now_us = esp_timer_get_time();
if (now_us >= deadline_us) {
return false;
}
uint32_t remain_ms = (uint32_t)((deadline_us - now_us + 999) / 1000);
if (remain_ms == 0) {
remain_ms = 1;
}
*ticks = runtime_timeout_ticks(remain_ms);
return true;
}
static bool write_runtime_marker(uint32_t seq, int64_t *enqueued_at_us)
{
prepare_payload(seq);
/* Include LBM packing and queueing in the measured runtime latency. */
int64_t before_us = esp_timer_get_time();
if (!ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload))) {
return false;
}
if (enqueued_at_us) {
*enqueued_at_us = before_us;
}
return true;
}
static bool read_runtime_marker(uint32_t *seq, uint32_t *ts_count,
int64_t *received_at_us)
{
const int64_t deadline_us = esp_timer_get_time() +
(int64_t)RT_READ_TIMEOUT_MS * 1000;
uint32_t observed_ts = 0;
while (true) {
TickType_t remaining;
if (!runtime_deadline_ticks(deadline_us, &remaining)) {
return false;
}
int64_t transport_received_at_us;
size_t len = ble_log_prph_test_read(s_capture, sizeof(s_capture), remaining, 0,
&transport_received_at_us);
if (!len) {
continue;
}
rt_marker_observer_t observer = {0};
TEST_ASSERT_TRUE_MESSAGE(test_ble_log_walk_frames(s_capture, len,
observe_runtime_marker,
&observer),
"Runtime dispatch produced an invalid transport");
observed_ts += observer.ts_count;
if (observer.found) {
*seq = observer.seq;
if (ts_count) {
*ts_count = observed_ts;
}
if (received_at_us) {
*received_at_us = transport_received_at_us;
}
return true;
}
}
}
static bool runtime_stream_is_quiet(void)
{
const int64_t drain_deadline_us = esp_timer_get_time() +
(int64_t)RT_QUIET_DRAIN_DEADLINE_MS * 1000;
while (esp_timer_get_time() < drain_deadline_us) {
const int64_t gap_deadline_us = esp_timer_get_time() +
(int64_t)RT_QUIET_TIMEOUT_MS * 1000;
size_t len = 0;
while (esp_timer_get_time() < gap_deadline_us) {
TickType_t remaining;
if (!runtime_deadline_ticks(gap_deadline_us, &remaining)) {
break;
}
len = ble_log_prph_test_read(s_capture, sizeof(s_capture), remaining, 0, NULL);
if (len) {
break;
}
}
if (!len) {
return true;
}
rt_marker_observer_t observer = {0};
if (!test_ble_log_walk_frames(s_capture, len, observe_runtime_marker, &observer) ||
observer.found) {
return false;
}
}
return false;
}
static void refill_runtime_queue(void *arg)
{
rt_starvation_ctx_t *ctx = arg;
if (ctx->stop || !ctx->remaining) {
return;
}
ctx->remaining--;
if (!ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload))) {
ctx->write_failed = true;
}
}
static void heartbeat_cb(void *arg)
{
rt_starvation_ctx_t *ctx = arg;
ctx->fired_us = esp_timer_get_time();
ctx->stop = true;
xSemaphoreGive(ctx->done);
}
#if CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD
static void BLE_LOG_IRAM_ATTR isr_write_cb(void *arg)
{
(void)arg;
(void)ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
}
#endif
static void noop_callback(void *arg)
{
(void)arg;
}
static void deinit_writer_task(void *arg)
{
rt_deinit_writer_ctx_t *ctx = arg;
while (!__atomic_load_n(&ctx->stop, __ATOMIC_ACQUIRE)) {
ctx->attempts++;
(void)ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
taskYIELD();
}
__atomic_store_n(&ctx->exited, true, __ATOMIC_RELEASE);
vTaskDelete(NULL);
}
static void observe_buf_util(const test_ble_log_frame_t *frame, void *ctx)
{
rt_peak_observer_t *observer = ctx;
if (frame->src != BLE_LOG_SRC_INTERNAL ||
frame->payload_len < sizeof(uint32_t) + sizeof(ble_log_buf_util_t) ||
frame->payload[sizeof(uint32_t)] != BLE_LOG_INT_SRC_BUF_UTIL) {
return;
}
ble_log_buf_util_t util;
memcpy(&util, frame->payload + sizeof(uint32_t), sizeof(util));
observer->buf_util_frames++;
if (util.inflight_peak > observer->max_inflight_peak) {
observer->max_inflight_peak = util.inflight_peak;
}
if (util.inflight_peak > util.trans_cnt) {
observer->over_limit = true;
}
}
static int compare_u32(const void *lhs, const void *rhs)
{
uint32_t a = *(const uint32_t *)lhs;
uint32_t b = *(const uint32_t *)rhs;
return (a > b) - (a < b);
}
static uint32_t percentile(const uint32_t *sorted, size_t count, uint32_t percent)
{
size_t rank = (count * percent + 99) / 100;
return sorted[rank - 1];
}
static void print_latency_stats(const char *mode, uint32_t batch, uint32_t *samples)
{
uint64_t total = 0;
for (size_t i = 0; i < RT_SAMPLE_COUNT; i++) {
total += samples[i];
}
qsort(samples, RT_SAMPLE_COUNT, sizeof(samples[0]), compare_u32);
printf("BLE_LOG_RT_PERF mode=%s samples=%u batch=%u payload=%uB "
"min=%" PRIu32 "us avg=%" PRIu64 "us p50=%" PRIu32
"us p95=%" PRIu32 "us max=%" PRIu32 "us\n",
mode, (unsigned)RT_SAMPLE_COUNT, (unsigned)batch,
(unsigned)sizeof(s_payload), samples[0], total / RT_SAMPLE_COUNT,
percentile(samples, RT_SAMPLE_COUNT, 50),
percentile(samples, RT_SAMPLE_COUNT, 95),
samples[RT_SAMPLE_COUNT - 1]);
}
static void warm_up_runtime(void)
{
uint32_t received_seq;
prepare_payload(0);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
s_payload, sizeof(s_payload)));
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL, NULL),
"Timed out waiting for runtime warm-up dispatch");
TEST_ASSERT_EQUAL_UINT32(0, received_seq);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
}
TEST_CASE("BLE Log runtime millisecond waits remain nonzero",
"[ble_log][runtime][ignore]")
{
TEST_ASSERT_GREATER_THAN_UINT32(0, runtime_timeout_ticks(1));
TEST_ASSERT_GREATER_THAN_UINT32(
0, runtime_timeout_ticks(RT_QUIET_TIMEOUT_MS));
TEST_ASSERT_GREATER_THAN_UINT32(
0, runtime_timeout_ticks(RT_READ_TIMEOUT_MS));
const int64_t start_us = esp_timer_get_time();
const int64_t deadline_us = start_us + (int64_t)RT_READ_TIMEOUT_MS * 1000;
TickType_t ticks;
while (runtime_deadline_ticks(deadline_us, &ticks)) {
vTaskDelay(ticks);
}
TEST_ASSERT_TRUE_MESSAGE(
esp_timer_get_time() - start_us >= (int64_t)RT_READ_TIMEOUT_MS * 1000,
"Millisecond timeout returned before the requested deadline");
}
TEST_CASE("BLE Log runtime quiet check rejects an extra marker",
"[ble_log][runtime][ignore]")
{
const uint32_t first_seq = UINT32_C(0x35000);
uint32_t received_seq;
TEST_ASSERT_TRUE(ble_log_enable(true));
(void)runtime_stream_is_quiet();
prepare_payload(first_seq);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
s_payload, sizeof(s_payload)));
prepare_payload(first_seq + 1);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
s_payload, sizeof(s_payload)));
TEST_ASSERT_TRUE(read_runtime_marker(&received_seq, NULL, NULL));
TEST_ASSERT_EQUAL_UINT32(first_seq, received_seq);
bool quiet = runtime_stream_is_quiet();
TEST_ASSERT_FALSE_MESSAGE(quiet,
"Quiet check silently discarded an extra runtime marker");
}
TEST_CASE("BLE Log runtime latency excludes consumer delay",
"[ble_log][runtime][ignore]")
{
const uint32_t seq = UINT32_C(0x36000);
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
int64_t start_us;
TEST_ASSERT_TRUE(write_runtime_marker(seq, &start_us));
const int64_t delay_deadline_us = esp_timer_get_time() +
(int64_t)RT_CONSUMER_DELAY_MS * 1000;
TickType_t delay_ticks;
while (runtime_deadline_ticks(delay_deadline_us, &delay_ticks)) {
vTaskDelay(delay_ticks);
}
TEST_ASSERT_TRUE(read_runtime_marker(&received_seq, NULL, &received_at_us));
uint32_t measured_latency_us = (uint32_t)(received_at_us - start_us);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(received_at_us >= start_us);
TEST_ASSERT_LESS_THAN_UINT32_MESSAGE(
RT_RECEIVE_MAX_LATENCY_US, measured_latency_us,
"Runtime latency included time spent waiting for the consumer");
}
TEST_CASE("BLE Log ISR-only submission arms runtime dispatch",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD
TEST_IGNORE_MESSAGE("Requires ESP Timer ISR dispatch support");
#else
const uint32_t seq = UINT32_C(0x28000);
uint32_t received_seq = 0;
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
prepare_payload(seq);
esp_timer_handle_t isr_timer = NULL;
const esp_timer_create_args_t timer_args = {
.callback = isr_write_cb,
.dispatch_method = ESP_TIMER_ISR,
.name = "ble_log_isr_write",
};
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_create(&timer_args, &isr_timer));
esp_err_t start_err = esp_timer_start_once(isr_timer, 1);
bool received = start_err == ESP_OK &&
read_runtime_marker(&received_seq, NULL, NULL);
TEST_ASSERT_EQUAL(ESP_OK,
esp_timer_stop_blocking(isr_timer, portMAX_DELAY));
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_delete(isr_timer));
TEST_ASSERT_EQUAL(ESP_OK, start_err);
TEST_ASSERT_TRUE_MESSAGE(received,
"ISR submission did not arm runtime dispatch");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
#endif
}
#if CONFIG_BLE_LOG_TS_ENABLED
TEST_CASE("BLE Log periodic timestamp skips light sleep wakeups",
"[ble_log][runtime][timestamp][ignore]")
{
const uint32_t seq = UINT32_C(0x40000);
uint32_t received_seq;
uint32_t ts_count = 0;
esp_timer_handle_t wake_probe_timer = NULL;
const esp_timer_create_args_t wake_probe_args = {
.callback = noop_callback,
.dispatch_method = ESP_TIMER_TASK,
.name = "ble_log_wake_probe",
};
TEST_ESP_OK(esp_timer_create(&wake_probe_args, &wake_probe_timer));
int64_t probe_start_us = esp_timer_get_time();
TEST_ESP_OK(esp_timer_start_once(
wake_probe_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_US * 3 / 2));
int64_t next_wake_us = esp_timer_get_next_alarm_for_wake_up();
TEST_ESP_OK(esp_timer_stop(wake_probe_timer));
TEST_ESP_OK(esp_timer_delete(wake_probe_timer));
TEST_ASSERT_TRUE_MESSAGE(next_wake_us != INT64_MAX,
"Wake-capable probe timer was not scheduled");
TEST_ASSERT_GREATER_THAN_INT64_MESSAGE(
BLE_LOG_TS_TRIGGER_TIMEOUT_US * 5 / 4,
next_wake_us - probe_start_us,
"Periodic timestamp timer was selected to wake light sleep");
TEST_ASSERT_TRUE(ble_log_enable(true));
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE(ble_log_sync_enable(true));
for (int i = 0; i < 3; i++) {
vTaskDelay(runtime_timeout_ticks(CONFIG_BLE_LOG_TS_TRIGGER_TIMEOUT_MS));
}
TEST_ASSERT_TRUE(ble_log_sync_enable(false));
/* A full marker rolls the partial timestamp transport through the normal
* LBM submission path without making runtime dispatch the TS trigger. */
TEST_ASSERT_TRUE(write_runtime_marker(seq, NULL));
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, &ts_count, NULL),
"Timed out waiting for the periodic timestamp probe");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
0, ts_count,
"Periodic ESP timer did not emit a timestamp frame");
}
#endif
TEST_CASE("BLE Log runtime dispatch yields to other timer callbacks",
"[ble_log][runtime][ignore]")
{
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
memset(&s_starvation, 0, sizeof(s_starvation));
s_starvation.done = xSemaphoreCreateBinary();
s_starvation.remaining = RT_STARVATION_FEEDBACK;
TEST_ASSERT_NOT_NULL(s_starvation.done);
esp_timer_handle_t heartbeat_timer = NULL;
const esp_timer_create_args_t timer_args = {
.callback = heartbeat_cb,
.arg = &s_starvation,
.dispatch_method = ESP_TIMER_TASK,
.name = "ble_log_heartbeat",
.skip_unhandled_events = true,
};
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_create(&timer_args, &heartbeat_timer));
prepare_payload(UINT32_C(0x30000));
ble_log_prph_test_set_auto_recycle_hook(refill_runtime_queue, &s_starvation);
int64_t start_us = esp_timer_get_time();
esp_err_t start_err = esp_timer_start_once(heartbeat_timer,
RT_HEARTBEAT_DELAY_US);
bool wrote = start_err == ESP_OK &&
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload,
sizeof(s_payload));
bool heartbeat_fired = false;
if (wrote) {
heartbeat_fired =
xSemaphoreTake(s_starvation.done, runtime_timeout_ticks(1000)) == pdTRUE;
}
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
esp_timer_stop_blocking(heartbeat_timer, portMAX_DELAY);
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_delete(heartbeat_timer));
vSemaphoreDelete(s_starvation.done);
(void)runtime_stream_is_quiet();
TEST_ASSERT_EQUAL(ESP_OK, start_err);
TEST_ASSERT_TRUE_MESSAGE(wrote, "Feedback seed write failed");
TEST_ASSERT_TRUE_MESSAGE(heartbeat_fired,
"Shared ESP timer callback never got CPU time");
TEST_ASSERT_TRUE_MESSAGE(
s_starvation.remaining < RT_STARVATION_FEEDBACK,
"Fairness test did not create feedback load");
TEST_ASSERT_FALSE_MESSAGE(s_starvation.write_failed,
"Feedback write unexpectedly failed");
TEST_ASSERT_TRUE_MESSAGE(s_starvation.fired_us >= start_us,
"Heartbeat fired before feedback load started");
TEST_ASSERT_TRUE_MESSAGE(
s_starvation.fired_us - start_us < RT_HEARTBEAT_MAX_ELAPSED_US,
"Runtime dispatch monopolized the shared ESP timer task");
}
TEST_CASE("BLE Log runtime defer timer keeps its first deadline and wakes light sleep",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_FREERTOS_UNICORE
TEST_IGNORE_MESSAGE("Requires single-core scheduler suspension");
#else
const uint32_t base_seq = UINT32_C(0x38000);
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
bool wrote = true;
vTaskSuspendAll();
int64_t wake_before = esp_timer_get_next_alarm_for_wake_up();
prepare_payload(base_seq);
int64_t first_write_entry_us = esp_timer_get_time();
wrote = ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
int64_t first_write_return_us = esp_timer_get_time();
int64_t first_defer_wake_us = esp_timer_get_next_alarm_for_wake_up();
for (uint32_t i = 1; i < RT_BURST_SIZE; i++) {
wrote = wrote && write_runtime_marker(base_seq + i, NULL);
}
int64_t burst_defer_wake_us = esp_timer_get_next_alarm_for_wake_up();
(void)xTaskResumeAll();
TEST_ASSERT_TRUE(wrote);
for (uint32_t i = 0; i < RT_BURST_SIZE; i++) {
uint32_t received_seq;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL, NULL),
"Timed out waiting for defer-wake probe");
TEST_ASSERT_EQUAL_UINT32(base_seq + i, received_seq);
}
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE_MESSAGE(first_defer_wake_us != INT64_MAX,
"Defer timer was not scheduled as a light-sleep wake source");
TEST_ASSERT_TRUE_MESSAGE(first_defer_wake_us < wake_before,
"Defer timer was not the newly scheduled wake alarm");
TEST_ASSERT_GREATER_OR_EQUAL_INT64_MESSAGE(
first_write_entry_us + RT_EXPECTED_DEFER_US, first_defer_wake_us,
"Defer timer was armed earlier than the fixed 1 ms delay");
TEST_ASSERT_LESS_OR_EQUAL_INT64_MESSAGE(
first_write_return_us + RT_EXPECTED_DEFER_US, first_defer_wake_us,
"Defer timer was armed later than the fixed 1 ms delay");
TEST_ASSERT_EQUAL_INT64_MESSAGE(
first_defer_wake_us, burst_defer_wake_us,
"Burst submissions moved the first defer deadline");
#endif
}
TEST_CASE("BLE Log runtime dispatch latency", "[ble_log][runtime][perf][ignore]")
{
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
for (uint32_t sample = 0; sample < RT_SAMPLE_COUNT; sample++) {
uint32_t seq = UINT32_C(0x10000) + sample;
uint32_t received_seq;
int64_t received_at_us;
int64_t start_us;
TEST_ASSERT_TRUE(write_runtime_marker(seq, &start_us));
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
&received_at_us),
"Timed out waiting for a single runtime dispatch");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(received_at_us >= start_us);
s_single_latency_us[sample] = (uint32_t)(received_at_us - start_us);
}
TEST_ASSERT_TRUE_MESSAGE(runtime_stream_is_quiet(),
"Unexpected runtime marker after single samples");
for (uint32_t sample = 0; sample < RT_SAMPLE_COUNT; sample++) {
uint32_t base_seq = UINT32_C(0x20000) + sample * RT_BURST_SIZE;
int64_t start_us[RT_BURST_SIZE];
for (uint32_t i = 0; i < RT_BURST_SIZE; i++) {
TEST_ASSERT_TRUE(write_runtime_marker(base_seq + i, &start_us[i]));
}
for (uint32_t i = 0; i < RT_BURST_SIZE; i++) {
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
&received_at_us),
"Timed out waiting for a burst runtime dispatch");
TEST_ASSERT_TRUE(received_at_us >= start_us[i]);
if (i == 0) {
s_burst_first_latency_us[sample] =
(uint32_t)(received_at_us - start_us[i]);
}
if (i == RT_BURST_SIZE - 1) {
s_burst_last_latency_us[sample] =
(uint32_t)(received_at_us - start_us[i]);
}
TEST_ASSERT_EQUAL_UINT32(base_seq + i, received_seq);
}
TEST_ASSERT_TRUE_MESSAGE(runtime_stream_is_quiet(),
"Unexpected runtime marker after burst sample");
}
print_latency_stats("single", 1, s_single_latency_us);
print_latency_stats("burst_first", RT_BURST_SIZE, s_burst_first_latency_us);
print_latency_stats("burst_last", RT_BURST_SIZE, s_burst_last_latency_us);
}
TEST_CASE("BLE Log runtime drains the full task pool in one batch",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_FREERTOS_UNICORE
TEST_IGNORE_MESSAGE("Requires dispatch exclusion during enqueue (single core)");
#else
const uint32_t base_seq = UINT32_C(0x50000);
int64_t first_received_us = 0;
int64_t last_received_us = 0;
TEST_ASSERT_TRUE(ble_log_enable(true));
/* Flush from this ordinary test task so every task-pool transport is free
* before constructing the callback-entry snapshot. */
ble_log_prph_test_set_auto_recycle_hook(noop_callback, NULL);
ble_log_flush();
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
/* Fill every transport reachable from ordinary task context before the
* first callback. The callback must drain the complete entry snapshot
* without an artificial item cap. */
bool wrote = true;
vTaskSuspendAll();
for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) {
prepare_payload(base_seq + i);
wrote = wrote &&
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
}
(void)xTaskResumeAll();
TEST_ASSERT_TRUE_MESSAGE(wrote, "Full task-pool enqueue failed");
for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) {
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
&received_at_us),
"Timed out waiting for a batched burst dispatch");
TEST_ASSERT_EQUAL_UINT32(base_seq + i, received_seq);
if (i == 0) {
first_received_us = received_at_us;
}
last_received_us = received_at_us;
}
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_LESS_THAN_INT64_MESSAGE(
RT_BURST_SPAN_MAX_US, last_received_us - first_received_us,
"Burst was split across multiple dispatch callbacks "
"(per-item re-defer instead of one batch)");
#endif
}
TEST_CASE("BLE Log LBM inflight peak stays bounded under bursts",
"[ble_log][runtime][ignore]")
{
rt_peak_observer_t observer = {0};
TEST_ASSERT_TRUE(ble_log_enable(true));
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
/* Queue several transports without consuming them so LBM transports are
* submitted while earlier ones are still in flight. */
for (uint32_t i = 0; i < RT_PEAK_WRITES; i++) {
uint32_t seq = UINT32_C(0x80000) + i;
TEST_ASSERT_TRUE(write_runtime_marker(seq, NULL));
}
/* Snapshot the recorded peaks. A full marker forces the partial BUF_UTIL
* transport to roll over through the normal LBM submission path. */
ble_log_write_buf_util();
TEST_ASSERT_TRUE(write_runtime_marker(UINT32_C(0x81000), NULL));
TEST_ASSERT_TRUE(ble_log_rt_drain());
const int64_t deadline_us = esp_timer_get_time() +
(int64_t)RT_READ_TIMEOUT_MS * 1000;
while (true) {
TickType_t remaining;
if (!runtime_deadline_ticks(deadline_us, &remaining)) {
break;
}
size_t len = ble_log_prph_test_read(s_capture, sizeof(s_capture),
remaining, 0, NULL);
if (!len) {
break;
}
TEST_ASSERT_TRUE(test_ble_log_walk_frames(s_capture, len,
observe_buf_util, &observer));
}
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
0, observer.buf_util_frames,
"No BUF_UTIL snapshots observed after flush");
TEST_ASSERT_FALSE_MESSAGE(observer.over_limit,
"inflight_peak exceeded the LBM transport count");
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
1, observer.max_inflight_peak,
"Burst did not record concurrent inflight transports");
/* ponytail: a single sequential writer cannot make this fail on the old
* plain-volatile code; it checks presence and bounds of the recorded
* peaks. Failing on the data race itself needs concurrent submitters or
* TSan, which this on-target suite does not provide. */
}
TEST_CASE("BLE Log runtime survives deinit racing submissions",
"[ble_log][runtime][ignore]")
{
rt_deinit_writer_ctx_t *ctx = &s_deinit_race;
bool reinit_ok = true;
memset(ctx, 0, sizeof(*ctx));
prepare_payload(UINT32_C(0x70000));
#if CONFIG_FREERTOS_UNICORE
BaseType_t task_created = xTaskCreate(
deinit_writer_task, "ble_log_deinit_wr", 4096, ctx,
uxTaskPriorityGet(NULL), NULL);
#else
/* Pin the writer away from this core so submissions run concurrently
* with deinit instead of alternating at yield points. */
BaseType_t task_created = xTaskCreatePinnedToCore(
deinit_writer_task, "ble_log_deinit_wr", 4096, ctx,
uxTaskPriorityGet(NULL), NULL, (xPortGetCoreID() == 0) ? 1 : 0);
#endif
TEST_ASSERT_EQUAL_MESSAGE(pdPASS, task_created, "Writer task create failed");
for (int i = 0; i < RT_DEINIT_ROUNDS; i++) {
ble_log_deinit();
reinit_ok = reinit_ok && ble_log_init();
taskYIELD();
}
/* Stop the writer and join with a bound before touching ctx or asserting:
* a unity longjmp past a live writer would leave it on a dead stack. */
__atomic_store_n(&ctx->stop, true, __ATOMIC_RELEASE);
const int64_t join_deadline_us = esp_timer_get_time() +
(int64_t)RT_JOIN_TIMEOUT_MS * 1000;
while (!__atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE)) {
TickType_t join_ticks;
if (!runtime_deadline_ticks(join_deadline_us, &join_ticks)) {
break;
}
vTaskDelay(join_ticks);
}
/* Recover module state before any assertion can abort the test: a
* failed re-init leaves the module deinit-ed and tearDown does not
* restore it, which would cascade into every later test. */
ble_log_deinit();
bool recovered = ble_log_init();
reinit_ok = reinit_ok && recovered;
TEST_ASSERT_TRUE_MESSAGE(
__atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE),
"Writer task did not exit after stop");
TEST_ASSERT_TRUE_MESSAGE(reinit_ok, "BLE Log re-init failed during the race");
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
RT_DEINIT_ROUNDS, ctx->attempts,
"Writer task did not run during the deinit race");
warm_up_runtime();
}
@@ -0,0 +1,14 @@
CONFIG_BT_ENABLED=y
CONFIG_BLE_LOG_ENABLED=y
CONFIG_BLE_LOG_PRPH_TEST=y
# Exercise the ISR-only runtime submission path.
CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD=y
# Production tick rate; the 1000 Hz regression variant is built from
# sdkconfig.defaults.tick_1000.
CONFIG_FREERTOS_HZ=100
CONFIG_BLE_LOG_TS_ENABLED=y
# Keep the production TS/hook cadence (Kconfig default 1000 ms) so the
# regressions see the production info/stat/buf-util cadence.
CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU0=n
# 64-bit assertions used by the runtime latency checks
CONFIG_UNITY_ENABLE_64BIT=y
@@ -0,0 +1,3 @@
# 1000 Hz tick regression. Use with sdkconfig.defaults:
# -D SDKCONFIG_DEFAULTS="sdkconfig.defaults;sdkconfig.defaults.tick_1000"
CONFIG_FREERTOS_HZ=1000
@@ -9,7 +9,7 @@
This test app verifies the BLE Log runtime behaviour on target, using the This test app verifies the BLE Log runtime behaviour on target, using the
in-memory test peripheral (`CONFIG_BLE_LOG_PRPH_TEST=y`) to capture the in-memory test peripheral (`CONFIG_BLE_LOG_PRPH_TEST=y`) to capture the
transport stream written by the runtime task hook. transport stream written by the runtime dispatch hook.
Currently covered: Currently covered:
@@ -24,7 +24,7 @@
#error "BLE Log test app requires CONFIG_BLE_LOG_PRPH_TEST" #error "BLE Log test app requires CONFIG_BLE_LOG_PRPH_TEST"
#endif #endif
/* The runtime task hook is throttled to one pass per /* The runtime dispatch hook is throttled to one pass per
* BLE_LOG_TS_TRIGGER_TIMEOUT_MS; let the window elapse between write bursts * BLE_LOG_TS_TRIGGER_TIMEOUT_MS; let the window elapse between write bursts
* so a hook pass is guaranteed to run after the settle delay. */ * so a hook pass is guaranteed to run after the settle delay. */
#define TEST_HOOK_SETTLE_MS (BLE_LOG_TS_TRIGGER_TIMEOUT_MS + 100) #define TEST_HOOK_SETTLE_MS (BLE_LOG_TS_TRIGGER_TIMEOUT_MS + 100)
@@ -102,7 +102,8 @@ static void test_reader_task(void *arg)
reader_ctx_t *ctx = arg; reader_ctx_t *ctx = arg;
while (!ctx->stop) { while (!ctx->stop) {
size_t len = ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), size_t len = ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0); pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0,
NULL);
if (len > 0 && if (len > 0 &&
!test_ble_log_walk_frames(s_read_buf, len, capture_version_info_frame, !test_ble_log_walk_frames(s_read_buf, len, capture_version_info_frame,
&ctx->capture)) { &ctx->capture)) {
@@ -127,7 +128,7 @@ TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]")
TEST_READER_PRIO, &reader)); TEST_READER_PRIO, &reader));
TEST_ASSERT_TRUE(ble_log_enable(true)); TEST_ASSERT_TRUE(ble_log_enable(true));
/* Transports are auto-submitted once full, which wakes the runtime task; /* Transports are auto-submitted once full, which arms the defer alarm;
* after the throttle window elapses, a hook pass writes the version frame * after the throttle window elapses, a hook pass writes the version frame
* into the LBM and a later transport carries it out. ble_log_flush() * into the LBM and a later transport carries it out. ble_log_flush()
* cannot be used here: it disables the module while waiting for the * cannot be used here: it disables the module while waiting for the