Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

sam0_common: make Timer implementation common across all sam0 MCUs #11336

Merged
merged 1 commit into from
May 21, 2019
Merged

sam0_common: make Timer implementation common across all sam0 MCUs #11336

merged 1 commit into from
May 21, 2019

Conversation

benpicco
Copy link
Contributor

@benpicco benpicco commented Apr 3, 2019

Contribution description

The currently supported SAM0 MCUs (samd21, saml21, saml1x) share the same Timer peripheral, yet each of them carries it's own copy of the Timer driver.

This introduces a new timer driver that is common for all sam0 MCUs and uses structs for configuration instead of defines.

Testing procedure

Only tested it on samr21-xpro and same54-xpro with the timer_periodic_wakeup example.

Issues/PRs references

#11305 will also use this implementation.

@benpicco benpicco mentioned this pull request Apr 3, 2019
Merged
@fedepell
Copy link
Contributor

fedepell commented Apr 5, 2019

Could be a good idea to test (and compare) using also tests/bench_timers/?

@fedepell
Copy link
Contributor

fedepell commented Apr 5, 2019

Trying around with a saml21-xpro. I have run the bench_timers on it (but see caveats and modifications needed in #10523) but the results would now look much worse.

Your branch:

main(): This is RIOT! (Version: 2014.01-19969-gc09ac-sam0-timer)

Statistical benchmark for timers
Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
TEST_MIN = 16
TEST_MAX = 128
TEST_MIN_REL = 16
TEST_MAX_REL = 128
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 = 38
Estimating benchmark overhead...
overhead_target = 17 (s2 = 0)
overhead_read = 17 (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
  16 -   17:     7640    117020      9618076    -23   172    15   1259  <=== SIC!
  18 -   19:     9294    169541     13327689    -26   173    18   1434  <=== SIC!
  20 -   23:     7725    150739     11945302    -30   173    19   1546  <=== SIC!
  24 -   31:     5893    131052      9494471    -38   173    22   1611  <=== SIC!
  32 -   47:     5181    118930      8836464    -53   172    22   1705  <=== SIC!
 48 -   79:     5199    109076      9864702    -84   172    20   1897  <=== SIC!
  80 -  143:     3920     70748      9438004   -134   172    18   2408  <=== SIC!
      TOTAL     44852    867106     72675361   -134   173    19   1620  <=== SIC!
=== timer_set resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     7317     93125      6416671     -8   173    12    877  <=== SIC!
  18 -   19:     8955    140520      9724856     -8   173    15   1086  <=== SIC!
  20 -   23:     7611    136902      9433226     -8   172    17   1239  <=== SIC!
  24 -   31:     5921    141600      8969243     -8   172    23   1515  <=== SIC!
  32 -   47:     5178    136590      8256035     -8   172    26   1594  <=== SIC!
  48 -   79:     5125    138417      8328534     -8   172    27   1625  <=== SIC!
  80 -  143:     3941    104281      6283480     -8   168    26   1594  <=== SIC!
      TOTAL     44048    891435     58392684     -8   173    20   1325  <=== SIC!
=== timer_set stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     7723    257578     17008525   -655   173    33   2202  <=== SIC!
  18 -   19:     8385    275675     18131117   -723   173    32   2162  <=== SIC!
  20 -   23:     7780    258451     19822729   -774   172    33   2548  <=== SIC!
  24 -   31:     6563    221751     14986635   -738   173    33   2283  <=== SIC!
  32 -   47:     6340    212822     15132468   -853   172    33   2387  <=== SIC!
  48 -   79:     6059    198475     14483779   -618   172    32   2390  <=== SIC!
  80 -  143:     4820    162880     11983974   -684   173    33   2486  <=== SIC!
      TOTAL     47670   1587632    111075077   -853   173    33   2330  <=== SIC!
=== timer_set stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     7655    259150     14614497     -9   171    33   1909  <=== SIC!
  18 -   19:     8394    280036     15987039     -8   173    33   1904  <=== SIC!
  20 -   23:     7592    256520     14540016     -8   172    33   1915  <=== SIC!
  24 -   31:     6579    222718     12778538     -8   173    33   1942  <=== SIC!
  32 -   47:     6182    208535     11968570     -8   170    33   1936  <=== SIC!
  48 -   79:     6104    205845     11846857     -8   172    33   1941  <=== SIC!
  80 -  143:     4577    153763      8927350     -8   173    33   1950  <=== SIC!
      TOTAL     47083   1586567     90662867     -9   173    33   1925  <=== SIC!
=== timer_set_absolute running ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     7578     71949      7775703    -24   171     9   1026  <=== SIC!
  18 -   19:     9060    118339     11240986    -26   172    13   1240  <=== SIC!
  20 -   23:     7640    120161     10757849    -29   172    15   1408  <=== SIC!
  24 -   31:     6033    125550      9554495    -37   172    20   1583  <=== SIC!
  32 -   47:     5181    121145      8898142    -53   173    23   1717  <=== SIC!
  48 -   79:     5248    115293      9492486    -85   172    21   1809  <=== SIC!
  48 -   79:     5142    126660      8298004     -8   172    24   1614  <=== SIC!
  80 -  143:     3896     93643      6286033     -8   173    24   1613  <=== SIC!
      TOTAL     44277    749691     59829505     -8   173    16   1351  <=== SIC!
=== timer_set_absolute stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     7256    240813     15564770   -460   171    33   2145  <=== SIC!
  18 -   19:     8073    266160     18323537  -1087   173    32   2270  <=== SIC!
  20 -   23:     7692    257327     17386510   -567   173    33   2260  <=== SIC!
  24 -   31:     6519    218811     15174321   -706   173    33   2328  <=== SIC!
  32 -   47:     6117    200383     16114272   -907   172    32   2634  <=== SIC!
  48 -   79:     6225    203364     14983838   -600   173    32   2407  <=== SIC!
  80 -  143:     4810    155901     15690576  -1369   172    32   3262  <=== SIC!
      TOTAL     46692   1542759    112412016  -1369   173    33   2407  <=== SIC!
=== timer_set_absolute stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     7483    253379     14313355     -9   172    33   1913  <=== SIC!
  18 -   19:     8437    280663     16002595     -8   173    33   1896  <=== SIC!
  20 -   23:     7657    259425     14656042     -8   171    33   1914  <=== SIC!
  24 -   31:     6518    220896     12708849     -8   172    33   1950  <=== SIC!
  32 -   47:     6269    211428     12156729     -8   172    33   1939  <=== SIC!
  48 -   79:     6223    212178     12207922     -8   173    34   1962  <=== SIC!
  80 -  143:     4791    162158      9342867     -8   172    33   1950  <=== SIC!
      TOTAL     47378   1600127     91600537     -9   173    33   1933  <=== SIC!
===== 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   183814   3907751    343686693   -857   165    21   1869  <=== SIC!
           running    44570    606980     68460831   -138   165    13   1536  <=== SIC!
           resched    43779    634807     61888569    -12   165    14   1413  <=== SIC!
           stopped    48045   1331913    113045996   -857   165    27   2352  <=== SIC!
  stopped, resched    47420   1334051     92260951    -12   165    28   1945  <=== SIC!

timer_set_absolute   182901   3671555    346193581  -1373   165    20   1892  <=== SIC!
           running    44305    519543     65568161   -137   165    11   1479  <=== SIC!
           resched    43918    510666     62707904    -12   165    11   1427  <=== SIC!
           stopped    47082   1298364    114674562  -1373   165    27   2435  <=== SIC!
  stopped, resched    47596   1342982     92682431    -12   165    28   1947  <=== SIC!
-------------- END STATISTICS ---------------

Master:

main(): This is RIOT! (Version: 2019.04-devel-837-gf6f98)

Statistical benchmark for timers
Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
TEST_MIN = 16
TEST_MAX = 128
TEST_MIN_REL = 16
TEST_MAX_REL = 128
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
  16 -   17:     5613     23181         2834      3     5     4      0
  18 -   19:     5607     11960         2835      1     3     2      0
  20 -   23:     5643      2125         4432     -1     4     0      0
  24 -   31:     5570     12676         4587      0     4     2      0
  32 -   47:     5590     13628         2448      2     3     2      0
  48 -   79:     5642     13795         2511      2     3     2      0
  80 -  143:     4304     10477         1869      2     3     2      0
      TOTAL     37969     87842        63628     -1     5     2      1
=== timer_set resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5435     22417         2755      3     5     4      0
  18 -   19:     5483     11675         2744      1     3     2      0
  20 -   23:     5646      2091         4340     -1     4     0      0
  24 -   31:     5660     12683         4504      0     4     2      0
  32 -   47:     5586     13666         2492      2     3     2      0
  48 -   79:     5606     13679         2467      2     3     2      0
  80 -  143:     4233     10305         1837      2     3     2      0
      TOTAL     37649     86516        61791     -1     5     2      1
=== timer_set stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5651    -36287         4121     -7    -3    -6      0
  18 -   19:     5657    -32423         6165     -6    -3    -5      1
  20 -   23:     5454    -20878         4817     -5    -3    -3      0
  24 -   31:     5481    -21924            0     -4    -4    -4      0
  32 -   47:     5652    -22608            0     -4    -4    -4      0
  48 -   79:     5434    -21736            0     -4    -4    -4      0
  80 -  143:     4289    -17156            0     -4    -4    -4      0
      TOTAL     37618   -173012       121359     -7    -3    -4      3
=== timer_set stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5572    -35815         4014     -7    -3    -6      0
  18 -   19:     5598    -32124         6171     -6    -3    -5      1
  20 -   23:     5564    -21279         4879     -5    -3    -3      0
  24 -   31:     5543    -22172            0     -4    -4    -4      0
  32 -   47:     5525    -22100            0     -4    -4    -4      0
  48 -   79:     5561    -22244            0     -4    -4    -4      0
  80 -  143:     4278    -17112            0     -4    -4    -4      0
      TOTAL     37641   -172846       119478     -7    -3    -4      3
=== timer_set_absolute running ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5528      1060         2777     -1     1     0      0
  18 -   19:     5555    -10073         6264     -3    -1    -1      1
  20 -   23:     5618    -19044         4946     -5     0    -3      0
  24 -   31:     5600     -8113         4793     -4     0    -1      0
  32 -   47:     5492     -7206         1714     -2    -1    -1      0
  48 -   79:     5500     -7208         1706     -2    -1    -1      0
  80 -  143:     4191     -5534         1342     -2    -1    -1      0
      TOTAL     37484    -56118        62690     -5     1    -1      1
=== timer_set_absolute resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5707      1028         2815     -1     1     0      0
  18 -   19:     5629    -10164         6243     -3    -1    -1      1
  20 -   23:     5582    -18944         4910     -5     0    -3      0
  24 -   31:     5588     -8081         4703     -4     0    -1      0
  32 -   47:     5619     -7386         1766     -2    -1    -1      0
  48 -   79:     5655     -7471         1816     -2    -1    -1      0
  80 -  143:     4272     -5567         1295     -2    -1    -1      0
      TOTAL     38052    -56585        62464     -5     1    -1      1
=== timer_set_absolute stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5423    -34880         3818     -7    -3    -6      0
  18 -   19:     5549    -31920         6074     -6    -3    -5      1
  20 -   23:     5581    -21318         4869     -5    -3    -3      0
  24 -   31:     5616    -22464            0     -4    -4    -4      0
  32 -   47:     5570    -22280            0     -4    -4    -4      0
  48 -   79:     5453    -21812            0     -4    -4    -4      0
  80 -  143:     4296    -17184            0     -4    -4    -4      0
      TOTAL     37488   -171858       117151     -7    -3    -4      3
=== timer_set_absolute stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5586    -35762         4058     -7    -3    -6      0
  18 -   19:     5595    -32156         6066     -6    -3    -5      1
  20 -   23:     5604    -21493         4963     -5    -3    -3      0
  24 -   31:     5654    -22616            0     -4    -4    -4      0
  32 -   47:     5639    -22556            0     -4    -4    -4      0
  48 -   79:     5644    -22576            0     -4    -4    -4      0
  80 -  143:     4303    -17212            0     -4    -4    -4      0
      TOTAL     38025   -174371       119306     -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   150877   -801894       864981     -9     0    -5      5
           running    37969   -118955        61940     -6     0    -3      1
           resched    37649   -118664        61317     -6     0    -3      1
           stopped    37618   -282151        44334     -9    -5    -7      1
  stopped, resched    37641   -282124        44078     -9    -5    -7      1

timer_set_absolute   151049  -1089532        43985     -9    -4    -7      0
           running    37484   -260133        84950     -9    -4    -6      2
           resched    38052   -263696        84653     -9    -4    -6      2
           stopped    37488   -280809        43357     -9    -5    -7      1
  stopped, resched    38025   -284894        43985     -9    -5    -7      1
-------------- END STATISTICS ---------------

@benpicco
Copy link
Contributor Author

benpicco commented Apr 5, 2019

Thank you for testing!
I don't have a saml21 here for testing, so I tried it on the samr21-xpro only to notice that it crashes when trying to configure TIMER_DEV(1) for reference - which makes me think I probably should implement 8/16 bit mode too as otherwise we only have one timer on this MCU.

After adding it to SINGLE_TIMER_BOARDS the test gets stuck though (both on master and my branch):

2019-04-05 17:29:50,454 - INFO # Statistical benchmark for timers
2019-04-05 17:29:50,460 - INFO # Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
2019-04-05 17:29:50,462 - INFO # TEST_MIN = 16
2019-04-05 17:29:50,463 - INFO # TEST_MAX = 128
2019-04-05 17:29:50,464 - INFO # TEST_MIN_REL = 0
2019-04-05 17:29:50,472 - INFO # TEST_MAX_REL = 112
2019-04-05 17:29:50,473 - INFO # TEST_NUM = 113
2019-04-05 17:29:50,475 - INFO # log2(TEST_NUM - 1) = 6
2019-04-05 17:29:50,476 - INFO # state vector elements per variant = 7
2019-04-05 17:29:50,478 - INFO # number of variants = 8
2019-04-05 17:29:50,479 - INFO # sizeof(state) = 32 bytes
2019-04-05 17:29:50,481 - INFO # state vector total memory usage = 1792 bytes
2019-04-05 17:29:50,486 - INFO # TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
2019-04-05 17:29:50,489 - INFO # TIM_REF_DEV  = 0, TIM_REF_FREQ  = 1000000
2019-04-05 17:29:50,491 - INFO # USE_REFERENCE = 1
2019-04-05 17:29:50,494 - INFO # TEST_PRINT_INTERVAL_TICKS = 30000000
2019-04-05 17:29:50,509 - INFO # Expected error variance due to truncation in tick conversion: 0
2019-04-05 17:29:50,510 - INFO # Calibrating spin delay...
2019-04-05 17:29:50,511 - INFO # spin_max = 90
2019-04-05 17:29:50,511 - INFO # Estimating benchmark overhead...
2019-04-05 17:29:50,657 - INFO # overhead_target = 17 (s2 = 0)
2019-04-05 17:29:50,659 - INFO # overhead_read = 17 (s2 = 0)
2019-04-05 17:29:50,661 - INFO # exp_mask = 00000007
2019-04-05 17:29:50,663 - INFO # max interval = 255

The discrepancy is surprising as the initialization is still the same between the new config and the old one.

I'll try to reproduce this issue so I can fix it.

@fedepell
Copy link
Contributor

fedepell commented Apr 5, 2019

Try checking out pr #11346, that should fix the test also for that board.

@benpicco
Copy link
Contributor Author

benpicco commented Apr 5, 2019

Alright!
this gives

master:

2019-04-05 17:45:10,776 - INFO # Statistical benchmark for timers
2019-04-05 17:45:10,777 - INFO # Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
2019-04-05 17:45:10,778 - INFO # TEST_MIN = 16
2019-04-05 17:45:10,785 - INFO # TEST_MAX = 128
2019-04-05 17:45:10,786 - INFO # TEST_MIN_REL = 16
2019-04-05 17:45:10,787 - INFO # TEST_MAX_REL = 128
2019-04-05 17:45:10,789 - INFO # TEST_NUM = 113
2019-04-05 17:45:10,790 - INFO # log2(TEST_NUM - 1) = 6
2019-04-05 17:45:10,792 - INFO # state vector elements per variant = 7
2019-04-05 17:45:10,793 - INFO # number of variants = 8
2019-04-05 17:45:10,794 - INFO # sizeof(state) = 32 bytes
2019-04-05 17:45:10,802 - INFO # state vector total memory usage = 1792 bytes
2019-04-05 17:45:10,806 - INFO # TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
2019-04-05 17:45:10,809 - INFO # TIM_REF_DEV  = 0, TIM_REF_FREQ  = 1000000
2019-04-05 17:45:10,811 - INFO # USE_REFERENCE = 1
2019-04-05 17:45:10,815 - INFO # TEST_PRINT_INTERVAL_TICKS = 30000000
2019-04-05 17:45:10,818 - INFO # Expected error variance due to truncation in tick conversion: 0
2019-04-05 17:45:10,820 - INFO # Calibrating spin delay...
2019-04-05 17:45:10,821 - INFO # spin_max = 90
2019-04-05 17:45:10,830 - INFO # Estimating benchmark overhead...
2019-04-05 17:45:10,971 - INFO # overhead_target = 16 (s2 = 0)
2019-04-05 17:45:10,975 - INFO # overhead_read = 16 (s2 = 0)
2019-04-05 17:45:10,975 - INFO # exp_mask = 00000007
2019-04-05 17:45:10,976 - INFO # max interval = 255
2019-04-05 17:46:15,011 - INFO # Elapsed time:
2019-04-05 17:46:15,014 - INFO #         Reference: 4294
2019-04-05 17:46:15,015 - INFO #  Timer under test: 4294
2019-04-05 17:46:15,023 - INFO #  Wall clock (RTT): 64
2019-04-05 17:46:15,030 - INFO # ------------- BEGIN STATISTICS --------------
2019-04-05 17:46:15,035 - INFO # ===== Reference timer statistics =====
2019-04-05 17:46:15,040 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2019-04-05 17:46:15,059 - INFO # Target error (actual trigger time - expected trigger time), in reference timer ticks
2019-04-05 17:46:15,068 - INFO # positive: timer under test is late, negative: timer under test is early
2019-04-05 17:46:15,077 - INFO # === timer_set running ===
2019-04-05 17:46:15,088 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,109 - INFO #   16 -   17:     7397    107232         3671     14    15    14      0  <=== SIC!
2019-04-05 17:46:15,114 - INFO #   18 -   19:     7453    111795            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,125 - INFO #   20 -   23:     7458    111870            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,146 - INFO #   24 -   31:     7473    112095            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,156 - INFO #   32 -   47:     7352    110280            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,168 - INFO #   48 -   79:     7393    110895            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,175 - INFO #   80 -  143:     5689     85335            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,185 - INFO #       TOTAL     50215    749502       645941     14    15    14     12  <=== SIC!
2019-04-05 17:46:15,187 - INFO # === timer_set resched ===
2019-04-05 17:46:15,200 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,213 - INFO #   16 -   17:     7375    106955         3705     14    15    14      0  <=== SIC!
2019-04-05 17:46:15,221 - INFO #   18 -   19:     7390    110850            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,234 - INFO #   20 -   23:     7493    112395            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,245 - INFO #   24 -   31:     7503    112545            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,259 - INFO #   32 -   47:     7404    111060            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,286 - INFO #   48 -   79:     7392    110880            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,296 - INFO #   80 -  143:     5674     85110            0     15    15    15      0  <=== SIC!
2019-04-05 17:46:15,318 - INFO #       TOTAL     50231    749795       646545     14    15    14     12  <=== SIC!
2019-04-05 17:46:15,333 - INFO # === timer_set stopped ===
2019-04-05 17:46:15,362 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,387 - INFO #   16 -   17:     7372     14744            0      2     2     2      0
2019-04-05 17:46:15,402 - INFO #   18 -   19:     7436     14872            0      2     2     2      0
2019-04-05 17:46:15,418 - INFO #   20 -   23:     7517     15034            0      2     2     2      0
2019-04-05 17:46:15,445 - INFO #   24 -   31:     7548     15096            0      2     2     2      0
2019-04-05 17:46:15,472 - INFO #   32 -   47:     7602     15204            0      2     2     2      0
2019-04-05 17:46:15,488 - INFO #   48 -   79:     7410     14820            0      2     2     2      0
2019-04-05 17:46:15,501 - INFO #   80 -  143:     5590     11180            0      2     2     2      0
2019-04-05 17:46:15,520 - INFO #       TOTAL     50475    100950            0      2     2     2      0
2019-04-05 17:46:15,531 - INFO # === timer_set stopped, resched ===
2019-04-05 17:46:15,548 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,558 - INFO #   16 -   17:     7464     14928            0      2     2     2      0
2019-04-05 17:46:15,567 - INFO #   18 -   19:     7371     14742            0      2     2     2      0
2019-04-05 17:46:15,587 - INFO #   20 -   23:     7260     14520            0      2     2     2      0
2019-04-05 17:46:15,601 - INFO #   24 -   31:     7336     14672            0      2     2     2      0
2019-04-05 17:46:15,618 - INFO #   32 -   47:     7358     14716            0      2     2     2      0
2019-04-05 17:46:15,639 - INFO #   48 -   79:     7453     14906            0      2     2     2      0
2019-04-05 17:46:15,640 - INFO #   80 -  143:     5653     11306            0      2     2     2      0
2019-04-05 17:46:15,642 - INFO #       TOTAL     49895     99790            0      2     2     2      0
2019-04-05 17:46:15,643 - INFO # === timer_set_absolute running ===
2019-04-05 17:46:15,644 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,646 - INFO #   16 -   17:     7333     54946         3614      7     8     7      0
2019-04-05 17:46:15,647 - INFO #   18 -   19:     7493     59944            0      8     8     8      0
2019-04-05 17:46:15,649 - INFO #   20 -   23:     7471     59768            0      8     8     8      0
2019-04-05 17:46:15,650 - INFO #   24 -   31:     7498     59984            0      8     8     8      0
2019-04-05 17:46:15,651 - INFO #   32 -   47:     7336     58688            0      8     8     8      0
2019-04-05 17:46:15,653 - INFO #   48 -   79:     7291     58328            0      8     8     8      0
2019-04-05 17:46:15,655 - INFO #   80 -  143:     5822     46576            0      8     8     8      0
2019-04-05 17:46:15,657 - INFO #       TOTAL     50244    398234       346902      7     8     7      6
2019-04-05 17:46:15,658 - INFO # === timer_set_absolute resched ===
2019-04-05 17:46:15,659 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,660 - INFO #   16 -   17:     7399     55617         3824      7     8     7      0
2019-04-05 17:46:15,662 - INFO #   18 -   19:     7512     60096            0      8     8     8      0
2019-04-05 17:46:15,663 - INFO #   20 -   23:     7548     60384            0      8     8     8      0
2019-04-05 17:46:15,664 - INFO #   24 -   31:     7427     59416            0      8     8     8      0
2019-04-05 17:46:15,666 - INFO #   32 -   47:     7534     60272            0      8     8     8      0
2019-04-05 17:46:15,667 - INFO #   48 -   79:     7453     59624            0      8     8     8      0
2019-04-05 17:46:15,669 - INFO #   80 -  143:     5632     45056            0      8     8     8      0
2019-04-05 17:46:15,670 - INFO #       TOTAL     50505    400465       348672      7     8     7      6
2019-04-05 17:46:15,671 - INFO # === timer_set_absolute stopped ===
2019-04-05 17:46:15,672 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,674 - INFO #   16 -   17:     7421     14842            0      2     2     2      0
2019-04-05 17:46:15,675 - INFO #   18 -   19:     7502     15004            0      2     2     2      0
2019-04-05 17:46:15,676 - INFO #   20 -   23:     7519     15038            0      2     2     2      0
2019-04-05 17:46:15,678 - INFO #   24 -   31:     7423     14846            0      2     2     2      0
2019-04-05 17:46:15,679 - INFO #   32 -   47:     7380     14760            0      2     2     2      0
2019-04-05 17:46:15,681 - INFO #   48 -   79:     7436     14872            0      2     2     2      0
2019-04-05 17:46:15,682 - INFO #   80 -  143:     5693     11386            0      2     2     2      0
2019-04-05 17:46:15,684 - INFO #       TOTAL     50374    100748            0      2     2     2      0
2019-04-05 17:46:15,686 - INFO # === timer_set_absolute stopped, resched ===
2019-04-05 17:46:15,688 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,689 - INFO #   16 -   17:     7329     14658            0      2     2     2      0
2019-04-05 17:46:15,690 - INFO #   18 -   19:     7428     14856            0      2     2     2      0
2019-04-05 17:46:15,691 - INFO #   20 -   23:     7366     14732            0      2     2     2      0
2019-04-05 17:46:15,693 - INFO #   24 -   31:     7507     15014            0      2     2     2      0
2019-04-05 17:46:15,694 - INFO #   32 -   47:     7418     14836            0      2     2     2      0
2019-04-05 17:46:15,696 - INFO #   48 -   79:     7392     14784            0      2     2     2      0
2019-04-05 17:46:15,697 - INFO #   80 -  143:     5733     11466            0      2     2     2      0
2019-04-05 17:46:15,700 - INFO #       TOTAL     50173    100346            0      2     2     2      0
2019-04-05 17:46:15,700 - INFO # ===== introspective statistics =====
2019-04-05 17:46:15,701 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2019-04-05 17:46:15,703 - INFO # self-referencing error (TUT time elapsed - expected TUT interval), in timer under test ticks
2019-04-05 17:46:15,705 - INFO # positive: timer target handling is slow, negative: TUT is dropping ticks or triggering callback early
2019-04-05 17:46:15,707 - INFO # function              count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:46:15,707 - INFO # 
2019-04-05 17:46:15,708 - INFO #          timer_set   200816   -107535      2286825     -4     3     0     11
2019-04-05 17:46:15,710 - INFO #            running    50215    146922        46462      2     3     2      0
2019-04-05 17:46:15,711 - INFO #            resched    50231    147023        46553      2     3     2      0
2019-04-05 17:46:15,713 - INFO #            stopped    50475   -201900            0     -4    -4    -4      0
2019-04-05 17:46:15,714 - INFO #   stopped, resched    49895   -199580            0     -4    -4    -4      0
2019-04-05 17:46:15,715 - INFO # 
2019-04-05 17:46:15,716 - INFO # timer_set_absolute   201296   -812477         7293     -5    -4    -4      0
2019-04-05 17:46:15,717 - INFO #            running    50244   -204694         3718     -5    -4    -4      0
2019-04-05 17:46:15,720 - INFO #            resched    50505   -205595         3575     -5    -4    -4      0
2019-04-05 17:46:15,722 - INFO #            stopped    50374   -201496            0     -4    -4    -4      0
2019-04-05 17:46:15,724 - INFO #   stopped, resched    50173   -200692            0     -4    -4    -4      0
2019-04-05 17:46:15,725 - INFO # -------------- END STATISTICS ---------------

this branch

2019-04-05 17:46:59,509 - INFO # Statistical benchmark for timers
2019-04-05 17:46:59,525 - INFO # Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
2019-04-05 17:46:59,526 - INFO # TEST_MIN = 16
2019-04-05 17:46:59,531 - INFO # TEST_MAX = 128
2019-04-05 17:46:59,541 - INFO # TEST_MIN_REL = 16
2019-04-05 17:46:59,542 - INFO # TEST_MAX_REL = 128
2019-04-05 17:46:59,542 - INFO # TEST_NUM = 113
2019-04-05 17:46:59,543 - INFO # log2(TEST_NUM - 1) = 6
2019-04-05 17:46:59,545 - INFO # state vector elements per variant = 7
2019-04-05 17:46:59,546 - INFO # number of variants = 8
2019-04-05 17:46:59,547 - INFO # sizeof(state) = 32 bytes
2019-04-05 17:46:59,550 - INFO # state vector total memory usage = 1792 bytes
2019-04-05 17:46:59,552 - INFO # TIM_TEST_DEV = 0, TIM_TEST_FREQ = 1000000, TIM_TEST_CHAN = 0
2019-04-05 17:46:59,553 - INFO # TIM_REF_DEV  = 0, TIM_REF_FREQ  = 1000000
2019-04-05 17:46:59,553 - INFO # USE_REFERENCE = 1
2019-04-05 17:46:59,554 - INFO # TEST_PRINT_INTERVAL_TICKS = 30000000
2019-04-05 17:46:59,556 - INFO # Expected error variance due to truncation in tick conversion: 0
2019-04-05 17:46:59,557 - INFO # Calibrating spin delay...
2019-04-05 17:46:59,558 - INFO # spin_max = 90
2019-04-05 17:46:59,559 - INFO # Estimating benchmark overhead...
2019-04-05 17:46:59,698 - INFO # overhead_target = 17 (s2 = 0)
2019-04-05 17:46:59,700 - INFO # overhead_read = 17 (s2 = 0)
2019-04-05 17:46:59,702 - INFO # exp_mask = 00000007
2019-04-05 17:46:59,704 - INFO # max interval = 255
2019-04-05 17:47:53,245 - INFO # Elapsed time:
2019-04-05 17:47:53,248 - INFO #         Reference: 4294
2019-04-05 17:47:53,250 - INFO #  Timer under test: 4294
2019-04-05 17:47:53,253 - INFO #  Wall clock (RTT): 53
2019-04-05 17:47:53,257 - INFO # ------------- BEGIN STATISTICS --------------
2019-04-05 17:47:53,260 - INFO # ===== Reference timer statistics =====
2019-04-05 17:47:53,278 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2019-04-05 17:47:53,319 - INFO # Target error (actual trigger time - expected trigger time), in reference timer ticks
2019-04-05 17:47:53,325 - INFO # positive: timer under test is late, negative: timer under test is early
2019-04-05 17:47:53,329 - INFO # === timer_set running ===
2019-04-05 17:47:53,335 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,343 - INFO #   16 -   17:    12587    207817      5853826    -17    98    16    465  <=== SIC!
2019-04-05 17:47:53,354 - INFO #   18 -   19:    12843    221375      6528464    -19    98    17    508  <=== SIC!
2019-04-05 17:47:53,374 - INFO #   20 -   23:    10644    177854      5608026    -23    97    16    526  <=== SIC!
2019-04-05 17:47:53,381 - INFO #   24 -   31:     7442    115622      4282554    -31    98    15    575  <=== SIC!
2019-04-05 17:47:53,388 - INFO #   32 -   47:     7491    103790      5304060    -47    96    13    708  <=== SIC!
2019-04-05 17:47:53,392 - INFO #   48 -   79:     7299     56704      7824465    -79    96     7   1072  <=== SIC!
2019-04-05 17:47:53,405 - INFO #   80 -  143:     5591     -5018     11607733   -127    97     0   2076  <=== SIC!
2019-04-05 17:47:53,413 - INFO #       TOTAL     63897    878144     49007895   -127    98    13    766  <=== SIC!
2019-04-05 17:47:53,418 - INFO # === timer_set resched ===
2019-04-05 17:47:53,435 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,447 - INFO #   16 -   17:    12440    188646      4106703     -7    98    15    330  <=== SIC!
2019-04-05 17:47:53,475 - INFO #   18 -   19:    12504    191789      4156076     -7    96    15    332  <=== SIC!
2019-04-05 17:47:53,481 - INFO #   20 -   23:    10635    183117      4159102     -7    99    17    391  <=== SIC!
2019-04-05 17:47:53,490 - INFO #   24 -   31:     7654    165627      3772253     -7    97    21    492  <=== SIC!
2019-04-05 17:47:53,513 - INFO #   32 -   47:     7217    154684      3487303     -7    98    21    483  <=== SIC!
2019-04-05 17:47:53,527 - INFO #   48 -   79:     7362    160263      3636294     -7    96    21    493  <=== SIC!
2019-04-05 17:47:53,551 - INFO #   80 -  143:     5566    119232      2733825     -7    97    21    491  <=== SIC!
2019-04-05 17:47:53,572 - INFO #       TOTAL     63378   1163358     26526552     -7    99    18    418  <=== SIC!
2019-04-05 17:47:53,579 - INFO # === timer_set stopped ===
2019-04-05 17:47:53,589 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,593 - INFO #   16 -   17:     8733    172516      6324319   -462    96    19    724  <=== SIC!
2019-04-05 17:47:53,610 - INFO #   18 -   19:     9419    190476      6403980   -347    96    20    679  <=== SIC!
2019-04-05 17:47:53,623 - INFO #   20 -   23:     9359    187390      6318497   -435    94    20    675  <=== SIC!
2019-04-05 17:47:53,639 - INFO #   24 -   31:     9358    187480      6227319   -361    95    20    665  <=== SIC!
2019-04-05 17:47:53,654 - INFO #   32 -   47:     9461    179308      7478407   -493    96    18    790  <=== SIC!
2019-04-05 17:47:53,665 - INFO #   48 -   79:     8981    150769      9480100   -654    96    16   1055  <=== SIC!
2019-04-05 17:47:53,693 - INFO #   80 -  143:     6843    108654      8737962   -462    97    15   1277  <=== SIC!
2019-04-05 17:47:53,730 - INFO #       TOTAL     62154   1176593     51646292   -654    97    18    830  <=== SIC!
2019-04-05 17:47:53,739 - INFO # === timer_set stopped, resched ===
2019-04-05 17:47:53,763 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,779 - INFO #   16 -   17:     8811    180931      4745378     -7    97    20    538  <=== SIC!
2019-04-05 17:47:53,791 - INFO #   18 -   19:     9038    189994      4842780     -7    96    21    535  <=== SIC!
2019-04-05 17:47:53,830 - INFO #   20 -   23:     8862    182735      4766057     -7    98    20    537  <=== SIC!
2019-04-05 17:47:53,856 - INFO #   24 -   31:     8855    183689      4765624     -7    99    20    538  <=== SIC!
2019-04-05 17:47:53,875 - INFO #   32 -   47:     8976    186381      4821297     -7    96    20    537  <=== SIC!
2019-04-05 17:47:53,883 - INFO #   48 -   79:     9159    188046      4880765     -7    98    20    532  <=== SIC!
2019-04-05 17:47:53,885 - INFO #   80 -  143:     6822    140700      3674654     -7    96    20    538  <=== SIC!
2019-04-05 17:47:53,886 - INFO #       TOTAL     60523   1252476     32686549     -7    99    20    540  <=== SIC!
2019-04-05 17:47:53,887 - INFO # === timer_set_absolute running ===
2019-04-05 17:47:53,888 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,891 - INFO #   16 -   17:    12137    106839      3199145    -17   100     8    263  <=== SIC!
2019-04-05 17:47:53,893 - INFO #   18 -   19:    12163    108740      3264995    -19    94     8    268  <=== SIC!
2019-04-05 17:47:53,894 - INFO #   20 -   23:    10486    104109      3194505    -23    95     9    304  <=== SIC!
2019-04-05 17:47:53,897 - INFO #   24 -   31:     7350     87287      2966295    -30    97    11    403  <=== SIC!
2019-04-05 17:47:53,899 - INFO #   32 -   47:     7730     90561      4116215    -47    98    11    532  <=== SIC!
2019-04-05 17:47:53,903 - INFO #   48 -   79:     7355     52137      5650888    -79    95     7    768  <=== SIC!
2019-04-05 17:47:53,906 - INFO #   80 -  143:     5854     14181      8632556   -128    94     2   1474  <=== SIC!
2019-04-05 17:47:53,907 - INFO #       TOTAL     63075    563854     31525029   -128   100     8    499  <=== SIC!
2019-04-05 17:47:53,908 - INFO # === timer_set_absolute resched ===
2019-04-05 17:47:53,909 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,912 - INFO #   16 -   17:    12384    120618      3967323     -7    99     9    320  <=== SIC!
2019-04-05 17:47:53,913 - INFO #   18 -   19:    12545    128430      4166112     -7    97    10    332  <=== SIC!
2019-04-05 17:47:53,914 - INFO #   20 -   23:    10887    130982      4007973     -7    95    12    368  <=== SIC!
2019-04-05 17:47:53,916 - INFO #   24 -   31:     7370    128500      3219222     -7    97    17    436  <=== SIC!
2019-04-05 17:47:53,918 - INFO #   32 -   47:     7442    132237      3294341     -7    96    17    442  <=== SIC!
2019-04-05 17:47:53,919 - INFO #   48 -   79:     7324    128559      3234011     -7    99    17    441  <=== SIC!
2019-04-05 17:47:53,921 - INFO #   80 -  143:     5569     99005      2496241     -7    96    17    448  <=== SIC!
2019-04-05 17:47:53,922 - INFO #       TOTAL     63521    868331     25339683     -7    99    13    398  <=== SIC!
2019-04-05 17:47:53,923 - INFO # === timer_set_absolute stopped ===
2019-04-05 17:47:53,925 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,927 - INFO #   16 -   17:     9077    183669      5967486   -388    95    20    657  <=== SIC!
2019-04-05 17:47:53,928 - INFO #   18 -   19:     9422    192336      6122529   -372    96    20    649  <=== SIC!
2019-04-05 17:47:53,931 - INFO #   20 -   23:     9456    186966      6542111   -400    94    19    691  <=== SIC!
2019-04-05 17:47:53,934 - INFO #   24 -   31:     9113    180018      6264181   -296    96    19    687  <=== SIC!
2019-04-05 17:47:53,937 - INFO #   32 -   47:     9048    168030      7308428   -681    95    18    807  <=== SIC!
2019-04-05 17:47:53,938 - INFO #   48 -   79:     9134    157547      8444164   -275    95    17    924  <=== SIC!
2019-04-05 17:47:53,940 - INFO #   80 -  143:     7006    109707      8865180   -232    96    15   1265  <=== SIC!
2019-04-05 17:47:53,942 - INFO #       TOTAL     62256   1178273     50146405   -681    96    18    805  <=== SIC!
2019-04-05 17:47:53,943 - INFO # === timer_set_absolute stopped, resched ===
2019-04-05 17:47:53,945 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,947 - INFO #   16 -   17:     8666    177757      4644767     -7    97    20    536  <=== SIC!
2019-04-05 17:47:53,948 - INFO #   18 -   19:     9024    187878      4865328     -7   100    20    539  <=== SIC!
2019-04-05 17:47:53,951 - INFO #   20 -   23:     8870    183978      4767542     -7    99    20    537  <=== SIC!
2019-04-05 17:47:53,953 - INFO #   24 -   31:     9353    194415      5039435     -7    97    20    538  <=== SIC!
2019-04-05 17:47:53,954 - INFO #   32 -   47:     8745    178997      4643745     -7    95    20    531  <=== SIC!
2019-04-05 17:47:53,956 - INFO #   48 -   79:     8936    183524      4755413     -7    98    20    532  <=== SIC!
2019-04-05 17:47:53,957 - INFO #   80 -  143:     6903    141868      3699420     -7    97    20    535  <=== SIC!
2019-04-05 17:47:53,959 - INFO #       TOTAL     60497   1248417     32415650     -7   100    20    535  <=== SIC!
2019-04-05 17:47:53,960 - INFO # ===== introspective statistics =====
2019-04-05 17:47:53,961 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2019-04-05 17:47:53,964 - INFO # self-referencing error (TUT time elapsed - expected TUT interval), in timer under test ticks
2019-04-05 17:47:53,967 - INFO # positive: timer target handling is slow, negative: TUT is dropping ticks or triggering callback early
2019-04-05 17:47:53,969 - INFO # function              count       sum       sum_sq    min   max  mean  variance
2019-04-05 17:47:53,970 - INFO # 
2019-04-05 17:47:53,972 - INFO #          timer_set   249708   2278083    147449337   -661    86     9    590  <=== SIC!
2019-04-05 17:47:53,974 - INFO #            running    62660    249902     32709056   -137    86     3    522  <=== SIC!
2019-04-05 17:47:53,975 - INFO #            resched    62141    454993     26127839    -13    84     7    420  <=== SIC!
2019-04-05 17:47:53,977 - INFO #            stopped    63319    752896     52208772   -661    84    11    824  <=== SIC!
2019-04-05 17:47:53,978 - INFO #   stopped, resched    61588    820292     34026108    -13    86    13    552  <=== SIC!
2019-04-05 17:47:53,979 - INFO # 
2019-04-05 17:47:53,980 - INFO # timer_set_absolute   249593   1741792    140397629   -688    87     6    562  <=== SIC!
2019-04-05 17:47:53,982 - INFO #            running    62093      -947     21727539   -133    85     0    349  <=== SIC!
2019-04-05 17:47:53,984 - INFO #            resched    62476    170668     25260677    -13    86     2    404  <=== SIC!
2019-04-05 17:47:53,985 - INFO #            stopped    63420    755968     50607759   -688    83    11    797  <=== SIC!
2019-04-05 17:47:53,987 - INFO #   stopped, resched    61604    816103     33986083    -13

it sure got worse :/

@benpicco
Copy link
Contributor Author

benpicco commented Apr 5, 2019

I found the issue! I didn't check if INTENSET was actually set, only if INTFLAG was set, so the interrupt callback got called even when then interrupt was not enabled, but another one triggered.

Now it looks like before:

2019-04-05 18:17:31,534 - INFO # ------------- BEGIN STATISTICS --------------
2019-04-05 18:17:31,537 - INFO # ===== Reference timer statistics =====
2019-04-05 18:17:31,542 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2019-04-05 18:17:31,553 - INFO # Target error (actual trigger time - expected trigger time), in reference timer ticks
2019-04-05 18:17:31,563 - INFO # positive: timer under test is late, negative: timer under test is early
2019-04-05 18:17:31,565 - INFO # === timer_set running ===
2019-04-05 18:17:31,569 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:31,580 - INFO #   16 -   17:    50966    784464        19994     14    16    15      0  <=== SIC!
2019-04-05 18:17:31,585 - INFO #   18 -   19:    51242    793777        25146     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,597 - INFO #   20 -   23:    51255    785653        16828     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,609 - INFO #   24 -   31:    51623    800483        26135     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,616 - INFO #   32 -   47:    51502    805521        32989     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,632 - INFO #   48 -   79:    51222    820462         1390     15    17    16      0  <=== SIC!
2019-04-05 18:17:31,649 - INFO #   80 -  143:    39063    632731         7723     16    17    16      0  <=== SIC!
2019-04-05 18:17:31,665 - INFO #       TOTAL    346873   5423091      1583398     14    17    15      4  <=== SIC!
2019-04-05 18:17:31,672 - INFO # === timer_set resched ===
2019-04-05 18:17:31,688 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:31,699 - INFO #   16 -   17:    51130    786622        19680     14    16    15      0  <=== SIC!
2019-04-05 18:17:31,704 - INFO #   18 -   19:    51303    794345        24800     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,717 - INFO #   20 -   23:    51542    790855        17725     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,732 - INFO #   24 -   31:    50968    790173        25649     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,741 - INFO #   32 -   47:    50769    792887        31351     15    16    15      0  <=== SIC!
2019-04-05 18:17:31,750 - INFO #   48 -   79:    50719    811914         1104     15    17    16      0  <=== SIC!
2019-04-05 18:17:31,762 - INFO #   80 -  143:    39174    632221         5437     16    17    16      0  <=== SIC!
2019-04-05 18:17:31,770 - INFO #       TOTAL    345605   5399017      1569881     14    17    15      4  <=== SIC!
2019-04-05 18:17:31,777 - INFO # === timer_set stopped ===
2019-04-05 18:17:31,787 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:31,813 - INFO #   16 -   17:    50694     50735           41      1     2     1      0
2019-04-05 18:17:31,825 - INFO #   18 -   19:    50919     67130        16210      1     2     1      0
2019-04-05 18:17:31,834 - INFO #   20 -   23:    51407     92272        40862      1     2     1      0
2019-04-05 18:17:31,845 - INFO #   24 -   31:    51272     72484        21211      1     2     1      0
2019-04-05 18:17:31,855 - INFO #   32 -   47:    51174     93631        42447      1     2     1      0
2019-04-05 18:17:31,867 - INFO #   48 -   79:    50857    103828         2118      1     3     2      0
2019-04-05 18:17:31,887 - INFO #   80 -  143:    38939     85710         7832      2     3     2      0
2019-04-05 18:17:31,896 - INFO #       TOTAL    345262    565790       320259      1     3     1      0
2019-04-05 18:17:31,902 - INFO # === timer_set stopped, resched ===
2019-04-05 18:17:31,911 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:31,920 - INFO #   16 -   17:    51130     51153           23      1     2     1      0
2019-04-05 18:17:31,933 - INFO #   18 -   19:    51265     65717        14452      1     2     1      0
2019-04-05 18:17:31,945 - INFO #   20 -   23:    50806     92003        41194      1     2     1      0
2019-04-05 18:17:31,958 - INFO #   24 -   31:    50427     70475        20042      1     2     1      0
2019-04-05 18:17:31,968 - INFO #   32 -   47:    51157     93328        42171      1     2     1      0
2019-04-05 18:17:31,983 - INFO #   48 -   79:    51144    103757         1477      1     3     2      0
2019-04-05 18:17:31,992 - INFO #   80 -  143:    39192     84116         5732      2     3     2      0
2019-04-05 18:17:31,996 - INFO #       TOTAL    345121    560549       312964      1     3     1      0
2019-04-05 18:17:32,009 - INFO # === timer_set_absolute running ===
2019-04-05 18:17:32,025 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:32,034 - INFO #   16 -   17:    51063    434732        26227      8     9     8      0
2019-04-05 18:17:32,045 - INFO #   18 -   19:    51390    435526        24406      8     9     8      0
2019-04-05 18:17:32,061 - INFO #   20 -   23:    51022    423384        15208      8     9     8      0
2019-04-05 18:17:32,074 - INFO #   24 -   31:    51058    434696        26232      8     9     8      0
2019-04-05 18:17:32,085 - INFO #   32 -   47:    50652    438253        33036      8     9     8      0
2019-04-05 18:17:32,096 - INFO #   48 -   79:    50765    457818         1359      8    10     9      0
2019-04-05 18:17:32,106 - INFO #   80 -  143:    39237    361124         7991      9    10     9      0
2019-04-05 18:17:32,114 - INFO #       TOTAL    345187   2985533       953401      8    10     8      2
2019-04-05 18:17:32,117 - INFO # === timer_set_absolute resched ===
2019-04-05 18:17:32,131 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:32,142 - INFO #   16 -   17:    51294    436289        25937      8     9     8      0
2019-04-05 18:17:32,148 - INFO #   18 -   19:    51274    434943        24751      8     9     8      0
2019-04-05 18:17:32,152 - INFO #   20 -   23:    51423    427006        15618      8     9     8      0
2019-04-05 18:17:32,154 - INFO #   24 -   31:    51349    436905        26111      8     9     8      0
2019-04-05 18:17:32,156 - INFO #   32 -   47:    50976    439774        31965      8     9     8      0
2019-04-05 18:17:32,158 - INFO #   48 -   79:    51123    460746         1203      8    10     9      0
2019-04-05 18:17:32,159 - INFO #   80 -  143:    38964    356992         6316      9    10     9      0
2019-04-05 18:17:32,160 - INFO #       TOTAL    346403   2992655       949639      8    10     8      2
2019-04-05 18:17:32,161 - INFO # === timer_set_absolute stopped ===
2019-04-05 18:17:32,162 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:32,164 - INFO #   16 -   17:    51157     51199           42      1     2     1      0
2019-04-05 18:17:32,166 - INFO #   18 -   19:    51252     67911        16658      1     2     1      0
2019-04-05 18:17:32,167 - INFO #   20 -   23:    51250     91670        40420      1     2     1      0
2019-04-05 18:17:32,169 - INFO #   24 -   31:    51216     72541        21325      1     2     1      0
2019-04-05 18:17:32,170 - INFO #   32 -   47:    50672     92978        42302      1     2     1      0
2019-04-05 18:17:32,172 - INFO #   48 -   79:    51215    104543         2119      1     3     2      0
2019-04-05 18:17:32,174 - INFO #   80 -  143:    38992     86147         8163      2     3     2      0
2019-04-05 18:17:32,176 - INFO #       TOTAL    345754    566989       321719      1     3     1      0
2019-04-05 18:17:32,177 - INFO # === timer_set_absolute stopped, resched ===
2019-04-05 18:17:32,178 - INFO #    interval     count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:32,180 - INFO #   16 -   17:    51159     51192           33      1     2     1      0
2019-04-05 18:17:32,182 - INFO #   18 -   19:    50690     65001        14311      1     2     1      0
2019-04-05 18:17:32,185 - INFO #   20 -   23:    51086     92495        41398      1     2     1      0
2019-04-05 18:17:32,186 - INFO #   24 -   31:    51276     71659        20383      1     2     1      0
2019-04-05 18:17:32,188 - INFO #   32 -   47:    50854     92703        41849      1     2     1      0
2019-04-05 18:17:32,191 - INFO #   48 -   79:    50632    102705         1445      1     3     2      0
2019-04-05 18:17:32,193 - INFO #   80 -  143:    38966     83717         5785      2     3     2      0
2019-04-05 18:17:32,194 - INFO #       TOTAL    344663    559472       311626      1     3     1      0
2019-04-05 18:17:32,195 - INFO # ===== introspective statistics =====
2019-04-05 18:17:32,196 - INFO # Limits: mean: [-10, 10], variance: [0, 16]
2019-04-05 18:17:32,198 - INFO # self-referencing error (TUT time elapsed - expected TUT interval), in timer under test ticks
2019-04-05 18:17:32,200 - INFO # positive: timer target handling is slow, negative: TUT is dropping ticks or triggering callback early
2019-04-05 18:17:32,202 - INFO # function              count       sum       sum_sq    min   max  mean  variance
2019-04-05 18:17:32,202 - INFO # 
2019-04-05 18:17:32,207 - INFO #          timer_set  1382861  -1623793     15035695     -5     3    -1     10
2019-04-05 18:17:32,208 - INFO #            running   346873    795356       101630      1     3     2      0
2019-04-05 18:17:32,210 - INFO #            resched   345605    790518        99315      1     3     2      0
2019-04-05 18:17:32,213 - INFO #            stopped   345262  -1605009       223956     -5    -4    -4      0
2019-04-05 18:17:32,214 - INFO #   stopped, resched   345121  -1604658       224171     -5    -4    -4      0
2019-04-05 18:17:32,215 - INFO # 
2019-04-05 18:17:32,217 - INFO # timer_set_absolute  1382007  -6466324       938289     -5    -4    -4      0
2019-04-05 18:17:32,219 - INFO #            running   345187  -1624035       243283     -5    -4    -4      0
2019-04-05 18:17:32,221 - INFO #            resched   346403  -1631766       246153     -5    -4    -4      0
2019-04-05 18:17:32,223 - INFO #            stopped   345754  -1606924       223906     -5    -4    -4      0
2019-04-05 18:17:32,225 - INFO #   stopped, resched   344663  -1603599       224947     -5    -4    -4      0
2019-04-05 18:17:32,225 - INFO # -------------- END STATISTICS ---------------

@fedepell
Copy link
Contributor

fedepell commented Apr 6, 2019

Very good, thanks for the changes!
I can confirm now that on my saml21-xpro the results of the benchmark are in line with the ones on the master:

main(): This is RIOT! (Version: 2014.01-19976-g6f0c7d-sam0-timer)

Statistical benchmark for timers
Running timer test with seed 123 using Tiny Mersenne Twister PRNG.
TEST_MIN = 16
TEST_MAX = 128
TEST_MIN_REL = 16
TEST_MAX_REL = 128
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 = 38
Estimating benchmark overhead...
overhead_target = 17 (s2 = 0)
overhead_read = 17 (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
  16 -   17:     5287     27061         2657      4     6     5      0
  18 -   19:     5430     16959         2685      2     4     3      0
  20 -   23:     5285      6460         2965      0     5     1      0
  24 -   31:     5338     15969         4848      0     5     2      0
  32 -   47:     5222     15355         4906      2     3     2      0
  48 -   79:     5364     15756         5014      2     3     2      0
  80 -  143:     4046     11910         3786      2     3     2      0
      TOTAL     35972    109470         9073      0     6     3      0
=== timer_set resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5194     26593         2516      4     6     5      0
  18 -   19:     5366     16775         2632      2     4     3      0
  20 -   23:     5353      6613         3280      0     5     1      0
  24 -   31:     5401     16151         7276      0     5     2      1
  32 -   47:     5318     15600         4964      2     3     2      0
  48 -   79:     5288     15542         4944      2     3     2      0
  80 -  143:     4085     12009         3809      2     3     2      0
      TOTAL     36005    109283        10079      0     6     3      0
=== timer_set stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5396    -42636         6435     -8    -4    -7      1
  18 -   19:     5303    -40387         7577     -8    -4    -7      1
  20 -   23:     5332    -30829         4201     -7    -5    -5      0
  24 -   31:     5330    -31980            0     -6    -6    -6      0
  32 -   47:     5389    -32334            0     -6    -6    -6      0
  48 -   79:     5281    -31686            0     -6    -6    -6      0
  80 -  143:     4136    -24816            0     -6    -6    -6      0
      TOTAL     36167   -234668       113852     -8    -4    -6      3
=== timer_set stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5363    -42372         6370     -8    -4    -7      1
  18 -   19:     5333    -40729         7526     -8    -4    -7      1
  20 -   23:     5276    -30569         4210     -7    -5    -5      0
  24 -   31:     5414    -32484            0     -6    -6    -6      0
  32 -   47:     5359    -32154            0     -6    -6    -6      0
  48 -   79:     5229    -31374            0     -6    -6    -6      0
  80 -  143:     4019    -24114            0     -6    -6    -6      0
      TOTAL     35993   -233796       113670     -8    -4    -6      3
=== timer_set_absolute running ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5418      -267         2618     -1     1     0      0
  18 -   19:     5378    -11122         2755     -3    -1    -2      0
  20 -   23:     5360    -20350         6399     -5     0    -3      1
  24 -   31:     5408    -10625         7470     -5     0    -1      1
  32 -   47:     5368    -11082          346     -3    -2    -2      0
  48 -   79:     5376    -11097          345     -3    -2    -2      0
  80 -  143:     4062     -8378          254     -3    -2    -2      0
      TOTAL     36370    -72921        29378     -5     1    -2      0
=== timer_set_absolute resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5427      -330         2712     -1     1     0      0
  18 -   19:     5436    -11212         2712     -3    -1    -2      0
  20 -   23:     5285    -20137         6258     -5     0    -3      1
  24 -   31:     5319    -10410         8007     -5     0    -1      1
  32 -   47:     5441    -11216          334     -3    -2    -2      0
  48 -   79:     5310    -10944          324     -3    -2    -2      0
  80 -  143:     4038     -8322          246     -3    -2    -2      0
      TOTAL     36256    -72571        29660     -5     1    -2      0
=== timer_set_absolute stopped ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5176    -40932         6113     -8    -4    -7      1
  18 -   19:     5266    -40446         7061     -8    -4    -7      1
  20 -   23:     5297    -30585         4129     -7    -5    -5      0
  24 -   31:     5286    -31716            0     -6    -6    -6      0
  32 -   47:     5272    -31632            0     -6    -6    -6      0
  48 -   79:     5323    -31938            0     -6    -6    -6      0
  80 -  143:     4125    -24750            0     -6    -6    -6      0
      TOTAL     35745   -231999       111963     -8    -4    -6      3
=== timer_set_absolute stopped, resched ===
   interval     count       sum       sum_sq    min   max  mean  variance
  16 -   17:     5287    -41820         6187     -8    -4    -7      1
  18 -   19:     5395    -41289         7425     -8    -4    -7      1
  20 -   23:     5378    -31187         4312     -7    -5    -5      0
  24 -   31:     5343    -32058            0     -6    -6    -6      0
  32 -   47:     5411    -32466            0     -6    -6    -6      0
  48 -   79:     5372    -32232            0     -6    -6    -6      0
  80 -  143:     4086    -24516            0     -6    -6    -6      0
      TOTAL     36272   -235568       114296     -8    -4    -6      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   144137  -1018897       799298    -12    -2    -7      5
           running    35972   -153762        59672     -7    -2    -4      1
           resched    36005   -154090        59503     -7    -2    -4      1
           stopped    36167   -356225        90602    -12    -8    -9      2
  stopped, resched    35993   -354820        90987    -12    -8    -9      2

timer_set_absolute   144643  -1385883       300262    -12    -7    -9      2
           running    36370   -338875        60473    -12    -7    -9      1
           resched    36256   -337631        59475    -12    -7    -9      1
           stopped    35745   -352062        89352    -12    -8    -9      2
  stopped, resched    36272   -357315        90962    -12    -8    -9      2
-------------- END STATISTICS ---------------

@fedepell
Copy link
Contributor

fedepell commented Apr 6, 2019

I have problems after the last commits using xtimer_sleep() on the saml21-xpro. It will just never returns, so sleep forever.
From the last commits I traced it down to the commit 9e3985d, from this one it will not work anymore.

To test it just write a simple program that uses xtimer_sleep(), ie I'm specifically using something like you see in the description of #10523.

@benpicco benpicco force-pushed the sam0-timer branch 2 times, most recently from e04df01 to 8be3898 Compare April 10, 2019 17:03
@fedepell fedepell mentioned this pull request May 9, 2019
Closed
dylad
dylad reviewed May 20, 2019
View reviewed changes
cpu/sam0_common/periph/timer.c
/**
* @brief Setup the given timer
*/
int timer_init(tim_t tim, unsigned long freq, timer_cb_t cb, void *arg)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

please add a guard in the very beginning of this function to ensure tim < TIMER_NUMOF
You can use an assert like other drivers or return an error.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok.

@dylad
Copy link
Member

dylad commented May 20, 2019

@fedepell Do you still have pending comment ? Or everything was addressed ?

@dylad dylad added Area: cpu Area: CPU/MCU ports CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR Platform: ARM Platform: This PR/issue effects ARM-based platforms labels May 20, 2019
@dylad
Copy link
Member

dylad commented May 20, 2019

Murdocks reports some boards miss their periph_conf update (arduino-mkr, hamilton, etc.)

@benpicco
Copy link
Contributor Author

benpicco commented May 20, 2019 •
edited
Loading

urg, Hamilton is new but the Arduino failures are due to sorry, unimplemented: non-trivial designated initializers not supported

How does this work for uart_config and not for timer_config? I don't want to wait for C++20

@benpicco
Copy link
Contributor Author

So in C++ the elements in the initializer have to be in the same order as in the struct definition. Thanks to @kaspar030 for pointing that out!

fedepell
fedepell reviewed May 21, 2019
View reviewed changes
boards/sodaq-explorer/include/periph_conf.h
/* interrupt function name mapping */
#define TIMER_0_ISR isr_tc4

#define TIMER_NUMOF (sizeof(timer_config) / sizeof(timer_config[0]))
/** @} */

Copy link
Contributor

@fedepell fedepell May 21, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Forgot to define TIMER_0_MAX_VALUE for this board? (as it is 16 bit needs to be here, otherwise defaults to 32)

Copy link
Contributor Author

@benpicco benpicco May 21, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

but it's 32 bit here.
nvm,I accidentally dropped the 16 bit timer - fixed.

@fedepell
Copy link
Contributor

@dylad : went through the code now and except that little note I put looks fine to me!

@dylad dylad added CI: run tests If set, CI server will run tests on hardware for the labeled PR Reviewed: 1-fundamentals The fundamentals of the PR were reviewed according to the maintainer guidelines labels May 21, 2019
@dylad dylad added Reviewed: 2-code-design The code design of the PR was reviewed according to the maintainer guidelines Reviewed: 4-code-style The adherence to coding conventions by the PR were reviewed according to the maintainer guidelines Reviewed: 5-documentation The documentation details of the PR were reviewed according to the maintainer guidelines CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR and removed CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR labels May 21, 2019
dylad
dylad approved these changes May 21, 2019
View reviewed changes
Copy link
Member

@dylad dylad left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK, please squash

@benpicco
sam0_common: make Timer implementation common across all sam0 MCUs
849dd4c 
The currently supported SAM0 MCUs (samd21, saml21, saml1x) share the same
Timer peripheral, yet each of them carries it's own copy of the Timer
driver.

This introduces a new timer driver that is common for all sam0 MCUs and
uses structs for configuration instead of defines.
@benpicco
Copy link
Contributor Author

squashed.

@dylad dylad added CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR Reviewed: 3-testing The PR was tested according to the maintainer guidelines and removed CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR labels May 21, 2019
@dylad
Copy link
Member

dylad commented May 21, 2019

Here we go

@dylad dylad merged commit 85d37bb into RIOT-OS:master May 21, 2019
@benpicco benpicco deleted the sam0-timer branch May 21, 2019 10:15
@dylad dylad mentioned this pull request May 22, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@fedepell fedepell fedepell requested changes

@dylad dylad dylad approved these changes

Assignees
No one assigned
Labels
Area: cpu Area: CPU/MCU ports CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR CI: run tests If set, CI server will run tests on hardware for the labeled PR Platform: ARM Platform: This PR/issue effects ARM-based platforms Reviewed: 1-fundamentals The fundamentals of the PR were reviewed according to the maintainer guidelines Reviewed: 2-code-design The code design of the PR was reviewed according to the maintainer guidelines Reviewed: 3-testing The PR was tested according to the maintainer guidelines Reviewed: 4-code-style The adherence to coding conventions by the PR were reviewed according to the maintainer guidelines Reviewed: 5-documentation The documentation details of the PR were reviewed according to the maintainer guidelines
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@benpicco @fedepell @dylad