Re: [Sched-tools] [PATCH v2 04/14] rt-app: add wake-up latency to the log metrics

On 17 November 2016 at 17:34, Juri Lelli juri.lelli@arm.com wrote:

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 442771f553f9..d23c3074f057 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,7 +563,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",
  

replacing tab with space breaks the cpufreq_governor_efficiency script

•                              "#idx", "perf", "run", "period",
  

•                              "start", "end", "rel_st", "wu_lat");
  
    if (opts.ftrace)
            log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);
  

@@ -588,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)
  

@@ -608,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 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 887bfc8ef79e..28896c9a76e6 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");
  

}

2.10.0