pico-sdk icon indicating copy to clipboard operation
pico-sdk copied to clipboard

BLE Host is only able to receive one packet per interval

Open sanjay900 opened this issue 2 years ago • 99 comments

I currently have two pico ws, one configured as a HOG Host, and one configured as a HOG Device, using code very similar to the hog keyboard hog host examples.

If i connect the device over bluetooth from a PC, i can get to poll rate around 850hz or so, which suggests that multiple packets are being sent per connection interval. However, if i instead connect to the HOG host running on a pico w, i end up with a poll rate of around 32hz, which lines up with the default 30ms connection interval.

If I then add the following line to the HOG host, I can lower the connection interval to the minimum 7.5ms, and I do end up seeing a poll rate of around 130hz or so, which also lines up with the 7.5ms connection interval. gap_set_connection_parameters(0x0060, 0x0030, 0x06, 0x06, 0, 0x0048, 2, 0x0030);

I also ran BTStack locally on my PC using the libusb port, and found that that did get to around 850hz as well, so it does appear to just be an issue with the pico w port specifically.

My eventual goal is to use this to allow a user to create a usb adapter for a bluetooth controller i am working on that can then be plugged into a console, hence the need for a very low latency.

sanjay900 avatar Apr 12 '23 07:04 sanjay900

You'll have to provide more context about the code you're running. What method are you using polling, background or are you using an rtos? Do you have any code that demonstrates a problem. Note that we're not actually bluetooth experts here so your report is assuming lots of prior knowledge. I don't know what "interval" you're referring to for example. Unless you can clarify what you're reporting in a way I can investigate a problem you're unlikely to get any help.

peterharperuk avatar Apr 12 '23 09:04 peterharperuk

Fair call, ill throw together a simplified repo that has an example for both sides of the pico. Ill admit I also don't really have much knowledge on the matter either, this was just what i gleamed after some experimentation with some of the btstack options, and some research.

From what i understand, BLE has a concept of a connection interval, which both sides of the connection agree on, and then the host will send out a packet each time the interval is hit. This can be configured but there is a lower limit of 7.5ms. It sounds like however you can sent multiple packets within this interval, which is how devices can update faster than 7.5ms.

I have essentially taken the hog_keyboard_demo and just have it sending data as often as possible, and with a PC (either using the linux bluetooth stack or btstack via libusb) it seems to be able to update at ~1ms or so, which suggests that this side of the equation is able to send out multiple packets per interval. I even left this side at the default connection interval of 30ms, so it is sending multiple packets per interval.

I then took the hog_host_demo and added a line to print out how often it receives data. It appears that GATTSERVICE_SUBEVENT_HID_REPORT is only ever fired once per connection interval here, so by default i only seem to get one report every 30ms. I can adjust the connection interval with gap_set_connection_parameters and if i lower it to the minimum 7.5ms value, then i also noted that I would get reports every 7.5ms.

I am using the background method, on both the device and the host.

sanjay900 avatar Apr 12 '23 09:04 sanjay900

Ok, thanks for adding some context. Examples (or modifications to existing examples) would be useful. In the background mode, we get an interrupt via a gpio to tell us there might be work to do (cyw43_gpio_irq_handler). This ends up in a call to cyw43_poll_func. We ask the chip if there's any work to do (cyw43_ll_bt_has_work) and call cyw43_bluetooth_hci_process which signals that a btstack data source has work to do. BTstack calls hci_transport_cyw43_process which keeps reading hci commands. So if the chip thinks there's nothing to do or there are no hci commands to read we won't try and "receive" anything. I would avoid debugging via logging as it's likely to affect timings. Probably best to use a logic analyser to work out what's going on.

peterharperuk avatar Apr 12 '23 09:04 peterharperuk

@peterharperuk if there are more than one ACL packet stored in the cyw43 ring buffer, will all of them get processed in a row until it's empty? or does this require another interrrupt via the GPIO line?

mringwal avatar Apr 12 '23 09:04 mringwal

@mringwal I think it should yes. hci_transport_cyw43_process keeps reading hci commands until there's no data (or an error). It's possible this loop is faulty somehow. It should perhaps keep going while cyw43_ll_bt_has_work is true. It might be worth debugging this area (without using printf).

peterharperuk avatar Apr 12 '23 09:04 peterharperuk

https://gist.github.com/sanjay900/fe87afaad7474707459718d0945da759 Here is my gamepad implementation, i am currently testing by just sending a random value to an axis on each tick, which I can then use tools like evhz on linux to test with. For the pico receiver, the standard hog_host_demo is enough to demonstrate the problem, simply just printing the milliseconds since the last GATTSERVICE_SUBEVENT_HID_REPORT is enough to show the issue (I was actually testing this with a program that would redirect the inputs directly to USB hid and testing with evhz, so I was not dealing with printf delays on that front)

You can listen to the LE_CONNECTION_COMPLETE event to get an idea of what the current interval is. I added this to the hog example locally just to work out what the current interval even was.

switch (hci_event_le_meta_get_subevent_code(packet)) {
    case HCI_SUBEVENT_LE_CONNECTION_COMPLETE: {
        // print connection parameters (without using float operations)
        uint16_t conn_interval = hci_subevent_le_connection_complete_get_conn_interval(packet);
        printf("LE Connection Complete:\n");
        printf("- Connection Interval: %u.%02u ms\n", conn_interval * 125 / 100, 25 * (conn_interval & 3));
        printf("- Connection Latency: %u\n", hci_subevent_le_connection_complete_get_conn_latency(packet));
        break;
    }
    case HCI_SUBEVENT_LE_CONNECTION_UPDATE_COMPLETE: {
        // print connection parameters (without using float operations)
        uint16_t conn_interval = hci_subevent_le_connection_update_complete_get_conn_interval(packet);
        printf("LE Connection Update:\n");
        printf("- Connection Interval: %u.%02u ms\n", conn_interval * 125 / 100, 25 * (conn_interval & 3));
        printf("- Connection Latency: %u\n", hci_subevent_le_connection_update_complete_get_conn_latency(packet));
        break;
    }
    default:
        break;
}

If you do just want to see the actual project i am testing with, it is at https://github.com/sanjay900/Ardwiino

sanjay900 avatar Apr 12 '23 10:04 sanjay900

@sanjay900 Could you run gatt_streamer_server on one pico and le_streamer_client on the other. le_streamer_client should be configured to use TEST_MODE_ENABLE_NOTIFICATIONS - so it's only receiving. As the demo prints the throughput, we can check how many packets are sent per interval.

I still don't see how only a single packet could get received in a connection interval. The sender in peripheral role will send as long as the central allows it to send and the central will keep the connection event open until it's buffers overflow. event with controller to host flow control, we should get a least a few packets per conn interval.

mringwal avatar Apr 12 '23 10:04 mringwal

Let me just build both of those and i will give it a try

sanjay900 avatar Apr 12 '23 10:04 sanjay900

Hmm, doesn't seem to be working right, here are the logs from the le_streamer_client

BTstack up and running on 43:43:A2:12:1F:AC.
Start scanning!
Stop scan. Connect to device with addr 43:43:A2:12:1F:AC.
Connection Interval: 30.00 ms
Connection Latency: 4
Search for LE Streamer service.
SERVICE_QUERY_RESULT, ATT Error 0x7f.
Disconnected 43:43:A2:12:1F:AC
Start scanning!
Stop scan. Connect to device with addr 43:43:A2:12:1F:AC.
Connection Interval: 30.00 ms
Connection Latency: 4
Search for LE Streamer service.

And from the gatt_streamer_server:

BTstack up and running on 43:43:A2:12:1F:AC.
To start the streaming, please run the le_streamer_client example on other device, or use some GATT Explorer, e.g. LightBlue, BLExplr.
A: ATT connected, handle 0x0040, test data len 20
- LE Connection 0x0040: connected - connection interval 30.00 ms, latency 4
- LE Connection 0x0040: request 15 ms connection interval
A: ATT MTU = 1688 => use test data of len 200
- LE Connection 0x0040: connection update - connection interval 15.00 ms, latency 0
A: ATT disconnected, handle 0x0040
- LE Connection 0x0040: disconnect, reason 22
A: ATT connected, handle 0x0040, test data len 20
- LE Connection 0x0040: connected - connection interval 30.00 ms, latency 4
- LE Connection 0x0040: request 15 ms connection interval
A: ATT MTU = 1688 => use test data of len 200
- LE Connection 0x0040: connection update - connection interval 15.00 ms, latency 0

sanjay900 avatar Apr 12 '23 10:04 sanjay900

@peterharperuk did anybody complain about all pico w using the same BD ADDR? In @sanjay900's logs, both have 43:43:A2:12:1F:AC - the first 6 hex digits indicate the used controller, a 4343A2.

I don't remember exactly, but BTstack avoids connections to devices with the same BD ADDR, as that allows for some sneaky security hacks.

@sanjay900 Thanks for trying. I can check myself tomorrow or Friday.

mringwal avatar Apr 12 '23 10:04 mringwal

It does however seem like something is broken with updating the connection parameters, as commenting out gap_request_connection_parameter_update(con_handle, 12, 12, 0, 0x0048); is enough to make it run. I actually found this myself too when i was looking for ways to increase my connection interval, but just assumed i was doing something wrong when it hung.

@peterharperuk Do you want this raised as a separate issue, or just kept here? I have no idea where that problem lies as it is just something i have found by testing.

@mringwal here is the output with that line commented out

BTstack up and running on 43:43:A2:12:1F:AC.
To start the streaming, please run the le_streamer_client example on other device, or use some GATT Explorer, e.g. LightBlue, BLExplr.
A: ATT connected, handle 0x0040, test data len 20
- LE Connection 0x0040: connected - connection interval 30.00 ms, latency 4
- LE Connection 0x0040: request 15 ms connection interval
A: ATT MTU = 1688 => use test data of len 200
A: Notifications enabled 1
A: 21000 bytes sent-> 6.930 kB/s
A: 19600 bytes sent-> 6.533 kB/s
A: 19600 bytes sent-> 6.533 kB/s
A: 19600 bytes sent-> 6.468 kB/s
A: 20000 bytes sent-> 6.666 kB/s
A: 20000 bytes sent-> 6.538 kB/s
A: 20000 bytes sent-> 6.600 kB/s
A: 20000 bytes sent-> 6.600 kB/s
A: 19600 bytes sent-> 6.468 kB/s
A: 20000 bytes sent-> 6.666 kB/s
A: 19600 bytes sent-> 6.533 kB/s
A: 19600 bytes sent-> 6.533 kB/s
A: 20000 bytes sent-> 6.600 kB/s
A: 20000 bytes sent-> 6.602 kB/s
A: 19200 bytes sent-> 6.400 kB/s
A: 19600 bytes sent-> 6.468 kB/s
A: 19600 bytes sent-> 6.533 kB/s
A: 19200 bytes sent-> 6.400 kB/s
A: 20000 bytes sent-> 6.666 kB/s
A: 19600 bytes sent-> 6.533 kB/s
A: 19800 bytes sent-> 6.600 kB/s

sanjay900 avatar Apr 12 '23 10:04 sanjay900

@peterharperuk did anybody complain about all pico w using the same BD ADDR? In @sanjay900's logs, both have 43:43:A2:12:1F:AC - the first 6 hex digits indicate the used controller, a 4343A2.

I don't remember exactly, but BTstack avoids connections to devices with the same BD ADDR, as that allows for some sneaky security hacks.

@sanjay900 Thanks for trying. I can check myself tomorrow or Friday.

@mringwal I know there are fixes for that in the develop branch, and I also had that thought myself but i ran my hid code with the develop branch and didn't really find it affected anything.

To run these examples I just pulled the pico-examples repo down for running these tests, which grabbed the currently released SDK which doesn't have the fix for BT addresses.

sanjay900 avatar Apr 12 '23 10:04 sanjay900

Yes 43:43:A2:12:1F:AC is the default btstack address (hardcoded in the infineon firmware to always be the same). I have a fix on develop that makes sure the btstack address is +1 the wifi mac address.

However I still haven't got to the bottom of why this issue is happening. I was unsure if it was because the OTP had not been set in the factory or if we had devices with duplicate addresses. @sanjay900 I would appreciate it if I could see the lines that say something like this for both the devices you have...

Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb9
cyw43 loaded ok, mac 28:cd:c1:07:86:f7
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
BTstack up and running on 28:CD:C1:07:86:F8.

peterharperuk avatar Apr 12 '23 11:04 peterharperuk

Yes 43:43:A2:12:1F:AC is the default btstack address (hardcoded in the infineon firmware to always be the same). I have a fix on develop that makes sure the btstack address is +1 the wifi mac address.

However I still haven't got to the bottom of why this issue is happening. I was unsure if it was because the OTP had not been set in the factory or if we had devices with duplicate addresses. @sanjay900 I would appreciate it if I could see the lines that say something like this for both the devices you have...

Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb9
cyw43 loaded ok, mac 28:cd:c1:07:86:f7
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
BTstack up and running on 28:CD:C1:07:86:F8.

what defines do i need to set to make those lines show up?

sanjay900 avatar Apr 12 '23 11:04 sanjay900

@peterharperuk I can get the outputs for one of them now, and ill hook up a UART to the other one tomorrow. If it helps i can test the other ones i have as well?

Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb0879
cyw43 loaded ok, mac 28:cd:c1:07:b7:95
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
BTstack up and running on 43:43:A2:12:1F:AC.
To start the streaming, please run the le_streamer_client example on other device, or use some GATT Explorer, e.g. LightBlue, BLExplr.

sanjay900 avatar Apr 12 '23 11:04 sanjay900

@sanjay900 thanks. It seems that OTP is set in your device, but for some reason the bt device address is not set. This is isn't the case with the devices I have suggesting something has changed in the factory.

peterharperuk avatar Apr 12 '23 11:04 peterharperuk

@sanjay900 good idea to skip the conn param update. With 30 ms and about 6.5 kB/s, we end up with 200 bytes per connection interval, which would indicate a single packet with 200 bytes (if DLE is supported and I think it is).

mringwal avatar Apr 12 '23 11:04 mringwal

@mringwal Out of curiosity, any idea why the conn param update breaks things?

sanjay900 avatar Apr 12 '23 20:04 sanjay900

I figured id try running the le_streamer_client on my pc using the libusb port, with a pico w running the gatt_streamer_server, and got this result:

Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb0879
cyw43 loaded ok, mac 28:cd:c1:07:b7:95
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
BTstack up and running on 43:43:A2:12:1F:AC.
To start the streaming, please run the le_streamer_client example on other device, or use some GATT Explorer, e.g. LightBlue, BLExplr.
A: ATT connected, handle 0x0040, test data len 20
- LE Connection 0x0040: connected - connection interval 30.00 ms, latency 4
- LE Connection 0x0040: request 15 ms connection interval
A: ATT MTU = 1688 => use test data of len 200
A: Notifications enabled 1
A: 97200 bytes sent-> 32.324 kB/s
A: 95000 bytes sent-> 31.666 kB/s
A: 87400 bytes sent-> 29.055 kB/s
A: 86800 bytes sent-> 28.770 kB/s
A: 94000 bytes sent-> 31.281 kB/s
A: 90000 bytes sent-> 30.000 kB/s

Here are the results if i run the gatt_streamer_server on my pc with the libusb port and the le_streamer_client on my pico w:

Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb0879
cyw43 loaded ok, mac 28:cd:c1:07:b7:95
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
BTstack up and running on 43:43:A2:12:1F:AC.
Start scanning!
Stop scan. Connect to device with addr 00:15:83:ED:65:E8.
Connection Interval: 30.00 ms
Connection Latency: 4
Search for LE Streamer service.
SERVICE_QUERY_RESULT, ATT Error 0x1f.
Disconnected 00:15:83:ED:65:E8
Start scanning!
Stop scan. Connect to device with addr 00:15:83:ED:65:E8.
Connection Interval: 30.00 ms
Connection Latency: 4
Search for LE Streamer service.
Search for LE Streamer RX characteristic.
Search for LE Streamer TX characteristic.
A: ATT MTU = 1691 => use test data of len 200
Start streaming - enable notify on test characteristic.
Notifications enabled, ATT status 0x00
A: 16800 bytes -> 5.586 kB/s
A: 18400 bytes -> 6.131 kB/s
A: 18600 bytes -> 6.200 kB/s
A: 18600 bytes -> 6.154 kB/s
A: 19400 bytes -> 6.449 kB/s
A: 19000 bytes -> 6.333 kB/s
A: 19000 bytes -> 6.333 kB/s
A: 19200 bytes -> 6.400 kB/s
A: 19400 bytes -> 6.402 kB/s
A: 19400 bytes -> 6.466 kB/s
A: 18600 bytes -> 6.200 kB/s
A: 19000 bytes -> 6.285 kB/s
A: 20000 bytes -> 6.648 kB/s
A: 18800 bytes -> 6.266 kB/s
A: 19200 bytes -> 6.351 kB/s
A: 18400 bytes -> 6.119 kB/s
A: 19200 bytes -> 6.400 kB/s
A: 19600 bytes -> 6.533 kB/s

Interestingly, even when running the gatt_streamer_server on my pc with the libusb port, I still needed to comment out the conn param line for the connection to work

sanjay900 avatar Apr 12 '23 21:04 sanjay900

@peterharperuk not sure if you still need this but heres that line from the other pico: I was wrong i did only buy just these two.

Version: 7.95.61 (abcd531 CY) CRC: 4528a809 Date: Wed 2023-01-11 10:29:38 PST Ucode Ver: 1043.2169 FWID 01-7afb0879
cyw43 loaded ok, mac 28:cd:c1:07:b8:11
BT FW download, version = CYW4343A2_001.003.016.0031.0000_Generic_SDIO_37MHz_wlbga_BU_dl_signed
BTstack up and running on 43:43:A2:12:1F:AC.
To start the streaming, please run the le_streamer_client example on other device, or use some GATT Explorer, e.g. LightBlue, BLExplr.

sanjay900 avatar Apr 12 '23 22:04 sanjay900

If there is anything else i can provide let me know

sanjay900 avatar Apr 13 '23 08:04 sanjay900

@mringwal Out of curiosity, any idea why the conn param update breaks things?

Well, the controllers seem to fail in synchronizing the change. You can try to use slave latency = 4 with the connection interval = 15 ms, too.

mringwal avatar Apr 13 '23 10:04 mringwal

Minor update: I've repeated the test with le_streamer_client on Pico W and gatt_streamer_server on my Mac with an USB CSR8510 dongle and as able to get a air trace using our Raccoon nRF5x sniffer.

I get the same (low) throughput. Interestingly, as the CSR8510 does not support DLE, the 200 bytes test packets are split into several smaller packets over the air. Still, only one of these packets are send per connection interval. The packets indicate that the peripheral (CSR8510) always has data to send, but the central (pico_w) does not/cannot receive it. While not impossible, I cannot imagine that the CYW43 can only receive this 200 bytes per connection interval. Quick test replacing the pico_w/cyw43439 with a CYW20704 on my Mac, I get 25 kB/s as well.

My hypothesis here is that they get stuck in the CYW43 on the Pico W. Will review the code a bit more to see if we can more details on this.

mringwal avatar Apr 15 '23 10:04 mringwal

Thanks for looking into it :)

sanjay900 avatar Apr 15 '23 10:04 sanjay900

To get deeper, I've reviewed the code (no issues there) and toggled a GPIO while in a) hci_transport_cyw43_process, b) cyw43_bluetooth_hci_read, and c) the processing in BTstack. Please see attached traces.

When testing against a CYW20704, I did get 66 kB/s when sending 200 byte packets. With lower packet sizes, the throughput goes down. One fact is that the CYW20704 has 8 buffers for LE ACL packets. If we receive them faster than we can read the with the RP2040, this could be a bottleneck.

@peterharperuk : in the traces for smaller packet sizes, hci_transport_cyw43_process is entered, but cyw43_bluetooth_hci_read seems to report no data to read. I don't know what to make of that.

@sanjay900 : what's your project requirements? Is it pico<->pico only? You can 'play' with the connection interval and the packet size (e.g. sending multiple reports in one packet if you don't need to comply to a standard). You could also try to use Bluetooth Classic HID to see if that works better for your case.

I still don't know what's really going on. One idea would be to ask Infineon if they can increase the number of LE ACL buffers (right not 8 x 251 ~ 2 kB are used and the Controller should have way more memory). e.g. 16 buffers? :0) this might help. I've also tried shorted connection intervals and in one session just got broken links while in another, it worked as expected with the same hardware on my table.

traces.zip

mringwal avatar Apr 17 '23 09:04 mringwal

@mringwal If i can i would like to stick with something HID based, as my goal is for my game controller to still work with a PC normally, and then for the pico <-> pico bit to be only necessary if a user would like to use their controller on a game console.

I originally tried bluetooth classic but it seems that had a lower latency even with just a PC when i tried that originally, but i didn't actually change any settings from the defaults in the classic examples.

sanjay900 avatar Apr 17 '23 09:04 sanjay900

@sanjay900 In that case, I would suggest to try the Classic HID examples :)

mringwal avatar Apr 17 '23 09:04 mringwal

Ill give that a go again tomorrow and see if i can work out a way to get them working at a decent speed.

sanjay900 avatar Apr 17 '23 09:04 sanjay900

it seems going to classic HID cuts the poll rate to around 374hz with a pc, though thats just using the default hid example, are there things i can tweak there to get a lower latency out of it?

sanjay900 avatar Apr 18 '23 10:04 sanjay900

Well, that's one report every 3 ms. isn't that good enough? :) you can compare to same code with libusb.

mringwal avatar Apr 18 '23 10:04 mringwal