Bluetooth: BLE stack notifications blocks host side for too long (`drivers/bluetooth/hci/spi.c` and `hci_spi`)

[flo-carrere]

First, I have no pretention in stating it is a bug, it may be the normal way of working of the BLE stack architecture at this moment.
In this case, it could be reclassified as an enhancement request if relevant. I may be expecting too much.

Preliminary context

I am using a classic dual-chip configuration:

• Host-side : custom board (stm32h7, similar to a nucleo-h743zi), using a host-build only
  • 3 services (HID, BAS, DIS)
  • HID reporting rate @133hz (7.5ms)
• Controller-side : standard hci_spi sample project flashed on nrf52840 addon board connected through SPI@1MHz

Describe the bug

From the host, using a simple bt_gatt_notify_cb to update a BLE service characteristic (let's say a 17-bytes long HID report update).
I have noticed this call is blocking (OK) for a unexpectedly long period of time (NOK) of approximately 1.5ms degrading others thread "performances" in a non-negligible way.

It's basically a 1.5ms penalty every 7.5ms that is spent in a busy-wait style fashion starving other actions in the system.
More details below on my investigations.

On the other hand, a similar system reporting through USB-HID at the same rate, do not suffer from the same deficiency and a reasonable 0.1 <-> 0.7ms is spent.

• What have you tried to diagnose or workaround this issue?

1. Independently of my full system I have been able to reproduce this blocking behavior by setting up a sample test application for the host side, reporting a classic BAS notification (battery level %) periodically (every 50ms down to every 7.5ms (target)) and measuring by software the time spent for a bt_gatt_notify_cb operation.

// Sample test - pseudo code
period = 50ms;
while(1) {
  time;
  bt_gatt_notify(); // reporting BAS notification
  elapsed = now - time;
  printf("%d", elapsed); // connected:~750us <--> ~980us, not connected: ~5us
  wait( period - elapsed );
}

The host-side prj.conf, I use for the sample test is provided below.
prj.conf.txt

2. I have also tried to pimp my BLE stack configuration using the throughput maximization sample project but with no effect.

3. When debugging, I noticed that the vast majority of time was spent in "waiting" for a rescheduling operation to complete in the implementation of the BLE stack, for some reason.

In a nutshell my call stack (host):

bt_gatt_notify_cb // app waiting here
  // GATT
    // ATT
     // ACL
       // KERNEL QUEUE - k_queue_append_list
        z_reschedule(&queue->lock, key);    <<<< Waiting here for ~80% of the time
     // HCI_SPI transfer happening at some point
   
   // ... returns and continues normally up to the next notification

  // Transfer OTA happening on controller -> at next connection interval -> OK   
  // callback notification sent received -> OK

4. I have not tried yet but I envisioned moving to a single-chip configuration (Host + Controller using HCI RAM) running on nrf52840 and connecting my current "Host" MCU with a custom protocol over SPI to receive raw notifications.

This way I could have a fully externalized BLE stack not impacting the rest of my system (hopefully)
With the big cons of maintaining two FWs instead of a single one....

Do you think it's a valid way of working around the issue?

• Is this a regression? If yes, have you been able to "git bisect" it to a specific commit?
  I don't think it's a regression, probably the way it has always worked

Expected behavior

From a system architecture point of view, I was expecting the dual-chip configuration to work in tandem:

• Host-side -> serializing and publishing notification very fast over HCI -> achieving a minimal time waiting
• Controller-side -> offloading the full BLE-OTA transfer
  • Tuned with sufficiently large HCI events queues according to the report rate/size/types

It's a pity to have two powerful MCUs (STM32H7 on host + nrf52840 on controller) and having such a poor behavior.

Impact

As stated this "poor notification performances" are very annoying as it considerably degrades the full system performance, and sometimes delays time-critical operations (acquisition threads...).

Environment (please complete the following information):

• Building on Windows 10, connecting my device (BLE) on the same laptop.
• Toolchain
  • Zephyr SDK 0.14.1
  • Zephyr v3.0 > Similar behavior on Zephyr v3.1

[Thalley]

I won't take a look at this, but from the issue text it sounds like it's a simple matter of the host running out of buffers, and have to wait for previous buffers to be free'd.

Also, as this seems to be a simple request for enhancing the performance (if possible), then I suggest to change the type from bug to enhancement.

[flo-carrere]

@Thalley No, I don't think so as it is exactly what I tried to check first with no success.

Let me explain further.

I have also tried to pimp my BLE stack configuration using the throughput maximization sample project but with no effect.

This basically proposes to increase both Host/Controller configuration with some more buffer/payload/MTUs/queue/stacks and so on up to their maximum configurable value, creating huge space at every level throughout the full stack.

Commented in the prj.conf.txt provided are the options I checked (with values) and results associated.

... reporting periodically (every 50ms down to every 7.5ms (target))

IMO, what you point as a "simple buffer problem" would be mitigated if we both:

• Increase the configuration as stated above
• Decrease the reporting rate, up to a point where we enqueue/dequeue at a similar rate (50ms sounds very reasonable to me but again I may be expecting too much).

I may re-run with very low reporting rate @1sec and let you know the outcome, what do you think?

[Thalley]

@flo-carrere Keep in mind that you can only send 1 GATT notification per connection interval. Have you tried increasing that as well? Since you are sending in a while(1) loop, it won't do any good to increase the number of buffers, if the buffers are queued faster than they can be sent.

[flo-carrere]

Keep in mind that you can only send 1 GATT notification per connection interval. Have you tried increasing that as well?

No I haven't, is there a kconfig option available to do so? Can you point me to a way to do so?

BTW I didn't modify any BLE stack code so far only went through during debugging.

Since you are sending in a while(1) loop, it won't do any good to increase the number of buffers, if the buffers are queued faster than they can be sent.

I agree with this, that's why I emulated a reporting rate of 50ms (see pseudo-code), that I believe is in the same order of magnitude as the connection interval (~15 <-> 40ms) based on the time I receive GATT notification callback.

[Thalley]

No I haven't, is there a kconfig option available to do so? Can you point me to a way to do so?

The connection interval is done at runtime, and is initially controller by the central. The peripheral may however ask to modify it by calling bt_conn_le_param_update.

If you also control the central, you can just modify the conn_param when calling bt_conn_le_create

The default values should be around 30-50ms interval, but can be reduced to 7.5ms

[flo-carrere]

I may re-run with very low reporting rate at 1sec and let you know the outcome, what do you think?

As I expected, even when diminishing the reporting rate to 1 Hz it does not change the time spent in GATT notify.

I measure a constant 1.482ms to "notify" a 17 bytes long HID report update, and I receive the callback from the controller 40ms after (using the default connection interval).

My understanding is that this time should be spent for 3 actions on host-side:

• Packetizing the GATT notification according to the LL-stack layers -> I expect this to run very fast as it's barely copying and wrapping a few bytes at every layer.
• Waiting for a buffer available -> According to my tests I think we can discard this being the root cause of my issue
• Pushing the packetized HCI event (containing my report and stuff) to the controller through SPI -> I expect this to be the limiting factor but still at 1MHz, I would expect the transfer being << 1.5ms

The connection interval is done at runtime, and is initially controller by the central. The peripheral may however ask to modify it by calling bt_conn_le_param_update

This I set but with no improvements either

    struct bt_le_conn_param bleconn_params = {
        .interval_min = CONFIG_BT_PERIPHERAL_PREF_MIN_INT, // 6*1.25
        .interval_max = CONFIG_BT_PERIPHERAL_PREF_MAX_INT, // 6*1.25
        .latency      = 0,
        .timeout      = 4,
    };

    bt_conn_le_param_update(conn, &bleconn_params);