diff --git a/tests/xtimer_drift/README.md b/tests/xtimer_drift/README.md new file mode 100644 index 000000000..1673e1c93 --- /dev/null +++ b/tests/xtimer_drift/README.md @@ -0,0 +1,16 @@ +# xtimer_drift test application + +Make note of the PC clock when starting this test. Let it run for a while, and +compare the printed time against the expected time from the PC clock. The +difference is the RIOT timer drift, this is likely caused by either: + +- an inaccurate hardware timer, or +- bugs in the software (xtimer or periph/timer) + +This test will run a periodic timer every `TEST_INTERVAL` microseconds (`TEST_HZ`). +The current time will be printed once per second, along with the difference +between the actual and expected `xtimer_now` value. The first output variable +`drift`, represents the total offset since start between `xtimer_now` and the +expected time. The second output variable `jitter`, represents the difference +in drift from the last printout. Two other threads are also running only to +cause CPU load with extra interrupts and context switches. diff --git a/tests/xtimer_drift/main.c b/tests/xtimer_drift/main.c index f45ad7184..814800e57 100644 --- a/tests/xtimer_drift/main.c +++ b/tests/xtimer_drift/main.c @@ -1,4 +1,5 @@ /* + * Copyright (C) 2017 HAW Hamburg * Copyright (C) 2015 Kaspar Schleiser * Copyright (C) 2015 Eistec AB * 2013 INRIA @@ -19,6 +20,7 @@ * @author Oliver Hahm * @author Christian Mehlis * @author Joakim Nohlgård + * @author Sebastian Meiling * * @} */ @@ -29,6 +31,7 @@ #include "xtimer.h" #include "thread.h" #include "msg.h" +#include "log.h" /* We generate some context switching and IPC traffic by using multiple threads * and generate some xtimer load by scheduling several messages to be called at @@ -38,9 +41,10 @@ * TEST_MSG_RX_USLEEP is a tiny sleep inside the message reception thread to * cause extra context switches. */ -#define TEST_HZ (64LU) -#define TEST_INTERVAL (1000000LU / TEST_HZ) -#define TEST_MSG_RX_USLEEP (200LU) +#define TEST_HZ (64LU) +#define TEST_INTERVAL (1000000LU / TEST_HZ) +#define TEST_MSG_RX_USLEEP (200LU) +#define TEST_MSG_QUEUE_SIZE (4U) char slacker_stack1[THREAD_STACKSIZE_DEFAULT]; char slacker_stack2[THREAD_STACKSIZE_DEFAULT]; @@ -63,12 +67,11 @@ void *slacker_thread(void *arg) (void) arg; timex_t now; - printf("Starting thread %" PRIkernel_pid "\n", thread_getpid()); + LOG_DEBUG("run thread %" PRIkernel_pid "\n", thread_getpid()); - /* we need a queue if the second message arrives while the first is still processed */ - /* without a queue, the message would get lost */ - msg_t msgq[4]; - msg_init_queue(msgq, 4); + /* we need a queue if a 2nd message arrives while the first is processed */ + msg_t msgq[TEST_MSG_QUEUE_SIZE]; + msg_init_queue(msgq, TEST_MSG_QUEUE_SIZE); while (1) { msg_t m; @@ -87,35 +90,35 @@ void *slacker_thread(void *arg) void *worker_thread(void *arg) { (void) arg; + uint32_t loop_counter = 0; uint32_t start = 0; uint32_t last = 0; - printf("Starting thread %" PRIkernel_pid "\n", thread_getpid()); + LOG_DEBUG("run thread %" PRIkernel_pid "\n", thread_getpid()); while (1) { msg_t m; msg_receive(&m); + xtimer_ticks32_t ticks = xtimer_now(); uint32_t now = xtimer_usec_from_ticks(ticks); + if (start == 0) { start = now; last = start; - ++loop_counter; - continue; } - - uint32_t us, sec; - us = now % US_PER_SEC; - sec = now / US_PER_SEC; - if ((loop_counter % TEST_HZ) == 0) { + else if ((loop_counter % TEST_HZ) == 0) { + uint32_t us = now % US_PER_SEC; + uint32_t sec = now / US_PER_SEC; uint32_t expected = start + loop_counter * TEST_INTERVAL; int32_t drift = now - expected; expected = last + TEST_HZ * TEST_INTERVAL; int32_t jitter = now - expected; printf("now=%" PRIu32 ".%06" PRIu32 " (0x%08" PRIx32 " ticks), ", - sec, us, ticks.ticks32); - printf("drift=%" PRId32 " us, jitter=%" PRId32 " us\n", drift, jitter); + sec, us, ticks.ticks32); + printf("drift=%" PRId32 " us, jitter=%" PRId32 " us\n", + drift, jitter); last = now; } ++loop_counter; @@ -124,70 +127,43 @@ void *worker_thread(void *arg) int main(void) { + LOG_DEBUG("[INIT]\n"); msg_t m; + /* create and trigger first background thread */ + kernel_pid_t pid1 = thread_create(slacker_stack1, sizeof(slacker_stack1), + THREAD_PRIORITY_MAIN - 1, + THREAD_CREATE_STACKTEST, + slacker_thread, NULL, "slacker1"); - puts("xtimer_drift test application"); - puts("Make note of the PC clock when starting this test, let run for a while, " - "compare the printed time against the expected time from the PC clock."); - puts("The difference is the RIOT timer drift, this is likely caused by either: " - "an inaccurate hardware timer, or bugs in the software (xtimer or periph/timer)."); - printf("This test will run a periodic timer every %lu microseconds (%lu Hz), ", - (unsigned long)TEST_INTERVAL, (unsigned long)TEST_HZ); - puts("The current time will be printed once per second, along with the " - "difference between the actual and expected xtimer_now value."); - puts("The first output variable, 'drift', represents the total offset since " - "start between xtimer_now and the expected time."); - puts("The second output variable, 'jitter', represents the difference in drift from the last printout."); - puts("Two other threads are also running only to cause extra interrupts and context switches."); - puts(" <====== PC clock if running in pyterm."); - puts(""); - puts(" ======================="); - puts(" ===== Test begins ====="); - puts(" ======================="); - - kernel_pid_t pid1 = thread_create( - slacker_stack1, - sizeof(slacker_stack1), - THREAD_PRIORITY_MAIN - 1, - THREAD_CREATE_STACKTEST, - slacker_thread, - NULL, - "slacker1"); - - puts("sending 1st msg"); + LOG_DEBUG("+ msg 1"); m.content.ptr = &msg_a; msg_try_send(&m, pid1); - puts("sending 2nd msg"); + LOG_DEBUG("+ msg 2"); m.content.ptr = &msg_b; msg_try_send(&m, pid1); - kernel_pid_t pid2 = thread_create( - slacker_stack2, - sizeof(slacker_stack2), - THREAD_PRIORITY_MAIN - 1, - THREAD_CREATE_STACKTEST, - slacker_thread, - NULL, - "slacker2"); + /* create and trigger second background thread */ + kernel_pid_t pid2 = thread_create(slacker_stack2, sizeof(slacker_stack2), + THREAD_PRIORITY_MAIN - 1, + THREAD_CREATE_STACKTEST, + slacker_thread, NULL, "slacker2"); - puts("sending 3rd msg"); + LOG_DEBUG("+ msg 3"); m.content.ptr = &msg_c; msg_try_send(&m, pid2); - puts("sending 4th msg"); + LOG_DEBUG("+ msg 4"); m.content.ptr = &msg_d; msg_try_send(&m, pid2); - kernel_pid_t pid3 = thread_create( - worker_stack, - sizeof(worker_stack), - THREAD_PRIORITY_MAIN - 1, - THREAD_CREATE_STACKTEST, - worker_thread, - NULL, - "worker"); + /* create and trigger worker thread */ + kernel_pid_t pid3 = thread_create(worker_stack, sizeof(worker_stack), + THREAD_PRIORITY_MAIN - 1, + THREAD_CREATE_STACKTEST, + worker_thread, NULL, "worker"); + puts("[START]\n"); xtimer_ticks32_t last_wakeup = xtimer_now(); while (1) { xtimer_periodic_wakeup(&last_wakeup, TEST_INTERVAL);