From c0f77d89933a5d84a986e8ed5c00f4362b927a0f Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:15 +0800 Subject: [PATCH 01/16] feat(ble): optimized macros readability (cherry picked from commit f8699785e9d177e9de6b9b1db73dab533f1e5bb3) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 258 ++++++++++-------- .../ble_log/include/ble_log/ble_log_spi_out.h | 44 +-- 2 files changed, 168 insertions(+), 134 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 5409ac9196..e78d4f7244 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -7,29 +7,46 @@ #if CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED -// Private defines -#define BLE_LOG_TAG "BLE_LOG" -#define SPI_OUT_BUS SPI2_HOST -#define SPI_OUT_MAX_TRANSFER_SIZE 10240 -#define SPI_OUT_FRAME_HEAD_LEN 4 -#define SPI_OUT_FRAME_TAIL_LEN 4 -#define SPI_OUT_FRAME_OVERHEAD (SPI_OUT_FRAME_HEAD_LEN + SPI_OUT_FRAME_TAIL_LEN) -#define SPI_OUT_RECYCLE_TIMEOUT_MS 10 -#define SPI_OUT_TRANS_CB_FLAG_AVAILABLE 0 -#define SPI_OUT_TRANS_CB_FLAG_NEED_QUEUE 1 -#define SPI_OUT_TRANS_CB_FLAG_IN_QUEUE 2 -#define SPI_OUT_FLUSHOUT_TIMEOUT (CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT * 1000) -#define SPI_OUT_PACKET_LOSS_UL 0 -#define SPI_OUT_PACKET_LOSS_LL_TASK 1 -#define SPI_OUT_PACKET_LOSS_LL_ISR 2 -#define SPI_OUT_PACKET_LOSS_FRAME_SIZE 6 -#define SPI_OUT_INTERFACE_FLAG_IN_ISR (1 << 3) -#define SPI_OUT_TRANS_ITVL_MIN_US 30 -#define SPI_OUT_SPI_MASTER_QUEUE_SIZE 6 +// sdkconfig defines +#define SPI_OUT_UL_TASK_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_UL_TASK_BUF_SIZE +#define SPI_OUT_LL_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#define SPI_OUT_LL_TASK_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LL_TASK_BUF_SIZE +#define SPI_OUT_LL_ISR_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LL_ISR_BUF_SIZE +#define SPI_OUT_MOSI_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_MOSI_IO_NUM +#define SPI_OUT_SCLK_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_SCLK_IO_NUM +#define SPI_OUT_CS_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_CS_IO_NUM +#define SPI_OUT_TS_SYNC_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#define SPI_OUT_SYNC_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM +#define SPI_OUT_FLUSH_TIMER_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#define SPI_OUT_FLUSH_TIMEOUT_US (CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT * 1000) -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED -#define SPI_OUT_TS_SYNC_TIMEOUT (1000 * 1000) -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +// Private defines +#define BLE_LOG_TAG "BLE_LOG" +#define SPI_OUT_BUS SPI2_HOST +#define SPI_OUT_MAX_TRANSFER_SIZE (10240) +#define SPI_OUT_FRAME_HEAD_LEN (4) +#define SPI_OUT_FRAME_TAIL_LEN (4) +#define SPI_OUT_FRAME_OVERHEAD (8) +#define SPI_OUT_PACKET_LOSS_FRAME_SIZE (6) +#define SPI_OUT_INTERFACE_FLAG_IN_ISR (1 << 3) +#define SPI_OUT_TRANS_ITVL_MIN_US (30) + +#if SPI_OUT_TS_SYNC_ENABLED +#define SPI_OUT_TS_SYNC_TIMEOUT (1000 * 1000) +#endif // SPI_OUT_TS_SYNC_ENABLED + +// Queue size defines +#define SPI_OUT_PING_PONG_BUF_CNT (2) +#define SPI_OUT_UL_QUEUE_SIZE (SPI_OUT_PING_PONG_BUF_CNT) + +#if SPI_OUT_LL_ENABLED +#define SPI_OUT_LL_QUEUE_SIZE (3 * SPI_OUT_PING_PONG_BUF_CNT) +#else +#define SPI_OUT_LL_QUEUE_SIZE (0) +#endif // SPI_OUT_LL_ENABLED + +#define SPI_OUT_SPI_MASTER_QUEUE_SIZE (SPI_OUT_UL_QUEUE_SIZE +\ + SPI_OUT_LL_QUEUE_SIZE) // Private typedefs typedef struct { @@ -49,6 +66,19 @@ typedef struct { uint8_t trans_loss_cnt; } spi_out_log_cb_t; +// Private enums +enum { + TRANS_CB_FLAG_AVAILABLE = 0, + TRANS_CB_FLAG_NEED_QUEUE, + TRANS_CB_FLAG_IN_QUEUE, +}; + +enum { + LOG_CB_TYPE_UL = 0, + LOG_CB_TYPE_LL_TASK, + LOG_CB_TYPE_LL_ISR, +}; + // Private variables static bool spi_out_inited = false; static spi_device_handle_t spi_handle = NULL; @@ -57,24 +87,24 @@ static uint32_t last_tx_done_ts = 0; static bool ul_log_inited = false; static SemaphoreHandle_t ul_log_mutex = NULL; static spi_out_log_cb_t *ul_log_cb = NULL; -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED static esp_timer_handle_t ul_log_flushout_timer = NULL; -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED static bool ll_log_inited = false; static spi_out_log_cb_t *ll_task_log_cb = NULL; static spi_out_log_cb_t *ll_isr_log_cb = NULL; -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED static esp_timer_handle_t ll_log_flushout_timer = NULL; -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_LL_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED static bool ts_sync_inited = false; static bool sync_io_level = false; static esp_timer_handle_t ts_sync_timer = NULL; -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED // Extern function declarations extern void esp_panic_handler_feed_wdts(void); @@ -97,17 +127,17 @@ static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); static int spi_out_ul_log_init(void); static void spi_out_ul_log_deinit(void); -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED static void esp_timer_cb_ul_log_flushout(void); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); static void spi_out_ll_log_deinit(void); static void spi_out_ll_log_ev_proc(void); -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED static void esp_timer_cb_ll_log_flushout(void); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED #if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\ defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) @@ -120,9 +150,9 @@ extern void ble_log_simple_put_ev(void); #define BLE_LOG_LL_PUT_EV #endif -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_LL_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED static int spi_out_ts_sync_init(void); static void spi_out_ts_sync_deinit(void); static void esp_timer_cb_ts_sync(void); @@ -138,7 +168,7 @@ extern uint32_t r_os_cputime_get32(void); #define SPI_OUT_GET_LC_TIME 0 #endif -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) @@ -183,7 +213,7 @@ IRAM_ATTR static void spi_out_tx_done_cb(spi_transaction_t *ret_trans) last_tx_done_ts = esp_timer_get_time(); spi_out_trans_cb_t *trans_cb = __containerof(ret_trans, spi_out_trans_cb_t, trans); trans_cb->length = 0; - trans_cb->flag = SPI_OUT_TRANS_CB_FLAG_AVAILABLE; + trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; } IRAM_ATTR static void spi_out_pre_tx_cb(spi_transaction_t *ret_trans) @@ -194,7 +224,7 @@ IRAM_ATTR static void spi_out_pre_tx_cb(spi_transaction_t *ret_trans) IRAM_ATTR static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb) { - if (trans_cb->flag != SPI_OUT_TRANS_CB_FLAG_NEED_QUEUE || !trans_cb->length) { + if (trans_cb->flag != TRANS_CB_FLAG_NEED_QUEUE || !trans_cb->length) { return -1; } @@ -202,11 +232,11 @@ IRAM_ATTR static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb) trans_cb->trans.length = trans_cb->length * 8; trans_cb->trans.rxlength = 0; if (spi_device_queue_trans(spi_handle, &(trans_cb->trans), 0) == ESP_OK) { - trans_cb->flag = SPI_OUT_TRANS_CB_FLAG_IN_QUEUE; + trans_cb->flag = TRANS_CB_FLAG_IN_QUEUE; return 0; } else { trans_cb->length = 0; - trans_cb->flag = SPI_OUT_TRANS_CB_FLAG_AVAILABLE; + trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; return -1; } } @@ -259,11 +289,11 @@ IRAM_ATTR static inline int spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, if (frame_len > trans_cb->buf_size) { goto failed; } - if (trans_cb->flag == SPI_OUT_TRANS_CB_FLAG_AVAILABLE) { + if (trans_cb->flag == TRANS_CB_FLAG_AVAILABLE) { if ((trans_cb->buf_size - trans_cb->length) >= (len + SPI_OUT_FRAME_OVERHEAD)) { return 0; } else { - trans_cb->flag = SPI_OUT_TRANS_CB_FLAG_NEED_QUEUE; + trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; } } log_cb->trans_cb_idx = !(log_cb->trans_cb_idx); @@ -281,7 +311,7 @@ IRAM_ATTR static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_c uint8_t idx = !log_cb->trans_cb_idx; for (uint8_t i = 0; i < 2; i++) { trans_cb = log_cb->trans_cb[idx]; - if (trans_cb->flag == SPI_OUT_TRANS_CB_FLAG_NEED_QUEUE) { + if (trans_cb->flag == TRANS_CB_FLAG_NEED_QUEUE) { if (spi_out_append_trans(trans_cb) != 0) { log_cb->trans_loss_cnt++; } @@ -293,8 +323,8 @@ IRAM_ATTR static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_c IRAM_ATTR static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb) { spi_out_trans_cb_t *trans_cb = log_cb->trans_cb[log_cb->trans_cb_idx]; - if (trans_cb->length && (trans_cb->flag == SPI_OUT_TRANS_CB_FLAG_AVAILABLE)) { - trans_cb->flag = SPI_OUT_TRANS_CB_FLAG_NEED_QUEUE; + if (trans_cb->length && (trans_cb->flag == TRANS_CB_FLAG_AVAILABLE)) { + trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; } } @@ -324,7 +354,7 @@ IRAM_ATTR static void spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 trans_cb->length += total_length + SPI_OUT_FRAME_OVERHEAD; log_cb->frame_cnt++; if ((trans_cb->buf_size - trans_cb->length) <= SPI_OUT_FRAME_OVERHEAD) { - trans_cb->flag = SPI_OUT_TRANS_CB_FLAG_NEED_QUEUE; + trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; } return; } @@ -379,7 +409,7 @@ static int spi_out_ul_log_init(void) goto mutex_init_failed; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED // Initialize flushout timer esp_timer_create_args_t timer_args = { .callback = (esp_timer_cb_t)esp_timer_cb_ul_log_flushout, @@ -389,10 +419,10 @@ static int spi_out_ul_log_init(void) ESP_LOGE(BLE_LOG_TAG, "Failed to initialize flushout timer upper layer task log!"); goto timer_init_failed; } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED // Initialize log control block - if (spi_out_log_cb_init(&ul_log_cb, CONFIG_BT_BLE_LOG_SPI_OUT_UL_TASK_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ul_log_cb, SPI_OUT_UL_TASK_BUF_SIZE) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for upper layer task log!"); goto log_cb_init_failed; } @@ -403,10 +433,10 @@ static int spi_out_ul_log_init(void) return 0; log_cb_init_failed: -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_delete(ul_log_flushout_timer); timer_init_failed: -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED vSemaphoreDelete(ul_log_mutex); mutex_init_failed: return -1; @@ -418,10 +448,10 @@ static void spi_out_ul_log_deinit(void) return; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_stop(ul_log_flushout_timer); esp_timer_delete(ul_log_flushout_timer); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED xSemaphoreTake(ul_log_mutex, portMAX_DELAY); spi_out_log_cb_deinit(&ul_log_cb); @@ -435,7 +465,7 @@ static void spi_out_ul_log_deinit(void) return; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED IRAM_ATTR static void esp_timer_cb_ul_log_flushout(void) { xSemaphoreTake(ul_log_mutex, portMAX_DELAY); @@ -443,18 +473,18 @@ IRAM_ATTR static void esp_timer_cb_ul_log_flushout(void) spi_out_log_cb_append_trans(ul_log_cb); xSemaphoreGive(ul_log_mutex); - esp_timer_start_once(ul_log_flushout_timer, SPI_OUT_FLUSHOUT_TIMEOUT); + esp_timer_start_once(ul_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void) { if (ll_log_inited) { return 0; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED // Initialize flushout timer esp_timer_create_args_t timer_args = { .callback = (esp_timer_cb_t)esp_timer_cb_ll_log_flushout, @@ -464,14 +494,14 @@ static int spi_out_ll_log_init(void) ESP_LOGE(BLE_LOG_TAG, "Failed to initialize flushout timer for controller log!"); goto timer_init_failed; } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED // Initialize log control blocks for controller task & ISR logs - if (spi_out_log_cb_init(&ll_task_log_cb, CONFIG_BT_BLE_LOG_SPI_OUT_LL_TASK_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller task!"); goto task_log_cb_init_failed; } - if (spi_out_log_cb_init(&ll_isr_log_cb, CONFIG_BT_BLE_LOG_SPI_OUT_LL_ISR_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ll_isr_log_cb, SPI_OUT_LL_ISR_BUF_SIZE) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); goto isr_log_cb_init_failed; } @@ -484,10 +514,10 @@ static int spi_out_ll_log_init(void) isr_log_cb_init_failed: spi_out_log_cb_deinit(&ll_task_log_cb); task_log_cb_init_failed: -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_delete(ll_log_flushout_timer); timer_init_failed: -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED return -1; } @@ -497,10 +527,10 @@ static void spi_out_ll_log_deinit(void) return; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_stop(ll_log_flushout_timer); esp_timer_delete(ll_log_flushout_timer); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED spi_out_log_cb_deinit(&ll_isr_log_cb); spi_out_log_cb_deinit(&ll_task_log_cb); @@ -513,7 +543,7 @@ static void spi_out_ll_log_deinit(void) IRAM_ATTR static void spi_out_ll_log_ev_proc(void) { -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED // Request from flushout timer spi_out_log_cb_flush_trans(ll_isr_log_cb); spi_out_log_cb_append_trans(ll_isr_log_cb); @@ -521,20 +551,20 @@ IRAM_ATTR static void spi_out_ll_log_ev_proc(void) spi_out_log_cb_flush_trans(ll_task_log_cb); spi_out_log_cb_append_trans(ll_task_log_cb); - esp_timer_start_once(ll_log_flushout_timer, SPI_OUT_FLUSHOUT_TIMEOUT); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED + esp_timer_start_once(ll_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); +#endif // SPI_OUT_FLUSH_TIMER_ENABLED return; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED IRAM_ATTR static void esp_timer_cb_ll_log_flushout(void) { BLE_LOG_LL_PUT_EV; } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED +#endif // SPI_OUT_LL_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED static int spi_out_ts_sync_init(void) { if (ts_sync_inited) { @@ -555,7 +585,7 @@ static int spi_out_ts_sync_init(void) gpio_config_t io_conf = { .intr_type = GPIO_INTR_DISABLE, .mode = GPIO_MODE_OUTPUT, - .pin_bit_mask = (1UL << CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM), + .pin_bit_mask = (1UL << SPI_OUT_SYNC_IO_NUM), .pull_down_en = 0, .pull_up_en = 0 }; @@ -567,7 +597,7 @@ static int spi_out_ts_sync_init(void) // Initialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize timestamp synchronizer!"); sync_io_level = false; - gpio_set_level(CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM, sync_io_level); + gpio_set_level(SPI_OUT_SYNC_IO_NUM, sync_io_level); ts_sync_inited = true; return 0; @@ -589,8 +619,8 @@ static void spi_out_ts_sync_deinit(void) // Deinitialize sync IO sync_io_level = false; - gpio_set_level(CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM, sync_io_level); - gpio_reset_pin(CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM); + gpio_set_level(SPI_OUT_SYNC_IO_NUM, sync_io_level); + gpio_reset_pin(SPI_OUT_SYNC_IO_NUM); // Deinitialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize timestamp synchronizer!"); @@ -616,7 +646,7 @@ static void esp_timer_cb_ts_sync(void) lc_ts = SPI_OUT_GET_LC_TIME; // Set sync IO level - gpio_set_level(CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM, (uint32_t)sync_io_level); + gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)sync_io_level); // Get ESP timestamp esp_ts = esp_timer_get_time(); @@ -630,7 +660,7 @@ static void esp_timer_cb_ts_sync(void) memcpy(sync_frame + 5, &esp_ts, sizeof(esp_ts)); ble_log_spi_out_write(BLE_LOG_SPI_OUT_SOURCE_SYNC, sync_frame, 9); } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED // Public functions int ble_log_spi_out_init(void) @@ -643,8 +673,8 @@ int ble_log_spi_out_init(void) // Initialize SPI spi_bus_config_t bus_config = { .miso_io_num = -1, - .mosi_io_num = CONFIG_BT_BLE_LOG_SPI_OUT_MOSI_IO_NUM, - .sclk_io_num = CONFIG_BT_BLE_LOG_SPI_OUT_SCLK_IO_NUM, + .mosi_io_num = SPI_OUT_MOSI_IO_NUM, + .sclk_io_num = SPI_OUT_SCLK_IO_NUM, .quadwp_io_num = -1, .quadhd_io_num = -1, .max_transfer_sz = SPI_OUT_MAX_TRANSFER_SIZE, @@ -655,7 +685,7 @@ int ble_log_spi_out_init(void) spi_device_interface_config_t dev_config = { .clock_speed_hz = SPI_MASTER_FREQ_20M, .mode = 0, - .spics_io_num = CONFIG_BT_BLE_LOG_SPI_OUT_CS_IO_NUM, + .spics_io_num = SPI_OUT_CS_IO_NUM, .queue_size = SPI_OUT_SPI_MASTER_QUEUE_SIZE, .post_cb = spi_out_tx_done_cb, .pre_cb = spi_out_pre_tx_cb, @@ -674,39 +704,39 @@ int ble_log_spi_out_init(void) goto ul_log_init_failed; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED if (spi_out_ll_log_init() != 0) { goto ll_log_init_failed; } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_LL_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED if (spi_out_ts_sync_init() != 0) { goto ts_sync_init_failed; } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED // Initialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize BLE log SPI output interface!"); spi_out_inited = true; -#if CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED // Start flushout timer - esp_timer_start_once(ul_log_flushout_timer, SPI_OUT_FLUSHOUT_TIMEOUT); + esp_timer_start_once(ul_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED - esp_timer_start_once(ll_log_flushout_timer, SPI_OUT_FLUSHOUT_TIMEOUT); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_LL_ENABLED + esp_timer_start_once(ll_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); +#endif // SPI_OUT_LL_ENABLED +#endif // SPI_OUT_FLUSH_TIMER_ENABLED return 0; -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED ts_sync_init_failed: -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_LL_ENABLED spi_out_ll_log_deinit(); ll_log_init_failed: -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_LL_ENABLED spi_out_ul_log_deinit(); ul_log_init_failed: spi_bus_remove_device(spi_handle); @@ -733,13 +763,13 @@ void ble_log_spi_out_deinit(void) spi_handle = NULL; spi_bus_free(SPI_OUT_BUS); -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED spi_out_ts_sync_deinit(); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED spi_out_ll_log_deinit(); -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_LL_ENABLED spi_out_ul_log_deinit(); @@ -747,7 +777,7 @@ void ble_log_spi_out_deinit(void) spi_out_inited = false; } -#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_TS_SYNC_ENABLED void ble_log_spi_out_ts_sync_start(void) { // Check if SPI out is initialized @@ -778,12 +808,12 @@ void ble_log_spi_out_ts_sync_stop(void) // Set sync IO to low level sync_io_level = 0; - gpio_set_level(CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM, (uint32_t)sync_io_level); + gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)sync_io_level); } } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED +#endif // SPI_OUT_TS_SYNC_ENABLED -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED // Only LL task has access to this API IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint32_t len_append,\ const uint8_t *addr_append, uint32_t flag) @@ -799,11 +829,11 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 if (spi_out_log_cb_check_trans(log_cb, total_length) == 0) { spi_out_log_cb_write(log_cb, addr, (uint16_t)len, addr_append, (uint16_t)len_append, source); if (in_isr) { - spi_out_log_cb_write_packet_loss(log_cb, SPI_OUT_PACKET_LOSS_LL_ISR); + spi_out_log_cb_write_packet_loss(log_cb, LOG_CB_TYPE_LL_ISR); } else { spi_out_log_cb_append_trans(ll_isr_log_cb); spi_out_log_cb_append_trans(ll_task_log_cb); - spi_out_log_cb_write_packet_loss(log_cb, SPI_OUT_PACKET_LOSS_LL_TASK); + spi_out_log_cb_write_packet_loss(log_cb, LOG_CB_TYPE_LL_TASK); } } return; @@ -816,7 +846,7 @@ IRAM_ATTR void ble_log_spi_out_ll_log_ev_proc(void) } return spi_out_ll_log_ev_proc(); } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_LL_ENABLED int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) { @@ -829,7 +859,7 @@ int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source); spi_out_log_cb_append_trans(ul_log_cb); - spi_out_log_cb_write_packet_loss(ul_log_cb, SPI_OUT_PACKET_LOSS_UL); + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); } xSemaphoreGive(ul_log_mutex); return 0; @@ -874,7 +904,7 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...) spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), (const uint8_t *)buffer, len, source); spi_out_log_cb_append_trans(ul_log_cb); - spi_out_log_cb_write_packet_loss(ul_log_cb, SPI_OUT_PACKET_LOSS_UL); + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); } xSemaphoreGive(ul_log_mutex); @@ -928,7 +958,7 @@ int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, c spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), (const uint8_t *)buffer, total_len, source); spi_out_log_cb_append_trans(ul_log_cb); - spi_out_log_cb_write_packet_loss(ul_log_cb, SPI_OUT_PACKET_LOSS_UL); + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); } xSemaphoreGive(ul_log_mutex); @@ -948,7 +978,7 @@ int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), addr, len, source); spi_out_log_cb_append_trans(ul_log_cb); - spi_out_log_cb_write_packet_loss(ul_log_cb, SPI_OUT_PACKET_LOSS_UL); + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); } xSemaphoreGive(ul_log_mutex); return 0; @@ -959,7 +989,7 @@ void ble_log_spi_out_dump_all(void) portMUX_TYPE spinlock = portMUX_INITIALIZER_UNLOCKED; portENTER_CRITICAL_SAFE(&spinlock); -#if CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#if SPI_OUT_LL_ENABLED if (ll_log_inited) { // Dump lower layer log buffer esp_rom_printf("[LL_ISR_LOG_DUMP_START:\n"); @@ -970,7 +1000,7 @@ void ble_log_spi_out_dump_all(void) spi_out_log_cb_dump(ll_task_log_cb); esp_rom_printf("\n:LL_TASK_LOG_DUMP_END]\n\n"); } -#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED +#endif // SPI_OUT_LL_ENABLED if (ul_log_inited) { // Dump upper layer log buffer diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 1b22ad5f42..355aaebe08 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -14,27 +14,31 @@ #include "esp_log.h" #include "freertos/semphr.h" -// Public typedefs -#define BLE_LOG_SPI_OUT_SOURCE_ESP 0 -#define BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY 1 -#define BLE_LOG_SPI_OUT_SOURCE_BLUEDROID 2 -#define BLE_LOG_SPI_OUT_SOURCE_NIMBLE 3 -#define BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM 4 -#define BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM 5 -#define BLE_LOG_SPI_OUT_SOURCE_ESP_ISR 6 -#define BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY_ISR 7 -#define BLE_LOG_SPI_OUT_SOURCE_USER 0x10 -#define BLE_LOG_SPI_OUT_SOURCE_SYNC 0xFE -#define BLE_LOG_SPI_OUT_SOURCE_LOSS 0xFF +// Public enums +enum { + BLE_LOG_SPI_OUT_SOURCE_ESP = 0, + BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY, + BLE_LOG_SPI_OUT_SOURCE_BLUEDROID, + BLE_LOG_SPI_OUT_SOURCE_NIMBLE, + BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, + BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, + BLE_LOG_SPI_OUT_SOURCE_ESP_ISR, + BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY_ISR, + BLE_LOG_SPI_OUT_SOURCE_USER = 0x10, + BLE_LOG_SPI_OUT_SOURCE_SSC = 0xFD, + BLE_LOG_SPI_OUT_SOURCE_SYNC, + BLE_LOG_SPI_OUT_SOURCE_LOSS, +}; -// SPI Log Level Definitions -#define BLE_LOG_SPI_OUT_LEVEL_NONE 0 /*!< No log output */ -#define BLE_LOG_SPI_OUT_LEVEL_ERROR 1 /*!< Critical errors that SPI driver cannot recover from */ -#define BLE_LOG_SPI_OUT_LEVEL_WARN 2 /*!< Recoverable error conditions in SPI communication */ -#define BLE_LOG_SPI_OUT_LEVEL_INFO 3 /*!< Informational messages about SPI transactions */ -#define BLE_LOG_SPI_OUT_LEVEL_DEBUG 4 /*!< Detailed debug information, such as SPI register values */ -#define BLE_LOG_SPI_OUT_LEVEL_VERBOSE 5 /*!< Very detailed debugging logs, potentially flooding output */ -#define BLE_LOG_SPI_OUT_LEVEL_MAX 6 /*!< Number of SPI log levels supported */ +enum { + BLE_LOG_SPI_OUT_LEVEL_NONE = 0, + BLE_LOG_SPI_OUT_LEVEL_ERROR, + BLE_LOG_SPI_OUT_LEVEL_WARN, + BLE_LOG_SPI_OUT_LEVEL_INFO, + BLE_LOG_SPI_OUT_LEVEL_DEBUG, + BLE_LOG_SPI_OUT_LEVEL_VERBOSE, + BLE_LOG_SPI_OUT_LEVEL_MAX, +}; // Public functions int ble_log_spi_out_init(void); From 0e59feac9db91b63840e81806dd66922f4f6bcc9 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:17 +0800 Subject: [PATCH 02/16] feat(ble): support hci log buffer separation (cherry picked from commit 16a3b2c71bb4a777f72da9a67598430d816e5e38) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 12 +++- .../bt/common/ble_log/ble_log_spi_out.c | 59 +++++++++++++++---- .../ble_log/include/ble_log/ble_log_spi_out.h | 1 + 3 files changed, 60 insertions(+), 12 deletions(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index 0976ea2888..42d05caeea 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -48,7 +48,7 @@ config BT_BLE_LOG_SPI_OUT_LL_TASK_BUF_SIZE depends on BT_BLE_LOG_SPI_OUT_LL_ENABLED default 1024 help - SPI transaction buffer size for upper layer task logs. + SPI transaction buffer size for lower layer task logs. There will be 2 SPI DMA buffers with the same size. config BT_BLE_LOG_SPI_OUT_LL_ISR_BUF_SIZE @@ -56,9 +56,17 @@ config BT_BLE_LOG_SPI_OUT_LL_ISR_BUF_SIZE depends on BT_BLE_LOG_SPI_OUT_LL_ENABLED default 512 help - SPI transaction buffer size for upper layer ISR logs. + SPI transaction buffer size for lower layer ISR logs. There will be 2 SPI DMA buffers with the same size. +config BT_BLE_LOG_SPI_OUT_LL_HCI_BUF_SIZE + int "SPI transaction buffer size for lower layer HCI logs" + depends on BT_BLE_LOG_SPI_OUT_LL_ENABLED + default 512 + help + SPI transaction buffer size for upper layer HCI logs. + There will be 2 SPI DMA buffers with the same size + config BT_BLE_LOG_SPI_OUT_MOSI_IO_NUM int "GPIO number of SPI MOSI" depends on BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index e78d4f7244..ee8b8862de 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -12,6 +12,7 @@ #define SPI_OUT_LL_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED #define SPI_OUT_LL_TASK_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LL_TASK_BUF_SIZE #define SPI_OUT_LL_ISR_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LL_ISR_BUF_SIZE +#define SPI_OUT_LL_HCI_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LL_HCI_BUF_SIZE #define SPI_OUT_MOSI_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_MOSI_IO_NUM #define SPI_OUT_SCLK_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_SCLK_IO_NUM #define SPI_OUT_CS_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_CS_IO_NUM @@ -28,7 +29,6 @@ #define SPI_OUT_FRAME_TAIL_LEN (4) #define SPI_OUT_FRAME_OVERHEAD (8) #define SPI_OUT_PACKET_LOSS_FRAME_SIZE (6) -#define SPI_OUT_INTERFACE_FLAG_IN_ISR (1 << 3) #define SPI_OUT_TRANS_ITVL_MIN_US (30) #if SPI_OUT_TS_SYNC_ENABLED @@ -77,6 +77,16 @@ enum { LOG_CB_TYPE_UL = 0, LOG_CB_TYPE_LL_TASK, LOG_CB_TYPE_LL_ISR, + LOG_CB_TYPE_LL_HCI, +}; + +enum { + LL_LOG_FLAG_CONTINUE = 0, + LL_LOG_FLAG_END, + LL_LOG_FLAG_TASK, + LL_LOG_FLAG_ISR, + LL_LOG_FLAG_HCI, + LL_LOG_FLAG_RAW, }; // Private variables @@ -95,6 +105,7 @@ static esp_timer_handle_t ul_log_flushout_timer = NULL; static bool ll_log_inited = false; static spi_out_log_cb_t *ll_task_log_cb = NULL; static spi_out_log_cb_t *ll_isr_log_cb = NULL; +static spi_out_log_cb_t *ll_hci_log_cb = NULL; #if SPI_OUT_FLUSH_TIMER_ENABLED static esp_timer_handle_t ll_log_flushout_timer = NULL; #endif // SPI_OUT_FLUSH_TIMER_ENABLED @@ -505,12 +516,18 @@ static int spi_out_ll_log_init(void) ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); goto isr_log_cb_init_failed; } + if (spi_out_log_cb_init(&ll_hci_log_cb, SPI_OUT_LL_HCI_BUF_SIZE) != 0) { + ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); + goto hci_log_cb_init_failed; + } // Initialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize log control blocks for controller task & ISR!"); ll_log_inited = true; return 0; +hci_log_cb_init_failed: + spi_out_log_cb_deinit(&ll_isr_log_cb); isr_log_cb_init_failed: spi_out_log_cb_deinit(&ll_task_log_cb); task_log_cb_init_failed: @@ -532,6 +549,7 @@ static void spi_out_ll_log_deinit(void) esp_timer_delete(ll_log_flushout_timer); #endif // SPI_OUT_FLUSH_TIMER_ENABLED + spi_out_log_cb_deinit(&ll_hci_log_cb); spi_out_log_cb_deinit(&ll_isr_log_cb); spi_out_log_cb_deinit(&ll_task_log_cb); @@ -545,6 +563,9 @@ IRAM_ATTR static void spi_out_ll_log_ev_proc(void) { #if SPI_OUT_FLUSH_TIMER_ENABLED // Request from flushout timer + spi_out_log_cb_flush_trans(ll_hci_log_cb); + spi_out_log_cb_append_trans(ll_hci_log_cb); + spi_out_log_cb_flush_trans(ll_isr_log_cb); spi_out_log_cb_append_trans(ll_isr_log_cb); @@ -822,18 +843,32 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 return; } - bool in_isr = (bool)(flag & SPI_OUT_INTERFACE_FLAG_IN_ISR); - uint8_t source = in_isr ? BLE_LOG_SPI_OUT_SOURCE_ESP_ISR : BLE_LOG_SPI_OUT_SOURCE_ESP; - spi_out_log_cb_t *log_cb = in_isr ? ll_isr_log_cb : ll_task_log_cb; - uint16_t total_length = (uint16_t)(len + len_append); - if (spi_out_log_cb_check_trans(log_cb, total_length) == 0) { + bool in_isr = false; + uint8_t log_cb_type; + uint8_t source; + spi_out_log_cb_t *log_cb; + if (flag & BIT(LL_LOG_FLAG_ISR)) { + log_cb = ll_isr_log_cb; + log_cb_type = LOG_CB_TYPE_LL_ISR; + source = BLE_LOG_SPI_OUT_SOURCE_ESP_ISR; + in_isr = true; + } else if (flag & BIT(LL_LOG_FLAG_HCI)) { + log_cb = ll_hci_log_cb; + log_cb_type = LOG_CB_TYPE_LL_HCI; + source = BLE_LOG_SPI_OUT_SOURCE_ESP; + } else { + log_cb = ll_task_log_cb; + log_cb_type = LOG_CB_TYPE_LL_TASK; + source = BLE_LOG_SPI_OUT_SOURCE_ESP; + } + + if (spi_out_log_cb_check_trans(log_cb, (uint16_t)(len + len_append)) == 0) { spi_out_log_cb_write(log_cb, addr, (uint16_t)len, addr_append, (uint16_t)len_append, source); - if (in_isr) { - spi_out_log_cb_write_packet_loss(log_cb, LOG_CB_TYPE_LL_ISR); - } else { + spi_out_log_cb_write_packet_loss(log_cb, log_cb_type); + if (!in_isr) { spi_out_log_cb_append_trans(ll_isr_log_cb); spi_out_log_cb_append_trans(ll_task_log_cb); - spi_out_log_cb_write_packet_loss(log_cb, LOG_CB_TYPE_LL_TASK); + spi_out_log_cb_append_trans(ll_hci_log_cb); } } return; @@ -999,6 +1034,10 @@ void ble_log_spi_out_dump_all(void) esp_rom_printf("[LL_TASK_LOG_DUMP_START:\n"); spi_out_log_cb_dump(ll_task_log_cb); esp_rom_printf("\n:LL_TASK_LOG_DUMP_END]\n\n"); + + esp_rom_printf("[LL_HCI_LOG_DUMP_START:\n"); + spi_out_log_cb_dump(ll_hci_log_cb); + esp_rom_printf("\n:LL_HCI_LOG_DUMP_END]\n\n"); } #endif // SPI_OUT_LL_ENABLED diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 355aaebe08..60c4aad1b1 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -24,6 +24,7 @@ enum { BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, BLE_LOG_SPI_OUT_SOURCE_ESP_ISR, BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY_ISR, + BLE_LOG_SPI_OUT_SOURCE_LL_HCI, BLE_LOG_SPI_OUT_SOURCE_USER = 0x10, BLE_LOG_SPI_OUT_SOURCE_SSC = 0xFD, BLE_LOG_SPI_OUT_SOURCE_SYNC, From 3d3b7caf95ec7f3e8078c3b7ed5e1b4bc0bd87f5 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:19 +0800 Subject: [PATCH 03/16] feat(ble): provided dynamic spi enable/disable api (cherry picked from commit 3568f19fef2c205556eb95c3e2ba116368f4be97) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 21 +++++++++++++++++++ .../ble_log/include/ble_log/ble_log_spi_out.h | 1 + 2 files changed, 22 insertions(+) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index ee8b8862de..33ffb2c598 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -91,6 +91,7 @@ enum { // Private variables static bool spi_out_inited = false; +static bool spi_out_enabled = false; static spi_device_handle_t spi_handle = NULL; static uint32_t last_tx_done_ts = 0; @@ -239,6 +240,13 @@ IRAM_ATTR static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb) return -1; } + // Note: To support dump log when disabled + if (!spi_out_enabled) { + trans_cb->length = 0; + trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; + return 0; + } + // CRITICAL: Length unit conversion from bytes to bits trans_cb->trans.length = trans_cb->length * 8; trans_cb->trans.rxlength = 0; @@ -740,6 +748,7 @@ int ble_log_spi_out_init(void) // Initialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize BLE log SPI output interface!"); spi_out_inited = true; + spi_out_enabled = true; #if SPI_OUT_FLUSH_TIMER_ENABLED // Start flushout timer @@ -796,6 +805,7 @@ void ble_log_spi_out_deinit(void) // Reset init flag spi_out_inited = false; + spi_out_enabled = false; } #if SPI_OUT_TS_SYNC_ENABLED @@ -1050,4 +1060,15 @@ void ble_log_spi_out_dump_all(void) portEXIT_CRITICAL_SAFE(&spinlock); } +void ble_log_spi_out_enable(bool enable) +{ + spi_out_enabled = enable; + + if (!enable) { +#if CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED + ble_log_spi_out_ts_sync_stop(); +#endif // CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED + } +} + #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 60c4aad1b1..4272d6ff0b 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -55,5 +55,6 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...); int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, const char *format, ...); int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t len); void ble_log_spi_out_dump_all(void); +void ble_log_spi_out_enable(bool enable); #endif // __BT_SPI_OUT_H__ From 68dd2c9a3c4193010efb56f5bb44a9981a500ef9 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:22 +0800 Subject: [PATCH 04/16] feat(ble): refactored ll isr buffer append and buffer flush using event handler (cherry picked from commit bba90309e75b1cfce58372c08ccba136fd636b14) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 173 ++++++++++++------ 1 file changed, 112 insertions(+), 61 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 33ffb2c598..dd57cc08a7 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -7,6 +7,9 @@ #if CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED +// Private includes +#include "esp_bt.h" + // sdkconfig defines #define SPI_OUT_UL_TASK_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_UL_TASK_BUF_SIZE #define SPI_OUT_LL_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LL_ENABLED @@ -89,6 +92,11 @@ enum { LL_LOG_FLAG_RAW, }; +enum { + LL_EV_ISR_APPEND = 0, + LL_EV_FLUSH_LOG, +}; + // Private variables static bool spi_out_inited = false; static bool spi_out_enabled = false; @@ -107,6 +115,8 @@ static bool ll_log_inited = false; static spi_out_log_cb_t *ll_task_log_cb = NULL; static spi_out_log_cb_t *ll_isr_log_cb = NULL; static spi_out_log_cb_t *ll_hci_log_cb = NULL; +static uint32_t ll_ev_flags = 0; +static esp_bt_controller_status_t ll_status = ESP_BT_CONTROLLER_STATUS_IDLE; #if SPI_OUT_FLUSH_TIMER_ENABLED static esp_timer_handle_t ll_log_flushout_timer = NULL; #endif // SPI_OUT_FLUSH_TIMER_ENABLED @@ -129,10 +139,10 @@ static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb); static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size); static void spi_out_log_cb_deinit(spi_out_log_cb_t **log_cb); -static inline int spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len); +static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len, bool *need_append); static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_cb); static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb); -static void spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, \ +static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, \ const uint8_t *addr_append, uint16_t len_append, uint8_t source); static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, uint8_t flag); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); @@ -146,22 +156,11 @@ static void esp_timer_cb_ul_log_flushout(void); #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); static void spi_out_ll_log_deinit(void); -static void spi_out_ll_log_ev_proc(void); +static void spi_out_ll_log_flush(void); +static inline void spi_out_ll_log_put_ev(void); #if SPI_OUT_FLUSH_TIMER_ENABLED static void esp_timer_cb_ll_log_flushout(void); #endif // SPI_OUT_FLUSH_TIMER_ENABLED - -#if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\ - defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) -extern void r_ble_log_simple_put_ev(void); -#define BLE_LOG_LL_PUT_EV r_ble_log_simple_put_ev() -#elif defined(CONFIG_IDF_TARGET_ESP32C2) -extern void ble_log_simple_put_ev(void); -#define BLE_LOG_LL_PUT_EV ble_log_simple_put_ev() -#else -#define BLE_LOG_LL_PUT_EV -#endif - #endif // SPI_OUT_LL_ENABLED #if SPI_OUT_TS_SYNC_ENABLED @@ -299,10 +298,11 @@ static void spi_out_log_cb_deinit(spi_out_log_cb_t **log_cb) return; } -IRAM_ATTR static inline int spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len) +IRAM_ATTR static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len, bool *need_append) { spi_out_trans_cb_t *trans_cb; uint16_t frame_len = len + SPI_OUT_FRAME_OVERHEAD; + *need_append = false; for (uint8_t i = 0; i < 2; i++) { trans_cb = log_cb->trans_cb[log_cb->trans_cb_idx]; if (frame_len > trans_cb->buf_size) { @@ -310,9 +310,10 @@ IRAM_ATTR static inline int spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, } if (trans_cb->flag == TRANS_CB_FLAG_AVAILABLE) { if ((trans_cb->buf_size - trans_cb->length) >= (len + SPI_OUT_FRAME_OVERHEAD)) { - return 0; + return true; } else { trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; + *need_append = true; } } log_cb->trans_cb_idx = !(log_cb->trans_cb_idx); @@ -320,7 +321,7 @@ IRAM_ATTR static inline int spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, failed: log_cb->bytes_loss_cnt += len + SPI_OUT_FRAME_OVERHEAD; log_cb->frame_cnt++; - return -1; + return false; } // CRITICAL: Shall not be called from ISR! @@ -347,7 +348,8 @@ IRAM_ATTR static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb } } -IRAM_ATTR static void spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, \ +// Return value: Need append +IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, \ const uint8_t *addr_append, uint16_t len_append, uint8_t source) { spi_out_trans_cb_t *trans_cb = log_cb->trans_cb[log_cb->trans_cb_idx]; @@ -374,8 +376,9 @@ IRAM_ATTR static void spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 log_cb->frame_cnt++; if ((trans_cb->buf_size - trans_cb->length) <= SPI_OUT_FRAME_OVERHEAD) { trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; + return true; } - return; + return false; } IRAM_ATTR static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, uint8_t flag) @@ -383,7 +386,8 @@ IRAM_ATTR static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, if (!log_cb->bytes_loss_cnt && !log_cb->trans_loss_cnt) { return; } - if (spi_out_log_cb_check_trans(log_cb, SPI_OUT_PACKET_LOSS_FRAME_SIZE) == 0) { + bool need_append; + if (spi_out_log_cb_check_trans(log_cb, SPI_OUT_PACKET_LOSS_FRAME_SIZE, &need_append)) { uint8_t packet_loss_frame[SPI_OUT_PACKET_LOSS_FRAME_SIZE]; packet_loss_frame[0] = flag; memcpy(packet_loss_frame + 1, (uint8_t *)&log_cb->bytes_loss_cnt, 4); @@ -567,28 +571,47 @@ static void spi_out_ll_log_deinit(void) return; } -IRAM_ATTR static void spi_out_ll_log_ev_proc(void) +IRAM_ATTR static inline void spi_out_ll_log_put_ev(void) { -#if SPI_OUT_FLUSH_TIMER_ENABLED - // Request from flushout timer - spi_out_log_cb_flush_trans(ll_hci_log_cb); - spi_out_log_cb_append_trans(ll_hci_log_cb); + if (ll_status < ESP_BT_CONTROLLER_STATUS_INITED) { + return; + } - spi_out_log_cb_flush_trans(ll_isr_log_cb); - spi_out_log_cb_append_trans(ll_isr_log_cb); +#if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\ + defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) + extern void r_ble_log_simple_put_ev(void); + r_ble_log_simple_put_ev(); +#elif defined(CONFIG_IDF_TARGET_ESP32C2) + extern void ble_log_simple_put_ev(void); + ble_log_simple_put_ev(); +#else +#endif +} +// Context: LL task +static void spi_out_ll_log_flush(void) +{ + // Flush task log and hci log buffer spi_out_log_cb_flush_trans(ll_task_log_cb); - spi_out_log_cb_append_trans(ll_task_log_cb); + spi_out_log_cb_flush_trans(ll_hci_log_cb); - esp_timer_start_once(ll_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); -#endif // SPI_OUT_FLUSH_TIMER_ENABLED - return; + // Race condition for isr log buffer + portMUX_TYPE spinlock = portMUX_INITIALIZER_UNLOCKED; + portENTER_CRITICAL_SAFE(&spinlock); + spi_out_log_cb_flush_trans(ll_isr_log_cb); + portEXIT_CRITICAL_SAFE(&spinlock); + + // Note: Save SPI transfer start time + spi_out_log_cb_append_trans(ll_task_log_cb); + spi_out_log_cb_append_trans(ll_hci_log_cb); + spi_out_log_cb_append_trans(ll_isr_log_cb); } #if SPI_OUT_FLUSH_TIMER_ENABLED IRAM_ATTR static void esp_timer_cb_ll_log_flushout(void) { - BLE_LOG_LL_PUT_EV; + ll_ev_flags |= BIT(LL_EV_FLUSH_LOG); + spi_out_ll_log_put_ev(); } #endif // SPI_OUT_FLUSH_TIMER_ENABLED #endif // SPI_OUT_LL_ENABLED @@ -872,15 +895,24 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 source = BLE_LOG_SPI_OUT_SOURCE_ESP; } - if (spi_out_log_cb_check_trans(log_cb, (uint16_t)(len + len_append)) == 0) { - spi_out_log_cb_write(log_cb, addr, (uint16_t)len, addr_append, (uint16_t)len_append, source); - spi_out_log_cb_write_packet_loss(log_cb, log_cb_type); - if (!in_isr) { - spi_out_log_cb_append_trans(ll_isr_log_cb); - spi_out_log_cb_append_trans(ll_task_log_cb); - spi_out_log_cb_append_trans(ll_hci_log_cb); + bool need_append; + if (spi_out_log_cb_check_trans(log_cb, (uint16_t)(len + len_append), &need_append)) { + need_append |= spi_out_log_cb_write(log_cb, addr, (uint16_t)len, addr_append, (uint16_t)len_append, source); + } + if (need_append) { + if (in_isr) { + ll_ev_flags |= BIT(LL_EV_ISR_APPEND); + spi_out_ll_log_put_ev(); + } else { + spi_out_log_cb_append_trans(log_cb); } } + spi_out_log_cb_write_packet_loss(log_cb, log_cb_type); + + // Update controller status + if (!in_isr) { + ll_status = esp_bt_controller_get_status(); + } return; } @@ -889,7 +921,16 @@ IRAM_ATTR void ble_log_spi_out_ll_log_ev_proc(void) if (!ll_log_inited) { return; } - return spi_out_ll_log_ev_proc(); + + if (ll_ev_flags & BIT(LL_EV_ISR_APPEND)) { + spi_out_log_cb_append_trans(ll_isr_log_cb); + ll_ev_flags &= ~BIT(LL_EV_ISR_APPEND); + } + + if (ll_ev_flags & BIT(LL_EV_FLUSH_LOG)) { + spi_out_ll_log_flush(); + ll_ev_flags &= ~BIT(LL_EV_FLUSH_LOG); + } } #endif // SPI_OUT_LL_ENABLED @@ -899,13 +940,15 @@ int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) return -1; } + bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, len) == 0) { - spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source); - spi_out_log_cb_append_trans(ul_log_cb); - - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + if (spi_out_log_cb_check_trans(ul_log_cb, len, &need_append)) { + need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source); } + if (need_append) { + spi_out_log_cb_append_trans(ul_log_cb); + } + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); xSemaphoreGive(ul_log_mutex); return 0; } @@ -944,13 +987,16 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...) va_end(args); uint32_t esp_ts = esp_timer_get_time(); + bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + len) == 0) { - spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), (const uint8_t *)buffer, len, source); - spi_out_log_cb_append_trans(ul_log_cb); - - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + len, &need_append)) { + need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), + (const uint8_t *)buffer, len, source); } + if (need_append) { + spi_out_log_cb_append_trans(ul_log_cb); + } + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); xSemaphoreGive(ul_log_mutex); // Release @@ -998,13 +1044,16 @@ int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, c va_end(args); uint32_t esp_ts = esp_timer_get_time(); + bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + total_len) == 0) { - spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), (const uint8_t *)buffer, total_len, source); - spi_out_log_cb_append_trans(ul_log_cb); - - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + total_len, &need_append)) { + need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), + (const uint8_t *)buffer, total_len, source); } + if (need_append) { + spi_out_log_cb_append_trans(ul_log_cb); + } + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); xSemaphoreGive(ul_log_mutex); free(buffer); @@ -1018,13 +1067,15 @@ int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t } uint32_t esp_ts = esp_timer_get_time(); + bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + len) == 0) { - spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), addr, len, source); - spi_out_log_cb_append_trans(ul_log_cb); - - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + len, &need_append)) { + need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), addr, len, source); } + if (need_append) { + spi_out_log_cb_append_trans(ul_log_cb); + } + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); xSemaphoreGive(ul_log_mutex); return 0; } From 9e0c4d226aa481e4a238e8a474dacc651253a76e Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:24 +0800 Subject: [PATCH 05/16] feat(ble): refactored flush module and provided public flush api (cherry picked from commit 70792443c73b279b599fece2d3b9512df010c583) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 162 ++++++++---------- .../ble_log/include/ble_log/ble_log_spi_out.h | 1 + 2 files changed, 73 insertions(+), 90 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index dd57cc08a7..c28503ab87 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -93,8 +93,8 @@ enum { }; enum { - LL_EV_ISR_APPEND = 0, - LL_EV_FLUSH_LOG, + LL_EV_FLAG_ISR_APPEND = 0, + LL_EV_FLAG_FLUSH_LOG, }; // Private variables @@ -106,9 +106,6 @@ static uint32_t last_tx_done_ts = 0; static bool ul_log_inited = false; static SemaphoreHandle_t ul_log_mutex = NULL; static spi_out_log_cb_t *ul_log_cb = NULL; -#if SPI_OUT_FLUSH_TIMER_ENABLED -static esp_timer_handle_t ul_log_flushout_timer = NULL; -#endif // SPI_OUT_FLUSH_TIMER_ENABLED #if SPI_OUT_LL_ENABLED static bool ll_log_inited = false; @@ -117,9 +114,6 @@ static spi_out_log_cb_t *ll_isr_log_cb = NULL; static spi_out_log_cb_t *ll_hci_log_cb = NULL; static uint32_t ll_ev_flags = 0; static esp_bt_controller_status_t ll_status = ESP_BT_CONTROLLER_STATUS_IDLE; -#if SPI_OUT_FLUSH_TIMER_ENABLED -static esp_timer_handle_t ll_log_flushout_timer = NULL; -#endif // SPI_OUT_FLUSH_TIMER_ENABLED #endif // SPI_OUT_LL_ENABLED #if SPI_OUT_TS_SYNC_ENABLED @@ -128,6 +122,10 @@ static bool sync_io_level = false; static esp_timer_handle_t ts_sync_timer = NULL; #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED +static esp_timer_handle_t flush_timer = NULL; +#endif // SPI_OUT_FLUSH_TIMER_ENABLED + // Extern function declarations extern void esp_panic_handler_feed_wdts(void); @@ -146,21 +144,16 @@ static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, const uint8_t *addr_append, uint16_t len_append, uint8_t source); static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, uint8_t flag); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); +static void spi_out_log_flush(void); static int spi_out_ul_log_init(void); static void spi_out_ul_log_deinit(void); -#if SPI_OUT_FLUSH_TIMER_ENABLED -static void esp_timer_cb_ul_log_flushout(void); -#endif // SPI_OUT_FLUSH_TIMER_ENABLED #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); static void spi_out_ll_log_deinit(void); static void spi_out_ll_log_flush(void); static inline void spi_out_ll_log_put_ev(void); -#if SPI_OUT_FLUSH_TIMER_ENABLED -static void esp_timer_cb_ll_log_flushout(void); -#endif // SPI_OUT_FLUSH_TIMER_ENABLED #endif // SPI_OUT_LL_ENABLED #if SPI_OUT_TS_SYNC_ENABLED @@ -342,9 +335,12 @@ IRAM_ATTR static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_c IRAM_ATTR static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb) { - spi_out_trans_cb_t *trans_cb = log_cb->trans_cb[log_cb->trans_cb_idx]; - if (trans_cb->length && (trans_cb->flag == TRANS_CB_FLAG_AVAILABLE)) { - trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; + spi_out_trans_cb_t *trans_cb; + for (uint8_t i = 0; i < 2; i++) { + trans_cb = log_cb->trans_cb[i]; + if (trans_cb->length && (trans_cb->flag == TRANS_CB_FLAG_AVAILABLE)) { + trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; + } } } @@ -419,6 +415,30 @@ static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb) } } +static void spi_out_log_flush(void) +{ + // Flush ul log + xSemaphoreTake(ul_log_mutex, portMAX_DELAY); + spi_out_log_cb_flush_trans(ul_log_cb); + spi_out_log_cb_append_trans(ul_log_cb); + xSemaphoreGive(ul_log_mutex); + +#if SPI_OUT_LL_ENABLED + // LL log flush shall be run in LL task context + ll_ev_flags |= BIT(LL_EV_FLAG_FLUSH_LOG); + spi_out_ll_log_put_ev(); +#endif // SPI_OUT_LL_ENABLED +} + +#if SPI_OUT_FLUSH_TIMER_ENABLED +// Context: ESP timer +static void esp_timer_cb_log_flush(void) +{ + spi_out_log_flush(); + esp_timer_start_once(flush_timer, SPI_OUT_FLUSH_TIMEOUT_US); +} +#endif // SPI_OUT_FLUSH_TIMER_ENABLED + static int spi_out_ul_log_init(void) { if (ul_log_inited) { @@ -432,18 +452,6 @@ static int spi_out_ul_log_init(void) goto mutex_init_failed; } -#if SPI_OUT_FLUSH_TIMER_ENABLED - // Initialize flushout timer - esp_timer_create_args_t timer_args = { - .callback = (esp_timer_cb_t)esp_timer_cb_ul_log_flushout, - .dispatch_method = ESP_TIMER_TASK - }; - if (esp_timer_create(&timer_args, &ul_log_flushout_timer) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize flushout timer upper layer task log!"); - goto timer_init_failed; - } -#endif // SPI_OUT_FLUSH_TIMER_ENABLED - // Initialize log control block if (spi_out_log_cb_init(&ul_log_cb, SPI_OUT_UL_TASK_BUF_SIZE) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for upper layer task log!"); @@ -456,10 +464,6 @@ static int spi_out_ul_log_init(void) return 0; log_cb_init_failed: -#if SPI_OUT_FLUSH_TIMER_ENABLED - esp_timer_delete(ul_log_flushout_timer); -timer_init_failed: -#endif // SPI_OUT_FLUSH_TIMER_ENABLED vSemaphoreDelete(ul_log_mutex); mutex_init_failed: return -1; @@ -471,11 +475,6 @@ static void spi_out_ul_log_deinit(void) return; } -#if SPI_OUT_FLUSH_TIMER_ENABLED - esp_timer_stop(ul_log_flushout_timer); - esp_timer_delete(ul_log_flushout_timer); -#endif // SPI_OUT_FLUSH_TIMER_ENABLED - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); spi_out_log_cb_deinit(&ul_log_cb); xSemaphoreGive(ul_log_mutex); @@ -488,18 +487,6 @@ static void spi_out_ul_log_deinit(void) return; } -#if SPI_OUT_FLUSH_TIMER_ENABLED -IRAM_ATTR static void esp_timer_cb_ul_log_flushout(void) -{ - xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - spi_out_log_cb_flush_trans(ul_log_cb); - spi_out_log_cb_append_trans(ul_log_cb); - xSemaphoreGive(ul_log_mutex); - - esp_timer_start_once(ul_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); -} -#endif // SPI_OUT_FLUSH_TIMER_ENABLED - #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void) { @@ -507,18 +494,6 @@ static int spi_out_ll_log_init(void) return 0; } -#if SPI_OUT_FLUSH_TIMER_ENABLED - // Initialize flushout timer - esp_timer_create_args_t timer_args = { - .callback = (esp_timer_cb_t)esp_timer_cb_ll_log_flushout, - .dispatch_method = ESP_TIMER_TASK - }; - if (esp_timer_create(&timer_args, &ll_log_flushout_timer) != ESP_OK) { - ESP_LOGE(BLE_LOG_TAG, "Failed to initialize flushout timer for controller log!"); - goto timer_init_failed; - } -#endif // SPI_OUT_FLUSH_TIMER_ENABLED - // Initialize log control blocks for controller task & ISR logs if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller task!"); @@ -543,10 +518,6 @@ hci_log_cb_init_failed: isr_log_cb_init_failed: spi_out_log_cb_deinit(&ll_task_log_cb); task_log_cb_init_failed: -#if SPI_OUT_FLUSH_TIMER_ENABLED - esp_timer_delete(ll_log_flushout_timer); -timer_init_failed: -#endif // SPI_OUT_FLUSH_TIMER_ENABLED return -1; } @@ -556,11 +527,6 @@ static void spi_out_ll_log_deinit(void) return; } -#if SPI_OUT_FLUSH_TIMER_ENABLED - esp_timer_stop(ll_log_flushout_timer); - esp_timer_delete(ll_log_flushout_timer); -#endif // SPI_OUT_FLUSH_TIMER_ENABLED - spi_out_log_cb_deinit(&ll_hci_log_cb); spi_out_log_cb_deinit(&ll_isr_log_cb); spi_out_log_cb_deinit(&ll_task_log_cb); @@ -606,14 +572,6 @@ static void spi_out_ll_log_flush(void) spi_out_log_cb_append_trans(ll_hci_log_cb); spi_out_log_cb_append_trans(ll_isr_log_cb); } - -#if SPI_OUT_FLUSH_TIMER_ENABLED -IRAM_ATTR static void esp_timer_cb_ll_log_flushout(void) -{ - ll_ev_flags |= BIT(LL_EV_FLUSH_LOG); - spi_out_ll_log_put_ev(); -} -#endif // SPI_OUT_FLUSH_TIMER_ENABLED #endif // SPI_OUT_LL_ENABLED #if SPI_OUT_TS_SYNC_ENABLED @@ -768,22 +726,32 @@ int ble_log_spi_out_init(void) } #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_FLUSH_TIMER_ENABLED + esp_timer_create_args_t timer_args = { + .callback = (esp_timer_cb_t)esp_timer_cb_log_flush, + .dispatch_method = ESP_TIMER_TASK + }; + if (esp_timer_create(&timer_args, &flush_timer) != ESP_OK) { + ESP_LOGE(BLE_LOG_TAG, "Failed to initialize flush timer!"); + goto timer_init_failed; + } +#endif // SPI_OUT_FLUSH_TIMER_ENABLED + // Initialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize BLE log SPI output interface!"); spi_out_inited = true; spi_out_enabled = true; #if SPI_OUT_FLUSH_TIMER_ENABLED - // Start flushout timer - esp_timer_start_once(ul_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); - -#if SPI_OUT_LL_ENABLED - esp_timer_start_once(ll_log_flushout_timer, SPI_OUT_FLUSH_TIMEOUT_US); -#endif // SPI_OUT_LL_ENABLED + esp_timer_start_once(flush_timer, SPI_OUT_FLUSH_TIMEOUT_US); #endif // SPI_OUT_FLUSH_TIMER_ENABLED return 0; +#if SPI_OUT_FLUSH_TIMER_ENABLED +timer_init_failed: +#endif // SPI_OUT_FLUSH_TIMER_ENABLED #if SPI_OUT_TS_SYNC_ENABLED + spi_out_ts_sync_deinit(); ts_sync_init_failed: #endif // SPI_OUT_TS_SYNC_ENABLED #if SPI_OUT_LL_ENABLED @@ -807,6 +775,11 @@ void ble_log_spi_out_deinit(void) return; } +#if SPI_OUT_FLUSH_TIMER_ENABLED + esp_timer_stop(flush_timer); + esp_timer_delete(flush_timer); +#endif // SPI_OUT_FLUSH_TIMER_ENABLED + // Drain all queued transactions assert(spi_device_acquire_bus(spi_handle, portMAX_DELAY) == ESP_OK); spi_device_release_bus(spi_handle); @@ -901,7 +874,7 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 } if (need_append) { if (in_isr) { - ll_ev_flags |= BIT(LL_EV_ISR_APPEND); + ll_ev_flags |= BIT(LL_EV_FLAG_ISR_APPEND); spi_out_ll_log_put_ev(); } else { spi_out_log_cb_append_trans(log_cb); @@ -922,14 +895,14 @@ IRAM_ATTR void ble_log_spi_out_ll_log_ev_proc(void) return; } - if (ll_ev_flags & BIT(LL_EV_ISR_APPEND)) { + if (ll_ev_flags & BIT(LL_EV_FLAG_ISR_APPEND)) { spi_out_log_cb_append_trans(ll_isr_log_cb); - ll_ev_flags &= ~BIT(LL_EV_ISR_APPEND); + ll_ev_flags &= ~BIT(LL_EV_FLAG_ISR_APPEND); } - if (ll_ev_flags & BIT(LL_EV_FLUSH_LOG)) { + if (ll_ev_flags & BIT(LL_EV_FLAG_FLUSH_LOG)) { spi_out_ll_log_flush(); - ll_ev_flags &= ~BIT(LL_EV_FLUSH_LOG); + ll_ev_flags &= ~BIT(LL_EV_FLAG_FLUSH_LOG); } } #endif // SPI_OUT_LL_ENABLED @@ -1122,4 +1095,13 @@ void ble_log_spi_out_enable(bool enable) } } +void ble_log_spi_out_flush(void) +{ + if (!spi_out_enabled) { + return; + } + + spi_out_log_flush(); +} + #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 4272d6ff0b..152c891e8e 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -56,5 +56,6 @@ int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, c int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t len); void ble_log_spi_out_dump_all(void); void ble_log_spi_out_enable(bool enable); +void ble_log_spi_out_flush(void); #endif // __BT_SPI_OUT_H__ From a73197e8865e6a8209df0ba9404a691156ea6502 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:26 +0800 Subject: [PATCH 06/16] feat(ble): optimized printf functions code size and speed (cherry picked from commit e4be25ba6388086b93e3d10a384a3d951aa0cc20) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 166 ++++++++---------- 1 file changed, 70 insertions(+), 96 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index c28503ab87..e56d752ed4 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -33,6 +33,7 @@ #define SPI_OUT_FRAME_OVERHEAD (8) #define SPI_OUT_PACKET_LOSS_FRAME_SIZE (6) #define SPI_OUT_TRANS_ITVL_MIN_US (30) +#define SPI_OUT_UL_LOG_STR_BUF_SIZE (100) #if SPI_OUT_TS_SYNC_ENABLED #define SPI_OUT_TS_SYNC_TIMEOUT (1000 * 1000) @@ -106,6 +107,7 @@ static uint32_t last_tx_done_ts = 0; static bool ul_log_inited = false; static SemaphoreHandle_t ul_log_mutex = NULL; static spi_out_log_cb_t *ul_log_cb = NULL; +static uint8_t *ul_log_str_buf = NULL; #if SPI_OUT_LL_ENABLED static bool ll_log_inited = false; @@ -148,6 +150,8 @@ static void spi_out_log_flush(void); static int spi_out_ul_log_init(void); static void spi_out_ul_log_deinit(void); +static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts); +static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args); #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); @@ -452,6 +456,13 @@ static int spi_out_ul_log_init(void) goto mutex_init_failed; } + // Initialize string buffer + ul_log_str_buf = (uint8_t *)malloc(SPI_OUT_UL_LOG_STR_BUF_SIZE); + if (!ul_log_str_buf) { + ESP_LOGE(BLE_LOG_TAG, "Failed to initialize string buffer for upper layer task log!"); + goto str_buf_init_failed; + } + // Initialize log control block if (spi_out_log_cb_init(&ul_log_cb, SPI_OUT_UL_TASK_BUF_SIZE) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for upper layer task log!"); @@ -464,6 +475,11 @@ static int spi_out_ul_log_init(void) return 0; log_cb_init_failed: + if (ul_log_str_buf) { + free(ul_log_str_buf); + ul_log_str_buf = NULL; + } +str_buf_init_failed: vSemaphoreDelete(ul_log_mutex); mutex_init_failed: return -1; @@ -474,8 +490,13 @@ static void spi_out_ul_log_deinit(void) if (!ul_log_inited) { return; } + ul_log_inited = false; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); + if (ul_log_str_buf) { + free(ul_log_str_buf); + ul_log_str_buf = NULL; + } spi_out_log_cb_deinit(&ul_log_cb); xSemaphoreGive(ul_log_mutex); @@ -483,10 +504,45 @@ static void spi_out_ul_log_deinit(void) ul_log_mutex = NULL; ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize upper layer log!"); - ul_log_inited = false; return; } +static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts) +{ + uint16_t total_len = with_ts? (len + sizeof(uint32_t)): len; + bool need_append; + if (spi_out_log_cb_check_trans(ul_log_cb, total_len, &need_append)) { + if (with_ts) { + uint32_t esp_ts = esp_timer_get_time(); + need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, + sizeof(uint32_t), addr, len, source); + } else { + need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source); + } + } + if (need_append) { + spi_out_log_cb_append_trans(ul_log_cb); + } + spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); +} + +static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args) +{ + int len = vsnprintf((char *)ul_log_str_buf, SPI_OUT_UL_LOG_STR_BUF_SIZE, format, args); + if (len < 0) { + return false; + } + + // Truncate string if overflowed + if (len >= SPI_OUT_UL_LOG_STR_BUF_SIZE) { + len = SPI_OUT_UL_LOG_STR_BUF_SIZE - 1; + ul_log_str_buf[len] = '\0'; + } + + spi_out_ul_log_write(source, ul_log_str_buf, len, true); + return true; +} + #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void) { @@ -913,15 +969,8 @@ int ble_log_spi_out_write(uint8_t source, const uint8_t *addr, uint16_t len) return -1; } - bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, len, &need_append)) { - need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source); - } - if (need_append) { - spi_out_log_cb_append_trans(ul_log_cb); - } - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + spi_out_ul_log_write(source, addr, len, false); xSemaphoreGive(ul_log_mutex); return 0; } @@ -936,45 +985,13 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...) va_list args; va_start(args, format); - // Get len as ref to allocate heap memory - va_list args_copy; - va_copy(args_copy, args); - int len = vsnprintf(NULL, 0, format, args_copy); - va_end(args_copy); - - // Length validation - if ((len < 0) || (len > 0xFFFF)) { - va_end(args); - return -1; - } - - // Allocate memory - uint8_t *buffer = malloc(len + 1); - if (!buffer) { - va_end(args); - return -1; - } - - // Generate string - vsnprintf((char *)buffer, len + 1, format, args); - va_end(args); - - uint32_t esp_ts = esp_timer_get_time(); - bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + len, &need_append)) { - need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), - (const uint8_t *)buffer, len, source); - } - if (need_append) { - spi_out_log_cb_append_trans(ul_log_cb); - } - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + bool ret = spi_out_ul_log_printf(source, format, args); xSemaphoreGive(ul_log_mutex); - // Release - free(buffer); - return 0; + va_end(args); + + return ret? 0: -1; } int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, const char *format, ...) @@ -983,54 +1000,19 @@ int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, c return -1; } - // Create log prefix in the format: "[level][tag] " - char prefix[32]; - int prefix_len = snprintf(prefix, sizeof(prefix), "[%d][%s] ", level, tag ? tag : "NULL"); - - // Compute the length of the formatted log message va_list args; va_start(args, format); - va_list args_copy; - va_copy(args_copy, args); - int log_len = vsnprintf(NULL, 0, format, args_copy); - va_end(args_copy); - // Validate length - if (log_len < 0 || log_len > 0xFFFF) { - va_end(args); - return -1; - } - - // Compute total log length (prefix + formatted message) - int total_len = prefix_len + log_len; - - // Allocate memory for the complete log message - uint8_t *buffer = malloc(total_len + 1); - if (!buffer) { - va_end(args); - return -1; - } - - // Construct the final log message - memcpy(buffer, prefix, prefix_len); // Copy the prefix - vsnprintf((char *)(buffer + prefix_len), log_len + 1, format, args); - va_end(args); - - uint32_t esp_ts = esp_timer_get_time(); - bool need_append; + // Create log prefix in the format: "[level][tag] " xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + total_len, &need_append)) { - need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), - (const uint8_t *)buffer, total_len, source); - } - if (need_append) { - spi_out_log_cb_append_trans(ul_log_cb); - } - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + snprintf((char *)ul_log_str_buf, SPI_OUT_UL_LOG_STR_BUF_SIZE, + "[%d][%s] %s", level, tag? tag: "NULL", format); + bool ret = spi_out_ul_log_printf(source, (const char *)ul_log_str_buf, args); xSemaphoreGive(ul_log_mutex); - free(buffer); - return 0; + va_end(args); + + return ret? 0: -1; } int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t len) @@ -1039,16 +1021,8 @@ int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t return -1; } - uint32_t esp_ts = esp_timer_get_time(); - bool need_append; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - if (spi_out_log_cb_check_trans(ul_log_cb, sizeof(uint32_t) + len, &need_append)) { - need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, sizeof(uint32_t), addr, len, source); - } - if (need_append) { - spi_out_log_cb_append_trans(ul_log_cb); - } - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + spi_out_ul_log_write(source, addr, len, true); xSemaphoreGive(ul_log_mutex); return 0; } From e100fc790c9846c13ee44d334a057cce15694e1d Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:29 +0800 Subject: [PATCH 07/16] feat(ble): support le audio log buffer separation (cherry picked from commit cd3aa6527c558e61c225834f31bb3add0ef30b10) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 15 +++ .../bt/common/ble_log/ble_log_spi_out.c | 110 +++++++++++++++--- .../ble_log/include/ble_log/ble_log_spi_out.h | 2 + 3 files changed, 113 insertions(+), 14 deletions(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index 42d05caeea..a09876f6a8 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -116,3 +116,18 @@ config BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT default 1000 help Buffer flush out period in unit of ms + +config BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED + bool "Enable LE Audio log output to SPI" + depends on BT_BLE_LOG_SPI_OUT_ENABLED + default n + help + Enable LE Audio log output to SPI + +config BT_BLE_LOG_SPI_OUT_LE_AUDIO_BUF_SIZE + int "SPI transaction buffer size for LE Audio logs" + depends on BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED + default 1024 + help + SPI transaction buffer size for LE Audio logs. + There will be 2 SPI DMA buffers with the same size. diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index e56d752ed4..190ac24731 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -23,6 +23,8 @@ #define SPI_OUT_SYNC_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM #define SPI_OUT_FLUSH_TIMER_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED #define SPI_OUT_FLUSH_TIMEOUT_US (CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT * 1000) +#define SPI_OUT_LE_AUDIO_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED +#define SPI_OUT_LE_AUDIO_BUF_SIZE CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_BUF_SIZE // Private defines #define BLE_LOG_TAG "BLE_LOG" @@ -82,6 +84,7 @@ enum { LOG_CB_TYPE_LL_TASK, LOG_CB_TYPE_LL_ISR, LOG_CB_TYPE_LL_HCI, + LOG_CB_TYPE_LE_AUDIO, }; enum { @@ -128,6 +131,11 @@ static esp_timer_handle_t ts_sync_timer = NULL; static esp_timer_handle_t flush_timer = NULL; #endif // SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED +static bool le_audio_log_inited = false; +static spi_out_log_cb_t *le_audio_log_cb = NULL; +#endif // SPI_OUT_LE_AUDIO_ENABLED + // Extern function declarations extern void esp_panic_handler_feed_wdts(void); @@ -142,8 +150,9 @@ static void spi_out_log_cb_deinit(spi_out_log_cb_t **log_cb); static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len, bool *need_append); static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_cb); static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb); -static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, \ - const uint8_t *addr_append, uint16_t len_append, uint8_t source); +static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, + const uint8_t *addr_append, uint16_t len_append, uint8_t source, + bool with_checksum); static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, uint8_t flag); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); static void spi_out_log_flush(void); @@ -178,6 +187,11 @@ extern uint32_t r_os_cputime_get32(void); #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED +static int spi_out_le_audio_log_init(void); +static void spi_out_le_audio_log_deinit(void); +#endif // SPI_OUT_LE_AUDIO_ENABLED + // Private functions static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) { @@ -349,8 +363,9 @@ IRAM_ATTR static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb } // Return value: Need append -IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, \ - const uint8_t *addr_append, uint16_t len_append, uint8_t source) +IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, + const uint8_t *addr_append, uint16_t len_append, uint8_t source, + bool with_checksum) { spi_out_trans_cb_t *trans_cb = log_cb->trans_cb[log_cb->trans_cb_idx]; @@ -358,11 +373,13 @@ IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 uint16_t total_length = len + len_append; const uint8_t head[4] = {total_length & 0xFF, (total_length >> 8) & 0xFF, source, log_cb->frame_cnt}; uint32_t checksum = 0; - for (int i = 0; i < len; i++) { - checksum += addr[i]; - } - for (int i = 0; i < len_append; i++) { - checksum += addr_append[i]; + if (with_checksum) { + for (int i = 0; i < len; i++) { + checksum += addr[i]; + } + for (int i = 0; i < len_append; i++) { + checksum += addr_append[i]; + } } memcpy(buf, head, SPI_OUT_FRAME_HEAD_LEN); @@ -392,7 +409,8 @@ IRAM_ATTR static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, packet_loss_frame[0] = flag; memcpy(packet_loss_frame + 1, (uint8_t *)&log_cb->bytes_loss_cnt, 4); packet_loss_frame[5] = log_cb->trans_loss_cnt; - spi_out_log_cb_write(log_cb, packet_loss_frame, SPI_OUT_PACKET_LOSS_FRAME_SIZE, NULL, 0, BLE_LOG_SPI_OUT_SOURCE_LOSS); + spi_out_log_cb_write(log_cb, packet_loss_frame, SPI_OUT_PACKET_LOSS_FRAME_SIZE, + NULL, 0, BLE_LOG_SPI_OUT_SOURCE_LOSS, true); log_cb->bytes_loss_cnt = 0; log_cb->trans_loss_cnt = 0; @@ -515,9 +533,9 @@ static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t l if (with_ts) { uint32_t esp_ts = esp_timer_get_time(); need_append |= spi_out_log_cb_write(ul_log_cb, (const uint8_t *)&esp_ts, - sizeof(uint32_t), addr, len, source); + sizeof(uint32_t), addr, len, source, true); } else { - need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source); + need_append |= spi_out_log_cb_write(ul_log_cb, addr, len, NULL, 0, source, true); } } if (need_append) { @@ -728,6 +746,40 @@ static void esp_timer_cb_ts_sync(void) } #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED +static int spi_out_le_audio_log_init(void) +{ + if (le_audio_log_inited) { + return 0; + } + + // Initialize log control blocks for controller task & ISR logs + if (spi_out_log_cb_init(&le_audio_log_cb, SPI_OUT_LE_AUDIO_BUF_SIZE) != 0) { + ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for LE audio!"); + return -1; + } + + // Initialization done + ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize log control blocks for LE Audio!"); + le_audio_log_inited = true; + return 0; +} + +static void spi_out_le_audio_log_deinit(void) +{ + if (!le_audio_log_inited) { + return; + } + + spi_out_log_cb_deinit(&le_audio_log_cb); + + // Deinitialization done + ESP_LOGI(BLE_LOG_TAG, "Succeeded to deinitialize LE audio log!"); + le_audio_log_inited = false; + return; +} +#endif // SPI_OUT_LE_AUDIO_ENABLED + // Public functions int ble_log_spi_out_init(void) { @@ -782,6 +834,12 @@ int ble_log_spi_out_init(void) } #endif // SPI_OUT_TS_SYNC_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED + if (spi_out_le_audio_log_init() != 0) { + goto le_audio_init_failed; + } +#endif // SPI_OUT_LE_AUDIO_ENABLED + #if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_create_args_t timer_args = { .callback = (esp_timer_cb_t)esp_timer_cb_log_flush, @@ -806,6 +864,10 @@ int ble_log_spi_out_init(void) #if SPI_OUT_FLUSH_TIMER_ENABLED timer_init_failed: #endif // SPI_OUT_FLUSH_TIMER_ENABLED +#if SPI_OUT_LE_AUDIO_ENABLED + spi_out_le_audio_log_deinit(); +le_audio_init_failed: +#endif // SPI_OUT_LE_AUDIO_ENABLED #if SPI_OUT_TS_SYNC_ENABLED spi_out_ts_sync_deinit(); ts_sync_init_failed: @@ -898,7 +960,7 @@ void ble_log_spi_out_ts_sync_stop(void) #if SPI_OUT_LL_ENABLED // Only LL task has access to this API -IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint32_t len_append,\ +IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint32_t len_append, const uint8_t *addr_append, uint32_t flag) { if (!ll_log_inited) { @@ -926,7 +988,8 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 bool need_append; if (spi_out_log_cb_check_trans(log_cb, (uint16_t)(len + len_append), &need_append)) { - need_append |= spi_out_log_cb_write(log_cb, addr, (uint16_t)len, addr_append, (uint16_t)len_append, source); + need_append |= spi_out_log_cb_write(log_cb, addr, (uint16_t)len, addr_append, + (uint16_t)len_append, source, true); } if (need_append) { if (in_isr) { @@ -1078,4 +1141,23 @@ void ble_log_spi_out_flush(void) spi_out_log_flush(); } +#if CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED +IRAM_ATTR void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len) +{ + if (!le_audio_log_inited) { + return; + } + + bool need_append; + if (spi_out_log_cb_check_trans(le_audio_log_cb, len, &need_append)) { + need_append |= spi_out_log_cb_write(le_audio_log_cb, addr, len, NULL, 0, + BLE_LOG_SPI_OUT_SOURCE_LE_AUDIO, false); + } + if (need_append) { + spi_out_log_cb_append_trans(le_audio_log_cb); + } + spi_out_log_cb_write_packet_loss(le_audio_log_cb, LOG_CB_TYPE_LE_AUDIO); + return; +} +#endif // CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h index 152c891e8e..4d251c6d08 100644 --- a/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h +++ b/components/bt/common/ble_log/include/ble_log/ble_log_spi_out.h @@ -25,6 +25,7 @@ enum { BLE_LOG_SPI_OUT_SOURCE_ESP_ISR, BLE_LOG_SPI_OUT_SOURCE_ESP_LEGACY_ISR, BLE_LOG_SPI_OUT_SOURCE_LL_HCI, + BLE_LOG_SPI_OUT_SOURCE_LE_AUDIO, BLE_LOG_SPI_OUT_SOURCE_USER = 0x10, BLE_LOG_SPI_OUT_SOURCE_SSC = 0xFD, BLE_LOG_SPI_OUT_SOURCE_SYNC, @@ -57,5 +58,6 @@ int ble_log_spi_out_write_with_ts(uint8_t source, const uint8_t *addr, uint16_t void ble_log_spi_out_dump_all(void); void ble_log_spi_out_enable(bool enable); void ble_log_spi_out_flush(void); +void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len); #endif // __BT_SPI_OUT_H__ From 5be9ac3d9315c896e9e2ca32efadf78a32421a04 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:31 +0800 Subject: [PATCH 08/16] feat(ble): refactored loss report module and represent frame using struct (cherry picked from commit 9800d715a516f6c92110a015a14be1137df79edf) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 104 +++++++++++------- 1 file changed, 63 insertions(+), 41 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 190ac24731..a9d24914a4 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -67,11 +67,30 @@ typedef struct { typedef struct { spi_out_trans_cb_t *trans_cb[2]; uint8_t trans_cb_idx; - uint8_t frame_cnt; - uint32_t bytes_loss_cnt; - uint8_t trans_loss_cnt; + uint8_t frame_sn; + uint16_t lost_frame_cnt; + uint32_t lost_bytes_cnt; + uint8_t type; } spi_out_log_cb_t; +typedef struct { + uint16_t length; + uint8_t source; + uint8_t frame_sn; +} __attribute__((packed)) frame_head_t; + +typedef struct { + uint8_t type; + uint16_t lost_frame_cnt; + uint32_t lost_bytes_cnt; +} __attribute__((packed)) loss_payload_t; + +typedef struct { + uint8_t io_level; + uint32_t lc_ts; + uint32_t esp_ts; +} __attribute__((packed)) sync_payload_t; + // Private enums enum { TRANS_CB_FLAG_AVAILABLE = 0, @@ -145,7 +164,7 @@ static void spi_out_deinit_trans(spi_out_trans_cb_t **trans_cb); static void spi_out_tx_done_cb(spi_transaction_t *ret_trans); static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb); -static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size); +static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type); static void spi_out_log_cb_deinit(spi_out_log_cb_t **log_cb); static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb, uint16_t len, bool *need_append); static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_cb); @@ -153,7 +172,7 @@ static inline void spi_out_log_cb_flush_trans(spi_out_log_cb_t *log_cb); static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8_t *addr, uint16_t len, const uint8_t *addr_append, uint16_t len_append, uint8_t source, bool with_checksum); -static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, uint8_t flag); +static void spi_out_log_cb_write_loss(spi_out_log_cb_t *log_cb); static void spi_out_log_cb_dump(spi_out_log_cb_t *log_cb); static void spi_out_log_flush(void); @@ -270,7 +289,7 @@ IRAM_ATTR static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb) } } -static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size) +static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type) { // Initialize log control block *log_cb = (spi_out_log_cb_t *)malloc(sizeof(spi_out_log_cb_t)); @@ -290,6 +309,8 @@ static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size) spi_out_log_cb_deinit(log_cb); return -1; } + + (*log_cb)->type = type; return 0; } @@ -330,8 +351,9 @@ IRAM_ATTR static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb log_cb->trans_cb_idx = !(log_cb->trans_cb_idx); } failed: - log_cb->bytes_loss_cnt += len + SPI_OUT_FRAME_OVERHEAD; - log_cb->frame_cnt++; + log_cb->lost_bytes_cnt += frame_len; + log_cb->lost_frame_cnt++; + log_cb->frame_sn++; return false; } @@ -343,9 +365,7 @@ IRAM_ATTR static inline void spi_out_log_cb_append_trans(spi_out_log_cb_t *log_c for (uint8_t i = 0; i < 2; i++) { trans_cb = log_cb->trans_cb[idx]; if (trans_cb->flag == TRANS_CB_FLAG_NEED_QUEUE) { - if (spi_out_append_trans(trans_cb) != 0) { - log_cb->trans_loss_cnt++; - } + spi_out_append_trans(trans_cb); } idx = !idx; } @@ -371,7 +391,11 @@ IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 uint8_t *buf = (uint8_t *)trans_cb->trans.tx_buffer + trans_cb->length; uint16_t total_length = len + len_append; - const uint8_t head[4] = {total_length & 0xFF, (total_length >> 8) & 0xFF, source, log_cb->frame_cnt}; + frame_head_t head = { + .length = total_length, + .source = source, + .frame_sn = log_cb->frame_sn, + }; uint32_t checksum = 0; if (with_checksum) { for (int i = 0; i < len; i++) { @@ -382,7 +406,7 @@ IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 } } - memcpy(buf, head, SPI_OUT_FRAME_HEAD_LEN); + memcpy(buf, (const uint8_t *)&head, SPI_OUT_FRAME_HEAD_LEN); memcpy(buf + SPI_OUT_FRAME_HEAD_LEN, addr, len); if (len_append) { memcpy(buf + SPI_OUT_FRAME_HEAD_LEN + len, addr_append, len_append); @@ -390,7 +414,7 @@ IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 memcpy(buf + SPI_OUT_FRAME_HEAD_LEN + total_length, &checksum, SPI_OUT_FRAME_TAIL_LEN); trans_cb->length += total_length + SPI_OUT_FRAME_OVERHEAD; - log_cb->frame_cnt++; + log_cb->frame_sn++; if ((trans_cb->buf_size - trans_cb->length) <= SPI_OUT_FRAME_OVERHEAD) { trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; return true; @@ -398,22 +422,23 @@ IRAM_ATTR static bool spi_out_log_cb_write(spi_out_log_cb_t *log_cb, const uint8 return false; } -IRAM_ATTR static void spi_out_log_cb_write_packet_loss(spi_out_log_cb_t *log_cb, uint8_t flag) +IRAM_ATTR static void spi_out_log_cb_write_loss(spi_out_log_cb_t *log_cb) { - if (!log_cb->bytes_loss_cnt && !log_cb->trans_loss_cnt) { + if (!log_cb->lost_bytes_cnt || !log_cb->lost_frame_cnt) { return; } bool need_append; - if (spi_out_log_cb_check_trans(log_cb, SPI_OUT_PACKET_LOSS_FRAME_SIZE, &need_append)) { - uint8_t packet_loss_frame[SPI_OUT_PACKET_LOSS_FRAME_SIZE]; - packet_loss_frame[0] = flag; - memcpy(packet_loss_frame + 1, (uint8_t *)&log_cb->bytes_loss_cnt, 4); - packet_loss_frame[5] = log_cb->trans_loss_cnt; - spi_out_log_cb_write(log_cb, packet_loss_frame, SPI_OUT_PACKET_LOSS_FRAME_SIZE, + if (spi_out_log_cb_check_trans(log_cb, sizeof(loss_payload_t), &need_append)) { + loss_payload_t payload = { + .type = log_cb->type, + .lost_frame_cnt = log_cb->lost_frame_cnt, + .lost_bytes_cnt = log_cb->lost_bytes_cnt, + }; + spi_out_log_cb_write(log_cb, (const uint8_t *)&payload, sizeof(loss_payload_t), NULL, 0, BLE_LOG_SPI_OUT_SOURCE_LOSS, true); - log_cb->bytes_loss_cnt = 0; - log_cb->trans_loss_cnt = 0; + log_cb->lost_frame_cnt = 0; + log_cb->lost_bytes_cnt = 0; } } @@ -482,7 +507,7 @@ static int spi_out_ul_log_init(void) } // Initialize log control block - if (spi_out_log_cb_init(&ul_log_cb, SPI_OUT_UL_TASK_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ul_log_cb, SPI_OUT_UL_TASK_BUF_SIZE, LOG_CB_TYPE_UL) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for upper layer task log!"); goto log_cb_init_failed; } @@ -541,7 +566,7 @@ static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t l if (need_append) { spi_out_log_cb_append_trans(ul_log_cb); } - spi_out_log_cb_write_packet_loss(ul_log_cb, LOG_CB_TYPE_UL); + spi_out_log_cb_write_loss(ul_log_cb); } static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args) @@ -569,15 +594,15 @@ static int spi_out_ll_log_init(void) } // Initialize log control blocks for controller task & ISR logs - if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ll_task_log_cb, SPI_OUT_LL_TASK_BUF_SIZE, LOG_CB_TYPE_LL_TASK) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller task!"); goto task_log_cb_init_failed; } - if (spi_out_log_cb_init(&ll_isr_log_cb, SPI_OUT_LL_ISR_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ll_isr_log_cb, SPI_OUT_LL_ISR_BUF_SIZE, LOG_CB_TYPE_LL_ISR) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); goto isr_log_cb_init_failed; } - if (spi_out_log_cb_init(&ll_hci_log_cb, SPI_OUT_LL_HCI_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&ll_hci_log_cb, SPI_OUT_LL_HCI_BUF_SIZE, LOG_CB_TYPE_LL_HCI) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for controller ISR!"); goto hci_log_cb_init_failed; } @@ -738,11 +763,12 @@ static void esp_timer_cb_ts_sync(void) // Exit critical // Write timestamp sync log - uint8_t sync_frame[9]; - sync_frame[0] = ((uint8_t)sync_io_level & 0xFF); - memcpy(sync_frame + 1, &lc_ts, sizeof(lc_ts)); - memcpy(sync_frame + 5, &esp_ts, sizeof(esp_ts)); - ble_log_spi_out_write(BLE_LOG_SPI_OUT_SOURCE_SYNC, sync_frame, 9); + sync_payload_t payload = { + .io_level = sync_io_level, + .lc_ts = lc_ts, + .esp_ts = esp_ts, + }; + ble_log_spi_out_write(BLE_LOG_SPI_OUT_SOURCE_SYNC, (const uint8_t *)&payload, sizeof(sync_payload_t)); } #endif // SPI_OUT_TS_SYNC_ENABLED @@ -754,7 +780,7 @@ static int spi_out_le_audio_log_init(void) } // Initialize log control blocks for controller task & ISR logs - if (spi_out_log_cb_init(&le_audio_log_cb, SPI_OUT_LE_AUDIO_BUF_SIZE) != 0) { + if (spi_out_log_cb_init(&le_audio_log_cb, SPI_OUT_LE_AUDIO_BUF_SIZE, LOG_CB_TYPE_LE_AUDIO) != 0) { ESP_LOGE(BLE_LOG_TAG, "Failed to initialize log control blocks for LE audio!"); return -1; } @@ -968,21 +994,17 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 } bool in_isr = false; - uint8_t log_cb_type; uint8_t source; spi_out_log_cb_t *log_cb; if (flag & BIT(LL_LOG_FLAG_ISR)) { log_cb = ll_isr_log_cb; - log_cb_type = LOG_CB_TYPE_LL_ISR; source = BLE_LOG_SPI_OUT_SOURCE_ESP_ISR; in_isr = true; } else if (flag & BIT(LL_LOG_FLAG_HCI)) { log_cb = ll_hci_log_cb; - log_cb_type = LOG_CB_TYPE_LL_HCI; source = BLE_LOG_SPI_OUT_SOURCE_ESP; } else { log_cb = ll_task_log_cb; - log_cb_type = LOG_CB_TYPE_LL_TASK; source = BLE_LOG_SPI_OUT_SOURCE_ESP; } @@ -999,7 +1021,7 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 spi_out_log_cb_append_trans(log_cb); } } - spi_out_log_cb_write_packet_loss(log_cb, log_cb_type); + spi_out_log_cb_write_loss(log_cb); // Update controller status if (!in_isr) { @@ -1156,7 +1178,7 @@ IRAM_ATTR void ble_log_spi_out_le_audio_write(const uint8_t *addr, uint16_t len) if (need_append) { spi_out_log_cb_append_trans(le_audio_log_cb); } - spi_out_log_cb_write_packet_loss(le_audio_log_cb, LOG_CB_TYPE_LE_AUDIO); + spi_out_log_cb_write_loss(le_audio_log_cb); return; } #endif // CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED From 4c7a13b570f5e9f3799461f0e5b6f233c44bd24d Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:34 +0800 Subject: [PATCH 09/16] feat(ble): support controller raw log print out (cherry picked from commit ed09e97c66618f49df4070b46abe25ed315992e9) Co-authored-by: Zhou Xiao --- components/bt/common/ble_log/ble_log_spi_out.c | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index a9d24914a4..dc52d0a73f 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -231,6 +231,7 @@ static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size) // Initialization (*trans_cb)->buf_size = buf_size; (*trans_cb)->trans.tx_buffer = buf; + (*trans_cb)->trans.user = (void *)(*trans_cb); return 0; } @@ -252,7 +253,7 @@ static void spi_out_deinit_trans(spi_out_trans_cb_t **trans_cb) IRAM_ATTR static void spi_out_tx_done_cb(spi_transaction_t *ret_trans) { last_tx_done_ts = esp_timer_get_time(); - spi_out_trans_cb_t *trans_cb = __containerof(ret_trans, spi_out_trans_cb_t, trans); + spi_out_trans_cb_t *trans_cb = (spi_out_trans_cb_t *)ret_trans->user; trans_cb->length = 0; trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; } @@ -989,6 +990,17 @@ void ble_log_spi_out_ts_sync_stop(void) IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint32_t len_append, const uint8_t *addr_append, uint32_t flag) { + // Raw logs will come in case of assert, shall be printed to console directly + if (flag & BIT(LL_LOG_FLAG_RAW)) { + if (len && addr) { + for (uint32_t i = 0; i < len; i++) { esp_rom_printf("%02x ", addr[i]); } + } + if (len_append && addr_append) { + for (uint32_t i = 0; i < len_append; i++) { esp_rom_printf("%02x ", addr_append[i]); } + } + if (flag & BIT(LL_LOG_FLAG_END)) { esp_rom_printf("\n"); } + } + if (!ll_log_inited) { return; } From 059a675e5c96d2b83afde5e733b900a152b0e935 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:36 +0800 Subject: [PATCH 10/16] feat(ble): support ts sync for sleep app (cherry picked from commit e10460ce14b9493990d7cf4e2ed330ca0233cdbe) Co-authored-by: Zhou Xiao --- components/bt/common/Kconfig.in | 7 + .../bt/common/ble_log/ble_log_spi_out.c | 171 ++++++++++-------- 2 files changed, 105 insertions(+), 73 deletions(-) diff --git a/components/bt/common/Kconfig.in b/components/bt/common/Kconfig.in index a09876f6a8..ff1947a326 100644 --- a/components/bt/common/Kconfig.in +++ b/components/bt/common/Kconfig.in @@ -102,6 +102,13 @@ config BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM help GPIO number of SYNC IO +config BT_BLE_LOG_SPI_OUT_TS_SYNC_SLEEP_SUPPORT + bool "Enable ble log & logic analyzer log time sync sleep support" + depends on BT_BLE_LOG_SPI_OUT_LL_ENABLED + default n + help + Enable ble log & logic analyzer log time sync sleep support + config BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED bool "Enable periodic buffer flush out" depends on BT_BLE_LOG_SPI_OUT_ENABLED diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index dc52d0a73f..7b515ac9bf 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -21,6 +21,7 @@ #define SPI_OUT_CS_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_CS_IO_NUM #define SPI_OUT_TS_SYNC_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_ENABLED #define SPI_OUT_SYNC_IO_NUM CONFIG_BT_BLE_LOG_SPI_OUT_SYNC_IO_NUM +#define SPI_OUT_TS_SYNC_SLEEP_SUPPORT CONFIG_BT_BLE_LOG_SPI_OUT_TS_SYNC_SLEEP_SUPPORT #define SPI_OUT_FLUSH_TIMER_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMER_ENABLED #define SPI_OUT_FLUSH_TIMEOUT_US (CONFIG_BT_BLE_LOG_SPI_OUT_FLUSH_TIMEOUT * 1000) #define SPI_OUT_LE_AUDIO_ENABLED CONFIG_BT_BLE_LOG_SPI_OUT_LE_AUDIO_ENABLED @@ -89,7 +90,7 @@ typedef struct { uint8_t io_level; uint32_t lc_ts; uint32_t esp_ts; -} __attribute__((packed)) sync_payload_t; +} __attribute__((packed)) ts_sync_data_t; // Private enums enum { @@ -137,13 +138,16 @@ static spi_out_log_cb_t *ll_task_log_cb = NULL; static spi_out_log_cb_t *ll_isr_log_cb = NULL; static spi_out_log_cb_t *ll_hci_log_cb = NULL; static uint32_t ll_ev_flags = 0; -static esp_bt_controller_status_t ll_status = ESP_BT_CONTROLLER_STATUS_IDLE; #endif // SPI_OUT_LL_ENABLED #if SPI_OUT_TS_SYNC_ENABLED static bool ts_sync_inited = false; -static bool sync_io_level = false; +static bool ts_sync_enabled = false; +static ts_sync_data_t ts_sync_data = {0}; + +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT static esp_timer_handle_t ts_sync_timer = NULL; +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT #endif // SPI_OUT_TS_SYNC_ENABLED #if SPI_OUT_FLUSH_TIMER_ENABLED @@ -185,13 +189,24 @@ static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list ar static int spi_out_ll_log_init(void); static void spi_out_ll_log_deinit(void); static void spi_out_ll_log_flush(void); -static inline void spi_out_ll_log_put_ev(void); + +#if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\ + defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) +extern void r_ble_log_simple_put_ev(void); +#define SPI_OUT_LL_PUT_EV r_ble_log_simple_put_ev() +#elif defined(CONFIG_IDF_TARGET_ESP32C2) +extern void ble_log_simple_put_ev(void); +#define SPI_OUT_LL_PUT_EV ble_log_simple_put_ev() +#else +#define SPI_OUT_LL_PUT_EV +#endif #endif // SPI_OUT_LL_ENABLED #if SPI_OUT_TS_SYNC_ENABLED static int spi_out_ts_sync_init(void); static void spi_out_ts_sync_deinit(void); -static void esp_timer_cb_ts_sync(void); +static void spi_out_ts_sync_enable(bool enable); +static void spi_out_ts_sync_toggle(void); #if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\ defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) @@ -204,6 +219,9 @@ extern uint32_t r_os_cputime_get32(void); #define SPI_OUT_GET_LC_TIME 0 #endif +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT +static void esp_timer_cb_ts_sync(void); +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT #endif // SPI_OUT_TS_SYNC_ENABLED #if SPI_OUT_LE_AUDIO_ENABLED @@ -472,9 +490,10 @@ static void spi_out_log_flush(void) xSemaphoreGive(ul_log_mutex); #if SPI_OUT_LL_ENABLED - // LL log flush shall be run in LL task context - ll_ev_flags |= BIT(LL_EV_FLAG_FLUSH_LOG); - spi_out_ll_log_put_ev(); + if (esp_bt_controller_get_status() >= ESP_BT_CONTROLLER_STATUS_INITED) { + ll_ev_flags |= BIT(LL_EV_FLAG_FLUSH_LOG); + SPI_OUT_LL_PUT_EV; + } #endif // SPI_OUT_LL_ENABLED } @@ -637,23 +656,6 @@ static void spi_out_ll_log_deinit(void) return; } -IRAM_ATTR static inline void spi_out_ll_log_put_ev(void) -{ - if (ll_status < ESP_BT_CONTROLLER_STATUS_INITED) { - return; - } - -#if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\ - defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) - extern void r_ble_log_simple_put_ev(void); - r_ble_log_simple_put_ev(); -#elif defined(CONFIG_IDF_TARGET_ESP32C2) - extern void ble_log_simple_put_ev(void); - ble_log_simple_put_ev(); -#else -#endif -} - // Context: LL task static void spi_out_ll_log_flush(void) { @@ -681,6 +683,7 @@ static int spi_out_ts_sync_init(void) return 0; } +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT // Initialize sync timer esp_timer_create_args_t timer_args = { .callback = (esp_timer_cb_t)esp_timer_cb_ts_sync, @@ -690,12 +693,13 @@ static int spi_out_ts_sync_init(void) ESP_LOGE(BLE_LOG_TAG, "Failed to initialize timestamp synchronizer timer!"); goto timer_init_failed; } +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT // Initialize sync IO gpio_config_t io_conf = { .intr_type = GPIO_INTR_DISABLE, .mode = GPIO_MODE_OUTPUT, - .pin_bit_mask = (1UL << SPI_OUT_SYNC_IO_NUM), + .pin_bit_mask = BIT(SPI_OUT_SYNC_IO_NUM), .pull_down_en = 0, .pull_up_en = 0 }; @@ -706,14 +710,14 @@ static int spi_out_ts_sync_init(void) // Initialization done ESP_LOGI(BLE_LOG_TAG, "Succeeded to initialize timestamp synchronizer!"); - sync_io_level = false; - gpio_set_level(SPI_OUT_SYNC_IO_NUM, sync_io_level); ts_sync_inited = true; return 0; gpio_init_failed: +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT esp_timer_delete(ts_sync_timer); timer_init_failed: +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT return -1; } @@ -723,13 +727,14 @@ static void spi_out_ts_sync_deinit(void) return; } +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT // Deinitialize timestamp synchronizer esp_timer_stop(ts_sync_timer); esp_timer_delete(ts_sync_timer); +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT // Deinitialize sync IO - sync_io_level = false; - gpio_set_level(SPI_OUT_SYNC_IO_NUM, sync_io_level); + spi_out_ts_sync_enable(false); gpio_reset_pin(SPI_OUT_SYNC_IO_NUM); // Deinitialization done @@ -738,39 +743,67 @@ static void spi_out_ts_sync_deinit(void) return; } -// CRITICAL: This function is called in ESP Timer task -static void esp_timer_cb_ts_sync(void) +static void spi_out_ts_sync_enable(bool enable) { - // Initialize variables - uint32_t lc_ts = 0; - uint32_t esp_ts = 0; + // Reset ts sync io + ts_sync_data.io_level = false; + gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)ts_sync_data.io_level); + // Update ts sync status + ts_sync_enabled = enable; + if (enable) { +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT + // Start timestamp sync timer + if (ts_sync_timer) { + if (!esp_timer_is_active(ts_sync_timer)) { + esp_timer_start_periodic(ts_sync_timer, SPI_OUT_TS_SYNC_TIMEOUT); + } + } +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT + } else { +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT + // Stop timestamp sync timer + if (ts_sync_timer) { + if (esp_timer_is_active(ts_sync_timer)) { + esp_timer_stop(ts_sync_timer); + } + } +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT + } +} + +static void spi_out_ts_sync_toggle(void) +{ // Toggle sync IO - sync_io_level = !sync_io_level; + ts_sync_data.io_level = !ts_sync_data.io_level; // Enter critical portMUX_TYPE spinlock = portMUX_INITIALIZER_UNLOCKED; portENTER_CRITICAL(&spinlock); // Get LC timestamp - lc_ts = SPI_OUT_GET_LC_TIME; + ts_sync_data.lc_ts = SPI_OUT_GET_LC_TIME; // Set sync IO level - gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)sync_io_level); + gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)ts_sync_data.io_level); // Get ESP timestamp - esp_ts = esp_timer_get_time(); + ts_sync_data.esp_ts = esp_timer_get_time(); portEXIT_CRITICAL(&spinlock); // Exit critical - - // Write timestamp sync log - sync_payload_t payload = { - .io_level = sync_io_level, - .lc_ts = lc_ts, - .esp_ts = esp_ts, - }; - ble_log_spi_out_write(BLE_LOG_SPI_OUT_SOURCE_SYNC, (const uint8_t *)&payload, sizeof(sync_payload_t)); } + +#if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT +// CRITICAL: This function is called in ESP Timer task +static void esp_timer_cb_ts_sync(void) +{ + spi_out_ts_sync_toggle(); + ble_log_spi_out_write(BLE_LOG_SPI_OUT_SOURCE_SYNC, (const uint8_t *)&ts_sync_data, + sizeof(ts_sync_data_t)); +} +#else + +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT #endif // SPI_OUT_TS_SYNC_ENABLED #if SPI_OUT_LE_AUDIO_ENABLED @@ -956,13 +989,7 @@ void ble_log_spi_out_ts_sync_start(void) if (!spi_out_inited) { return; } - - // Start timestamp sync timer - if (ts_sync_timer) { - if (!esp_timer_is_active(ts_sync_timer)) { - esp_timer_start_periodic(ts_sync_timer, SPI_OUT_TS_SYNC_TIMEOUT); - } - } + spi_out_ts_sync_enable(true); } void ble_log_spi_out_ts_sync_stop(void) @@ -971,17 +998,7 @@ void ble_log_spi_out_ts_sync_stop(void) if (!spi_out_inited) { return; } - - // Stop timestamp sync timer - if (ts_sync_timer) { - if (esp_timer_is_active(ts_sync_timer)) { - esp_timer_stop(ts_sync_timer); - } - - // Set sync IO to low level - sync_io_level = 0; - gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)sync_io_level); - } + spi_out_ts_sync_enable(false); } #endif // SPI_OUT_TS_SYNC_ENABLED @@ -1014,7 +1031,7 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 in_isr = true; } else if (flag & BIT(LL_LOG_FLAG_HCI)) { log_cb = ll_hci_log_cb; - source = BLE_LOG_SPI_OUT_SOURCE_ESP; + source = BLE_LOG_SPI_OUT_SOURCE_LL_HCI; } else { log_cb = ll_task_log_cb; source = BLE_LOG_SPI_OUT_SOURCE_ESP; @@ -1028,18 +1045,24 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 if (need_append) { if (in_isr) { ll_ev_flags |= BIT(LL_EV_FLAG_ISR_APPEND); - spi_out_ll_log_put_ev(); + SPI_OUT_LL_PUT_EV; } else { spi_out_log_cb_append_trans(log_cb); + +#if SPI_OUT_TS_SYNC_SLEEP_SUPPORT + if (ts_sync_inited && ts_sync_enabled) { + if ((last_tx_done_ts - ts_sync_data.esp_ts) >= SPI_OUT_TS_SYNC_TIMEOUT) { + if (spi_out_log_cb_check_trans(ll_task_log_cb, sizeof(ts_sync_data_t), &need_append)) { + spi_out_ts_sync_toggle(); + spi_out_log_cb_write(ll_task_log_cb, (const uint8_t *)&ts_sync_data, + sizeof(ts_sync_data_t), NULL, 0, BLE_LOG_SPI_OUT_SOURCE_SYNC, true); + } + } + } +#endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT } } spi_out_log_cb_write_loss(log_cb); - - // Update controller status - if (!in_isr) { - ll_status = esp_bt_controller_get_status(); - } - return; } IRAM_ATTR void ble_log_spi_out_ll_log_ev_proc(void) @@ -1057,6 +1080,8 @@ IRAM_ATTR void ble_log_spi_out_ll_log_ev_proc(void) spi_out_ll_log_flush(); ll_ev_flags &= ~BIT(LL_EV_FLAG_FLUSH_LOG); } + + ll_ev_flags = 0; } #endif // SPI_OUT_LL_ENABLED From 1c81d11ec331ffa6f98ee06a33502be1a6d30800 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Thu, 22 May 2025 16:55:39 +0800 Subject: [PATCH 11/16] fix(ble): fixed upper layer trans append failure bug (cherry picked from commit 1e6bc70837410ffe7c09a77f8793d16ef042158d) Co-authored-by: Zhou Xiao --- .../bt/common/ble_log/ble_log_spi_out.c | 28 +++++++++---------- 1 file changed, 14 insertions(+), 14 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 7b515ac9bf..bdeb79f117 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -166,7 +166,7 @@ extern void esp_panic_handler_feed_wdts(void); static int spi_out_init_trans(spi_out_trans_cb_t **trans_cb, uint16_t buf_size); static void spi_out_deinit_trans(spi_out_trans_cb_t **trans_cb); static void spi_out_tx_done_cb(spi_transaction_t *ret_trans); -static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb); +static inline void spi_out_append_trans(spi_out_trans_cb_t *trans_cb); static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type); static void spi_out_log_cb_deinit(spi_out_log_cb_t **log_cb); @@ -282,30 +282,30 @@ IRAM_ATTR static void spi_out_pre_tx_cb(spi_transaction_t *ret_trans) while (esp_timer_get_time() - last_tx_done_ts < SPI_OUT_TRANS_ITVL_MIN_US) {} } -IRAM_ATTR static inline int spi_out_append_trans(spi_out_trans_cb_t *trans_cb) +IRAM_ATTR static inline void spi_out_append_trans(spi_out_trans_cb_t *trans_cb) { if (trans_cb->flag != TRANS_CB_FLAG_NEED_QUEUE || !trans_cb->length) { - return -1; + return; } // Note: To support dump log when disabled if (!spi_out_enabled) { - trans_cb->length = 0; - trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; - return 0; + goto recycle; } // CRITICAL: Length unit conversion from bytes to bits trans_cb->trans.length = trans_cb->length * 8; trans_cb->trans.rxlength = 0; - if (spi_device_queue_trans(spi_handle, &(trans_cb->trans), 0) == ESP_OK) { - trans_cb->flag = TRANS_CB_FLAG_IN_QUEUE; - return 0; - } else { - trans_cb->length = 0; - trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; - return -1; + trans_cb->flag = TRANS_CB_FLAG_IN_QUEUE; + if (spi_device_queue_trans(spi_handle, &(trans_cb->trans), 0) != ESP_OK) { + goto recycle; } + return; + +recycle: + trans_cb->length = 0; + trans_cb->flag = TRANS_CB_FLAG_AVAILABLE; + return; } static int spi_out_log_cb_init(spi_out_log_cb_t **log_cb, uint16_t buf_size, uint8_t type) @@ -360,7 +360,7 @@ IRAM_ATTR static inline bool spi_out_log_cb_check_trans(spi_out_log_cb_t *log_cb goto failed; } if (trans_cb->flag == TRANS_CB_FLAG_AVAILABLE) { - if ((trans_cb->buf_size - trans_cb->length) >= (len + SPI_OUT_FRAME_OVERHEAD)) { + if ((trans_cb->buf_size - trans_cb->length) >= frame_len) { return true; } else { trans_cb->flag = TRANS_CB_FLAG_NEED_QUEUE; From 0904640409d138a796ef887ff6c9b2aa7ad04e7e Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Fri, 23 May 2025 12:29:46 +0800 Subject: [PATCH 12/16] fix(ble): fixed printf va list cross function pass failure --- .../bt/common/ble_log/ble_log_spi_out.c | 40 ++++++++++++++----- 1 file changed, 30 insertions(+), 10 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index bdeb79f117..e2624a2a95 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -183,7 +183,7 @@ static void spi_out_log_flush(void); static int spi_out_ul_log_init(void); static void spi_out_ul_log_deinit(void); static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t len, bool with_ts); -static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args); +static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args, int offset); #if SPI_OUT_LL_ENABLED static int spi_out_ll_log_init(void); @@ -589,12 +589,14 @@ static void spi_out_ul_log_write(uint8_t source, const uint8_t *addr, uint16_t l spi_out_log_cb_write_loss(ul_log_cb); } -static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args) +static bool spi_out_ul_log_printf(uint8_t source, const char *format, va_list args, int offset) { - int len = vsnprintf((char *)ul_log_str_buf, SPI_OUT_UL_LOG_STR_BUF_SIZE, format, args); + int len = vsnprintf((char *)(ul_log_str_buf + offset), + SPI_OUT_UL_LOG_STR_BUF_SIZE - offset, format, args); if (len < 0) { return false; } + len += offset; // Truncate string if overflowed if (len >= SPI_OUT_UL_LOG_STR_BUF_SIZE) { @@ -1103,16 +1105,23 @@ int ble_log_spi_out_printf(uint8_t source, const char *format, ...) return -1; } + if (!format) { + return -1; + } + // Get arguments va_list args; va_start(args, format); + va_list args_copy; + va_copy(args_copy, args); + xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - bool ret = spi_out_ul_log_printf(source, format, args); + bool ret = spi_out_ul_log_printf(source, format, args_copy, 0); xSemaphoreGive(ul_log_mutex); + va_end(args_copy); va_end(args); - return ret? 0: -1; } @@ -1122,18 +1131,29 @@ int ble_log_spi_out_printf_enh(uint8_t source, uint8_t level, const char *tag, c return -1; } + if (!tag || !format) { + return -1; + } + va_list args; va_start(args, format); + va_list args_copy; + va_copy(args_copy, args); + // Create log prefix in the format: "[level][tag] " + bool ret = false; xSemaphoreTake(ul_log_mutex, portMAX_DELAY); - snprintf((char *)ul_log_str_buf, SPI_OUT_UL_LOG_STR_BUF_SIZE, - "[%d][%s] %s", level, tag? tag: "NULL", format); - bool ret = spi_out_ul_log_printf(source, (const char *)ul_log_str_buf, args); + int prefix_len = snprintf((char *)ul_log_str_buf, SPI_OUT_UL_LOG_STR_BUF_SIZE, + "[%d][%s]", level, tag? tag: "NULL"); + if ((prefix_len < 0) || (prefix_len >= SPI_OUT_UL_LOG_STR_BUF_SIZE)) { + goto exit; + } + ret = spi_out_ul_log_printf(source, format, args_copy, prefix_len); +exit: xSemaphoreGive(ul_log_mutex); - + va_end(args_copy); va_end(args); - return ret? 0: -1; } From 80c92bae34f52553b1899a708307cd6136068287 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Fri, 23 May 2025 19:11:50 +0800 Subject: [PATCH 13/16] fix(ble): fixed ts sync sleep support trigger --- components/bt/common/ble_log/ble_log_spi_out.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index e2624a2a95..3e2f3057c9 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -1053,7 +1053,7 @@ IRAM_ATTR void ble_log_spi_out_ll_write(uint32_t len, const uint8_t *addr, uint3 #if SPI_OUT_TS_SYNC_SLEEP_SUPPORT if (ts_sync_inited && ts_sync_enabled) { - if ((last_tx_done_ts - ts_sync_data.esp_ts) >= SPI_OUT_TS_SYNC_TIMEOUT) { + if (last_tx_done_ts >= (SPI_OUT_TS_SYNC_TIMEOUT + ts_sync_data.esp_ts)) { if (spi_out_log_cb_check_trans(ll_task_log_cb, sizeof(ts_sync_data_t), &need_append)) { spi_out_ts_sync_toggle(); spi_out_log_cb_write(ll_task_log_cb, (const uint8_t *)&ts_sync_data, From 0a3cc83a8618a6fe8a7fe67ff5b93c51665ec4fe Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Mon, 26 May 2025 10:46:19 +0800 Subject: [PATCH 14/16] fix(ble): fixed spi log init failure return value for ESP32 --- components/bt/controller/esp32/bt.c | 1 + 1 file changed, 1 insertion(+) diff --git a/components/bt/controller/esp32/bt.c b/components/bt/controller/esp32/bt.c index abf5c3d4d3..bf85ceb4b7 100644 --- a/components/bt/controller/esp32/bt.c +++ b/components/bt/controller/esp32/bt.c @@ -1701,6 +1701,7 @@ esp_err_t esp_bt_controller_init(esp_bt_controller_config_t *cfg) #if CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED if (ble_log_spi_out_init() != 0) { ESP_LOGE(BTDM_LOG_TAG, "BLE Log SPI output init failed"); + err = ESP_ERR_NO_MEM; goto error; } #endif // CONFIG_BT_BLE_LOG_SPI_OUT_ENABLED From 6687749fae148ca3afd7f95eed45e7e93b16f7bf Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Mon, 26 May 2025 15:33:47 +0800 Subject: [PATCH 15/16] change(ble): make falling edge when disabling ts sync --- components/bt/common/ble_log/ble_log_spi_out.c | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index 3e2f3057c9..c63e447c8f 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -747,10 +747,6 @@ static void spi_out_ts_sync_deinit(void) static void spi_out_ts_sync_enable(bool enable) { - // Reset ts sync io - ts_sync_data.io_level = false; - gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)ts_sync_data.io_level); - // Update ts sync status ts_sync_enabled = enable; if (enable) { @@ -771,7 +767,12 @@ static void spi_out_ts_sync_enable(bool enable) } } #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT + if (!ts_sync_data.io_level) { + gpio_set_level(SPI_OUT_SYNC_IO_NUM, 1); + } } + ts_sync_data.io_level = 0; + gpio_set_level(SPI_OUT_SYNC_IO_NUM, (uint32_t)ts_sync_data.io_level); } static void spi_out_ts_sync_toggle(void) From a2cd5640448eae68057fa7ea5bd998e08bdb27c4 Mon Sep 17 00:00:00 2001 From: Zhou Xiao Date: Fri, 30 May 2025 15:23:05 +0800 Subject: [PATCH 16/16] fix(ble): set timer handle to null after deletion --- components/bt/common/ble_log/ble_log_spi_out.c | 3 +++ 1 file changed, 3 insertions(+) diff --git a/components/bt/common/ble_log/ble_log_spi_out.c b/components/bt/common/ble_log/ble_log_spi_out.c index c63e447c8f..18e2dd0169 100644 --- a/components/bt/common/ble_log/ble_log_spi_out.c +++ b/components/bt/common/ble_log/ble_log_spi_out.c @@ -718,6 +718,7 @@ static int spi_out_ts_sync_init(void) gpio_init_failed: #if !SPI_OUT_TS_SYNC_SLEEP_SUPPORT esp_timer_delete(ts_sync_timer); + ts_sync_timer = NULL; timer_init_failed: #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT return -1; @@ -733,6 +734,7 @@ static void spi_out_ts_sync_deinit(void) // Deinitialize timestamp synchronizer esp_timer_stop(ts_sync_timer); esp_timer_delete(ts_sync_timer); + ts_sync_timer = NULL; #endif // !SPI_OUT_TS_SYNC_SLEEP_SUPPORT // Deinitialize sync IO @@ -959,6 +961,7 @@ void ble_log_spi_out_deinit(void) #if SPI_OUT_FLUSH_TIMER_ENABLED esp_timer_stop(flush_timer); esp_timer_delete(flush_timer); + flush_timer = NULL; #endif // SPI_OUT_FLUSH_TIMER_ENABLED // Drain all queued transactions