Mirrors/esp-idf
1
0
Fork 0
mirror of https://github.com/espressif/esp-idf.git synced 2026-09-22 13:01:16 +03:00
Code Issues Packages Projects Releases Wiki Activity

feat(ble_log): attribute compressed records with a task-id registry

Browse Source 
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.
This commit is contained in:
Zhou Xiao
2026-09-05 01:35:05 +08:00
committed by guozifan
parent 0b8368ee86
commit 2cf0638686
17 changed files with 1033 additions and 277 deletions
Download Patch File Download Diff File Expand all files Collapse all files

1
components/bt/common/CMakeLists.txt
View File

@@ -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"
)

34
components/bt/common/ble_log/Kconfig.in
View File

@@ -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)"

70
components/bt/common/ble_log/README.md
View File

@@ -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.

1
components/bt/common/ble_log/extension/log_compression/Kconfig.in
View File

@@ -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"

91
components/bt/common/ble_log/extension/log_compression/ble_log_compression.c
View File

@@ -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;
}

12
components/bt/common/ble_log/extension/log_compression/include/log_compression/utils.h
View File

@@ -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)

10
components/bt/common/ble_log/include/ble_log.h
View File

@@ -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

31
components/bt/common/ble_log/src/ble_log_lbm_v2.c
View File

@@ -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]));

7
components/bt/common/ble_log/src/ble_log_rt.c
View File

@@ -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 |

272
components/bt/common/ble_log/src/ble_log_task_registry.c Normal file
View File

@@ -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, &timestamp, 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

28
components/bt/common/ble_log/src/internal_include/ble_log_lbm_v2.h
View File

@@ -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

87
components/bt/common/ble_log/src/internal_include/ble_log_task_registry.h Normal file
View File

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

5
components/bt/common/ble_log/src/internal_include/ble_log_util.h
View File

@@ -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;

82
components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c
View File

@@ -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. */

2
components/bt/common/ble_log/test_apps/ble_log_test/README.md
View File

@@ -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;

572
components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c
View File

@@ -7,6 +7,7 @@
#include <stdbool.h>
#include <stddef.h>
#include <stdint.h>
#include <stdio.h>
#include <string.h>
#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;

5
components/bt/common/ble_log/test_apps/ble_log_test/sdkconfig.defaults
View File

@@ -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