diff --git a/tests/bench_xtimer_load/Makefile b/tests/bench_xtimer_load/Makefile new file mode 100644 index 0000000000..fce58f27a3 --- /dev/null +++ b/tests/bench_xtimer_load/Makefile @@ -0,0 +1,9 @@ +include ../Makefile.tests_common + +USEMODULE += xtimer + +# configure benchmark frequency +TEST_HZ ?= 64 +CFLAGS += -DTEST_HZ=$(TEST_HZ)LU + +include $(RIOTBASE)/Makefile.include diff --git a/tests/bench_xtimer_load/Makefile.ci b/tests/bench_xtimer_load/Makefile.ci new file mode 100644 index 0000000000..73c8498472 --- /dev/null +++ b/tests/bench_xtimer_load/Makefile.ci @@ -0,0 +1,10 @@ +BOARD_INSUFFICIENT_MEMORY := \ + arduino-duemilanove \ + arduino-leonardo \ + arduino-nano \ + arduino-uno \ + atmega328p \ + nucleo-f031k6 \ + nucleo-f042k6 \ + stm32f030f4-demo \ + # diff --git a/tests/bench_xtimer_load/README.md b/tests/bench_xtimer_load/README.md new file mode 100644 index 0000000000..57c3f52c07 --- /dev/null +++ b/tests/bench_xtimer_load/README.md @@ -0,0 +1,38 @@ +# bench_xtimer_load test application + +This benchmark will run a periodic timer every `TEST_INTERVAL` microseconds +(`TEST_HZ`). Two other threads are also running only to cause CPU load with +extra interrupts and context switches. + +This benchmark is heavily based on tests/xtimer_drift. It basically minimizes +the per-second printout and adds statistic gathering / printing. + +With low TEST_HZ (`<64`), this test can expose accuracy issues in the timer +configuration. +With high TEST_HZ (depending on the platform, `64 - 8192`), it exposes issues +with both high timer isr load issues in periph_timer and concurrency +/ race condition issues in xtimer. If it finishes, the resulting values can +give an indication of the timer implementation efficiency. + +The difference between the actual and expected `xtimer_now()` value ("drift") +will be calculated, along with the drift change since the last iteration ("jitter"). +Every second, a dot (".") will be printed. + +After TEST_TIME seconds (defaults to 10), the minimum and maximum values for +both drift and jitter will be printed, along with the final drift and average +jitter (sum(abs(jitter)) / num_samples). + +The default TEST_HZ is quite low (16Hz), which should result in close to zero +drift and jitter. + +With higher TEST_HZ, timer isr collisions are more likely, causing increased +jitter. + +As long as the CPU can handle the load, the final drift should stay low. +If the CPU can't handle the load, drift will increase with every iteration. + + +# Notes + +This benchmark will currently get stuck due to xtimer bugs on at least native +and every board where xtimer uses a `<32bit` hardware timer. diff --git a/tests/bench_xtimer_load/main.c b/tests/bench_xtimer_load/main.c new file mode 100644 index 0000000000..a48c0ea0a7 --- /dev/null +++ b/tests/bench_xtimer_load/main.c @@ -0,0 +1,214 @@ +/* + * Copyright (C) 2019 Kaspar Schleiser + * Copyright (C) 2019 Freie Universität Berlin + * Copyright (C) 2017 HAW Hamburg + * Copyright (C) 2015 Eistec AB + * 2013 INRIA + * + * This file is subject to the terms and conditions of the GNU Lesser + * General Public License v2.1. See the file LICENSE in the top level + * directory for more details. + */ + +/** + * @ingroup tests + * @{ + * + * @file + * @brief bench_xtimer_load test application + * + * This is based on tests/xtimer_drift. It removes the lengthy printout of the + * worker thread and adds some stats keeping. + * + * @author Kaspar Schleiser + * @author Oliver Hahm + * @author Christian Mehlis + * @author Joakim Nohlgård + * @author Sebastian Meiling + * + * @} + */ + +#include +#include +#include + +#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 + * different times. TEST_HZ is the frequency of messages being sent from the + * main thread to the worker, all other message frequencies are derived from + * TEST_HZ. + * TEST_MSG_RX_USLEEP is a tiny sleep inside the message reception thread to + * cause extra context switches. + */ +#ifndef TEST_HZ +#define TEST_HZ (16LU) +#endif +#define TEST_INTERVAL (US_PER_SEC / TEST_HZ) +#define TEST_MSG_RX_USLEEP (200LU) +#define TEST_MSG_QUEUE_SIZE (4U) +#define TEST_TIME (10U) + +static char slacker_stack1[THREAD_STACKSIZE_DEFAULT]; +static char slacker_stack2[THREAD_STACKSIZE_DEFAULT]; +static char worker_stack[THREAD_STACKSIZE_MAIN]; + +struct timer_msg { + xtimer_t timer; + uint32_t interval; + msg_t msg; +}; + +static struct timer_msg msg_a = { .interval = (TEST_INTERVAL / 2) }; +static struct timer_msg msg_b = { .interval = (TEST_INTERVAL / 3) }; +static struct timer_msg msg_c = { .interval = (TEST_INTERVAL * 5) }; +static struct timer_msg msg_d = { .interval = (TEST_INTERVAL * 2) }; + +/* This thread is only here to give the kernel some extra load */ +static void *slacker_thread(void *arg) +{ + (void)arg; + timex_t now; + + LOG_DEBUG("run thread %" PRIkernel_pid "\n", thread_getpid()); + + /* 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; + msg_receive(&m); + struct timer_msg *tmsg = m.content.ptr; + xtimer_now_timex(&now); + xtimer_usleep(TEST_MSG_RX_USLEEP); + + tmsg->msg.type = 12345; + tmsg->msg.content.ptr = tmsg; + xtimer_set_msg(&tmsg->timer, tmsg->interval, &tmsg->msg, + thread_getpid()); + } + + return NULL; +} + +static volatile int32_t _min_drift, _max_drift, _min_jitter, _max_jitter; +static volatile int32_t _final_drift; +static volatile uint32_t _total_jitter, _samples; + +/* This thread will print the drift to stdout once per second */ +void *worker_thread(void *arg) +{ + (void)arg; + + /* Calculate interval based on possible precision when 'XTIMER_SHIFT > 0', + * to apply precision loss to expected interval length. + * test_interval != TEST_INTERVAL */ + uint32_t test_interval = + xtimer_usec_from_ticks(xtimer_ticks_from_usec(TEST_INTERVAL)); + uint32_t start = 0; + uint32_t last = 0; + uint32_t loop_counter = 0; + + LOG_DEBUG("run thread %" PRIkernel_pid "\n", thread_getpid()); + + while (1) { + msg_t m; + msg_receive(&m); + + uint32_t now = xtimer_now_usec(); + + if (start == 0) { + start = now; + last = start; + } + else if (loop_counter && (loop_counter % TEST_HZ) == 0) { + uint32_t expected = start + loop_counter * test_interval; + int32_t drift = now - expected; + expected = last + TEST_HZ * test_interval; + int32_t jitter = now - expected; + if (jitter < _min_jitter) { + _min_jitter = jitter; + } + if (jitter > _max_jitter) { + _max_jitter = jitter; + } + if (drift < _min_drift) { + _min_drift = drift; + } + if (drift > _max_drift) { + _max_drift = drift; + } + _final_drift = drift; + _total_jitter += labs(jitter); + _samples++; + + last = now; + puts("."); + } + ++loop_counter; + } +} + +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"); + + LOG_DEBUG("+ msg 1"); + m.content.ptr = &msg_a; + msg_try_send(&m, pid1); + + LOG_DEBUG("+ msg 2"); + m.content.ptr = &msg_b; + msg_try_send(&m, pid1); + + /* 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"); + + LOG_DEBUG("+ msg 3"); + m.content.ptr = &msg_c; + msg_try_send(&m, pid2); + + LOG_DEBUG("+ msg 4"); + m.content.ptr = &msg_d; + msg_try_send(&m, pid2); + + /* create and trigger worker thread */ + kernel_pid_t pid3 = thread_create(worker_stack, sizeof(worker_stack), + THREAD_PRIORITY_MAIN - 2, + THREAD_CREATE_STACKTEST, + worker_thread, NULL, "worker"); + + + printf("TEST_HZ=%lu\n", TEST_HZ); + + puts("[START]"); + + uint32_t iterations = (TEST_TIME * TEST_HZ) + 1; + xtimer_ticks32_t last_wakeup = xtimer_now(); + while (iterations--) { + xtimer_periodic_wakeup(&last_wakeup, TEST_INTERVAL); + msg_send(&m, pid3); + } + + printf("drift: min=%" PRIi32 " max=%" PRIi32 " final=%" PRIi32 "\n", + _min_drift, _max_drift, _final_drift); + printf("jitter: min=%" PRIi32 " max=%" PRIi32 " abs avg=%" PRIi32 "\n", + _min_jitter, _max_jitter, _total_jitter / _samples); + + puts("[DONE]"); +} diff --git a/tests/bench_xtimer_load/tests/01-run.py b/tests/bench_xtimer_load/tests/01-run.py new file mode 100755 index 0000000000..1e6d5535ef --- /dev/null +++ b/tests/bench_xtimer_load/tests/01-run.py @@ -0,0 +1,29 @@ +#!/usr/bin/env python3 +# -*- coding: utf-8 -*- +# vim:fenc=utf-8 + +# Copyright (C) 2019 Kaspar Schleiser +# 2019 Freie Universität Berlin +# +# This file is subject to the terms and conditions of the GNU Lesser +# General Public License v2.1. See the file LICENSE in the top level +# directory for more details. + +import sys +from testrunner import run + + +def testfunc(child): + child.expect(r"TEST_HZ=\d+\r\n") + child.expect_exact("[START]\r\n") + for _ in range(10): + child.expect_exact(".\r\n") + + child.expect(r"drift: min=-?\d+ max=-?\d+ final=-?\d+\r\n") + child.expect(r"jitter: min=-?\d+ max=-?\d+ abs avg=\d+\r\n") + + child.expect_exact("[DONE]\r\n") + + +if __name__ == "__main__": + sys.exit(run(testfunc))