patrick/zephyr
1
0
Fork 0
Code Issues Pull requests Actions 7 Packages Projects Releases Wiki Activity

tests: benchmarking: cleanup of the benchmarking code.

Browse source 
The kernel will no longer reference the code written in the
test folder.

GH-1236

Signed-off-by: Adithya Baglody <adithya.nagaraj.baglody@intel.com>
This commit is contained in:
Adithya Baglody 2017-10-31 11:12:56 +05:30 committed by Anas Nashif
parent 7166920a1d
commit edd072e730
8 changed files with 205 additions and 114 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

1
arch/common/Makefile
View file

@ -1 +1,2 @@
obj-$(CONFIG_GEN_ISR_TABLES) += isr_tables.o
obj-$(CONFIG_EXECUTION_BENCHMARKING) += timing_info_bench.o

89
arch/common/timing_info_bench.c Normal file
View file

@ -0,0 +1,89 @@
/*
* Copyright (c) 2017 Intel Corporation.
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <kernel.h>
/* #include <kernel_structs.h> */
u64_t __noinit __start_swap_time;
u64_t __noinit __end_swap_time;
u64_t __noinit __start_intr_time;
u64_t __noinit __end_intr_time;
u64_t __noinit __start_tick_time;
u64_t __noinit __end_tick_time;
/* location of the time stamps*/
u32_t __read_swap_end_time_value;
u64_t __common_var_swap_end_time;
/* NRF RTC TIMER runs ar very slow rate (32KHz), So in order to measure
* Kernel stats dedicated timer is used to measure kernel stats
*/
#if defined(CONFIG_NRF_RTC_TIMER)
#include <arch/arm/cortex_m/cmsis.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])
#define TIMING_INFO_GET_TIMER_VALUE() TIMING_INFO_OS_GET_TIME()
#else /* All other architectures */
#define TIMING_INFO_PRE_READ()
#define TIMING_INFO_OS_GET_TIME() k_cycle_get_32()
#ifdef CONFIG_ARM
#include <arch/arm/cortex_m/cmsis.h>
#define TIMING_INFO_GET_TIMER_VALUE() SysTick->VAL
#endif /* CONFIG_ARM */
#endif /* CONFIG_NRF_RTC_TIMER */
#ifdef CONFIG_ARM
void read_timer_start_of_swap(void)
{
TIMING_INFO_PRE_READ();
__start_swap_time = (u32_t) TIMING_INFO_GET_TIMER_VALUE();
}
void read_timer_end_of_swap(void)
{
if (__read_swap_end_time_value == 1) {
TIMING_INFO_PRE_READ();
__read_swap_end_time_value = 2;
__common_var_swap_end_time = TIMING_INFO_OS_GET_TIME();
}
}
/* ARM processors read current value of time through sysTick timer
* and nrf soc read it though timer
*/
void read_timer_start_of_isr(void)
{
TIMING_INFO_PRE_READ();
__start_intr_time = (u32_t) TIMING_INFO_GET_TIMER_VALUE();
}
void read_timer_end_of_isr(void)
{
TIMING_INFO_PRE_READ();
__end_intr_time = (u32_t) TIMING_INFO_GET_TIMER_VALUE();
}
void read_timer_start_of_tick_handler(void)
{
TIMING_INFO_PRE_READ();
__start_tick_time = (u32_t)TIMING_INFO_GET_TIMER_VALUE();
}
void read_timer_end_of_tick_handler(void)
{
TIMING_INFO_PRE_READ();
__end_tick_time = (u32_t) TIMING_INFO_GET_TIMER_VALUE();
}
#endif /* CONFIG_ARM */

8
kernel/init.c
View file

@ -67,14 +67,6 @@ u64_t __noinit __main_time_stamp; /* timestamp when main task starts */
u64_t __noinit __idle_time_stamp; /* timestamp when CPU goes idle */
#endif
#ifdef CONFIG_EXECUTION_BENCHMARKING
u64_t __noinit __start_swap_time;
u64_t __noinit __end_swap_time;
u64_t __noinit __start_intr_time;
u64_t __noinit __end_intr_time;
u64_t __noinit __start_tick_time;
u64_t __noinit __end_tick_time;
#endif
/* init/main and idle threads */
#define IDLE_STACK_SIZE CONFIG_IDLE_STACK_SIZE

44
tests/benchmarks/timing_info/src/msg_passing_bench.c
View file

@ -156,13 +156,15 @@ void msg_passing_bench(void)
/* Msg queue for get*/
/* from previous step got the msg_q full now just do a simple read*/
msg_q_get_wo_cxt_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
msg_q_get_wo_cxt_start_time = TIMING_INFO_OS_GET_TIME();
received_data_get = k_msgq_get(&benchmark_q_get,
&received_data_consumer,
K_NO_WAIT);
msg_q_get_wo_cxt_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
msg_q_get_wo_cxt_end_time = TIMING_INFO_OS_GET_TIME();
/*******************************************************************/
@ -227,11 +229,13 @@ void msg_passing_bench(void)
.rx_source_thread = K_ANY,
.tx_target_thread = K_ANY
};
mbox_get_w_cxt_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mbox_get_w_cxt_start_time = TIMING_INFO_OS_GET_TIME();
k_mbox_get(&benchmark_mbox, &rx_msg, &single_element_buffer, 300);
mbox_get_w_cxt_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mbox_get_w_cxt_end_time = TIMING_INFO_OS_GET_TIME();
/*******************************************************************/
@ -313,7 +317,8 @@ void thread_producer_msgq_w_cxt_switch(void *p1, void *p2, void *p3)
int data_to_send = 5050;
__read_swap_end_time_value = 1;
__msg_q_put_w_cxt_start_time = (u32_t) GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
__msg_q_put_w_cxt_start_time = (u32_t) TIMING_INFO_OS_GET_TIME();
k_msgq_put(&benchmark_q, &data_to_send, K_NO_WAIT);
}
@ -322,9 +327,13 @@ void thread_producer_msgq_wo_cxt_switch(void *p1, void *p2, void *p3)
{
int data_to_send = 5050;
__msg_q_put_wo_cxt_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
__msg_q_put_wo_cxt_start_time = TIMING_INFO_OS_GET_TIME();
k_msgq_put(&benchmark_q, &data_to_send, K_NO_WAIT);
__msg_q_put_wo_cxt_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
__msg_q_put_wo_cxt_end_time = TIMING_INFO_OS_GET_TIME();
}
@ -345,11 +354,13 @@ void thread_consumer_get_msgq_w_cxt_switch(void *p1, void *p2, void *p3)
producer_get_w_cxt_switch_tid->base.timeout.delta_ticks_from_prev =
_EXPIRED;
__read_swap_end_time_value = 1;
__msg_q_get_w_cxt_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
__msg_q_get_w_cxt_start_time = TIMING_INFO_OS_GET_TIME();
received_data_get = k_msgq_get(&benchmark_q_get,
&received_data_consumer,
300);
time_check = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
time_check = TIMING_INFO_OS_GET_TIME();
}
@ -364,10 +375,12 @@ void thread_mbox_sync_put_send(void *p1, void *p2, void *p3)
.tx_target_thread = K_ANY,
};
mbox_sync_put_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mbox_sync_put_start_time = TIMING_INFO_OS_GET_TIME();
__read_swap_end_time_value = 1;
k_mbox_put(&benchmark_mbox, &tx_msg, 300);
time_check = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
time_check = TIMING_INFO_OS_GET_TIME();
}
void thread_mbox_sync_put_receive(void *p1, void *p2, void *p3)
@ -406,7 +419,8 @@ void thread_mbox_sync_get_receive(void *p1, void *p2, void *p3)
};
__read_swap_end_time_value = 1;
mbox_sync_get_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mbox_sync_get_start_time = TIMING_INFO_OS_GET_TIME();
k_mbox_get(&benchmark_mbox, &rx_msg, &single_element_buffer, 300);
}
@ -421,9 +435,11 @@ void thread_mbox_async_put_send(void *p1, void *p2, void *p3)
.tx_target_thread = K_ANY,
};
mbox_async_put_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mbox_async_put_start_time = TIMING_INFO_OS_GET_TIME();
k_mbox_async_put(&benchmark_mbox, &tx_msg, &mbox_sem);
mbox_async_put_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mbox_async_put_end_time = TIMING_INFO_OS_GET_TIME();
k_mbox_async_put(&benchmark_mbox, &tx_msg, &mbox_sem);
}

39
tests/benchmarks/timing_info/src/semaphore_bench.c
View file

@ -83,17 +83,22 @@ void semaphore_bench(void)
/* Semaphore without context switch*/
u32_t sem_give_wo_cxt_start = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
u32_t sem_give_wo_cxt_start = TIMING_INFO_OS_GET_TIME();
k_sem_give(&sem_bench);
u32_t sem_give_wo_cxt_end = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
u32_t sem_give_wo_cxt_end = TIMING_INFO_OS_GET_TIME();
u32_t sem_give_wo_cxt_cycles = sem_give_wo_cxt_end -
sem_give_wo_cxt_start;
u32_t sem_take_wo_cxt_start = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
u32_t sem_take_wo_cxt_start = TIMING_INFO_OS_GET_TIME();
k_sem_take(&sem_bench, 10);
u32_t sem_take_wo_cxt_end = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
u32_t sem_take_wo_cxt_end = TIMING_INFO_OS_GET_TIME();
u32_t sem_take_wo_cxt_cycles = sem_take_wo_cxt_end -
sem_take_wo_cxt_start;
@ -126,13 +131,21 @@ void mutex_bench(void)
u32_t mutex_unlock_diff = 0;
for (int i = 0; i < 1000; i++) {
mutex_lock_start_time = GET_CURRENT_TIME();
k_mutex_lock(&mutex0, 100);
mutex_lock_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mutex_lock_start_time = TIMING_INFO_OS_GET_TIME();
k_mutex_lock(&mutex0, 100);
TIMING_INFO_PRE_READ();
mutex_lock_end_time = TIMING_INFO_OS_GET_TIME();
TIMING_INFO_PRE_READ();
mutex_unlock_start_time = TIMING_INFO_OS_GET_TIME();
mutex_unlock_start_time = GET_CURRENT_TIME();
k_mutex_unlock(&mutex0);
mutex_unlock_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
mutex_unlock_end_time = TIMING_INFO_OS_GET_TIME();
mutex_lock_diff += (mutex_lock_end_time -
mutex_lock_start_time);
@ -154,7 +167,8 @@ void thread_sem1_test(void *p1, void *p2, void *p3)
k_sem_give(&sem_bench); /* sync the 2 threads*/
__read_swap_end_time_value = 1;
sem_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
sem_start_time = TIMING_INFO_OS_GET_TIME();
k_sem_take(&sem_bench, 10);
}
@ -173,19 +187,18 @@ void thread_sem1_give_test(void *p1, void *p2, void *p3)
k_sem_give(&sem_bench); /* sync the 2 threads*/
k_sem_take(&sem_bench_1, 1000); /* clear the previous sem_give*/
/* test_time1 = GET_CURRENT_TIME(); */
}
void thread_sem0_give_test(void *p1, void *p2, void *p3)
{
k_sem_take(&sem_bench, 10);/* To sync threads */
/* test_time2 = GET_CURRENT_TIME(); */
/* To make sure that the sem give will cause a swap to occur */
k_thread_priority_set(sem1_tid, 1);
__read_swap_end_time_value = 1;
sem_give_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
sem_give_start_time = TIMING_INFO_OS_GET_TIME();
k_sem_give(&sem_bench_1);
}

84
tests/benchmarks/timing_info/src/thread_bench.c
View file

@ -19,8 +19,8 @@ char sline[256];
/* FILE *output_file = stdout; */
/* location of the time stamps*/
u32_t __read_swap_end_time_value;
u64_t __common_var_swap_end_time;
extern u32_t __read_swap_end_time_value;
extern u64_t __common_var_swap_end_time;
volatile u64_t thread_abort_end_time;
volatile u64_t thread_abort_start_time;
@ -85,52 +85,10 @@ u32_t benchmarking_overhead_swap(void)
"pop %edx\n\t"
"pop %eax\n\t");
/* u64_t end_time = GET_CURRENT_TIME(); */
return(test_end_time - start_time);
}
#endif
#if CONFIG_ARM
void read_timer_start_of_swap(void)
{
__start_swap_time = (u32_t) GET_TIMER_VALUE();
}
void read_timer_end_of_swap(void)
{
if (__read_swap_end_time_value == 1) {
__read_swap_end_time_value = 2;
__common_var_swap_end_time = GET_CURRENT_TIME();
}
}
/* ARM processors read current value of time through sysTick timer
* and nrf soc read it though timer
*/
void read_timer_start_of_isr(void)
{
__start_intr_time = (u32_t) GET_TIMER_VALUE();
}
void read_timer_end_of_isr(void)
{
__end_intr_time = (u32_t) GET_TIMER_VALUE();
}
void read_timer_start_of_tick_handler(void)
{
__start_tick_time = (u32_t)GET_TIMER_VALUE();
}
void read_timer_end_of_tick_handler(void)
{
__end_tick_time = (u32_t) GET_TIMER_VALUE();
}
#endif /* CONFIG_ARM */
void test_thread_entry(void *p, void *p1, void *p2)
{
static int i;
@ -142,7 +100,8 @@ void test_thread_entry(void *p, void *p1, void *p2)
void thread_swap_test(void *p1, void *p2, void *p3)
{
__read_swap_end_time_value = 1;
thread_abort_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_abort_start_time = TIMING_INFO_OS_GET_TIME();
k_thread_abort(_current);
}
@ -202,20 +161,24 @@ void system_thread_bench(void)
/*******************************************************************/
/* thread create*/
thread_create_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_create_start_time = TIMING_INFO_OS_GET_TIME();
k_tid_t my_tid = k_thread_create(&my_thread, my_stack_area,
STACK_SIZE,
thread_swap_test,
NULL, NULL, NULL,
5 /*priority*/, 0, 10);
thread_create_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_create_end_time = TIMING_INFO_OS_GET_TIME();
/* thread Termination*/
thread_cancel_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_cancel_start_time = TIMING_INFO_OS_GET_TIME();
s32_t ret_value_thread_cancel = k_thread_cancel(my_tid);
thread_cancel_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_cancel_end_time = TIMING_INFO_OS_GET_TIME();
ARG_UNUSED(ret_value_thread_cancel);
/* Thread suspend*/
@ -225,7 +188,8 @@ void system_thread_bench(void)
NULL, NULL, NULL,
-1 /*priority*/, 0, 0);
thread_suspend_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_suspend_end_time = TIMING_INFO_OS_GET_TIME();
/* At this point test for resume*/
k_thread_resume(sus_res_tid);
@ -304,11 +268,13 @@ void system_thread_bench(void)
void thread_suspend_test(void *p1, void *p2, void *p3)
{
thread_suspend_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_suspend_start_time = TIMING_INFO_OS_GET_TIME();
k_thread_suspend(_current);
/* comes to this line once its resumed*/
thread_resume_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_resume_end_time = TIMING_INFO_OS_GET_TIME();
/* k_thread_suspend(_current); */
}
@ -328,17 +294,23 @@ void heap_malloc_free_bench(void)
u32_t sum_free = 0;
while (count++ != 100) {
heap_malloc_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
heap_malloc_start_time = TIMING_INFO_OS_GET_TIME();
void *allocated_mem = k_malloc(10);
heap_malloc_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
heap_malloc_end_time = TIMING_INFO_OS_GET_TIME();
if (allocated_mem == NULL) {
TC_PRINT("\n Malloc failed at count %d\n", count);
break;
}
heap_free_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
heap_free_start_time = TIMING_INFO_OS_GET_TIME();
k_free(allocated_mem);
heap_free_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
heap_free_end_time = TIMING_INFO_OS_GET_TIME();
sum_malloc += heap_malloc_end_time - heap_malloc_start_time;
sum_free += heap_free_end_time - heap_free_start_time;
}

45
tests/benchmarks/timing_info/src/timing_info.h
View file

@ -13,22 +13,11 @@
special_char##profile##_##name##_start_time); \
}
/*total_##profile##_##name##_time =
* profile##_##name##_end_us - profile##_##name##_start_us;
*/
#define DECLARE_VAR(profile, name) \
u64_t total_##profile##_##name##_time;
extern u64_t __start_swap_time;
extern u64_t __end_swap_time;
extern u64_t __start_intr_time;
extern u64_t __end_intr_time;
extern u64_t __start_tick_time;
extern u64_t __end_tick_time;
/* NRF RTC TIMER runs ar very slow rate (32KHz), So in order to measure
* Kernel stats dedicated timer is used to measure kernel stats
* Kernel starts a dedicated timer to measure kernel stats.
*/
#if defined(CONFIG_NRF_RTC_TIMER)
#define NANOSECS_PER_SEC 1000000000
@ -37,12 +26,13 @@ extern u64_t __end_tick_time;
* Capture Register and Current Count will be copied into corresponding
* current count register.
*/
#define GET_CURRENT_TIME() ((NRF_TIMER2->TASKS_CAPTURE[0] = 1) ? \
NRF_TIMER2->CC[0] : 0)
#define TIMING_INFO_PRE_READ() (NRF_TIMER2->TASKS_CAPTURE[0] = 1)
#define TIMING_INFO_OS_GET_TIME() (NRF_TIMER2->CC[0])
#define TIMING_INFO_GET_TIMER_VALUE() TIMING_INFO_GET_CURRENT_TIME()
#define CYCLES_TO_NS(x) ((x) * (NANOSECS_PER_SEC/CYCLES_PER_SEC))
#define PRINT_STATS(x, y, z) PRINT_F(x, (y*((SystemCoreClock)/ \
CYCLES_PER_SEC)), z)
#define GET_TIMER_VALUE() GET_CURRENT_TIME()
/* Configure Timer parameters */
static inline void benchmark_timer_init(void)
@ -71,15 +61,22 @@ static inline u32_t get_core_freq_MHz(void)
return SystemCoreClock/1000000;
}
#else
#define GET_CURRENT_TIME() OS_GET_TIME()
#define CYCLES_TO_NS(x) SYS_CLOCK_HW_CYCLES_TO_NS(x)
#define GET_TIMER_VALUE() SysTick->VAL
/* Dummy functions for timer */
#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 TIMING_INFO_PRE_READ()
#define TIMING_INFO_OS_GET_TIME() k_cycle_get_32()
#ifdef CONFIG_ARM
#define TIMING_INFO_GET_TIMER_VALUE() SysTick->VAL
#endif /* CONFIG_ARM */
#define CYCLES_TO_NS(x) SYS_CLOCK_HW_CYCLES_TO_NS(x)
/* Dummy functions for timer */
/* Get Core Frequency in MHz */
static inline u32_t get_core_freq_MHz(void)
{
@ -97,6 +94,14 @@ void semaphore_bench(void);
void mutex_bench(void);
void msg_passing_bench(void);
/* External variables */
extern u64_t __start_swap_time;
extern u64_t __end_swap_time;
extern u64_t __start_intr_time;
extern u64_t __end_intr_time;
extern u64_t __start_tick_time;
extern u64_t __end_tick_time;
/* PRINT_F
* Macro to print a formatted output string. fprintf is used when
* Assumed that sline character array of SLINE_LEN + 1 characters

9
tests/benchmarks/timing_info/src/yield_bench.c
View file

@ -57,7 +57,8 @@ void yield_bench(void)
/*read the time of start of the sleep till the swap happens */
__read_swap_end_time_value = 1;
thread_sleep_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_sleep_start_time = TIMING_INFO_OS_GET_TIME();
k_sleep(1000);
thread_sleep_end_time = ((u32_t)__common_var_swap_end_time);
@ -75,12 +76,14 @@ void yield_bench(void)
void thread_yield0_test(void *p1, void *p2, void *p3)
{
k_sem_take(&yield_sem, 10);
thread_start_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_start_time = TIMING_INFO_OS_GET_TIME();
while (count != 1000) {
count++;
k_yield();
}
thread_end_time = GET_CURRENT_TIME();
TIMING_INFO_PRE_READ();
thread_end_time = TIMING_INFO_OS_GET_TIME();
k_thread_abort(yield1_tid);
}