tests/bench_xtimer: initial import

[kaspar030]

Contribution description

This PR provides a basic benchmark for some of xtimer's operations.

Testing procedure

Please comment if the benchmaring methodology makes sense.
The usual review otherwise.

Issues/PRs references

[kaspar030]

All boards are now sorted into their corresponding memory lists.

[kaspar030]

Sorry, I accidentally squashed those commits.

[kaspar030]

Murdock shows an unrelated failure in tests/shell on esp32-wroom-32. I'll trigger again.

[kaspar030]

@MichelRottleuthner We'll get numbers!! 😉

[MichelRottleuthner]

@MichelRottleuthner We'll get numbers!! wink

Awesome, thanks for adding this! As I said before I won't really have time to spend time on this till beginning of next year but I'm very eager to see the results 😃

[kaspar030]

@MichelRottleuthner could we maybe fasttrack this to make testing #9530 for (too heavy) regressions easier?

[MichelRottleuthner]

A bit short on time today, but I'd be fine with fast-tracking this one as it won't break anything.
Regarding #9530 I just wonder how much value we get out of benching a currently not working implementation against a (hopefully) working solution. I'd still prefer the degraded performance over a non-working solution with better performance characteristics ;)

One thing that should be added to the readme is a short description on how to interpret the values.
Looking at the results of a first try it looks like at least for set() one remove() one set() + remove() one and xtimer_now() need more repetitions to give a more precise calculated end result.

I didn't at all look at how reasonable the benches are. But even executing all basic operations a few times gives us something as a starting point for comparison and it can be easily extended later.

[MrKevinWeiss]

Each board was run on the HiL setup which means raspberry pi 3s so maybe that affects timing. Three runs for each board.

samr21-xpro

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    29002 / 1000 = 29
                  remove() one     2134 / 1000 = 2
          set() + remove() one    33007 / 1000 = 33
  set() many increasing target   143512 / 1000 = 143
               re-set()  first   233896 / 1000 = 233
               re-set() middle   465902 / 1000 = 465
               re-set()   last   685452 / 1000 = 685
       remove() + set()  first   448879 / 1000 = 448
       remove() + set() middle   681102 / 1000 = 681
       remove() + set()   last   896479 / 1000 = 896
      remove() many decreasing   106247 / 1000 = 106
                  xtimer_now()     7007 / 1000 = 7
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    29002 / 1000 = 29
                  remove() one     2134 / 1000 = 2
          set() + remove() one    33007 / 1000 = 33
  set() many increasing target   143512 / 1000 = 143
               re-set()  first   233896 / 1000 = 233
               re-set() middle   466013 / 1000 = 466
               re-set()   last   685452 / 1000 = 685
       remove() + set()  first   448879 / 1000 = 448
       remove() + set() middle   681050 / 1000 = 681
       remove() + set()   last   896479 / 1000 = 896
      remove() many decreasing   106247 / 1000 = 106
                  xtimer_now()     7007 / 1000 = 7
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    29002 / 1000 = 29
                  remove() one     2134 / 1000 = 2
          set() + remove() one    33007 / 1000 = 33
  set() many increasing target   143512 / 1000 = 143
               re-set()  first   233896 / 1000 = 233
               re-set() middle   465992 / 1000 = 465
               re-set()   last   685452 / 1000 = 685
       remove() + set()  first   448879 / 1000 = 448
       remove() + set() middle   681050 / 1000 = 681
       remove() + set()   last   896473 / 1000 = 896
      remove() many decreasing   106247 / 1000 = 106
                  xtimer_now()     7007 / 1000 = 7
done.

nrf52dk

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     7688 / 1000 = 7
                  remove() one     1065 / 1000 = 1
          set() + remove() one     8752 / 1000 = 8
  set() many increasing target    90128 / 1000 = 90
               re-set()  first   163773 / 1000 = 163
               re-set() middle   401869 / 1000 = 401
               re-set()   last   582398 / 1000 = 582
       remove() + set()  first   323388 / 1000 = 323
       remove() + set() middle   609513 / 1000 = 609
       remove() + set()   last   786276 / 1000 = 786
      remove() many decreasing   102384 / 1000 = 102
                  xtimer_now()      813 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     7687 / 1000 = 7
                  remove() one     1065 / 1000 = 1
          set() + remove() one     8751 / 1000 = 8
  set() many increasing target    90129 / 1000 = 90
               re-set()  first   163774 / 1000 = 163
               re-set() middle   401869 / 1000 = 401
               re-set()   last   582398 / 1000 = 582
       remove() + set()  first   323388 / 1000 = 323
       remove() + set() middle   609513 / 1000 = 609
       remove() + set()   last   786276 / 1000 = 786
      remove() many decreasing   102384 / 1000 = 102
                  xtimer_now()      813 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     7687 / 1000 = 7
                  remove() one     1065 / 1000 = 1
          set() + remove() one     8752 / 1000 = 8
  set() many increasing target    90129 / 1000 = 90
               re-set()  first   163774 / 1000 = 163
               re-set() middle   401869 / 1000 = 401
               re-set()   last   582398 / 1000 = 582
       remove() + set()  first   323388 / 1000 = 323
       remove() + set() middle   609513 / 1000 = 609
       remove() + set()   last   786276 / 1000 = 786
      remove() many decreasing   102384 / 1000 = 102
                  xtimer_now()      813 / 1000 = 0
done.

nucleo-l073rz

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    14826 / 1000 = 14
                  remove() one     3189 / 1000 = 3
          set() + remove() one    17845 / 1000 = 17
  set() many increasing target     4765 / 100 = 47
               re-set()  first    51476 / 1000 = 51
               re-set() middle   107308 / 1000 = 107
               re-set()   last   154125 / 1000 = 154
       remove() + set()  first    90590 / 1000 = 90
       remove() + set() middle   146396 / 1000 = 146
       remove() + set()   last   191265 / 1000 = 191
      remove() many decreasing     2073 / 100 = 20
                  xtimer_now()     1752 / 1000 = 1
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    14811 / 1000 = 14
                  remove() one     3189 / 1000 = 3
          set() + remove() one    17845 / 1000 = 17
  set() many increasing target     4766 / 100 = 47
               re-set()  first    51475 / 1000 = 51
               re-set() middle   107306 / 1000 = 107
               re-set()   last   154125 / 1000 = 154
       remove() + set()  first    90589 / 1000 = 90
       remove() + set() middle   146396 / 1000 = 146
       remove() + set()   last   191265 / 1000 = 191
      remove() many decreasing     2073 / 100 = 20
                  xtimer_now()     1752 / 1000 = 1
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    14811 / 1000 = 14
                  remove() one     3189 / 1000 = 3
          set() + remove() one    17845 / 1000 = 17
  set() many increasing target     4765 / 100 = 47
               re-set()  first    51475 / 1000 = 51
               re-set() middle   107306 / 1000 = 107
               re-set()   last   154125 / 1000 = 154
       remove() + set()  first    90589 / 1000 = 90
       remove() + set() middle   146396 / 1000 = 146
       remove() + set()   last   191265 / 1000 = 191
      remove() many decreasing     2074 / 100 = 20
                  xtimer_now()     1752 / 1000 = 1
done.

nucleo-f411re

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     3730 / 1000 = 3
                  remove() one      626 / 1000 = 0
          set() + remove() one     4314 / 1000 = 4
  set() many increasing target    59325 / 1000 = 59
               re-set()  first   107737 / 1000 = 107
               re-set() middle   217873 / 1000 = 217
               re-set()   last   324989 / 1000 = 324
       remove() + set()  first   213480 / 1000 = 213
       remove() + set() middle   323653 / 1000 = 323
       remove() + set()   last   429659 / 1000 = 429
      remove() many decreasing    52621 / 1000 = 52
                  xtimer_now()      250 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     3729 / 1000 = 3
                  remove() one      627 / 1000 = 0
          set() + remove() one     4313 / 1000 = 4
  set() many increasing target    59326 / 1000 = 59
               re-set()  first   107737 / 1000 = 107
               re-set() middle   217873 / 1000 = 217
               re-set()   last   324989 / 1000 = 324
       remove() + set()  first   213480 / 1000 = 213
       remove() + set() middle   323652 / 1000 = 323
       remove() + set()   last   429658 / 1000 = 429
      remove() many decreasing    52622 / 1000 = 52
                  xtimer_now()      251 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     3729 / 1000 = 3
                  remove() one      627 / 1000 = 0
          set() + remove() one     4313 / 1000 = 4
  set() many increasing target    59326 / 1000 = 59
               re-set()  first   107737 / 1000 = 107
               re-set() middle   217873 / 1000 = 217
               re-set()   last   324989 / 1000 = 324
       remove() + set()  first   213480 / 1000 = 213
       remove() + set() middle   323652 / 1000 = 323
       remove() + set()   last   429658 / 1000 = 429
      remove() many decreasing    52622 / 1000 = 52
                  xtimer_now()      251 / 1000 = 0
done.

remote-revb

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    27914 / 1000 = 27
                  remove() one     4631 / 1000 = 4
          set() + remove() one    32256 / 1000 = 32
  set() many increasing target   617505 / 1000 = 617
               re-set()  first  1073707 / 1000 = 1073
               re-set() middle  2207968 / 1000 = 2207
               re-set()   last  3077357 / 1000 = 3077
       remove() + set()  first  2121249 / 1000 = 2121
       remove() + set() middle  2679843 / 1000 = 2679
0x201769
*** RIOT kernel panic:
FAILED ASSERTION.

*** halted.

Timeout in expect script at "child.expect(r"\s+[\w() _\+]+\s+\d+ / \d+ = \d+\r\n")" (tests/bench_xtimer/tests/01-run.py:16)

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    27914 / 1000 = 27
                  remove() one     4631 / 1000 = 4
          set() + remove() one    32256 / 1000 = 32
  set() many increasing target   617501 / 1000 = 617
               re-set()  first  1073703 / 1000 = 1073
               re-set() middle  2207967 / 1000 = 2207
               re-set()   last  3077357 / 1000 = 3077
       remove() + set()  first  2121281 / 1000 = 2121
       remove() + set() middle  2220028 / 1000 = 2220
0x201769
*** RIOT kernel panic:
FAILED ASSERTION.

*** halted.

Timeout in expect script at "child.expect(r"\s+[\w() _\+]+\s+\d+ / \d+ = \d+\r\n")" (tests/bench_xtimer/tests/01-run.py:16)

arduino-mega2560

Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 111, in expect_loop
    incoming = spawn.read_nonblocking(spawn.maxread, timeout)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/pty_spawn.py", line 509, in read_nonblocking
    raise TIMEOUT('Timeout exceeded.')
pexpect.exceptions.TIMEOUT: Timeout exceeded.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/tmp/RIOT/tests/bench_xtimer/tests/01-run.py", line 22, in <module>
    sys.exit(run(testfunc))
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/__init__.py", line 27, in run
    logfile=sys.stdout if echo else None)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 56, in setup_child
    sync_child(child)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 79, in sync_child
    _test_utils_interactive_sync(child, modules)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 86, in _test_utils_interactive_sync
    utils.test_utils_interactive_sync(child, retries=retries, delay=delay)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/utils.py", line 24, in test_utils_interactive_sync
    child.expect_exact('READY', timeout=0)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/spawnbase.py", line 418, in expect_exact
    return exp.expect_loop(timeout)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 119, in expect_loop
    return self.timeout(e)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 82, in timeout
    raise TIMEOUT(msg)
pexpect.exceptions.TIMEOUT: Timeout exceeded.
<pexpect.pty_spawn.spawn object at 0x7667fef0>
command: /usr/bin/make
args: [b'/usr/bin/make', b'cleanterm']
buffer (last 100 chars): '.\r\ns to start test, r to print it is ready\r\n\x0c\r\nHelp: Press s to start test, r to print it is ready\r\n'
before (last 100 chars): '.\r\ns to start test, r to print it is ready\r\n\x0c\r\nHelp: Press s to start test, r to print it is ready\r\n'
after: <class 'pexpect.exceptions.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 29308
child_fd: 5
closed: False
timeout: 10
delimiter: <class 'pexpect.exceptions.EOF'>
logfile: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
logfile_read: None
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1
searcher: searcher_string:
    0: 'READY'
make: *** [/home/pi/tmp/RIOT/tests/bench_xtimer/../../Makefile.include:704: test] Error 1

nucleo-f103rb

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     6500 / 1000 = 6
                  remove() one     1279 / 1000 = 1
          set() + remove() one     7703 / 1000 = 7
  set() many increasing target     2101 / 100 = 21
               re-set()  first    31991 / 1000 = 31
               re-set() middle    61246 / 1000 = 61
               re-set()   last    87626 / 1000 = 87
       remove() + set()  first    58688 / 1000 = 58
       remove() + set() middle    87947 / 1000 = 87
       remove() + set()   last   113571 / 1000 = 113
      remove() many decreasing     1381 / 100 = 13
                  xtimer_now()      987 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     6499 / 1000 = 6
                  remove() one     1279 / 1000 = 1
          set() + remove() one     7702 / 1000 = 7
  set() many increasing target     2101 / 100 = 21
               re-set()  first    31991 / 1000 = 31
               re-set() middle    61246 / 1000 = 61
               re-set()   last    87627 / 1000 = 87
       remove() + set()  first    58688 / 1000 = 58
       remove() + set() middle    87948 / 1000 = 87
       remove() + set()   last   113571 / 1000 = 113
      remove() many decreasing     1381 / 100 = 13
                  xtimer_now()      987 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     6499 / 1000 = 6
                  remove() one     1279 / 1000 = 1
          set() + remove() one     7695 / 1000 = 7
  set() many increasing target     2101 / 100 = 21
               re-set()  first    31991 / 1000 = 31
               re-set() middle    61246 / 1000 = 61
               re-set()   last    87626 / 1000 = 87
       remove() + set()  first    58688 / 1000 = 58
       remove() + set() middle    87947 / 1000 = 87
       remove() + set()   last   113571 / 1000 = 113
      remove() many decreasing     1381 / 100 = 13
                  xtimer_now()      987 / 1000 = 0
done.

frdm-k22f

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     9298 / 1000 = 9
                  remove() one     1002 / 1000 = 1
          set() + remove() one    10401 / 1000 = 10
  set() many increasing target    96554 / 1000 = 96
               re-set()  first   175696 / 1000 = 175
               re-set() middle   352837 / 1000 = 352
               re-set()   last   522099 / 1000 = 522
       remove() + set()  first   346051 / 1000 = 346
       remove() + set() middle   523268 / 1000 = 523
       remove() + set()   last   689498 / 1000 = 689
      remove() many decreasing    84207 / 1000 = 84
                  xtimer_now()      634 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     9099 / 1000 = 9
                  remove() one     1002 / 1000 = 1
          set() + remove() one    10501 / 1000 = 10
  set() many increasing target    96553 / 1000 = 96
               re-set()  first   175696 / 1000 = 175
               re-set() middle   352837 / 1000 = 352
               re-set()   last   522099 / 1000 = 522
       remove() + set()  first   346051 / 1000 = 346
       remove() + set() middle   523269 / 1000 = 523
       remove() + set()   last   689499 / 1000 = 689
      remove() many decreasing    84208 / 1000 = 84
                  xtimer_now()      635 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     9297 / 1000 = 9
                  remove() one     1004 / 1000 = 1
          set() + remove() one    10502 / 1000 = 10
  set() many increasing target    96555 / 1000 = 96
               re-set()  first   175697 / 1000 = 175
               re-set() middle   352836 / 1000 = 352
               re-set()   last   522098 / 1000 = 522
       remove() + set()  first   346049 / 1000 = 346
       remove() + set() middle   523268 / 1000 = 523
       remove() + set()   last   689499 / 1000 = 689
      remove() many decreasing    84207 / 1000 = 84
                  xtimer_now()      634 / 1000 = 0
done.

slstk3401a

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     8252 / 1000 = 8
                  remove() one     1576 / 1000 = 1
          set() + remove() one     9876 / 1000 = 9
  set() many increasing target   231736 / 1000 = 231
               re-set()  first   293224 / 1000 = 293
               re-set() middle   664444 / 1000 = 664
               re-set()   last  1005760 / 1000 = 1005
       remove() + set()  first   579996 / 1000 = 579
       remove() + set() middle   950768 / 1000 = 950
       remove() + set()   last  1282344 / 1000 = 1282
      remove() many decreasing   139124 / 1000 = 139
                  xtimer_now()     1252 / 1000 = 1
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     8252 / 1000 = 8
                  remove() one     1576 / 1000 = 1
          set() + remove() one     9880 / 1000 = 9
  set() many increasing target   231740 / 1000 = 231
               re-set()  first   293224 / 1000 = 293
               re-set() middle   664444 / 1000 = 664
               re-set()   last  1005756 / 1000 = 1005
       remove() + set()  first   579992 / 1000 = 579
       remove() + set() middle   950772 / 1000 = 950
       remove() + set()   last  1282348 / 1000 = 1282
      remove() many decreasing   139124 / 1000 = 139
                  xtimer_now()     1252 / 1000 = 1
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     8252 / 1000 = 8
                  remove() one     1576 / 1000 = 1
          set() + remove() one     9880 / 1000 = 9
  set() many increasing target   231732 / 1000 = 231
               re-set()  first   293236 / 1000 = 293
               re-set() middle   664444 / 1000 = 664
               re-set()   last  1005756 / 1000 = 1005
       remove() + set()  first   579992 / 1000 = 579
       remove() + set() middle   950772 / 1000 = 950
       remove() + set()   last  1282348 / 1000 = 1282
      remove() many decreasing   139124 / 1000 = 139
                  xtimer_now()     1252 / 1000 = 1
done.

arduino-mkrzero

Welcome to pyterm!
Type '/exit' to exit.
r
shell: command not found: r
> r
 r
shell: command not found: r
> r
 r
shell: command not found: r
> r
 r
shell: command not found: r
> r
 r
shell: command not found: r
> Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 111, in expect_loop
    incoming = spawn.read_nonblocking(spawn.maxread, timeout)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/pty_spawn.py", line 509, in read_nonblocking
    raise TIMEOUT('Timeout exceeded.')
pexpect.exceptions.TIMEOUT: Timeout exceeded.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/tmp/RIOT/tests/bench_xtimer/tests/01-run.py", line 22, in <module>
    sys.exit(run(testfunc))
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/__init__.py", line 27, in run
    logfile=sys.stdout if echo else None)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 56, in setup_child
    sync_child(child)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 79, in sync_child
    _test_utils_interactive_sync(child, modules)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 86, in _test_utils_interactive_sync
    utils.test_utils_interactive_sync(child, retries=retries, delay=delay)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/utils.py", line 24, in test_utils_interactive_sync
    child.expect_exact('READY', timeout=0)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/spawnbase.py", line 418, in expect_exact
    return exp.expect_loop(timeout)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 119, in expect_loop
    return self.timeout(e)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 82, in timeout
    raise TIMEOUT(msg)
pexpect.exceptions.TIMEOUT: Timeout exceeded.
<pexpect.pty_spawn.spawn object at 0x7671bed0>
command: /usr/bin/make
args: [b'/usr/bin/make', b'cleanterm']
buffer (last 100 chars): 'hell: command not found: r\r\n>  r\r\nshell: command not found: r\r\n>  r\r\nshell: command not found: r\r\n> '
before (last 100 chars): 'hell: command not found: r\r\n>  r\r\nshell: command not found: r\r\n>  r\r\nshell: command not found: r\r\n> '
after: <class 'pexpect.exceptions.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 18071
child_fd: 5
closed: False
timeout: 10
delimiter: <class 'pexpect.exceptions.EOF'>
logfile: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
logfile_read: None
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1
searcher: searcher_string:
    0: 'READY'
make: *** [/home/pi/tmp/RIOT/tests/bench_xtimer/../../Makefile.include:704: test] Error 1

nucleo-f767zi

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     4848 / 1000 = 4
                  remove() one      770 / 1000 = 0
          set() + remove() one     5767 / 1000 = 5
  set() many increasing target   104365 / 1000 = 104
               re-set()  first   139963 / 1000 = 139
               re-set() middle   310674 / 1000 = 310
               re-set()   last   474943 / 1000 = 474
       remove() + set()  first   277464 / 1000 = 277
       remove() + set() middle   448206 / 1000 = 448
       remove() + set()   last   610186 / 1000 = 610
      remove() many decreasing    67927 / 1000 = 67
                  xtimer_now()      515 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     4849 / 1000 = 4
                  remove() one      771 / 1000 = 0
          set() + remove() one     5766 / 1000 = 5
  set() many increasing target   104366 / 1000 = 104
               re-set()  first   139962 / 1000 = 139
               re-set() middle   310674 / 1000 = 310
               re-set()   last   474943 / 1000 = 474
       remove() + set()  first   277464 / 1000 = 277
       remove() + set() middle   448206 / 1000 = 448
       remove() + set()   last   610187 / 1000 = 610
      remove() many decreasing    67926 / 1000 = 67
                  xtimer_now()      515 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     4848 / 1000 = 4
                  remove() one      771 / 1000 = 0
          set() + remove() one     5766 / 1000 = 5
  set() many increasing target   104366 / 1000 = 104
               re-set()  first   139963 / 1000 = 139
               re-set() middle   310674 / 1000 = 310
               re-set()   last   474943 / 1000 = 474
       remove() + set()  first   277464 / 1000 = 277
       remove() + set() middle   448207 / 1000 = 448
       remove() + set()   last   610186 / 1000 = 610
      remove() many decreasing    67926 / 1000 = 67
                  xtimer_now()      515 / 1000 = 0
done.

frdm-kw41z

Welcome to pyterm!
Type '/exit' to exit.
r
r
r
r
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 111, in expect_loop
    incoming = spawn.read_nonblocking(spawn.maxread, timeout)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/pty_spawn.py", line 509, in read_nonblocking
    raise TIMEOUT('Timeout exceeded.')
pexpect.exceptions.TIMEOUT: Timeout exceeded.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/pi/tmp/RIOT/tests/bench_xtimer/tests/01-run.py", line 22, in <module>
    sys.exit(run(testfunc))
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/__init__.py", line 27, in run
    logfile=sys.stdout if echo else None)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 56, in setup_child
    sync_child(child)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 79, in sync_child
    _test_utils_interactive_sync(child, modules)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/spawn.py", line 86, in _test_utils_interactive_sync
    utils.test_utils_interactive_sync(child, retries=retries, delay=delay)
  File "/home/pi/tmp/RIOT/dist/pythonlibs/testrunner/utils.py", line 24, in test_utils_interactive_sync
    child.expect_exact('READY', timeout=0)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/spawnbase.py", line 418, in expect_exact
    return exp.expect_loop(timeout)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 119, in expect_loop
    return self.timeout(e)
  File "/usr/local/lib/python3.7/dist-packages/pexpect/expect.py", line 82, in timeout
    raise TIMEOUT(msg)
pexpect.exceptions.TIMEOUT: Timeout exceeded.
<pexpect.pty_spawn.spawn object at 0x766e2030>
command: /usr/bin/make
args: [b'/usr/bin/make', b'cleanterm']
buffer (last 100 chars): " JSON capabilities\r\nConnect to serial port /dev/ttyACM0\r\nWelcome to pyterm!\r\nType '/exit' to exit.\r\n"
before (last 100 chars): " JSON capabilities\r\nConnect to serial port /dev/ttyACM0\r\nWelcome to pyterm!\r\nType '/exit' to exit.\r\n"
after: <class 'pexpect.exceptions.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: False
pid: 6202
child_fd: 5
closed: False
timeout: 10
delimiter: <class 'pexpect.exceptions.EOF'>
logfile: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='UTF-8'>
logfile_read: None
logfile_send: None
maxread: 2000
ignorecase: False
searchwindowsize: None
delaybeforesend: 0.05
delayafterclose: 0.1
delayafterterminate: 0.1
searcher: searcher_string:
    0: 'READY'
make: *** [/home/pi/tmp/RIOT/tests/bench_xtimer/../../Makefile.include:704: test] Error 1

a different arduino-mega2560

                     set() one    51000 / 1000 = 51
                  remove() one     8632 / 1000 = 8
          set() + remove() one    59384 / 1000 = 59
  set() many increasing target    25484 / 100 = 254
               re-set()  first   180588 / 1000 = 180
               re-set() middle   506564 / 1000 = 506
               re-set()   last   644888 / 1000 = 644
       remove() + set()  first   304344 / 1000 = 304
       remove() + set() middle   624932 / 1000 = 624
       remove() + set()   last   739644 / 1000 = 739
      remove() many decreasing     5240 / 100 = 52
                  xtimer_now()     6820 / 1000 = 6
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    51000 / 1000 = 51
                  remove() one     8636 / 1000 = 8
          set() + remove() one    59420 / 1000 = 59
  set() many increasing target    25480 / 100 = 254
               re-set()  first   180600 / 1000 = 180
               re-set() middle   506572 / 1000 = 506
               re-set()   last   644924 / 1000 = 644
       remove() + set()  first   304360 / 1000 = 304
       remove() + set() middle   624976 / 1000 = 624
       remove() + set()   last   739680 / 1000 = 739
      remove() many decreasing     5240 / 100 = 52
                  xtimer_now()     6816 / 1000 = 6
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    51000 / 1000 = 51
                  remove() one     8632 / 1000 = 8
          set() + remove() one    59416 / 1000 = 59
  set() many increasing target    25484 / 100 = 254
               re-set()  first   180604 / 1000 = 180
               re-set() middle   506568 / 1000 = 506
               re-set()   last   644888 / 1000 = 644
       remove() + set()  first   304352 / 1000 = 304
       remove() + set() middle   624936 / 1000 = 624
       remove() + set()   last   739644 / 1000 = 739
      remove() many decreasing     5236 / 100 = 52
                  xtimer_now()     6820 / 1000 = 6
done.

saml10-xpro

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    31501 / 1000 = 31
                  remove() one     5259 / 1000 = 5
          set() + remove() one    36571 / 1000 = 36
  set() many increasing target     5606 / 100 = 56
               re-set()  first    93380 / 1000 = 93
               re-set() middle   162932 / 1000 = 162
               re-set()   last   217258 / 1000 = 217
       remove() + set()  first   164314 / 1000 = 164
       remove() + set() middle   234103 / 1000 = 234
       remove() + set()   last   284320 / 1000 = 284
      remove() many decreasing     3601 / 100 = 36
                  xtimer_now()     4505 / 1000 = 4
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    31501 / 1000 = 31
                  remove() one     5259 / 1000 = 5
          set() + remove() one    36570 / 1000 = 36
  set() many increasing target     5606 / 100 = 56
               re-set()  first    93381 / 1000 = 93
               re-set() middle   162932 / 1000 = 162
               re-set()   last   217258 / 1000 = 217
       remove() + set()  first   164313 / 1000 = 164
       remove() + set() middle   234103 / 1000 = 234
       remove() + set()   last   284321 / 1000 = 284
      remove() many decreasing     3601 / 100 = 36
                  xtimer_now()     4505 / 1000 = 4
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    31501 / 1000 = 31
                  remove() one     5259 / 1000 = 5
          set() + remove() one    36571 / 1000 = 36
  set() many increasing target     5606 / 100 = 56
               re-set()  first    93381 / 1000 = 93
               re-set() middle   162932 / 1000 = 162
               re-set()   last   217259 / 1000 = 217
       remove() + set()  first   164314 / 1000 = 164
       remove() + set() middle   234102 / 1000 = 234
       remove() + set()   last   284321 / 1000 = 284
      remove() many decreasing     3600 / 100 = 36
                  xtimer_now()     4505 / 1000 = 4
done.

esp32-wroom-32

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    11958 / 1000 = 11
                  remove() one     1503 / 1000 = 1
          set() + remove() one    12793 / 1000 = 12
  set() many increasing target    79217 / 1000 = 79
               re-set()  first   157786 / 1000 = 157
               re-set() middle   308986 / 1000 = 308
               re-set()   last   454674 / 1000 = 454
       remove() + set()  first   311153 / 1000 = 311
       remove() + set() middle   462556 / 1000 = 462
       remove() + set()   last   606031 / 1000 = 606
      remove() many decreasing    76324 / 1000 = 76
                  xtimer_now()      676 / 1000 = 0
done.

xtimer benchmark application.

                     set() one    11957 / 1000 = 11
                  remove() one     1503 / 1000 = 1
          set() + remove() one    12792 / 1000 = 12
  set() many increasing target    79218 / 1000 = 79
               re-set()  first   157786 / 1000 = 157
               re-set() middle   308986 / 1000 = 308
               re-set()   last   454674 / 1000 = 454
       remove() + set()  first   311154 / 1000 = 311
       remove() + set() middle   462556 / 1000 = 462
       remove() + set()   last   606032 / 1000 = 606
      remove() many decreasing    76325 / 1000 = 76
                  xtimer_now()      675 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one    11957 / 1000 = 11
                  remove() one     1503 / 1000 = 1
          set() + remove() one    12792 / 1000 = 12
  set() many increasing target    79218 / 1000 = 79
               re-set()  first   157787 / 1000 = 157
               re-set() middle   308986 / 1000 = 308
               re-set()   last   454674 / 1000 = 454
       remove() + set()  first   311154 / 1000 = 311
       remove() + set() middle   462557 / 1000 = 462
       remove() + set()   last   606030 / 1000 = 606
      remove() many decreasing    76325 / 1000 = 76
                  xtimer_now()      675 / 1000 = 0
done.

arduino-due

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     6225 / 1000 = 6
                  remove() one     1263 / 1000 = 1
          set() + remove() one     7560 / 1000 = 7
  set() many increasing target   116853 / 1000 = 116
               re-set()  first   168542 / 1000 = 168
               re-set() middle   364590 / 1000 = 364
               re-set()   last   551581 / 1000 = 551
       remove() + set()  first   333425 / 1000 = 333
       remove() + set() middle   529418 / 1000 = 529
       remove() + set()   last   713332 / 1000 = 713
      remove() many decreasing    81464 / 1000 = 81
                  xtimer_now()      441 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     6225 / 1000 = 6
                  remove() one     1263 / 1000 = 1
          set() + remove() one     7560 / 1000 = 7
  set() many increasing target   116854 / 1000 = 116
               re-set()  first   168542 / 1000 = 168
               re-set() middle   364590 / 1000 = 364
               re-set()   last   551581 / 1000 = 551
       remove() + set()  first   333425 / 1000 = 333
       remove() + set() middle   529418 / 1000 = 529
       remove() + set()   last   713332 / 1000 = 713
      remove() many decreasing    81465 / 1000 = 81
                  xtimer_now()      440 / 1000 = 0
done.

main(): This is RIOT! (Version: 2020.01-devel-1378-g61290-test1)
xtimer benchmark application.

                     set() one     6225 / 1000 = 6
                  remove() one     1263 / 1000 = 1
          set() + remove() one     7560 / 1000 = 7
  set() many increasing target   116854 / 1000 = 116
               re-set()  first   168542 / 1000 = 168
               re-set() middle   364590 / 1000 = 364
               re-set()   last   551581 / 1000 = 551
       remove() + set()  first   333425 / 1000 = 333
       remove() + set() middle   529418 / 1000 = 529
       remove() + set()   last   713332 / 1000 = 713
      remove() many decreasing    81465 / 1000 = 81
                  xtimer_now()      441 / 1000 = 0
done.

[MrKevinWeiss]

@kaspar030 can you just look over the results so they make sense to you and maybe note why the bold ones could be failing (I am willing to accept it is my setup as an arduino-mega2560 passed but a different one was failing).

[kaspar030]

@kaspar030 can you just look over the results so they make sense to you and maybe note why the bold ones could be failing (I am willing to accept it is my setup as an arduino-mega2560 passed but a different one was failing).

I agree on the arduino. My local one works fine.

• frdm-kw41z doesn't seem to even start the test. Maybe check manually if the board crashes early on? Is it very RAM constrained?

• arduino-mkrzero seems to be flashed with a shell application, I guess flashing failed. Maybe retry?

• remote-revb seems to be reeeally slow, the first timers trigger. I've increased the base time from 10s to 100s. Could you retry?

The others look fine!

[kaspar030]

One thing that should be added to the readme is a short description on how to interpret the values.

I've added some description.

Looking at the results of a first try it looks like at least for set() one remove() one set() + remove() one and xtimer_now() need more repetitions to give a more precise calculated end result.

Do you think? The numbers are very stable, more iterations don't change them. Just the last printout is truncated. I'd rather keep it as is to have fast running tests. For accurate numbers, we can always manually use the numbers before division.

I didn't at all look at how reasonable the benches are. But even executing all basic operations a few times gives us something as a starting point for comparison and it can be easily extended later.

Yup. They already show some things, e.g., if the implicit "remove() on set()" is properly optimized, or that msp430 seems to be very slow in the list operations.

[MichelRottleuthner]

I've added some description.

Looks very good!

(...) Just the last printout is truncated. I'd rather keep it as is to have fast running tests. For accurate numbers, we can always manually use the numbers before division.

Ok.

You said the remote just seems to be reeeally slow, but the test shouldn't create a kernel panic in these cases, right? Apart from that I'm fine with merging this PR. See below for small typos etc..

[kaspar030]

You said the remote just seems to be reeeally slow, but the test shouldn't create a kernel panic in these cases, right?

Well, all timers are set at BASE + (N * SPREAD). BASE was at 10 sec. Between each test, an assert() checks if any timer has triggered, which they are not supposed to. The remote took longer than 10s, so the assertion failed after remove() + set() middle, causing the panic. I've increased BASE to 100s now.

[kaspar030]

See below for small typos etc..

addressed!

[MichelRottleuthner]

I don't have access to a remote right now but tomorrow we can re-test. After confirmed working we should go ahead and merge this. Feel free to squash already.

[fjmolinas]

Test output for remote-revb, for some reason it gets stuck if running make flash-only test so I ran make flash-only term I'll debug that tomorrow, but at least the results are in this way.

START
main(): This is RIOT! (Version: 2020.01-devel-1377-gd89de-pr-12942)
xtimer benchmark application.

                     set() one    27917 / 1000 = 27
                  remove() one     4569 / 1000 = 4
          set() + remove() one    32318 / 1000 = 32
  set() many increasing target   617251 / 1000 = 617
               re-set()  first  1073715 / 1000 = 1073
               re-set() middle  2207938 / 1000 = 2207
               re-set()   last  3077303 / 1000 = 3077
       remove() + set()  first  2121391 / 1000 = 2121
       remove() + set() middle  3248776 / 1000 = 3248
       remove() + set()   last  4021561 / 1000 = 4021
      remove() many decreasing   473376 / 1000 = 473
                  xtimer_now()     5756 / 1000 = 5
done.

[fjmolinas]

Test output for remote-revb, for some reason it gets stuck if running make flash-only test so I ran make flash-only term I'll debug that tomorrow, but at least the results are in this way.

I know why, this PR doesn't have the change so that the board is not reset after term is opened.

[kaspar030]

After confirmed working we should go ahead and merge this.

remote-revb is working. I guess this just needs an ACK.

[MrKevinWeiss]

Test output for remote-revb, for some reason it gets stuck if running make flash-only test so I ran make flash-only term I'll debug that tomorrow, but at least the results are in this way.

Maybe because test tries to reset which changes the baud of the connection?

[fjmolinas]

Nice one!