Merge pull request #6662 from smlng/pr/tests/opt_xtimer_drift

tests: optimize xtimer drift for size

tests/xtimer_drift/README.md

+# 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.

tests/xtimer_drift/main.c

 /*
+ * Copyright (C) 2017 HAW Hamburg
  * Copyright (C) 2015 Kaspar Schleiser <kaspar@schleiser.de>
  * Copyright (C) 2015 Eistec AB
  *               2013 INRIA
@@ -19,6 +20,7 @@
  * @author   Oliver Hahm <oliver.hahm@inria.fr>
  * @author   Christian Mehlis <mehlis@inf.fu-berlin.de>
  * @author   Joakim Nohlgård <joakim.nohlgard@eistec.se>
+ * @author   Sebastian Meiling <s@mlng.net>
  *
  * @}
  */
@@ -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);