saml21 system time vs rtc

[fedepell]

Description

System time on my saml21-xpro seems to be quite innacurate, both compared to the RTC and to an external source. In about 1 hour I can see a drift of about 15 seconds which seems quite a lot.
Is this to be expected or could something be lying behind that could be analyzed better? (I can try to give a deeper look if this is not expected)

Steps to reproduce the issue

I did a simple application that has a loop that every minute reads the system time, reads the RTC time and prints them out. Something more or less like:

    time_t rawtime;
    struct tm *info;
    struct tm curtime;

    char buffer[80];
    char buffer2[80];
    int contatore=0;

    while (1) {
      time( &rawtime );
      info = localtime( &rawtime );      
      strftime(buffer,80,"%x %H:%M:%S", info);

      rtc_get_time(&curtime);
      strftime(buffer2,80,"%x %H:%M:%S", &curtime);
      
      printf("[CNT: %8d][SYS: %s][RTC: %s]\r\n",contatore,buffer,buffer2);

      contatore++;
      xtimer_sleep(60);
    }

RTC is initialized at some known value at the beginning.

Expected results

I would expect them to run roughly at the same speed.

Actual results

I see a drift of about 15 seconds in an hour which sounds quite something to me. Compared to an external source (my PC) the time read from the RTC is the correct one, as that one is aligned (at least after a couple of hours and to a precision of 1 sec) to the PC.
What I see running the test is (I omit some iterations) for example:

RTC Start time is 18 November 2018 at 08:00:00
[CNT:        0][SYS: 01/01/70 00:00:00][RTC: 11/18/18 08:00:00]
[CNT:        1][SYS: 01/01/70 00:01:00][RTC: 11/18/18 08:01:00]
[CNT:        2][SYS: 01/01/70 00:02:00][RTC: 11/18/18 08:02:00]
[CNT:        3][SYS: 01/01/70 00:03:00][RTC: 11/18/18 08:03:00]
[CNT:        4][SYS: 01/01/70 00:04:00][RTC: 11/18/18 08:04:00]
[CNT:        5][SYS: 01/01/70 00:05:00][RTC: 11/18/18 08:05:01]
[CNT:        6][SYS: 01/01/70 00:06:00][RTC: 11/18/18 08:06:01]
[CNT:        7][SYS: 01/01/70 00:07:00][RTC: 11/18/18 08:07:01]
[CNT:        8][SYS: 01/01/70 00:08:00][RTC: 11/18/18 08:08:01]
[CNT:        9][SYS: 01/01/70 00:09:00][RTC: 11/18/18 08:09:02]
[CNT:       10][SYS: 01/01/70 00:10:00][RTC: 11/18/18 08:10:02]
....
[CNT:       59][SYS: 01/01/70 00:59:00][RTC: 11/18/18 08:59:14]
[CNT:       60][SYS: 01/01/70 01:00:00][RTC: 11/18/18 09:00:14]
[CNT:       61][SYS: 01/01/70 01:01:00][RTC: 11/18/18 09:01:15]
[CNT:       62][SYS: 01/01/70 01:02:00][RTC: 11/18/18 09:02:15]
.....
[CNT:      109][SYS: 01/01/70 01:49:00][RTC: 11/18/18 09:49:27]
[CNT:      110][SYS: 01/01/70 01:50:00][RTC: 11/18/18 09:50:27]
[CNT:      111][SYS: 01/01/70 01:51:00][RTC: 11/18/18 09:51:27]

So the system time seem to be running slower than the RTC/real one. While I could understand some degree of imprecision I would think that 15 seconds per hour sounds quite high. While the RTC (that could be tuned eventually) seems to perform quite ok.

Is this behaviour expected ?

I saw this behaviour on a custom hardware but then to clear doubts about the hardware implementation I tried also on the EVB and got the same results indeed. Also on custom hardware the RTC seemed to run fine, while the system time was drifting, but interestingly enough not always at the same speed, always lagging but not always at the same speed.

[jnohlgard]

I have seen some bad results with the tests/bench_timer application on samr21-xpro as well. I think the sam0 periph/timer driver is the problem and that it loses ticks, but I have not had time to investigate further.
Could you try the tests/bench_timer application on your dev board as well?

[dylad]

Thanks for reporting it back @fedepell !
I'll try to have a look at it on my saml21-xpro board soon.
@gebart periph_timer implementation is not shared between sam0 based board. each CPU defines its own implementation (which are very likely IIRC). It could also be a different issue on samr21-xpro.
I can also try on a arduino-zero like board in the same time.

[fedepell]

@gebart : I wanted to run the test but am stuck with it, it starts but (as far as I see) then it blocks.

As the saml21-xpro has a single timer I put my board under SINGLE_TIMER_BOARDS in the makefile and build and flashed, but then it will start and:

Statistical benchmark for timers
Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
TEST_MIN = 16
TEST_MAX = 128
TEST_MIN_REL = 0
TEST_MAX_REL = 112
TEST_NUM = 113
log2(TEST_NUM - 1) = 6
state vector elements per variant = 7
number of variants = 8
sizeof(state) = 32 bytes
state vector total memory usage = 1792 bytes
TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
TIM_REF_DEV  = 0, TIM_REF_FREQ  = 1000000
USE_REFERENCE = 1
TEST_PRINT_INTERVAL_TICKS = 30000000
Expected error variance due to truncation in tick conversion: 0
Calibrating spin delay...
spin_max = 47
Estimating benchmark overhead...
overhead_target = 14 (s2 = 0)
overhead_read = 14 (s2 = 0)
exp_mask = 00000007
max interval = 255

Any hint maybe how I could run it? Thanks a lot!

[jnohlgard]

@fedepell might be xtimer or something interfering with the hardware timer. Try adding DISABLE_MODULE=xtimer on the command line when building.

[fedepell]

@gebart : thanks for the hint. Sadly didn't change much.

I checked a bit more in detail and noticed that it is always stuck at the

mutex_lock(&mtx_cb);

At the end of run_test. Seems like mtx_cb is already locked and nothing happens to unlock it. Trying to figure out why now.

[dylad]

@fedepell I just tested your code on arduino-zero like board. It works like a charm without any drift (after 20 minutes).
I believe SAMD21 and SAML21 share the same timer IP.
I was also able to reproduce your issue on my saml21-xpro and I got the same results as you.
Maybe we should try to merge these drivers into a single one ?

[dylad]

Full result with arduino-zero like:

2018-12-02 18:01:51,318 - INFO # main(): This is RIOT! (Version: 2018.10-RC1-392-g43d3)
2018-12-02 18:01:51,359 - INFO # [CNT:        0][SYS: 01/01/70 00:00:00][RTC: 00/00/00 00:00:00]
2018-12-02 18:02:51,363 - INFO # [CNT:        1][SYS: 01/01/70 00:01:00][RTC: 01/01/00 00:01:00]
2018-12-02 18:03:51,389 - INFO # [CNT:        2][SYS: 01/01/70 00:02:00][RTC: 01/01/00 00:02:00]
...
2018-12-02 18:22:52,235 - INFO # [CNT:       21][SYS: 01/01/70 00:21:00][RTC: 01/01/00 00:21:00]
2018-12-02 18:23:52,277 - INFO # [CNT:       22][SYS: 01/01/70 00:22:00][RTC: 01/01/00 00:22:01]
2018-12-02 18:24:52,316 - INFO # [CNT:       23][SYS: 01/01/70 00:23:01][RTC: 01/01/00 00:23:01]
2018-12-02 18:25:52,353 - INFO # [CNT:       24][SYS: 01/01/70 00:24:01][RTC: 01/01/00 00:24:01]
...
2018-12-02 18:47:52,946 - INFO # [CNT:       46][SYS: 01/01/70 00:46:01][RTC: 01/01/00 00:46:01]
2018-12-02 18:48:52,967 - INFO # [CNT:       47][SYS: 01/01/70 00:47:01][RTC: 01/01/00 00:47:01]
2018-12-02 18:49:52,987 - INFO # [CNT:       48][SYS: 01/01/70 00:48:02][RTC: 01/01/00 00:48:01]
2018-12-02 18:50:53,008 - INFO # [CNT:       49][SYS: 01/01/70 00:49:02][RTC: 01/01/00 00:49:01]
2018-12-02 18:51:53,032 - INFO # [CNT:       50][SYS: 01/01/70 00:50:02][RTC: 01/01/00 00:50:01]
2018-12-02 18:52:53,066 - INFO # [CNT:       51][SYS: 01/01/70 00:51:02][RTC: 01/01/00 00:51:01]
2018-12-02 18:53:53,099 - INFO # [CNT:       52][SYS: 01/01/70 00:52:02][RTC: 01/01/00 00:52:01]
2018-12-02 18:54:53,133 - INFO # [CNT:       53][SYS: 01/01/70 00:53:02][RTC: 01/01/00 00:53:01]
2018-12-02 18:55:53,167 - INFO # [CNT:       54][SYS: 01/01/70 00:54:02][RTC: 01/01/00 00:54:02]
2018-12-02 18:56:53,201 - INFO # [CNT:       55][SYS: 01/01/70 00:55:02][RTC: 01/01/00 00:55:02]
2018-12-02 18:57:53,241 - INFO # [CNT:       56][SYS: 01/01/70 00:56:02][RTC: 01/01/00 00:56:02]
2018-12-02 18:58:53,283 - INFO # [CNT:       57][SYS: 01/01/70 00:57:02][RTC: 01/01/00 00:57:02]
2018-12-02 18:59:53,326 - INFO # [CNT:       58][SYS: 01/01/70 00:58:02][RTC: 01/01/00 00:58:02]
2018-12-02 19:00:53,368 - INFO # [CNT:       59][SYS: 01/01/70 00:59:02][RTC: 01/01/00 00:59:02]
2018-12-02 19:01:53,412 - INFO # [CNT:       60][SYS: 01/01/70 01:00:02][RTC: 01/01/00 01:00:02]

[fedepell]

I was trying to work a bit more on this issue, mainly first of all trying to make the bench_timers work on my saml21-xpro and have some more information hoping it may be of some help.

First of all as mentioned before (just to make sure I'm not doing something stupid) I put in the Makefile saml21-xpro in SINGLE_TIMER_BOARDS so it uses the only timer.

Then what I noticed trying to debug is this:

Mainly the test will set a first timer (an absolute one) and then get stuck there on the "mutex_lock(&mtx_cb)". It seems as the ISR callback is actually never called (so mutex never unlocked).

First interesting thing I noticed is that while timer_init() is called, it usually does mostly nothing as it will return immediately on the:

        if (TIMER_0_DEV.CTRLA.bit.ENABLE) {
            return 0;
        }

So it sees the timer already enabled (on boot outside of timer.c? From pre-boot?) and it will immediately return, without setting further registers and the callback. Commenting out this "return 0" will make things already much better, in the sense that now timer gets alive.

Still the test would usually sooner or later stop at some point (always same mutex / ISR never called). Here adding debug prints made the issue mostly disappear so it looked like a timing issue. Interesting enough if the timer is always stopped for the test (so I do a variant |= TEST_STOPPED when generating the variant) then it will always work, so it looks like it happens just for tests that don't go through a stopped phase.
After further investigation I found that the problem happens when the interval is very small (I saw from the trace that was set to values such as 1 and 2, from 3 up seems fine), so after I made TEST_MIN_REL bigger (16 as TEST_MIN, but was working mostly fine also from 3) I could have it working also without the stopped phase.
So if the interval is very small it will work just from stopped state, otherwise also from non stopped.

Suggestion: shouldn't the TEST_MIN_REL definition follow the one of TEST_MIN ? (where a differentiation between 1 and 16 is done depending on timer frequency?)

I put the output results of the test after the modifications I mentioned here.

Not sure how this findings may help in understanding the original problem, but probably having at least the timer benchmark working may be something to begin with.

Maybe @kaspar030 or @thomaseichinger can have some comments and ideas?

[fedepell]

Test output of a run on saml21-xpro:

main(): This is RIOT! (Version: 2018.10-RC1-432-g7815a)

Statistical benchmark for timers
Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
TEST_MIN = 16
TEST_MAX = 128
TEST_MIN_REL = 3
TEST_MAX_REL = 115
TEST_NUM = 113
log2(TEST_NUM - 1) = 6
state vector elements per variant = 7
number of variants = 8
sizeof(state) = 32 bytes
state vector total memory usage = 1792 bytes
TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
TIM_REF_DEV  = 0, TIM_REF_FREQ  = 1000000
USE_REFERENCE = 1
TEST_PRINT_INTERVAL_TICKS = 30000000
Expected error variance due to truncation in tick conversion: 0
Calibrating spin delay...
spin_max = 47
Estimating benchmark overhead...
overhead_target = 14 (s2 = 0)
overhead_read = 14 (s2 = 0)
exp_mask = 00000007
max interval = 255
Elapsed time:
        Reference: 4294
 Timer under test: 4294
 Wall clock (RTT): 0
------------- BEGIN STATISTICS --------------
===== Reference timer statistics =====
Limits: mean: [-10, 10], variance: [0, 16]
Target error (actual trigger time - expected trigger time), in reference timer ticks
positive: timer under test is late, negative: timer under test is early
=== timer_set running ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:     5865      1804         2843     -1     1     0      0
   5 -    6:     5886      2204         2930     -1     1     0      0
   7 -   10:     5908     21163        15411      0     6     3      2
  11 -   18:     5874     24953        48218      0     9     4      8
  19 -   34:     5848     10552        11356     -1     4     1      1
  35 -   66:     5898     14345         2549      2     3     2      0
  67 -  130:     4496     10955         1963      2     3     2      0
      TOTAL     39775     85976       137771     -1     9     2      3
=== timer_set resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:     5683      1333         2358     -1     1     0      0
   5 -    6:     5741      2174         2892     -1     1     0      0
   7 -   10:     5907     20758        15181      0     6     3      2
  11 -   18:     5920     25056        49367      0     9     4      8
  19 -   34:     5836     10577        11268     -1     4     1      1
  35 -   66:     5870     14321         2581      2     3     2      0
  67 -  130:     4431     10825         1963      2     3     2      0
      TOTAL     39388     85044       138889     -1     9     2      3
=== timer_set stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:     5926    -14808         2953     -3    -2    -2      0
   5 -    6:     5934    -26721         2985     -5    -4    -4      0
   7 -   10:     5740    -15770        64519     -6     1    -2     11
  11 -   18:     5750    -24355        22951     -7    -1    -4      3
  19 -   34:     5901    -25037         3581     -6    -3    -4      0
  35 -   66:     5696    -22784            0     -4    -4    -4      0
  67 -  130:     4502    -18008            0     -4    -4    -4      0
      TOTAL     39449   -147483       183316     -7     1    -3      4
=== timer_set stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:     5837    -14596         2922     -3    -2    -2      0
   5 -    6:     5876    -26452         2948     -5    -4    -4      0
   7 -   10:     5818    -15881        65296     -6     1    -2     11
  11 -   18:     5832    -24711        23199     -7    -1    -4      3
  19 -   34:     5791    -24570         3454     -6    -3    -4      0
  35 -   66:     5812    -23248            0     -4    -4    -4      0
  67 -  130:     4501    -18004            0     -4    -4    -4      0
      TOTAL     39467   -147462       184327     -7     1    -3      4
=== timer_set_absolute running ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5814      8375         2905      0     2     1      0
  18 -   19:     5811     -3314         3687     -2     0     0      0
  20 -   23:     5890    -18377         3765     -5     0    -3      0
  24 -   31:     5876    -10131         9453     -4     0    -1      1
  32 -   47:     5768     -7569         1801     -2    -1    -1      0
  48 -   79:     5764     -7568         1804     -2    -1    -1      0
  80 -  143:     4401     -5733         1331     -2    -1    -1      0
      TOTAL     39324    -44317        74936     -5     2    -1      1
=== timer_set_absolute resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5976      8564         2974      0     2     1      0
  18 -   19:     5913     -3335         3708     -2     0     0      0
  20 -   23:     5832    -18142         3995     -5     0    -3      0
  24 -   31:     5857    -10219         9785     -4     0    -1      1
  32 -   47:     5910     -7891         1981     -2    -1    -1      0
  48 -   79:     5923     -7761         1838     -2    -1    -1      0
  80 -  143:     4461     -5862         1401     -2    -1    -1      0
      TOTAL     39872    -44646        75759     -5     2    -1      1
=== timer_set_absolute stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5685    -36941         2828     -7    -6    -6      0
  18 -   19:     5810    -34523         6050     -6    -3    -5      1
  20 -   23:     5876    -26174         8158     -6    -3    -4      1
  24 -   31:     5877    -23508            0     -4    -4    -4      0
  32 -   47:     5861    -23444            0     -4    -4    -4      0
  48 -   79:     5687    -22748            0     -4    -4    -4      0
  80 -  143:     4516    -18064            0     -4    -4    -4      0
      TOTAL     39312   -185402       151086     -7    -3    -4      3
=== timer_set_absolute stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5858    -38179         3030     -7    -6    -6      0
  18 -   19:     5851    -34798         6074     -6    -3    -5      1
  20 -   23:     5882    -26045         7801     -6    -3    -4      1
  24 -   31:     5944    -23776            0     -4    -4    -4      0
  32 -   47:     5907    -23628            0     -4    -4    -4      0
  48 -   79:     5929    -23716            0     -4    -4    -4      0
  80 -  143:     4500    -18000            0     -4    -4    -4      0
      TOTAL     39871   -188142       153755     -7    -3    -4      3
===== introspective statistics =====
Limits: mean: [-10, 10], variance: [0, 16]
self-referencing error (TUT time elapsed - expected TUT interval), in timer under test ticks
positive: timer target handling is slow, negative: TUT is dropping ticks or triggering callback early
function              count       sum       sum_sq    min   max  mean  variance

         timer_set   158079   -775254      1417366     -9     4    -4      8
           running    39775   -130271       170426     -6     4    -3      4
           resched    39388   -129286       170858     -6     4    -3      4
           stopped    39449   -257916       151570     -9    -1    -6      3
  stopped, resched    39467   -257781       152675     -9    -1    -6      3

timer_set_absolute   158379  -1117732            0     -9    -3    -7      0
           running    39324   -257670       104194     -9    -3    -6      2
           resched    39872   -260678       104467     -9    -3    -6      2
           stopped    39312   -297564        45298     -9    -5    -7      1
  stopped, resched    39871   -301820        45905     -9    -5    -7      1
-------------- END STATISTICS ---------------

[fedepell]

One more output from a longer run, but I think statistically is quite similar:

main(): This is RIOT! (Version: 2018.10-RC1-432-g7815a)

Statistical benchmark for timers
Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
TEST_MIN = 16
TEST_MAX = 128
TEST_MIN_REL = 3
TEST_MAX_REL = 115
TEST_NUM = 113
log2(TEST_NUM - 1) = 6
state vector elements per variant = 7
number of variants = 8
sizeof(state) = 32 bytes
state vector total memory usage = 1792 bytes
TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
TIM_REF_DEV  = 0, TIM_REF_FREQ  = 1000000
USE_REFERENCE = 1
TEST_PRINT_INTERVAL_TICKS = 300000000
Expected error variance due to truncation in tick conversion: 0
Calibrating spin delay...
spin_max = 47
Estimating benchmark overhead...
overhead_target = 14 (s2 = 0)
overhead_read = 14 (s2 = 0)
exp_mask = 00000007
max interval = 255
Elapsed time:
        Reference: 4294
 Timer under test: 4294
 Wall clock (RTT): 0
------------- BEGIN STATISTICS --------------
===== Reference timer statistics =====
Limits: mean: [-10, 10], variance: [0, 16]
Target error (actual trigger time - expected trigger time), in reference timer ticks
positive: timer under test is late, negative: timer under test is early
=== timer_set running ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:    58673     18203        29194     -1     1     0      0
   5 -    6:    58506     21954        29192     -1     1     0      0
   7 -   10:    58848    209505       149981      0     6     3      2
  11 -   18:    58784    247000       478171      0     9     4      8
  19 -   34:    58499    104698       112805     -1     4     1      1
  35 -   66:    58682    142961        25597      2     3     2      0
  67 -  130:    44550    108583        19483      2     3     2      0
      TOTAL    396542    852904      1362916     -1     9     2      3
=== timer_set resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:    58145     12770        23657     -1     1     0      0
   5 -    6:    58560     22182        29322     -1     1     0      0
   7 -   10:    58613    208329       150476      0     6     3      2
  11 -   18:    58598    245497       476658      0     9     4      8
  19 -   34:    58415    105000       111752     -1     4     1      1
  35 -   66:    58348    142229        25533      2     3     2      0
  67 -  130:    44656    108992        19680      2     3     2      0
      TOTAL    395335    844999      1361497     -1     9     2      3
=== timer_set stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:    58617   -146555        29318     -3    -2    -2      0
   5 -    6:    58619   -263806        29330     -5    -4    -4      0
   7 -   10:    58474   -159531       656546     -6     1    -2     11
  11 -   18:    58428   -248955       233303     -7    -1    -4      3
  19 -   34:    58468   -247413        34607     -6    -3    -4      0
  35 -   66:    58212   -232848            0     -4    -4    -4      0
  67 -  130:    44570   -178280            0     -4    -4    -4      0
      TOTAL    395388  -1477388      1848320     -7     1    -3      4
=== timer_set stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
   3 -    4:    58702   -146741        29337     -3    -2    -2      0
   5 -    6:    58397   -263001        29413     -5    -4    -4      0
   7 -   10:    58109   -159126       651831     -6     1    -2     11
  11 -   18:    58615   -248620       233582     -7    -1    -4      3
  19 -   34:    58633   -247940        34408     -6    -3    -4      0
  35 -   66:    58381   -233524            0     -4    -4    -4      0
  67 -  130:    44680   -178720            0     -4    -4    -4      0
      TOTAL    395517  -1477672      1844509     -7     1    -3      4
=== timer_set_absolute running ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:    58506     83981        29153      0     2     1      0
  18 -   19:    58309    -32997        36594     -2     0     0      0
  20 -   23:    58493   -182178        38317     -5     0    -3      0
  24 -   31:    58683   -101530        95921     -4     0    -1      1
  32 -   47:    58292    -76329        18037     -2    -1    -1      0
  48 -   79:    58529    -76462        17933     -2    -1    -1      0
  80 -  143:    44940    -58976        14036     -2    -1    -1      0
      TOTAL    395752   -444491       749312     -5     2    -1      1
=== timer_set_absolute resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:    58475     84175        29196      0     2     1      0
  18 -   19:    58500    -33096        36839     -2     0     0      0
  20 -   23:    58380   -181705        38300     -5     0    -3      0
  24 -   31:    58712   -102181        97760     -4     0    -1      1
  32 -   47:    58540    -77054        18514     -2    -1    -1      0
  48 -   79:    58832    -77206        18374     -2    -1    -1      0
  80 -  143:    44542    -58399        13857     -2    -1    -1      0
      TOTAL    395981   -445466       751504     -5     2    -1      1
=== timer_set_absolute stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:    58476   -379926        29067     -7    -6    -6      0
  18 -   19:    58440   -347372        61299     -6    -3    -5      1
  20 -   23:    58621   -260121        80323     -6    -3    -4      1
  24 -   31:    58740   -234960            0     -4    -4    -4      0
  32 -   47:    58617   -234468            0     -4    -4    -4      0
  48 -   79:    58061   -232244            0     -4    -4    -4      0
  80 -  143:    44885   -179540            0     -4    -4    -4      0
      TOTAL    395840  -1868631      1534919     -7    -3    -4      3
=== timer_set_absolute stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:    58617   -381298        29595     -7    -6    -6      0
  18 -   19:    57992   -344888        60723     -6    -3    -5      1
  20 -   23:    58089   -258114        79838     -6    -3    -4      1
  24 -   31:    58196   -232784            0     -4    -4    -4      0
  32 -   47:    57919   -231676            0     -4    -4    -4      0
  48 -   79:    58100   -232400            0     -4    -4    -4      0
  80 -  143:    44786   -179144            0     -4    -4    -4      0
      TOTAL    393699  -1860304      1532210     -7    -3    -4      3
===== introspective statistics =====
Limits: mean: [-10, 10], variance: [0, 16]
self-referencing error (TUT time elapsed - expected TUT interval), in timer under test ticks
positive: timer target handling is slow, negative: TUT is dropping ticks or triggering callback early
function              count       sum       sum_sq    min   max  mean  variance

         timer_set  1582782  -7774043     14177737     -9     4    -4      8
           running   396542  -1302847      1692711     -6     4    -3      4
           resched   395335  -1304852      1700439     -6     4    -3      4
           stopped   395388  -2582854      1533888     -9    -1    -6      3
  stopped, resched   395517  -2583490      1525710     -9    -1    -6      3

timer_set_absolute  1581272 -11163573            0     -9    -3    -7      0
           running   395752  -2591816      1038566     -9    -3    -6      2
           resched   395981  -2593006      1040429     -9    -3    -6      2
           stopped   395840  -2996778       457034     -9    -5    -7      1
  stopped, resched   393699  -2981973       456692     -9    -5    -7      1
-------------- END STATISTICS ---------------

[jcarrano]

@fedepell The time() function is wrongly implemented in that it returns time since boot, using xtimer (instead of the RTC).

I have a PR open since a while ago (#9258 ). I think this commit in particular might solve your issue.

I might have screwed up by changing the implementation and splitting the modules in the same PR. If the time()/RTC thing is an issue, I might split the change.

[fedepell]

@jcarrano: thanks for the pointer, I'll try to check out the PR/commit!
For my specific application there is not a problem, I can explicitly use the RTC to timestamp data (I mean call rtc_get_time to add to my readings) which would connect to your PR (but without the need to call rtc_get_time explicitly).

Mostly I was finding it strange that the system time is so "quite wrong" (15 sec in 1 hour), so I was more concerned about the fact that if I (conceptually) do a xtimer_sleep of 1 hour I will be woken up with 15 full seconds of error (which is not little on 1hour, I believe).

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. If you want me to ignore this issue, please mark it with the "State: don't stale" label. Thank you for your contributions.