rt-app: add slack to log metrics

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>
Acked-by: Vincent Guittot <vincent.guittot@linaro.org>

4 files changed, 28 insertions, 10 deletions

diff --git a/src/rt-app.c b/src/rt-app.c
index 9f32551..5a550eb 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;
@@ -563,9 +568,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);
@@ -596,9 +601,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)
@@ -617,6 +623,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 4c20f43..0570e7b 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 28896c9..a1a7c05 100644
--- a/src/rt-app_utils.c
+++ b/src/rt-app_utils.c
@@ -35,6 +35,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)
@@ -134,7 +140,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,
@@ -142,7 +148,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 a41d8ad..6a8d921 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);