test/xtimer_drift: interval calculation

[Josar]

This PR corrects the calculation of the interval. In the current implementation the TEST_INTERVAL is calculated with 1000000/64 = 15 625.
If the xtimer precision is not better than 1ms this will always produce drift as this results in wrong intervals.

With this PR the intervall to calculate drift and jittter is based on the achievable precision and not on the requested precision of TEST_INTERVAL.

This makes it easier to spot errors. At the moment if the achievable precision with the xtimer does not match the requested precision the drift will always increase and the jitter always change so it is impossible to see if the periodic timer works as expected.

This PR is not dependent on the following PRs but with
#9211
#9595
#9596

merged and calibration done as described in
#8990

the result will look as follows
https://gist.github.com/Josar/19006fe56d39a49b268c34f40942cbcd

[A-Paul]

Hi @Josar, you again? ;)
Your test log is rather long. You might consider to put that in a gist and link it.
More important for me is, what board did you use?

Your changes would only make a difference on MCUs that have XTIMER_SHIFT != 0, right?

[Josar]

Hi @A-Paul I used the Jiminy board. And yes this commit only changes the outcome of the test if the board is configured to use a xtimer which is not based on a clock that has a precision equal to 1us.

[A-Paul]

The change in calculating the test_interval looks reasonable.
To check the difference for affected MCUs and also identical behavior otherwise I modified the code to generate output with the old and new values in two lines.
Also prints the XTIMER_SHIFT value.

With an arduino-mega3560:

2018-08-03 18:35:17,486 - INFO # main(): This is RIOT! (Version: 2018.10-devel-62-gf85a16-mobi31-Josar_pr/xtimer_drift/interval)
2018-08-03 18:35:17,514 - INFO # [START],[XTIMER_SHIFT:02]
2018-08-03 18:35:19,350 - INFO # now=1.142636 (0x00045bdb ticks):
2018-08-03 18:35:19,382 - INFO # drift1=-64 us, jitter1=-64 us
2018-08-03 18:35:19,411 - INFO # drift2=0 us, jitter2=0 us
2018-08-03 18:35:21,664 - INFO # now=2.142572 (0x00082c5b ticks):
2018-08-03 18:35:21,697 - INFO # drift1=-128 us, jitter1=-64 us
2018-08-03 18:35:21,726 - INFO # drift2=0 us, jitter2=0 us
[...]
2018-08-03 18:37:00,062 - INFO # now=100.136292 (0x017dfd59 ticks):
2018-08-03 18:37:00,099 - INFO # drift1=-6408 us, jitter1=-72 us
2018-08-03 18:37:00,128 - INFO # drift2=-8 us, jitter2=-8 us
2018-08-03 18:37:01,066 - INFO # now=101.136236 (0x0181cddb ticks):
2018-08-03 18:37:01,098 - INFO # drift1=-6464 us, jitter1=-56 us
2018-08-03 18:37:01,127 - INFO # drift2=0 us, jitter2=8 us

and with cc2538dk

2018-08-03 19:50:18,897 - INFO # main(): This is RIOT! (Version: 2018.10-devel-62-gf85a16-mobi31-Josar_pr/xtimer_drift/interval)
2018-08-03 19:50:18,897 - INFO # [START],[XTIMER_SHIFT:00]
2018-08-03 19:50:19,920 - INFO # now=1.025325 (0x000fa52d ticks):
2018-08-03 19:50:19,921 - INFO # drift1=0 us, jitter1=0 us
2018-08-03 19:50:19,921 - INFO # drift2=0 us, jitter2=0 us
2018-08-03 19:50:20,912 - INFO # now=2.025325 (0x001ee76d ticks):
2018-08-03 19:50:20,913 - INFO # drift1=0 us, jitter1=0 us
2018-08-03 19:50:20,928 - INFO # drift2=0 us, jitter2=0 us
[...]
2018-08-03 19:52:00,923 - INFO # now=102.025389 (0x0614c8ad ticks):
2018-08-03 19:52:00,924 - INFO # drift1=64 us, jitter1=64 us
2018-08-03 19:52:00,924 - INFO # drift2=64 us, jitter2=64 us
2018-08-03 19:52:01,915 - INFO # now=103.025325 (0x06240aad ticks):
2018-08-03 19:52:01,916 - INFO # drift1=0 us, jitter1=-64 us
2018-08-03 19:52:01,916 - INFO # drift2=0 us, jitter2=-64 us

[A-Paul]

@Josar, if your interested. My modification for the output is here: A-Paul@f85a161.
Maybe you can run it on your board for 1-2min and post a sample here (same as in my review, just with the first and last two events).

[A-Paul]

Hi @Josar, I think the purpose of this function(reverse function()) construct is not obvious. Someone may come and "optimize" this away.
Please put a short comment there. Something like:
/* Apply precision loss, when 'XTIMER_SHIFT > 0', to expected interval length. */

[A-Paul]

Insert an explaining comment.

[Josar]

main(): This is RIOT! (Version: 2018.10)
[START],[XTIMER_SHIFT:03]
now=1.052224 (0x000201c8 ticks):
	drift1=-64 us, jitter1=-64 us
	drift2=0 us, jitter2=0 us
now=2.052176 (0x0003ea0a ticks):
	drift1=-112 us, jitter1=-48 us
	drift2=16 us, jitter2=16 us
now=3.052264 (0x0005d25d ticks):
	drift1=-24 us, jitter1=88 us
	drift2=168 us, jitter2=152 us


now=97.047232 (0x00b91a58 ticks):
	drift1=-5056 us, jitter1=-40 us
	drift2=1152 us, jitter2=24 us
now=98.047184 (0x00bb029a ticks):
	drift1=-5104 us, jitter1=-48 us
	drift2=1168 us, jitter2=16 us

As this test is based on this branch and does not contain the mentionen PRs above there is clearly a error compared to the first post.

xxxx-xx-xx xx:xx:40,512 - INFO # [START]
xxxx-xx-xx xx:xx:40,512 - INFO # 
xxxx-xx-xx xx:xx:41,515 - INFO # now=1.045872 (0x0001feae ticks), drift=0 us, jitter=0 us
xxxx-xx-xx xx:xx:42,513 - INFO # now=2.045808 (0x0003e6ee ticks), drift=0 us, jitter=0 us
2.045808: Invalid timebetween messages, expected 0.9 < 0.13449978828430176 < 1.1
xxxx-xx-xx xx:xx:43,514 - INFO # now=3.046312 (0x0005cf75 ticks), drift=568 us, jitter=568 us
.
.
.
xxxx-xx-xx xx:xx:29,514 - INFO # now=109.038944 (0x00cff9ac ticks), drift=-16 us, jitter=-16 us
xxxx-xx-xx xx:xx:30,513 - INFO # now=110.038896 (0x00d1e1ee ticks), drift=0 us, jitter=16 us
xxxx-xx-xx xx:xx:31,513 - INFO # now=111.038832 (0x00d3ca2e ticks), drift=0 us, jitter=0 us

[A-Paul]

@Josar, please squash.

[Josar]

@A-Paul done.

[A-Paul]

Hi @Josar, CI is showing an error with tests/xtimer_now64_continuity on native. It might be an issue with the commit which you rebased on.
Please rebase to actual master again.

[Josar]

done.

[A-Paul]

@Josar, that looks better. Thanks for addressing comments and so on ... ;)