Add measured slack to log metrics; it is meausured as the interval of time between the end of the current activation and the begin of the next one.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 23 +++++++++++++++-------- src/rt-app_types.h | 1 + src/rt-app_utils.c | 11 +++++++++-- src/rt-app_utils.h | 3 +++ 4 files changed, 28 insertions(+), 10 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index c620985d9b44..77d682acf3db 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, unsigned long *wu_latency) + struct timespec *t_first, unsigned long *wu_latency, long *slack) { 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, t_wu; + struct timespec t_period, t_now, t_wu, t_slack; log_debug("timer %d ", event->duration);
t_period = usec_to_timespec(event->duration); @@ -311,6 +311,8 @@ 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); + t_slack = timespec_sub(&rdata->res.timer.t_next, &t_now); + *slack = timespec_to_usec_long(&t_slack); if (timespec_lower(&t_now, &rdata->res.timer.t_next)) { clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, &rdata->res.timer.t_next, NULL); clock_gettime(CLOCK_MONOTONIC, &t_now); @@ -358,7 +360,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, - unsigned long *wu_latency) + unsigned long *wu_latency, + long *slack) { event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -375,7 +378,8 @@ 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, wu_latency); + lock += run_event(&events[i], !continue_running, &perf, + duration, resources, t_first, wu_latency, slack); }
return perf; @@ -424,6 +428,7 @@ void *thread_body(void *arg) struct timespec t_start, t_end, t_first; unsigned long t_start_usec; unsigned long perf, duration, wu_latency; + long slack; timing_point_t *curr_timing; timing_point_t *timings; timing_point_t tmp_timing; @@ -559,9 +564,9 @@ void *thread_body(void *arg)
log_notice("[%d] starting thread ...\n", data->ind);
- fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s\n", + fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s\n", "#idx", "perf", "run", "period", - "start", "end", "rel_st", "wu_lat"); + "start", "end", "rel_st", "wu_lat", "slack");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind); @@ -592,9 +597,10 @@ 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 = wu_latency = 0; + duration = wu_latency = slack = 0; clock_gettime(CLOCK_MONOTONIC, &t_start); - perf = run(data->ind, pdata, &duration, *(data->resources), &t_first, &wu_latency); + perf = run(data->ind, pdata, &duration, *(data->resources), + &t_first, &wu_latency, &slack); clock_gettime(CLOCK_MONOTONIC, &t_end);
if (timings) @@ -613,6 +619,7 @@ void *thread_body(void *arg) curr_timing->duration = duration; curr_timing->perf = perf; curr_timing->wu_latency = wu_latency; + curr_timing->slack = slack;
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 4c20f43cb627..0570e7b5ad3e 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -192,6 +192,7 @@ typedef struct _timing_point_t { unsigned long duration; unsigned long period; unsigned long wu_latency; + long slack; __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 0bdc66f60973..45cf26a964e2 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -33,6 +33,12 @@ timespec_to_usec_ull(struct timespec *ts) return llround((ts->tv_sec * 1E9 + ts->tv_nsec) / 1000.0); }
+long +timespec_to_usec_long(struct timespec *ts) +{ + return round((ts->tv_sec * 1E9 + ts->tv_nsec) / 1000.0); +} + #ifdef DLSCHED __u64 timespec_to_nsec(struct timespec *ts) @@ -132,7 +138,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler, - "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu", + "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld", t->ind, t->perf, t->duration, @@ -140,7 +146,8 @@ log_timing(FILE *handler, timing_point_t *t) t->start_time, t->end_time, t->rel_start_time, - t->wu_latency + t->wu_latency, + t->slack ); fprintf(handler, "\n"); } diff --git a/src/rt-app_utils.h b/src/rt-app_utils.h index a41d8ad205aa..6a8d921d1321 100644 --- a/src/rt-app_utils.h +++ b/src/rt-app_utils.h @@ -92,6 +92,9 @@ timespec_to_usec(struct timespec *ts); unsigned long long timespec_to_usec_ull(struct timespec *ts);
+long +timespec_to_usec_long(struct timespec *ts); + struct timespec usec_to_timespec(unsigned long usec);