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): Add frame check support for restart flow

Browse Source 
(cherry picked from commit a81322a2ce)

Co-authored-by: guozifan <guozifan@espressif.com>
This commit is contained in:
Guo Zifan
2026-06-24 11:25:26 +08:00
parent 9b35fc0e81
commit a25fac6c71
6 changed files with 239 additions and 85 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -7,6 +7,14 @@ config BLE_LOG_ENABLED
Enable BT Log Async Output
if BLE_LOG_ENABLED
config BLE_LOG_LBM_AUTO_FLUSH
bool "Enable automatic BLE Log LBM buffer flush"
default n
help
Periodically flush partially-filled BLE Log LBM transport buffers
that remain pending, reducing latency for low-volume or
intermittent logging.
config BLE_LOG_TASK_STACK_SIZE
int "Stack size for BLE Log Task"
default 1024 if IDF_TARGET_ARCH_RISCV

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

@@ -80,7 +80,7 @@ void app_main() {
uint8_t data[] = {0x01, 0x02, 0x03, 0x04};
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, data, sizeof(data));
// Force flush buffers
// End session and flush buffers
ble_log_flush();
// Cleanup resources
@@ -178,9 +178,15 @@ Write hexadecimal log data.
#### `void ble_log_flush(void)`
Force flush all buffers and send pending logs immediately.
End the current logging session and flush pending logs immediately.
**Note**: This operation is blocking and will pause module operation until all buffers are cleared.
This API temporarily suspends ordinary log writes, waits for in-progress
writers to exit, emits a final statistics internal frame, flushes pending
transport buffers, resets statistics, and then restores the enable state that
was in effect before the call.
**Note**: This operation is blocking. If BLE Log was enabled before the call,
it remains enabled after the flush completes.
#### `void ble_log_dump_to_console(void)`
@@ -272,7 +278,7 @@ void example_basic_logging() {
uint8_t host_data[] = {0x02, 0x00, 0x20, 0x0B, 0x00, 0x07, 0x00, 0x04, 0x00, 0x10, 0x01, 0x00, 0xFF, 0xFF, 0x00, 0x28};
ble_log_write_hex(BLE_LOG_SRC_HOST, host_data, sizeof(host_data));
// Force send
// End session and flush buffers
ble_log_flush();
// Cleanup
@@ -334,6 +340,7 @@ void example_performance_test() {
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, test_data, sizeof(test_data));
}
// End session and flush buffers
ble_log_flush();
uint32_t end_time = esp_timer_get_time();

26
components/bt/common/ble_log/src/ble_log.c
View File

@@ -1,5 +1,5 @@
/*
* SPDX-FileCopyrightText: 2025 Espressif Systems (Shanghai) CO LTD
* SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
@@ -13,12 +13,22 @@
#include "ble_log_lbm.h"
#include "ble_log_prph.h"
#include "ble_log_util.h"
#include "esp_log.h"
#include "esp_system.h"
#if CONFIG_BLE_LOG_TS_ENABLED
#include "ble_log_ts.h"
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* VARIABLE */
#define TAG "ble_log"
BLE_LOG_STATIC bool ble_log_inited = false;
BLE_LOG_STATIC bool shutdown_handler_registered = false;
BLE_LOG_STATIC void ble_log_shutdown_handler(void)
{
ble_log_flush();
}
/* INTERFACE */
bool ble_log_init(void)
@@ -53,6 +63,12 @@ bool ble_log_init(void)
/* Initialization done */
ble_log_inited = true;
ble_log_enable(true);
esp_err_t ret = esp_register_shutdown_handler(ble_log_shutdown_handler);
if (ret == ESP_OK) {
shutdown_handler_registered = true;
} else {
ESP_LOGW(TAG, "Register shutdown handler failed, ret = 0x%x", ret);
}
/* Write initialization done log */
ble_log_info_t ble_log_info = {
@@ -69,6 +85,14 @@ exit:
void ble_log_deinit(void)
{
if (shutdown_handler_registered) {
esp_err_t ret = esp_unregister_shutdown_handler(ble_log_shutdown_handler);
if (ret == ESP_OK) {
shutdown_handler_registered = false;
} else {
ESP_LOGW(TAG, "Unregister shutdown handler failed, ret = 0x%x", ret);
}
}
ble_log_enable(false);
ble_log_inited = false;

250
components/bt/common/ble_log/src/ble_log_lbm.c
View File

@@ -11,15 +11,20 @@
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_rt.h"
#include "esp_log.h"
#if CONFIG_SOC_ESP_NIMBLE_CONTROLLER
#include "os/os_mbuf.h"
#endif /* CONFIG_SOC_ESP_NIMBLE_CONTROLLER */
/* VARIABLE */
#define TAG "ble_log"
#define BLE_LOG_LBM_WAIT_TIMEOUT_MS (1000)
BLE_LOG_STATIC volatile uint32_t lbm_ref_count = 0;
BLE_LOG_STATIC bool lbm_inited = false;
BLE_LOG_STATIC bool lbm_enabled = false;
BLE_LOG_STATIC volatile bool flush_in_progress = false;
BLE_LOG_STATIC ble_log_lbm_ctx_t *lbm_ctx = NULL;
BLE_LOG_STATIC ble_log_stat_mgr_t *stat_mgr_ctx[BLE_LOG_SRC_MAX] = {0};
@@ -30,10 +35,14 @@ bool ble_log_lbm_acquire_trans(size_t log_len, ble_log_lbm_t **out_lbm,
BLE_LOG_STATIC void ble_log_lbm_release(ble_log_lbm_t *lbm);
BLE_LOG_STATIC
ble_log_prph_trans_t **ble_log_lbm_get_trans(ble_log_lbm_t *lbm, size_t log_len);
BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void);
BLE_LOG_STATIC void ble_log_lbm_reset_stats(void);
BLE_LOG_STATIC
void ble_log_lbm_write_trans(ble_log_prph_trans_t **trans, ble_log_src_t src_code,
const uint8_t *addr, uint16_t len,
const uint8_t *addr_append, uint16_t len_append, bool omdata);
BLE_LOG_STATIC
bool ble_log_write_hex_core(ble_log_src_t src_code, const uint8_t *addr, size_t len);
#if BLE_LOG_UART_REDIR_ENABLED
BLE_LOG_STATIC
void ble_log_lbm_stream_seal(ble_log_prph_trans_t **trans, ble_log_src_t src_code);
@@ -110,6 +119,66 @@ void ble_log_lbm_release(ble_log_lbm_t *lbm)
}
}
BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void)
{
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
bool in_progress;
TickType_t start_tick = xTaskGetTickCount();
/* Queue transports with logs */
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
int trans_idx = lbm->trans_idx;
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = &(lbm->trans[trans_idx]);
if (!__atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE) &&
(*trans)->pos) {
ble_log_rt_queue_trans(trans);
}
trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
}
/* Wait for transportation to finish */
do {
in_progress = false;
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = &(lbm->trans[j]);
in_progress |= __atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE);
}
}
if (in_progress) {
if ((xTaskGetTickCount() - start_tick) >=
pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log transports");
return false;
}
vTaskDelay(1);
}
} while (in_progress);
return true;
}
BLE_LOG_STATIC void ble_log_lbm_reset_stats(void)
{
ble_log_lbm_t *lbm;
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
BLE_LOG_MEMSET(stat_mgr_ctx[i], 0, sizeof(ble_log_stat_mgr_t));
}
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
__atomic_store_n(&lbm->trans_inflight, 0, __ATOMIC_RELAXED);
__atomic_store_n(&lbm->trans_inflight_peak, 0, __ATOMIC_RELAXED);
}
ble_log_prph_reset_util_counters();
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_lbm_write_trans(ble_log_prph_trans_t **trans, ble_log_src_t src_code,
const uint8_t *addr, uint16_t len,
@@ -203,6 +272,35 @@ void ble_log_stat_mgr_update(ble_log_src_t src_code, uint32_t len, bool lost)
}
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
bool ble_log_write_hex_core(ble_log_src_t src_code, const uint8_t *addr, size_t len)
{
/* Get transport from the best available pool */
size_t payload_len = len + sizeof(uint32_t);
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
if (!ble_log_lbm_acquire_trans(payload_len, &lbm, &trans)) {
goto failed;
}
/* Write transport */
uint32_t os_ts = pdTICKS_TO_MS(BLE_LOG_IN_ISR()?
xTaskGetTickCountFromISR():
xTaskGetTickCount());
ble_log_lbm_write_trans(trans, src_code, (const uint8_t *)&os_ts,
sizeof(uint32_t), addr, len, false);
/* Release */
ble_log_lbm_release(lbm);
return true;
failed:
if (lbm_inited) {
ble_log_stat_mgr_update(src_code, payload_len, true);
}
return false;
}
/* -------------------------- */
/* INTERNAL INTERFACE */
/* -------------------------- */
@@ -289,10 +387,15 @@ void ble_log_lbm_deinit(void)
lbm_enabled = false;
/* Disable module and wait for all references to be released */
uint32_t time_waited = 0;
TickType_t start_tick = xTaskGetTickCount();
while (__atomic_load_n(&lbm_ref_count, __ATOMIC_ACQUIRE) > 0) {
vTaskDelay(pdMS_TO_TICKS(1));
BLE_LOG_ASSERT(time_waited++ < 1000);
if ((xTaskGetTickCount() - start_tick) >=
pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log references during deinit");
}
BLE_LOG_ASSERT((xTaskGetTickCount() - start_tick) <
pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS));
vTaskDelay(1);
}
/* Release statistic manager context */
@@ -501,6 +604,33 @@ deref:
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
}
void ble_log_write_final_stat(void)
{
BLE_LOG_REF_COUNT_ACQUIRE(&lbm_ref_count);
if (!lbm_inited) {
goto deref;
}
ble_log_final_stat_t final_stat;
final_stat.int_src_code = BLE_LOG_INT_SRC_FINAL_STAT;
final_stat.src_cnt = BLE_LOG_SRC_MAX;
BLE_LOG_ENTER_CRITICAL();
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
ble_log_final_stat_entry_t *entry = &final_stat.entries[i];
entry->src_code = i;
BLE_LOG_MEMCPY(&entry->written_frame_cnt,
&stat_mgr_ctx[i]->written_frame_cnt,
4 * sizeof(uint32_t));
}
BLE_LOG_EXIT_CRITICAL();
ble_log_write_internal((const uint8_t *)&final_stat, sizeof(final_stat));
deref:
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
}
/* ------------------------ */
/* PUBLIC INTERFACE */
/* ------------------------ */
@@ -518,7 +648,6 @@ void ble_log_flush(void)
/* Prevent concurrent flush — two concurrent callers would deadlock on
* the ref_count spin-wait (both hold a ref, both wait for ref_count <= 1).
* Second caller returns immediately instead of deadlocking. */
static volatile bool flush_in_progress = false;
if (__atomic_test_and_set(&flush_in_progress, __ATOMIC_ACQUIRE)) {
return;
}
@@ -527,8 +656,6 @@ void ble_log_flush(void)
if (!lbm_inited) {
goto deref;
}
/* Write enhanced statistics before module disable */
ble_log_write_enh_stat();
ble_log_write_buf_util();
@@ -541,64 +668,32 @@ void ble_log_flush(void)
/* Disable module and wait for all other references to release */
bool lbm_enabled_copy = lbm_enabled;
lbm_enabled = false;
uint32_t time_waited = 0;
TickType_t start_tick = xTaskGetTickCount();
while (__atomic_load_n(&lbm_ref_count, __ATOMIC_ACQUIRE) > 1) {
vTaskDelay(pdMS_TO_TICKS(1));
BLE_LOG_ASSERT(time_waited++ < 1000);
}
/* Queue transports with logs */
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
/* Flush pools */
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
int trans_idx = lbm->trans_idx;
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = &(lbm->trans[trans_idx]);
if (!__atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE) &&
(*trans)->pos) {
ble_log_rt_queue_trans(trans);
}
trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
if ((xTaskGetTickCount() - start_tick) >=
pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log writers");
goto fail;
}
vTaskDelay(1);
}
/* Wait for transportation to finish */
time_waited = 0;
bool in_progress;
do {
in_progress = false;
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = &(lbm->trans[j]);
in_progress |= __atomic_load_n(&(*trans)->prph_owned, __ATOMIC_ACQUIRE);
}
}
if (in_progress) {
vTaskDelay(pdMS_TO_TICKS(1));
BLE_LOG_ASSERT(time_waited++ < 1000);
}
} while (in_progress);
/* Reset statistics manager after all operations complete */
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
BLE_LOG_MEMSET(stat_mgr_ctx[i], 0, sizeof(ble_log_stat_mgr_t));
if (!ble_log_lbm_flush_all_trans()) {
goto fail;
}
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
__atomic_store_n(&lbm->trans_inflight, 0, __ATOMIC_RELAXED);
__atomic_store_n(&lbm->trans_inflight_peak, 0, __ATOMIC_RELAXED);
}
ble_log_prph_reset_util_counters();
ble_log_write_final_stat();
/* Resume enable status */
if (!ble_log_lbm_flush_all_trans()) {
goto fail;
}
ble_log_lbm_reset_stats();
fail:
/* Resume enable status after a completed or failed flush. */
lbm_enabled = lbm_enabled_copy;
deref:
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
__atomic_clear(&flush_in_progress, __ATOMIC_RELEASE);
@@ -607,38 +702,33 @@ deref:
BLE_LOG_IRAM_ATTR
bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len)
{
bool ret = false;
BLE_LOG_REF_COUNT_ACQUIRE(&lbm_ref_count);
if (!lbm_enabled) {
goto exit;
}
/* Get transport from the best available pool */
size_t payload_len = len + sizeof(uint32_t);
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
if (!ble_log_lbm_acquire_trans(payload_len, &lbm, &trans)) {
goto failed;
}
/* Write transport */
uint32_t os_ts = pdTICKS_TO_MS(BLE_LOG_IN_ISR()?
xTaskGetTickCountFromISR():
xTaskGetTickCount());
ble_log_lbm_write_trans(trans, src_code, (const uint8_t *)&os_ts,
sizeof(uint32_t), addr, len, false);
/* Release */
ble_log_lbm_release(lbm);
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return true;
failed:
if (lbm_inited) {
ble_log_stat_mgr_update(src_code, payload_len, true);
}
ret = ble_log_write_hex_core(src_code, addr, len);
exit:
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return false;
return ret;
}
BLE_LOG_IRAM_ATTR
bool ble_log_write_internal(const uint8_t *addr, size_t len)
{
bool ret = false;
BLE_LOG_REF_COUNT_ACQUIRE(&lbm_ref_count);
if (!lbm_inited) {
goto exit;
}
ret = ble_log_write_hex_core(BLE_LOG_SRC_INTERNAL, addr, len);
exit:
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return ret;
}
#if CONFIG_BLE_LOG_LL_ENABLED

24
components/bt/common/ble_log/src/internal_include/ble_log_lbm.h
View File

@@ -13,6 +13,7 @@
/* ---------------- */
/* Includes */
/* ---------------- */
#include "ble_log.h"
#include "ble_log_prph.h"
#include "freertos/FreeRTOS.h"
@@ -174,6 +175,25 @@ typedef struct {
uint32_t lost_bytes_cnt;
} __attribute__((packed)) ble_log_enh_stat_t;
/* -------------------------------- */
/* Final Statistics Defines */
/* -------------------------------- */
typedef struct {
uint8_t src_code;
uint32_t written_frame_cnt;
uint32_t lost_frame_cnt;
uint32_t written_bytes_cnt;
uint32_t lost_bytes_cnt;
} __attribute__((packed)) ble_log_final_stat_entry_t;
typedef struct {
uint8_t int_src_code;
uint8_t src_cnt;
ble_log_final_stat_entry_t entries[BLE_LOG_SRC_MAX];
} __attribute__((packed)) ble_log_final_stat_t;
#define BLE_LOG_FINAL_STAT_LEN sizeof(ble_log_final_stat_t)
/* -------------------------------------- */
/* Log Statistics Manager Context */
/* -------------------------------------- */
@@ -220,6 +240,8 @@ _Static_assert(CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE % BLE_LOG_TRANS_BUF_CNT == 0
#endif
_Static_assert(CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE / BLE_LOG_TRANS_BUF_CNT >= BLE_LOG_FRAME_OVERHEAD,
"Common LBM per-buffer size too small for a single frame");
_Static_assert(BLE_LOG_TRANS_SIZE >= BLE_LOG_FINAL_STAT_LEN + sizeof(uint32_t) + BLE_LOG_FRAME_OVERHEAD,
"Common LBM per-buffer size too small for final statistics frame");
_Static_assert((BLE_LOG_TRANS_BUF_CNT & (BLE_LOG_TRANS_BUF_CNT - 1)) == 0,
"BLE_LOG_TRANS_BUF_CNT must be a power of 2");
_Static_assert(1 + BLE_LOG_LBM_ATOMIC_TASK_CNT <= 16,
@@ -235,6 +257,8 @@ _Static_assert(BLE_LOG_TRANS_BUF_CNT <= 255,
bool ble_log_lbm_init(void);
void ble_log_lbm_deinit(void);
void ble_log_lbm_enable(bool enable);
bool ble_log_write_internal(const uint8_t *addr, size_t len);
void ble_log_write_final_stat(void);
void ble_log_write_enh_stat(void);
void ble_log_write_buf_util(void);
#if BLE_LOG_UART_REDIR_ENABLED

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

@@ -144,6 +144,7 @@ typedef enum {
BLE_LOG_INT_SRC_INFO,
BLE_LOG_INT_SRC_FLUSH,
BLE_LOG_INT_SRC_BUF_UTIL,
BLE_LOG_INT_SRC_FINAL_STAT,
BLE_LOG_INT_SRC_MAX,
} ble_log_int_src_t;