Skip to content

Commit

Permalink
test: Enhance benchmark latency reporting
Browse files Browse the repository at this point in the history 
Enhances the reporting of the benchmark latency failures in the
following ways:

1. The failing test is now clearly identified
2. Failures follow the general reporting pattern

Signed-off-by: Peter Mitsis <[email protected]>
  • Loading branch information
@peter-mitsis @nashif
peter-mitsis authored and nashif committed Jul 19, 2023
1 parent fe922d3 commit aa4f246
Show file tree
Hide file tree
Showing 9 changed files with 142 additions and 68 deletions.
27 changes: 19 additions & 8 deletions tests/benchmarks/latency_measure/src/coop_ctx_switch.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -95,6 +95,10 @@ int coop_ctx_switch(void)
{
ctx_switch_counter = 0U;
ctx_switch_balancer = 0;
char error_string[80];
const char *notes = "";
bool failed = false;
int end;

timing_start();
bench_test_start();
Expand All @@ -106,18 +110,25 @@ int coop_ctx_switch(void)
(k_thread_entry_t)thread_two, NULL, NULL, NULL,
K_PRIO_COOP(6), 0, K_NO_WAIT);

end = bench_test_end();

if (ctx_switch_balancer > 3 || ctx_switch_balancer < -3) {
printk(" Balance is %d. FAILED", ctx_switch_balancer);
} else if (bench_test_end() != 0) {
error_count++;
PRINT_OVERFLOW_ERROR();
} else {
uint32_t diff;

diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average context switch time between threads (coop)", diff, ctx_switch_counter);
snprintk(error_string, 78, " Balance is %d",
ctx_switch_balancer);
notes = error_string;
failed = true;
} else if (end != 0) {
error_count++;
notes = TICK_OCCURRENCE_ERROR;
}

uint32_t diff;

diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average context switch time between threads (coop)",
diff, ctx_switch_counter, failed, notes);

timing_stop();

return 0;
Expand Down
30 changes: 19 additions & 11 deletions tests/benchmarks/latency_measure/src/heap_malloc_free.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -23,6 +23,10 @@ void heap_malloc_free(void)
uint32_t sum_malloc = 0U;
uint32_t sum_free = 0U;

bool failed = false;
char error_string[80];
const char *notes = "";

timing_start();

while (count != TEST_COUNT) {
Expand All @@ -31,8 +35,10 @@ void heap_malloc_free(void)

heap_malloc_end_time = timing_counter_get();
if (allocated_mem == NULL) {
printk("Failed to alloc memory from heap "
"at count %d\n", count);
error_count++;
snprintk(error_string, 78,
"alloc memory @ iteration %d", count);
notes = error_string;
break;
}

Expand All @@ -47,18 +53,20 @@ void heap_malloc_free(void)
count++;
}

/* if count is 0, it means that there is not enough memory heap
* to do k_malloc at least once, then it's meaningless to
* calculate average time of memory allocation and free.
/*
* If count is 0, it means that there is not enough memory heap
* to do k_malloc at least once. Override the error string.
*/

if (count == 0) {
printk("Error: there isn't enough memory heap to do "
"k_malloc at least once, please "
"increase heap size\n");
} else {
PRINT_STATS_AVG("Average time for heap malloc", sum_malloc, count);
PRINT_STATS_AVG("Average time for heap free", sum_free, count);
failed = true;
notes = "Memory heap too small--increase it.";
}

PRINT_STATS_AVG("Average time for heap malloc", sum_malloc, count,
failed, notes);
PRINT_STATS_AVG("Average time for heap free", sum_free, count,
failed, notes);

timing_stop();
}
19 changes: 11 additions & 8 deletions tests/benchmarks/latency_measure/src/int_to_thread.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -51,11 +51,7 @@ static void make_int(void)
{
flag_var = 0;
irq_offload(latency_test_isr, NULL);
if (flag_var != 1) {
printk(" Flag variable has not changed. FAILED\n");
} else {
timestamp_end = timing_counter_get();
}
timestamp_end = timing_counter_get();
}

/**
Expand All @@ -67,14 +63,21 @@ static void make_int(void)
int int_to_thread(void)
{
uint32_t diff;
bool failed = false;
const char *notes = "";

timing_start();
TICK_SYNCH();
make_int();
if (flag_var == 1) {
diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS("Switch from ISR back to interrupted thread", diff);
if (flag_var != 1) {
error_count++;
notes = "Flag variable did not change";
failed = true;
}

diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS("Switch from ISR back to interrupted thread",
diff, failed, notes);
timing_stop();
return 0;
}
3 changes: 2 additions & 1 deletion tests/benchmarks/latency_measure/src/int_to_thread_evt.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -90,7 +90,8 @@ int int_to_thread_evt(void)

diff = timing_cycles_get(&timestamp_start, &timestamp_end);

PRINT_STATS("Time from ISR to executing a different thread", diff);
PRINT_STATS("Time from ISR to executing a different thread",
diff, false, "");

return 0;
}
24 changes: 22 additions & 2 deletions tests/benchmarks/latency_measure/src/mutex_lock_unlock.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,8 +30,11 @@ int mutex_lock_unlock(void)
uint32_t diff;
timing_t timestamp_start;
timing_t timestamp_end;
const char *notes = "";
int end;

timing_start();
bench_test_start();

timestamp_start = timing_counter_get();

Expand All @@ -40,20 +43,37 @@ int mutex_lock_unlock(void)
}

timestamp_end = timing_counter_get();
end = bench_test_end();

diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average time to lock a mutex", diff, N_TEST_MUTEX);

if (end != 0) {
notes = TICK_OCCURRENCE_ERROR;
error_count++;
}

PRINT_STATS_AVG("Average time to lock a mutex", diff, N_TEST_MUTEX,
false, notes);

bench_test_start();
timestamp_start = timing_counter_get();

for (i = 0; i < N_TEST_MUTEX; i++) {
k_mutex_unlock(&test_mutex);
}

timestamp_end = timing_counter_get();
end = bench_test_end();
diff = timing_cycles_get(&timestamp_start, &timestamp_end);

PRINT_STATS_AVG("Average time to unlock a mutex", diff, N_TEST_MUTEX);
if (end != 0) {
notes = TICK_OCCURRENCE_ERROR;
error_count++;
}

PRINT_STATS_AVG("Average time to unlock a mutex", diff, N_TEST_MUTEX,
false, notes);

timing_stop();
return 0;
}
31 changes: 18 additions & 13 deletions tests/benchmarks/latency_measure/src/sema_test_signal_release.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,6 @@ int sema_context_switch(void)
{
uint32_t diff;

bench_test_start();
timing_start();

k_thread_create(&thread_one_data, thread_one_stack,
Expand All @@ -57,13 +56,13 @@ int sema_context_switch(void)

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);
PRINT_STATS("Semaphore take time (context switch)", diff, false, "");


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);
PRINT_STATS("Semaphore give time (context switch)", diff, false, "");

timing_stop();

Expand All @@ -85,6 +84,8 @@ int sema_test_signal(void)
uint32_t diff;
timing_t timestamp_start;
timing_t timestamp_end;
const char *notes = "";
int end;

bench_test_start();
timing_start();
Expand All @@ -96,16 +97,18 @@ int sema_test_signal(void)
}

timestamp_end = timing_counter_get();
end = bench_test_end();
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 {
if (end != 0) {
error_count++;
PRINT_OVERFLOW_ERROR();
notes = TICK_OCCURRENCE_ERROR;
}

diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average semaphore signal time", diff, N_TEST_SEMA,
false, notes);

bench_test_start();
timing_start();

Expand All @@ -116,15 +119,17 @@ int sema_test_signal(void)
}

timestamp_end = timing_counter_get();
end = bench_test_end();
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 {
if (end != 0) {
error_count++;
PRINT_OVERFLOW_ERROR();
notes = TICK_OCCURRENCE_ERROR;
}

diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average semaphore test time", diff, N_TEST_SEMA,
false, notes);

return 0;
}
10 changes: 5 additions & 5 deletions tests/benchmarks/latency_measure/src/thread.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -60,27 +60,27 @@ int suspend_resume(void)

diff = timing_cycles_get(&timestamp_start_create_c,
&timestamp_end_create_c);
PRINT_STATS("Time to create a thread (without start)", diff);
PRINT_STATS("Time to create a thread (without start)", diff, false, "");

diff = timing_cycles_get(&timestamp_start_start_c,
&timestamp_start_suspend_c);
PRINT_STATS("Time to start a thread", diff);
PRINT_STATS("Time to start a thread", diff, false, "");

diff = timing_cycles_get(&timestamp_start_suspend_c,
&timestamp_end_suspend_c);
PRINT_STATS("Time to suspend a thread", diff);
PRINT_STATS("Time to suspend a thread", diff, false, "");

diff = timing_cycles_get(&timestamp_start_resume_c,
&timestamp_end_resume_c);
PRINT_STATS("Time to resume a thread", diff);
PRINT_STATS("Time to resume a thread", diff, false, "");

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);
PRINT_STATS("Time to abort a thread (not running)", diff, false, "");

timing_stop();
return 0;
Expand Down
35 changes: 23 additions & 12 deletions tests/benchmarks/latency_measure/src/thread_switch_yield.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -49,6 +49,10 @@ void thread_switch_yield(void)
timing_t timestamp_start;
timing_t timestamp_end;
uint32_t ts_diff;
const char *notes = "";
char error_string[80];
bool failed = false;
int end;

timing_start();
bench_test_start();
Expand All @@ -71,6 +75,7 @@ void thread_switch_yield(void)

/* get the number of cycles it took to do the test */
timestamp_end = timing_counter_get();
end = bench_test_end();

/* Ensure both helper and this routine were context switching back &
* forth.
Expand All @@ -80,23 +85,29 @@ void thread_switch_yield(void)
* back and forth.
*/
delta = iterations - helper_thread_iterations;
if (bench_test_end() < 0) {
error_count++;
PRINT_OVERFLOW_ERROR();
} else if (abs(delta) > 1) {
if (abs(delta) > 1) {
/* expecting even alternating context switch, seems one routine
* called yield without the other having chance to execute
*/
error_count++;
printk(" Error, iteration:%u, helper iteration:%u",
iterations, helper_thread_iterations);
} else {
/* thread_yield is called (iterations + helper_thread_iterations)
* times in total.
*/
ts_diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average thread context switch using yield", ts_diff, (iterations + helper_thread_iterations));
snprintk(error_string, 78,
"Error: iteration:%u : helper iteration:%u",
iterations, helper_thread_iterations);
notes = error_string;
failed = true;
} else if (end != 0) {
error_count++;
notes = TICK_OCCURRENCE_ERROR;
}

/*
* thread_yield is called (iterations + helper_thread_iterations)
* times in total.
*/

ts_diff = timing_cycles_get(&timestamp_start, &timestamp_end);
PRINT_STATS_AVG("Average thread context switch using yield", ts_diff,
(iterations + helper_thread_iterations), failed, notes);

timing_stop();
}
Loading

0 comments on commit aa4f246

Please sign in to comment.