Skip to content

Commit

Permalink
tests: latency_measure: Increase verbosity of summary lines
Browse files Browse the repository at this point in the history 
Feedback from the previous summary line change has been that it
had become more difficult for people to parse and understand what
is being tested/benchmarked when the description consisted of
just using a terse tag. To improve the situation a more human
oriented description has been added to follow that tag so that
not only can tools still parse on the tag, but people can use
both tag and the extra description to understand the test/benchmark.

Summary lines for each test now consist of the following:
    1. A terse tag (for tools to parse)
    2. A more human oriented description.
    3. Number of cycles.
    4. Number of nanoseconds.

Signed-off-by: Peter Mitsis <[email protected]>
  • Loading branch information
@peter-mitsis @carlescufi
peter-mitsis authored and carlescufi committed Jan 22, 2024
1 parent db58810 commit d3a3d63
Show file tree
Hide file tree
Showing 11 changed files with 356 additions and 264 deletions.
303 changes: 152 additions & 151 deletions tests/benchmarks/latency_measure/README.rst
View file

Large diffs are not rendered by default.

58 changes: 36 additions & 22 deletions tests/benchmarks/latency_measure/src/events.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,8 @@ static void event_ops_entry(void *p1, void *p2, void *p3)
timing_t finish;
uint32_t i;
uint64_t cycles;
char description[80];
char tag[50];
char description[120];

k_event_clear(&event_set, ALL_EVENTS);

Expand All @@ -43,9 +44,10 @@ static void event_ops_entry(void *p1, void *p2, void *p3)
}
finish = timing_timestamp_get();

snprintf(description, sizeof(description),
"EVENTS post.immediate.%s",
snprintf(tag, sizeof(tag), "events.post.immediate.%s",
(options & K_USER) ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Post events (nothing wakes)", tag);
cycles = timing_cycles_get(&start, &finish);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand All @@ -56,9 +58,10 @@ static void event_ops_entry(void *p1, void *p2, void *p3)
}
finish = timing_timestamp_get();

snprintf(description, sizeof(description),
"EVENTS set.immediate.%s",
snprintf(tag, sizeof(tag), "events.set.immediate.%s",
(options & K_USER) ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Set events (nothing wakes)", tag);
cycles = timing_cycles_get(&start, &finish);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand All @@ -69,9 +72,10 @@ static void event_ops_entry(void *p1, void *p2, void *p3)
}
finish = timing_timestamp_get();

snprintf(description, sizeof(description),
"EVENTS wait.immediate.%s",
snprintf(tag, sizeof(tag), "events.wait.immediate.%s",
(options & K_USER) ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Wait for any events (no ctx switch)", tag);
cycles = timing_cycles_get(&start, &finish);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand All @@ -82,9 +86,10 @@ static void event_ops_entry(void *p1, void *p2, void *p3)
}
finish = timing_timestamp_get();

snprintf(description, sizeof(description),
"EVENTS wait_all.immediate.%s",
snprintf(tag, sizeof(tag), "events.wait_all.immediate.%s",
(options & K_USER) ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Wait for all events (no ctx switch)", tag);
cycles = timing_cycles_get(&start, &finish);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand All @@ -97,7 +102,8 @@ static void start_thread_entry(void *p1, void *p2, void *p3)
uint32_t alt_options = (uint32_t)(uintptr_t)p3;
uint32_t i;
uint64_t cycles;
char description[80];
char tag[50];
char description[120];

k_thread_start(&alt_thread);

Expand All @@ -109,20 +115,24 @@ static void start_thread_entry(void *p1, void *p2, void *p3)
k_event_set(&event_set, BENCH_EVENT_SET);
}

snprintf(tag, sizeof(tag),
"events.wait.blocking.%c_to_%c",
(alt_options & K_USER) ? 'u' : 'k',
(options & K_USER) ? 'u' : 'k');
snprintf(description, sizeof(description),
"EVENTS wait.blocking.(%c -> %c)",
(alt_options & K_USER) ? 'U' : 'K',
(options & K_USER) ? 'U' : 'K');
"%-40s - Wait for any events (w/ ctx switch)", tag);
cycles = timestamp.cycles -
timestamp_overhead_adjustment(options, alt_options);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);

snprintf(tag, sizeof(tag),
"events.set.wake+ctx.%c_to_%c",
(options & K_USER) ? 'u' : 'k',
(alt_options & K_USER) ? 'u' : 'k');
snprintf(description, sizeof(description),
"EVENTS set.wake+ctx.(%c -> %c)",
(options & K_USER) ? 'U' : 'K',
(alt_options & K_USER) ? 'U' : 'K');
"%-40s - Set events (w/ ctx switch)", tag);
cycles = timestamp.cycles -
timestamp_overhead_adjustment(options, alt_options);
PRINT_STATS_AVG(description, (uint32_t)cycles,
Expand All @@ -137,19 +147,23 @@ static void start_thread_entry(void *p1, void *p2, void *p3)
k_event_post(&event_set, BENCH_EVENT_SET);
}

snprintf(tag, sizeof(tag),
"events.wait_all.blocking.%c_to_%c",
(alt_options & K_USER) ? 'u' : 'k',
(options & K_USER) ? 'u' : 'k');
snprintf(description, sizeof(description),
"EVENTS wait_all.blocking.(%c -> %c)",
(alt_options & K_USER) ? 'U' : 'K',
(options & K_USER) ? 'U' : 'K');
"%-40s - Wait for all events (w/ ctx switch)", tag);
cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);

snprintf(tag, sizeof(tag),
"events.post.wake+ctx.%c_to_%c",
(options & K_USER) ? 'u' : 'k',
(alt_options & K_USER) ? 'u' : 'k');
snprintf(description, sizeof(description),
"EVENTS post.wake+ctx.(%c -> %c)",
(options & K_USER) ? 'U' : 'K',
(alt_options & K_USER) ? 'U' : 'K');
"%-40s - Post events (w/ ctx switch)", tag);
cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand Down
62 changes: 40 additions & 22 deletions tests/benchmarks/latency_measure/src/fifo.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -93,7 +93,8 @@ int fifo_ops(uint32_t num_iterations, uint32_t options)
{
int priority;
uint64_t cycles;
char description[80];
char tag[50];
char description[120];

priority = k_thread_priority_get(k_current_get());

Expand All @@ -111,38 +112,46 @@ int fifo_ops(uint32_t num_iterations, uint32_t options)
k_thread_start(&start_thread);

if ((options & K_USER) == 0) {
snprintf(description, sizeof(description),
"FIFO put.immediate.%s",
snprintf(tag, sizeof(tag),
"fifo.put.immediate.%s",
options & K_USER ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Add data to FIFO (no ctx switch)", tag);

cycles = timestamp.cycles;
cycles -= timestamp_overhead_adjustment(options, options);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);

snprintf(description, sizeof(description),
"FIFO get.immediate.%s",
snprintf(tag, sizeof(tag),
"fifo.get.immediate.%s",
options & K_USER ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Get data from FIFO (no ctx switch)", tag);
cycles = timestamp.cycles;
cycles -= timestamp_overhead_adjustment(options, options);
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);
}

snprintf(description, sizeof(description),
"FIFO put.alloc.immediate.%s",
snprintf(tag, sizeof(tag),
"fifo.put.alloc.immediate.%s",
options & K_USER ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Allocate to add data to FIFO (no ctx switch)", tag);

cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);

snprintf(description, sizeof(description),
"FIFO get.free.immediate.%s",
snprintf(tag, sizeof(tag),
"fifo.get.free.immediate.%s",
options & K_USER ? "user" : "kernel");
snprintf(description, sizeof(description),
"%-40s - Free when getting data from FIFO (no ctx switch)", tag);
cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand Down Expand Up @@ -258,7 +267,8 @@ int fifo_blocking_ops(uint32_t num_iterations, uint32_t start_options,
{
int priority;
uint64_t cycles;
char description[80];
char tag[50];
char description[120];

priority = k_thread_priority_get(k_current_get());

Expand All @@ -284,40 +294,48 @@ int fifo_blocking_ops(uint32_t num_iterations, uint32_t start_options,
k_thread_start(&start_thread);

if (((start_options | alt_options) & K_USER) == 0) {
snprintf(tag, sizeof(tag),
"fifo.get.blocking.%s_to_%s",
alt_options & K_USER ? "u" : "k",
start_options & K_USER ? "u" : "k");
snprintf(description, sizeof(description),
"FIFO get.blocking.(%s -> %s)",
alt_options & K_USER ? "U" : "K",
start_options & K_USER ? "U" : "K");
"%-40s - Get data from FIFO (w/ ctx switch)", tag);

cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);

snprintf(tag, sizeof(tag),
"fifo.put.wake+ctx.%s_to_%s",
start_options & K_USER ? "u" : "k",
alt_options & K_USER ? "u" : "k");
snprintf(description, sizeof(description),
"FIFO put.wake+ctx.(%s -> %s)",
start_options & K_USER ? "U" : "K",
alt_options & K_USER ? "U" : "K");
"%-40s - Add data to FIFO (w/ ctx switch)", tag);
cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);
}

snprintf(tag, sizeof(tag),
"fifo.get.free.blocking.%s_to_%s",
alt_options & K_USER ? "u" : "k",
start_options & K_USER ? "u" : "k");
snprintf(description, sizeof(description),
"FIFO get.free.blocking.(%s -> %s)",
alt_options & K_USER ? "U" : "K",
start_options & K_USER ? "U" : "K");
"%-40s - Free when getting data from FIFO (w/ ctx siwtch)", tag);

cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
k_sem_give(&pause_sem);

snprintf(tag, sizeof(tag),
"fifo.put.alloc.wake+ctx.%s_to_%s",
start_options & K_USER ? "u" : "k",
alt_options & K_USER ? "u" : "k");
snprintf(description, sizeof(description),
"FIFO put.alloc.wake+ctx.(%s -> %s)",
start_options & K_USER ? "U" : "K",
alt_options & K_USER ? "U" : "K");
"%-40s - Allocate to add data to FIFO (w/ ctx switch)", tag);
cycles = timestamp.cycles;
PRINT_STATS_AVG(description, (uint32_t)cycles,
num_iterations, false, "");
Expand Down
14 changes: 10 additions & 4 deletions tests/benchmarks/latency_measure/src/heap_malloc_free.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ void heap_malloc_free(void)

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

timing_start();
Expand Down Expand Up @@ -63,10 +64,15 @@ void heap_malloc_free(void)
notes = "Memory heap too small--increase it.";
}

PRINT_STATS_AVG("HEAP malloc.immediate", sum_malloc, count,
failed, notes);
PRINT_STATS_AVG("HEAP free.immediate", sum_free, count,
failed, notes);
snprintf(description, sizeof(description),
"%-40s - Average time for heap malloc",
"heap.malloc.immediate");
PRINT_STATS_AVG(description, sum_malloc, count, failed, notes);

snprintf(description, sizeof(description),
"%-40s - Average time for heap free",
"heap.free.immediate");
PRINT_STATS_AVG(description, sum_free, count, failed, notes);

timing_stop();
}
19 changes: 13 additions & 6 deletions tests/benchmarks/latency_measure/src/int_to_thread.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -166,6 +166,7 @@ static void int_to_another_thread(uint32_t num_iterations, uint64_t *sum,
int int_to_thread(uint32_t num_iterations)
{
uint64_t sum;
char description[120];

timing_start();
TICK_SYNCH();
Expand All @@ -174,17 +175,21 @@ int int_to_thread(uint32_t num_iterations)

sum -= timestamp_overhead_adjustment(0, 0);

PRINT_STATS_AVG("ISR resume.interrupted.thread.kernel",
(uint32_t)sum, num_iterations, false, "");
snprintf(description, sizeof(description),
"%-40s - Return from ISR to interrupted thread",
"isr.resume.interrupted.thread.kernel");
PRINT_STATS_AVG(description, (uint32_t)sum, num_iterations, false, "");

/* ************** */

int_to_another_thread(num_iterations, &sum, 0);

sum -= timestamp_overhead_adjustment(0, 0);

PRINT_STATS_AVG("ISR resume.different.thread.kernel",
(uint32_t)sum, num_iterations, false, "");
snprintf(description, sizeof(description),
"%-40s - Return from ISR to another thread",
"isr.resume.different.thread.kernel");
PRINT_STATS_AVG(description, (uint32_t)sum, num_iterations, false, "");

/* ************** */

Expand All @@ -193,8 +198,10 @@ int int_to_thread(uint32_t num_iterations)

sum -= timestamp_overhead_adjustment(0, K_USER);

PRINT_STATS_AVG("ISR resume.different.thread.user",
(uint32_t)sum, num_iterations, false, "");
snprintf(description, sizeof(description),
"%-40s - Return from ISR to another thread",
"isr.resume.different.thread.user");
PRINT_STATS_AVG(description, (uint32_t)sum, num_iterations, false, "");
#endif

timing_stop();
Expand Down
Loading

0 comments on commit d3a3d63

Please sign in to comment.