xtimer: weird behavior of tests/xtimer_drift, bug?

[haukepetersen]

I am not sure if this is a bug in the xtimer, the xtimer_drift test but it is very likely. I got this broken behavior when running the xtimer_drift test on nrf51 base boards (e.g. airfy-beacon, nrf51dongle):

2016-03-18 10:36:51,856 - INFO # now=15.397038 (0 hours 0 min), diff=0
2016-03-18 10:36:52,861 - INFO # now=16.397038 (0 hours 0 min), diff=0
2016-03-18 10:36:53,856 - INFO # now=17.397038 (0 hours 0 min), diff=0 // so far good
2016-03-18 10:37:28,411 - INFO # now=18.397038 (0 hours 0 min), diff=0 // jump of 35 sec
2016-03-18 10:37:46,190 - INFO # now=19.397038 (0 hours 0 min), diff=0 // jump of 18 sec
2016-03-18 10:37:47,190 - INFO # now=20.397038 (0 hours 0 min), diff=0
2016-03-18 10:37:48,190 - INFO # now=21.397038 (0 hours 0 min), diff=0
2016-03-18 10:37:49,190 - INFO # now=22.397038 (0 hours 0 min), diff=0
2016-03-18 10:37:50,191 - INFO # now=23.397038 (0 hours 0 min), diff=0
2016-03-18 10:38:07,966 - INFO # now=24.397038 (0 hours 0 min), diff=0 // jump of 17 sec
2016-03-18 10:38:08,966 - INFO # now=25.397038 (0 hours 0 min), diff=0

or

2016-03-18 10:49:04,860 - INFO # now=102.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:05,860 - INFO # now=103.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:23,637 - INFO # now=104.098898 (0 hours 1 min), diff=0 // jump
2016-03-18 10:49:24,637 - INFO # now=105.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:25,637 - INFO # now=106.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:26,637 - INFO # now=107.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:27,637 - INFO # now=108.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:28,637 - INFO # now=109.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:29,637 - INFO # now=110.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:47,414 - INFO # now=111.098898 (0 hours 1 min), diff=0 // jump
2016-03-18 10:49:48,414 - INFO # now=112.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:49,414 - INFO # now=113.098898 (0 hours 1 min), diff=0
2016-03-18 10:49:50,414 - INFO # now=114.098898 (0 hours 1 min), diff=0

Those jumps appear on random intervals.

I am ~90% convinced, that this is not caused by the peripheral timer driver, as the exact code is also running on the nrf52dk, where this behavior does not appear. It rather seems to me, that the xtimer (or the test app) has some concurrency issue, which shows only at the clock speed of the nrf51 boards (16MHz), but not at the higher speed of the nrf52 board.

I actually found this when debugging the timer for the cc26x0 (#4675), where the test shows also very strange behavior...

[haukepetersen]

Just out of interest, I have been running this test on the same CPUs:

#define TIM_SPEED           (1000000ul) /* try to run with 1MHz */

#define STEP                (10000U)
#define SUM                 (500)

static volatile int busy = 1;
static volatile int count = 0;

static void cb(void *arg, int chan)
{
    ++count;
    if (count == SUM) {
        count = 0;
        busy = 0;
    }

    timer_set(TIMER_DEV(0), 0, STEP);
}

int main(void)
{
    timer_init(TIMER_DEV(0), TIM_SPEED, cb, NULL);
    timer_set(TIMER_DEV(0), 0, STEP);

    while (1) {
        while (busy) {}
        busy = 1;
        puts("PING");
    }

    return 0;
}

With this, I get the PING message printed out reliable every 5s, for about half an hour now, without any pings skipped. So the issues seems only to appear when actually multiplexing timers?!

[jnohlgard]

I guess a missed deadline. Try increasing XTIMER_BACKOFF and XTIMER_OVERHEAD (or whatever the constants in xtimer.h are called, I'm too lazy to look them up right now)

[haukepetersen]

already played with XTIMER_SHIFT_ON_COMPARE, same behavior for different values...

[haukepetersen]

same for XTIMER_BACKOFF

[jnohlgard]

@haukepetersen is that the platform with 16 MHz timer fixed frequency?

what values did you test?

[kaspar030]

@haukepetersen Is the underlying timer 32bit wide?

[haukepetersen]

EDIT:
24-bit timer with a system clock of 16MHz

[haukepetersen]

xtimer config is:

#define XTIMER                      (0)
#define XTIMER_CHAN                 (0)
#define XTIMER_MASK                 (0xff000000)
#define XTIMER_SHIFT_ON_COMPARE     (2)
#define XTIMER_BACKOFF              (40)

[haukepetersen]

and the (well functioning) nrf52dk runs at 48MHz with a 32-bit timer configuration (with xtimer default config).

[jnohlgard]

The mask is wrong
On Mar 21, 2016 10:54 AM, "Hauke Petersen" notifications@github.com wrote:

xtimer config is:

#define XTIMER (0)
#define XTIMER_CHAN (0)
#define XTIMER_MASK (0xff000000)
#define XTIMER_SHIFT_ON_COMPARE (2)
#define XTIMER_BACKOFF (40)

—
You are receiving this because you commented.
Reply to this email directly or view it on GitHub
#5103 (comment)

[haukepetersen]

you mean it should be 0xffffff00?

How about we spend some more documentation on the xtimer configuration values? And possibly put them into one easy to find block in the xtimer.h?

[kaspar030]

you mean it should be 0xffffff00?

No, he answered before you edited your post stating the timer was 16bit.