On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
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 d23c3074f057..d1155092844a 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);
As said in previous patch, i think that you have mixed wake up latency and slack According to the description in patch 14 : slack: for periodic phases (phases that ends with a timer), time between the end of last event and the end of the phase, e.g
you should have *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 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 28896c9a76e6..a1a7c05d202e 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 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);
-- 2.10.0