From 2cf0638686c686f642b8a863a22ee2fba7bf1453 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Sat, 5 Sep 2026 01:35:05 +0800 Subject: [PATCH] feat(ble_log): attribute compressed records with a task-id registry Protocol v8: every ENCODE record carries the one-byte id of the task that formatted it, replacing the incremental TASK_SWITCH marker scheme. Attribution becomes a property of the record: the per-source CAS lock, the last_task_handle writeback, and the try-lock contention drops are deleted, so concurrent writers to one source can no longer lose records to attribution races. The registry is a self-contained module (ble_log_task_registry.c/h, structured like the UART redirection writer): an append-only name-keyed table shared by every ENCODE writer, 16 bytes of RAM per entry, sized by CONFIG_BLE_LOG_TASK_ID_MAX. Word compares resolve ids lock-free on the record path; the registration CAS serializes only the cold path (once per task lifetime), and a record resolves its writer id after its claim succeeds, so the claim's lifetime reference pins the registry epoch and the id cannot cross an init/deinit boundary. A full registry or a contended registration degrades that record to the unknown id (0xFF) and still emits it. ISR callers stop at the lookup-miss branch before registration mutates shared state. Bindings are module-owned system output: every periodic snapshot window broadcasts one INTERNAL frame packing one fixed-layout record per registered entry on the registry's own dedicated transport, with a sequence of its own (a gap counts a skipped broadcast window, never a lost snapshot). A busy transport skips the window and the next one rebroadcasts, so a receiver that joined late converges on the next window. BLE_LOG_VERSION is bumped to 8: old decoders must not parse the new record layout. The compression encoders reject truncated NULL-buffer records instead of committing partial payloads, and the test app enables host compression with a 4-entry registry so the table-full path is reachable on target. --- components/bt/common/CMakeLists.txt | 1 + components/bt/common/ble_log/Kconfig.in | 34 +- components/bt/common/ble_log/README.md | 70 ++- .../extension/log_compression/Kconfig.in | 1 + .../log_compression/ble_log_compression.c | 91 +-- .../include/log_compression/utils.h | 12 +- .../bt/common/ble_log/include/ble_log.h | 10 +- .../bt/common/ble_log/src/ble_log_lbm_v2.c | 31 +- components/bt/common/ble_log/src/ble_log_rt.c | 7 +- .../ble_log/src/ble_log_task_registry.c | 272 +++++++++ .../src/internal_include/ble_log_lbm_v2.h | 28 +- .../internal_include/ble_log_task_registry.h | 87 +++ .../src/internal_include/ble_log_util.h | 5 +- .../main/test_ble_log_perf.c | 82 +++ .../ble_log/test_apps/ble_log_test/README.md | 2 +- .../ble_log_test/main/test_ble_log_rt.c | 572 +++++++++++++----- .../test_apps/ble_log_test/sdkconfig.defaults | 5 + 17 files changed, 1033 insertions(+), 277 deletions(-) create mode 100644 components/bt/common/ble_log/src/ble_log_task_registry.c create mode 100644 components/bt/common/ble_log/src/internal_include/ble_log_task_registry.h diff --git a/components/bt/common/CMakeLists.txt b/components/bt/common/CMakeLists.txt index 2f2f99b10cb..91e8c14b379 100644 --- a/components/bt/common/CMakeLists.txt +++ b/components/bt/common/CMakeLists.txt @@ -173,6 +173,7 @@ if(CONFIG_BLE_LOG_ENABLED) "${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_lbm_v2.c" "${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_redir.c" "${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_rt.c" + "${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_task_registry.c" "${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_util.c" ) diff --git a/components/bt/common/ble_log/Kconfig.in b/components/bt/common/ble_log/Kconfig.in index f0ba28e06be..ab45d42f07a 100644 --- a/components/bt/common/ble_log/Kconfig.in +++ b/components/bt/common/ble_log/Kconfig.in @@ -35,6 +35,24 @@ if BLE_LOG_ENABLED in one transport. SPI builds require a multiple of four so they can append peripheral-only zero padding to each logical frame. + config BLE_LOG_TASK_ID_MAX + int "Maximum number of distinct logging tasks" + range 2 32 + default 16 + help + Size of the task-id registry (protocol v8). Every ENCODE record + carries the one-byte id of the task that formatted it; the + registry maps task names to those stable ids. One binding record + per registered entry is broadcast as an INTERNAL frame on every + periodic snapshot window, so a receiver that missed or lost a + binding converges on the next window. A task that starts logging + after the registry is full falls back to the unknown id (0xFF) + and its records are still emitted. + + RAM cost is 16 bytes per entry (256 bytes at the default 16) + plus one dedicated binding transport (320 bytes at 16 entries, + 624 at 32; the broadcast frame must fit in one transport). + config BLE_LOG_IS_ESP_CONTROLLER bool "Current BLE Controller is ESP BLE Controller" depends on BT_CONTROLLER_ENABLED @@ -84,14 +102,6 @@ if BLE_LOG_ENABLED and require BLE_LOG_LL_ENABLED. Disabling this option suppresses HCI records from both capture paths. - config BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED - bool "Enable BLE Host side HCI Logging" - default n - select BLE_LOG_HCI_LOG_ENABLED - help - Deprecated. Renamed to BLE_LOG_HCI_LOG_ENABLED; kept so sdkconfig - files pinning the old name keep Host side HCI logging enabled. - config BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED bool "Toggle a GPIO on every BLE Log TS sync sample" default n @@ -270,6 +280,14 @@ if BLE_LOG_ENABLED config BLE_LOG_TS_TRIGGER_ESP_TIMER_ISR_DISPATCH_METHOD bool default n + + # Deprecated: renamed to BLE_LOG_HCI_LOG_ENABLED. No prompt, so it + # never appears in menuconfig; kept so sdkconfig files pinning the old + # name keep Host side HCI logging enabled. + config BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED + bool + default n + select BLE_LOG_HCI_LOG_ENABLED endif menu "Legacy SPI Log Output (Deprecated - use BT Log Async Output instead)" diff --git a/components/bt/common/ble_log/README.md b/components/bt/common/ble_log/README.md index cb6fbda3288..67c75721077 100644 --- a/components/bt/common/ble_log/README.md +++ b/components/bt/common/ble_log/README.md @@ -34,7 +34,7 @@ callback drains the queue depth captured at entry and schedules another fixed defer only for arrivals left behind, so it does not continuously monopolize the shared ESP Timer task. -## Version 7 frame +## Version 8 frame All multi-byte fields use the target's little-endian representation. @@ -75,7 +75,7 @@ redirection flush) is the alignment reference against the core timeline. ### Sources The public `ble_log_src_t` ABI is frozen and its values are the on-wire -source IDs of protocol v7 frames: +source IDs of protocol v8 frames: ```text 0 INTERNAL @@ -93,12 +93,14 @@ Log sources except INTERNAL and REDIR share one 24-bit Global SN: it is consumed at API entry, so it totally orders log attempts — including equal-timestamp records from different sources — and every lost or rejected attempt leaves a gap in the sequence. Internal Snapshot frames carry their -own separate sequence (a gap counts skipped snapshots), and the REDIR -console stream keeps its own sequence as well (a gap counts a dropped -console batch). `ble_log_init()` resets all three sequences, and its required -`INIT` snapshot starts a new receiver epoch. They remain continuous through -`FLUSH` within that epoch. Callers must not write until `ble_log_init()` -returns, so the `INIT` snapshot is submitted first. +own separate sequence (a gap counts skipped snapshots), the periodic +task-binding broadcast keeps its own sequence as well (a gap counts a +skipped broadcast window), and the REDIR console stream keeps its own +sequence too (a gap counts a dropped console batch). `ble_log_init()` +resets all the sequences, and its required `INIT` snapshot starts a new +receiver epoch. They remain continuous through `FLUSH` within that epoch. +Callers must not write until `ble_log_init()` returns, so the `INIT` +snapshot is submitted first. `CONFIG_BLE_LOG_HCI_LOG_ENABLED` controls HCI logging. Bluedroid and legacy VHCI NimBLE retain Host-side capture and suppress duplicate Controller HCI @@ -111,8 +113,11 @@ bit 7. Disabling HCI logging suppresses records from both capture paths. ## Internal Snapshot -All BLE Log-owned Internal information is emitted as one fixed-layout frame -from one dedicated 148-byte transport. Its logical frame length is 148 bytes. +All BLE Log-owned internal information is emitted as fixed-layout frames +from dedicated transports: the snapshot frame is 148 logical bytes on its +own transport, and the periodic task-binding broadcast has its own +transport sized to the registry (one full binding frame per window; +`CONFIG_BLE_LOG_TASK_ID_MAX` entries of 19 bytes plus a timestamp). The snapshot contains: @@ -155,7 +160,8 @@ void ble_log_deinit(void); bool ble_log_enable(bool enable); void ble_log_flush(void); bool ble_log_write_hex(ble_log_src_t source, const uint8_t *data, size_t len); -uint8_t *ble_log_claim(ble_log_src_t source, size_t maximum, uint32_t *handle); +uint8_t *ble_log_claim(ble_log_src_t source, size_t maximum, + uint32_t *handle, bool wait_for_transport); void ble_log_commit(uint32_t handle, size_t actual_len); void ble_log_write_hex_ll(uint32_t len, const uint8_t *data, uint32_t append_len, const uint8_t *append, @@ -187,7 +193,8 @@ Compression encoders write directly into shared-pool storage: ```c uint32_t handle; -uint8_t *payload = ble_log_claim(BLE_LOG_SRC_ENCODE, maximum, &handle); +uint8_t *payload = ble_log_claim(BLE_LOG_SRC_ENCODE, maximum, + &handle, true); if (payload) { size_t encoded = encode(payload, maximum); ble_log_commit(handle, encoded); @@ -195,15 +202,38 @@ if (payload) { ``` `ble_log_claim()` reserves the hidden frame header, ESP Timer timestamp, and -checksum. Every successful claim must be committed exactly once before +checksum. It waits for a shared transport in yieldable contexts when +`wait_for_transport` is true (writer backpressure); pass false for a lossy +fast path from contexts that must not block, such as the shared ESP Timer +task. Non-yieldable contexts (ISR, critical section) fail fast either way. +Every successful claim must be committed exactly once before `ble_log_deinit()`; `ble_log_commit(handle, 0)` cancels it. Handles include a transport generation so a stale handle cannot commit a later claim in the same lifecycle. Mesh, ISO, Bluedroid, and NimBLE compression no longer allocate three static -payload buffers per channel. Each logical compression source uses a non-blocking -trylock so its task-switch state follows commit order; a contending record is -canceled and counted as lost. +payload buffers per channel. Every ENCODE record names its writer: the byte +after the source is a task id from a name-keyed registry. The registry is a +self-contained module (`ble_log_task_registry.c/h`, structured like the +UART redirection writer: a small append-only table shared by every ENCODE +writer; RAM cost 16 bytes per entry, sized by `CONFIG_BLE_LOG_TASK_ID_MAX`). + +The registry broadcast is module-owned system output: every periodic snapshot +window, one INTERNAL frame (`BLE_LOG_INT_SRC_TASK_BINDING`) packs one +fixed-layout record per registered entry, binding each id to its task name. +It rides the registry's own dedicated transport with a sequence of its own +(a window skipped despite a non-empty registry leaves a gap in the binding +sequence, never in the snapshot sequence), is never counted in the +per-source written/lost stats, and never contends with the snapshot +transport or with user records for pool transports. A receiver that joined +late or lost a frame converges on the next window; a record of a new task +keeps its id and is bound by name at the next window. Announcements are +idempotent on the wire and best effort (a busy binding transport — the +previous broadcast still in DMA — skips a window). +Attribution is a property of the record, so concurrent writers to one source +need no serialization and never drop a record on contention. When the registry +is full, a new task degrades to the unknown id (`0xFF`) and its records are +still emitted. ## Configuration @@ -215,6 +245,7 @@ canceled and counted as lost. | `CONFIG_BLE_LOG_POOL_TRANS_SIZE` | 640 | Bytes per shared transport; SPI builds require a multiple of four | | `CONFIG_BLE_LOG_LL_ENABLED` | target dependent | Controller LL logging | | `CONFIG_BLE_LOG_HCI_LOG_ENABLED` | y | HCI capture from Host or Controller, selected by transport | +| `CONFIG_BLE_LOG_TASK_ID_MAX` | 16 | Task-id registry size, range 2..32; 16 bytes of RAM per entry | | `CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED` | n | Build the optional analyzer GPIO toggle | | `CONFIG_BLE_LOG_TS_ENABLED` | n | Deprecated compatibility entry selecting the GPIO toggle | @@ -235,7 +266,8 @@ cd ../ble_log_perf_test idf.py build ``` -`ble_log_test` validates golden v7 bytes, the consolidated Internal Snapshot, +`ble_log_test` validates golden v8 bytes, the consolidated Internal Snapshot, source/HCI metadata and capture selection, pool exhaustion and reserve use, -snapshot busy loss, stale claims, and enable/disable/deinit races. `ble_log_rt_test` covers batched -dispatch, timer behavior, inflight statistics, and repeated deinit races. +snapshot busy loss, stale claims, and enable/disable/deinit races. +`ble_log_rt_test` covers batched dispatch, timer behavior, inflight statistics, +and repeated deinit races. diff --git a/components/bt/common/ble_log/extension/log_compression/Kconfig.in b/components/bt/common/ble_log/extension/log_compression/Kconfig.in index 9b2f442a547..4db87fcdc63 100644 --- a/components/bt/common/ble_log/extension/log_compression/Kconfig.in +++ b/components/bt/common/ble_log/extension/log_compression/Kconfig.in @@ -15,6 +15,7 @@ config BLE_COMPRESSED_LOG_ENABLE for installation instructions. if BLE_COMPRESSED_LOG_ENABLE + source "$IDF_PATH/components/bt/common/ble_log/extension/log_compression/profile/mesh/Kconfig.mesh.in" source "$IDF_PATH/components/bt/common/ble_log/extension/log_compression/iso/audio/Kconfig.iso.in" source "$IDF_PATH/components/bt/common/ble_log/extension/log_compression/host/Kconfig.host.in" diff --git a/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c b/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c index 8eaef8661b0..b86b6f3b275 100644 --- a/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c +++ b/components/bt/common/ble_log/extension/log_compression/ble_log_compression.c @@ -9,9 +9,9 @@ // Private includes #include "freertos/FreeRTOS.h" -#include "freertos/task.h" #include "sdkconfig.h" #include "ble_log_lbm_v2.h" +#include "ble_log_task_registry.h" #include "ble_log_util.h" #include "log_compression/utils.h" @@ -39,69 +39,30 @@ _Static_assert(CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN <= } \ } while (0) -#if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE -char * mesh_last_task_handle = NULL; -static ble_log_atomic_lock_t mesh_source_lock; -#endif - -#if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE -char * iso_last_task_handle = NULL; -static ble_log_atomic_lock_t iso_source_lock; -#endif - -#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && CONFIG_BT_BLUEDROID_ENABLED -char * host_last_task_handle = NULL; -static ble_log_atomic_lock_t host_source_lock; -#endif - -#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && CONFIG_BT_NIMBLE_ENABLED -char * nimble_last_task_handle = NULL; -static ble_log_atomic_lock_t nimble_source_lock; -#endif - -#if CONFIG_BLE_LOG_PRPH_TEST -extern void ble_log_test_compression_after_lock_hook(uint8_t source) -__attribute__((weak)); -#endif - /* The maximum number of supported parameters is 64 */ #define LOG_HEADER(log_type, info) ((log_type << 6) | (info & 0x3f)) int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t *mgmt) { - char ** last_handle = NULL; - ble_log_atomic_lock_t *source_lock = NULL; uint16_t claim_len = 0; - char * cur_handle = pcTaskGetName(NULL); switch (source) { #if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE case BLE_COMPRESSED_LOG_OUT_SOURCE_MESH: case BLE_COMPRESSED_LOG_OUT_SOURCE_MESH_LIB: - last_handle = &mesh_last_task_handle; - source_lock = &mesh_source_lock; claim_len = CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN; break; #endif #if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE case BLE_COMPRESSED_LOG_OUT_SOURCE_ISO: case BLE_COMPRESSED_LOG_OUT_SOURCE_AUDIO_LIB: - last_handle = &iso_last_task_handle; - source_lock = &iso_source_lock; claim_len = CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN; break; #endif #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && (CONFIG_BT_BLUEDROID_ENABLED || CONFIG_BT_NIMBLE_ENABLED) case BLE_COMPRESSED_LOG_OUT_SOURCE_HOST: claim_len = CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN; -#if CONFIG_BT_BLUEDROID_ENABLED - last_handle = &host_last_task_handle; - source_lock = &host_source_lock; -#elif CONFIG_BT_NIMBLE_ENABLED - last_handle = &nimble_last_task_handle; - source_lock = &nimble_source_lock; -#endif break; #endif default: @@ -111,57 +72,34 @@ int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t *mgmt) mgmt->len = claim_len; mgmt->idx = 0; - mgmt->source_lock = source_lock; - mgmt->last_task_handle = last_handle; - mgmt->current_task_handle = cur_handle; - mgmt->task_switched = false; - mgmt->buffer = ble_log_claim(BLE_LOG_SRC_ENCODE, claim_len, &mgmt->handle); + mgmt->buffer = ble_log_claim(BLE_LOG_SRC_ENCODE, claim_len, + &mgmt->handle, true); if (!mgmt->buffer) { return -1; } - if (!BLE_LOG_CAS_ACQUIRE(source_lock)) { + /* Resolve the task id only after the claim succeeded: the claim's + * lifetime reference pins the current registry epoch, so the id + * cannot cross an init/deinit boundary (which reassigns ids from 0). + * Resolving before the claim instead left a window where a full + * deinit/reinit completed and the stale id named a different task. */ + uint8_t task_id = ble_log_task_id_current(); + if (ble_log_cp_push_u8(mgmt, source) != 0 || + ble_log_cp_push_u8(mgmt, task_id) != 0) { ble_log_commit(mgmt->handle, 0); return -1; } -#if CONFIG_BLE_LOG_PRPH_TEST - if (ble_log_test_compression_after_lock_hook) { - ble_log_test_compression_after_lock_hook(source); - } -#endif - - if (ble_log_cp_push_u8(mgmt, source) != 0) { - ble_log_commit(mgmt->handle, 0); - BLE_LOG_CAS_RELEASE(source_lock); - return -1; - } - char *previous_handle = __atomic_load_n(last_handle, __ATOMIC_RELAXED); - if (previous_handle == NULL || previous_handle != cur_handle) { - if (ble_log_cp_push_u8( - mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_TASK_SWITCH)) != 0) { - ble_log_commit(mgmt->handle, 0); - BLE_LOG_CAS_RELEASE(source_lock); - return -1; - } - mgmt->task_switched = true; - } return 0; } static inline int ble_compressed_log_commit(ble_cp_log_buffer_mgmt_t *mgmt) { ble_log_commit(mgmt->handle, mgmt->idx); - if (mgmt->task_switched) { - __atomic_store_n(mgmt->last_task_handle, mgmt->current_task_handle, - __ATOMIC_RELAXED); - } - BLE_LOG_CAS_RELEASE(mgmt->source_lock); return 0; } static inline int ble_compressed_log_abort(ble_cp_log_buffer_mgmt_t *mgmt) { ble_log_commit(mgmt->handle, 0); - BLE_LOG_CAS_RELEASE(mgmt->source_lock); return 0; } @@ -357,8 +295,11 @@ int ble_log_compressed_hex_print_buf(uint8_t source, uint32_t log_index, uint8_t } if (buf == NULL) { - ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_NULL_BUF)); - ble_log_cp_push_u16(&mgmt, log_index); + if (ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_NULL_BUF)) != 0 || + ble_log_cp_push_u16(&mgmt, log_index) != 0) { + ble_compressed_log_abort(&mgmt); + return 0; + } ble_compressed_log_commit(&mgmt); return 0; } diff --git a/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h b/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h index fe35e793ff3..969e85e9d94 100644 --- a/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h +++ b/components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h @@ -32,23 +32,19 @@ enum { #define LOG_TYPE_ZERO_ARGS 0 #define LOG_TYPE_HEX_ARGS 1 #define LOG_TYPE_HEX_BUF 2 -/* This type of message is used to update log information, - * such as there is currently a new task log */ +/* Informational in-band records (protocol v8). Task-id bindings used to + * be one of these; they are broadcast as INTERNAL frames on the periodic + * snapshot window now (see ble_log_task_registry.h), keeping the ENCODE + * stream user records only. */ #define LOG_TYPE_INFO 3 -#define LOG_TYPE_INFO_TASK_ID_UPDATE 0 #define LOG_TYPE_INFO_NULL_BUF 1 -#define LOG_TYPE_INFO_TASK_SWITCH 2 typedef struct { uint8_t *buffer; /* claim() payload pointer */ uint16_t idx; /* bytes written so far */ uint16_t len; /* claimed capacity (max_len) */ uint32_t handle; /* claim handle for commit/abort */ - volatile uint32_t *source_lock; - char **last_task_handle; - char *current_task_handle; - bool task_switched; } ble_cp_log_buffer_mgmt_t; static inline int ble_log_cp_buffer_safe_check(ble_cp_log_buffer_mgmt_t *pbuf_mgmt, uint16_t write_len) diff --git a/components/bt/common/ble_log/include/ble_log.h b/components/bt/common/ble_log/include/ble_log.h index c5ce103819d..98a7410e7c6 100644 --- a/components/bt/common/ble_log/include/ble_log.h +++ b/components/bt/common/ble_log/include/ble_log.h @@ -21,7 +21,7 @@ * memory requirements, keep it as less as possible; it's recommended to use subcode for more * log data structure decoding */ /* CRITICAL: this enum is a public ABI and must not be reordered or renamed. - * Its values are the base on-wire source IDs of protocol v7 frames. */ + * Its values are the base on-wire source IDs of protocol v8 frames. */ typedef enum { /* Internal */ BLE_LOG_SRC_INTERNAL = 0, @@ -69,8 +69,12 @@ bool ble_log_enable(bool enable); void ble_log_flush(void); /* Waits for a shared transport in yieldable contexts; ISR and critical-section callers fail fast. */ bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len); -/* Same backpressure as ble_log_write_hex(): yieldable claims wait for a shared transport. */ -uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, uint32_t *handle); +/* Same backpressure as ble_log_write_hex(): yieldable claims wait for a + * shared transport when wait_for_transport is true; pass false for a lossy + * fast path from contexts that must not block (system periodic output). + * Non-yieldable contexts (ISR, critical section) fail fast either way. */ +uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, + uint32_t *handle, bool wait_for_transport); void ble_log_commit(uint32_t handle, size_t actual_len); void ble_log_dump_to_console(void); #if CONFIG_BLE_LOG_LL_ENABLED diff --git a/components/bt/common/ble_log/src/ble_log_lbm_v2.c b/components/bt/common/ble_log/src/ble_log_lbm_v2.c index ef33c795b64..9ac016d0bf3 100644 --- a/components/bt/common/ble_log/src/ble_log_lbm_v2.c +++ b/components/bt/common/ble_log/src/ble_log_lbm_v2.c @@ -10,6 +10,7 @@ /* INCLUDE */ #include "ble_log.h" #include "ble_log_lbm_v2.h" +#include "ble_log_task_registry.h" #include "ble_log_rt.h" #include "esp_timer.h" @@ -560,7 +561,16 @@ void ble_log_pool_finish_frame(ble_log_prph_trans_t *trans, uint16_t payload_len /* ---------------------------------------------- */ /* CLAIM / COMMIT INTERFACE (holds lock) */ /* ---------------------------------------------- */ -uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, uint32_t *handle) + +/* Claim with a caller-chosen wait policy. wait_for_transport=true applies + * backpressure in a yieldable context (the writer waits for a shared + * transport instead of dropping); false is a lossy fast path that returns + * NULL on a busy pool, for callers that must never block (e.g. system + * periodic output on the shared ESP timer task). Non-yieldable contexts + * (ISR, scheduler suspended) never wait whatever the policy: they keep + * their dedicated reserve and fail fast on contention. */ +uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, + uint32_t *handle, bool wait_for_transport) { if (!handle || src_code != BLE_LOG_SRC_ENCODE || max_len == 0 || max_len > UINT16_MAX || BLE_LOG_IN_ISR()) { @@ -581,8 +591,12 @@ uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, uint32_t *handle) bool non_yield = !xPortCanYield() || xTaskGetSchedulerState() != taskSCHEDULER_RUNNING; size_t payload_capacity = sizeof(timestamp) + max_len; - ble_log_prph_trans_t *trans = - ble_log_pool_acquire(payload_capacity, non_yield, !non_yield); + /* Non-yieldable contexts never wait, whatever the requested policy: + * blocking there would suspend the only context that can free the + * transport. wait_for_transport=false is the lossy fast path for + * yieldable contexts that must not block. */ + ble_log_prph_trans_t *trans = ble_log_pool_acquire( + payload_capacity, non_yield, wait_for_transport && !non_yield); if (!trans) { ble_log_stat_mgr_mark_lost(src_code); BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); @@ -706,6 +720,11 @@ bool ble_log_lbm_init(void) BLE_LOG_MEMSET(stat_mgr_ctx, 0, sizeof(stat_mgr_ctx)); g_frame_sn = 0; g_snapshot_sn = 0; + /* Task registry: fresh epoch (registry, sequence and its dedicated + * transport) for the new receiver epoch. */ + if (!ble_log_task_registry_init()) { + goto exit; + } BLE_LOG_MEMSET(&internal_snapshot, 0, sizeof(internal_snapshot)); internal_snapshot.int_src_code = BLE_LOG_INT_SRC_SNAPSHOT; internal_snapshot.pool.trans_cnt = BLE_LOG_POOL_TRANS_CNT; @@ -729,6 +748,11 @@ void ble_log_lbm_begin_deinit(void) BLE_LOG_ATOMIC_STORE_SEQ_CST(lbm_inited, false); BLE_LOG_EXIT_CRITICAL(); + /* Close the task-registry gate with the LBM gate: its broadcast is + * system output, so only teardown stops it. The publish path never + * blocks, so this drain is immediate. */ + ble_log_task_registry_begin_deinit(); + /* Wake any blocked task writers and wait until BOTH the reference count * and the waiting-task count drain to zero. Blocked writers hold no * reference while parked, so waiting on ref_count alone could free the @@ -763,6 +787,7 @@ void ble_log_lbm_deinit(void) { ble_log_lbm_begin_deinit(); + ble_log_task_registry_deinit(); ble_log_prph_trans_deinit(&internal_trans); for (int id = 0; id < BLE_LOG_POOL_TRANS_CNT; id++) { ble_log_prph_trans_deinit(&(g_pool.trans[id])); 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 5c24513ccda..9d3d8ea452d 100644 --- a/components/bt/common/ble_log/src/ble_log_rt.c +++ b/components/bt/common/ble_log/src/ble_log_rt.c @@ -12,6 +12,7 @@ #include "ble_log.h" #include "ble_log_rt.h" #include "ble_log_lbm_v2.h" +#include "ble_log_task_registry.h" #include "ble_log_util.h" #include "esp_log.h" @@ -158,8 +159,12 @@ BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg) /* Unified periodic output: best-effort flush of partially-filled OPEN * transports ahead of the periodic snapshot, so parked frames do not - * wait for the next capacity seal. */ + * wait for the next capacity seal. The task-id binding broadcast + * rides the same window, ahead of the snapshot, on its own dedicated + * transport: a receiver that missed a binding converges on the next + * one, and the snapshot never waits behind it. */ ble_log_lbm_flush_open_trans(); + ble_log_task_bindings_publish(); (void)ble_log_internal_snapshot( BLE_LOG_SNAPSHOT_REASON_PERIODIC | diff --git a/components/bt/common/ble_log/src/ble_log_task_registry.c b/components/bt/common/ble_log/src/ble_log_task_registry.c new file mode 100644 index 00000000000..f9e8c92a82d --- /dev/null +++ b/components/bt/common/ble_log/src/ble_log_task_registry.c @@ -0,0 +1,272 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/* ------------------------------------ */ +/* BLE Log - Task-id Registry */ +/* */ +/* Owns the name-to-id registry, its */ +/* broadcast sequence and its dedicated */ +/* transport; a separate .c/.h pair */ +/* like the UART redirection writer. */ +/* ------------------------------------ */ + +/* INCLUDE */ +#include "ble_log_task_registry.h" +#include "ble_log_rt.h" + +#include "freertos/task.h" +#include "esp_timer.h" + +/* MACRO */ +/* Registry entries are word-compared on the record path. */ +#define BLE_LOG_TASK_NAME_WORDS (BLE_LOG_TASK_NAME_LEN / sizeof(uint32_t)) +/* ble_log_task_lookup() and ble_log_task_register() compare the four name + * words literally; a different name width must rework them. */ +_Static_assert(BLE_LOG_TASK_NAME_WORDS == 4, + "Unexpected BLE Log task name word count"); + +/* VARIABLE */ +/* Plain static variables (NOBITS .bss): the registry has no IRAM path, and zero + * page-image bytes beat DRAM_ATTR placement for a table this size. */ +BLE_LOG_STATIC uint32_t s_task_names[CONFIG_BLE_LOG_TASK_ID_MAX][BLE_LOG_TASK_NAME_WORDS]; +BLE_LOG_STATIC volatile uint8_t s_task_cnt; +BLE_LOG_STATIC ble_log_atomic_lock_t s_task_reg_lock; + +/* The binding broadcast keeps its own 24-bit frame sequence, separate + * from the snapshot sequence (see ble_log_lbm_v2.h): a gap counts a + * broadcast window skipped despite a non-empty registry, never a lost + * snapshot. ble_log_task_registry_init resets it. */ +BLE_LOG_STATIC uint32_t g_task_binding_sn; +#define BLE_LOG_GET_TASK_BINDING_SN() BLE_LOG_GET_FRAME_SN(g_task_binding_sn) + +/* Module lifetime gate, closed by begin_deinit (LBM teardown starts): + * publish is system output beyond the public producer gate, and only + * module teardown stops new broadcasts. The publish path never blocks, + * so the begin_deinit drain is immediate. */ +BLE_LOG_STATIC volatile uint32_t s_registry_ref_count = 0; +BLE_LOG_STATIC uint32_t s_registry_inited = 0; +/* The dedicated single-frame transport. It shares the INTERNAL owner + * kind: recycled by the peripheral tx-done straight back to FREE, with + * no pool bookkeeping. */ +BLE_LOG_STATIC ble_log_prph_trans_t *binding_trans; + +/* ------------------------------- */ +/* Registry Lookup/Insert */ +/* ------------------------------- */ +/* - Entries are append-only: an inserter (holding s_task_reg_lock) + * writes all name words first and publishes the entry by storing the + * new count with RELEASE; readers ACQUIRE-load the count and scan + * only the entries below it, so the read path is lock-free. + * - Names are matched by content, not by TCB pointer, so a recycled + * TCB cannot alias two different tasks onto one id. + * - Names longer than the storage are truncated; tasks sharing the + * truncated prefix share an id (identical names are indistinguishable + * in the decoded log anyway). + * - A full registry, or a contended registration attempt, degrades that + * record to the unknown id (BLE_LOG_TASK_ID_UNKNOWN) and still emits + * it; the task retries the registration with its next record. + * - Bindings are broadcast on every periodic snapshot window, so a + * receiver that joined late or lost a frame converges on the next + * window; broadcasts are idempotent on the wire and a lost one + * self-heals on the next window. A task that starts logging between + * windows emits records tagged with its id; the receiver binds the id + * at the next window. */ + +/* Normalizes a task name to NUL-padded words. Word-level compare + * replaces strcmp on the record path: the first word acts as the hash, + * a miss costs one load per entry, and there is no call overhead. Inline: + * every ENCODE record resolves its writer id, so this runs per record. */ +BLE_LOG_STATIC inline void ble_log_task_name_to_words( + const char *name, uint32_t w[BLE_LOG_TASK_NAME_WORDS]) +{ + BLE_LOG_MEMSET(w, 0, BLE_LOG_TASK_NAME_LEN); + BLE_LOG_MEMCPY(w, name, strnlen(name, BLE_LOG_TASK_NAME_LEN)); +} + +/* Per-record lookup: inline for the same reason as the normalizer above. */ +BLE_LOG_STATIC inline uint8_t ble_log_task_lookup( + const uint32_t w[BLE_LOG_TASK_NAME_WORDS]) +{ + uint8_t cnt = BLE_LOG_ATOMIC_LOAD_ACQUIRE(s_task_cnt); + for (uint8_t i = 0; i < cnt; i++) { + if (s_task_names[i][0] != w[0]) { + continue; + } + if (w[1] == s_task_names[i][1] && w[2] == s_task_names[i][2] && + w[3] == s_task_names[i][3]) { + return i; + } + } + return BLE_LOG_TASK_ID_UNKNOWN; +} + +/* Cold path, once per task lifetime. A single CAS attempt serializes + * inserters: on contention this record degrades to the unknown id + * instead of blocking, and the next record of the task retries. */ +BLE_LOG_STATIC uint8_t ble_log_task_register(const uint32_t w[BLE_LOG_TASK_NAME_WORDS]) +{ + uint8_t id = BLE_LOG_TASK_ID_UNKNOWN; + + if (!BLE_LOG_CAS_ACQUIRE(&s_task_reg_lock)) { + return BLE_LOG_TASK_ID_UNKNOWN; + } + uint8_t cnt = s_task_cnt; + for (uint8_t i = 0; i < cnt; i++) { + if (w[0] == s_task_names[i][0] && w[1] == s_task_names[i][1] && + w[2] == s_task_names[i][2] && w[3] == s_task_names[i][3]) { + BLE_LOG_CAS_RELEASE(&s_task_reg_lock); + return i; /* raced with another first lookup */ + } + } + if (cnt < CONFIG_BLE_LOG_TASK_ID_MAX) { + BLE_LOG_MEMCPY(s_task_names[cnt], w, BLE_LOG_TASK_NAME_LEN); + id = cnt; + BLE_LOG_ATOMIC_STORE_RELEASE(s_task_cnt, cnt + 1); + } + BLE_LOG_CAS_RELEASE(&s_task_reg_lock); + return id; +} + +uint8_t ble_log_task_id_current(void) +{ + const char *cur_name = pcTaskGetName(NULL); + if (!cur_name) { + return BLE_LOG_TASK_ID_UNKNOWN; + } + uint32_t w[BLE_LOG_TASK_NAME_WORDS]; + ble_log_task_name_to_words(cur_name, w); + uint8_t id = ble_log_task_lookup(w); + /* Registration mutates shared state; ISR callers stop at the + * lookup-hit path and read only. */ + if (id == BLE_LOG_TASK_ID_UNKNOWN && !BLE_LOG_IN_ISR()) { + id = ble_log_task_register(w); + } + return id; +} + +/* ----------------------------------- */ +/* Periodic Binding Broadcast */ +/* ----------------------------------- */ +/* One binding frame on the dedicated registry transport, packing every + * registered entry in id order. Best effort, single CAS attempt: a busy + * transport (the previous broadcast still in DMA) skips this window and + * the next one rebroadcasts. The registry is only read here (ACQUIRE + * count, append-only entries), so this races no inserter. */ +BLE_LOG_STATIC bool ble_log_task_binding_send(uint8_t cnt, uint32_t timestamp) +{ + /* Snapshot-sequence semantics: the window SN is consumed before + * contending for the transport, so a skipped window burns it and + * the gap in the binding sequence counts skipped windows. */ + uint32_t frame_sn = BLE_LOG_GET_TASK_BINDING_SN(); + if (!BLE_LOG_CAS_ACQUIRE(&binding_trans->atomic_lock)) { + return false; + } + if (BLE_LOG_ATOMIC_LOAD_RELAXED(binding_trans->state) != + BLE_LOG_TRANS_STATE_FREE) { + BLE_LOG_CAS_RELEASE(&binding_trans->atomic_lock); + return false; + } + + ble_log_frame_head_t frame_head = { + .length = (uint16_t)(sizeof(uint32_t) + + cnt * sizeof(ble_log_task_binding_t)), + .frame_meta = BLE_LOG_MAKE_FRAME_META(BLE_LOG_SRC_INTERNAL, frame_sn), + }; + uint8_t *buf = binding_trans->buf; + BLE_LOG_MEMCPY(buf, &frame_head, sizeof(frame_head)); + size_t pos = BLE_LOG_FRAME_HEAD_LEN; + BLE_LOG_MEMCPY(buf + pos, ×tamp, sizeof(timestamp)); + pos += sizeof(timestamp); + for (uint8_t i = 0; i < cnt; i++) { + ble_log_task_binding_t binding = { + .int_src_code = BLE_LOG_INT_SRC_TASK_BINDING, + .task_id = i, + }; + BLE_LOG_MEMCPY(binding.task_name, s_task_names[i], + BLE_LOG_TASK_NAME_LEN); + BLE_LOG_MEMCPY(buf + pos, &binding, sizeof(binding)); + pos += sizeof(binding); + } + uint32_t checksum = ble_log_fast_checksum( + buf, BLE_LOG_FRAME_HEAD_LEN + frame_head.length); + BLE_LOG_MEMCPY(buf + BLE_LOG_FRAME_HEAD_LEN + frame_head.length, + &checksum, sizeof(checksum)); + + binding_trans->pos = (uint16_t)(pos + BLE_LOG_FRAME_TAIL_LEN); + BLE_LOG_ATOMIC_STORE_RELAXED(binding_trans->state, + BLE_LOG_TRANS_STATE_SENDING); + BLE_LOG_CAS_RELEASE(&binding_trans->atomic_lock); + ble_log_rt_submit_trans(binding_trans); + return true; +} + +void ble_log_task_bindings_publish(void) +{ + if (!ble_log_ref_count_try_acquire(&s_registry_ref_count, &s_registry_inited)) { + return; + } + /* Empty registry: nothing to broadcast; no window attempt, no SN. */ + uint8_t cnt = BLE_LOG_ATOMIC_LOAD_ACQUIRE(s_task_cnt); + if (cnt != 0) { + uint32_t timestamp = (uint32_t)esp_timer_get_time(); + (void)ble_log_task_binding_send(cnt, timestamp); + } + BLE_LOG_REF_COUNT_RELEASE(&s_registry_ref_count); +} + +/* --------------------------- */ +/* Module Lifetime */ +/* --------------------------- */ +bool ble_log_task_registry_init(void) +{ + if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(s_registry_inited)) { + return true; + } + + /* Fresh epoch: empty registry, no broadcast sequence. init runs + * single-threaded (from ble_log_lbm_init), so the registry state and + * its lock are cleared by value. */ + BLE_LOG_MEMSET(s_task_names, 0, sizeof(s_task_names)); + BLE_LOG_ATOMIC_STORE_RELEASE(s_task_cnt, 0); + s_task_reg_lock = 0; + g_task_binding_sn = 0; + + if (!ble_log_prph_trans_init(&binding_trans, BLE_LOG_TASK_BINDING_TRANS_SIZE)) { + return false; + } + binding_trans->id = BLE_LOG_TRANS_ID_NONE; + binding_trans->owner_kind = BLE_LOG_TRANS_OWNER_INTERNAL; + + BLE_LOG_ATOMIC_STORE_RELEASE(s_registry_inited, true); + return true; +} + +void ble_log_task_registry_begin_deinit(void) +{ + /* Closing gate: pairs with the seq_cst acquire in publish. */ + BLE_LOG_ATOMIC_STORE_SEQ_CST(s_registry_inited, false); + while (!ble_log_ref_count_wait(&s_registry_ref_count, 0)) { + BLE_LOG_ASSERT(false); + } +} + +void ble_log_task_registry_deinit(void) +{ + ble_log_task_registry_begin_deinit(); + ble_log_prph_trans_deinit(&binding_trans); +} + +#if CONFIG_BLE_LOG_PRPH_TEST +/* Test-only: wipes the task registry so test cases stay order-independent. + * Call between cases, with no writers in flight. */ +void ble_log_test_task_registry_reset(void) +{ + if (BLE_LOG_CAS_ACQUIRE(&s_task_reg_lock)) { + BLE_LOG_ATOMIC_STORE_RELEASE(s_task_cnt, 0); + BLE_LOG_CAS_RELEASE(&s_task_reg_lock); + } +} +#endif diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_lbm_v2.h b/components/bt/common/ble_log/src/internal_include/ble_log_lbm_v2.h index a61f337e566..0a057a0b93e 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_lbm_v2.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_lbm_v2.h @@ -7,7 +7,7 @@ #define __BLE_LOG_LBM_V2_H__ /* -------------------------------------------------- */ -/* BLE Log - Unified Transport Pool (v7) */ +/* BLE Log - Unified Transport Pool (v8) */ /* -------------------------------------------------- */ /* Replaces the legacy multi-LBM design (ble_log_lbm.h) with one shared * transport pool. Written as a new module so the legacy implementation @@ -44,6 +44,8 @@ typedef struct { #define BLE_LOG_TRANS_SIZE BLE_LOG_POOL_TRANS_SIZE #define BLE_LOG_MAX_PAYLOAD_LEN (BLE_LOG_POOL_TRANS_SIZE - BLE_LOG_FRAME_OVERHEAD) #define BLE_LOG_TRANS_INTERNAL_CNT (1) +/* Dedicated transport of the task-id registry binding broadcast. */ +#define BLE_LOG_TRANS_TASK_BINDING_CNT (1) #if BLE_LOG_UART_REDIR_ENABLED #define BLE_LOG_TRANS_REDIR_CNT BLE_LOG_TRANS_BUF_CNT @@ -52,10 +54,11 @@ typedef struct { #endif #define BLE_LOG_TRANS_TOTAL_CNT \ - (BLE_LOG_POOL_TRANS_CNT + BLE_LOG_TRANS_INTERNAL_CNT + BLE_LOG_TRANS_REDIR_CNT) + (BLE_LOG_POOL_TRANS_CNT + BLE_LOG_TRANS_INTERNAL_CNT + \ + BLE_LOG_TRANS_TASK_BINDING_CNT + BLE_LOG_TRANS_REDIR_CNT) /* --------------------------------------- */ -/* Protocol v7 Source ID Space */ +/* Protocol v8 Source ID Space */ /* --------------------------------------- */ /* The frozen public ble_log_src_t values are the on-wire and statistic * source IDs: the frame source byte carries the bare enum value. */ @@ -105,9 +108,10 @@ typedef struct { * REDIR: consumed at API entry (before pool contention), it orders all * log attempts — including equal-timestamp records from different * sources — and every lost or rejected attempt leaves a gap. INTERNAL - * snapshot frames and the REDIR console stream keep their own separate - * sequences (a gap counts a skipped snapshot or a dropped console batch). - * ble_log_init() resets all three sequences; its required INIT snapshot + * snapshot frames, the periodic task-binding broadcast, and the REDIR + * console stream keep their own separate sequences (a gap counts a + * skipped snapshot, a skipped broadcast window, or a dropped console + * batch). ble_log_init() resets all of them; its required INIT snapshot * starts a new receiver epoch. They stay continuous through FLUSH within * that epoch. The per-counter macros live next to their counters in the * owning translation units; the 24-bit wire field is enforced where the @@ -235,10 +239,18 @@ bool ble_log_internal_snapshot(uint16_t reason_flags, const ble_log_ts_info_t *ts_info, bool wait_for_transport); +/* The task-id registry (protocol v8 attribution) lives in its own module: + * ble_log_task_registry.c/h, like the UART redirection writer. */ + /* Claim/commit: the public ble_log_src_t is accepted for API stability, but * only BLE_LOG_SRC_ENCODE is supported; its frames are stamped with the - * ENCODE source ID on the wire. */ -uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, uint32_t *handle); + * ENCODE source ID on the wire. wait_for_transport=false turns a busy pool + * into a lossy fast path (NULL, as in a non-yieldable context) instead of + * waiting, for output that must not block its caller (e.g. the shared ESP + * timer task); true waits in yieldable contexts, never in non-yieldable + * ones. */ +uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, + uint32_t *handle, bool wait_for_transport); void ble_log_commit(uint32_t handle, size_t actual_len); #if BLE_LOG_UART_REDIR_ENABLED diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_task_registry.h b/components/bt/common/ble_log/src/internal_include/ble_log_task_registry.h new file mode 100644 index 00000000000..8c08f1612bd --- /dev/null +++ b/components/bt/common/ble_log/src/internal_include/ble_log_task_registry.h @@ -0,0 +1,87 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef __BLE_LOG_TASK_REGISTRY_H__ +#define __BLE_LOG_TASK_REGISTRY_H__ + +/* ------------------------------------ */ +/* BLE Log - Task-id Registry */ +/* ------------------------------------ */ +/* Self-contained module (one .c/.h pair, like the UART redirection + * writer): owns the name-to-id registry, its broadcast sequence and its + * dedicated transport, so it never contends with the internal snapshot + * transport or the pool. */ + +/* INCLUDE */ +#include "ble_log_lbm_v2.h" + +/* ------------------------- */ +/* Wire Format (v8) */ +/* ------------------------- */ +/* Writer attribution: every ENCODE record names the task that formatted + * it (one byte after the record source); the registry maps task names to + * stable ids. The name width is a wire property of the binding record + * below. */ +#define BLE_LOG_TASK_ID_UNKNOWN UINT8_C(0xff) +#define BLE_LOG_TASK_NAME_LEN (16U) + +/* The binding record inside an INTERNAL frame: every periodic window + * broadcasts one frame that packs one record per registered entry, in id + * order. The name is NUL-padded to the registry width plus one byte, so + * a decoder can bind the id in place even when the task name fills the + * whole field. */ +typedef struct { + uint8_t int_src_code; + uint8_t task_id; + uint8_t task_name[BLE_LOG_TASK_NAME_LEN + 1]; +} __attribute__((packed)) ble_log_task_binding_t; + +/* One binding frame must fit the dedicated transport in a single frame: + * one submit per window, and the transport is recycled only when the + * peripheral has read it. */ +#define BLE_LOG_TASK_BINDING_FRAME_LEN \ + (BLE_LOG_FRAME_OVERHEAD + sizeof(uint32_t) + \ + CONFIG_BLE_LOG_TASK_ID_MAX * sizeof(ble_log_task_binding_t)) +/* Word-aligned by construction (SPI builds require aligned transfers). */ +#define BLE_LOG_TASK_BINDING_TRANS_SIZE \ + ((BLE_LOG_TASK_BINDING_FRAME_LEN + 3U) & ~3U) + +_Static_assert(sizeof(ble_log_task_binding_t) == 19, + "Unexpected task-binding record layout"); + +/* --------------------------- */ +/* Internal Interfaces */ +/* --------------------------- */ +/* Module lifetime, driven by the LBM layer (ble_log_lbm_init/deinit): + * init allocates the dedicated transport and wipes the registry and its + * sequence for a fresh epoch; begin_deinit closes the gate and waits for + * in-flight publishes; deinit frees the transport. */ +bool ble_log_task_registry_init(void); +void ble_log_task_registry_begin_deinit(void); +void ble_log_task_registry_deinit(void); + +/* Resolves the calling task's name to its stable registry id, registering + * the name on a miss. ISR-safe: an ISR caller reads only (a miss returns + * the unknown id). Every ENCODE record must resolve before its claim so + * the registry already holds the id the record carries. */ +uint8_t ble_log_task_id_current(void); + +/* Periodic window output: broadcasts one INTERNAL frame packing one + * fixed-layout binding record per registered entry, in id order, on the + * dedicated registry transport. Runs on the shared ESP timer task and + * must never block: a busy transport (previous broadcast still in DMA) + * skips this window and the next one rebroadcasts. Best-effort control + * traffic, never counted in the per-source written/lost stats, and + * carried on its own sequence (see ble_log_task_registry.c) so a skipped + * window cannot look like a lost snapshot. */ +void ble_log_task_bindings_publish(void); + +#if CONFIG_BLE_LOG_PRPH_TEST +/* Test-only: wipes the task registry so test cases stay order-independent. + * Call between cases, with no writers in flight. */ +void ble_log_test_task_registry_reset(void); +#endif + +#endif /* __BLE_LOG_TASK_REGISTRY_H__ */ diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_util.h b/components/bt/common/ble_log/src/internal_include/ble_log_util.h index bc631d48a8a..5e9b2eeca67 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_util.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_util.h @@ -85,7 +85,7 @@ extern void esp_panic_handler_feed_wdts(void); #define BLE_LOG_CAS_RELEASE(cas_lock) \ __atomic_store_n((cas_lock), 0, __ATOMIC_RELEASE) -#define BLE_LOG_VERSION (7) +#define BLE_LOG_VERSION (8) #define BLE_LOG_IDF_COMMIT_LEN (12) /* Lib commit hashes are at most 10 hex chars; zero-padded when shorter */ #define BLE_LOG_LIB_COMMIT_LEN (10) @@ -101,6 +101,9 @@ typedef enum { BLE_LOG_INT_SRC_FINAL_STAT, BLE_LOG_INT_SRC_VERSION_INFO, BLE_LOG_INT_SRC_SNAPSHOT, + /* protocol v8: periodic task-id binding broadcast; its frames carry a + * sequence of their own (a gap counts a skipped broadcast window). */ + BLE_LOG_INT_SRC_TASK_BINDING, BLE_LOG_INT_SRC_MAX, } ble_log_int_src_t; 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 fdf0ee0180e..95d02496988 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 @@ -1031,6 +1031,88 @@ TEST_CASE("BLE Log write_hex_ll append cycles (32+32B)", "[ble_log][perf][cycle] #endif #if CONFIG_BLE_COMPRESSED_LOG_ENABLE +/* ---------------------- */ +/* Attribution cycles */ +/* ---------------------- */ + +/* Compressed records attribute every record to their writer task by + * normalizing the FreeRTOS task name to NUL-padded words and scanning + * the registry. A hand-rolled copy (no libc calls) was measured on + * ESP32-H2 at -Og against this libc version: the two trade places + * across name lengths (inline wins ~31 cycles on 3-char names, loses + * ~31 on full 16-char names, ties in between) against ~1.6k cycles per + * compressed record - no variant is meaningfully faster. The module + * keeps the libc version because it is three lines; this case records + * the numbers so the decision does not get re-litigated blind. */ +#define NORM_WORDS 4 /* BLE_CP_TASK_NAME_WORDS, private to the module */ +#define NORM_LEN (NORM_WORDS * sizeof(uint32_t)) +#define NORM_ROUNDS 5 +#define NORM_ITERS 20000 + +typedef void (*norm_fn_t)(const char *name, uint32_t w[NORM_WORDS]); + +static void norm_libc(const char *name, uint32_t w[NORM_WORDS]) +{ + memset(w, 0, NORM_LEN); + memcpy(w, name, strnlen(name, NORM_LEN)); +} + +static void norm_inline(const char *name, uint32_t w[NORM_WORDS]) +{ + for (unsigned i = 0; i < NORM_WORDS; i++) { + uint32_t v = 0; + for (unsigned b = 0; b < sizeof(uint32_t); b++) { + uint8_t c = (uint8_t)*name; + if (c == '\0') { + break; + } + v |= (uint32_t)c << (8 * b); + name++; + } + w[i] = v; + } +} + +static volatile uint32_t s_norm_sink; + +static uint32_t norm_bench_once(norm_fn_t fn, const char *name) +{ + uint32_t sink = 0; + uint32_t start = esp_cpu_get_cycle_count(); + for (uint32_t i = 0; i < NORM_ITERS; i++) { + uint32_t w[NORM_WORDS]; + fn(name, w); + sink ^= w[0] ^ w[1] ^ w[2] ^ w[3]; + } + s_norm_sink = sink; /* the copies must stay live */ + return (esp_cpu_get_cycle_count() - start) / NORM_ITERS; +} + +TEST_CASE("BLE Log task-name normalization cycles", "[ble_log][perf][cycle][ignore]") +{ + static const char *const names[] = {"BTU", "NIMBLE_HOST", "0123456789ABCDEF"}; + for (size_t i = 0; i < sizeof(names) / sizeof(names[0]); i++) { + /* both variants must agree on every shape before timing them */ + uint32_t wa[NORM_WORDS], wb[NORM_WORDS]; + norm_libc(names[i], wa); + norm_inline(names[i], wb); + TEST_ASSERT_EQUAL_UINT32_ARRAY(wa, wb, NORM_WORDS); + + uint32_t best_libc = UINT32_MAX; + uint32_t best_inline = UINT32_MAX; + for (int r = 0; r < NORM_ROUNDS; r++) { /* interleaved rounds */ + uint32_t a = norm_bench_once(norm_libc, names[i]); + uint32_t b = norm_bench_once(norm_inline, names[i]); + best_libc = a < best_libc ? a : best_libc; + best_inline = b < best_inline ? b : best_inline; + } + printf("BLE_LOG_PERF norm name=%-16s libc=%4" PRIu32 " inline=%4" PRIu32 + " delta=%+" PRId32 " cycles/call\n", + names[i], best_libc, best_inline, + (int32_t)best_libc - (int32_t)best_inline); + } +} + /* Compressed records are log_index + 0..2 U32 args, not a raw payload * length. One case per arg count splits encode vs downstream write_hex * cost for each workload shape. */ 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 6649298b486..13923c713d7 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 @@ -12,7 +12,7 @@ validate the BLE Log transport on target. It covers: -- literal protocol-v7 framing and fixed Internal Snapshot ABI; +- literal protocol-v8 framing and fixed Internal Snapshot ABI; - build, library, chip, and protocol versions inside the snapshot; - task and critical-section writes plus HCI direction encoding; - direct compression claim/commit, stale handles, and per-source serialization; 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 dc6cc952e39..3ca6ae4ecd5 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 @@ -7,6 +7,7 @@ #include #include #include +#include #include #include "esp_chip_info.h" @@ -19,6 +20,7 @@ #include "ble_log_lbm_v2.h" #include "ble_log_prph_test.h" #include "ble_log_rt.h" +#include "ble_log_task_registry.h" #include "test_ble_log_main.h" #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE #include "log_compression/utils.h" @@ -64,11 +66,6 @@ static SemaphoreHandle_t s_enable_hook_continue; static volatile bool s_disable_hook_armed; static SemaphoreHandle_t s_disable_hook_entered; static SemaphoreHandle_t s_disable_hook_continue; -#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE -static volatile bool s_compression_hook_armed; -static SemaphoreHandle_t s_compression_hook_entered; -static SemaphoreHandle_t s_compression_hook_continue; -#endif void ble_log_test_claim_pre_publish_hook(void); void ble_log_test_claim_locked_hook(void); @@ -76,7 +73,6 @@ void ble_log_test_init_snapshot_before_acquire_hook(void); void ble_log_test_enable_before_lifecycle_lock_hook(void); void ble_log_test_disable_before_wake_hook(void); #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE -void ble_log_test_compression_after_lock_hook(uint8_t source); extern int ble_log_compressed_hex_print(uint8_t source, uint32_t log_index, size_t args_cnt, ...); #endif @@ -125,17 +121,6 @@ void ble_log_test_disable_before_wake_hook(void) } } -#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE -void ble_log_test_compression_after_lock_hook(uint8_t source) -{ - if (s_compression_hook_armed && - source == BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) { - xSemaphoreGive(s_compression_hook_entered); - xSemaphoreTake(s_compression_hook_continue, portMAX_DELAY); - } -} -#endif - /* A commit field is hex characters, zero-padded after a shorter value; * anything else (garbage, non-hex, zeros after data) is invalid. */ static bool commit_is_valid(const uint8_t *commit, size_t len) @@ -239,7 +224,7 @@ static void capture_golden_frame(const test_ble_log_frame_t *frame, void *ctx) capture->count++; } -TEST_CASE("BLE Log v7 framing matches golden bytes", "[ble_log][wire]") +TEST_CASE("BLE Log v8 framing matches golden bytes", "[ble_log][wire]") { static const uint8_t golden_frame[] = { 0x05, 0x00, 0x07, 0xde, 0xc0, 0x00, @@ -250,7 +235,7 @@ TEST_CASE("BLE Log v7 framing matches golden bytes", "[ble_log][wire]") 0x78, 0x56, 0x34, 0x12, 0xab, }; - TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_VERSION); + TEST_ASSERT_EQUAL_UINT8(8, BLE_LOG_VERSION); TEST_ASSERT_EQUAL_UINT8(1, BLE_LOG_SRC_CORE_FIRST); TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_CORE_COUNT); TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_ENCODE); @@ -495,7 +480,7 @@ TEST_CASE("BLE Log writes from critical sections and commits claimed payload", #endif uint32_t handle; - uint8_t *claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &handle); + uint8_t *claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &handle, true); TEST_ASSERT_NOT_NULL(claimed); claimed[0] = 0x33; ble_log_commit(handle, 1); @@ -506,7 +491,7 @@ TEST_CASE("BLE Log writes from critical sections and commits claimed payload", s_stale_claim_handle = handle; s_claim_hook_armed = true; uint32_t fresh_handle; - claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &fresh_handle); + claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &fresh_handle, true); s_claim_hook_armed = false; TEST_ASSERT_NOT_NULL(claimed); TEST_ASSERT_NOT_EQUAL(handle, fresh_handle); @@ -554,135 +539,184 @@ TEST_CASE("BLE Log writes from critical sections and commits claimed payload", } #if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE -#define TEST_CP_INDEX_FIRST UINT16_C(0x601) -#define TEST_CP_INDEX_DROPPED UINT16_C(0x602) -#define TEST_CP_INDEX_SECOND UINT16_C(0x603) -#define TEST_CP_TASK_SWITCH UINT8_C(0xc2) -#define TEST_CP_ZERO_ARGS UINT8_C(0x40) +#define TEST_CP_TASK_UNKNOWN UINT8_C(0xff) +#define TEST_CP_ZERO_ARGS UINT8_C(0x40) +#define TEST_CP_WRITER_RECORDS 8 +#define TEST_CP_INDEX_MAIN_A UINT16_C(0x600) +#define TEST_CP_INDEX_MAIN_B UINT16_C(0x601) +#define TEST_CP_INDEX_BASE_A UINT16_C(0x700) +#define TEST_CP_INDEX_BASE_B UINT16_C(0x710) +#define TEST_CP_INDEX_FILL_A UINT16_C(0x720) +#define TEST_CP_INDEX_FILL_B UINT16_C(0x721) +#define TEST_CP_INDEX_FILLER UINT16_C(0x722) +#define TEST_CP_NAME_MAX 17 typedef struct { - bool first_found; - uint32_t first_sn; - bool dropped_found; - bool second_found; - bool second_switched; - uint32_t second_sn; - bool third_found; - bool third_switched; - uint32_t third_sn; + /* id-to-name bindings learned from INTERNAL task-binding records */ + char names[CONFIG_BLE_LOG_TASK_ID_MAX][TEST_CP_NAME_MAX]; + uint8_t announce_cnt[CONFIG_BLE_LOG_TASK_ID_MAX]; + /* per-writer record accounting */ + uint8_t main_records; + uint8_t a_records; + uint8_t b_records; + uint8_t filler_records; + uint8_t fill_a_records; + uint8_t fill_b_records; + bool a_id_set; + bool a_id_mismatch; + uint8_t a_id; + bool b_id_set; + bool b_id_mismatch; + uint8_t b_id; + bool main_id_set; + bool main_id_mismatch; + uint8_t main_id; + bool filler_unknown; + bool fill_a_id_set; + uint8_t fill_a_id; + bool fill_b_unknown; } compression_capture_t; typedef struct { - SemaphoreHandle_t committed; - SemaphoreHandle_t exit; - SemaphoreHandle_t exited; + SemaphoreHandle_t token; + SemaphoreHandle_t peer_token; + SemaphoreHandle_t done; + uint16_t index_base; } compression_writer_ctx_t; -static void capture_compressed_frame(const test_ble_log_frame_t *frame, - void *ctx) -{ - compression_capture_t *capture = ctx; - if (frame->src != BLE_LOG_SRC_ENCODE || - frame->payload_len < sizeof(uint32_t) + 4) { - return; - } - - const uint8_t *record = frame->payload + sizeof(uint32_t); - size_t offset = 0; - if (record[offset++] != BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) { - return; - } - size_t record_len = frame->payload_len - sizeof(uint32_t); - bool switched = record[offset] == TEST_CP_TASK_SWITCH; - offset += switched; - if (record_len - offset < 3 || record[offset++] != TEST_CP_ZERO_ARGS) { - return; - } +typedef struct { + SemaphoreHandle_t done; uint16_t log_index; - memcpy(&log_index, record + offset, sizeof(log_index)); - - if (log_index == TEST_CP_INDEX_FIRST) { - capture->first_found = true; - capture->first_sn = frame->sn; - } else if (log_index == TEST_CP_INDEX_DROPPED) { - capture->dropped_found = true; - } else if (log_index == TEST_CP_INDEX_SECOND) { - capture->second_found = true; - capture->second_switched = switched; - capture->second_sn = frame->sn; - } else if (log_index == TEST_CP_INDEX_SECOND + 1) { - capture->third_found = true; - capture->third_switched = switched; - capture->third_sn = frame->sn; - } -} +} compression_once_ctx_t; static void compression_writer_task(void *arg) { compression_writer_ctx_t *ctx = arg; - ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, - TEST_CP_INDEX_SECOND, 0); - xSemaphoreGive(ctx->committed); - xSemaphoreTake(ctx->exit, portMAX_DELAY); - xSemaphoreGive(ctx->exited); + for (int i = 0; i < TEST_CP_WRITER_RECORDS; i++) { + xSemaphoreTake(ctx->token, portMAX_DELAY); + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + ctx->index_base + i, 0); + xSemaphoreGive(ctx->peer_token); + } + xSemaphoreGive(ctx->done); vTaskDelete(NULL); } -TEST_CASE("BLE Log serializes task context per compression source", - "[ble_log][compression]") +static void compression_once_task(void *arg) { - TEST_ASSERT_TRUE(ble_log_enable(true)); - ble_log_lbm_flush_open_trans(); - for (int round = 0; round < 2; round++) { - TEST_ASSERT_TRUE(ble_log_rt_drain()); - while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), - 0, 0, NULL) > 0) { + compression_once_ctx_t *ctx = arg; + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + ctx->log_index, 0); + xSemaphoreGive(ctx->done); + vTaskDelete(NULL); +} + +/* Walks one ENCODE frame: [ts 4B][source 1B][task_id 1B][header 1B]... + * and one INTERNAL task-binding frame: [ts 4B][int_src 1B][task_id 1B] + * [name 17B] (the periodic registry broadcast). */ +static void capture_compressed_frame(const test_ble_log_frame_t *frame, + void *ctx) +{ + compression_capture_t *capture = ctx; + /* Bindings ride the INTERNAL stream: one frame per periodic window, + * packing one fixed-layout record per registered entry. */ + if (frame->src == BLE_LOG_SRC_INTERNAL && + frame->payload_len >= sizeof(uint32_t) + + sizeof(ble_log_task_binding_t) && + (frame->payload_len - sizeof(uint32_t)) % + sizeof(ble_log_task_binding_t) == 0) { + const uint8_t *record = frame->payload + sizeof(uint32_t); + size_t records = (frame->payload_len - sizeof(uint32_t)) / + sizeof(ble_log_task_binding_t); + for (size_t r = 0; r < records; r++, record += sizeof(ble_log_task_binding_t)) { + if (record[0] != BLE_LOG_INT_SRC_TASK_BINDING) { + continue; + } + uint8_t task_id = record[1]; + const uint8_t *name = record + 2; + if (task_id < CONFIG_BLE_LOG_TASK_ID_MAX) { + capture->announce_cnt[task_id]++; + if (capture->announce_cnt[task_id] == 1) { + memcpy(capture->names[task_id], name, + sizeof(capture->names[task_id])); + } else if (strcmp(capture->names[task_id], + (const char *)name) != 0) { + /* same id re-announced with a different name */ + capture->names[task_id][0] = '\0'; + } + } + } + return; + } + if (frame->src != BLE_LOG_SRC_ENCODE) { + return; + } + const uint8_t *record = frame->payload + sizeof(uint32_t); + size_t record_len = frame->payload_len - sizeof(uint32_t); + if (record_len < 3 || + record[0] != BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) { + return; + } + uint8_t task_id = record[1]; + uint8_t header = record[2]; + + if (header != TEST_CP_ZERO_ARGS || record_len < 5) { + return; + } + uint16_t log_index; + memcpy(&log_index, record + 3, sizeof(log_index)); + + if (log_index == TEST_CP_INDEX_MAIN_A || log_index == TEST_CP_INDEX_MAIN_B) { + capture->main_records++; + if (!capture->main_id_set) { + capture->main_id_set = true; + capture->main_id = task_id; + } else if (capture->main_id != task_id) { + capture->main_id_mismatch = true; + } + } else if (log_index >= TEST_CP_INDEX_BASE_A && + log_index < TEST_CP_INDEX_BASE_A + TEST_CP_WRITER_RECORDS) { + capture->a_records++; + if (!capture->a_id_set) { + capture->a_id_set = true; + capture->a_id = task_id; + } else if (capture->a_id != task_id) { + capture->a_id_mismatch = true; + } + } else if (log_index >= TEST_CP_INDEX_BASE_B && + log_index < TEST_CP_INDEX_BASE_B + TEST_CP_WRITER_RECORDS) { + capture->b_records++; + if (!capture->b_id_set) { + capture->b_id_set = true; + capture->b_id = task_id; + } else if (capture->b_id != task_id) { + capture->b_id_mismatch = true; + } + } else if (log_index >= TEST_CP_INDEX_FILLER && + log_index < TEST_CP_INDEX_FILLER + CONFIG_BLE_LOG_TASK_ID_MAX - 1) { + capture->filler_records++; + if (task_id == TEST_CP_TASK_UNKNOWN) { + capture->filler_unknown = true; + } + } else if (log_index == TEST_CP_INDEX_FILL_A) { + capture->fill_a_records++; + if (task_id != TEST_CP_TASK_UNKNOWN) { + capture->fill_a_id_set = true; + capture->fill_a_id = task_id; + } + } else if (log_index == TEST_CP_INDEX_FILL_B) { + capture->fill_b_records++; + if (task_id == TEST_CP_TASK_UNKNOWN) { + capture->fill_b_unknown = true; } } +} - ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, - TEST_CP_INDEX_FIRST, 0); - - s_compression_hook_entered = xSemaphoreCreateBinary(); - s_compression_hook_continue = xSemaphoreCreateBinary(); - compression_writer_ctx_t writer = { - .committed = xSemaphoreCreateBinary(), - .exit = xSemaphoreCreateBinary(), - .exited = xSemaphoreCreateBinary(), - }; - TEST_ASSERT_NOT_NULL(s_compression_hook_entered); - TEST_ASSERT_NOT_NULL(s_compression_hook_continue); - TEST_ASSERT_NOT_NULL(writer.committed); - TEST_ASSERT_NOT_NULL(writer.exit); - TEST_ASSERT_NOT_NULL(writer.exited); - - s_compression_hook_armed = true; - TEST_ASSERT_EQUAL( - pdTRUE, - xTaskCreate(compression_writer_task, "ble_log_cp", - TEST_LIFECYCLE_STACK_SIZE, &writer, - TEST_LIFECYCLE_PRIO, NULL)); - TEST_ASSERT_TRUE(xSemaphoreTake(s_compression_hook_entered, - pdMS_TO_TICKS(1000))); - - /* This call claims pool space but fails the per-source trylock. It must - * cancel immediately, count one lost ENCODE SN, and leave task state to - * the lock owner. */ - ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, - TEST_CP_INDEX_DROPPED, 0); - xSemaphoreGive(s_compression_hook_continue); - TEST_ASSERT_TRUE(xSemaphoreTake(writer.committed, - pdMS_TO_TICKS(1000))); - s_compression_hook_armed = false; - - ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, - TEST_CP_INDEX_SECOND + 1, 0); - xSemaphoreGive(writer.exit); - TEST_ASSERT_TRUE(xSemaphoreTake(writer.exited, pdMS_TO_TICKS(1000))); - +static void compression_drain_and_capture(compression_capture_t *capture) +{ ble_log_lbm_flush_open_trans(); TEST_ASSERT_TRUE(ble_log_rt_drain()); - compression_capture_t capture = {0}; + memset(capture, 0, sizeof(*capture)); for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) { size_t len = ble_log_prph_test_read( s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), @@ -691,29 +725,267 @@ TEST_CASE("BLE Log serializes task context per compression source", break; } TEST_ASSERT_TRUE(test_ble_log_walk_frames( - s_read_buf, len, capture_compressed_frame, &capture)); + s_read_buf, len, capture_compressed_frame, capture)); + } +} + +static void compression_reset_streams(void) +{ + /* Wipe the task-id registry so neither compression case depends on the + * other's registrations or on test-case order. */ + ble_log_test_task_registry_reset(); + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_trans(); + for (int round = 0; round < 2; round++) { + TEST_ASSERT_TRUE(ble_log_rt_drain()); + while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + 0, 0, NULL) > 0) { + } + } +} + +static uint8_t compression_announced_id(const compression_capture_t *capture, + const char *name) +{ + for (int i = 0; i < CONFIG_BLE_LOG_TASK_ID_MAX; i++) { + if (capture->announce_cnt[i] > 0 && + strcmp(capture->names[i], name) == 0) { + return (uint8_t)i; + } + } + return TEST_CP_TASK_UNKNOWN; +} + +/* Protocol v8: task attribution is a property of the record. Two writers + * interleave records on one compression source; every record carries its + * writer's id and no record is dropped for contention (there is no source + * lock to contend). Bindings are broadcast on the periodic window only + * (the LBM task-binding publish), so it is driven once before the capture + * below. */ +TEST_CASE("BLE Log attributes compressed records to their writer task", + "[ble_log][compression]") +{ + compression_reset_streams(); + + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_MAIN_A, 0); + + compression_writer_ctx_t writer_a = { + .token = xSemaphoreCreateBinary(), + .peer_token = NULL, + .done = xSemaphoreCreateBinary(), + .index_base = TEST_CP_INDEX_BASE_A, + }; + compression_writer_ctx_t writer_b = { + .token = xSemaphoreCreateBinary(), + .peer_token = NULL, + .done = xSemaphoreCreateBinary(), + .index_base = TEST_CP_INDEX_BASE_B, + }; + writer_a.peer_token = writer_b.token; + writer_b.peer_token = writer_a.token; + TEST_ASSERT_NOT_NULL(writer_a.token); + TEST_ASSERT_NOT_NULL(writer_b.token); + TEST_ASSERT_NOT_NULL(writer_a.done); + TEST_ASSERT_NOT_NULL(writer_b.done); + + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(compression_writer_task, "cp_wr_a", + TEST_LIFECYCLE_STACK_SIZE, &writer_a, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(compression_writer_task, "cp_wr_b", + TEST_LIFECYCLE_STACK_SIZE, &writer_b, + TEST_LIFECYCLE_PRIO, NULL)); + + xSemaphoreGive(writer_a.token); + TEST_ASSERT_TRUE(xSemaphoreTake(writer_a.done, pdMS_TO_TICKS(2000))); + TEST_ASSERT_TRUE(xSemaphoreTake(writer_b.done, pdMS_TO_TICKS(2000))); + + /* A second record from the main task must not register a new entry: + * its records keep the registered id. Periodic publish may repeat + * the binding in this window, always with the same name. */ + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_MAIN_B, 0); + + /* Bindings ride the periodic window only: drive the LBM broadcast + * once so this capture carries every registered writer's binding. */ + ble_log_task_bindings_publish(); + + compression_capture_t capture; + compression_drain_and_capture(&capture); + + const char *main_name = pcTaskGetName(NULL); + TEST_ASSERT_NOT_NULL(main_name); + + /* All records present: contention between interleaved writers no + * longer drops records. */ + TEST_ASSERT_EQUAL_UINT8(TEST_CP_WRITER_RECORDS, capture.a_records); + TEST_ASSERT_EQUAL_UINT8(TEST_CP_WRITER_RECORDS, capture.b_records); + TEST_ASSERT_EQUAL_UINT8(2, capture.main_records); + + /* Every record of a writer carries that writer's announced id. */ + TEST_ASSERT_TRUE(capture.a_id_set); + TEST_ASSERT_FALSE(capture.a_id_mismatch); + TEST_ASSERT_TRUE(capture.b_id_set); + TEST_ASSERT_FALSE(capture.b_id_mismatch); + TEST_ASSERT_TRUE(capture.main_id_set); + TEST_ASSERT_FALSE(capture.main_id_mismatch); + TEST_ASSERT_NOT_EQUAL(TEST_CP_TASK_UNKNOWN, + compression_announced_id(&capture, "cp_wr_a")); + TEST_ASSERT_NOT_EQUAL(TEST_CP_TASK_UNKNOWN, + compression_announced_id(&capture, "cp_wr_b")); + TEST_ASSERT_NOT_EQUAL(TEST_CP_TASK_UNKNOWN, + compression_announced_id(&capture, main_name)); + TEST_ASSERT_EQUAL_UINT8(compression_announced_id(&capture, "cp_wr_a"), + capture.a_id); + TEST_ASSERT_EQUAL_UINT8(compression_announced_id(&capture, "cp_wr_b"), + capture.b_id); + TEST_ASSERT_EQUAL_UINT8(compression_announced_id(&capture, main_name), + capture.main_id); + + /* Every writer is announced at least once by the driven publish (a + * production tick may add another, with the same name), and the + * capture rejects a same-id rename. */ + TEST_ASSERT_TRUE( + capture.announce_cnt[compression_announced_id(&capture, "cp_wr_a")] >= 1); + TEST_ASSERT_TRUE( + capture.announce_cnt[compression_announced_id(&capture, "cp_wr_b")] >= 1); + TEST_ASSERT_TRUE( + capture.announce_cnt[compression_announced_id(&capture, main_name)] >= 1); + + vSemaphoreDelete(writer_a.token); + vSemaphoreDelete(writer_b.token); + vSemaphoreDelete(writer_a.done); + vSemaphoreDelete(writer_b.done); +} + +/* Periodic binding publish: bindings are broadcast on the snapshot window + * (the LBM periodic publish); a task's first record already carries its + * id and is bound by name at the next window. Drive the publish + * synchronously so the window is deterministic: capture the main task's + * record first to learn its id, then the driven publish binds that id to + * the name and announces no other id. */ +TEST_CASE("BLE Log republishes task bindings on the periodic window", + "[ble_log][compression]") +{ + compression_reset_streams(); + + const char *main_name = pcTaskGetName(NULL); + TEST_ASSERT_NOT_NULL(main_name); + + /* First window: the record carries the registered id, but no binding + * is guaranteed yet (a production tick may or may not have landed in + * this window, so no announce assertion is made here). */ + ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST, + TEST_CP_INDEX_MAIN_A, 0); + compression_capture_t first; + compression_drain_and_capture(&first); + TEST_ASSERT_TRUE(first.main_id_set); + uint8_t main_id = first.main_id; + TEST_ASSERT_NOT_EQUAL(TEST_CP_TASK_UNKNOWN, main_id); + + /* One synchronous publish; a production tick may add another with the + * same id, so only presence and id/name stability are asserted. */ + ble_log_task_bindings_publish(); + compression_capture_t second; + compression_drain_and_capture(&second); + + TEST_ASSERT_TRUE(second.announce_cnt[main_id] >= 1); + TEST_ASSERT_EQUAL_UINT8(main_id, + compression_announced_id(&second, main_name)); + /* Publishing never fabricates bindings: no other id is announced. */ + for (int i = 0; i < CONFIG_BLE_LOG_TASK_ID_MAX; i++) { + if (i != main_id) { + TEST_ASSERT_EQUAL_UINT8(0, second.announce_cnt[i]); + } + } +} + +/* The registry is sized by CONFIG_BLE_LOG_TASK_ID_MAX (4 in this + * app) and wiped between cases, so this case fills it itself: one-shot + * filler tasks consume every slot but the last, cp_fill_a takes the last + * free slot, and cp_fill_b beyond the registry degrades to the unknown id + * (0xFF) and its record is still emitted. Bindings are broadcast on the + * periodic window only, so the publish is driven once before the + * capture. */ +TEST_CASE("BLE Log degrades to the unknown task id when the registry is full", + "[ble_log][compression]") +{ + compression_reset_streams(); + + /* Consume every slot but the last with distinct one-shot tasks. The + * name is copied into the task's TCB, so one buffer is reused. */ + compression_once_ctx_t filler[CONFIG_BLE_LOG_TASK_ID_MAX - 1]; + char filler_name[8]; + for (int i = 0; i < CONFIG_BLE_LOG_TASK_ID_MAX - 1; i++) { + filler[i].done = xSemaphoreCreateBinary(); + TEST_ASSERT_NOT_NULL(filler[i].done); + filler[i].log_index = TEST_CP_INDEX_FILLER + i; + snprintf(filler_name, sizeof(filler_name), "cp_f%d", i); + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(compression_once_task, filler_name, + TEST_LIFECYCLE_STACK_SIZE, &filler[i], + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(filler[i].done, pdMS_TO_TICKS(2000))); } - TEST_ASSERT_TRUE(capture.first_found); - TEST_ASSERT_FALSE(capture.dropped_found); - TEST_ASSERT_TRUE(capture.second_found); - TEST_ASSERT_TRUE(capture.second_switched); - TEST_ASSERT_TRUE(capture.third_found); - TEST_ASSERT_TRUE(capture.third_switched); - /* The blocked writer claims its SN before taking the compression lock; - * the rejected contender burns the following SN. */ - TEST_ASSERT_EQUAL_HEX32((capture.first_sn + 1) & 0x00ffffffU, - capture.second_sn); - TEST_ASSERT_EQUAL_HEX32((capture.second_sn + 2) & 0x00ffffffU, - capture.third_sn); + compression_once_ctx_t fill_a = { + .done = xSemaphoreCreateBinary(), + .log_index = TEST_CP_INDEX_FILL_A, + }; + compression_once_ctx_t fill_b = { + .done = xSemaphoreCreateBinary(), + .log_index = TEST_CP_INDEX_FILL_B, + }; + TEST_ASSERT_NOT_NULL(fill_a.done); + TEST_ASSERT_NOT_NULL(fill_b.done); - vSemaphoreDelete(writer.committed); - vSemaphoreDelete(writer.exit); - vSemaphoreDelete(writer.exited); - vSemaphoreDelete(s_compression_hook_entered); - vSemaphoreDelete(s_compression_hook_continue); - s_compression_hook_entered = NULL; - s_compression_hook_continue = NULL; + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(compression_once_task, "cp_fill_a", + TEST_LIFECYCLE_STACK_SIZE, &fill_a, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(fill_a.done, pdMS_TO_TICKS(2000))); + + TEST_ASSERT_EQUAL(pdTRUE, + xTaskCreate(compression_once_task, "cp_fill_b", + TEST_LIFECYCLE_STACK_SIZE, &fill_b, + TEST_LIFECYCLE_PRIO, NULL)); + TEST_ASSERT_TRUE(xSemaphoreTake(fill_b.done, pdMS_TO_TICKS(2000))); + + /* Bindings ride the periodic window only: drive the LBM broadcast + * once so the capture carries every registered name. */ + ble_log_task_bindings_publish(); + + compression_capture_t capture; + compression_drain_and_capture(&capture); + + /* The fillers consumed the first slots: every record emitted with a + * valid id. */ + TEST_ASSERT_EQUAL_UINT8(CONFIG_BLE_LOG_TASK_ID_MAX - 1, + capture.filler_records); + TEST_ASSERT_FALSE(capture.filler_unknown); + + /* The last free slot still works: valid id, bound by the driven + * periodic publish. */ + TEST_ASSERT_EQUAL_UINT8(1, capture.fill_a_records); + TEST_ASSERT_TRUE(capture.fill_a_id_set); + TEST_ASSERT_NOT_EQUAL(TEST_CP_TASK_UNKNOWN, + compression_announced_id(&capture, "cp_fill_a")); + TEST_ASSERT_EQUAL_UINT8(compression_announced_id(&capture, "cp_fill_a"), + capture.fill_a_id); + + /* Beyond the registry: unknown id, no binding, log still emitted. */ + TEST_ASSERT_EQUAL_UINT8(1, capture.fill_b_records); + TEST_ASSERT_TRUE(capture.fill_b_unknown); + TEST_ASSERT_EQUAL_UINT8(TEST_CP_TASK_UNKNOWN, + compression_announced_id(&capture, "cp_fill_b")); + + for (int i = 0; i < CONFIG_BLE_LOG_TASK_ID_MAX - 1; i++) { + vSemaphoreDelete(filler[i].done); + } + vSemaphoreDelete(fill_a.done); + vSemaphoreDelete(fill_b.done); } #endif /* CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE */ @@ -1119,7 +1391,7 @@ static void blocked_claim_task(void *arg) blocked_writer_ctx_t *ctx = arg; uint32_t handle; xSemaphoreGive(ctx->started); - uint8_t *payload = ble_log_claim(BLE_LOG_SRC_ENCODE, 1, &handle); + uint8_t *payload = ble_log_claim(BLE_LOG_SRC_ENCODE, 1, &handle, true); ctx->result = payload != NULL; if (payload) { payload[0] = 0x58; diff --git a/components/bt/common/ble_log/test_apps/ble_log_test/sdkconfig.defaults b/components/bt/common/ble_log/test_apps/ble_log_test/sdkconfig.defaults index 7bbad451380..6f03c3e16dd 100644 --- a/components/bt/common/ble_log/test_apps/ble_log_test/sdkconfig.defaults +++ b/components/bt/common/ble_log/test_apps/ble_log_test/sdkconfig.defaults @@ -4,3 +4,8 @@ CONFIG_BLE_LOG_PRPH_TEST=y CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU0=n CONFIG_UNITY_ENABLE_64BIT=y CONFIG_BLE_MESH=y +# Exercise the compressed-log encoders and the task-id registry (protocol v8). +CONFIG_BLE_COMPRESSED_LOG_ENABLE=y +CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE=y +# Small registry so the table-full degradation is reachable on target. +CONFIG_BLE_LOG_TASK_ID_MAX=4