rt-app: add wake-up latency to the log metrics

Add wake-up latency metric (a la cyclictest).

Signed-off-by: Juri Lelli <juri.lelli@arm.com>
Acked-by: Vincent Guittot <vincent.guittot@linaro.org>

3 files changed, 22 insertions, 13 deletions

diff --git a/src/rt-app.c b/src/rt-app.c
index 71c04d0..9f32551 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;
@@ -557,9 +563,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\n",
+	fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s\n",
 				   "#idx", "perf", "run", "period",
-				   "start", "end", "rel_st");
+				   "start", "end", "rel_st", "wu_lat");
 
 	if (opts.ftrace)
 		log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);
@@ -590,9 +596,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)
@@ -610,6 +616,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 57fb80d..4c20f43 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 887bfc8..28896c9 100644
--- a/src/rt-app_utils.c
+++ b/src/rt-app_utils.c
@@ -134,14 +134,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");
 }