We have built a wearable device that takes measurements and sends the results over BLE to an Android device every 20msec. We are getting strange results where the first 270 packets are received on time and without loss, but at 271 things get strange. We will give five packets (on time) and then drop 32 packets, and then repeat.
The mobile phone is a Nexus 5X with Android 7.1.1. The device is running an nRF51 with BLE 4.2. And we are using the Android nRF toolbox v2.4.0 based on the Template app.
One hypothesis we had was that the ConnectionPriority was wrong and that we need to set to a higher priority. We have tried adding the following in the BleManager:
mBluetoothGatt.requestConnectionPriority(BluetoothGatt.CONNECTION_PRIORITY_HIGH);
But is makes no difference. The odd thing is that the system seems to work find for the first 270 packets.
Any ideas how to debug this?
Sample logcat below. Note that the packet numbers are the received packet numbers on the Android side, not the packet numbers from the device side:
Packet #258; SensorTime = 256.175sec; Delta = 018.8msec
Packet #259; SensorTime = 256.200sec; Delta = 025.0msec
Packet #260; SensorTime = 256.213sec; Delta = 012.5msec
Packet #261; SensorTime = 256.238sec; Delta = 025.0msec
Packet #262; SensorTime = 256.256sec; Delta = 018.8msec
Packet #263; SensorTime = 256.275sec; Delta = 018.8msec
Packet #264; SensorTime = 256.300sec; Delta = 025.0msec
Packet #265; SensorTime = 256.319sec; Delta = 018.8msec
Packet #266; SensorTime = 256.338sec; Delta = 018.8msec
Packet #267; SensorTime = 256.356sec; Delta = 018.7msec
Packet #268; SensorTime = 256.375sec; Delta = 018.8msec
Packet #269; SensorTime = 256.394sec; Delta = 018.8msec
Packet #270; SensorTime = 256.419sec; Delta = 025.0msec
Packet #271; SensorTime = 256.438sec; Delta = 018.8msec
=== Time Fault :: Time 256.656sec : Time delta = 218.8 msec; mTime since last fault = 0.000 sec
Packet #272; SensorTime = 256.656sec; Delta = 218.8msec
=== Time Fault :: Time 257.294sec : Time delta = 637.5 msec; mTime since last fault = 0.001 sec
Packet #273; SensorTime = 257.294sec; Delta = 637.5msec
Packet #274; SensorTime = 257.313sec; Delta = 018.8msec
=== Time Fault :: Time 257.938sec : Time delta = 625.0 msec; mTime since last fault = 0.639 sec
Packet #275; SensorTime = 257.938sec; Delta = 625.0msec
=== Time Fault :: Time 258.594sec : Time delta = 656.3 msec; mTime since last fault = 0.003 sec
Packet #276; SensorTime = 258.594sec; Delta = 656.3msec
Packet #277; SensorTime = 258.613sec; Delta = 018.8msec
Packet #278; SensorTime = 258.638sec; Delta = 025.0msec
Packet #279; SensorTime = 258.650sec; Delta = 012.5msec
Packet #280; SensorTime = 258.675sec; Delta = 025.0msec
=== Time Fault :: Time 259.231sec : Time delta = 556.2 msec; mTime since last fault = 0.639 sec
Packet #281; SensorTime = 259.231sec; Delta = 556.2msec
Packet #282; SensorTime = 259.256sec; Delta = 025.0msec
Packet #283; SensorTime = 259.275sec; Delta = 018.8msec
Packet #284; SensorTime = 259.294sec; Delta = 018.7msec
Packet #285; SensorTime = 259.313sec; Delta = 018.8msec
=== Time Fault :: Time 259.875sec : Time delta = 562.5 msec; mTime since last fault = 0.657 sec
Packet #286; SensorTime = 259.875sec; Delta = 562.5msec
Packet #287; SensorTime = 259.894sec; Delta = 018.8msec
Packet #288; SensorTime = 259.913sec; Delta = 018.8msec
Packet #289; SensorTime = 259.931sec; Delta = 018.8msec
Packet #290; SensorTime = 259.956sec; Delta = 025.0msec
=== Time Fault :: Time 260.513sec : Time delta = 556.2 msec; mTime since last fault = 0.636 sec
Packet #291; SensorTime = 260.513sec; Delta = 556.2msec
Packet #292; SensorTime = 260.531sec; Delta = 018.8msec
Packet #293; SensorTime = 260.550sec; Delta = 018.8msec
Packet #294; SensorTime = 260.569sec; Delta = 018.8msec
Packet #295; SensorTime = 260.594sec; Delta = 025.0msec
=== Time Fault :: Time 261.169sec : Time delta = 575.0 msec; mTime since last fault = 0.645 sec
Packet #296; SensorTime = 261.169sec; Delta = 575.0msec
Packet #297; SensorTime = 261.188sec; Delta = 018.8msec
Packet #298; SensorTime = 261.213sec; Delta = 025.0msec
Packet #299; SensorTime = 261.231sec; Delta = 018.7msec
Packet #300; SensorTime = 261.250sec; Delta = 018.8msec
=== Time Fault :: Time 261.806sec : Time delta = 556.3 msec; mTime since last fault = 0.645 sec
Packet #301; SensorTime = 261.806sec; Delta = 556.3msec
Packet #302; SensorTime = 261.831sec; Delta = 025.0msec
Packet #303; SensorTime = 261.850sec; Delta = 018.8msec
Packet #304; SensorTime = 261.869sec; Delta = 018.8msec
Packet #305; SensorTime = 261.894sec; Delta = 025.0msec
=== Time Fault :: Time 262.456sec : Time delta = 562.5 msec; mTime since last fault = 1.283 sec
Packet #306; SensorTime = 262.456sec; Delta = 562.5msec
Packet #307; SensorTime = 262.469sec; Delta = 012.5msec
Packet #308; SensorTime = 262.488sec; Delta = 018.8msec
Packet #309; SensorTime = 262.506sec; Delta = 018.8msec
Packet #310; SensorTime = 262.525sec; Delta = 018.8msec
=== Time Fault :: Time 263.106sec : Time delta = 581.2 msec; mTime since last fault = 0.658 sec
Packet #311; SensorTime = 263.106sec; Delta = 581.2msec
=== Time Fault :: Time 263.750sec : Time delta = 643.8 msec; mTime since last fault = 0.631 sec
Packet #312; SensorTime = 263.750sec; Delta = 643.8msec
=== Time Fault :: Time 264.388sec : Time delta = 637.5 msec; mTime since last fault = 0.003 sec
Packet #313; SensorTime = 264.388sec; Delta = 637.5msec
After tracking packet with a BLE sniffer, we discovered that, on the device side, there was a pair of bad constants:
#define MIN_CONN_INTERVAL MSEC_TO_UNITS(400, UNIT_1_25_MS)
#define MAX_CONN_INTERVAL MSEC_TO_UNITS(650, UNIT_1_25_MS)
These were corrected as follows:
#define MIN_CONN_INTERVAL MSEC_TO_UNITS(10, UNIT_1_25_MS)
#define MAX_CONN_INTERVAL MSEC_TO_UNITS(20, UNIT_1_25_MS)
Once corrected the connection rate settled our fine. The most bizarre part was that some devices and some phones worked at full speed, but others would drop into the above incorrect Connection Priority. THanks for the help. The sniffer was the key here!