diff --git a/components/bt/common/ble_log/README.md b/components/bt/common/ble_log/README.md index fa86105ae0c..5fe0c793285 100644 --- a/components/bt/common/ble_log/README.md +++ b/components/bt/common/ble_log/README.md @@ -29,6 +29,19 @@ writers retain reserve access and fail-fast behavior. The Internal Snapshot and UART0 redirection transports are not members of the bitmap pool. +Periodic flushing scans the whole bounded pool, not just OPEN bitmap hints: +writers temporarily remove their hints while writing or holding a claim. A +failed try-lock leaves `pending_seal`; the next claim seals the old buffer +before appending, or a later periodic scan seals it when unlocked. This is a +deferred request, not a snapshot barrier. Seal and recycle clear the flag, +but a delayed flusher can set it afterwards; an extra early partial seal is +allowed. Full flush/deinit retain OPEN-only scans after writers drain. + +FREE acquisition requires the lock, FREE state, and atomically removing an +actually published FREE bit. A cached candidate alone cannot bypass the +recycler's state-to-bitmap publication window. UART0 periodic flushing is +independent of producer enable: disable stops new writes, not cached output. + ## Runtime dispatch Sealed transports enter one bounded queue. The first submission anchors a @@ -94,15 +107,18 @@ source IDs of protocol v8 frames: 8 REDIR extension ``` -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), 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 +Core log sources (`CUSTOM` through `ENCODE`) and Internal Snapshots share one +24-bit Global SN. Core logs consume it after entry validation and gate acceptance, +before buffer contention; lost log attempts leave gaps accounted for by +`lost_frame_cnt`. Snapshots consume it only after acquiring their dedicated +transport, when assembling the frame. Busy/skipped snapshots do not consume a +Global SN and are not included in `lost_frame_cnt`. +Snapshots also carry a separate 24-bit `anchor_count` in their payload: +only snapshot attempts advance this counter, including skipped snapshots. +The periodic task-binding broadcast and REDIR console stream retain their +own separate header sequences (gaps count skipped binding windows or dropped +console batches). `ble_log_init()` resets all sequences and the anchor counter, +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. @@ -119,14 +135,15 @@ bit 7. Disabling HCI logging suppresses records from both capture paths. ## Internal Snapshot 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 +from dedicated transports: the snapshot frame is 179 logical bytes on its +180-byte aligned 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: - reason flags (`INIT`, `PERIODIC`, `FLUSH`, `TS_VALID`); +- a 24-bit little-endian `anchor_count` (three bytes), immediately after the reason flags; - the complete 58-byte build, library, chip, and protocol version block; - the LC clock, ESP Timer, and FreeRTOS tick samples captured together with the GPIO sync level; @@ -136,26 +153,40 @@ The snapshot contains: The periodic snapshot is an always-on system behavior from initialization until deinitialization. It cannot be stopped by the TS sync IO control API. -A skipped periodic snapshot burns one snapshot SN instead: the gap in the -snapshot sequence is the loss signal, and it is visible directly in the -frame header without a dedicated payload field. +A skipped periodic snapshot advances only the anchor count, not the Global SN. +Anchor counts start at zero for INIT, also advance for FLUSH, and wrap modulo +2^24 on the wire (the atomic runtime counter remains uint32_t). +A gap between anchor counts identifies missed snapshot attempts without +mistaking intervening ordinary logs for missed snapshots. Each source statistic contains only: ```c uint32_t written_frame_cnt; uint32_t lost_frame_cnt; +uint32_t written_bytes_cnt; ``` Successful counts are incremented only after a complete frame is committed to -a transport; they do not imply confirmed physical TX. Core counts and the pool -peak restart after a completed FLUSH; the Global SN and the snapshot -sequence remain continuous. A busy periodic Internal +a transport; they do not imply confirmed physical TX. `written_bytes_cnt` +counts the full logical frame (six-byte header, payload including any timestamp +prefix, and four-byte checksum), excluding peripheral DMA padding. Rejected or +aborted writes do not add bytes; there is no lost-byte counter. Internal and +REDIR frames are not included in these per-core-source byte counters. All three +counters are uint32 values and wrap modulo 2^32. +Core counts and the pool peak restart after a completed FLUSH; the Global SN +and anchor count remain continuous. A busy periodic Internal transport is never overwritten; that snapshot is skipped and counted. Required INIT and FLUSH snapshots use a bounded task-context wait. -The snapshot is not an Anchor: it does not seal the shared pool and does not -define a Log Segment boundary. +The protocol version remains v8 despite the changed snapshot payload layout and +header sequence semantics. Receivers must be updated together with the producer; +the version byte alone cannot distinguish the old and new layouts. +The snapshot remains a sampling point, +not a confirmed TX boundary: periodic OPEN flushing is best-effort, statistics +are sampled individually while writers can run, and Global SN allocation order +is not submission order. Neither deferred sealing nor the anchor count makes +snapshot differences an exact SN-interval accounting boundary. ## Public API @@ -229,7 +260,7 @@ 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 +sequence, never in the Global SN or snapshot anchor count), 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 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 f25223e036a..f173c1d0146 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 @@ -74,9 +74,10 @@ _Static_assert(sizeof(ble_log_version_info_t) == 58, typedef struct { ble_log_prph_trans_t *trans[BLE_LOG_POOL_TRANS_CNT]; - /* Hint bitmaps: a set bit means "this buffer is likely FREE/OPEN". The - * real ownership is the per-buffer atomic_lock; bitmaps only accelerate - * candidate lookup and may be transiently stale. */ + /* Bitmaps accelerate lookup; cached candidates may be stale. Ownership + * still requires the per-buffer lock and a state check. FREE acceptance + * also requires atomically taking a published FREE bit: state=FREE alone + * can precede the recycler's bitmap publication. OPEN is only a hint. */ volatile uint32_t free_bitmap; volatile uint32_t open_bitmap; @@ -117,12 +118,12 @@ BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t lbm_enabled = 0; BLE_LOG_STATIC volatile bool flush_in_progress = false; BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_pool_t g_pool; BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_stat_mgr_t stat_mgr_ctx[BLE_LOG_SRC_MAX]; -/* Global SN (the log sources except INTERNAL and REDIR) and the separate - * Internal Snapshot sequence; see ble_log_lbm_v2.h. */ +/* Global SN (core logs and snapshots) and the snapshot-only anchor count; + * task bindings and REDIR retain independent sequences. */ BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t g_frame_sn; -BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t g_snapshot_sn; +BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t g_anchor_count; #define BLE_LOG_GET_GLOBAL_SN() BLE_LOG_GET_FRAME_SN(g_frame_sn) -#define BLE_LOG_GET_SNAPSHOT_SN() BLE_LOG_GET_FRAME_SN(g_snapshot_sn) +#define BLE_LOG_GET_ANCHOR_COUNT() BLE_LOG_GET_FRAME_SN(g_anchor_count) BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_prph_trans_t *internal_trans; BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_pool_claim_t pool_claim_ctx[BLE_LOG_POOL_TRANS_CNT]; BLE_LOG_STATIC ble_log_internal_snapshot_t internal_snapshot; @@ -187,7 +188,8 @@ ble_log_pool_bitmap_set(volatile uint32_t *bitmap, uint8_t id) BLE_LOG_IRAM_ATTR BLE_LOG_STATIC uint32_t ble_log_pool_bitmap_clear(volatile uint32_t *bitmap, uint8_t id) { - /* Clearing a hint publishes no data; ownership is already held by lock. */ + /* Clearing publishes no data; ownership is held by lock. For FREE, the + * returned bit also confirms that recycle publication completed. */ return __atomic_fetch_and(bitmap, ~BIT(id), __ATOMIC_RELAXED); } @@ -297,8 +299,10 @@ ble_log_pool_waiter_adjust(int delta) BLE_LOG_IRAM_ATTR void ble_log_lbm_recycle_trans(ble_log_prph_trans_t *trans) { trans->pos = 0; - /* A marker set while the transport was SENDING must not leak into its - * next lifecycle. */ + /* Clear existing requests. A flusher delayed after a failed try-lock may + * store true after this clear, even in the next lifecycle. That hint may + * cause an extra partial seal; it never grants permission to send a + * buffer still owned by a writer. */ BLE_LOG_ATOMIC_STORE_RELAXED(trans->pending_seal, false); if (trans->owner_kind == BLE_LOG_TRANS_OWNER_INTERNAL) { @@ -419,6 +423,10 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_from(volatile uint32_t *bitmap, uint32_t previous = ble_log_pool_bitmap_clear(bitmap, id); if (bitmap == &g_pool.free_bitmap) { + if (!(previous & BIT(id))) { + ble_log_pool_release_candidate(trans); + continue; + } ble_log_pool_update_peak(previous & ~BIT(id)); } /* Keep packing the same OPEN transport instead of scanning the rest @@ -600,6 +608,8 @@ void ble_log_pool_finish_frame(ble_log_prph_trans_t *trans, uint16_t payload_len trans->pos += payload_len + BLE_LOG_FRAME_OVERHEAD; BLE_LOG_ATOMIC_ADD_RELAXED(stat_mgr->counters.written_frame_cnt, 1); + BLE_LOG_ATOMIC_ADD_RELAXED(stat_mgr->counters.written_bytes_cnt, + payload_len + BLE_LOG_FRAME_OVERHEAD); /* Completion: seal if nearly full, otherwise publish as OPEN. */ if (BLE_LOG_TRANS_FREE_SPACE(trans) <= BLE_LOG_FRAME_OVERHEAD) { @@ -767,7 +777,7 @@ bool ble_log_lbm_init(void) g_pool.open_bitmap = 0; BLE_LOG_MEMSET(stat_mgr_ctx, 0, sizeof(stat_mgr_ctx)); g_frame_sn = 0; - g_snapshot_sn = 0; + g_anchor_count = 0; /* Task registry: fresh epoch (registry, sequence and its dedicated * transport) for the new receiver epoch. */ if (!ble_log_task_registry_init()) { @@ -842,6 +852,8 @@ void ble_log_snapshot_stats(ble_log_source_stat_t *snapshots) BLE_LOG_ATOMIC_LOAD_RELAXED(stat_mgr->counters.written_frame_cnt); snapshots[i].lost_frame_cnt = BLE_LOG_ATOMIC_LOAD_RELAXED(stat_mgr->counters.lost_frame_cnt); + snapshots[i].written_bytes_cnt = + BLE_LOG_ATOMIC_LOAD_RELAXED(stat_mgr->counters.written_bytes_cnt); } } @@ -963,7 +975,16 @@ bool ble_log_internal_snapshot(uint16_t reason_flags, (uint8_t)BLE_LOG_ATOMIC_LOAD_RELAXED(g_pool.inflight_peak); ble_log_snapshot_stats(internal_snapshot.stats); - uint32_t frame_sn = BLE_LOG_GET_SNAPSHOT_SN(); + /* Only a snapshot that acquired its transport consumes a Global SN. + * Busy snapshots are not in the core loss statistics; their gaps belong + * exclusively to anchor_count. The transport lock serializes successful + * snapshots, so no extra critical section is needed for these counters. */ + uint32_t frame_sn = BLE_LOG_GET_GLOBAL_SN(); + uint32_t anchor_count = BLE_LOG_GET_ANCHOR_COUNT(); + for (unsigned i = 0; i < sizeof(internal_snapshot.anchor_count); i++) { + internal_snapshot.anchor_count[i] = (uint8_t)(anchor_count >> (8U * i)); + } + ble_log_frame_head_t frame_head = { .length = sizeof(timestamp) + sizeof(internal_snapshot), .frame_meta = BLE_LOG_MAKE_FRAME_META(BLE_LOG_SRC_INTERNAL, frame_sn), @@ -987,9 +1008,7 @@ bool ble_log_internal_snapshot(uint16_t reason_flags, return true; lost: - /* A skipped snapshot burns one snapshot SN: the gap in the snapshot - * sequence is the loss signal. */ - (void)BLE_LOG_GET_SNAPSHOT_SN(); + (void)BLE_LOG_GET_ANCHOR_COUNT(); failed: BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); return false; @@ -1023,14 +1042,13 @@ void ble_log_lbm_flush_open_trans(void) } for (int id = 0; id < BLE_LOG_POOL_TRANS_CNT; id++) { - if (!(BLE_LOG_ATOMIC_LOAD_ACQUIRE(g_pool.open_bitmap) & BIT(id))) { - continue; - } + /* Scan the bounded pool, including writers absent from OPEN hints. */ ble_log_prph_trans_t *trans = g_pool.trans[id]; #if CONFIG_BLE_LOG_PRPH_TEST - /* Test point: the OPEN hint was just observed; a test can play the - * other core before this scan takes the candidate lock. */ - if (ble_log_test_flush_hint_seen_hook) { + /* Preserve the stale-OPEN-hint test's target without filtering the + * production scan. Unrelated FREE candidates must not fire its hooks. */ + bool had_open_hint = BLE_LOG_ATOMIC_LOAD_ACQUIRE(g_pool.open_bitmap) & BIT(id); + if (had_open_hint && ble_log_test_flush_hint_seen_hook) { ble_log_test_flush_hint_seen_hook((uint8_t)id); } #endif @@ -1050,7 +1068,7 @@ void ble_log_lbm_flush_open_trans(void) #if CONFIG_BLE_LOG_PRPH_TEST /* Test point: this scan holds a candidate lock taken on a * stale hint; the transport state is not OPEN. */ - if (ble_log_test_flush_stale_locked_hook) { + if (had_open_hint && ble_log_test_flush_stale_locked_hook) { ble_log_test_flush_stale_locked_hook(); } #endif @@ -1192,11 +1210,11 @@ void ble_log_flush(void) } /* FLUSH is not a segment boundary: reset interval counters while the - * Global SN and the snapshot sequence stay continuous. Snapshot loss is - * lifecycle-cumulative in the snapshot sequence and is preserved. */ + * Global SN and snapshot anchor count stay continuous. */ for (int i = 0; i < BLE_LOG_SRC_MAX; i++) { BLE_LOG_ATOMIC_STORE_RELAXED(stat_mgr_ctx[i].counters.written_frame_cnt, 0); BLE_LOG_ATOMIC_STORE_RELAXED(stat_mgr_ctx[i].counters.lost_frame_cnt, 0); + BLE_LOG_ATOMIC_STORE_RELAXED(stat_mgr_ctx[i].counters.written_bytes_cnt, 0); } BLE_LOG_ATOMIC_STORE_RELAXED(g_pool.inflight_peak, 0); #if BLE_LOG_UART_REDIR_ENABLED 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 index 537833a594b..5a1d8130d28 100644 --- a/components/bt/common/ble_log/src/ble_log_task_registry.c +++ b/components/bt/common/ble_log/src/ble_log_task_registry.c @@ -36,7 +36,7 @@ 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 + * from the log/snapshot Global SN (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; 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 da8dc7047f5..fdace26460d 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 @@ -64,9 +64,8 @@ typedef struct { * source IDs: the frame source byte carries the bare enum value. */ /* Statistic slots in the Internal Snapshot: every public source that can - * produce frames, i.e. CUSTOM through ENCODE. INTERNAL frames carry their - * own snapshot sequence in the frame header; REDIR is a raw console - * stream. */ + * produce core frames, i.e. CUSTOM through ENCODE. Snapshots share the + * Global SN but have no statistic slot; REDIR is a raw console stream. */ #define BLE_LOG_SRC_CORE_FIRST BLE_LOG_SRC_CUSTOM #define BLE_LOG_SRC_CORE_COUNT (BLE_LOG_SRC_ENCODE - BLE_LOG_SRC_CORE_FIRST + 1) @@ -93,6 +92,9 @@ typedef struct { typedef struct { uint32_t written_frame_cnt; uint32_t lost_frame_cnt; + /* Successfully committed logical frame bytes, including head and tail, + * excluding DMA padding. Not a physical-TX acknowledgement. */ + uint32_t written_bytes_cnt; } __attribute__((packed)) ble_log_source_stat_t; /* Runtime per-source counters. The aligned wrapper keeps the embedded @@ -104,18 +106,17 @@ typedef struct { #define BLE_LOG_GET_FRAME_SN(VAR) BLE_LOG_ATOMIC_ADD_RELAXED(VAR, 1) -/* One 24-bit Global SN is shared by the log sources except INTERNAL and - * 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, 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 - * frame meta is packed. */ +/* Core logs and INTERNAL snapshots share one 24-bit Global SN. Core logs + * consume it after entry validation and gate acceptance, before contention; + * failed log attempts leave gaps accounted for by lost_frame_cnt. Snapshots + * only consume it after acquiring their dedicated transport. Busy/skipped + * snapshots are not in core loss statistics and advance only the separate + * 24-bit anchor_count, never the Global SN. + * Task-binding broadcasts and REDIR retain independent header sequences. + * ble_log_init() resets every sequence; INIT starts a new receiver epoch. + * FLUSH resets interval statistics, but never the sequences or anchor count. + * Allocation order is not physical TX order; a snapshot is not a drain + * barrier. The wire SN is masked to 24 bits when frame_meta is packed. */ /* -------------------------------- */ /* Internal Snapshot Frame */ @@ -137,6 +138,9 @@ typedef struct { typedef struct { uint8_t int_src_code; uint16_t reason_flags; + /* Snapshot attempts (INIT/PERIODIC/FLUSH), including skipped points. + * Little-endian low 24 bits; the runtime counter remains uint32_t. */ + uint8_t anchor_count[3]; ble_log_version_info_t version_info; /* Clock samples captured at the same instant, mirroring @@ -203,14 +207,14 @@ _Static_assert((BLE_LOG_POOL_TRANS_SIZE & 3U) == 0, #endif _Static_assert(sizeof(ble_log_version_info_t) == 58, "Unexpected BLE Log version information size"); -_Static_assert(sizeof(ble_log_source_stat_t) == 8, +_Static_assert(sizeof(ble_log_source_stat_t) == 12, "Unexpected BLE Log source statistic size"); _Static_assert(offsetof(ble_log_stat_mgr_t, counters) == 0 && - sizeof(ble_log_stat_mgr_t) == 8, + sizeof(ble_log_stat_mgr_t) == 12, "stat manager layout must keep the counters word-aligned"); -_Static_assert(sizeof(ble_log_internal_snapshot_t) == 134, +_Static_assert(sizeof(ble_log_internal_snapshot_t) == 165, "Unexpected BLE Log Internal Snapshot size"); -_Static_assert(BLE_LOG_INTERNAL_FRAME_LEN == 148, +_Static_assert(BLE_LOG_INTERNAL_FRAME_LEN == 179, "Unexpected BLE Log Internal frame size"); _Static_assert(BLE_LOG_INTERNAL_TRANS_SIZE >= BLE_LOG_INTERNAL_FRAME_LEN, "Internal transport is too small"); diff --git a/components/bt/common/ble_log/src/internal_include/ble_log_prph.h b/components/bt/common/ble_log/src/internal_include/ble_log_prph.h index bc2ab9b0fd5..3a4eee27b02 100644 --- a/components/bt/common/ble_log/src/internal_include/ble_log_prph.h +++ b/components/bt/common/ble_log/src/internal_include/ble_log_prph.h @@ -45,7 +45,9 @@ typedef struct { /* Lazy flush marker, pool-owned: set by the periodic flusher (without * holding atomic_lock) when the transport was busy at flush time; the * next claim that takes the lock seals the buffered frames first. - * Cleared by seal_and_send and on recycle. */ + * Cleared by seal_and_send and on recycle, but a delayed flusher may + * store true afterwards. Such a stale hint permits an extra partial + * seal in the next lifecycle, never sending a writer-owned buffer. */ volatile uint8_t pending_seal; uint8_t *buf; diff --git a/components/bt/common/ble_log/src/prph/ble_log_prph_uart_dma.c b/components/bt/common/ble_log/src/prph/ble_log_prph_uart_dma.c index 7736178d04e..854e499aedb 100644 --- a/components/bt/common/ble_log/src/prph/ble_log_prph_uart_dma.c +++ b/components/bt/common/ble_log/src/prph/ble_log_prph_uart_dma.c @@ -72,8 +72,8 @@ BLE_LOG_STATIC void esp_timer_cb_flush_log(void *arg) { (void)arg; - if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(prph_inited) || - !ble_log_lbm_is_enabled()) { + /* Producer disable stops new writes, not periodic draining of old data. */ + if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(prph_inited)) { return; } 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 13923c713d7..affd8dae9fe 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 @@ -17,5 +17,6 @@ It covers: - task and critical-section writes plus HCI direction encoding; - direct compression claim/commit, stale handles, and per-source serialization; - oversized-record rejection, flush sequence continuity, pool exhaustion, and non-yield reserve use; -- periodic snapshot busy/loss behavior; +- shared log/snapshot Global SN, independent 24-bit anchor counts, and snapshot busy/loss behavior; +- successful logical-byte counts for public, claim/commit, and LL writes, plus FLUSH reset; - enable, disable, parked-writer, and deinit races. 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 02288e3a387..fef271fa58f 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 @@ -218,9 +218,18 @@ static void capture_version_info_frame(const test_ble_log_frame_t *frame, void * } } +static uint32_t snapshot_anchor_count(const ble_log_internal_snapshot_t *snapshot) +{ + return (uint32_t)snapshot->anchor_count[0] | + ((uint32_t)snapshot->anchor_count[1] << 8) | + ((uint32_t)snapshot->anchor_count[2] << 16); +} + typedef struct { bool found; uint16_t reason_flags; + uint32_t sn; + uint32_t anchor_count; } first_snapshot_capture_t; static void capture_first_snapshot(const test_ble_log_frame_t *frame, void *ctx) @@ -237,6 +246,8 @@ static void capture_first_snapshot(const test_ble_log_frame_t *frame, void *ctx) if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT) { capture->found = true; capture->reason_flags = snapshot.reason_flags; + capture->sn = frame->sn; + capture->anchor_count = snapshot_anchor_count(&snapshot); } } @@ -288,19 +299,27 @@ TEST_CASE("BLE Log v8 framing matches golden bytes", "[ble_log][wire]") TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_ENCODE); TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_INT_SRC_VERSION_INFO); TEST_ASSERT_EQUAL_UINT8(8, BLE_LOG_INT_SRC_SNAPSHOT); - TEST_ASSERT_EQUAL_size_t(8, sizeof(ble_log_source_stat_t)); - TEST_ASSERT_EQUAL_size_t(134, sizeof(ble_log_internal_snapshot_t)); + TEST_ASSERT_EQUAL_size_t(12, sizeof(ble_log_source_stat_t)); + TEST_ASSERT_EQUAL_size_t(165, sizeof(ble_log_internal_snapshot_t)); TEST_ASSERT_EQUAL_size_t( - 3, offsetof(ble_log_internal_snapshot_t, version_info)); + 3, offsetof(ble_log_internal_snapshot_t, anchor_count)); TEST_ASSERT_EQUAL_size_t( - 62, offsetof(ble_log_internal_snapshot_t, ts.lc_ts)); + 6, offsetof(ble_log_internal_snapshot_t, version_info)); TEST_ASSERT_EQUAL_size_t( - 66, offsetof(ble_log_internal_snapshot_t, ts.esp_ts)); + 65, offsetof(ble_log_internal_snapshot_t, ts.lc_ts)); TEST_ASSERT_EQUAL_size_t( - 70, offsetof(ble_log_internal_snapshot_t, ts.os_ts)); + 69, offsetof(ble_log_internal_snapshot_t, ts.esp_ts)); TEST_ASSERT_EQUAL_size_t( - 78, offsetof(ble_log_internal_snapshot_t, stats)); - TEST_ASSERT_EQUAL_UINT32(148, BLE_LOG_INTERNAL_FRAME_LEN); + 73, offsetof(ble_log_internal_snapshot_t, ts.os_ts)); + TEST_ASSERT_EQUAL_size_t( + 81, offsetof(ble_log_internal_snapshot_t, stats)); + TEST_ASSERT_EQUAL_UINT32(179, BLE_LOG_INTERNAL_FRAME_LEN); + TEST_ASSERT_EQUAL_UINT32(180, BLE_LOG_INTERNAL_TRANS_SIZE); + const ble_log_internal_snapshot_t anchor_fixture = { + .anchor_count = {0x56, 0x34, 0x12}, + }; + TEST_ASSERT_EQUAL_size_t(3, sizeof(anchor_fixture.anchor_count)); + TEST_ASSERT_EQUAL_HEX32(0x123456, snapshot_anchor_count(&anchor_fixture)); #if CONFIG_BLE_LOG_LL_ENABLED TEST_ASSERT_EQUAL_UINT8(4, BLE_LOG_LL_FLAG_HCI); TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_LL_FLAG_HCI_UPSTREAM); @@ -413,6 +432,8 @@ TEST_CASE("BLE Log INIT snapshot starts each receiver epoch", "[ble_log][wire]") TEST_ASSERT_TRUE(capture.found); TEST_ASSERT_EQUAL_HEX16(BLE_LOG_SNAPSHOT_REASON_INIT, capture.reason_flags); + TEST_ASSERT_EQUAL_UINT32(0, capture.sn); + TEST_ASSERT_EQUAL_UINT32(0, capture.anchor_count); } TEST_CASE("BLE Log sync IO APIs retain runtime lifecycle checks", "[ble_log]") @@ -1185,21 +1206,23 @@ TEST_CASE("BLE Log preserves LL payload and rejects oversized records", TEST_ASSERT_TRUE(captures[CUSTOM_BEFORE].found); TEST_ASSERT_FALSE(captures[CUSTOM_OVERSIZED].found); TEST_ASSERT_TRUE(captures[CUSTOM_AFTER].found); - TEST_ASSERT_EQUAL_HEX32( - (captures[CUSTOM_BEFORE].sn + 2) & 0x00ffffffU, - captures[CUSTOM_AFTER].sn); + /* Periodic snapshots may allocate additional Global SNs between writes. */ + uint32_t custom_delta = (captures[CUSTOM_AFTER].sn - + captures[CUSTOM_BEFORE].sn) & 0x00ffffffU; + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(2, custom_delta); + TEST_ASSERT_LESS_THAN_UINT32(0x00800000U, custom_delta); #if CONFIG_BLE_LOG_LL_ENABLED TEST_ASSERT_TRUE(captures[LL_BEFORE].found); TEST_ASSERT_FALSE(captures[LL_PRIMARY_OVERSIZED].found); TEST_ASSERT_FALSE(captures[LL_APPEND_OVERSIZED].found); TEST_ASSERT_TRUE(captures[LL_AFTER].found); - TEST_ASSERT_EQUAL_HEX32( - (captures[LL_BEFORE].sn + 3) & 0x00ffffffU, - captures[LL_AFTER].sn); + uint32_t ll_delta = (captures[LL_AFTER].sn - captures[LL_BEFORE].sn) & 0x00ffffffU; + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(3, ll_delta); + TEST_ASSERT_LESS_THAN_UINT32(0x00800000U, ll_delta); #endif } -TEST_CASE("BLE Log flush preserves source-local sequence continuity", +TEST_CASE("BLE Log flush snapshot consumes the continuous Global SN", "[ble_log][wire]") { const uint8_t before_marker = 0x71; @@ -1240,7 +1263,11 @@ TEST_CASE("BLE Log flush preserves source-local sequence continuity", }; read_sequence_frames(&after, 1); TEST_ASSERT_TRUE(after.found); - TEST_ASSERT_EQUAL_HEX32((before.sn + 1) & 0x00ffffffU, after.sn); + /* At least the FLUSH snapshot consumes a Global SN between the logs; + * periodic snapshots may consume additional numbers during the reads. */ + TEST_ASSERT_GREATER_OR_EQUAL_UINT32( + 2, (after.sn - before.sn) & 0x00ffffffU); + TEST_ASSERT_LESS_THAN_UINT32(0x00800000U, (after.sn - before.sn) & 0x00ffffffU); } /* ------- pending-seal and deinit drain ------- */ @@ -2048,6 +2075,7 @@ TEST_CASE("BLE Log ESP Timer writers never wait for shared transports", typedef struct { uint32_t sn[SNAPSHOT_CAPTURE_MAX]; + ble_log_internal_snapshot_t snapshot[SNAPSHOT_CAPTURE_MAX]; int count; } snapshot_capture_t; @@ -2065,7 +2093,8 @@ static void capture_snapshot_loss(const test_ble_log_frame_t *frame, void *ctx) if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT && (snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_PERIODIC) && capture->count < SNAPSHOT_CAPTURE_MAX) { - capture->sn[capture->count++] = frame->sn; + capture->sn[capture->count] = frame->sn; + capture->snapshot[capture->count++] = snapshot; } } @@ -2109,6 +2138,27 @@ TEST_CASE("BLE Log periodic snapshot ignores producer gate and fails fast when b TEST_ASSERT_TRUE(test_ble_log_walk_frames( s_read_buf, first_len, capture_snapshot_loss, &capture)); + /* Interleave successful and rejected log attempts with snapshots. These + * consume Global SNs but must not consume snapshot anchor counts. */ + static const uint8_t marker[] = {0xa5, 0x5a, 0x33}; + static const uint8_t oversized[BLE_LOG_MAX_PAYLOAD_LEN] = {0}; + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, marker, sizeof(marker))); + TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, oversized, sizeof(oversized))); + uint32_t log_attempts = 2; + uint32_t handle; + uint8_t *claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, sizeof(marker), &handle, true); + TEST_ASSERT_NOT_NULL(claimed); + memcpy(claimed, marker, sizeof(marker)); + ble_log_commit(handle, sizeof(marker)); + claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, sizeof(marker), &handle, true); + TEST_ASSERT_NOT_NULL(claimed); + ble_log_commit(handle, 0); /* An aborted claim contributes no written bytes. */ + log_attempts += 2; +#if CONFIG_BLE_LOG_LL_ENABLED + ble_log_write_hex_ll(sizeof(marker), marker, 0, NULL, BIT(BLE_LOG_LL_FLAG_TASK)); + log_attempts++; +#endif + TEST_ASSERT_TRUE(ble_log_internal_snapshot( BLE_LOG_SNAPSHOT_REASON_PERIODIC, &ts_info, false)); TEST_ASSERT_TRUE(ble_log_rt_drain()); @@ -2123,16 +2173,69 @@ TEST_CASE("BLE Log periodic snapshot ignores producer gate and fails fast when b TEST_ASSERT_TRUE(test_ble_log_walk_frames( s_read_buf, len, capture_snapshot_loss, &capture)); } - /* The busy periodic attempt burned one snapshot SN: the gap in the - * snapshot sequence is the loss signal. */ + /* Busy snapshots only advance anchor_count. Each captured snapshot and + * each ordinary log attempt consumes one Global SN; skipped snapshots + * must not create unaccounted gaps in that sequence. */ TEST_ASSERT_GREATER_OR_EQUAL_INT(2, capture.count); bool gap_seen = false; for (int i = 1; i < capture.count; i++) { - if (((capture.sn[i] - capture.sn[i - 1]) & 0x00ffffffU) >= 2) { + if (((snapshot_anchor_count(&capture.snapshot[i]) - + snapshot_anchor_count(&capture.snapshot[i - 1])) & 0x00ffffffU) >= 2) { gap_seen = true; } } TEST_ASSERT_TRUE(gap_seen); + int last = capture.count - 1; + TEST_ASSERT_EQUAL_UINT32( + ((uint32_t)last + log_attempts) & 0x00ffffffU, + (capture.sn[last] - capture.sn[0]) & 0x00ffffffU); + const ble_log_source_stat_t *before_stat = &capture.snapshot[0].stats[0]; + const ble_log_source_stat_t *after_stat = &capture.snapshot[last].stats[0]; + TEST_ASSERT_EQUAL_UINT32(1, after_stat->written_frame_cnt - before_stat->written_frame_cnt); + TEST_ASSERT_EQUAL_UINT32(1, after_stat->lost_frame_cnt - before_stat->lost_frame_cnt); + TEST_ASSERT_EQUAL_UINT32(BLE_LOG_FRAME_OVERHEAD + sizeof(uint32_t) + sizeof(marker), + after_stat->written_bytes_cnt - before_stat->written_bytes_cnt); + unsigned encode_slot = BLE_LOG_SRC_ENCODE - BLE_LOG_SRC_CORE_FIRST; + before_stat = &capture.snapshot[0].stats[encode_slot]; + after_stat = &capture.snapshot[last].stats[encode_slot]; + TEST_ASSERT_EQUAL_UINT32(1, after_stat->written_frame_cnt - before_stat->written_frame_cnt); + TEST_ASSERT_EQUAL_UINT32(1, after_stat->lost_frame_cnt - before_stat->lost_frame_cnt); + TEST_ASSERT_EQUAL_UINT32(BLE_LOG_FRAME_OVERHEAD + sizeof(uint32_t) + sizeof(marker), + after_stat->written_bytes_cnt - before_stat->written_bytes_cnt); +#if CONFIG_BLE_LOG_LL_ENABLED + unsigned ll_slot = BLE_LOG_SRC_LL_TASK - BLE_LOG_SRC_CORE_FIRST; + TEST_ASSERT_EQUAL_UINT32(BLE_LOG_FRAME_OVERHEAD + sizeof(marker), + capture.snapshot[last].stats[ll_slot].written_bytes_cnt - + capture.snapshot[0].stats[ll_slot].written_bytes_cnt); +#endif + + uint32_t previous_anchor = snapshot_anchor_count(&capture.snapshot[last]); + uint32_t previous_sn = capture.sn[last]; + ble_log_prph_test_set_auto_recycle_hook(auto_recycle_noop, NULL); + ble_log_flush(); + ble_log_prph_test_set_auto_recycle_hook(NULL, NULL); + capture.count = 0; + TEST_ASSERT_TRUE(ble_log_internal_snapshot( + BLE_LOG_SNAPSHOT_REASON_PERIODIC, &ts_info, true)); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT && !capture.count; i++) { + size_t len = ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), + pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0, NULL); + TEST_ASSERT_GREATER_THAN_size_t(0, len); + TEST_ASSERT_TRUE(test_ble_log_walk_frames(s_read_buf, len, capture_snapshot_loss, &capture)); + } + TEST_ASSERT_GREATER_THAN_INT(0, capture.count); + TEST_ASSERT_EQUAL_UINT32(0, capture.snapshot[0].stats[0].written_frame_cnt); + TEST_ASSERT_EQUAL_UINT32(0, capture.snapshot[0].stats[0].lost_frame_cnt); + TEST_ASSERT_EQUAL_UINT32(0, capture.snapshot[0].stats[0].written_bytes_cnt); + TEST_ASSERT_EQUAL_UINT32(0, capture.snapshot[0].stats[encode_slot].written_bytes_cnt); + uint32_t anchor_delta = (snapshot_anchor_count(&capture.snapshot[0]) - + previous_anchor) & 0x00ffffffU; + uint32_t sn_delta = (capture.sn[0] - previous_sn) & 0x00ffffffU; + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(2, anchor_delta); /* FLUSH + next sample */ + TEST_ASSERT_LESS_THAN_UINT32(0x00800000U, anchor_delta); + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(2, sn_delta); + TEST_ASSERT_LESS_OR_EQUAL_UINT32(anchor_delta, sn_delta); } #if CONFIG_BLE_LOG_LL_ENABLED