Add wake-up latency metric (a la cyclictest).
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 29 +++++++++++++++++++---------- src/rt-app_types.h | 1 + src/rt-app_utils.c | 5 +++-- 3 files changed, 23 insertions(+), 12 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 51aadf480a3f..c620985d9b44 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -220,7 +220,7 @@ static void memload(unsigned long count, struct _rtapp_iomem_buf *iomem)
static int run_event(event_data_t *event, int dry_run, unsigned long *perf, unsigned long *duration, rtapp_resource_t *resources, - struct timespec *t_first) + struct timespec *t_first, unsigned long *wu_latency) { rtapp_resource_t *rdata = &(resources[event->res]); rtapp_resource_t *ddata = &(resources[event->dep]); @@ -299,7 +299,7 @@ static int run_event(event_data_t *event, int dry_run, break; case rtapp_timer: { - struct timespec t_period, t_now; + struct timespec t_period, t_now, t_wu; log_debug("timer %d ", event->duration);
t_period = usec_to_timespec(event->duration); @@ -311,10 +311,15 @@ static int run_event(event_data_t *event, int dry_run,
rdata->res.timer.t_next = timespec_add(&rdata->res.timer.t_next, &t_period); clock_gettime(CLOCK_MONOTONIC, &t_now); - if (timespec_lower(&t_now, &rdata->res.timer.t_next)) + if (timespec_lower(&t_now, &rdata->res.timer.t_next)) { clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, &rdata->res.timer.t_next, NULL); - else + clock_gettime(CLOCK_MONOTONIC, &t_now); + t_wu = timespec_sub(&t_now, &rdata->res.timer.t_next); + *wu_latency = timespec_to_usec(&t_wu); + } else { clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next); + *wu_latency = 0UL; + } } break; case rtapp_suspend: @@ -352,7 +357,8 @@ static int run_event(event_data_t *event, int dry_run,
int run(int ind, phase_data_t *pdata, unsigned long *duration, rtapp_resource_t *resources, - struct timespec *t_first) + struct timespec *t_first, + unsigned long *wu_latency) { event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -369,7 +375,7 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, log_ftrace(ft_data.marker_fd, "[%d] executing %d", ind, i); - lock += run_event(&events[i], !continue_running, &perf, duration, resources, t_first); + lock += run_event(&events[i], !continue_running, &perf, duration, resources, t_first, wu_latency); }
return perf; @@ -417,7 +423,7 @@ void *thread_body(void *arg) struct sched_param param; struct timespec t_start, t_end, t_first; unsigned long t_start_usec; - unsigned long perf, duration; + unsigned long perf, duration, wu_latency; timing_point_t *curr_timing; timing_point_t *timings; timing_point_t tmp_timing; @@ -553,7 +559,9 @@ void *thread_body(void *arg)
log_notice("[%d] starting thread ...\n", data->ind);
- fprintf(data->log_handler, "#idx\tperf\trun\tperiod\tstart\t\tend\t\trel_st\n"); + fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s\n", + "#idx", "perf", "run", "period", + "start", "end", "rel_st", "wu_lat");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind); @@ -584,9 +592,9 @@ void *thread_body(void *arg) log_ftrace(ft_data.marker_fd, "[%d] begins loop %d phase %d step %d", data->ind, i, j, loop); log_debug("[%d] begins loop %d phase %d step %d", data->ind, i, j, loop);;
- duration = 0; + duration = wu_latency = 0; clock_gettime(CLOCK_MONOTONIC, &t_start); - perf = run(data->ind, pdata, &duration, *(data->resources), &t_first); + perf = run(data->ind, pdata, &duration, *(data->resources), &t_first, &wu_latency); clock_gettime(CLOCK_MONOTONIC, &t_end);
if (timings) @@ -604,6 +612,7 @@ void *thread_body(void *arg) curr_timing->period = timespec_to_usec(&t_diff); curr_timing->duration = duration; curr_timing->perf = perf; + curr_timing->wu_latency = wu_latency;
if (opts.logsize && !timings) log_timing(data->log_handler, curr_timing); diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 57fb80d363d5..4c20f43cb627 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -191,6 +191,7 @@ typedef struct _timing_point_t { unsigned long perf; unsigned long duration; unsigned long period; + unsigned long wu_latency; __u64 start_time; __u64 end_time; __u64 rel_start_time; diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index fc01f944235e..0bdc66f60973 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -132,14 +132,15 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler, - "%d\t%lu\t%lu\t%lu\t%llu\t%llu\t%llu", + "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu", t->ind, t->perf, t->duration, t->period, t->start_time, t->end_time, - t->rel_start_time + t->rel_start_time, + t->wu_latency ); fprintf(handler, "\n"); }