From 76b577e180f81faaa8d27c12b958d03e6c9decd2 Mon Sep 17 00:00:00 2001 From: Youvedeep Singh Date: Thu, 31 Aug 2017 20:05:05 +0530 Subject: [PATCH] tests: benchmark: timing_info: Change API/variable Name. The API/Variable names in timing_info looks very speicific to platform (like systick etc), whereas these variabled are used across platforms (nrf/arm/quark). So this patch :- 1. changing API/Variable names to generic one. 2. Creating some of Macros whose implimentation is platform depenent. Jira: ZEP-2314 Signed-off-by: Youvedeep Singh --- arch/arm/core/isr_wrapper.S | 4 +- arch/arm/core/swap.S | 4 +- arch/x86/core/intstub.S | 8 +- arch/x86/core/swap.S | 10 +- drivers/timer/cortex_m_systick.c | 8 +- drivers/timer/loapic_timer.c | 8 +- kernel/init.c | 12 +- .../timing_info/src/msg_passing_bench.c | 120 ++++++------ .../timing_info/src/semaphore_bench.c | 80 ++++---- .../benchmarks/timing_info/src/thread_bench.c | 178 +++++++++--------- .../benchmarks/timing_info/src/timing_info.h | 27 +-- .../benchmarks/timing_info/src/yield_bench.c | 28 +-- 12 files changed, 246 insertions(+), 241 deletions(-) diff --git a/arch/arm/core/isr_wrapper.S b/arch/arm/core/isr_wrapper.S index b26c4112b57..68a0e846192 100644 --- a/arch/arm/core/isr_wrapper.S +++ b/arch/arm/core/isr_wrapper.S @@ -44,7 +44,7 @@ SECTION_FUNC(TEXT, _isr_wrapper) push {lr} /* lr is now the first item on the stack */ #ifdef CONFIG_EXECUTION_BENCHMARKING - bl read_systick_start_of_isr + bl read_timer_start_of_isr #endif #ifdef CONFIG_KERNEL_EVENT_LOGGER_INTERRUPT @@ -114,7 +114,7 @@ _idle_state_cleared: push {r3} #endif push {lr} - bl read_systick_end_of_isr + bl read_timer_end_of_isr #if defined(CONFIG_ARMV6_M) pop {r3} mov lr,r3 diff --git a/arch/arm/core/swap.S b/arch/arm/core/swap.S index 2280ba7656b..d05dfbc57ec 100644 --- a/arch/arm/core/swap.S +++ b/arch/arm/core/swap.S @@ -190,7 +190,7 @@ _thread_irq_disabled: #endif push {lr} - bl read_systick_end_of_swap + bl read_timer_end_of_swap #if defined(CONFIG_ARMV6_M) pop {r3} @@ -367,7 +367,7 @@ SECTION_FUNC(TEXT, __swap) push {r3} #endif push {lr} - bl read_systick_start_of_swap + bl read_timer_start_of_swap #if defined(CONFIG_ARMV6_M) pop {r3} mov lr,r3 diff --git a/arch/x86/core/intstub.S b/arch/x86/core/intstub.S index c3bf02fd99d..79b24f8f8eb 100644 --- a/arch/x86/core/intstub.S +++ b/arch/x86/core/intstub.S @@ -82,8 +82,8 @@ SECTION_FUNC(TEXT, _interrupt_enter) pushl %eax pushl %edx rdtsc - mov %eax, __start_intr_tsc - mov %edx, __start_intr_tsc+4 + mov %eax, __start_intr_time + mov %edx, __start_intr_time+4 pop %edx pop %eax #endif @@ -262,8 +262,8 @@ alreadyOnIntStack: pushl %eax pushl %edx rdtsc - mov %eax,__end_intr_tsc - mov %edx,__end_intr_tsc+4 + mov %eax,__end_intr_time + mov %edx,__end_intr_time+4 pop %edx pop %eax #endif diff --git a/arch/x86/core/swap.S b/arch/x86/core/swap.S index 8687ebec49a..c2a80bf447b 100644 --- a/arch/x86/core/swap.S +++ b/arch/x86/core/swap.S @@ -94,8 +94,8 @@ SECTION_FUNC(TEXT, __swap) push %eax push %edx rdtsc - mov %eax,__start_swap_tsc - mov %edx,__start_swap_tsc+4 + mov %eax,__start_swap_time + mov %edx,__start_swap_time+4 pop %edx pop %eax #endif @@ -362,10 +362,10 @@ skipIntLatencyStop: /* Save the eax and edx registers before reading the time stamp * once done pop the values. */ - cmp $0x1,__read_swap_end_tsc_value + cmp $0x1,__read_swap_end_time_value jne time_read_not_needed - movw $0x2,__read_swap_end_tsc_value - read_tsc __common_var_swap_end_tsc + movw $0x2,__read_swap_end_time_value + read_tsc __common_var_swap_end_time time_read_not_needed: #endif ret diff --git a/drivers/timer/cortex_m_systick.c b/drivers/timer/cortex_m_systick.c index 8d6b646b921..a01b4c558e1 100644 --- a/drivers/timer/cortex_m_systick.c +++ b/drivers/timer/cortex_m_systick.c @@ -216,8 +216,8 @@ void _timer_int_handler(void *unused) ARG_UNUSED(unused); #ifdef CONFIG_EXECUTION_BENCHMARKING - extern void read_systick_start_of_tick_handler(void); - read_systick_start_of_tick_handler(); + extern void read_timer_start_of_tick_handler(void); + read_timer_start_of_tick_handler(); #endif #ifdef CONFIG_KERNEL_EVENT_LOGGER_INTERRUPT @@ -350,8 +350,8 @@ void _timer_int_handler(void *unused) #endif /* CONFIG_SYS_POWER_MANAGEMENT */ #ifdef CONFIG_EXECUTION_BENCHMARKING - extern void read_systick_end_of_tick_handler(void); - read_systick_end_of_tick_handler(); + extern void read_timer_end_of_tick_handler(void); + read_timer_end_of_tick_handler(); #endif extern void _ExcExit(void); diff --git a/drivers/timer/loapic_timer.c b/drivers/timer/loapic_timer.c index 1128fb57bd6..ab127c5b6d9 100644 --- a/drivers/timer/loapic_timer.c +++ b/drivers/timer/loapic_timer.c @@ -257,8 +257,8 @@ void _timer_int_handler(void *unused /* parameter is not used */ "pushl %eax\n\t" "pushl %edx\n\t" "rdtsc\n\t" - "mov %eax, __start_tick_tsc\n\t" - "mov %edx, __start_tick_tsc+4\n\t" + "mov %eax, __start_tick_time\n\t" + "mov %edx, __start_tick_time+4\n\t" "pop %edx\n\t" "pop %eax\n\t"); #endif @@ -339,8 +339,8 @@ void _timer_int_handler(void *unused /* parameter is not used */ "pushl %eax\n\t" "pushl %edx\n\t" "rdtsc\n\t" - "mov %eax, __end_tick_tsc\n\t" - "mov %edx, __end_tick_tsc+4\n\t" + "mov %eax, __end_tick_time\n\t" + "mov %edx, __end_tick_time+4\n\t" "pop %edx\n\t" "pop %eax\n\t"); #endif /* CONFIG_EXECUTION_BENCHMARKING */ diff --git a/kernel/init.c b/kernel/init.c index cade51a237b..39b0f0c69dd 100644 --- a/kernel/init.c +++ b/kernel/init.c @@ -67,12 +67,12 @@ u64_t __noinit __idle_time_stamp; /* timestamp when CPU goes idle */ #endif #ifdef CONFIG_EXECUTION_BENCHMARKING -u64_t __noinit __start_swap_tsc; -u64_t __noinit __end_swap_tsc; -u64_t __noinit __start_intr_tsc; -u64_t __noinit __end_intr_tsc; -u64_t __noinit __start_tick_tsc; -u64_t __noinit __end_tick_tsc; +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 */ diff --git a/tests/benchmarks/timing_info/src/msg_passing_bench.c b/tests/benchmarks/timing_info/src/msg_passing_bench.c index 1163d22ff75..6ff5a2bde91 100644 --- a/tests/benchmarks/timing_info/src/msg_passing_bench.c +++ b/tests/benchmarks/timing_info/src/msg_passing_bench.c @@ -23,38 +23,38 @@ K_MBOX_DEFINE(benchmark_mbox); K_SEM_DEFINE(mbox_sem, 1, 1); /* common location for the swap to write the tsc data*/ -extern u32_t __read_swap_end_tsc_value; -extern u64_t __common_var_swap_end_tsc; +extern u32_t __read_swap_end_time_value; +extern u64_t __common_var_swap_end_time; /* location of the time stamps*/ u64_t __msg_q_put_state; u64_t __msg_q_get_state; -u64_t __msg_q_put_w_cxt_start_tsc; -u64_t __msg_q_put_w_cxt_end_tsc; +u64_t __msg_q_put_w_cxt_start_time; +u64_t __msg_q_put_w_cxt_end_time; -u64_t __msg_q_put_wo_cxt_start_tsc; /* without context switch */ -u64_t __msg_q_put_wo_cxt_end_tsc; +u64_t __msg_q_put_wo_cxt_start_time; /* without context switch */ +u64_t __msg_q_put_wo_cxt_end_time; -u64_t __msg_q_get_w_cxt_start_tsc; -u64_t __msg_q_get_w_cxt_end_tsc; +u64_t __msg_q_get_w_cxt_start_time; +u64_t __msg_q_get_w_cxt_end_time; -u64_t msg_q_get_wo_cxt_start_tsc; -u64_t msg_q_get_wo_cxt_end_tsc; +u64_t msg_q_get_wo_cxt_start_time; +u64_t msg_q_get_wo_cxt_end_time; u32_t __mbox_sync_put_state; -u64_t mbox_sync_put_start_tsc; -u64_t mbox_sync_put_end_tsc; +u64_t mbox_sync_put_start_time; +u64_t mbox_sync_put_end_time; u32_t __mbox_sync_get_state; -u64_t mbox_sync_get_start_tsc; -u64_t mbox_sync_get_end_tsc; +u64_t mbox_sync_get_start_time; +u64_t mbox_sync_get_end_time; -u64_t mbox_async_put_start_tsc; -u64_t mbox_async_put_end_tsc; +u64_t mbox_async_put_start_time; +u64_t mbox_async_put_end_time; -u64_t mbox_get_w_cxt_start_tsc; -u64_t mbox_get_w_cxt_end_tsc; +u64_t mbox_get_w_cxt_start_time; +u64_t mbox_get_w_cxt_end_time; /*For benchmarking msg queues*/ k_tid_t producer_w_cxt_switch_tid; @@ -130,7 +130,7 @@ void msg_passing_bench(void) k_thread_abort(producer_w_cxt_switch_tid); k_thread_abort(producer_wo_cxt_switch_tid); - __msg_q_put_w_cxt_end_tsc = ((u32_t)__common_var_swap_end_tsc); + __msg_q_put_w_cxt_end_time = ((u32_t)__common_var_swap_end_time); ARG_UNUSED(msg_status); /*******************************************************************/ @@ -150,19 +150,19 @@ void msg_passing_bench(void) 2 /*priority*/, 0, 50); k_sleep(2000); /* make the main thread sleep */ k_thread_abort(producer_get_w_cxt_switch_tid); - __msg_q_get_w_cxt_end_tsc = (__common_var_swap_end_tsc); + __msg_q_get_w_cxt_end_time = (__common_var_swap_end_time); /*******************************************************************/ /* Msg queue for get*/ /* from previous step got the msg_q full now just do a simple read*/ - msg_q_get_wo_cxt_start_tsc = OS_GET_TIME(); + msg_q_get_wo_cxt_start_time = GET_CURRENT_TIME(); received_data_get = k_msgq_get(&benchmark_q_get, &received_data_consumer, K_NO_WAIT); - msg_q_get_wo_cxt_end_tsc = OS_GET_TIME(); + msg_q_get_wo_cxt_end_time = GET_CURRENT_TIME(); /*******************************************************************/ @@ -182,7 +182,7 @@ void msg_passing_bench(void) NULL, NULL, NULL, 1 /*priority*/, 0, 0); k_sleep(1000); /* make the main thread sleep */ - mbox_sync_put_end_tsc = (__common_var_swap_end_tsc); + mbox_sync_put_end_time = (__common_var_swap_end_time); /*******************************************************************/ @@ -200,7 +200,7 @@ void msg_passing_bench(void) thread_mbox_sync_get_receive, NULL, NULL, NULL, 2 /*priority*/, 0, 0); k_sleep(1000); /* make the main thread sleep */ - mbox_sync_get_end_tsc = (__common_var_swap_end_tsc); + mbox_sync_get_end_time = (__common_var_swap_end_time); /*******************************************************************/ @@ -227,11 +227,11 @@ void msg_passing_bench(void) .rx_source_thread = K_ANY, .tx_target_thread = K_ANY }; - mbox_get_w_cxt_start_tsc = OS_GET_TIME(); + mbox_get_w_cxt_start_time = GET_CURRENT_TIME(); k_mbox_get(&benchmark_mbox, &rx_msg, &single_element_buffer, 300); - mbox_get_w_cxt_end_tsc = OS_GET_TIME(); + mbox_get_w_cxt_end_time = GET_CURRENT_TIME(); /*******************************************************************/ @@ -266,43 +266,43 @@ void msg_passing_bench(void) /*******************************************************************/ /* Only print lower 32bit of time result */ - PRINT_F("Message Queue Put with context switch", - (u32_t)((__msg_q_put_w_cxt_end_tsc - - __msg_q_put_w_cxt_start_tsc) & 0xFFFFFFFFULL), + PRINT_STATS("Message Queue Put with context switch", + (u32_t)((__msg_q_put_w_cxt_end_time - + __msg_q_put_w_cxt_start_time) & 0xFFFFFFFFULL), (u32_t) (total_msg_q_put_w_cxt_time & 0xFFFFFFFFULL)); - PRINT_F("Message Queue Put without context switch", - (u32_t)((__msg_q_put_wo_cxt_end_tsc - - __msg_q_put_wo_cxt_start_tsc) & 0xFFFFFFFFULL), + PRINT_STATS("Message Queue Put without context switch", + (u32_t)((__msg_q_put_wo_cxt_end_time - + __msg_q_put_wo_cxt_start_time) & 0xFFFFFFFFULL), (u32_t) (total_msg_q_put_wo_cxt_time & 0xFFFFFFFFULL)); - PRINT_F("Message Queue get with context switch", - (u32_t)((__msg_q_get_w_cxt_end_tsc - - __msg_q_get_w_cxt_start_tsc) & 0xFFFFFFFFULL), + PRINT_STATS("Message Queue get with context switch", + (u32_t)((__msg_q_get_w_cxt_end_time - + __msg_q_get_w_cxt_start_time) & 0xFFFFFFFFULL), (u32_t) (total_msg_q_get_w_cxt_time & 0xFFFFFFFFULL)); - PRINT_F("Message Queue get without context switch", - (u32_t)((msg_q_get_wo_cxt_end_tsc - - msg_q_get_wo_cxt_start_tsc) & 0xFFFFFFFFULL), + PRINT_STATS("Message Queue get without context switch", + (u32_t)((msg_q_get_wo_cxt_end_time - + msg_q_get_wo_cxt_start_time) & 0xFFFFFFFFULL), (u32_t) (total_msg_q_get_wo_cxt_time & 0xFFFFFFFFULL)); - PRINT_F("MailBox synchronous put", - (u32_t)((mbox_sync_put_end_tsc - mbox_sync_put_start_tsc) + PRINT_STATS("MailBox synchronous put", + (u32_t)((mbox_sync_put_end_time - mbox_sync_put_start_time) & 0xFFFFFFFFULL), (u32_t) (total_mbox_sync_put_time & 0xFFFFFFFFULL)); - PRINT_F("MailBox synchronous get", - (u32_t)((mbox_sync_get_end_tsc - mbox_sync_get_start_tsc) + PRINT_STATS("MailBox synchronous get", + (u32_t)((mbox_sync_get_end_time - mbox_sync_get_start_time) & 0xFFFFFFFFULL), (u32_t) (total_mbox_sync_get_time & 0xFFFFFFFFULL)); - PRINT_F("MailBox asynchronous put", - (u32_t)((mbox_async_put_end_tsc - mbox_async_put_start_tsc) + PRINT_STATS("MailBox asynchronous put", + (u32_t)((mbox_async_put_end_time - mbox_async_put_start_time) & 0xFFFFFFFFULL), (u32_t) (total_mbox_async_put_time & 0xFFFFFFFFULL)); - PRINT_F("MailBox get without context switch", - (u32_t)((mbox_get_w_cxt_end_tsc - mbox_get_w_cxt_start_tsc) + PRINT_STATS("MailBox get without context switch", + (u32_t)((mbox_get_w_cxt_end_time - mbox_get_w_cxt_start_time) & 0xFFFFFFFFULL), (u32_t) (total_mbox_get_w_cxt_time & 0xFFFFFFFFULL)); @@ -312,8 +312,8 @@ void thread_producer_msgq_w_cxt_switch(void *p1, void *p2, void *p3) { int data_to_send = 5050; - __read_swap_end_tsc_value = 1; - __msg_q_put_w_cxt_start_tsc = (u32_t) OS_GET_TIME(); + __read_swap_end_time_value = 1; + __msg_q_put_w_cxt_start_time = (u32_t) GET_CURRENT_TIME(); k_msgq_put(&benchmark_q, &data_to_send, K_NO_WAIT); } @@ -322,9 +322,9 @@ void thread_producer_msgq_wo_cxt_switch(void *p1, void *p2, void *p3) { int data_to_send = 5050; - __msg_q_put_wo_cxt_start_tsc = OS_GET_TIME(); + __msg_q_put_wo_cxt_start_time = GET_CURRENT_TIME(); k_msgq_put(&benchmark_q, &data_to_send, K_NO_WAIT); - __msg_q_put_wo_cxt_end_tsc = OS_GET_TIME(); + __msg_q_put_wo_cxt_end_time = GET_CURRENT_TIME(); } @@ -344,12 +344,12 @@ 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_tsc_value = 1; - __msg_q_get_w_cxt_start_tsc = OS_GET_TIME(); + __read_swap_end_time_value = 1; + __msg_q_get_w_cxt_start_time = GET_CURRENT_TIME(); received_data_get = k_msgq_get(&benchmark_q_get, &received_data_consumer, 300); - time_check = OS_GET_TIME(); + time_check = GET_CURRENT_TIME(); } @@ -364,10 +364,10 @@ void thread_mbox_sync_put_send(void *p1, void *p2, void *p3) .tx_target_thread = K_ANY, }; - mbox_sync_put_start_tsc = OS_GET_TIME(); - __read_swap_end_tsc_value = 1; + mbox_sync_put_start_time = GET_CURRENT_TIME(); + __read_swap_end_time_value = 1; k_mbox_put(&benchmark_mbox, &tx_msg, 300); - time_check = OS_GET_TIME(); + time_check = GET_CURRENT_TIME(); } void thread_mbox_sync_put_receive(void *p1, void *p2, void *p3) @@ -405,8 +405,8 @@ void thread_mbox_sync_get_receive(void *p1, void *p2, void *p3) .tx_target_thread = K_ANY }; - __read_swap_end_tsc_value = 1; - mbox_sync_get_start_tsc = OS_GET_TIME(); + __read_swap_end_time_value = 1; + mbox_sync_get_start_time = GET_CURRENT_TIME(); k_mbox_get(&benchmark_mbox, &rx_msg, &single_element_buffer, 300); } @@ -421,9 +421,9 @@ void thread_mbox_async_put_send(void *p1, void *p2, void *p3) .tx_target_thread = K_ANY, }; - mbox_async_put_start_tsc = OS_GET_TIME(); + mbox_async_put_start_time = GET_CURRENT_TIME(); k_mbox_async_put(&benchmark_mbox, &tx_msg, &mbox_sem); - mbox_async_put_end_tsc = OS_GET_TIME(); + mbox_async_put_end_time = GET_CURRENT_TIME(); k_mbox_async_put(&benchmark_mbox, &tx_msg, &mbox_sem); } diff --git a/tests/benchmarks/timing_info/src/semaphore_bench.c b/tests/benchmarks/timing_info/src/semaphore_bench.c index 72d205013c6..ceabe98dc5d 100644 --- a/tests/benchmarks/timing_info/src/semaphore_bench.c +++ b/tests/benchmarks/timing_info/src/semaphore_bench.c @@ -23,8 +23,8 @@ extern K_THREAD_STACK_DEFINE(my_stack_area_0, STACK_SIZE); extern struct k_thread my_thread; extern struct k_thread my_thread_0; -/* u64_t thread_yield_start_tsc[1000]; */ -/* u64_t thread_yield_end_tsc[1000]; */ +/* u64_t thread_yield_start_time[1000]; */ +/* u64_t thread_yield_end_time[1000]; */ u64_t thread_start_time; u64_t thread_end_time; u64_t sem_start_time; @@ -44,8 +44,8 @@ void thread_sem1_give_test(void *p1, void *p2, void *p3); k_tid_t sem0_tid; k_tid_t sem1_tid; -extern u64_t __common_var_swap_end_tsc; -extern u32_t __read_swap_end_tsc_value; +extern u64_t __common_var_swap_end_time; +extern u32_t __read_swap_end_time_value; void semaphore_bench(void) { @@ -65,7 +65,7 @@ void semaphore_bench(void) /* u64_t test_time1 = _tsc_read(); */ - sem_end_time = (__common_var_swap_end_tsc); + sem_end_time = (__common_var_swap_end_time); u32_t sem_cycles = sem_end_time - sem_start_time; sem0_tid = k_thread_create(&my_thread, my_stack_area, @@ -78,73 +78,73 @@ void semaphore_bench(void) 2 /*priority*/, 0, 0); k_sleep(1000); - sem_give_end_time = (__common_var_swap_end_tsc); + sem_give_end_time = (__common_var_swap_end_time); u32_t sem_give_cycles = sem_give_end_time - sem_give_start_time; /* Semaphore without context switch*/ - u32_t sem_give_wo_cxt_start = OS_GET_TIME(); + u32_t sem_give_wo_cxt_start = GET_CURRENT_TIME(); k_sem_give(&sem_bench); - u32_t sem_give_wo_cxt_end = OS_GET_TIME(); + u32_t sem_give_wo_cxt_end = GET_CURRENT_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 = OS_GET_TIME(); + u32_t sem_take_wo_cxt_start = GET_CURRENT_TIME(); k_sem_take(&sem_bench, 10); - u32_t sem_take_wo_cxt_end = OS_GET_TIME(); + u32_t sem_take_wo_cxt_end = GET_CURRENT_TIME(); u32_t sem_take_wo_cxt_cycles = sem_take_wo_cxt_end - sem_take_wo_cxt_start; /* TC_PRINT("test_time1 , %d cycles\n", (u32_t)test_time1); */ /* TC_PRINT("test_time2 , %d cycles\n", (u32_t)test_time2); */ - PRINT_F("Semaphore Take with context switch", - sem_cycles, SYS_CLOCK_HW_CYCLES_TO_NS(sem_cycles)); - PRINT_F("Semaphore Give with context switch", - sem_give_cycles, SYS_CLOCK_HW_CYCLES_TO_NS(sem_give_cycles)); + PRINT_STATS("Semaphore Take with context switch", + sem_cycles, CYCLES_TO_NS(sem_cycles)); + PRINT_STATS("Semaphore Give with context switch", + sem_give_cycles, CYCLES_TO_NS(sem_give_cycles)); - PRINT_F("Semaphore Take without context switch", + PRINT_STATS("Semaphore Take without context switch", sem_take_wo_cxt_cycles, - SYS_CLOCK_HW_CYCLES_TO_NS(sem_take_wo_cxt_cycles)); - PRINT_F("Semaphore Give without context switch", + CYCLES_TO_NS(sem_take_wo_cxt_cycles)); + PRINT_STATS("Semaphore Give without context switch", sem_give_wo_cxt_cycles, - SYS_CLOCK_HW_CYCLES_TO_NS(sem_give_wo_cxt_cycles)); + CYCLES_TO_NS(sem_give_wo_cxt_cycles)); } /******************************************************************************/ K_MUTEX_DEFINE(mutex0); void mutex_bench(void) { - u32_t mutex_lock_start_tsc; - u32_t mutex_lock_end_tsc; + u32_t mutex_lock_start_time; + u32_t mutex_lock_end_time; u32_t mutex_lock_diff = 0; - u32_t mutex_unlock_start_tsc; - u32_t mutex_unlock_end_tsc; + u32_t mutex_unlock_start_time; + u32_t mutex_unlock_end_time; u32_t mutex_unlock_diff = 0; for (int i = 0; i < 1000; i++) { - mutex_lock_start_tsc = OS_GET_TIME(); + mutex_lock_start_time = GET_CURRENT_TIME(); k_mutex_lock(&mutex0, 100); - mutex_lock_end_tsc = OS_GET_TIME(); + mutex_lock_end_time = GET_CURRENT_TIME(); - mutex_unlock_start_tsc = OS_GET_TIME(); + mutex_unlock_start_time = GET_CURRENT_TIME(); k_mutex_unlock(&mutex0); - mutex_unlock_end_tsc = OS_GET_TIME(); + mutex_unlock_end_time = GET_CURRENT_TIME(); - mutex_lock_diff += (mutex_lock_end_tsc - mutex_lock_start_tsc); - mutex_unlock_diff += (mutex_unlock_end_tsc - - mutex_unlock_start_tsc); + mutex_lock_diff += (mutex_lock_end_time - + mutex_lock_start_time); + mutex_unlock_diff += (mutex_unlock_end_time - + mutex_unlock_start_time); } - PRINT_F("Mutex lock", mutex_lock_diff / 1000, - SYS_CLOCK_HW_CYCLES_TO_NS(mutex_lock_diff / 1000)); - - PRINT_F("Mutex unlock", mutex_unlock_diff / 1000, - SYS_CLOCK_HW_CYCLES_TO_NS(mutex_unlock_diff / 1000)); + PRINT_STATS("Mutex lock", mutex_lock_diff / 1000, + CYCLES_TO_NS(mutex_lock_diff / 1000)); + PRINT_STATS("Mutex unlock", mutex_unlock_diff / 1000, + CYCLES_TO_NS(mutex_unlock_diff / 1000)); } /******************************************************************************/ @@ -153,8 +153,8 @@ void thread_sem1_test(void *p1, void *p2, void *p3) k_sem_give(&sem_bench); /* sync the 2 threads*/ - __read_swap_end_tsc_value = 1; - sem_start_time = OS_GET_TIME(); + __read_swap_end_time_value = 1; + sem_start_time = GET_CURRENT_TIME(); k_sem_take(&sem_bench, 10); } @@ -173,19 +173,19 @@ 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 = OS_GET_TIME(); */ + /* 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 = OS_GET_TIME(); */ + /* 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_tsc_value = 1; - sem_give_start_time = OS_GET_TIME(); + __read_swap_end_time_value = 1; + sem_give_start_time = GET_CURRENT_TIME(); k_sem_give(&sem_bench_1); } diff --git a/tests/benchmarks/timing_info/src/thread_bench.c b/tests/benchmarks/timing_info/src/thread_bench.c index 1e6ad94a943..933ee21c5e6 100644 --- a/tests/benchmarks/timing_info/src/thread_bench.c +++ b/tests/benchmarks/timing_info/src/thread_bench.c @@ -15,28 +15,27 @@ #include #include #include "timing_info.h" - char sline[256]; /* FILE *output_file = stdout; */ /* location of the time stamps*/ -u32_t __read_swap_end_tsc_value; -u64_t __common_var_swap_end_tsc; +u32_t __read_swap_end_time_value; +u64_t __common_var_swap_end_time; -volatile u64_t thread_abort_end_tsc; -volatile u64_t thread_abort_start_tsc; +volatile u64_t thread_abort_end_time; +volatile u64_t thread_abort_start_time; /* Thread suspend*/ -volatile u64_t thread_suspend_start_tsc; -volatile u64_t thread_suspend_end_tsc; +volatile u64_t thread_suspend_start_time; +volatile u64_t thread_suspend_end_time; /* Thread resume*/ -volatile u64_t thread_resume_start_tsc; -volatile u64_t thread_resume_end_tsc; +volatile u64_t thread_resume_start_time; +volatile u64_t thread_resume_end_time; /* Thread sleep*/ -volatile u64_t thread_sleep_start_tsc; -volatile u64_t thread_sleep_end_tsc; +volatile u64_t thread_sleep_start_time; +volatile u64_t thread_sleep_end_time; /*For benchmarking msg queues*/ k_tid_t producer_tid; @@ -49,7 +48,7 @@ K_THREAD_STACK_DEFINE(my_stack_area_0, STACK_SIZE); struct k_thread my_thread; struct k_thread my_thread_0; -u32_t __read_swap_end_tsc_value_test = 1; +u32_t __read_swap_end_time_value_test = 1; u64_t dummy_time; u64_t start_time; u64_t test_end_time; @@ -69,9 +68,9 @@ u32_t benchmarking_overhead_swap(void) "rdtsc\n\t" "mov %eax,start_time\n\t" "mov %edx,start_time+4\n\t" - "cmp $0x1,__read_swap_end_tsc_value_test\n\t" + "cmp $0x1,__read_swap_end_time_value_test\n\t" "jne time_read_not_needed_test\n\t" - "movw $0x2,__read_swap_end_tsc_value\n\t" + "movw $0x2,__read_swap_end_time_value\n\t" "pushl %eax\n\t" "pushl %edx\n\t" "rdtsc\n\t" @@ -86,46 +85,49 @@ u32_t benchmarking_overhead_swap(void) "pop %edx\n\t" "pop %eax\n\t"); - /* u64_t end_time = OS_GET_TIME(); */ + /* u64_t end_time = GET_CURRENT_TIME(); */ return(test_end_time - start_time); } #endif #if CONFIG_ARM -void read_systick_start_of_swap(void) +void read_timer_start_of_swap(void) { - __start_swap_tsc = (u32_t)SysTick->VAL; + __start_swap_time = GET_CURRENT_TIME(); } -void read_systick_end_of_swap(void) +void read_timer_end_of_swap(void) { - if (__read_swap_end_tsc_value == 1) { - __read_swap_end_tsc_value = 2; - __common_var_swap_end_tsc = OS_GET_TIME(); + if (__read_swap_end_time_value == 1) { + __read_swap_end_time_value = 2; + __common_var_swap_end_time = GET_CURRENT_TIME(); } } -void read_systick_start_of_isr(void) +/* 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_tsc = (u32_t)SysTick->VAL; + __start_intr_time = (u32_t)SysTick->VAL; } -void read_systick_end_of_isr(void) +void read_timer_end_of_isr(void) { - __end_intr_tsc = (u32_t)SysTick->VAL; + __end_intr_time = (u32_t)SysTick->VAL; } -void read_systick_start_of_tick_handler(void) +void read_timer_start_of_tick_handler(void) { - __start_tick_tsc = (u32_t)SysTick->VAL; + __start_tick_time = (u32_t)SysTick->VAL; } -void read_systick_end_of_tick_handler(void) +void read_timer_end_of_tick_handler(void) { - __end_tick_tsc = (u32_t)SysTick->VAL; + __end_tick_time = (u32_t)SysTick->VAL; } -#endif +#endif /* CONFIG_ARM */ @@ -139,8 +141,8 @@ void test_thread_entry(void *p, void *p1, void *p2) void thread_swap_test(void *p1, void *p2, void *p3) { - __read_swap_end_tsc_value = 1; - thread_abort_start_tsc = OS_GET_TIME(); + __read_swap_end_time_value = 1; + thread_abort_start_time = GET_CURRENT_TIME(); k_thread_abort(_current); } @@ -157,14 +159,14 @@ void system_thread_bench(void) u64_t total_tick_time; /*Thread create*/ - u64_t thread_create_start_tsc; - u64_t thread_create_end_tsc; + u64_t thread_create_start_time; + u64_t thread_create_end_time; DECLARE_VAR(thread, create) /*Thread cancel*/ - u64_t thread_cancel_start_tsc; - u64_t thread_cancel_end_tsc; + u64_t thread_cancel_start_time; + u64_t thread_cancel_end_time; DECLARE_VAR(thread, cancel) /* Thread Abort*/ @@ -183,38 +185,37 @@ void system_thread_bench(void) NULL, NULL, NULL, -1 /*priority*/, 0, 0); - thread_abort_end_tsc = (__common_var_swap_end_tsc); - __end_swap_tsc = __common_var_swap_end_tsc; + thread_abort_end_time = (__common_var_swap_end_time); + __end_swap_time = __common_var_swap_end_time; - u32_t total_swap_cycles = __end_swap_tsc - - SUBTRACT_CLOCK_CYCLES(__start_swap_tsc); + u32_t total_swap_cycles = __end_swap_time - + SUBTRACT_CLOCK_CYCLES(__start_swap_time); /* Interrupt latency*/ - total_intr_time = SYS_CLOCK_HW_CYCLES_TO_NS(__end_intr_tsc - - __start_intr_tsc); + total_intr_time = CYCLES_TO_NS(__end_intr_time - + __start_intr_time); /* tick overhead*/ - total_tick_time = SYS_CLOCK_HW_CYCLES_TO_NS(__end_tick_tsc - - __start_tick_tsc); + total_tick_time = CYCLES_TO_NS(__end_tick_time - + __start_tick_time); /*******************************************************************/ /* thread create*/ - thread_create_start_tsc = OS_GET_TIME(); + thread_create_start_time = GET_CURRENT_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_tsc = OS_GET_TIME(); + thread_create_end_time = GET_CURRENT_TIME(); /* thread Termination*/ - thread_cancel_start_tsc = OS_GET_TIME(); + thread_cancel_start_time = GET_CURRENT_TIME(); s32_t ret_value_thread_cancel = k_thread_cancel(my_tid); - thread_cancel_end_tsc = OS_GET_TIME(); + thread_cancel_end_time = GET_CURRENT_TIME(); ARG_UNUSED(ret_value_thread_cancel); /* Thread suspend*/ @@ -224,7 +225,7 @@ void system_thread_bench(void) NULL, NULL, NULL, -1 /*priority*/, 0, 0); - thread_suspend_end_tsc = OS_GET_TIME(); + thread_suspend_end_time = GET_CURRENT_TIME(); /* At this point test for resume*/ k_thread_resume(sus_res_tid); @@ -241,61 +242,60 @@ void system_thread_bench(void) CALCULATE_TIME(, thread, suspend) /* calculation for resume */ - thread_resume_start_tsc = thread_suspend_end_tsc; + thread_resume_start_time = thread_suspend_end_time; CALCULATE_TIME(, thread, resume) /*******************************************************************/ /* Only print lower 32bit of time result */ - - PRINT_F("Context switch", + PRINT_STATS("Context switch", (u32_t)(total_swap_cycles & 0xFFFFFFFFULL), - (u32_t)SYS_CLOCK_HW_CYCLES_TO_NS(total_swap_cycles)); + (u32_t) CYCLES_TO_NS(total_swap_cycles)); /*TC_PRINT("Swap Overhead:%d cycles\n", benchmarking_overhead_swap());*/ /*Interrupt latency */ - u32_t intr_latency_cycles = SUBTRACT_CLOCK_CYCLES(__end_intr_tsc) - - SUBTRACT_CLOCK_CYCLES(__start_intr_tsc); + u32_t intr_latency_cycles = SUBTRACT_CLOCK_CYCLES(__end_intr_time) - + SUBTRACT_CLOCK_CYCLES(__start_intr_time); - PRINT_F("Interrupt latency", + PRINT_STATS("Interrupt latency", (u32_t)(intr_latency_cycles), - (u32_t) (SYS_CLOCK_HW_CYCLES_TO_NS(intr_latency_cycles))); + (u32_t) (CYCLES_TO_NS(intr_latency_cycles))); /*tick overhead*/ - u32_t tick_overhead_cycles = SUBTRACT_CLOCK_CYCLES(__end_tick_tsc) - - SUBTRACT_CLOCK_CYCLES(__start_tick_tsc); - PRINT_F("Tick overhead", + u32_t tick_overhead_cycles = SUBTRACT_CLOCK_CYCLES(__end_tick_time) - + SUBTRACT_CLOCK_CYCLES(__start_tick_time); + PRINT_STATS("Tick overhead", (u32_t)(tick_overhead_cycles), - (u32_t) (SYS_CLOCK_HW_CYCLES_TO_NS(tick_overhead_cycles))); + (u32_t) (CYCLES_TO_NS(tick_overhead_cycles))); /*thread creation*/ - PRINT_F("Thread Creation", - (u32_t)((thread_create_end_tsc - thread_create_start_tsc) & + PRINT_STATS("Thread Creation", + (u32_t)((thread_create_end_time - thread_create_start_time) & 0xFFFFFFFFULL), - (u32_t) (total_thread_create_time & 0xFFFFFFFFULL)); + (u32_t) ((total_thread_create_time) & 0xFFFFFFFFULL)); /*thread cancel*/ - PRINT_F("Thread cancel", - (u32_t)((thread_cancel_end_tsc - thread_cancel_start_tsc) & + PRINT_STATS("Thread cancel", + (u32_t)((thread_cancel_end_time - thread_cancel_start_time) & 0xFFFFFFFFULL), (u32_t) (total_thread_cancel_time & 0xFFFFFFFFULL)); /*thread abort*/ - PRINT_F("Thread abort", - (u32_t)((thread_abort_end_tsc - thread_abort_start_tsc) & + PRINT_STATS("Thread abort", + (u32_t)((thread_abort_end_time - thread_abort_start_time) & 0xFFFFFFFFULL), (u32_t) (total_thread_abort_time & 0xFFFFFFFFULL)); /*thread suspend*/ - PRINT_F("Thread Suspend", - (u32_t)((thread_suspend_end_tsc - thread_suspend_start_tsc) & + PRINT_STATS("Thread Suspend", + (u32_t)((thread_suspend_end_time - thread_suspend_start_time) & 0xFFFFFFFFULL), (u32_t) (total_thread_suspend_time & 0xFFFFFFFFULL)); /*thread resume*/ - PRINT_F("Thread Resume", - (u32_t)((thread_resume_end_tsc - thread_suspend_end_tsc) + PRINT_STATS("Thread Resume", + (u32_t)((thread_resume_end_time - thread_suspend_end_time) & 0xFFFFFFFFULL), (u32_t) (total_thread_resume_time & 0xFFFFFFFFULL)); @@ -304,11 +304,11 @@ void system_thread_bench(void) void thread_suspend_test(void *p1, void *p2, void *p3) { - thread_suspend_start_tsc = OS_GET_TIME(); + thread_suspend_start_time = GET_CURRENT_TIME(); k_thread_suspend(_current); /* comes to this line once its resumed*/ - thread_resume_end_tsc = OS_GET_TIME(); + thread_resume_end_time = GET_CURRENT_TIME(); /* k_thread_suspend(_current); */ } @@ -316,38 +316,38 @@ void thread_suspend_test(void *p1, void *p2, void *p3) void heap_malloc_free_bench(void) { /* heap malloc*/ - u64_t heap_malloc_start_tsc = 0; - u64_t heap_malloc_end_tsc = 0; + u64_t heap_malloc_start_time = 0; + u64_t heap_malloc_end_time = 0; /* heap free*/ - u64_t heap_free_start_tsc = 0; - u64_t heap_free_end_tsc = 0; + u64_t heap_free_start_time = 0; + u64_t heap_free_end_time = 0; s32_t count = 0; u32_t sum_malloc = 0; u32_t sum_free = 0; while (count++ != 100) { - heap_malloc_start_tsc = OS_GET_TIME(); + heap_malloc_start_time = GET_CURRENT_TIME(); void *allocated_mem = k_malloc(10); - heap_malloc_end_tsc = OS_GET_TIME(); + heap_malloc_end_time = GET_CURRENT_TIME(); if (allocated_mem == NULL) { TC_PRINT("\n Malloc failed at count %d\n", count); break; } - heap_free_start_tsc = OS_GET_TIME(); + heap_free_start_time = GET_CURRENT_TIME(); k_free(allocated_mem); - heap_free_end_tsc = OS_GET_TIME(); - sum_malloc += heap_malloc_end_tsc - heap_malloc_start_tsc; - sum_free += heap_free_end_tsc - heap_free_start_tsc; + heap_free_end_time = GET_CURRENT_TIME(); + sum_malloc += heap_malloc_end_time - heap_malloc_start_time; + sum_free += heap_free_end_time - heap_free_start_time; } - PRINT_F("Heap Malloc", + PRINT_STATS("Heap Malloc", (u32_t)((sum_malloc / count) & 0xFFFFFFFFULL), - (u32_t)(SYS_CLOCK_HW_CYCLES_TO_NS(sum_malloc / count))); - PRINT_F("Heap Free", + (u32_t)(CYCLES_TO_NS(sum_malloc / count))); + PRINT_STATS("Heap Free", (u32_t)((sum_free / count) & 0xFFFFFFFFULL), - (u32_t)(SYS_CLOCK_HW_CYCLES_TO_NS(sum_free / count))); + (u32_t)(CYCLES_TO_NS(sum_free / count))); } diff --git a/tests/benchmarks/timing_info/src/timing_info.h b/tests/benchmarks/timing_info/src/timing_info.h index 3ae9e31fb10..2487aa63fb0 100644 --- a/tests/benchmarks/timing_info/src/timing_info.h +++ b/tests/benchmarks/timing_info/src/timing_info.h @@ -8,9 +8,9 @@ #define CALCULATE_TIME(special_char, profile, name) \ { \ - total_##profile##_##name##_time = SYS_CLOCK_HW_CYCLES_TO_NS( \ - special_char##profile##_##name##_end_tsc - \ - special_char##profile##_##name##_start_tsc); \ + total_##profile##_##name##_time = CYCLES_TO_NS( \ + special_char##profile##_##name##_end_time - \ + special_char##profile##_##name##_start_time); \ } /*total_##profile##_##name##_time = @@ -20,14 +20,17 @@ #define DECLARE_VAR(profile, name) \ u64_t total_##profile##_##name##_time; -extern u64_t __start_swap_tsc; -extern u64_t __end_swap_tsc; -extern u64_t __start_intr_tsc; -extern u64_t __end_intr_tsc; -extern u64_t __start_tick_tsc; -extern u64_t __end_tick_tsc; +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; +#define GET_CURRENT_TIME() OS_GET_TIME() +#define CYCLES_TO_NS(x) SYS_CLOCK_HW_CYCLES_TO_NS(x) +#define PRINT_STATS(x, y, z) PRINT_F(x, y, z) /* Function prototypes */ void system_thread_bench(void); @@ -88,13 +91,15 @@ void msg_passing_bench(void); * always incrementing i.e count up counter. * If we are using the ARM based controllers the systick is a * count down counter. + * If we are using nrf SOC, we are using external timer which always increments + * ie count up counter. * Hence to calculate the cycles taken up by the code we need to adjust the * values accordingly. * * NOTE: Needed only when reading value from end of swap operation */ #if CONFIG_ARM -#define SUBTRACT_CLOCK_CYCLES(val) (SysTick->LOAD - (u32_t)val) +#define SUBTRACT_CLOCK_CYCLES(val) (SysTick->LOAD - (u32_t) val) #else #define SUBTRACT_CLOCK_CYCLES(val) (val) -#endif +#endif /* CONFIG_ARM */ diff --git a/tests/benchmarks/timing_info/src/yield_bench.c b/tests/benchmarks/timing_info/src/yield_bench.c index a09fe912050..f77bf1d3552 100644 --- a/tests/benchmarks/timing_info/src/yield_bench.c +++ b/tests/benchmarks/timing_info/src/yield_bench.c @@ -19,15 +19,15 @@ extern K_THREAD_STACK_DEFINE(my_stack_area_0, STACK_SIZE); extern struct k_thread my_thread; extern struct k_thread my_thread_0; -/* u64_t thread_yield_start_tsc[1000]; */ -/* u64_t thread_yield_end_tsc[1000]; */ +/* u64_t thread_yield_start_time[1000]; */ +/* u64_t thread_yield_end_time[1000]; */ /* location of the time stamps*/ -extern u32_t __read_swap_end_tsc_value; -extern u64_t __common_var_swap_end_tsc; +extern u32_t __read_swap_end_time_value; +extern u64_t __common_var_swap_end_time; extern char sline[]; -u64_t thread_sleep_start_tsc; -u64_t thread_sleep_end_tsc; +u64_t thread_sleep_start_time; +u64_t thread_sleep_end_time; u64_t thread_start_time; u64_t thread_end_time; static u32_t count; @@ -55,19 +55,19 @@ void yield_bench(void) 0 /*priority*/, 0, 0); /*read the time of start of the sleep till the swap happens */ - __read_swap_end_tsc_value = 1; + __read_swap_end_time_value = 1; - thread_sleep_start_tsc = OS_GET_TIME(); + thread_sleep_start_time = OS_GET_TIME(); k_sleep(1000); - thread_sleep_end_tsc = ((u32_t)__common_var_swap_end_tsc); + thread_sleep_end_time = ((u32_t)__common_var_swap_end_time); u32_t yield_cycles = (thread_end_time - thread_start_time) / 2000; - u32_t sleep_cycles = thread_sleep_end_tsc - thread_sleep_start_tsc; + u32_t sleep_cycles = thread_sleep_end_time - thread_sleep_start_time; - PRINT_F("Thread Yield", yield_cycles, - SYS_CLOCK_HW_CYCLES_TO_NS(yield_cycles)); - PRINT_F("Thread Sleep", sleep_cycles, - SYS_CLOCK_HW_CYCLES_TO_NS(sleep_cycles)); + PRINT_STATS("Thread Yield", yield_cycles, + CYCLES_TO_NS(yield_cycles)); + PRINT_STATS("Thread Sleep", sleep_cycles, + CYCLES_TO_NS(sleep_cycles)); }