adafruit-mirror/zephyr
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions 9

tests: latency_measure: Using timing functions

Browse source 
Use new timing API instead if local macros and functions. Add new
becnhmarks for threads and semaphore and change the output to be
parseable.

Signed-off-by: Anas Nashif <anas.nashif@intel.com>
This commit is contained in:
Anas Nashif 2020-08-18 08:41:02 -04:00 committed by Maureen Helm
parent 4b41cb14a8
commit e90a4bb6b3
18 changed files with 426 additions and 571 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

41
tests/benchmarks/latency_measure/README.rst Normal file
View file

@ -0,0 +1,41 @@
Latency Measurements
####################
This benchmark measures the latency of selected kernel capabilities, including:
* Measure time to switch from ISR back to interrupted thread
* Measure time from ISR to executing a different thread (rescheduled)
* Measure average time to signal a semaphore then test that semaphore
* Measure average time to signal a semaphore then test that semaphore with a context switch
* Measure average time to lock a mutex then unlock that mutex
* Measure average context switch time between threads using (k_yield)
* Measure average context switch time between threads (coop)
* Time it takes to suspend a thread
* Time it takes to resume a suspended thread
* Time it takes to create a new thread (without starting it)
* Time it takes to start a newly created thread
Sample output of the benchmark::
*** Booting Zephyr OS build zephyr-v2.3.0-2257-g0f420483db07 ***
START - Time Measurement
Timing results: Clock frequency: 120 MHz
Average thread context switch using yield : 420 cycles , 3502 ns
Average context switch time between threads (coop) : 429 cycles , 3583 ns
Switch from ISR back to interrupted thread : 670 cycles , 5583 ns
Time from ISR to executing a different thread : 570 cycles , 4750 ns
Time to create a thread (without start) : 360 cycles , 3000 ns
Time to start a thread : 545 cycles , 4541 ns
Time to suspend a thread : 605 cycles , 5041 ns
Time to resume a thread : 660 cycles , 5500 ns
Time to abort a thread (not running) : 495 cycles , 4125 ns
Average semaphore signal time : 195 cycles , 1626 ns
Average semaphore test time : 62 cycles , 518 ns
Semaphore take time (context switch) : 695 cycles , 5791 ns
Semaphore give time (context switch) : 845 cycles , 7041 ns
Average time to lock a mutex : 79 cycles , 659 ns
Average time to unlock a mutex : 370 cycles , 3085 ns
===================================================================
PROJECT EXECUTION SUCCESSFUL

41
tests/benchmarks/latency_measure/README.txt
View file

@ -1,41 +0,0 @@
Title: Latency Measurement
Description:
This benchmark measures the latency of selected capabilities
IMPORTANT: The sample output below was generated using a simulation
environment, and may not reflect the results that will be generated using other
environments (simulated or otherwise).
Sample Output:
***** BOOTING ZEPHYR OS v1.7.99 - BUILD: Mar 24 2017 22:46:05 *****
|-----------------------------------------------------------------------------|
| Latency Benchmark |
|-----------------------------------------------------------------------------|
| tcs = timer clock cycles: 1 tcs is 10 nsec |
|-----------------------------------------------------------------------------|
| 1 - Measure time to switch from ISR back to interrupted thread |
| switching time is 12591 tcs = 125910 nsec |
|-----------------------------------------------------------------------------|
| 2 - Measure time from ISR to executing a different thread (rescheduled) |
| switch time is 8344 tcs = 83440 nsec |
|-----------------------------------------------------------------------------|
| 3 - Measure average time to signal a sema then test that sema |
| Average semaphore signal time 63 tcs = 638 nsec |
| Average semaphore test time 49 tcs = 498 nsec |
|-----------------------------------------------------------------------------|
| 4- Measure average time to lock a mutex then unlock that mutex |
| Average time to lock the mutex 107 tcs = 1078 nsec |
| Average time to unlock the mutex 92 tcs = 929 nsec |
|-----------------------------------------------------------------------------|
| 5 - Measure average context switch time between threads using (k_yield) |
| Average thread context switch using yield 110 tcs = 1107 nsec |
|-----------------------------------------------------------------------------|
| 6 - Measure average context switch time between threads (coop) |
| Average context switch time is 88 tcs = 882 nsec |
|-----------------------------------------------------------------------------|
===================================================================
PROJECT EXECUTION SUCCESSFUL

3
tests/benchmarks/latency_measure/prj.conf
View file

@ -1,6 +1,4 @@
CONFIG_TEST=y CONFIG_TEST=y
# needed for printf output sent to console
CONFIG_STDOUT_CONSOLE=y
# eliminate timer interrupts during the benchmark # eliminate timer interrupts during the benchmark
CONFIG_SYS_CLOCK_TICKS_PER_SEC=1 CONFIG_SYS_CLOCK_TICKS_PER_SEC=1
@ -21,3 +19,4 @@ CONFIG_SYS_POWER_MANAGEMENT=n
# Can only run under 1 CPU # Can only run under 1 CPU
CONFIG_MP_NUM_CPUS=1 CONFIG_MP_NUM_CPUS=1
CONFIG_TIMING_FUNCTIONS=y

43
tests/benchmarks/latency_measure/src/coop_ctx_switch.c
View file

@ -16,16 +16,14 @@
* forth by yielding the cpu. When counter reaches the maximal value, threads * forth by yielding the cpu. When counter reaches the maximal value, threads
* stop and the average time of context switch is displayed. * stop and the average time of context switch is displayed.
*/ */
#include <kernel.h>
#include <timing/timing.h>
#include "utils.h" #include "utils.h"
#include "timing_info.h"
#include <arch/cpu.h>
/* number of context switches */ /* number of context switches */
#define NCTXSWITCH 10000 #define NCTXSWITCH 10000
#ifndef STACKSIZE #ifndef STACKSIZE
#define STACKSIZE (512 + CONFIG_TEST_EXTRA_STACKSIZE) #define STACKSIZE (512 + CONFIG_TEST_EXTRA_STACKSIZE)
#endif #endif
/* stack used by the threads */ /* stack used by the threads */
@ -34,8 +32,8 @@ static K_THREAD_STACK_DEFINE(thread_two_stack, STACKSIZE);
static struct k_thread thread_one_data; static struct k_thread thread_one_data;
static struct k_thread thread_two_data; static struct k_thread thread_two_data;
static uint32_t timestamp_start; static timing_t timestamp_start;
static uint32_t timestamp_end; static timing_t timestamp_end;
/* context switches counter */ /* context switches counter */
static volatile uint32_t ctx_switch_counter; static volatile uint32_t ctx_switch_counter;
@ -58,8 +56,7 @@ static void thread_one(void)
{ {
k_sem_take(&sync_sema, K_FOREVER); k_sem_take(&sync_sema, K_FOREVER);
TIMING_INFO_PRE_READ(); timestamp_start = timing_counter_get();
timestamp_start = TIMING_INFO_OS_GET_TIME();
while (ctx_switch_counter < NCTXSWITCH) { while (ctx_switch_counter < NCTXSWITCH) {
k_yield(); k_yield();
@ -67,8 +64,7 @@ static void thread_one(void)
ctx_switch_balancer--; ctx_switch_balancer--;
} }
TIMING_INFO_PRE_READ(); timestamp_end = timing_counter_get();
timestamp_end = TIMING_INFO_OS_GET_TIME();
} }
/** /**
@ -98,37 +94,32 @@ static void thread_two(void)
*/ */
int coop_ctx_switch(void) int coop_ctx_switch(void)
{ {
PRINT_FORMAT(" 6 - Measure average context switch time between threads (coop)");
ctx_switch_counter = 0U; ctx_switch_counter = 0U;
ctx_switch_balancer = 0; ctx_switch_balancer = 0;
benchmark_timer_start(); timing_start();
bench_test_start(); bench_test_start();
k_thread_create(&thread_one_data, thread_one_stack, STACKSIZE, k_thread_create(&thread_one_data, thread_one_stack, STACKSIZE,
(k_thread_entry_t) thread_one, NULL, NULL, NULL, (k_thread_entry_t)thread_one, NULL, NULL, NULL,
6, 0, K_NO_WAIT); K_PRIO_COOP(6), 0, K_NO_WAIT);
k_thread_create(&thread_two_data, thread_two_stack, STACKSIZE, k_thread_create(&thread_two_data, thread_two_stack, STACKSIZE,
(k_thread_entry_t) thread_two, NULL, NULL, NULL, (k_thread_entry_t)thread_two, NULL, NULL, NULL,
6, 0, K_NO_WAIT); K_PRIO_COOP(6), 0, K_NO_WAIT);
if (ctx_switch_balancer > 3 || ctx_switch_balancer < -3) { if (ctx_switch_balancer > 3 || ctx_switch_balancer < -3) {
PRINT_FORMAT(" Balance is %d. FAILED", ctx_switch_balancer); printk(" Balance is %d. FAILED", ctx_switch_balancer);
} else if (bench_test_end() != 0) { } else if (bench_test_end() != 0) {
error_count++; error_count++;
PRINT_OVERFLOW_ERROR(); PRINT_OVERFLOW_ERROR();
} else { } else {
uint32_t diff; uint32_t diff;
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end); diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average context switch time between threads (coop)", diff, ctx_switch_counter);
PRINT_FORMAT(" Average context switch time is %u tcs = %u"
" nsec",
diff / ctx_switch_counter,
CYCLES_TO_NS_AVG(diff, ctx_switch_counter));
} }
benchmark_timer_stop(); timing_stop();
return 0; return 0;
} }

27
tests/benchmarks/latency_measure/src/int_to_thread.c
View file

@ -14,16 +14,15 @@
* handler back to the interrupted thread. * handler back to the interrupted thread.
*/ */
#include <kernel.h>
#include "utils.h" #include "utils.h"
#include "timing_info.h"
#include <arch/cpu.h>
#include <irq_offload.h> #include <irq_offload.h>
static volatile int flag_var; static volatile int flag_var;
static uint32_t timestamp_start; static timing_t timestamp_start;
static uint32_t timestamp_end; static timing_t timestamp_end;
/** /**
* *
@ -36,11 +35,9 @@ static uint32_t timestamp_end;
static void latency_test_isr(const void *unused) static void latency_test_isr(const void *unused)
{ {
ARG_UNUSED(unused); ARG_UNUSED(unused);
flag_var = 1; flag_var = 1;
TIMING_INFO_PRE_READ(); timestamp_start = timing_counter_get();
timestamp_start = TIMING_INFO_OS_GET_TIME();
} }
/** /**
@ -57,10 +54,9 @@ static void make_int(void)
flag_var = 0; flag_var = 0;
irq_offload(latency_test_isr, NULL); irq_offload(latency_test_isr, NULL);
if (flag_var != 1) { if (flag_var != 1) {
PRINT_FORMAT(" Flag variable has not changed. FAILED\n"); printk(" Flag variable has not changed. FAILED\n");
} else { } else {
TIMING_INFO_PRE_READ(); timestamp_end = timing_counter_get();
timestamp_end = TIMING_INFO_OS_GET_TIME();
} }
} }
@ -74,16 +70,13 @@ int int_to_thread(void)
{ {
uint32_t diff; uint32_t diff;
PRINT_FORMAT(" 1 - Measure time to switch from ISR back to" timing_start();
" interrupted thread");
benchmark_timer_start();
TICK_SYNCH(); TICK_SYNCH();
make_int(); make_int();
if (flag_var == 1) { if (flag_var == 1) {
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end); diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_FORMAT(" switching time is %u tcs = %u nsec", PRINT_STATS("Switch from ISR back to interrupted thread", diff);
diff, CYCLES_TO_NS(diff));
} }
benchmark_timer_stop(); timing_stop();
return 0; return 0;
} }

34
tests/benchmarks/latency_measure/src/int_to_thread_evt.c
View file

@ -19,18 +19,14 @@
#include <irq_offload.h> #include <irq_offload.h>
#include "utils.h" #include "utils.h"
#include "timing_info.h"
#include <arch/cpu.h> static timing_t timestamp_start;
static timing_t timestamp_end;
static uint32_t timestamp_start;
static uint32_t timestamp_end;
static struct k_work work; static struct k_work work;
K_SEM_DEFINE(INTSEMA, 0, 1); K_SEM_DEFINE(INTSEMA, 0, 1);
K_SEM_DEFINE(WORKSEMA, 0, 1); K_SEM_DEFINE(WORKSEMA, 0, 1);
/** /**
* *
* @brief Test ISR used to measure best case interrupt latency * @brief Test ISR used to measure best case interrupt latency
@ -44,18 +40,14 @@ static void latency_test_isr(const void *unused)
ARG_UNUSED(unused); ARG_UNUSED(unused);
k_work_submit(&work); k_work_submit(&work);
timestamp_start = timing_counter_get();
TIMING_INFO_PRE_READ();
timestamp_start = TIMING_INFO_OS_GET_TIME();
} }
static void worker(struct k_work *item) static void worker(struct k_work *item)
{ {
(void)item; (void)item;
TIMING_INFO_PRE_READ(); timestamp_end = timing_counter_get();
timestamp_end = TIMING_INFO_OS_GET_TIME();
k_sem_give(&WORKSEMA); k_sem_give(&WORKSEMA);
} }
@ -76,10 +68,8 @@ void int_thread(void)
k_thread_suspend(k_current_get()); k_thread_suspend(k_current_get());
} }
K_THREAD_DEFINE(int_thread_id, 512, (k_thread_entry_t)int_thread, NULL, NULL,
K_THREAD_DEFINE(int_thread_id, 512, NULL, 11, 0, 0);
(k_thread_entry_t) int_thread, NULL, NULL, NULL,
11, 0, 0);
/** /**
* *
@ -91,19 +81,17 @@ int int_to_thread_evt(void)
{ {
uint32_t diff; uint32_t diff;
PRINT_FORMAT(" 2 - Measure time from ISR to executing a different thread"
" (rescheduled)");
k_work_init(&work, worker); k_work_init(&work, worker);
benchmark_timer_start(); timing_start();
TICK_SYNCH(); TICK_SYNCH();
k_sem_give(&INTSEMA); k_sem_give(&INTSEMA);
k_sem_take(&WORKSEMA, K_FOREVER); k_sem_take(&WORKSEMA, K_FOREVER);
benchmark_timer_stop(); timing_stop();
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end); diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS("Time from ISR to executing a different thread", diff)
PRINT_FORMAT(" switch time is %u tcs = %u nsec",
diff, CYCLES_TO_NS(diff));
return 0; return 0;
} }

48
tests/benchmarks/latency_measure/src/main.c
View file

@ -12,53 +12,55 @@
#include <timestamp.h> #include <timestamp.h>
#include "utils.h" #include "utils.h"
#include <tc_util.h> #include <tc_util.h>
#include "timing_info.h"
#define STACK_SIZE (1024 + CONFIG_TEST_EXTRA_STACKSIZE) #define STACK_SIZE (1024 + CONFIG_TEST_EXTRA_STACKSIZE)
uint32_t tm_off; /* time necessary to read the time */ uint32_t tm_off; /* time necessary to read the time */
int error_count; /* track number of errors */ int error_count; /* track number of errors */
extern void thread_switch_yield(void); extern void thread_switch_yield(void);
extern void int_to_thread(void); extern void int_to_thread(void);
extern void int_to_thread_evt(void); extern void int_to_thread_evt(void);
extern void sema_lock_unlock(void); extern void sema_test_signal(void);
extern void mutex_lock_unlock(void); extern void mutex_lock_unlock(void);
extern int coop_ctx_switch(void); extern int coop_ctx_switch(void);
extern int sema_test(void);
extern int sema_context_switch(void);
extern int suspend_resume(void);
void test_thread(void *arg1, void *arg2, void *arg3) void test_thread(void *arg1, void *arg2, void *arg3)
{ {
PRINT_BANNER(); uint32_t freq;
PRINT_TIME_BANNER();
bench_test_init(); bench_test_init();
benchmark_timer_init();
int_to_thread(); freq = timing_freq_get_mhz();
print_dash_line();
int_to_thread_evt(); TC_START("Time Measurement");
print_dash_line(); TC_PRINT("Timing results: Clock frequency: %u MHz\n", freq);
sema_lock_unlock(); timing_init();
print_dash_line();
mutex_lock_unlock();
print_dash_line();
thread_switch_yield(); thread_switch_yield();
print_dash_line();
coop_ctx_switch(); coop_ctx_switch();
print_dash_line();
int_to_thread();
int_to_thread_evt();
suspend_resume();
sema_test_signal();
sema_context_switch();
mutex_lock_unlock();
TC_END_REPORT(error_count); TC_END_REPORT(error_count);
} }
K_THREAD_DEFINE(tt_id, STACK_SIZE, K_THREAD_DEFINE(test_thread_id, STACK_SIZE, test_thread, NULL, NULL, NULL, K_PRIO_PREEMPT(10), 0, 0);
test_thread, NULL, NULL, NULL,
10, 0, 0);
void main(void) void main(void)
{ {

59
tests/benchmarks/latency_measure/src/mutex_lock_unlock.c Normal file
View file

@ -0,0 +1,59 @@
/*
* Copyright (c) 2012-2015 Wind River Systems, Inc.
* Copyright (c) 2020 Intel Corporation
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <zephyr.h>
#include <timing/timing.h>
#include "utils.h"
/* the number of mutex lock/unlock cycles */
#define N_TEST_MUTEX 1000
K_MUTEX_DEFINE(test_mutex);
/**
*
* @brief Test for the multiple mutex lock/unlock time
*
* The routine performs multiple mutex locks and then multiple mutex
* unlocks to measure the necessary time.
*
* @return 0 on success
*/
int mutex_lock_unlock(void)
{
int i;
uint32_t diff;
timing_t timestamp_start;
timing_t timestamp_end;
timing_start();
timestamp_start = timing_counter_get();
for (i = 0; i < N_TEST_MUTEX; i++) {
k_mutex_lock(&test_mutex, K_FOREVER);
}
timestamp_end = timing_counter_get();
diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average time to lock a mutex", diff, N_TEST_MUTEX);
timestamp_start = timing_counter_get();
for (i = 0; i < N_TEST_MUTEX; i++) {
k_mutex_unlock(&test_mutex);
}
timestamp_end = timing_counter_get();
diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average time to unlock a mutex", diff, N_TEST_MUTEX);
timing_stop();
return 0;
}

151
tests/benchmarks/latency_measure/src/sema_lock_release.c
View file

@ -1,151 +0,0 @@
/*
* Copyright (c) 2012-2015 Wind River Systems, Inc.
*
* SPDX-License-Identifier: Apache-2.0
*/
/*
* @file measure time for sema lock and release
*
* This file contains the test that measures semaphore and mutex lock and
* release time in the kernel. There is no contention on the sema nor the
* mutex being tested.
*/
#include <zephyr.h>
#include "utils.h"
#include "timing_info.h"
#include <arch/cpu.h>
/* the number of semaphore give/take cycles */
#define N_TEST_SEMA 1000
/* the number of mutex lock/unlock cycles */
#define N_TEST_MUTEX 1000
static uint32_t timestamp_start;
static uint32_t timestamp_end;
K_SEM_DEFINE(lock_unlock_sema, 0, N_TEST_SEMA);
K_MUTEX_DEFINE(TEST_MUTEX);
/**
*
* @brief The function tests semaphore lock/unlock time
*
* The routine performs unlock the quite amount of semaphores and then
* acquires them in order to measure the necessary time.
*
* @return 0 on success
*/
int sema_lock_unlock(void)
{
int i;
uint32_t diff;
PRINT_FORMAT(" 3 - Measure average time to signal a sema then test"
" that sema");
bench_test_start();
benchmark_timer_start();
TIMING_INFO_PRE_READ();
timestamp_start = TIMING_INFO_OS_GET_TIME();
for (i = 0; i < N_TEST_SEMA; i++) {
k_sem_give(&lock_unlock_sema);
}
TIMING_INFO_PRE_READ();
timestamp_end = TIMING_INFO_OS_GET_TIME();
benchmark_timer_stop();
if (bench_test_end() == 0) {
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end);
PRINT_FORMAT(" Average semaphore signal time %u tcs = %u"
" nsec",
diff / N_TEST_SEMA,
CYCLES_TO_NS_AVG(diff, N_TEST_SEMA));
} else {
error_count++;
PRINT_OVERFLOW_ERROR();
}
bench_test_start();
benchmark_timer_start();
TIMING_INFO_PRE_READ();
timestamp_start = TIMING_INFO_OS_GET_TIME();
for (i = 0; i < N_TEST_SEMA; i++) {
k_sem_take(&lock_unlock_sema, K_FOREVER);
}
TIMING_INFO_PRE_READ();
timestamp_end = TIMING_INFO_OS_GET_TIME();
benchmark_timer_stop();
if (bench_test_end() == 0) {
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end);
PRINT_FORMAT(" Average semaphore test time %u tcs = %u "
"nsec",
diff / N_TEST_SEMA,
CYCLES_TO_NS_AVG(diff, N_TEST_SEMA));
} else {
error_count++;
PRINT_OVERFLOW_ERROR();
}
return 0;
}
/**
*
* @brief Test for the multiple mutex lock/unlock time
*
* The routine performs multiple mutex locks and then multiple mutex
* unlocks to measure the necessary time.
*
* @return 0 on success
*/
int mutex_lock_unlock(void)
{
int i;
uint32_t diff;
benchmark_timer_start();
PRINT_FORMAT(" 4- Measure average time to lock a mutex then"
" unlock that mutex");
TIMING_INFO_PRE_READ();
timestamp_start = TIMING_INFO_OS_GET_TIME();
for (i = 0; i < N_TEST_MUTEX; i++) {
k_mutex_lock(&TEST_MUTEX, K_FOREVER);
}
TIMING_INFO_PRE_READ();
timestamp_end = TIMING_INFO_OS_GET_TIME();
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end);
PRINT_FORMAT(" Average time to lock the mutex %u tcs = %u nsec",
diff / N_TEST_MUTEX,
CYCLES_TO_NS_AVG(diff, N_TEST_MUTEX));
TIMING_INFO_PRE_READ();
timestamp_start = TIMING_INFO_OS_GET_TIME();
for (i = 0; i < N_TEST_MUTEX; i++) {
k_mutex_unlock(&TEST_MUTEX);
}
TIMING_INFO_PRE_READ();
timestamp_end = TIMING_INFO_OS_GET_TIME();
diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end);
PRINT_FORMAT(" Average time to unlock the mutex %u tcs = %u nsec",
diff / N_TEST_MUTEX,
CYCLES_TO_NS_AVG(diff, N_TEST_MUTEX));
benchmark_timer_stop();
return 0;
}

126
tests/benchmarks/latency_measure/src/sema_test_signal_release.c Normal file
View file

@ -0,0 +1,126 @@
/*
* Copyright (c) 2012-2015 Wind River Systems, Inc.
*
* SPDX-License-Identifier: Apache-2.0
*/
/*
* @file measure time for sema lock and release
*
* This file contains the test that measures semaphore and mutex lock and
* release time in the kernel. There is no contention on the sema nor the
* mutex being tested.
*/
#include <zephyr.h>
#include <timing/timing.h>
#include "utils.h"
/* the number of semaphore give/take cycles */
#define N_TEST_SEMA 1000
#define STACK_SIZE (512 + CONFIG_TEST_EXTRA_STACKSIZE)
/* stack used by the threads */
static K_THREAD_STACK_DEFINE(thread_one_stack, STACK_SIZE);
static struct k_thread thread_one_data;
K_SEM_DEFINE(lock_unlock_sema, 0, N_TEST_SEMA);
K_SEM_DEFINE(sem_bench, 0, 1);
timing_t timestamp_start_sema_t_c;
timing_t timestamp_end_sema_t_c;
timing_t timestamp_start_sema_g_c;
timing_t timestamp_end_sema_g_c;
void thread_sema_test1(void *p1, void *p2, void *p3)
{
timestamp_start_sema_t_c = timing_counter_get();
k_sem_take(&sem_bench, K_FOREVER);
timestamp_end_sema_g_c = timing_counter_get();
}
int sema_context_switch(void)
{
uint32_t diff;
timing_start();
k_thread_create(&thread_one_data, thread_one_stack,
STACK_SIZE, thread_sema_test1,
NULL, NULL, NULL,
K_PRIO_PREEMPT(3), 0, K_FOREVER);
k_thread_name_set(&thread_one_data, "sema_test1");
k_thread_start(&thread_one_data);
timestamp_end_sema_t_c = timing_counter_get();
diff = timing_cycles_get(&timestamp_start_sema_t_c, &timestamp_end_sema_t_c);
PRINT_STATS("Semaphore take time (context switch)", diff);
timestamp_start_sema_g_c = timing_counter_get();
k_sem_give(&sem_bench);
diff = timing_cycles_get(&timestamp_start_sema_g_c, &timestamp_end_sema_g_c);
PRINT_STATS("Semaphore give time (context switch)", diff);
return 0;
}
/**
*
* @brief The function tests semaphore test/signal time
*
* The routine performs unlock the quite amount of semaphores and then
* acquires them in order to measure the necessary time.
*
* @return 0 on success
*/
int sema_test_signal(void)
{
int i;
uint32_t diff;
timing_t timestamp_start;
timing_t timestamp_end;
bench_test_start();
timing_start();
timestamp_start = timing_counter_get();
for (i = 0; i < N_TEST_SEMA; i++) {
k_sem_give(&lock_unlock_sema);
}
timestamp_end = timing_counter_get();
timing_stop();
if (bench_test_end() == 0) {
diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average semaphore signal time", diff, N_TEST_SEMA);
} else {
error_count++;
PRINT_OVERFLOW_ERROR();
}
bench_test_start();
timing_start();
timestamp_start = timing_counter_get();
for (i = 0; i < N_TEST_SEMA; i++) {
k_sem_take(&lock_unlock_sema, K_FOREVER);
}
timestamp_end = timing_counter_get();
timing_stop();
if (bench_test_end() == 0) {
diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average semaphore test time", diff, N_TEST_SEMA);
} else {
error_count++;
PRINT_OVERFLOW_ERROR();
}
timing_stop();
return 0;
}

42
tests/benchmarks/latency_measure/src/test_asm_inline_gcc.h
View file

@ -1,42 +0,0 @@
/* GCC specific test inline assembler functions and macros */
/*
* Copyright (c) 2015, Wind River Systems, Inc.
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef _TEST_ASM_INLINE_GCC_H
#define _TEST_ASM_INLINE_GCC_H
#if !defined(__GNUC__)
#error test_asm_inline_gcc.h goes only with GCC
#endif
#if defined(CONFIG_X86)
static inline void timestamp_serialize(void)
{
__asm__ __volatile__ (/* serialize */
"xorl %%eax,%%eax;\n\t"
"cpuid;\n\t"
:
:
: "%eax", "%ebx", "%ecx", "%edx");
}
#elif defined(CONFIG_CPU_CORTEX_M)
static inline void timestamp_serialize(void)
{
/* isb is available in all Cortex-M */
__asm__ __volatile__ (
"isb;\n\t"
:
:
: "memory");
}
#elif defined(CONFIG_CPU_ARCV2)
#define timestamp_serialize()
#else
#error implementation of timestamp_serialize() not provided for your CPU target
#endif
#endif /* _TEST_ASM_INLINE_GCC_H */

87
tests/benchmarks/latency_measure/src/thread.c Normal file
View file

@ -0,0 +1,87 @@
/*
* Copyright (c) 2020 Intel Corporation
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <zephyr.h>
#include <timing/timing.h>
#include "utils.h"
#define STACK_SIZE (512 + CONFIG_TEST_EXTRA_STACKSIZE)
/* stack used by the threads */
static K_THREAD_STACK_DEFINE(t1_stack, STACK_SIZE);
static struct k_thread t1;
timing_t timestamp_start_create_c;
timing_t timestamp_end_create_c;
timing_t timestamp_start_start_c;
timing_t timestamp_end_start_c;
timing_t timestamp_start_suspend_c;
timing_t timestamp_end_suspend_c;
timing_t timestamp_start_resume_c;
timing_t timestamp_end_resume_c;
timing_t timestamp_start_abort_1;
timing_t timestamp_end_abort_1;
void thread_suspend_resume(void *p1, void *p2, void *p3)
{
timestamp_start_suspend_c = timing_counter_get();
k_thread_suspend(_current);
/* comes to this line once its resumed*/
timestamp_start_resume_c = timing_counter_get();
}
int suspend_resume(void)
{
uint32_t diff;
timing_start();
timestamp_start_create_c = timing_counter_get();
k_tid_t t1_tid = k_thread_create(&t1, t1_stack, STACK_SIZE,
thread_suspend_resume, NULL, NULL,
NULL, K_PRIO_PREEMPT(6), 0, K_FOREVER);
timestamp_end_create_c = timing_counter_get();
k_thread_name_set(t1_tid, "t1");
timestamp_start_start_c = timing_counter_get();
k_thread_start(t1_tid);
timestamp_end_suspend_c = timing_counter_get();
k_thread_resume(t1_tid);
timestamp_end_resume_c = timing_counter_get();
diff = timing_cycles_get(&timestamp_start_create_c,
&timestamp_end_create_c);
PRINT_STATS("Time to create a thread (without start)", diff);
diff = timing_cycles_get(&timestamp_start_start_c,
&timestamp_start_suspend_c);
PRINT_STATS("Time to start a thread", diff);
diff = timing_cycles_get(&timestamp_start_suspend_c,
&timestamp_end_suspend_c);
PRINT_STATS("Time to suspend a thread", diff);
diff = timing_cycles_get(&timestamp_start_resume_c,
&timestamp_end_resume_c);
PRINT_STATS("Time to resume a thread", diff);
timestamp_start_abort_1 = timing_counter_get();
k_thread_abort(t1_tid);
timestamp_end_abort_1 = timing_counter_get();
diff = timing_cycles_get(&timestamp_start_abort_1,
&timestamp_end_abort_1);
PRINT_STATS("Time to abort a thread (not running)", diff);
timing_stop();
return 0;
}

48
tests/benchmarks/latency_measure/src/thread_switch_yield.c
View file

@ -12,24 +12,23 @@
*/ */
#include <zephyr.h> #include <zephyr.h>
#include <timing/timing.h>
#include <stdlib.h> #include <stdlib.h>
#include "timestamp.h" #include "timestamp.h"
#include "utils.h" /* PRINT () and other macros */ #include "utils.h" /* PRINT () and other macros */
#include "timing_info.h"
/* context switch enough time so our measurement is precise */ /* context switch enough time so our measurement is precise */
#define NB_OF_YIELD 1000 #define NB_OF_YIELD 1000
static uint32_t helper_thread_iterations; static uint32_t helper_thread_iterations;
#define Y_STACK_SIZE (512 + CONFIG_TEST_EXTRA_STACKSIZE) #define Y_STACK_SIZE (512 + CONFIG_TEST_EXTRA_STACKSIZE)
#define Y_PRIORITY 10 #define Y_PRIORITY K_PRIO_PREEMPT(10)
K_THREAD_STACK_DEFINE(y_stack_area, Y_STACK_SIZE); K_THREAD_STACK_DEFINE(y_stack_area, Y_STACK_SIZE);
static struct k_thread y_thread; static struct k_thread y_thread;
/** /**
*
* @brief Helper thread for measuring thread switch latency using yield * @brief Helper thread for measuring thread switch latency using yield
* *
* @return N/A * @return N/A
@ -43,7 +42,6 @@ void yielding_thread(void *arg1, void *arg2, void *arg3)
} }
/** /**
*
* @brief Entry point for thread context switch using yield test * @brief Entry point for thread context switch using yield test
* *
* @return N/A * @return N/A
@ -52,24 +50,21 @@ void thread_switch_yield(void)
{ {
uint32_t iterations = 0U; uint32_t iterations = 0U;
int32_t delta; int32_t delta;
uint32_t timestamp_start; timing_t timestamp_start;
uint32_t timestamp_end; timing_t timestamp_end;
uint32_t ts_diff; uint32_t ts_diff;
PRINT_FORMAT(" 5 - Measure average context switch time between threads" timing_start();
" using (k_yield)");
benchmark_timer_start();
bench_test_start(); bench_test_start();
/* launch helper thread of the same priority than this routine */ /* launch helper thread of the same priority as the thread
k_thread_create(&y_thread, y_stack_area, Y_STACK_SIZE, * of routine
yielding_thread, NULL, NULL, NULL, */
Y_PRIORITY, 0, K_NO_WAIT); k_thread_create(&y_thread, y_stack_area, Y_STACK_SIZE, yielding_thread,
NULL, NULL, NULL, Y_PRIORITY, 0, K_NO_WAIT);
/* get initial timestamp */ /* get initial timestamp */
TIMING_INFO_PRE_READ(); timestamp_start = timing_counter_get();
timestamp_start = TIMING_INFO_OS_GET_TIME();
/* loop until either helper or this routine reaches number of yields */ /* loop until either helper or this routine reaches number of yields */
while (iterations < NB_OF_YIELD && while (iterations < NB_OF_YIELD &&
@ -79,8 +74,7 @@ void thread_switch_yield(void)
} }
/* get the number of cycles it took to do the test */ /* get the number of cycles it took to do the test */
TIMING_INFO_PRE_READ(); timestamp_end = timing_counter_get();
timestamp_end = TIMING_INFO_OS_GET_TIME();
/* Ensure both helper and this routine were context switching back & /* Ensure both helper and this routine were context switching back &
* forth. * forth.
@ -98,19 +92,15 @@ void thread_switch_yield(void)
* called yield without the other having chance to execute * called yield without the other having chance to execute
*/ */
error_count++; error_count++;
PRINT_FORMAT(" Error, iteration:%u, helper iteration:%u", printk(" Error, iteration:%u, helper iteration:%u",
iterations, helper_thread_iterations); iterations, helper_thread_iterations);
} else { } else {
/* thread_yield is called (iterations + helper_thread_iterations) /* thread_yield is called (iterations + helper_thread_iterations)
* times in total. * times in total.
*/ */
ts_diff = TIMING_INFO_GET_DELTA(timestamp_start, timestamp_end); ts_diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_FORMAT(" Average thread context switch using " PRINT_STATS_AVG("Average thread context switch using yield", ts_diff, (iterations + helper_thread_iterations));
"yield %u tcs = %u nsec",
ts_diff / (iterations + helper_thread_iterations),
CYCLES_TO_NS_AVG(ts_diff,
(iterations + helper_thread_iterations)));
} }
benchmark_timer_stop(); timing_stop();
} }

119
tests/benchmarks/latency_measure/src/timing_info.h
View file

@ -1,119 +0,0 @@
/*
* Copyright (c) 2017 Intel Corporation.
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef _TIMING_INFO_H_
#define _TIMING_INFO_H_
#include <timestamp.h>
#ifdef CONFIG_NRF_RTC_TIMER
#include <soc.h>
/* To get current count of timer, first 1 need to be written into
* Capture Register and Current Count will be copied into corresponding
* current count register.
*/
#define TIMING_INFO_PRE_READ() (NRF_TIMER2->TASKS_CAPTURE[0] = 1)
#define TIMING_INFO_OS_GET_TIME() (NRF_TIMER2->CC[0])
#elif CONFIG_SOC_SERIES_MEC1501X
#include <soc.h>
#define TIMING_INFO_PRE_READ()
#define TIMING_INFO_OS_GET_TIME() (B32TMR1_REGS->CNT)
#else
#define TIMING_INFO_PRE_READ()
#define TIMING_INFO_OS_GET_TIME() (k_cycle_get_32())
#endif
/******************************************************************************/
/* NRF RTC TIMER runs ar very slow rate (32KHz), So in order to measure
* Kernel starts a dedicated timer to measure kernel stats.
*/
#ifdef CONFIG_NRF_RTC_TIMER
#define NANOSECS_PER_SEC (1000000000)
#define CYCLES_PER_SEC (16000000/(1 << NRF_TIMER2->PRESCALER))
#define CYCLES_TO_NS(x) ((x) * (NANOSECS_PER_SEC/CYCLES_PER_SEC))
#define CYCLES_TO_NS_AVG(x, NCYCLES) \
(CYCLES_TO_NS(x) / NCYCLES)
/* Configure Timer parameters */
static inline void benchmark_timer_init(void)
{
NRF_TIMER2->TASKS_CLEAR = 1; /* Clear Timer */
NRF_TIMER2->MODE = 0; /* Timer Mode */
NRF_TIMER2->PRESCALER = 0; /* 16M Hz */
NRF_TIMER2->BITMODE = 3; /* 32 - bit */
}
/* Stop the timer */
static inline void benchmark_timer_stop(void)
{
NRF_TIMER2->TASKS_STOP = 1; /* Stop Timer */
}
/*Start the timer */
static inline void benchmark_timer_start(void)
{
NRF_TIMER2->TASKS_START = 1; /* Start Timer */
}
#elif CONFIG_SOC_SERIES_MEC1501X
#define NANOSECS_PER_SEC (1000000000)
#define CYCLES_PER_SEC (48000000)
#define CYCLES_TO_NS(x) ((x) * (NANOSECS_PER_SEC/CYCLES_PER_SEC))
#define CYCLES_TO_NS_AVG(x, NCYCLES) \
(CYCLES_TO_NS(x) / NCYCLES)
/* Configure Timer parameters */
static inline void benchmark_timer_init(void)
{
/* Setup counter */
B32TMR1_REGS->CTRL =
MCHP_BTMR_CTRL_ENABLE |
MCHP_BTMR_CTRL_AUTO_RESTART |
MCHP_BTMR_CTRL_COUNT_UP;
B32TMR1_REGS->PRLD = 0; /* Preload */
B32TMR1_REGS->CNT = 0; /* Counter value */
B32TMR1_REGS->IEN = 0; /* Disable interrupt */
B32TMR1_REGS->STS = 1; /* Clear interrupt */
}
/* Stop the timer */
static inline void benchmark_timer_stop(void)
{
B32TMR1_REGS->CTRL &= ~MCHP_BTMR_CTRL_START;
}
/* Start the timer */
static inline void benchmark_timer_start(void)
{
B32TMR1_REGS->CTRL |= MCHP_BTMR_CTRL_START;
}
#else /* All other architectures */
/* Done because weak attribute doesn't work on static inline. */
static inline void benchmark_timer_init(void) { }
static inline void benchmark_timer_stop(void) { }
static inline void benchmark_timer_start(void) { }
#define CYCLES_TO_NS(x) ((uint32_t)k_cyc_to_ns_floor64(x))
#define CYCLES_TO_NS_AVG(x, NCYCLES) \
((uint32_t)(k_cyc_to_ns_floor64(x) / NCYCLES))
#endif /* CONFIG_NRF_RTC_TIMER */
static inline uint32_t TIMING_INFO_GET_DELTA(uint32_t start, uint32_t end)
{
return (end >= start) ? (end - start) : (ULONG_MAX - start + end);
}
#endif /* _TIMING_INFO_H_ */

20
tests/benchmarks/latency_measure/src/utils.c
View file

@ -1,20 +0,0 @@
/* utils.c - utility functions used by latency measurement */
/*
* Copyright (c) 2012-2014 Wind River Systems, Inc.
*
* SPDX-License-Identifier: Apache-2.0
*/
/*
* DESCRIPTION
* this file contains commonly used functions
*/
#include <zephyr.h>
#include "timestamp.h"
#include "utils.h"
/* scratchpad for the string used to print on console */
char tmp_string[TMP_STRING_SIZE];

88
tests/benchmarks/latency_measure/src/utils.h
View file

@ -1,85 +1,47 @@
/* utils.h - utility functions used by latency measurement */
/* /*
* Copyright (c) 2012-2014 Wind River Systems, Inc. * Copyright (c) 2012-2014 Wind River Systems, Inc.
* *
* SPDX-License-Identifier: Apache-2.0 * SPDX-License-Identifier: Apache-2.0
*/ */
#ifndef _LATENCY_MEASURE_UNIT_H
#define _LATENCY_MEASURE_UNIT_H
/* /*
* DESCRIPTION * @brief This file contains function declarations, macroses and inline functions
* This file contains function declarations, macroses and inline functions
* used in latency measurement. * used in latency measurement.
*/ */
#include "timing_info.h" #include <timing/timing.h>
#include <sys/printk.h>
#include <stdio.h>
#include "timestamp.h"
#define INT_IMM8_OFFSET 1 #define INT_IMM8_OFFSET 1
#define IRQ_PRIORITY 3 #define IRQ_PRIORITY 3
#ifdef CONFIG_PRINTK
#include <sys/printk.h>
#include <stdio.h>
#include "timestamp.h"
extern char tmp_string[];
extern int error_count; extern int error_count;
#define TMP_STRING_SIZE 100
#define PRINT(fmt, ...) printk(fmt, ##__VA_ARGS__)
#define PRINTF(fmt, ...) printf(fmt, ##__VA_ARGS__)
#define PRINT_FORMAT(fmt, ...) \
do { \
snprintf(tmp_string, TMP_STRING_SIZE, fmt, ##__VA_ARGS__); \
PRINTF("|%-77s|\n", tmp_string); \
} while (0)
/**
*
* @brief Print dash line
*
* @return N/A
*/
static inline void print_dash_line(void)
{
PRINTF("|-------------------------------------------------------"
"----------------------|\n");
}
#define PRINT_END_BANNER() \
do { \
PRINTF("| E N D " \
" |\n"); \
print_dash_line(); \
} while (0)
#define PRINT_BANNER() \
do { \
print_dash_line(); \
PRINTF("| Latency Benchmark " \
" |\n"); \
print_dash_line(); \
} while (0)
#define PRINT_TIME_BANNER() \
do { \
PRINT_FORMAT(" tcs = timer clock cycles: 1 tcs is %u nsec", \
CYCLES_TO_NS(1)); \
print_dash_line(); \
} while (0)
#define PRINT_OVERFLOW_ERROR() \ #define PRINT_OVERFLOW_ERROR() \
PRINT_FORMAT(" Error: tick occurred") printk(" Error: tick occurred\n")
#ifdef CSV_FORMAT_OUTPUT
#define FORMAT "%-60s,%8u,%8u\n"
#else #else
#error PRINTK configuration option needs to be enabled #define FORMAT "%-60s:%8u cycles , %8u ns\n"
#endif #endif
void raiseIntFunc(void); #define PRINT_F(...) \
extern void raiseInt(uint8_t id); { \
char sline[256]; \
snprintk(sline, 254, FORMAT, ##__VA_ARGS__); \
printk("%s", sline); \
}
/* pointer to the ISR */ #define PRINT_STATS(x, y) \
typedef void (*ptestIsr) (void *unused); PRINT_F(x, y, (uint32_t)timing_cycles_to_ns(y))
#define PRINT_STATS_AVG(x, y, counter) \
PRINT_F(x, y / counter, (uint32_t)timing_cycles_to_ns_avg(y, counter));
#endif

5
tests/benchmarks/latency_measure/testcase.yaml
View file

@ -1,7 +1,8 @@
tests: tests:
benchmark.kernel.latency: benchmark.kernel.latency:
arch_allow: x86 arm posix arch_allow: x86 arm posix
platform_exclude: qemu_x86_64 # FIXME: no DWT and no RTC_TIMER for qemu_cortex_m0
platform_exclude: qemu_x86_64 qemu_cortex_m0
filter: CONFIG_PRINTK and not CONFIG_SOC_FAMILY_STM32 filter: CONFIG_PRINTK and not CONFIG_SOC_FAMILY_STM32
tags: benchmark tags: benchmark
@ -10,6 +11,8 @@ tests:
# 20 Ticks per secondes allows a frequency up to 335544300Hz (335MHz) # 20 Ticks per secondes allows a frequency up to 335544300Hz (335MHz)
benchmark.kernel.latency.stm32: benchmark.kernel.latency.stm32:
filter: CONFIG_PRINTK and CONFIG_SOC_FAMILY_STM32 filter: CONFIG_PRINTK and CONFIG_SOC_FAMILY_STM32
# FIXME: no DWT and no RTC_TIMER
platform_exclude: qemu_cortex_m0
tags: benchmark tags: benchmark
extra_configs: extra_configs:
- CONFIG_SYS_CLOCK_TICKS_PER_SEC=20 - CONFIG_SYS_CLOCK_TICKS_PER_SEC=20

15
tests/benchmarks/sys_kernel/src/syskernel.c
View file

@ -88,19 +88,6 @@ int check_result(int i, uint32_t t)
return 1; return 1;
} }
/**
*
* @brief Check for a key press
*
* @return 1 when a keyboard key is pressed, or 0 if no keyboard support
*/
int kbhit(void)
{
return 0;
}
/** /**
* *
* @brief Prepares the test output * @brief Prepares the test output
@ -193,7 +180,7 @@ void main(void)
} }
TC_PRINT_RUNID; TC_PRINT_RUNID;
} while (continuously && !kbhit()); } while (continuously);
output_close(); output_close();
} }