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 <youvedeep.singh@intel.com>
This commit is contained in:
Youvedeep Singh 2017-08-31 20:05:05 +05:30 committed by Anas Nashif
commit 76b577e180
12 changed files with 246 additions and 241 deletions

View file

@ -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

View file

@ -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

View file

@ -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

View file

@ -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

View file

@ -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);

View file

@ -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 */

View file

@ -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 */

View file

@ -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);
}

View file

@ -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);
}

View file

@ -15,28 +15,27 @@
#include <tc_util.h>
#include <ksched.h>
#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)));
}

View file

@ -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 */

View file

@ -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));
}