Mirrors/esp-idf
1
0
Fork 0
mirror of https://github.com/espressif/esp-idf.git synced 2026-10-01 18:50:34 +03:00
Code Issues Packages Projects Releases Wiki Activity

fix(ble_log): extend snapshot accounting and correct pool flushing

Browse Source 
Count successful frame bytes and share Global SN with snapshots.
Track snapshot attempts with a separate 24-bit anchor_count. Keep protocol v8.

Scan writer-held buffers during periodic flush and require a published FREE bit.
Keep UART0 periodic draining active when producers are disabled.
Document late pending-seal hints and update existing snapshot checks.
This commit is contained in:
guozifan
2026-09-10 15:39:56 +08:00
parent e3e3ac6541
commit 7a07b79fc6
8 changed files with 247 additions and 88 deletions
Download Patch File Download Diff File Expand all files Collapse all files
components/bt/common/ble_log/README.md
+51 -20
View File
@@ -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
components/bt/common/ble_log/src/ble_log_lbm_v2.c
+42 -24
View File
@@ -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
components/bt/common/ble_log/src/ble_log_task_registry.c
+1 -1
View File
@@ -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;
components/bt/common/ble_log/src/internal_include/ble_log_lbm_v2.h
+23 -19
View File
@@ -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");
components/bt/common/ble_log/src/internal_include/ble_log_prph.h
+3 -1
View File
@@ -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;
components/bt/common/ble_log/src/prph/ble_log_prph_uart_dma.c
+2 -2
View File
@@ -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;
}
components/bt/common/ble_log/test_apps/ble_log_test/README.md
+2 -1
View File
@@ -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.
components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c
+123 -20
View File
@@ -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