(I also posted this on the mbed BLE_API forum)
Hi all,
Sorry for the long post, I'm starting yet another discussion on BLE throughput, but I feel this merits a deeper look.
tl;dr - I'm getting BLE_GATTS_EVT_WRITE callbacks only once every 2 sec.
Background
I'm trying to transfer about 20 kB of data over a BLE link, from an iPhone to a Nordic mbed kit. I'm doing this by writing 16 byte chunks with 2 byte offset (total 18 bytes) to a "write without response" (write command) characteristic. I've set the connection parameters to the minimum that's supported by iOS. Theoretically I should be able to do 6 packets of 16 bytes, per conn. interval of 20 ms, giving me about 4.8 kB/sec. I know this doesn't actually happen, and my conservative calculation says I should at least be able to transfer one packet every conn.interval, and get approx 0.8 kB/sec. Even if the conn.interval is 40 ms (the max I've set), I should still get 0.4 kB/sec.
In early phase, I was doing a request-response design where the nordic chip sends a request for a particular block and iOS responds, but this was too slow for obvious reasons. Now I switched to write-without-response and no requests from chip to phone.
iOS side
On iOS, I run a loop to write n packets every x ms. I've set x to 20 ms, 50 ms etc. and tried sending between 1 and 6 packets on every timer tick. This succeeds as far as the iPhone is concerned.
BLE (nordic) side
In the firmware, I set preferred connection parameters on initialisation, and send a parameter update on connection. I should be getting a write callback for every packet. But I noticed strange behaviour here --
- initially, I was getting a lot of missed and repeated packets. I always got the correct number of callbacks (and thus packets received). But many packets were copies of other packets. This was repeatable in almost the same order every time. For example, for a transfer of 10 packets (#0 to #9), I would something like: 2,3,3,3,5,6,7,9,9,9. 0 and 1 would always be missing, 9 was always sent thrice etc. I guessed it was because a new packet would come in and overwrite the previous while I was still processing it. However I reduced my "processing" to barely reading in the packet, and printing out over serial port some debug info. Then I also tried turning off DEBUG logs. No difference. I also added CRITICAL_REGION_ENTER() and ..EXIT() around the callback, which helped a little but still had issues with larger number of blocks losing sync.
- next I tried creating 6 characteristics and transferred the data one by one. So, first block to ch 0, 2nd to ch1 and so on in a round robin way. This helped, but I also had to increase time between packets to 200 ms and sending only 1 packet per tick. With this I was able to transfer 80-100 packets fine reliably. Almost always after 136 packets, the 137th would be missed and instead, two 138 would be sent and thereafter it would lose sync.
- many times, if I sent data right after connecting, small transfer (10-20 packets) would complete very fast as expected. But it would eventually slow down (see more info below).
- I tried several other things, like using BLE_GATTS_VLOC_USER for the characteristics
Finally I tried to print the time elapsed between successive calls to nRF51GattServer::hwCallback() (in mbed BLE library) which receives the BLE_GATTS_EVT_WRITE from the softdevice. This is where I realised something out of my understanding is going on.
I noticed that the callbacks were coming in approx every 2000 ms! Sometimes I would get callbacks every 80 ms right after connecting, but within a few sec it would slow down back to every 2 sec. This meant I was only getting about one 16 byte packet per 2 sec!
Below is a log of when transfer happened fast:
Initialising | Built Aug 13 2014 16:22:39
Bluetooth initialising...
Conn. params => min=16, max=40, slave=0, supervision=500
Added service
Ready. Advertising.
____[ Connected ]______________________________________
time 0 ms
time 353 ms
Notifications enabled for 2
time 105 ms
time 1999 ms
Download RESET
time 131 ms
Offered file len=156, crc=0x1234, acceptFile=1, downloadInProgress=0
time 181 ms
.time 83 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 131 ms
.time 82 ms
.time 83 ms
.File transfer took 1.1 sec
and here is another log where you can see the slow-down occurring after a while:
Initialising | Built Aug 13 2014 16:22:39
Bluetooth initialising...
Conn. params => min=16, max=40, slave=0, supervision=500
Added service
Ready. Advertising.
____[ Connected ]______________________________________
time 0 ms
time 292 ms
Notifications enabled for 2
time 165 ms
time 1689 ms
Download RESET
time 245 ms
Offered file len=1267, crc=0x1234, acceptFile=1, downloadInProgress=0
time 181 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 83 ms
.time 132 ms
.time 148 ms
.time 82 ms
.time 149 ms
.time 82 ms
.time 149 ms
time 0 ms
.time 1716 ms <-- note slow down point
.time 2044 ms
.time 1979 ms
.time 2044 ms
.time 1979 ms
.time 1979 ms
.time 1979 ms
.time 1979 ms
.time 2044 ms
.time 1979 ms
.time 2044 ms
.time 1979 ms
.time 1979 ms
.time 1979 ms
.time 1979 ms
.time 1979 ms
.time 1979 ms
.time 2044 ms
....
It seems some sort of power management is kicking in, slowing down the hardware ??
So I guess my question is: why is this happening, and how can I investigate this further? Is this on mbed BLE API side, or the nordic softdevice side, or in my code? I would be happy to help with any kind of debugging. Please help!
For reference, I've successfully been transferring about 128 kB of data in under 3 min, using almost exactly the same method, with the TI CC2541.
Thanks.
