From fdf4942485f2334ad1d1e78c1a892eca3b371e23 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Wed, 2 Sep 2026 14:35:48 +0800 Subject: [PATCH] feat(ble_log): add periodic auto flush with pending-seal handoff Partially-filled OPEN transports previously waited for a capacity seal or an explicit ble_log_flush(); an app that never calls flush loses the parked frames at test end. Three triggers now cover the gap: - The periodic output tick (the TS trigger, or the runtime hook when TS is disabled) flushes OPEN transports ahead of the periodic snapshot. The flusher never waits for a lock: a transport whose lock is held is left a pending-seal marker instead. - The next claim that takes the transport lock sees the marker and seals the buffered frames before scanning on for another transport; if no writer ever returns, the next periodic pass seals the transport uncontended. - ble_log_deinit() drains the remaining OPEN transports after the writer gate closes and before the runtime queue is destroyed; the peripheral deinit wait completes the delivery. The marker is cleared by seal_and_send (the choke point of every seal path), by the direct FREE return in ble_log_commit's error path, and on recycle, so it never survives a transport lifecycle. The full-barrier ble_log_flush() semantics are unchanged. Tests cover the pending-seal handoff (claim-locked flush hook), the deinit drain of a parked sub-capacity burst, and the real ble_log_deinit() path through the auto-recycle hook. --- components/bt/common/ble_log/src/ble_log.c | 9 +- .../bt/common/ble_log/src/ble_log_lbm_v2.c | 63 +++++- components/bt/common/ble_log/src/ble_log_rt.c | 13 +- .../src/internal_include/ble_log_lbm_v2.h | 6 + .../src/internal_include/ble_log_prph.h | 6 + .../ble_log_test/main/test_ble_log_rt.c | 186 ++++++++++++++++++ 6 files changed, 279 insertions(+), 4 deletions(-) diff --git a/components/bt/common/ble_log/src/ble_log.c b/components/bt/common/ble_log/src/ble_log.c index d434effc624..81dc6690dbd 100644 --- a/components/bt/common/ble_log/src/ble_log.c +++ b/components/bt/common/ble_log/src/ble_log.c @@ -90,11 +90,18 @@ void ble_log_deinit(void) ble_log_inited = false; ble_log_lbm_begin_deinit(); + /* Residual frames parked in OPEN transports would be discarded with + * the pool. Seal and dispatch them while the runtime queue is still + * alive; the peripheral deinit wait below completes the delivery. */ + ble_log_lbm_drain_open_transports(); + /* CRITICAL - Deinit ordering rationale: * * 1. The LBM writer gate is closed before submodule teardown. Writers * already inside the gate keep a reference until they finish; later - * writers are rejected. + * writers are rejected. With writers gone, the deinit drain seals + * the remaining OPEN transports and hands them to the runtime + * queue, so residual frames are not discarded with the pool. * * 2. Runtime dispatch must be stopped FIRST to prevent it from sending * transports to an already-destroyed peripheral driver. Active 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 b7bc01735e3..c17264de38d 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 @@ -97,6 +97,7 @@ BLE_LOG_STATIC ble_log_internal_snapshot_t internal_snapshot; extern void ble_log_test_claim_pre_publish_hook(void) __attribute__((weak)); extern void ble_log_test_enable_before_lifecycle_lock_hook(void) __attribute__((weak)); extern void ble_log_test_disable_before_wake_hook(void) __attribute__((weak)); +extern void ble_log_test_claim_locked_hook(void) __attribute__((weak)); #endif BLE_LOG_IRAM_ATTR BLE_LOG_STATIC @@ -217,6 +218,9 @@ BLE_LOG_STATIC void ble_log_pool_wake_all(void) 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. */ + BLE_LOG_ATOMIC_STORE_RELAXED(trans->pending_seal, false); if (trans->owner_kind == BLE_LOG_TRANS_OWNER_INTERNAL) { BLE_LOG_ATOMIC_STORE_RELEASE(trans->state, BLE_LOG_TRANS_STATE_FREE); @@ -245,6 +249,10 @@ BLE_LOG_IRAM_ATTR void ble_log_lbm_recycle_trans(ble_log_prph_trans_t *trans) /* -------------------------------------- */ BLE_LOG_IRAM_ATTR void ble_log_pool_seal_and_send(ble_log_prph_trans_t *trans) { + /* Consumes any pending-seal marker: every seal path (capacity, claim, + * periodic flush, full drain) funnels through here while holding the + * lock. */ + BLE_LOG_ATOMIC_STORE_RELAXED(trans->pending_seal, false); BLE_LOG_ATOMIC_STORE_RELAXED(trans->state, BLE_LOG_TRANS_STATE_SENDING); /* A claimed buffer is already absent from free_bitmap. Remove any OPEN * hint before releasing the SENDING buffer to the runtime task. */ @@ -290,7 +298,11 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_from(volatile uint32_t *bitmap, } if (expected_state == BLE_LOG_TRANS_STATE_OPEN && - BLE_LOG_TRANS_FREE_SPACE(trans) < frame_len) { + (BLE_LOG_TRANS_FREE_SPACE(trans) < frame_len || + BLE_LOG_ATOMIC_LOAD_ACQUIRE(trans->pending_seal))) { + /* No room for this frame, or a periodic flush left a + * pending-seal marker while the transport was busy: send the + * buffered frames and scan on for another transport. */ ble_log_pool_seal_and_send(trans); /* releases the lock */ continue; } @@ -324,7 +336,19 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_available(uint32_t frame_len, bool ble_log_prph_trans_t *open_trans = g_pool.trans[open_id]; if (BLE_LOG_CAS_ACQUIRE(&open_trans->atomic_lock)) { if (BLE_LOG_ATOMIC_LOAD_RELAXED(open_trans->state) == BLE_LOG_TRANS_STATE_OPEN) { - if (BLE_LOG_TRANS_FREE_SPACE(open_trans) >= frame_len) { + /* A pending-seal marker left by a periodic flush that lost + * the lock race sends the buffered frames first; this claim + * continues with another transport below. */ + if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(open_trans->pending_seal) && + BLE_LOG_TRANS_FREE_SPACE(open_trans) >= frame_len) { +#if CONFIG_BLE_LOG_PRPH_TEST + /* Test point: the transport is locked and still listed + * in open_bitmap, mirroring an in-progress writer for a + * concurrent flush attempt. */ + if (ble_log_test_claim_locked_hook) { + ble_log_test_claim_locked_hook(); + } +#endif ble_log_pool_bitmap_clear(&g_pool.open_bitmap, open_id); return open_trans; } @@ -532,6 +556,9 @@ void ble_log_commit(uint32_t handle, size_t actual_len) if (actual_len == 0 || actual_len > claim->max_len) { ble_log_stat_mgr_mark_lost(src_code); if (trans->pos == 0) { + /* Returning straight to FREE bypasses seal_and_send: also drop + * any pending-seal marker here. */ + BLE_LOG_ATOMIC_STORE_RELAXED(trans->pending_seal, false); BLE_LOG_ATOMIC_STORE_RELEASE(trans->state, BLE_LOG_TRANS_STATE_FREE); ble_log_pool_bitmap_set(&g_pool.free_bitmap, trans->id); BLE_LOG_CAS_RELEASE(&trans->atomic_lock); @@ -610,6 +637,7 @@ bool ble_log_lbm_init(void) g_pool.trans[id]->owner_kind = BLE_LOG_TRANS_OWNER_POOL; g_pool.trans[id]->state = BLE_LOG_TRANS_STATE_FREE; g_pool.trans[id]->atomic_lock = 0; + g_pool.trans[id]->pending_seal = 0; } if (!ble_log_prph_trans_init(&internal_trans, BLE_LOG_INTERNAL_TRANS_SIZE)) { @@ -826,6 +854,12 @@ void ble_log_lbm_flush_open_transports(void) } ble_log_prph_trans_t *trans = g_pool.trans[id]; if (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) { + /* A writer holds the buffer: leave a pending-seal marker for + * the next claim instead of waiting (the flusher never + * competes for a lock). The marker is serviced by the next + * writer on this transport, or by the next periodic pass once + * the lock is uncontended. */ + BLE_LOG_ATOMIC_STORE_RELEASE(trans->pending_seal, true); continue; } if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) == BLE_LOG_TRANS_STATE_OPEN && @@ -839,6 +873,31 @@ void ble_log_lbm_flush_open_transports(void) BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count); } +void ble_log_lbm_drain_open_transports(void) +{ + /* Contract (see header): called after ble_log_lbm_begin_deinit() and + * before ble_log_rt_deinit(). The producer gate is closed and writers + * have drained, so no lock is held for longer than one frame copy. */ + for (int id = 0; id < BLE_LOG_POOL_TRANS_CNT; id++) { + if (!(BLE_LOG_ATOMIC_LOAD_ACQUIRE(g_pool.open_bitmap) & BIT(id))) { + continue; + } + ble_log_prph_trans_t *trans = g_pool.trans[id]; + while (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) { + } + if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) == BLE_LOG_TRANS_STATE_OPEN && + trans->pos > 0) { + ble_log_pool_seal_and_send(trans); /* releases the lock */ + } else { + BLE_LOG_CAS_RELEASE(&trans->atomic_lock); + } + } + + /* Hand the sealed buffers to the peripheral before the runtime queue + * is destroyed; the peripheral deinit wait completes the delivery. */ + (void)ble_log_rt_drain(); +} + /* ------------------------ */ /* PUBLIC INTERFACE */ /* ------------------------ */ diff --git a/components/bt/common/ble_log/src/ble_log_rt.c b/components/bt/common/ble_log/src/ble_log_rt.c index d6ed9ea8571..72d00f77edd 100644 --- a/components/bt/common/ble_log/src/ble_log_rt.c +++ b/components/bt/common/ble_log/src/ble_log_rt.c @@ -127,6 +127,10 @@ BLE_LOG_STATIC void ble_log_rt_run_hook(void) return; } rt_last_hook_os_ts = now; + /* 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. */ + ble_log_lbm_flush_open_transports(); (void)ble_log_internal_snapshot(BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false); } @@ -178,7 +182,14 @@ BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg) } ble_log_ts_info_t ts_info; - if (ble_log_ts_info_update(&ts_info)) { + bool ts_valid = ble_log_ts_info_update(&ts_info); + + /* 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. */ + ble_log_lbm_flush_open_transports(); + + if (ts_valid) { (void)ble_log_internal_snapshot( BLE_LOG_SNAPSHOT_REASON_PERIODIC | BLE_LOG_SNAPSHOT_REASON_TS_VALID, 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 5754bd8259e..90eabec255b 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 @@ -219,6 +219,12 @@ void ble_log_lbm_begin_deinit(void); void ble_log_lbm_deinit(void); bool ble_log_lbm_is_enabled(void); void ble_log_lbm_flush_open_transports(void); +/* Deinit drain: seal every OPEN transport and dispatch it to the runtime + * queue. Contract: called after ble_log_lbm_begin_deinit() (producer gate + * closed, writers drained) and before ble_log_rt_deinit(); every transport + * lock is then uncontended. The peripheral deinit wait completes the + * delivery of the dispatched buffers. */ +void ble_log_lbm_drain_open_transports(void); void ble_log_lbm_recycle_trans(ble_log_prph_trans_t *trans); void ble_log_internal_set_version_info(const ble_log_version_info_t *version_info); bool ble_log_internal_snapshot(uint16_t reason_flags, 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 801445bae69..8d881ccd9d9 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 @@ -42,6 +42,12 @@ typedef struct { uint8_t id; uint8_t owner_kind; + /* 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. */ + volatile uint8_t pending_seal; + uint8_t *buf; uint16_t size; uint16_t pos; 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 9fb3d2167d6..daee52f5da1 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 @@ -57,6 +57,7 @@ typedef struct { static uint8_t s_read_buf[TEST_READ_BUF_SIZE]; static bool s_claim_hook_armed; static uint32_t s_stale_claim_handle; +static volatile bool s_locked_hook_armed; static volatile bool s_enable_hook_armed; static SemaphoreHandle_t s_enable_hook_entered; static SemaphoreHandle_t s_enable_hook_continue; @@ -70,6 +71,7 @@ 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); 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 @@ -88,6 +90,17 @@ void ble_log_test_claim_pre_publish_hook(void) } } +void ble_log_test_claim_locked_hook(void) +{ + if (s_locked_hook_armed) { + s_locked_hook_armed = false; + /* Runs while the claiming writer itself holds the OPEN transport + * lock: the flush must skip the busy transport and leave the + * pending-seal marker for the next claim. */ + ble_log_lbm_flush_open_transports(); + } +} + void ble_log_test_enable_before_lifecycle_lock_hook(void) { if (s_enable_hook_armed) { @@ -812,6 +825,179 @@ TEST_CASE("BLE Log flush preserves source-local sequence continuity", TEST_ASSERT_EQUAL_HEX32((before.sn + 1) & 0x00ffffffU, after.sn); } +/* ------- pending-seal and deinit drain ------- */ + +#define TEST_MARKER_CHUNK_MAX (4) + +typedef struct { + uint8_t markers[TEST_MARKER_CHUNK_MAX]; + int count; +} marker_chunk_capture_t; + +static void capture_custom_marker(const test_ble_log_frame_t *frame, void *ctx) +{ + marker_chunk_capture_t *capture = ctx; + if (frame->src == BLE_LOG_SRC_CUSTOM && + frame->payload_len == sizeof(uint32_t) + 1 && + capture->count < TEST_MARKER_CHUNK_MAX) { + capture->markers[capture->count++] = frame->payload[sizeof(uint32_t)]; + } +} + +/* Reads every pending transport chunk, keeping only the chunks that carry + * CUSTOM marker frames; interleaved snapshot transports are consumed and + * ignored. */ +static int read_marker_chunks(marker_chunk_capture_t *chunks, int max_chunks) +{ + int marker_chunks = 0; + 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), + 0, NULL); + if (!len) { + break; + } + marker_chunk_capture_t chunk = {0}; + TEST_ASSERT_TRUE(test_ble_log_walk_frames(s_read_buf, len, + capture_custom_marker, + &chunk)); + if (chunk.count && marker_chunks < max_chunks) { + chunks[marker_chunks++] = chunk; + } + } + return marker_chunks; +} + +static void auto_recycle_count(void *ctx) +{ + (*(int *)ctx)++; +} + +TEST_CASE("BLE Log pending-seal marker defers the busy transport flush", + "[ble_log][lbm]") +{ + const uint8_t first_marker = 0xd1; + const uint8_t cursor_marker = 0xd2; + const uint8_t hooked_marker = 0xd3; + const uint8_t post_marker = 0xd4; + + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + 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) { + } + } + + /* Park one frame in an OPEN transport; the claim cursor stays on it. */ + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &first_marker, sizeof(first_marker))); + + /* A prior test may leave open_cursor at any recycled transport. Prime + * it through either the direct path or the OPEN bitmap scan before + * arming the direct-path hook. */ + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &cursor_marker, sizeof(cursor_marker))); + + /* The armed hook runs a flush while the claiming writer itself holds + * the transport lock: the flush must skip the busy transport and leave + * the pending-seal marker for the NEXT claim. */ + s_locked_hook_armed = true; + bool hooked_write = ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &hooked_marker, + sizeof(hooked_marker)); + bool hook_ran = !s_locked_hook_armed; + s_locked_hook_armed = false; + TEST_ASSERT_TRUE(hooked_write); + TEST_ASSERT_TRUE(hook_ran); + + /* The next writer must seal the flagged transport first and place its + * own frame in another one. */ + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &post_marker, sizeof(post_marker))); + + ble_log_lbm_flush_open_transports(); + TEST_ASSERT_TRUE(ble_log_rt_drain()); + + marker_chunk_capture_t chunks[2] = {0}; + TEST_ASSERT_EQUAL(2, read_marker_chunks(chunks, 2)); + TEST_ASSERT_EQUAL(3, chunks[0].count); + TEST_ASSERT_EQUAL_HEX8(first_marker, chunks[0].markers[0]); + TEST_ASSERT_EQUAL_HEX8(cursor_marker, chunks[0].markers[1]); + TEST_ASSERT_EQUAL_HEX8(hooked_marker, chunks[0].markers[2]); + TEST_ASSERT_EQUAL(1, chunks[1].count); + TEST_ASSERT_EQUAL_HEX8(post_marker, chunks[1].markers[0]); +} + +TEST_CASE("BLE Log deinit drain delivers parked open transports", + "[ble_log][lbm]") +{ + const uint8_t markers[TEST_MARKER_CHUNK_MAX] = {0xe1, 0xe2, 0xe3, 0xe4}; + + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + 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) { + } + } + + /* Sub-capacity burst: frames park in an OPEN transport that no + * capacity seal ever sends. */ + for (int i = 0; i < TEST_MARKER_CHUNK_MAX; i++) { + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &markers[i], 1)); + } + + /* Exercise the exact deinit-drain contract: close the producer gate and + * wait for writers before sealing every OPEN transport. */ + ble_log_lbm_begin_deinit(); + ble_log_lbm_drain_open_transports(); + + marker_chunk_capture_t chunks[1] = {0}; + int chunk_count = read_marker_chunks(chunks, 1); + + /* Finish the partially-entered teardown and restore the module before + * assertions so the following Unity case starts from a valid lifetime. */ + ble_log_deinit(); + TEST_ASSERT_TRUE(ble_log_init()); + + TEST_ASSERT_EQUAL(1, chunk_count); + TEST_ASSERT_EQUAL(TEST_MARKER_CHUNK_MAX, chunks[0].count); + for (int i = 0; i < TEST_MARKER_CHUNK_MAX; i++) { + TEST_ASSERT_EQUAL_HEX8(markers[i], chunks[0].markers[i]); + } +} + +TEST_CASE("BLE Log deinit hands residual transports to the peripheral", + "[ble_log][lbm]") +{ + const uint8_t marker = 0xf1; + int recycled = 0; + + TEST_ASSERT_TRUE(ble_log_enable(true)); + ble_log_lbm_flush_open_transports(); + 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) { + } + } + + TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, + &marker, sizeof(marker))); + + /* Auto-recycle turns every dispatched transport into a countable + * event, so the real deinit path is observable without a reader + * task racing the teardown. */ + ble_log_prph_test_set_auto_recycle_hook(auto_recycle_count, &recycled); + ble_log_deinit(); + TEST_ASSERT_GREATER_OR_EQUAL(1, recycled); + TEST_ASSERT_TRUE(ble_log_init()); +} + #define SNAPSHOT_CAPTURE_MAX 8 typedef struct {