ble_gatts_notify_custom takes 9 ms for 240 bytes

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.

Start at the ble_hs_hci_acl_tx_now call path described in the issue and inspect the BLE_MONITOR conditional around ble_hs_log_mbuf. Verify how logging is configured when BLE_MONITOR is disabled, then confirm that notification calls no longer spend milliseconds formatting packet bytes while the intended monitor behavior remains available.

Written by the indexing model from the issue text.