Bad chronological ordering of events

[Matthew Bradbury]

Hello,

I am running some experiments (with a colleague) on the testbed and am consistently getting results where the chronology isn't correct.

For example, a node will report that a packet was received before the sending node reports that the packet was sent.

We are using serial messages in text to report these events. Most events are correctly ordered, however a small number are not.

An older post [1] said that NTP time synchronisation is performed every 1-2 min. Is that still the case?

What is the resolution of the timer used to timestamp the received serial message?

Thanks,
Matthew

[1] https://groups.google.com/forum/#!newtopic/flocklab-users/flocklab-users/wKyD3CeF_cw

[rdaforno]

Hi Matthew

The synchronization of our Testbed is based on a wireless protocol. Therefore, it sometimes happens that observers get disconnected due to a bad RF link / interference, especially in the 868 MHz band. If everything runs well, then the time accuracy is in the order of a few 100 nanoseconds.

Please let me know the test number where you have seen this time shift, then I will have a look at it.

Currently, our monitoring system doesn't indicate an issue with timesync.

Cheers,
Reto

[Jack Kirton]

Hi Reto

An example test where this occurs is 54904, where the delivery metrics (M-CD) occur on lines 3073, 3449, 3877, 4080 and 4441 and the broadcast metric (M-CB) occurs on line 4943.

Cheers,

Jack

[rdaforno]

Hi Jack

Correction on the timestamp accuracy for the serial output: The sub microsecond timestamps are only available for the GPIO tracing and power profiling. For the serial output, NTP time is used and therefore, differences of several milliseconds are not uncommon.

The minimum polling interval is 32 seconds. 

You are welcome to look into and contribute to the Flocklab code.

Cheers,
Reto

[Matthew Bradbury]

Hi Reto,

Just to keep you up-to-date with us looking into this. We had a number of experiments run before 2018-04-25 10:01:28 +01:00, none of which encountered this issue. All deliver events were preceded with broadcast events. However, on the 26th the following change was made to the time sync configuration: https://gitlab.ethz.ch/tec/public/flocklab/commit/ce6616efa847db98e615cdb279625757206c282c

Perhaps it is worth checking that the two time servers agree with each other regarding what time it is? It might also be worth checking the drift between local nodes and the time server. (I cannot check as neither time server is accessible, I assume they are restricted to ETH Zurich's intranet)

However, it looks like all logging is done on a single node (https://gitlab.ethz.ch/tec/public/flocklab/blob/master/observer/services/python/flocklab_serial.py), so I think time sync might not be the source of our problem.

Many thanks,
Matthew