ble_gatts_notify_custom takes 9 ms for 240 bytes

[bvdberg]

We are streaming data as fast as possible over BLE using the ble_gatts_notify_custom call with a payload of 240 bytes.
Our connection interval is 6 (=7.5 ms), so around 133 Hz. Using a 2 Mbit connection, we should be able to send at least 4 frames per interval (each around 256 bytes including header). Right?

To get to around 1 Mbit/sec (payload, so 128 KB/sec), we need to send around 500 240 byte frames. So each frame can take 2 ms maximum. However, the ble_gatts_notify_custom() takes 9 ms. Diving into this, it seems one call takes up most time:
(call stack)
ble_gatts_notify_custom
ble_att_clt_tx_notify
ble_att_tx
ble_att_tx_with_conn
ble_l2cap_tx
ble_hs_hci_acl_tx
ble_hs_hci_acl_tx_now -> takes 8.9 ms in code fragment below

#if !BLE_MONITOR
BLE_HS_LOG(DEBUG, "ble_hs_hci_acl_tx(): ");
ble_hs_log_mbuf(frag);
BLE_HS_LOG(DEBUG, "\n");
#endif

We have disable the BLE_MONITOR, so the code fragment is active. The ble_hs_log_mbuf seems to log byte per byte into a buffer, printed as hex. Disabling this fragment speeds up the notify to 300 usec per call, so good enough.

It seems weird to me that ble_hs_log is always called whenever BLE_MONITOR is disabled. I would expect a separate HS_LOG define or something, that maybe defines ble_hs_log_mbuf as nothing.