From 620a3c90a973639c1c9aacf42770796f6ccfe883 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 25 Aug 2026 10:55:36 +0800 Subject: [PATCH 1/2] 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. --- components/bt/common/ble_log/Kconfig.in | 15 +- components/bt/common/ble_log/README.md | 16 +- .../bt/common/ble_log/include/ble_log.h | 1 + components/bt/common/ble_log/src/ble_log.c | 14 +- .../bt/common/ble_log/src/ble_log_lbm.c | 7 +- components/bt/common/ble_log/src/ble_log_rt.c | 203 +++++++++++------- .../ble_log/src/internal_include/ble_log_rt.h | 5 +- 7 files changed, 163 insertions(+), 98 deletions(-) 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__ */ From 327016d1a31ce1f93950067197759d79877e2318 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Tue, 25 Aug 2026 11:03:55 +0800 Subject: [PATCH 2/2] test(ble_log): add dedicated runtime dispatch test app Extend the test peripheral with receipt timestamps and an auto-recycle hook so runtime tests can observe handoff latency and sustain arrivals from dispatch completion. Add a standalone Unity app covering fixed first-submission deadlines, callback-entry batch drain, shared ESP timer task fairness, periodic timestamp light-sleep behavior, synchronous flush, dispatch latency, deinit races, bounded inflight peaks, and timeout conversion at both supported tick rates. Verify FIFO delivery and reject delayed-consumer and extra-marker false positives. Render BLE_LOG_RT_PERF lines in the performance log parser and cross-reference the runtime and performance apps from their READMEs. --- .../internal_include/prph/ble_log_prph_test.h | 14 +- .../ble_log/src/prph/ble_log_prph_test.c | 56 +- .../ble_log/test_apps/.build-test-rules.yml | 8 + .../test_apps/ble_log_perf_test/README.md | 6 + .../main/test_ble_log_perf.c | 4 +- .../ble_log_perf_test/tools/parse_perf_log.py | 63 +- .../test_apps/ble_log_rt_test/CMakeLists.txt | 13 + .../test_apps/ble_log_rt_test/README.md | 67 ++ .../ble_log_rt_test/main/CMakeLists.txt | 17 + .../ble_log_rt_test/main/test_ble_log_main.c | 70 ++ .../ble_log_rt_test/main/test_ble_log_main.h | 27 + .../main/test_ble_log_runtime.c | 817 ++++++++++++++++++ .../ble_log_rt_test/sdkconfig.defaults | 14 + .../sdkconfig.defaults.tick_1000 | 3 + .../ble_log/test_apps/ble_log_test/README.md | 2 +- .../ble_log_test/main/test_ble_log_rt.c | 7 +- 16 files changed, 1175 insertions(+), 13 deletions(-) create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/CMakeLists.txt create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/main/CMakeLists.txt create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.h create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults create mode 100644 components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults.tick_1000 diff --git a/components/bt/common/ble_log/src/internal_include/prph/ble_log_prph_test.h b/components/bt/common/ble_log/src/internal_include/prph/ble_log_prph_test.h index b5d3b9eed1e..bb5fdab42a0 100644 --- a/components/bt/common/ble_log/src/internal_include/prph/ble_log_prph_test.h +++ b/components/bt/common/ble_log/src/internal_include/prph/ble_log_prph_test.h @@ -16,12 +16,22 @@ /* TYPEDEF */ typedef struct { uint8_t *trans_buf; + int64_t received_at_us; } 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 * 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, - uint32_t bytes_per_second); + uint32_t bytes_per_second, int64_t *received_at_us); #endif /* __BLE_LOG_PRPH_TEST_H__ */ diff --git a/components/bt/common/ble_log/src/prph/ble_log_prph_test.c b/components/bt/common/ble_log/src/prph/ble_log_prph_test.c index 6e9e9d848b6..28f6982901c 100644 --- a/components/bt/common/ble_log/src/prph/ble_log_prph_test.c +++ b/components/bt/common/ble_log/src/prph/ble_log_prph_test.c @@ -13,6 +13,7 @@ #include "esp_timer.h" #include "freertos/queue.h" #include "freertos/semphr.h" +#include "freertos/task.h" /* VARIABLE */ 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 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) { (void)arg; @@ -50,6 +60,7 @@ bool ble_log_prph_init(size_t trans_cnt) void ble_log_prph_deinit(void) { + ble_log_prph_test_set_auto_recycle_hook(NULL, NULL); s_tx_deadline_us = 0; s_tx_rate = 0; 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. */ 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) { trans->pos = 0; 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, - uint32_t bytes_per_second) +void ble_log_prph_test_set_auto_recycle_hook(ble_log_prph_test_auto_recycle_hook_t hook, + 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) { 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; } + 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; BLE_LOG_MEMCPY(data, trans->buf, copied); trans->pos = 0; diff --git a/components/bt/common/ble_log/test_apps/.build-test-rules.yml b/components/bt/common/ble_log/test_apps/.build-test-rules.yml index 4e7c9339041..2327f869853 100644 --- a/components/bt/common/ble_log/test_apps/.build-test-rules.yml +++ b/components/bt/common/ble_log/test_apps/.build-test-rules.yml @@ -8,6 +8,14 @@ components/bt/common/ble_log/test_apps/ble_log_perf_test: depends_components: - 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: disable: - if: IDF_TARGET != "none" diff --git a/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md b/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md index 9104774017a..de7c10477f3 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md +++ b/components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md @@ -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 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 | 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. +The parser also renders the `BLE_LOG_RT_PERF` latency lines printed by the +sibling `ble_log_rt_test` app. + ## 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 | diff --git a/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c b/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c index 91f0f72d641..202c3f8e9a4 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c +++ b/components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c @@ -511,7 +511,7 @@ static void perf_sink_task(void *arg) while (!sink->stop) { size_t len = ble_log_prph_test_read(data, sizeof(data), pdMS_TO_TICKS(PERF_READ_TIMEOUT_MS), - sink->bytes_per_second); + sink->bytes_per_second, NULL); if (!len) { sink->drained = true; 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))); 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; diff --git a/components/bt/common/ble_log/test_apps/ble_log_perf_test/tools/parse_perf_log.py b/components/bt/common/ble_log/test_apps/ble_log_perf_test/tools/parse_perf_log.py index 379e3762b9e..b025262a3e2 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_perf_test/tools/parse_perf_log.py +++ b/components/bt/common/ble_log/test_apps/ble_log_perf_test/tools/parse_perf_log.py @@ -17,6 +17,7 @@ from typing import TypedDict KV = re.compile(r'(\w+)=(\S+)') 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): @@ -42,8 +43,12 @@ def main() -> int: lines = f.read().splitlines() runs: list[Run] = [] + rt_rows: list[dict[str, str]] = [] cur: Run | None = None for line in lines: + if line.startswith('BLE_LOG_RT_PERF '): + rt_rows.append(fields(line)) + continue if not line.startswith('BLE_LOG_PERF '): continue kv = fields(line) @@ -62,8 +67,8 @@ def main() -> int: else: cur['other'].append(line[len('BLE_LOG_PERF ') :]) - if not runs: - print(f'no BLE_LOG_PERF lines found in {path}') + if not runs and not rt_rows: + print(f'no BLE_LOG_PERF or BLE_LOG_RT_PERF lines found in {path}') return 1 for i, run in enumerate(runs, 1): @@ -85,15 +90,39 @@ def main() -> int: print(f'- `{o}`') 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: with open(csv_path, 'w', newline='', encoding='utf-8') as 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): h = run['head'] for w in run['writers']: wcsv.writerow( [ + 'perf', i, h.get('mode', ''), h.get('profile', ''), @@ -101,8 +130,36 @@ def main() -> int: h.get('isolate', ''), w.get('writer', ''), *(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}') return 0 diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/CMakeLists.txt b/components/bt/common/ble_log/test_apps/ble_log_rt_test/CMakeLists.txt new file mode 100644 index 00000000000..914ca94c8e1 --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/CMakeLists.txt @@ -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) diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md b/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md new file mode 100644 index 00000000000..75af9d61753 --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md @@ -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 +idf.py -p 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 -D SDKCONFIG=sdkconfig.1000 \ + -D SDKCONFIG_DEFAULTS="sdkconfig.defaults;sdkconfig.defaults.tick_1000" \ + set-target 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 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. diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/CMakeLists.txt b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/CMakeLists.txt new file mode 100644 index 00000000000..d6d356fde4f --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/CMakeLists.txt @@ -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" +) diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c new file mode 100644 index 00000000000..bdb96ad8ae9 --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c @@ -0,0 +1,70 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include + +#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(); +} diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.h b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.h new file mode 100644 index 00000000000..1f82cf73b33 --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.h @@ -0,0 +1,27 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#pragma once + +#include +#include +#include + +#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); diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c new file mode 100644 index 00000000000..1f1791d1c53 --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c @@ -0,0 +1,817 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include +#include +#include +#include + +#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(); +} diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults b/components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults new file mode 100644 index 00000000000..75545a6db78 --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults @@ -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 diff --git a/components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults.tick_1000 b/components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults.tick_1000 new file mode 100644 index 00000000000..ac98eb628df --- /dev/null +++ b/components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults.tick_1000 @@ -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 diff --git a/components/bt/common/ble_log/test_apps/ble_log_test/README.md b/components/bt/common/ble_log/test_apps/ble_log_test/README.md index 316cb36a6ce..251e6e27533 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_test/README.md +++ b/components/bt/common/ble_log/test_apps/ble_log_test/README.md @@ -9,7 +9,7 @@ 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 -transport stream written by the runtime task hook. +transport stream written by the runtime dispatch hook. Currently covered: diff --git a/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c b/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c index 1ff0c6fd5cb..6f1ecb2e182 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c +++ b/components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c @@ -24,7 +24,7 @@ #error "BLE Log test app requires CONFIG_BLE_LOG_PRPH_TEST" #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 * so a hook pass is guaranteed to run after the settle delay. */ #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; while (!ctx->stop) { 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 && !test_ble_log_walk_frames(s_read_buf, len, capture_version_info_frame, &ctx->capture)) { @@ -127,7 +128,7 @@ TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]") TEST_READER_PRIO, &reader)); 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 * 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