tests/bench_timers: A comprehensive benchmark for periph_timer #8531
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
jnohlgard
added
Area: tests
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
3 times, most recently
from
1adb576
to
63ba28f
Compare
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
2 times, most recently
from
cefa238
to
c959c37
Compare
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
5 times, most recently
from
e0e34fe
to
bec4d17
Compare
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
2 times, most recently
from
137c001
to
a925203
Compare
jnohlgard
changed the title
|
This is ready for review now. |
jnohlgard
added
the
State: waiting for other PR
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
from
a0999d0
to
6827f10
Compare
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
from
9d21da4
to
9b840d3
Compare
|
@gebart can you squash? I might have time to review this one this evening on Hack'n'ACK. |
|
I won't be able to do it tonight. You may squash and push to my branch if you like |
jnohlgard
changed the title
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
from
9b840d3
to
857eaf4
Compare
|
@kYc0o rebased ;) |
|
on macOS the benchmark seems to hang, which isn't that surprising bc I regularly have problems with timers on RIOT native and macOS. Output so far, but nothing happening after long wait: no table with results, or is this expected? |
|
tested on PhyNode, works! Output: sums and some values are negative, though - overflow or expected? |
|
The negative values means that the timer fired too early and is an indication of an underlying timer problem. However, it may also be caused by the test runtime overhead being estimated too high (see the output you get when the application is starting) |
|
@gebart thanks for clearing things up! |
smlng
approved these changes
May 30, 2018
but then this problem is board specific and related to timer configuration there in, hence does not block this PR but rather shows the value and usefulness of this benchmark 😄 |
|
murdock is not completely happy, please fix and amend/squash directly |
|
Probably due to the nucleo board renames. Will fix. |
|
mhm, benchmark hangs on remote-revb. I had to use Output is: Note the warning regarding the cb. |
|
and here the output for Arduino-mega2560, gets stuck too - here I had to change the frequency to 250kHz for both timers |
|
oops, sorry Arduino didn't get stuck - just took some time. Here the stats output: |
|
The cb warning comes up when the callback is called on the reference timer, which should not happen because we don't set a target for it. |
|
Apparently nucleo-f031k6 hasn't enough memory for this, @gebart can you add it to the blacklist to finally merge this? I think it's ready. |
aabadie
requested changes
Jun 4, 2018
tests/bench_timers/Makefile
Outdated
| # CFLAGS configuration to build properly | ||
| SINGLE_TIMER_BOARDS = \ | ||
| native \ | ||
| nucleo32-f031 \ |
There was a problem hiding this comment.
This PR still uses the old nucleo board names. Here it should be nucleo-f031k8 nucleo-f031k6 and below nucleo-f042k8 nucleo-f042k6
tests/bench_timers/Makefile
Outdated
| # with the default settings of TEST_MIN and TEST_MAX, so DETAILED_STATS will be | ||
| # disabled by default for these boards unless explicitly enabled | ||
| SMALL_RAM_BOARDS = \ | ||
| nucleo32-f031 \ |
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
from
857eaf4
to
eee7d32
Compare
This test is intended to collect statistics about the runtime delays in the periph_timer implementation. This tool is mainly intended to detect problems in the low level driver implementation which can be difficult to detect from higher level systems such as xtimer.
jnohlgard
force-pushed
the
pr/periph-timer-stats
branch
from
eee7d32
to
0541940
Compare
|
@aabadie Corrected the names of the nucleo boards |
aabadie
approved these changes
Jun 8, 2018
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Depends on #8733
(Excerpts from the README)
Benchmark test for periph_timer
This test is intended to collect statistics about the runtime delays in the
periph_timer implementation. This tool is mainly intended to detect problems in
the low level driver implementation which can be difficult to detect from
higher level systems such as xtimer.
Test outline
The basic idea of the test is to generate a wide variety of calls to the
periph/timer API, in order to detect problems with the software implementation.
The test consists of a single thread of execution which will set random
timeouts on a periph_timer device. A reference timer is used to measure the
time it takes until the callback is called. The difference between the expected
time and the measured time is computed, and the mean and variance of the
recorded values are calculated. The results are printed as a table on stdout
every 30 seconds. All of the test scenarios used in this application are
based on experience from real world bugs encountered during the development of
RIOT and other systems.
API functions tested
Both timer_set and timer_set_absolute calls are mixed in a random order, to
ensure that both functions are working correctly.
Rescheduling
Some bugs may occur only when the application attempts to replace an already
set timer by calling timer_set again while the timer is running. This is dubbed
"resched" in this application. The application will issue rescheduling timer
calls in the normal operation of the test to catch this class of problems.
Setting stopped timers
Another class of bugs is the kind where a timer is not behaving correctly if it
was stopped before setting a timer target. The timer should set the new target,
but not begin counting towards the target until timer_start is called. This is
covered by this application under the "stopped" category of test inputs.
Avoiding phase lock
The CPU time used for generation and setting of the next timer target in
software is approximately constant across iterations. When the application flow
is driven by the timer under test, via a mutex which is unlocked from the timer
callback, the application will be "phase locked" to the timer under test. This
peculiarity may hide certain implementation race conditions which only occur at
specific phases of the timer ticks. In the test application, this problem is
avoided by inserting random CPU delay loops at key locations:
Estimating benchmark CPU overhead
An estimation of the overhead resulting from the CPU processing delays inside
the benchmarking code is performed during benchmark initialization. The
estimation algorithm attempts to perform the exact same actions that the real
benchmark will perform, but without setting any timers. The measured delay is
assumed to originate in the benchmark code and will be subtracted when
computing the difference between expected and actual values. A warning is
printed when the variance of the estimated CPU overhead is too high, this can
be a sign that some other process is running on the CPU and disrupting the
estimation, or a sign of serious problems inside the timer_read function.
Results
When the test has run for a certain amount of time, the current results will be
presented as a table on stdout. To assist with finding the source of any
discrepancies, the results are split according to three parameters:
Interpreting timer_read statistics
A separate table is displayed for statistics on timer_read. This table compares
the expected timer under test time after a timer has triggered, against the
actual reported value from
timer_read(TIM_TEST_DEV). A positive value meansthat the TUT time has passed the timer target time. A negative value means
that, according to the timer under test, the alarm target time has not yet been
reached, even though the timer callback has been executed.
Example output
Below is a short sample of a test of a 32768 Hz timer with a 1 MHz reference:
...
The statistics above show that the timer implementation introduces a small
delay on short timers. Note however that it is not clear whether this delay is
in timer_set, or timer_read, but the combined effect of all error sources make
the timer overshoot its target by on average 17 microseconds. The difference
between min and max is close to the expected difference of approximately
1/32768 s = 30.51 µs. The lower min and mean for the longer timer intervals are
most likely caused by a drift between the 1 MHz clock and the 32.768 kHz clocks
inside the CPU, and is expected when using two separate clock sources for the
timers being compared.
Below is a short sample of a test where there is something wrong with the timer
implementation, again a 32768 Hz timer tested with a 1 MHz reference:
We can see that the variance, the maximum error, and the mean are very large.
This particular timer implementation needs some work on its timer_set_absolute
implementation.