tests/xtimer_usleep_short: add expected runtime #9037

Josar · 2018-04-27T10:18:16Z

In some cases the sleep time is very long compared to the expected sleep time.
This pr adds a functionality to test against the expected sleep time.
If the sleep time is far of the expected sleep time an error is thrown.

aabadie

I have a few comments regarding your changes but the general idea sounds valid.

aabadie · 2018-04-27T11:30:35Z

tests/xtimer_usleep_short/tests/01-run.py

+    runtime = int(child.match.group(1))
+    expected = int(child.match.group(2))
+
+    if runtime < expected*0.9 or runtime > expected*1.1:


This should be tested in the test application not by the pexpect script

aabadie · 2018-04-27T11:31:00Z

tests/xtimer_usleep_short/main.c

 int main(void)
 {
    xtimer_sleep(3);
    printf("This test will call xtimer_usleep for values from %d down to %d\n",
            TEST_USLEEP_MAX, TEST_USLEEP_MIN);

+    uint32_t start, sleeping_time=0;


put spaces around = operator

aabadie · 2018-04-27T11:33:09Z

tests/xtimer_usleep_short/main.c

@@ -22,17 +22,25 @@
 #define TEST_USLEEP_MIN (0)
 #define TEST_USLEEP_MAX (500)

+#define TEST_TIME (125250)


How did you determine this value ?

http://www.wolframalpha.com/input/?i=500%2B499%2B498%2B+...+%2B+1

Then threre's direct relationship with TEST_USLEEP_MAX and TEST_USLEEP_MIN, so I think it's useless.

I don't understand what you mean, but changed the value to be calculated.

aabadie · 2018-04-27T13:10:48Z

This looks more to what I had in mind now. I tested on arduino-zero, microbit and an stm32l4 based board. It only works on the latter, the other ones exceeds the expected test time (even with 20% error tolerance).
What hardware are you using @Josar ?

Josar · 2018-04-27T13:13:50Z

I just add some improvements to the xtimer while testing the jiminy board.
Maybe the tollerance has to be adapted or the changes from #8990 have to be applied.
It is still wip but i change the test according to related errors which i stumble upon.

cladmi · 2018-05-03T13:21:25Z

There is an example here with a configurable margin instead of doing *0.9
I prefer saying it's that margin more than percentage.

https://github.com/RIOT-OS/RIOT/blob/master/tests/posix_semaphore/main.c#L241

I need to add other cases because the current posix_semaphore margin is not enough on wsn430, so a way of setting this margin on a per board/archi basis will also be required.

smlng · 2018-05-04T21:04:29Z

I would make the check in the python test script instead, i.e. just print actual an expected sleep timings and then make any check/verification in the test later on. That makes it more flexible.

Josar · 2018-05-07T10:18:30Z

@aabadie

This should be tested in the test application not by the pexpect script

@smlng

check in the python test script instead,

Could you please discuss this and come to a conclusion!

Josar · 2018-05-09T14:56:11Z

Added reports for each sleep, changed the test to be done in python and made the deviation configurable.

aabadie · 2018-05-09T15:33:13Z

changed the test to be done in python and made the deviation configurable.

I'm still not in favour of having the time checks done by the python script. The python script is here to verify the output (and in general it checks that SUCCESS is displayed).
See xtimer_now64_continuity, xtimer_periodic_wakeup for example. I admit that checks are performed in the Python script for xtimer_usleep but I don't like this as it's quite difficult to follow (the logic is scattered in 2 different implementations and one has to play with regexp to retrieve the measures. Maybe @smlng and @cladmi can also give their thoughts about that.

…untime

Josar · 2018-05-23T20:27:29Z

@smlng and @cladmi any thoughts?

smlng · 2018-05-24T07:02:43Z

I'm still (and in general) in favour of making any checks and verifications in the python script. Thus let the C test program be simple with limited output which also reduces binary size. I also think its easier to make maths for verification in Python than in C.

…ected runtime

Josar · 2018-05-24T09:23:26Z

As my objective was to highlight the times when the timer delay is too long, thus getting a hint when the timer lags. So i had to change the test to test it in the c code as the Python print does not print sequentially.

…add expected runtime

Josar · 2018-05-29T11:38:00Z

@aabadie @smlng any thoughts about this?

aabadie

This is much better now. There's an unused variable in the python script (see below).
Didn't test.

aabadie · 2018-05-29T11:41:17Z

tests/xtimer_usleep_short/tests/01-run.py

@@ -10,21 +10,31 @@
 import sys
 import pexpect

+DEVIATION = .1


This is unused

…short: add expected runtime

smlng

having some output on the expected and actual sleep time might be good, but I'm totally against doing any checks within the C code but suggest to put any such evaluation into the python script which can parse the output.

smlng · 2018-05-29T12:23:42Z

tests/xtimer_usleep_short/main.c

        xtimer_usleep(i);
+        uint32_t slept = xtimer_now_usec() - start;


making two xtimer_now calls is not necessary when saving the last (from previous iteration) and also assuming that all the other calls cost only marginal time compared to the sleep. xtimer_now is rather expensive, anyways.

The print of "going to sleep %d us\n", if i am not mistaken, needs:
20 * 10 * 1000/9600Buad = 20,8 ms

Then the second print will also need some time.
This test goes from 500ms down to 1ms. So is the time marginal or not?

I am also in favor of doing two times xtimer_now it helps timing tests correctly, printf takes time.

smlng · 2018-05-29T12:25:57Z

tests/xtimer_usleep_short/main.c

+        uint32_t slept = xtimer_now_usec() - start;
+        printf("Slept for      %" PRIu32 " us\n", slept);
+
+        if (slept < (unsigned int)i) {


as already written several times: I'm against making any checks within in the C-code and would rather do this in the (python) test script. We should keep the C test code simple avoiding unnecessary maths operations and also increasing the code size with such addition code and output. Its already the case that many tests don't fit on all boards just because of excessive output.

Maybe there is a way to get the python script print sequentially?

The idea behind this is to make it obvious if the XTIMER_BACKOFF border or something else causes the error.
Thus the print has to be exactly after the sleep, not 5 sleeps after it.

Adding the slept time is neccessary to get a hint of errors like this #9211

There are boards that we cannot reboot with make reset so cannot run the automated python tests on them. If the test can alone say it is working I find it better.
All the tests based on embunit are doing asserts on the node and python only checks for [SUCCESS] already.

Also, here they are not math operations, they are simple integer comparison and addition.

cladmi · 2018-06-01T17:24:53Z

tests/xtimer_usleep_short/main.c

        xtimer_usleep(i);
+        uint32_t slept = xtimer_now_usec() - start;
+        printf("Slept for      %" PRIu32 " us\n", slept);


I would prefer a single line for this with also the printed interval.
Now it is actually quite long also

going to sleep 12 us Slept for 35 us Timeout longer than expected margin.

Maybe a message like:

ERROR: Slept for 35 us not in range [12, 32] us. OK: Slept for 15 us in range [12, 32] us.

cladmi · 2018-06-01T17:25:36Z

tests/xtimer_usleep_short/tests/01-run.py


-    i = 500
+    i = sleep_max - sleep_min

    while (i >= 0):


for delay in range(sleep_max, sleep_min -1, -1): It is python not C :)
It is time to fix the previous code.

cladmi

I am also in favor of testing in C code, that what we have been doing for the last months.

I have some remarks inline:

some problems were already there before but it would be good to fix them
have more information in the firmware output but be more concise
python test script reliability.

cladmi · 2018-06-01T17:26:55Z

tests/xtimer_usleep_short/tests/01-run.py

@@ -12,19 +12,27 @@


 def testfunc(child):
-    child.expect(u"This test will call xtimer_usleep for values from \\d+ down to \\d+\r\n")
+    child.expect(u"This test will call xtimer_usleep for values from (\d+) down to (\d+)")


Now that we are using python3 none of the string required the u in front anymore.

cladmi · 2018-06-01T17:27:58Z

tests/xtimer_usleep_short/tests/01-run.py


    while (i >= 0):
        try:
-            child.expect(u"going to sleep \\d+ usecs...\r\n", timeout=3)
+            child.expect(u"going to sleep (\d+) us", timeout=3)


Here you can replace (\d+) by the value of i or if renamed delay. It would prevent issue when testing with text taken from node before make reset.

cladmi · 2018-06-01T17:28:28Z

tests/xtimer_usleep_short/tests/01-run.py


    while (i >= 0):
        try:
-            child.expect(u"going to sleep \\d+ usecs...\r\n", timeout=3)
+            child.expect(u"going to sleep (\d+) us", timeout=3)
+            sleep_exp = int(child.match.group(1))


sleep_exp would not be necessary as it would have matched against the value of i.

cladmi · 2018-06-01T17:29:05Z

tests/xtimer_usleep_short/tests/01-run.py

        except pexpect.TIMEOUT:
-            print("xtimer stuck when trying to sleep %d usecs" % (i+1))
+            print("xtimer stuck when trying to sleep %d us" % (sleep_exp))
            print("[FAILED]")
            break


This break should be an exit(1), not print failed then success…
It's a good time to fix it.

cladmi · 2018-06-01T17:31:26Z

tests/xtimer_usleep_short/main.c

+#else
+#define TEST_XTIMER_USLEEP_SHORT_SLEEP_MARGIN_US (20)
+#endif /* BOARD_NATIVE */
+
 int main(void)
 {
    xtimer_sleep(3);


This xtimer_sleep(3) break my tests when doing make flash test on some boards as the test could match the child.expect(u"This test will call xtimer_usleep for values from (\d+) down to (\d+)") line before make reset is done.

Any suggestions on how to fix this? Increase the sleep?

cladmi · 2018-06-01T17:32:27Z

tests/xtimer_usleep_short/main.c

+/* native can sometime take more time to respond as it is not real time */
+#define TEST_XTIMER_USLEEP_SHORT_SLEEP_MARGIN_US (1000)
+#else
+#define TEST_XTIMER_USLEEP_SHORT_SLEEP_MARGIN_US (20)


The margin may not be enough as mentioned in #8990.
I need to do the xtimer_configure to check if it helps getting in the margin.

cladmi · 2018-06-01T17:35:18Z

tests/xtimer_usleep_short/main.c


    for (int i = TEST_USLEEP_MAX; i >= TEST_USLEEP_MIN; i--) {
-        printf("going to sleep %d usecs...\n", i);
+        printf("going to sleep %d us\n", i);


Inconsistent with first letter lowercase.

cladmi · 2018-06-01T17:39:34Z

I can do a PR on your branch if you want for the updating script changes (on monday though).

Josar · 2018-06-04T10:25:43Z

@cladmi feel free to contribute.

Josar · 2018-06-07T15:07:28Z

@aabadie @smlng @cladmi tried to address all requested changes. However, the probelm with testing in C-Code or not is still not settled.

…usleep_short: add expected runtime

Josar · 2018-07-03T15:59:08Z

@aabadie @smlng @cladmi did you find a agreement for the testing?

smlng · 2018-07-04T06:32:00Z

I'm still against having any evaluation in the (test) application, specifically this delay margin. IMHO its up to the human tester or a high layer test framework to decide whether the test passes or fails according to the values reported/printed. It might also be that we only want to evaluate if a PR improves or degrades the sleep time precision, and don't want to look that much into the actual margin.

Josar · 2018-09-18T14:21:22Z

So @smlng you and @aabadie do not agree. Is there a possibility that you work out a solution?

smlng · 2018-09-19T06:24:45Z

I'll dismiss my review for now, but I want to stress the point that we should keep the code of the test application as simple as possible. And to me that means just print the values needed to make a proper decision but leave that to the tester or auto test framework, i.e. if the test passes or not.

But it seams that is a more general discussion and needs to be resolved within a larger group.

Don't like it but won't block it either.

Josar · 2018-10-18T12:40:59Z

@cladmi @aabadie any further remarks?

stale · 2019-08-10T04:08:14Z

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

tests/xtimer_usleep_short: add expected runtime

9af59b4

aabadie requested changes Apr 27, 2018

View reviewed changes

Josar added 2 commits April 27, 2018 14:18

fixup! tests/xtimer_usleep_short: add expected runtime

6550535

fixup! fixup! tests/xtimer_usleep_short: add expected runtime

c4e543c

fixup! fixup! fixup! tests/xtimer_usleep_short: add expected runtime

dfcf9e9

Josar mentioned this pull request May 15, 2018

xtimer_core: reduce idle time #8990

Closed

fixup! fixup! fixup! fixup! tests/xtimer_usleep_short: add expected r…

cb23ea4

…untime

fixup! fixup! fixup! fixup! fixup! tests/xtimer_usleep_short: add exp…

6a4b963

…ected runtime

Josar force-pushed the pr/xtimer_usleept_short branch from fc751f4 to d4cc724 Compare May 24, 2018 09:25

fixup! fixup! fixup! fixup! fixup! fixup! tests/xtimer_usleep_short: …

fd6a9c6

…add expected runtime

Josar force-pushed the pr/xtimer_usleept_short branch from d4cc724 to fd6a9c6 Compare May 24, 2018 09:27

Josar mentioned this pull request May 28, 2018

xtimer: timer & target overflow, hang resolved. #9211

Merged

aabadie requested changes May 29, 2018

View reviewed changes

tests/xtimer_usleep_short/tests/01-run.py Outdated

@@ -10,21 +10,31 @@

import sys

import pexpect

DEVIATION = .1

Copy link

Contributor

aabadie May 29, 2018

Choose a reason for hiding this comment

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

This is unused

fixup! fixup! fixup! fixup! fixup! fixup! fixup! tests/xtimer_usleep_…

ec11938

…short: add expected runtime

smlng previously requested changes May 29, 2018

View reviewed changes

smlng added Discussion: contested The item of discussion was contested and removed CI: ready for build If set, CI server will compile all applications for all available boards for the labeled PR labels May 29, 2018

cladmi reviewed Jun 1, 2018

View reviewed changes

cladmi suggested changes Jun 1, 2018

View reviewed changes

Josar force-pushed the pr/xtimer_usleept_short branch 2 times, most recently from 4cb9371 to 3b621d8 Compare June 5, 2018 11:17

fixup! fixup! fixup! fixup! fixup! fixup! fixup! fixup! tests/xtimer_…

bfe9884

…usleep_short: add expected runtime

Josar force-pushed the pr/xtimer_usleept_short branch from 3b621d8 to bfe9884 Compare June 7, 2018 21:48

stale bot added the State: stale State: The issue / PR has no activity for >185 days label Aug 10, 2019

stale bot closed this Sep 10, 2019

		xtimer_usleep(i);
		uint32_t slept = xtimer_now_usec() - start;

tests/xtimer_usleep_short: add expected runtime #9037

tests/xtimer_usleep_short: add expected runtime #9037

Conversation

Josar commented Apr 27, 2018

aabadie left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aabadie Apr 27, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aabadie commented Apr 27, 2018

Josar commented Apr 27, 2018 • edited Loading

cladmi commented May 3, 2018

smlng commented May 4, 2018

Josar commented May 7, 2018

Josar commented May 9, 2018

aabadie commented May 9, 2018

Josar commented May 23, 2018

smlng commented May 24, 2018

Josar commented May 24, 2018

Josar commented May 29, 2018

aabadie left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

smlng left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cladmi Jun 1, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cladmi Jun 1, 2018 • edited Loading

Choose a reason for hiding this comment

cladmi left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cladmi commented Jun 1, 2018

Josar commented Jun 4, 2018

Josar commented Jun 7, 2018

Josar commented Jul 3, 2018 • edited Loading

smlng commented Jul 4, 2018

Josar commented Sep 18, 2018

smlng commented Sep 19, 2018

Josar commented Oct 18, 2018

stale bot commented Aug 10, 2019

aabadie Apr 27, 2018 •

edited

Loading

Josar commented Apr 27, 2018 •

edited

Loading

cladmi Jun 1, 2018 •

edited

Loading

cladmi Jun 1, 2018 •

edited

Loading

Josar commented Jul 3, 2018 •

edited

Loading