diff --git a/components/bt/esp_ble_audio/host/adapter/nimble/profiles/mcs.c b/components/bt/esp_ble_audio/host/adapter/nimble/profiles/mcs.c index 781536cbf8b..07ec835e88c 100644 --- a/components/bt/esp_ble_audio/host/adapter/nimble/profiles/mcs.c +++ b/components/bt/esp_ble_audio/host/adapter/nimble/profiles/mcs.c @@ -632,7 +632,9 @@ static int inc_ots_svc_init(void) int bt_le_nimble_gmcs_init(bool ots_included) { +#if CONFIG_BT_OTS bool inc_ots_added = false; +#endif /* CONFIG_BT_OTS */ int rc; LOG_DBG("[N]GmcsInit[%u]", ots_included); diff --git a/components/bt/esp_ble_iso/host/adapter/bluedroid/hci.c b/components/bt/esp_ble_iso/host/adapter/bluedroid/hci.c index 0dbfb79a416..ec7baa0cd88 100644 --- a/components/bt/esp_ble_iso/host/adapter/bluedroid/hci.c +++ b/components/bt/esp_ble_iso/host/adapter/bluedroid/hci.c @@ -80,6 +80,8 @@ static void direct_hci_complete_cb(BT_HDR *response, void *context) ARG_UNUSED(context); + LOG_INF("[B]DirectHciCompleteCb[%04x]", direct_hci_rsp.opcode); + event_param_len = response->data[response->offset + 1]; STREAM_TO_UINT16(opcode, stream); @@ -115,6 +117,13 @@ static void direct_hci_complete_cb(BT_HDR *response, void *context) k_sem_give(&direct_hci_sem); } +/* Dropped-wakeup recovery in send_sync below. SLICE is well above the ~5 ms + * round trip so a healthy command never kicks; the first kick already recovers, + * and the leftover budget is one final wait, keeping the total K_SEM_SHORT. */ +#define DIRECT_HCI_KICK_SLICE (50 / portTICK_PERIOD_MS) +#define DIRECT_HCI_KICK_MAX 3 +#define DIRECT_HCI_WAIT_REST (K_SEM_SHORT - DIRECT_HCI_KICK_MAX * DIRECT_HCI_KICK_SLICE) + tBTM_STATUS bt_le_bluedroid_hci_send_sync(uint16_t opcode, const uint8_t *cmd_params, uint8_t cmd_params_len, @@ -123,6 +132,7 @@ tBTM_STATUS bt_le_bluedroid_hci_send_sync(uint16_t opcode, { BT_HDR *p; UINT8 *pp; + uint8_t kicks; hci_cmd_metadata_t *metadata; p = HCI_GET_CMD_BUF(cmd_params_len); @@ -158,7 +168,50 @@ tBTM_STATUS bt_le_bluedroid_hci_send_sync(uint16_t opcode, hci_layer_get_interface()->transmit_command(p, direct_hci_complete_cb, NULL, NULL); - if (k_sem_take(&direct_hci_sem, K_SEM_SHORT) != 0) { + for (kicks = 0; kicks < DIRECT_HCI_KICK_MAX; kicks++) { + if (k_sem_take_poll(&direct_hci_sem, DIRECT_HCI_KICK_SLICE) == 0) { + break; + } + + LOG_WRN("[B]DirectHciKick[0x%04x][%u]", opcode, kicks + 1); + + /* Re-post the downstream event: our own wakeup may have been dropped. + * + * transmit_command() does not write the command from this task. It + * appends to hci_host_env.command_queue and wakes the hciT worker via + * hci_downstream_data_post(), whose return value it discards. + * osi_thread_post_event() refuses to post while OSI_EVENT_FLAG_POSTING + * is set, and that flag is held by whichever task is mid-post from the + * moment it sets the flag until it is rescheduled: osi_thread_post() + * ends in osi_sem_give(work_sem), which immediately yields to the + * higher-priority hciT, so POSTING stays set across the whole handler + * run. A second producer landing in that window is rejected: + * + * BTU set QUEUED|POSTING; osi_thread_post() -> sem give --. + * hciT clear QUEUED; handler: send the ACL, command_queue <-' + * still empty -> break; block again + * iso_task (same prio as BTU, round-robin) transmit_command(): + * enqueue cmd ok, post -> QUEUED clear but POSTING set + * -> rejected, no wakeup, return value discarded + * BTU resumes, clears POSTING (too late) + * + * The command then sits in command_queue with nothing scheduled to + * drain it. It never reached commands_pending_response either, so + * Bluedroid's own COMMAND_PENDING_TIMEOUT never arms and only this + * task's sem timeout notices. That is expensive here: the caller is the + * ISO task, sole consumer of the ISO RX queue, so a full K_SEM_SHORT + * stall drops every SDU received during it. + * + * One slice later the POSTING holder has long been rescheduled, so this + * post lands and hciT drains the queued command. Bluedroid-only: NimBLE + * writes the command inline from the caller's task (ble_hs_hci_cmd_tx), + * so it has no wakeup to lose. Drop this loop once the POSTING gate in + * osi_event_can_post_locked() is fixed (regression in 0564b09e86f). */ + hci_downstream_data_post(OSI_THREAD_MAX_TIMEOUT); + } + + if (kicks == DIRECT_HCI_KICK_MAX && + k_sem_take(&direct_hci_sem, DIRECT_HCI_WAIT_REST) != 0) { LOG_ERR("[B]DirectHciTimeout[0x%04x]", opcode); return BTM_ERR_PROCESSING; } diff --git a/components/bt/esp_ble_iso/host/adapter/nimble/gatt/gatt.db.c b/components/bt/esp_ble_iso/host/adapter/nimble/gatt/gatt.db.c index 36d88c7ba76..13f6e114f2d 100644 --- a/components/bt/esp_ble_iso/host/adapter/nimble/gatt/gatt.db.c +++ b/components/bt/esp_ble_iso/host/adapter/nimble/gatt/gatt.db.c @@ -230,29 +230,33 @@ static void gattc_db_chrc_insert(sys_slist_t *chrc_list, const struct ble_gatt_c } static void gattc_db_dsc_cccd_store(sys_slist_t *chrc_list, - uint16_t chr_val_handle, const struct ble_gatt_dsc *dsc) { struct gattc_db_chrc *achrc; + struct gattc_db_chrc *owner = NULL; - /* LOG_DBG("[N]GattcDbDscCccdStore[%u]", chr_val_handle); */ - + /* chrc_list is handle-ordered; the CCCD belongs to the last chrc whose + * value handle is below the descriptor. NimBLE's service-range + * disc_all_dscs reports one chr_val_handle for all descriptors, so locate + * the owner by descriptor handle instead. */ SYS_SLIST_FOR_EACH_CONTAINER(chrc_list, achrc, node) { - /* Match by the char value handle NimBLE reports this descriptor belongs - * to, not dsc->handle-1: a descriptor between value and CCCD would break - * the offset assumption and leave CCCD unstored. */ - if (achrc->chrc.val_handle == chr_val_handle) { - if (achrc->cccd.handle) { - LOG_WRN("[N]GattcDbCccAlreadyUpd[%u][%u]", chr_val_handle, achrc->cccd.handle); - return; - } - - /* LOG_DBG("[N]GattcDbCccUpd[%u][%u]", achrc->chrc.val_handle, dsc->handle); */ - - memcpy(&achrc->cccd, dsc, sizeof(achrc->cccd)); - return; + if (achrc->chrc.val_handle < dsc->handle) { + owner = achrc; + } else { + break; } } + + if (owner == NULL) { + return; + } + + if (owner->cccd.handle) { + LOG_WRN("[N]GattcDbCccAlreadyUpd[%u][%u]", owner->chrc.val_handle, owner->cccd.handle); + return; + } + + memcpy(&owner->cccd, dsc, sizeof(owner->cccd)); } static struct gattc_db_svc *gattc_db_disc_find(struct gattc_db *adb) @@ -858,7 +862,7 @@ static int gattc_db_disc_all_inc_dscs_cb_safe(uint16_t conn_handle, dsc->uuid.u16.value == BT_UUID_GATT_CCC_VAL) { LOG_DBG("[N]GattcDbDiscAllIncDscs[%u][%u]", chr_val_handle, dsc->handle); - gattc_db_dsc_cccd_store(&ainc_svc->chrc_list, chr_val_handle, dsc); + gattc_db_dsc_cccd_store(&ainc_svc->chrc_list, dsc); } break; @@ -921,7 +925,7 @@ static int gattc_db_disc_all_dscs_cb_safe(uint16_t conn_handle, dsc->uuid.u16.value == BT_UUID_GATT_CCC_VAL) { LOG_DBG("[N]GattcDbDiscAllDscs[%u]", dsc->handle); - gattc_db_dsc_cccd_store(&asvc->chrc_list, chr_val_handle, dsc); + gattc_db_dsc_cccd_store(&asvc->chrc_list, dsc); } break; @@ -1390,6 +1394,10 @@ static int handle_gattc_disc_all_dscs(struct bt_conn *conn, SYS_SLIST_FOR_EACH_CONTAINER(&asvc->chrc_list, achrc, node) { if (achrc->chrc.val_handle == sub_params->value_handle) { + LOG_DBG("[N]GattcDbCccLookup[%u][%u][%u][%u]", + asvc->svc.start_handle, asvc->svc.end_handle, + achrc->chrc.val_handle, achrc->cccd.handle); + if (achrc->cccd.handle) { attr.handle = achrc->cccd.handle; found = &attr; diff --git a/components/bt/esp_ble_iso/host/common/iso.c b/components/bt/esp_ble_iso/host/common/iso.c index 8cf5a36cd24..f127e8cc3a1 100644 --- a/components/bt/esp_ble_iso/host/common/iso.c +++ b/components/bt/esp_ble_iso/host/common/iso.c @@ -44,6 +44,17 @@ LOG_MODULE_REGISTER(ISO_SHIM, CONFIG_BT_ISO_LOG_LEVEL); #define ISO_PKT_COMP_SDU (0b10) #define ISO_PKT_LAST_FRAG (0b11) +/* Both callbacks that feed the iso task from the controller task (iso_tx_comp_cb, + * bt_le_iso_rx) can fail to hand off an item, and neither may log there: + * esp_log_write is a blocking UART write (~3 ms/line at 115200), so reporting at + * the failure rate would spend most of a second inside it and deepen the very + * congestion it reports. They only count; the matching iso-task handler reports + * once every ISO_DROP_REPORT_STEP items, by which point the queue has room again + * so the report never competes with the burst that caused it. Causes are counted + * apart because they need different fixes: a full queue means the iso task is + * behind, a failed alloc means the heap is exhausted. */ +#define ISO_DROP_REPORT_STEP 100 + static BT_ISO_EXT_RAM_BSS_ATTR sys_slist_t iso_cbs; #if CONFIG_BT_ISO_UNICAST @@ -636,6 +647,11 @@ struct iso_tx_comp_event { struct bt_iso_tx_cb_info info; }; +/* See ISO_DROP_REPORT_STEP. */ +static BT_ISO_CTRL_BSS_ATTR uint32_t iso_tx_comp_drop_cnt; /* task queue full */ +static BT_ISO_CTRL_BSS_ATTR uint32_t iso_tx_comp_nomem_cnt; /* evt alloc failed */ +static BT_ISO_CTRL_BSS_ATTR uint32_t iso_tx_comp_reported; + void bt_le_iso_handle_tx_comp(uint8_t *data, size_t data_len) { struct iso_tx_comp_event *evt = (struct iso_tx_comp_event *)data; @@ -644,11 +660,19 @@ void bt_le_iso_handle_tx_comp(uint8_t *data, size_t data_len) struct bt_conn *iso; bt_conn_tx_cb_t cb; sys_snode_t *node; + uint32_t dropped; void *ud; int err; BT_LE_ASSERT(data && data_len == sizeof(*evt)); + dropped = iso_tx_comp_drop_cnt + iso_tx_comp_nomem_cnt; + if (dropped - iso_tx_comp_reported >= ISO_DROP_REPORT_STEP) { + iso_tx_comp_reported = dropped; + LOG_WRN("IsoTxCompDrop[q=%u][nomem=%u]", + iso_tx_comp_drop_cnt, iso_tx_comp_nomem_cnt); + } + bt_le_host_lock(); while (1) { @@ -724,7 +748,7 @@ static void iso_tx_comp_cb(uint16_t conn_handle, void *info, size_t size) evt = bt_le_int_calloc(1, sizeof(*evt)); if (evt == NULL) { - LOG_ERR("IsoTxCompNoMem[%u]", sizeof(*evt)); + iso_tx_comp_nomem_cnt++; return; } @@ -733,7 +757,7 @@ static void iso_tx_comp_cb(uint16_t conn_handle, void *info, size_t size) err = bt_le_iso_task_post(ISO_QUEUE_ITEM_TYPE_ISO_TX_COMP, evt, sizeof(*evt)); if (err) { - LOG_ERR("IsoTxCompPostFail[%d]", err); + iso_tx_comp_drop_cnt++; free(evt); } } @@ -746,12 +770,24 @@ void bt_le_iso_handle_tx_comp(uint8_t *data, size_t data_len) #endif /* CONFIG_BT_ISO_TX */ #if CONFIG_BT_ISO_RX +/* See ISO_DROP_REPORT_STEP. */ +static BT_ISO_CTRL_BSS_ATTR uint32_t iso_rx_drop_cnt; /* task queue full */ +static BT_ISO_CTRL_BSS_ATTR uint32_t iso_rx_nomem_cnt; /* rx_data alloc failed */ +static BT_ISO_CTRL_BSS_ATTR uint32_t iso_rx_reported; + void bt_le_iso_handle_rx_data(uint8_t *data, size_t data_len) { struct net_buf buf = {0}; + uint32_t dropped; BT_LE_ASSERT(data && data_len); + dropped = iso_rx_drop_cnt + iso_rx_nomem_cnt; + if (dropped - iso_rx_reported >= ISO_DROP_REPORT_STEP) { + iso_rx_reported = dropped; + LOG_WRN("IsoRxDrop[q=%u][nomem=%u]", iso_rx_drop_cnt, iso_rx_nomem_cnt); + } + bt_le_host_lock(); net_buf_simple_init_with_data(&buf.b, (void *)data, data_len); hci_iso(&buf); @@ -778,7 +814,7 @@ int bt_le_iso_rx(const uint8_t *data, uint16_t len, void *arg) rx_data = bt_le_int_calloc(1, len); if (rx_data == NULL) { - LOG_ERR("IsoRxNoMem[%u]", len); + iso_rx_nomem_cnt++; return -ENOMEM; } @@ -786,7 +822,7 @@ int bt_le_iso_rx(const uint8_t *data, uint16_t len, void *arg) err = bt_le_iso_task_post(ISO_QUEUE_ITEM_TYPE_ISO_RX_DATA, rx_data, len); if (err) { - LOG_ERR("IsoRxPostFail[%d]", err); + iso_rx_drop_cnt++; free(rx_data); return -EIO; } diff --git a/components/bt/esp_ble_iso/include/zephyr/kernel.h b/components/bt/esp_ble_iso/include/zephyr/kernel.h index 195bf9c1312..876e9f1dfda 100644 --- a/components/bt/esp_ble_iso/include/zephyr/kernel.h +++ b/components/bt/esp_ble_iso/include/zephyr/kernel.h @@ -140,7 +140,8 @@ static inline void k_sem_delete(struct k_sem *sem) #define K_SEM_LOG_ERR(fmt, args...) BT_ISO_LOGE("ISO_SEM", fmt, ## args) #endif -static inline int k_sem_take(struct k_sem *sem, uint32_t timeout) +/* Implementation of k_sem_take; call through the macro below. */ +static inline int k_sem_take_dbg(struct k_sem *sem, uint32_t timeout, const char *func) { BT_LE_ASSERT(sem); BT_LE_ASSERT(sem->handle); @@ -156,13 +157,28 @@ static inline int k_sem_take(struct k_sem *sem, uint32_t timeout) } #if !CONFIG_BT_ISO_NO_LOG && (CONFIG_BT_ISO_LOG_LEVEL >= BT_ISO_LOG_ERROR) - K_SEM_LOG_ERR("TakeFail[self=%s]", pcTaskGetName(NULL)); + K_SEM_LOG_ERR("TakeFail[%s][%s]", func, pcTaskGetName(NULL)); #else + ARG_UNUSED(func); K_SEM_LOG_ERR("TakeFail"); #endif return -EIO; } +/* Macro, not a wrapper function, so __func__ names the CALLER — that identifies + * both the wedged operation and the sem, with no per-sem RAM. */ +#define k_sem_take(sem, timeout) k_sem_take_dbg((sem), (timeout), __func__) + +/* Silent take for slice-polling callers, where only the final expiry is an error + * and k_sem_take would log TakeFail per slice. Same sem->result contract. */ +static inline int k_sem_take_poll(struct k_sem *sem, uint32_t timeout) +{ + BT_LE_ASSERT(sem); + BT_LE_ASSERT(sem->handle); + + return (xSemaphoreTake(sem->handle, timeout) == pdTRUE) ? 0 : -EIO; +} + static inline int k_sem_give(struct k_sem *sem) { BT_LE_ASSERT(sem);