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__ */ 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