Weird log data from data sent by ESP32

[Uwe]

Hi,

I played around with the ESP32 example for Phyphox taken from here:
https://phyphox.org/wiki/index.php?title...ed_sensors

When I raised the frequency of notifications I found a surprising behaviour with time stamps logged in Phyphox and started to dig into that.
I modified the sketch so it sends the value of millis() (converted to 16bit int) every 5ms to my Samsung S6 running Phyphox app.
Here's the sketch used:

Code:

/*
//#############################################################################
//In this sketch a BLE server with one service and one characeristic is created.
//The analog input (pin 36) is readout periodically.

Diese Version dient dazu, zu testen, mit welcher Frequenz BLE Notifications an Phyphox verschickt werden können.
Dazu wird in einer Endlos-Schleife der jeweils aktuelle Wert von micros() gesendet.
In Phyphox kann man dann anhand der erhaltenen Werte sehen, mit welchem zeitlichen Abstand das erfolgt ist.

//#############################################################################
*/
#include <BLEDevice.h>
#include <BLEUtils.h>
#include <BLEServer.h>
#include <esp_system.h>
#include <BLE2902.h>


//uuid's can be generated on https://www.uuidgenerator.net/
//#define SERVICE_UUID        "cddf0001-30f7-4671-8b43-5e40ba53514a"
//#define CHARACTERISTIC_UUID "cddf0002-30f7-4671-8b43-5e40ba53514a"
#define SERVICE_UUID        "4fafc201-1fb5-459e-8fcc-c5c9c331914b"
#define CHARACTERISTIC_UUID "59f51a40-8852-4abe-a50f-2d45e6bd51ac"
BLECharacteristic *aCharacteristic;

uint16_t timestamp;

void setup() {
Serial.begin(115200);

//BLE server is being initialized
//create one BLEService and one Characteristic
BLEDevice::init("ESP32");
BLEServer *aServer = BLEDevice::createServer();
//uuid for the BLE service is set
BLEService *aService = aServer->createService(SERVICE_UUID);
//uuid for the BLE characteristic is set
//the characteristics properties are defined
aCharacteristic = aService->createCharacteristic(
                     CHARACTERISTIC_UUID,
                     BLECharacteristic::PROPERTY_READ   |
                     BLECharacteristic::PROPERTY_WRITE  |
                     BLECharacteristic::PROPERTY_NOTIFY 
                   );
aCharacteristic->addDescriptor(new BLE2902());

//BLE server is being started
aService->start();
BLEAdvertising *aAdvertising = aServer->getAdvertising();
aAdvertising->start();

}

void loop() {
timestamp = int(millis());
aCharacteristic->setValue(timestamp);
aCharacteristic->notify();
Serial.println(timestamp);
delay(5);

}

So each notification's value sent by ESP 32 increments by 5 and notification transmit interval is 5ms. No sensor used at all.
This allows to compare timing of GATT server and client (so I thought).

What I saw in Phyphox log was astonishing and up to now I have no idea what's going on:

1. When timestamps in Phyphox suggest that 1 sec has passed, only about 120 notifications (equivalent to 600 ms) arrived.
   This is a stable problem.
   
2. While timestamps logged show about 7-8 decimal places (which suggest a high resolution) values don't show a constant increase from entry to entry when one looks to decimals 2-8. Sometimes there is even the same timestamp for sequent entries !
   I know that anything more than 3-4 decimals doesn't make any sense, but if we cannot rely on decimal 2 than everything faster than 10Hz won't work.
   
3. Every 2 seconds the notification's value shows an instant increase of about 820 counts (= 820 ms = 160 notifications); so value of 2 sequent notifications differs by 820 counts
   It looks like as ESP32 has paused sending for a while; but at the same time there is NO gap in timestamps logged !!
   

With effects #1 and #3 combined timestamps and received values are in sync again after about 2 secs (600ms + 600ms + 820ms = 2000ms) , but nevertheless the behaviour seems to be strange and would mean a loss of data.
On ESP32 I added logging of millis() to serial monitor but didn't saw any pause or spontaneous increase of the value.

Good news is: this is not limited to Phyphox app; I also was able to see that behaviour e.g. with nRF connect app or LightBlue when logging data.
So it seems to be a BLE topic in general (may be in combination with Android).

I haven't tested other BLE connection parameters e.g. connection interval or others; even didn't set them explicitly at all, as I don't understand in detail (# packets per connection interval), so implicit default settings were used.

I've attached Excel sheet with log data from Phyphox' CSV export.

My questions:

1. Any idea where this might come from ? Anybody seen this or something similar before ?
   
2. Is frequency of notifications just to high (didn't test other intervals thoroughly) ?
   
3. Any hint how to proceed or solve ?
   

Thanks
Uwe

[Sebastian Staacks]

• When timestamps in Phyphox suggest that 1 sec has passed, only about 120 notifications (equivalent to 600 ms) arrived.This is a stable problem.

Not surprising so far, this is similar to the maximum rate we have seen when trying to use higher rates. This of course can depend on signal quality and the actual devices used.

• While timestamps logged show about 7-8 decimal places (which suggest a high resolution) values don't show a constant increase from entry to entry when one looks to decimals 2-8. Sometimes there is even the same timestamp for sequent entries !
  I know that anything more than 3-4 decimals doesn't make any sense, but if we cannot rely on decimal 2 than everything faster than 10Hz won't work.
  
• Every 2 seconds the notification's value shows an instant increase of about 820 counts (= 820 ms = 160 notifications); so value of 2 sequent notifications differs by 820 counts
  It looks like as ESP32 has paused sending for a while; but at the same time there is NO gap in timestamps logged !!
  

Well, the clock used has indeed a high resolution. Phyphox calls System.nanoTime() (Android) when it receives a value and that is the number you get there (here it is in the code:https://github.com/Staacks/phyphox-android/blob/335ab6bd71ec63a1eb769fcd3a0069310b00f308/app/src/main/java/de/rwth_aachen/phyphox/Bluetooth/BluetoothInput.java#L306) . However, this is not the time the value was measured or the time at which you called "notify". It is the time at which the value has passed the Bluetooth stacks and was handed over to the callback function in phyphox. When multiple values have the same timestamp, I would guess that there is some optimization going on that multiple values are transferred in one "burst", but I have to admit that my understanding of the Bluetooth protocol at that point is very limited.

Good news is: this is not limited to Phyphox app; I also was able to see that behaviour e.g. with nRF connect app or LightBlue when logging data.
So it seems to be a BLE topic in general (may be in combination with Android).

Relieved to read that This adds to my guess that it is an optimization in Bluetooth. BLE is not designed to guarantee the arrival of a value at a given time, but to be suitable for low energy applications. It makes sense that multiple values are stored to be sent in a single burst for efficiency.

1. Any idea where this might come from ? Anybody seen this or something similar before ?
   
2. Is frequency of notifications just to high (didn't test other intervals thoroughly) ?
   
3. Any hint how to proceed or solve ?
   

So, yes, 200 Hz in my experience is a bit much. You might be able to increase the data rate by packing multiple values into a single notification. Simply let your characteristic not hold a single 16bit int (2 byte), but a sequence of multiple, which you can unpack in phyphox by using different offsets and appending the result. Not sure how much it helps, but it should reduce the overhead a bit. If this helps a lot in your case, you can also increase the MTU since the last phyphox version, to pack even more into a single package, although I would expect that there is a limit at which it won't help that much.

The timestamp created by phyphox will always be subject to network lag, so even at lower rates with a weak and unstable connection, you might see some surprising delays in this value. To solve the timestamp issue, meaning to get reliable and precise timestamps, you need to measure the time on your device and either transfer it or make sure that you transfer equidistant (or is "equitemporal" the word?) measurements and create the timestamp in phyphox based on the assumption that you did not miss anything. You can either pack the timestamp with your transferred value (and simply assign them in phyphox using an offset= and the appropriate conversion function) or have a look at what we do for most sensor boxes. They all just send a stream of values and we have to assume that they are created at a given rate. This reduces the required bandwidth and remains precise even on a laggy connection. The downside is that value is not long-term stable if a package is missed. An example can be found in our configuration for the SensorTag: https://github.com/Staacks/phyphox-exper...er.phyphox - we simply create the time axis with a "ramp" module.

[Uwe]

Your reply explains very comprehensible what I saw during my tests.

To summarize your recommendations:

1. on timestamps: generate timestamps in Phyphox assuming equidistant measurements and no loss in transmission (at least last one being in question what I saw) or add timestamp to notification and send together with sensor value
   
2. data rate: collect multiple measure on peripheral device and send in one notification
   

Sounds great especially in combinations with Phyphox capabilities for post processing of data received.
I wasn't aware of these capabilities in details and all the functionality they provide. Again a lot to learn ....

So a wide range of measure to work on and good chance to improve 

Thanks a lot for your outstanding support and help !!
Uwe