Hi all,
this is an attempt to align and finally merge Linaro's and ARM's versions of rt-app.
v3 should address Vincent's comments on v2 (by also adding a couple of patches, the log header description one and the relative/absolute timers one).
Please comment and let me know if this new version of the set is OK for merging.
Thanks a lot,
- Juri
[1] https://github.com/scheduler-tools/rt-app/commits/master
Juri Lelli (17): doc: clarify example for config step rt-app: fix compile warnings rt-app: add a t_zero to which every tasks has to refer rt-app: convert log header to fixed width spaces rt-app: add wake-up latency to the log metrics rt-app: add slack to log metrics rt-app: fix batch tasks rt-app: add 'configured period' to log metrics rt-app: write logs only if continue_running is set rt-app: refactor log data to reduce the number of parameters of run() rt-app: move wu_lat to the end of the log rt-app: make c_prd c_period and enlarge it rt-app: add configured duration (c_duration) to log metrics doc: add log header fields descriptions rt-app: let caller manage tracing start/stop rt-app: add delay thread property rt-app: implement relative/absolute timers
doc/examples/cpufreq_governor_efficiency/dvfs.sh | 2 +- doc/tutorial.txt | 128 +++++++++++++++++++-- libdl/dl_syscalls.h | 4 +- src/rt-app.c | 137 ++++++++++++++++------- src/rt-app_args.h | 3 - src/rt-app_parse_config.c | 11 ++ src/rt-app_parse_config.h | 2 + src/rt-app_types.h | 16 +++ src/rt-app_utils.c | 27 ++++- src/rt-app_utils.h | 6 + 10 files changed, 278 insertions(+), 58 deletions(-)
Add detailed example for static cross-compile of rt-app.
Signed-off-by: Juri Lelli juri.lelli@arm.com Acked-by: Vincent Guittot vincent.guittot@linaro.org --- doc/tutorial.txt | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index 100a2df068c6..78cd1fe0e2e2 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -43,6 +43,31 @@ export ac_cv_lib_json_c_json_object_from_file=yes ./configure --host=aarch64-linux-gnu LDFLAGS=" --static -L<path to parent of json repo>/json-c/. libs/" CFLAGS="-I<path to parent of json repo>" --with-deadline make
+e.g, with a directory structure like the following: + +$ tree -d +. +├── autom4te.cache +├── build +├── build-aux +├── doc +│ └── examples +│ ├── cpufreq_governor_efficiency +│ ├── merge +│ └── tutorial +├── json-c +│ ├── autom4te.cache +│ ├── doc +│ │ └── html +│ └── tests +├── libdl +├── m4 +└── src + +the configure step becomes + +./configure --host=aarch64-linux-gnu LDFLAGS="--static -L./../json-c/." CFLAGS="-I./.." --with-deadline + **** json file skeleton ****
The json file that describes a workload is made on 3 main objects: tasks,
Fix various compilation warnings in one go.
Signed-off-by: Juri Lelli juri.lelli@arm.com Acked-by: Vincent Guittot vincent.guittot@linaro.org --- libdl/dl_syscalls.h | 4 +++- src/rt-app.c | 4 ++-- src/rt-app_args.h | 3 --- src/rt-app_parse_config.h | 2 ++ src/rt-app_utils.c | 13 +++++++++++-- src/rt-app_utils.h | 3 +++ 6 files changed, 21 insertions(+), 8 deletions(-)
diff --git a/libdl/dl_syscalls.h b/libdl/dl_syscalls.h index 27cbfe16882d..ca07503ea744 100644 --- a/libdl/dl_syscalls.h +++ b/libdl/dl_syscalls.h @@ -17,7 +17,9 @@ #define __DL_SYSCALLS__
#include <linux/kernel.h> -#include <linux/unistd.h> +#define _GNU_SOURCE +#include <unistd.h> +#include <sys/syscall.h> #include <time.h> #include <linux/types.h>
diff --git a/src/rt-app.c b/src/rt-app.c index 5283ac7fd668..211dd77da98f 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -170,7 +170,7 @@ int calibrate_cpu_cycles(int clock)
}
-static inline loadwait(unsigned long exec) +static inline unsigned long loadwait(unsigned long exec) { unsigned long load_count;
@@ -358,7 +358,7 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, for (i = 0; i < nbevents; i++) { if (!continue_running && !lock) - return; + return perf;
log_debug("[%d] runs events %d type %d ", ind, i, events[i].type); if (opts.ftrace) diff --git a/src/rt-app_args.h b/src/rt-app_args.h index 9bbde384328b..23ba50c5f343 100644 --- a/src/rt-app_args.h +++ b/src/rt-app_args.h @@ -36,10 +36,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. #ifdef DLSCHED #include "dl_syscalls.h" #endif - -#ifdef JSON #include "rt-app_parse_config.h" -#endif
#define DEFAULT_THREAD_PRIORITY 10 #define PATH_LENGTH 256 diff --git a/src/rt-app_parse_config.h b/src/rt-app_parse_config.h index 023cabd2ca62..9b0e5faf425d 100644 --- a/src/rt-app_parse_config.h +++ b/src/rt-app_parse_config.h @@ -45,5 +45,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
void parse_config(const char *filename, rtapp_options_t *opts); +void +parse_config_stdin(rtapp_options_t *opts);
#endif // _RTAPP_PARSE_CONFIG_H diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index c4840db89625..887bfc8ef79e 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -19,6 +19,8 @@ along with this program; if not, write to the Free Software Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. */
+#include <errno.h> +#include <string.h> #include "rt-app_utils.h"
unsigned long @@ -253,7 +255,7 @@ resource_to_string(resource_t resource, char *resource_name) void ftrace_write(int mark_fd, const char *fmt, ...) { va_list ap; - int n, size = BUF_SIZE; + int n, size = BUF_SIZE, ret; char *tmp, *ntmp;
if (mark_fd < 0) { @@ -274,8 +276,15 @@ void ftrace_write(int mark_fd, const char *fmt, ...)
/* If it worked return success */ if (n > -1 && n < size) { - write(mark_fd, tmp, n); + ret = write(mark_fd, tmp, n); free(tmp); + if (ret < 0) { + log_error("Cannot write mark_fd: %s\n", + strerror(errno)); + exit(EXIT_FAILURE); + } else if (ret < n) { + log_debug("Cannot write all bytes at once into mark_fd\n"); + } return; }
diff --git a/src/rt-app_utils.h b/src/rt-app_utils.h index 64f97f60aaab..a41d8ad205aa 100644 --- a/src/rt-app_utils.h +++ b/src/rt-app_utils.h @@ -28,6 +28,9 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA. #include <string.h> #include <stdarg.h> #include <stdlib.h> +#define _GNU_SOURCE +#include <unistd.h> +#include <sys/syscall.h> #include "rt-app_types.h"
#ifndef LOG_PREFIX
Also a barrier is added so that execution starts at the same instant for everybody.
Signed-off-by: Juri Lelli juri.lelli@arm.com Acked-by: Vincent Guittot vincent.guittot@linaro.org --- src/rt-app.c | 33 ++++++++++++++++++++++++++------- 1 file changed, 26 insertions(+), 7 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 211dd77da98f..442771f553f9 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -35,6 +35,8 @@ static int nthreads; static volatile sig_atomic_t running_threads; static int p_load; rtapp_options_t opts; +static struct timespec t_zero; +static pthread_barrier_t threads_barrier;
static ftrace_data_t ft_data = { .debugfs = "/sys/kernel/debug", @@ -217,7 +219,8 @@ 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) + unsigned long *perf, unsigned long *duration, rtapp_resource_t *resources, + struct timespec *t_first) { rtapp_resource_t *rdata = &(resources[event->res]); rtapp_resource_t *ddata = &(resources[event->dep]); @@ -303,7 +306,7 @@ static int run_event(event_data_t *event, int dry_run,
if (rdata->res.timer.init == 0) { rdata->res.timer.init = 1; - clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next); + rdata->res.timer.t_next = *t_first; }
rdata->res.timer.t_next = timespec_add(&rdata->res.timer.t_next, &t_period); @@ -348,7 +351,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) + rtapp_resource_t *resources, + struct timespec *t_first) { event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -365,7 +369,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); + lock += run_event(&events[i], !continue_running, &perf, duration, resources, t_first); }
return perf; @@ -411,7 +415,7 @@ void *thread_body(void *arg) thread_data_t *data = (thread_data_t*) arg; phase_data_t *pdata; struct sched_param param; - struct timespec t_start, t_end; + struct timespec t_start, t_end, t_first; unsigned long t_start_usec; unsigned long perf, duration; timing_point_t *curr_timing; @@ -536,6 +540,21 @@ void *thread_body(void *arg) } }
+ if (data->ind == 0) { + /* + * Only first thread sets t_zero. Other threads sync with this + * timestamp. + */ + clock_gettime(CLOCK_MONOTONIC, &t_zero); + if (opts.ftrace) + log_ftrace(ft_data.marker_fd, + "[%d] sets zero time", + data->ind); + } + + pthread_barrier_wait(&threads_barrier); + t_first = t_zero; + log_notice("[%d] starting thread ...\n", data->ind);
fprintf(data->log_handler, "#idx\tperf\trun\tperiod\tstart\t\tend\t\trel_st\n"); @@ -571,7 +590,7 @@ void *thread_body(void *arg)
duration = 0; clock_gettime(CLOCK_MONOTONIC, &t_start); - perf = run(data->ind, pdata, &duration, *(data->resources)); + perf = run(data->ind, pdata, &duration, *(data->resources), &t_first); clock_gettime(CLOCK_MONOTONIC, &t_end);
if (timings) @@ -660,7 +679,7 @@ int main(int argc, char* argv[]) /* allocated threads */ nthreads = opts.nthreads; threads = malloc(nthreads * sizeof(pthread_t)); - running_threads = 0; + pthread_barrier_init(&threads_barrier, NULL, nthreads);
/* install a signal handler for proper shutdown */ signal(SIGQUIT, shutdown);
Convert thread logs header to fixed width spaces to improve readability (of both logs and code).
Also, update cpufreq_governor_efficiency script accordingly.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- doc/examples/cpufreq_governor_efficiency/dvfs.sh | 2 +- src/rt-app.c | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-)
diff --git a/doc/examples/cpufreq_governor_efficiency/dvfs.sh b/doc/examples/cpufreq_governor_efficiency/dvfs.sh index 7caee7d437f7..ac69a53086e2 100755 --- a/doc/examples/cpufreq_governor_efficiency/dvfs.sh +++ b/doc/examples/cpufreq_governor_efficiency/dvfs.sh @@ -32,7 +32,7 @@ if [ $1 ] ; then sum=0 loop=0 overrun=0 - for i in $(cat rt-app_$1_run$3us_sleep$4us.log | sed '1d;n;d' | sed '1d' |cut -f 3); do + for i in $(cat rt-app_$1_run$3us_sleep$4us.log | sed '1d;n;d' | sed '1d' | awk '{print $3}'); do loop=$(expr $loop + 1) sum=$(expr $sum + $i) if [ $4 -le $i ] ; then diff --git a/src/rt-app.c b/src/rt-app.c index 442771f553f9..71c04d0639b9 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -557,7 +557,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\n", + "#idx", "perf", "run", "period", + "start", "end", "rel_st");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);
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, 22 insertions(+), 13 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 71c04d0639b9..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,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 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"); }
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); 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);
A big run duration can cause load_count to overflow. Fix this issue by running the workload in bursts of 1 sec each.
Signed-off-by: Juri Lelli juri.lelli@arm.com Acked-by: Vincent Guittot vincent.guittot@linaro.org --- src/rt-app.c | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index d1155092844a..3c66a9b99454 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -48,10 +48,11 @@ static ftrace_data_t ft_data = { * Function: to do some useless operation. * TODO: improve the waste loop with more heavy functions */ -void waste_cpu_cycles(int load_loops) +void waste_cpu_cycles(unsigned long long load_loops) { double param, result; - double n, i; + double n; + unsigned long long i;
param = 0.95; n = 4; @@ -175,7 +176,24 @@ int calibrate_cpu_cycles(int clock) static inline unsigned long loadwait(unsigned long exec) { unsigned long load_count; + unsigned long secs; + int i; + + /* + * If exec is still too big, let's run it in bursts + * so that we don't overflow load_count. + */ + secs = exec / 1000000;
+ for (i = 0; i < secs; i++) { + load_count = 1000000000/p_load; + waste_cpu_cycles(load_count); + exec -= 1000000; + } + + /* + * Run for the remainig exec (if any). + */ load_count = (exec * 1000)/p_load; waste_cpu_cycles(load_count);
It is handy to have the configured period directly in logs. Add it there.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 22 ++++++++++++++-------- src/rt-app_types.h | 1 + src/rt-app_utils.c | 5 +++-- 3 files changed, 18 insertions(+), 10 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 3c66a9b99454..69e6f8646a12 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -238,7 +238,8 @@ 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, long *slack) + struct timespec *t_first, unsigned long *wu_latency, long *slack, + unsigned long *c_period) { rtapp_resource_t *rdata = &(resources[event->res]); rtapp_resource_t *ddata = &(resources[event->dep]); @@ -321,6 +322,7 @@ static int run_event(event_data_t *event, int dry_run, log_debug("timer %d ", event->duration);
t_period = usec_to_timespec(event->duration); + *c_period += event->duration;
if (rdata->res.timer.init == 0) { rdata->res.timer.init = 1; @@ -379,7 +381,8 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, rtapp_resource_t *resources, struct timespec *t_first, unsigned long *wu_latency, - long *slack) + long *slack, + unsigned long *c_period) { event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -397,7 +400,8 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, "[%d] executing %d", ind, i); lock += run_event(&events[i], !continue_running, &perf, - duration, resources, t_first, wu_latency, slack); + duration, resources, t_first, wu_latency, slack, + c_period); }
return perf; @@ -445,7 +449,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, wu_latency; + unsigned long perf, duration, wu_latency, c_period; long slack; timing_point_t *curr_timing; timing_point_t *timings; @@ -586,9 +590,10 @@ 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 %10s\n", + fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s %8s\n", "#idx", "perf", "run", "period", - "start", "end", "rel_st", "wu_lat", "slack"); + "start", "end", "rel_st", "wu_lat", "slack", + "c_prd");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind); @@ -619,10 +624,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 = slack = 0; + duration = wu_latency = slack = c_period = 0; clock_gettime(CLOCK_MONOTONIC, &t_start); perf = run(data->ind, pdata, &duration, *(data->resources), - &t_first, &wu_latency, &slack); + &t_first, &wu_latency, &slack, &c_period); clock_gettime(CLOCK_MONOTONIC, &t_end);
if (timings) @@ -642,6 +647,7 @@ void *thread_body(void *arg) curr_timing->perf = perf; curr_timing->wu_latency = wu_latency; curr_timing->slack = slack; + curr_timing->c_period = c_period;
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 0570e7b5ad3e..0ec8781562ee 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 c_period; unsigned long wu_latency; long slack; __u64 start_time; diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index a1a7c05d202e..e7cd8a83cec7 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler, - "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld", + "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld %8lu", t->ind, t->perf, t->duration, @@ -149,7 +149,8 @@ log_timing(FILE *handler, timing_point_t *t) t->end_time, t->rel_start_time, t->wu_latency, - t->slack + t->slack, + t->c_period ); fprintf(handler, "\n"); }
This is to avoid cases where the last row can contain bogus values.
Signed-off-by: Juri Lelli juri.lelli@arm.com Acked-by: Vincent Guittot vincent.guittot@linaro.org --- src/rt-app.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 69e6f8646a12..691a67064d86 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -649,7 +649,7 @@ void *thread_body(void *arg) curr_timing->slack = slack; curr_timing->c_period = c_period;
- if (opts.logsize && !timings) + if (opts.logsize && !timings && continue_running) log_timing(data->log_handler, curr_timing);
if (opts.ftrace)
Just keep log related variables on a struct to reduce the number of parameters we pass to run[_event]().
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 49 +++++++++++++++++++++++-------------------------- src/rt-app_types.h | 8 ++++++++ 2 files changed, 31 insertions(+), 26 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 691a67064d86..2c2dc1263def 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -237,9 +237,8 @@ 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, long *slack, - unsigned long *c_period) + unsigned long *perf, rtapp_resource_t *resources, + struct timespec *t_first, log_data_t *ldata) { rtapp_resource_t *rdata = &(resources[event->res]); rtapp_resource_t *ddata = &(resources[event->dep]); @@ -293,7 +292,7 @@ static int run_event(event_data_t *event, int dry_run, *perf += loadwait(event->duration); clock_gettime(CLOCK_MONOTONIC, &t_end); t_end = timespec_sub(&t_end, &t_start); - *duration += timespec_to_usec(&t_end); + ldata->duration += timespec_to_usec(&t_end); } break; case rtapp_runtime: @@ -313,7 +312,7 @@ static int run_event(event_data_t *event, int dry_run, } while ((diff_ns / 1000) < event->duration);
t_end = timespec_sub(&t_end, &t_start); - *duration += timespec_to_usec(&t_end); + ldata->duration += timespec_to_usec(&t_end); } break; case rtapp_timer: @@ -322,7 +321,7 @@ static int run_event(event_data_t *event, int dry_run, log_debug("timer %d ", event->duration);
t_period = usec_to_timespec(event->duration); - *c_period += event->duration; + ldata->c_period += event->duration;
if (rdata->res.timer.init == 0) { rdata->res.timer.init = 1; @@ -332,15 +331,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); t_slack = timespec_sub(&rdata->res.timer.t_next, &t_now); - *slack += timespec_to_usec_long(&t_slack); + ldata->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); t_wu = timespec_sub(&t_now, &rdata->res.timer.t_next); - *wu_latency = timespec_to_usec(&t_wu); + ldata->wu_latency = timespec_to_usec(&t_wu); } else { clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next); - *wu_latency = 0UL; + ldata->wu_latency = 0UL; } } break; @@ -377,12 +376,11 @@ static int run_event(event_data_t *event, int dry_run, return lock; }
-int run(int ind, phase_data_t *pdata, unsigned long *duration, - rtapp_resource_t *resources, - struct timespec *t_first, - unsigned long *wu_latency, - long *slack, - unsigned long *c_period) +int run(int ind, + phase_data_t *pdata, + rtapp_resource_t *resources, + struct timespec *t_first, + log_data_t *ldata) { event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -400,8 +398,7 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, "[%d] executing %d", ind, i); lock += run_event(&events[i], !continue_running, &perf, - duration, resources, t_first, wu_latency, slack, - c_period); + resources, t_first, ldata); }
return perf; @@ -446,10 +443,10 @@ void *thread_body(void *arg) { thread_data_t *data = (thread_data_t*) arg; phase_data_t *pdata; + log_data_t ldata; struct sched_param param; struct timespec t_start, t_end, t_first; unsigned long t_start_usec; - unsigned long perf, duration, wu_latency, c_period; long slack; timing_point_t *curr_timing; timing_point_t *timings; @@ -624,10 +621,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 = slack = c_period = 0; + memset(&ldata, 0, sizeof(ldata)); clock_gettime(CLOCK_MONOTONIC, &t_start); - perf = run(data->ind, pdata, &duration, *(data->resources), - &t_first, &wu_latency, &slack, &c_period); + ldata.perf = run(data->ind, pdata, *(data->resources), + &t_first, &ldata); clock_gettime(CLOCK_MONOTONIC, &t_end);
if (timings) @@ -643,11 +640,11 @@ void *thread_body(void *arg) curr_timing->start_time = timespec_to_usec_ull(&t_start); curr_timing->end_time = timespec_to_usec_ull(&t_end); curr_timing->period = timespec_to_usec(&t_diff); - curr_timing->duration = duration; - curr_timing->perf = perf; - curr_timing->wu_latency = wu_latency; - curr_timing->slack = slack; - curr_timing->c_period = c_period; + curr_timing->duration = ldata.duration; + curr_timing->perf = ldata.perf; + curr_timing->wu_latency = ldata.wu_latency; + curr_timing->slack = ldata.slack; + curr_timing->c_period = ldata.c_period;
if (opts.logsize && !timings && continue_running) log_timing(data->log_handler, curr_timing); diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 0ec8781562ee..276bce02d1e6 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -160,6 +160,14 @@ typedef struct _ftrace_data_t { int marker_fd; } ftrace_data_t;
+typedef struct _log_data_t { + unsigned long perf; + unsigned long duration; + unsigned long wu_latency; + unsigned long c_period; + long slack; +} log_data_t; + typedef struct _rtapp_options_t { int lock_pages;
Move wu_lat to the end of the log, so that can be easily removed in the future if not needed anymore.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 6 +++--- src/rt-app_utils.c | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 2c2dc1263def..6e80d21c0cf8 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -587,10 +587,10 @@ 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 %10s %8s\n", + fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %8s %10s\n", "#idx", "perf", "run", "period", - "start", "end", "rel_st", "wu_lat", "slack", - "c_prd"); + "start", "end", "rel_st", "slack", + "c_prd", "wu_lat");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind); diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index e7cd8a83cec7..747ac2b7d83d 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler, - "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld %8lu", + "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %8lu %10lu", t->ind, t->perf, t->duration, @@ -148,9 +148,9 @@ log_timing(FILE *handler, timing_point_t *t) t->start_time, t->end_time, t->rel_start_time, - t->wu_latency, t->slack, - t->c_period + t->c_period, + t->wu_latency ); fprintf(handler, "\n"); }
As the name is more understandable.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 4 ++-- src/rt-app_utils.c | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 6e80d21c0cf8..66ae021cb180 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -587,10 +587,10 @@ 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 %8s %10s\n", + fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s %10s\n", "#idx", "perf", "run", "period", "start", "end", "rel_st", "slack", - "c_prd", "wu_lat"); + "c_period", "wu_lat");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind); diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index 747ac2b7d83d..ea5724d8c523 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler, - "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %8lu %10lu", + "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %10lu %10lu", t->ind, t->perf, t->duration,
Add c_duration (sum of durations of the different events that comes from json configuration file). This is handy for post-processing logs.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 7 +++++-- src/rt-app_types.h | 2 ++ src/rt-app_utils.c | 3 ++- 3 files changed, 9 insertions(+), 3 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 66ae021cb180..becc3649f791 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -288,6 +288,7 @@ static int run_event(event_data_t *event, int dry_run, { struct timespec t_start, t_end; log_debug("run %d ", event->duration); + ldata->c_duration += event->duration; clock_gettime(CLOCK_MONOTONIC, &t_start); *perf += loadwait(event->duration); clock_gettime(CLOCK_MONOTONIC, &t_end); @@ -301,6 +302,7 @@ static int run_event(event_data_t *event, int dry_run, int64_t diff_ns;
log_debug("runtime %d ", event->duration); + ldata->c_duration += event->duration; clock_gettime(CLOCK_MONOTONIC, &t_start);
do { @@ -587,10 +589,10 @@ 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 %10s %10s\n", + fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s %10s %10s\n", "#idx", "perf", "run", "period", "start", "end", "rel_st", "slack", - "c_period", "wu_lat"); + "c_duration", "c_period", "wu_lat");
if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind); @@ -645,6 +647,7 @@ void *thread_body(void *arg) curr_timing->wu_latency = ldata.wu_latency; curr_timing->slack = ldata.slack; curr_timing->c_period = ldata.c_period; + curr_timing->c_duration = ldata.c_duration;
if (opts.logsize && !timings && continue_running) log_timing(data->log_handler, curr_timing); diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 276bce02d1e6..ae088f0f4c4b 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -164,6 +164,7 @@ typedef struct _log_data_t { unsigned long perf; unsigned long duration; unsigned long wu_latency; + unsigned long c_duration; unsigned long c_period; long slack; } log_data_t; @@ -199,6 +200,7 @@ typedef struct _timing_point_t { unsigned long perf; unsigned long duration; unsigned long period; + unsigned long c_duration; unsigned long c_period; unsigned long wu_latency; long slack; diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index ea5724d8c523..f12f48cffa90 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler, - "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %10lu %10lu", + "%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %10lu %10lu %10lu", t->ind, t->perf, t->duration, @@ -149,6 +149,7 @@ log_timing(FILE *handler, timing_point_t *t) t->end_time, t->rel_start_time, t->slack, + t->c_duration, t->c_period, t->wu_latency );
Add descrition for newly introduced log header fiels (slack, c_duration, c_period and wu_lat).
Signed-off-by: Juri Lelli juri.lelli@arm.com --- doc/tutorial.txt | 36 +++++++++++++++++++++++++++--------- 1 file changed, 27 insertions(+), 9 deletions(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index 78cd1fe0e2e2..bb6734c0b076 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -430,20 +430,38 @@ metrics are: - run: time spent by the thread to execute the run events - period: duration to execute the complte phase - start/end : absolute start and end time of a phase. Same time base is used in -ftrace + ftrace - rel_st: start time of a phase relatively to the beg of the use case +- 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. + + taskA ...|-- run5 --|- sleep5 -|-- run5--|..timer20.|-- run5 --|- sleep5 -|-- run6 --|.timer20.| + <--------------- period 20 --------------> <--------------- period 20 --------------> + <-slack5-> <slack4-> + + it can also be negative if the execution of a phases' events overshoots the + current period, e.g. + + taskA ...|-- run5 --|- sleep5 -|------- run30 ------xxxxxxxxxx| + <--------------- period 20 --------------> + <slack-5> + +- c_duration: sum of the configured duration of run/runtime events +- c_period: sum of the timer(s) period(s) +- wu_lat: sum of wakeup latencies after timer events
Below is an extract of a log:
# Policy : SCHED_OTHER priority : 0 -#idx perf run period start end rel_st -0 500000 34382 114492 175604833899 175604948391 785 -0 500000 29786 109863 175604948437 175605058300 115323 -0 500000 26977 107077 175605058336 175605165413 225223 -0 500000 28667 108771 175605165458 175605274229 332344 -0 500000 26644 106745 175605274274 175605381019 441160 -0 500000 26745 106867 175605381061 175605487928 547947 -0 500000 29513 109620 175605487974 175605597595 654860 +#idx perf run period start end rel_st slack c_duration c_period wu_lat + 0 92164 19935 98965 504549567051 504549666016 2443 78701 20000 100000 266 + 0 92164 19408 99952 504549666063 504549766015 101455 80217 20000 100000 265 + 0 92164 19428 99952 504549766062 504549866014 201454 80199 20000 100000 264 + 0 92164 19438 99955 504549866060 504549966015 301452 80190 20000 100000 265 + 0 92164 19446 99952 504549966061 504550066013 401453 80093 20000 100000 264 + 0 92164 19415 99953 504550066060 504550166013 501452 80215 20000 100000 263 + 0 92164 19388 99954 504550166059 504550266013 601451 80242 20000 100000 264 + 0 92164 19444 99956 504550266060 504550366015 701452 80185 20000 100000 265
Some gnuplot files are also created to generate charts based on the log files for each thread and for each kind of metrics. The format of the chart that
Don't explicitly manage start/stop of tracing, but assume that the caller does that before starting rt-app. This helps if the caller wants more padding before/after an rt-app execution.
In case tracing is not started and ftrace is enable in the json configuration, rt-app will fail to start.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- src/rt-app.c | 17 ++--------------- 1 file changed, 2 insertions(+), 15 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index becc3649f791..e32dbe413ef4 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -40,7 +40,6 @@ static pthread_barrier_t threads_barrier;
static ftrace_data_t ft_data = { .debugfs = "/sys/kernel/debug", - .trace_fd = -1, .marker_fd = -1, };
@@ -431,10 +430,8 @@ shutdown(int sig) }
if (opts.ftrace) { - log_notice("stopping ftrace"); log_ftrace(ft_data.marker_fd, "main ends\n"); - log_ftrace(ft_data.trace_fd, "0"); - close(ft_data.trace_fd); + log_notice("deconfiguring ftrace"); close(ft_data.marker_fd); }
@@ -732,21 +729,14 @@ int main(int argc, char* argv[]) log_notice("configuring ftrace"); strcpy(tmp, ft_data.debugfs); strcat(tmp, "/tracing/tracing_on"); - ft_data.trace_fd = open(tmp, O_WRONLY); - if (ft_data.trace_fd < 0) { - log_error("Cannot open trace_fd file %s", tmp); - exit(EXIT_FAILURE); - } - strcpy(tmp, ft_data.debugfs); strcat(tmp, "/tracing/trace_marker"); ft_data.marker_fd = open(tmp, O_WRONLY); - if (ft_data.trace_fd < 0) { + if (ft_data.marker_fd < 0) { log_error("Cannot open trace_marker file %s", tmp); exit(EXIT_FAILURE); }
- log_ftrace(ft_data.trace_fd, "1"); log_ftrace(ft_data.marker_fd, "main creates threads\n"); }
@@ -936,10 +926,7 @@ int main(int argc, char* argv[]) }
if (opts.ftrace) { - log_notice("stopping ftrace"); log_ftrace(ft_data.marker_fd, "main ends\n"); - log_ftrace(ft_data.trace_fd, "0"); - close(ft_data.trace_fd); close(ft_data.marker_fd); } exit(EXIT_SUCCESS);
Add a new thread property called 'delay' with which the initial starting time of a thread can be delayed. Parameter is expressed in usec.
Usage is:
"tasks" : { "thread0" : { ... "delay" : 1000000, ... } }
Signed-off-by: Juri Lelli juri.lelli@arm.com Acked-by: Vincent Guittot vincent.guittot@linaro.org --- doc/tutorial.txt | 3 +++ src/rt-app.c | 10 ++++++++++ src/rt-app_parse_config.c | 5 +++++ src/rt-app_types.h | 2 ++ 4 files changed, 20 insertions(+)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index bb6734c0b076..dfcc40567729 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -200,6 +200,9 @@ class. Default value is period. The unit is usec. * cpus: Array of Integer. Define the CPU affinity of the thread. Default value is all CPUs of the system. An example : "cpus" : [0, 2, 3]
+* delay: Integer. Initial delay before a thread starts execution. The unit +is usec. + * phases: Object. The phases object described TBF
If there is only 1 phase, the sequence of events can be directly put in the diff --git a/src/rt-app.c b/src/rt-app.c index e32dbe413ef4..93282e0a068c 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -611,6 +611,16 @@ void *thread_body(void *arg) } } #endif + + if (data->delay > 0) { + struct timespec delay = usec_to_timespec(data->delay); + + log_debug("initial delay %d ", data->delay); + t_first = timespec_add(&t_first, &delay); + clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, &t_first, + NULL); + } + i = j = loop = idx = 0;
while (continue_running && (i != data->loop)) { diff --git a/src/rt-app_parse_config.c b/src/rt-app_parse_config.c index c59b56290bbf..b0f302e2ba25 100644 --- a/src/rt-app_parse_config.c +++ b/src/rt-app_parse_config.c @@ -689,6 +689,11 @@ parse_thread_data(char *name, struct json_object *obj, int index, } log_info(PIN "key: cpus %s", data->cpuset_str);
+ /* initial delay */ + data->delay = get_int_value_from(obj, "delay", TRUE, 0); + if (data->delay < 0) + data->delay = 0; + /* Get phases */ phases_obj = get_in_object(obj, "phases", TRUE); if (phases_obj) { diff --git a/src/rt-app_types.h b/src/rt-app_types.h index ae088f0f4c4b..89983203f479 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -149,6 +149,8 @@ typedef struct _thread_data_t { char sched_policy_descr[RTAPP_POLICY_DESCR_LENGTH]; int sched_prio;
+ unsigned long delay; + #ifdef DLSCHED struct sched_attr dl_params; #endif
Implement "relative" (current behavior) and "absolute" working modes for timer events. Text added in doc/tutorial.txt gives more information about the two modes.
Signed-off-by: Juri Lelli juri.lelli@arm.com --- doc/tutorial.txt | 64 +++++++++++++++++++++++++++++++++++++++++++++++ src/rt-app.c | 3 ++- src/rt-app_parse_config.c | 6 +++++ src/rt-app_types.h | 1 + 4 files changed, 73 insertions(+), 1 deletion(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index dfcc40567729..a4455b601cd3 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -321,6 +321,70 @@ below: } }
+Timers can work with a "relative" or an "absolute" reference. By default they +work in "relative" mode, but this mode can also be explicity specified as the +following: + + "phases" : { + "phase0" : { + "loop" : 10, + "run0" : 10000, + "timer0" : { "ref" : "unique", "period" : 20000, "mode" : "relative" }, + } + +"relative" mode means that the reference for setting the next timer event is +relative to the end of the current phase. This in turn means that if, for some +reason (i.e., clock frequency was too low), events in a certain phase took too +long to execute and the timer of that phase couldn't actually fire at all, the +next phase won't be affected. For example: + + +---- + +-----+ +-------------------+-----+ +--- + |r0 | |r0 | |r0 |r0 | |r0 + | | | | | | | | + o-----------o-----------o-------------------o-----------o-------> + 0 10 20 30 40 50 60 70 80 100 120 + ^ ^ ^ ^ + | | | MISS! | + + + + + + Timer0 Timer0 Timer0 Timer0 + +In this example character "o" denotes when phases finish/start. Third +activation of Timer0 is missed, since r0 executed for more that 20ms. However +the next phase is not affected as Timer0 was set considering the instant of +time when the misbehaving r0 finished executing. + +"absolute" mode is specified as the following: + + "phases" : { + "phase0" : { + "loop" : 10, + "run0" : 10000, + "timer0" : { "ref" : "unique", "period" : 20000, "mode" : "absolute" }, + } + +"absolute" mode means that the reference for setting the next timer event is +fixed and always consider the starting time of the first phase. This means that +if, for some reason (i.e., clock frequency was too low), events in a certain +phase took too long to execute and the timer of that phase couldn't actually +fire at all, the next phase (and potentially other subsequent phases) _will_ be +affected. For example, considering again the example above: + + +---- + +-----+ +-------------------+-----+-----+ +--- + |r0 | |r0 | |r0 |r0 |r0 | |r0 + | | | | | | | | | + o-----------o-----------o-------------------o-----o---------o----> + 0 10 20 30 40 50 60 70 80 100 120 + ^ ^ ^ ^ ^ + | | | MISS! | MISS! | + + + + + + + Timer0 Timer0 Timer0 Timer0 Timer0 + +Third activation of Timer0 is missed, since r0 executed for more that 20ms. +Even if 4th activation of r0 executes for 10ms (as specified in the +configuration), 4th Timer0 is still missed because the reference didn't change. +In this example 5th activation of r0 then managed to recover, but in general it +depends on how badly a certain phase misbehaves. + * lock : String. Lock the mutex defined by the string value.
* unlock : String. Unlock the mutex defined by the string value. diff --git a/src/rt-app.c b/src/rt-app.c index 93282e0a068c..5b67a935397f 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -339,7 +339,8 @@ static int run_event(event_data_t *event, int dry_run, t_wu = timespec_sub(&t_now, &rdata->res.timer.t_next); ldata->wu_latency = timespec_to_usec(&t_wu); } else { - clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next); + if (rdata->res.timer.relative) + clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next); ldata->wu_latency = 0UL; } } diff --git a/src/rt-app_parse_config.c b/src/rt-app_parse_config.c index b0f302e2ba25..fbc4612b2257 100644 --- a/src/rt-app_parse_config.c +++ b/src/rt-app_parse_config.c @@ -181,6 +181,7 @@ static int init_timer_resource(rtapp_resource_t *data, const rtapp_options_t *op { log_info(PIN3 "Init: %s timer", data->name); data->res.timer.init = 0; + data->res.timer.relative = 1; }
static int init_cond_resource(rtapp_resource_t *data, const rtapp_options_t *opts) @@ -489,6 +490,11 @@ parse_thread_event_data(char *name, struct json_object *obj, rdata = &(opts->resources[data->res]); ddata = &(opts->resources[data->dep]);
+ tmp = get_string_value_from(obj, "mode", TRUE, "relative"); + if (!strncmp(tmp, "absolute", strlen("absolute"))) + rdata->res.timer.relative = 0; + free(tmp); + log_info(PIN2 "type %d target %s [%d] period %d", data->type, rdata->name, rdata->index, data->duration); return; } diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 89983203f479..718ce7798cc2 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -87,6 +87,7 @@ struct _rtapp_signal { struct _rtapp_timer { struct timespec t_next; int init; + int relative; };
struct _rtapp_iomem_buf {
On 24 November 2016 at 11:32, 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, 22 insertions(+), 13 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 71c04d0639b9..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);
Haven't you mixed wu_latency and slack behavior ? According to the description in patch 14 : wu_lat: sum of wakeup latencies after timer events
you should have *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 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
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
On 24/11/16 11:54, Vincent Guittot wrote:
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
[...]
@@ -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);
I agree on the wu_lat (will fix the corresponding patch).
On the slack we probably didn't finish the discussion started on v2. I'm summing up beacuse we can have multiple timer events in the same phase, and though that sum up intermediate slacks is a sensible thing to do. What you think? (if we go this direction I'll of course update the description in patch 14).
Le Thursday 24 Nov 2016 à 11:01:50 (+0000), Juri Lelli a écrit :
On 24/11/16 11:54, Vincent Guittot wrote:
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
[...]
@@ -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);
I agree on the wu_lat (will fix the corresponding patch).
On the slack we probably didn't finish the discussion started on v2. I'm summing up beacuse we can have multiple timer events in the same phase, and though that sum up intermediate slacks is a sensible thing to do. What you think? (if we go this direction I'll of course update the description in patch 14).
So my original understanding of slack was that you want to get the "margin" or " real idle" time in a phase which means that we are interested in summing the slack values of the different timers of a phase (1st example below) Then, we started to discuss the use of slack as a margin to be compared with the deadline of a deadline task and in this case only the slack of the last timer is relevant (2nd example).
If I take an example similar to the one in patch 14
your current proposal is doing this taskA ...|-- run5 --|- timer7 -|-- run5--|..timer13.|-- run5 --|- timer7 -|-- run6 --|.timer13..| <--------------- period 20 --------------> <--------------- period 20 ---------------> <-slack2-> <+slack5-> <-slack2-> <+slack4->
so slack will be +7 and then +6
And from a deadline point of view only the last slack of the period is interesting taskA ...|-- run5 --|- timer7 -|-- run5--|..timer13.|-- run5 --|- timer7 -|-- run6 --|.timer13..| <--------------- period 20 --------------> <--------------- period 20 ---------------> <-slack5-> <-slack4->
On 24/11/16 12:26, Vincent Guittot wrote:
Le Thursday 24 Nov 2016 à 11:01:50 (+0000), Juri Lelli a écrit :
On 24/11/16 11:54, Vincent Guittot wrote:
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
[...]
@@ -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);
I agree on the wu_lat (will fix the corresponding patch).
On the slack we probably didn't finish the discussion started on v2. I'm summing up beacuse we can have multiple timer events in the same phase, and though that sum up intermediate slacks is a sensible thing to do. What you think? (if we go this direction I'll of course update the description in patch 14).
So my original understanding of slack was that you want to get the "margin" or " real idle" time in a phase which means that we are interested in summing the slack values of the different timers of a phase (1st example below) Then, we started to discuss the use of slack as a margin to be compared with the deadline of a deadline task and in this case only the slack of the last timer is relevant (2nd example).
If I take an example similar to the one in patch 14
your current proposal is doing this taskA ...|-- run5 --|- timer7 -|-- run5--|..timer13.|-- run5 --|- timer7 -|-- run6 --|.timer13..| <--------------- period 20 --------------> <--------------- period 20 ---------------> <-slack2-> <+slack5-> <-slack2-> <+slack4->
so slack will be +7 and then +6
And from a deadline point of view only the last slack of the period is interesting taskA ...|-- run5 --|- timer7 -|-- run5--|..timer13.|-- run5 --|- timer7 -|-- run6 --|.timer13..| <--------------- period 20 --------------> <--------------- period 20 ---------------> <-slack5-> <-slack4->
Humm, to be honest, both make sense to me and might be useful. :)
Patrick is proposing that we add another property to timer events
"slack" : "[cumulative|last]"
What you think?
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
Convert thread logs header to fixed width spaces to improve readability (of both logs and code).
Also, update cpufreq_governor_efficiency script accordingly.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
doc/examples/cpufreq_governor_efficiency/dvfs.sh | 2 +- src/rt-app.c | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-)
diff --git a/doc/examples/cpufreq_governor_efficiency/dvfs.sh b/doc/examples/cpufreq_governor_efficiency/dvfs.sh index 7caee7d437f7..ac69a53086e2 100755 --- a/doc/examples/cpufreq_governor_efficiency/dvfs.sh +++ b/doc/examples/cpufreq_governor_efficiency/dvfs.sh @@ -32,7 +32,7 @@ if [ $1 ] ; then sum=0 loop=0 overrun=0
for i in $(cat rt-app_$1_run$3us_sleep$4us.log | sed '1d;n;d' | sed '1d' |cut -f 3); do
for i in $(cat rt-app_$1_run$3us_sleep$4us.log | sed '1d;n;d' | sed '1d' | awk '{print $3}'); do loop=$(expr $loop + 1) sum=$(expr $sum + $i) if [ $4 -le $i ] ; thendiff --git a/src/rt-app.c b/src/rt-app.c index 442771f553f9..71c04d0639b9 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -557,7 +557,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\n","#idx", "perf", "run", "period","start", "end", "rel_st"); if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);-- 2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
It is handy to have the configured period directly in logs. Add it there.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
src/rt-app.c | 22 ++++++++++++++-------- src/rt-app_types.h | 1 + src/rt-app_utils.c | 5 +++-- 3 files changed, 18 insertions(+), 10 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 3c66a9b99454..69e6f8646a12 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -238,7 +238,8 @@ 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, long *slack)
struct timespec *t_first, unsigned long *wu_latency, long *slack,unsigned long *c_period){ rtapp_resource_t *rdata = &(resources[event->res]); rtapp_resource_t *ddata = &(resources[event->dep]); @@ -321,6 +322,7 @@ static int run_event(event_data_t *event, int dry_run, log_debug("timer %d ", event->duration);
t_period = usec_to_timespec(event->duration);
*c_period += event->duration; if (rdata->res.timer.init == 0) { rdata->res.timer.init = 1;@@ -379,7 +381,8 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, rtapp_resource_t *resources, struct timespec *t_first, unsigned long *wu_latency,
long *slack)
long *slack,unsigned long *c_period){ event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -397,7 +400,8 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, "[%d] executing %d", ind, i); lock += run_event(&events[i], !continue_running, &perf,
duration, resources, t_first, wu_latency, slack);
duration, resources, t_first, wu_latency, slack,c_period); } return perf;@@ -445,7 +449,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, wu_latency;
unsigned long perf, duration, wu_latency, c_period; long slack; timing_point_t *curr_timing; timing_point_t *timings;@@ -586,9 +590,10 @@ 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 %10s\n",
fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s %8s\n", "#idx", "perf", "run", "period",
"start", "end", "rel_st", "wu_lat", "slack");
"start", "end", "rel_st", "wu_lat", "slack","c_prd"); if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);@@ -619,10 +624,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 = slack = 0;
duration = wu_latency = slack = c_period = 0; clock_gettime(CLOCK_MONOTONIC, &t_start); perf = run(data->ind, pdata, &duration, *(data->resources),
&t_first, &wu_latency, &slack);
&t_first, &wu_latency, &slack, &c_period); clock_gettime(CLOCK_MONOTONIC, &t_end); if (timings)@@ -642,6 +647,7 @@ void *thread_body(void *arg) curr_timing->perf = perf; curr_timing->wu_latency = wu_latency; curr_timing->slack = slack;
curr_timing->c_period = c_period; 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 0570e7b5ad3e..0ec8781562ee 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 c_period; unsigned long wu_latency; long slack; __u64 start_time;diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index a1a7c05d202e..e7cd8a83cec7 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler,
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld",
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld %8lu", t->ind, t->perf, t->duration,@@ -149,7 +149,8 @@ log_timing(FILE *handler, timing_point_t *t) t->end_time, t->rel_start_time, t->wu_latency,
t->slack
t->slack,t->c_period ); fprintf(handler, "\n");}
2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
Just keep log related variables on a struct to reduce the number of parameters we pass to run[_event]().
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
src/rt-app.c | 49 +++++++++++++++++++++++-------------------------- src/rt-app_types.h | 8 ++++++++ 2 files changed, 31 insertions(+), 26 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 691a67064d86..2c2dc1263def 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -237,9 +237,8 @@ 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, long *slack,unsigned long *c_period)
unsigned long *perf, rtapp_resource_t *resources,struct timespec *t_first, log_data_t *ldata){ rtapp_resource_t *rdata = &(resources[event->res]); rtapp_resource_t *ddata = &(resources[event->dep]); @@ -293,7 +292,7 @@ static int run_event(event_data_t *event, int dry_run, *perf += loadwait(event->duration); clock_gettime(CLOCK_MONOTONIC, &t_end); t_end = timespec_sub(&t_end, &t_start);
*duration += timespec_to_usec(&t_end);
ldata->duration += timespec_to_usec(&t_end); } break; case rtapp_runtime:@@ -313,7 +312,7 @@ static int run_event(event_data_t *event, int dry_run, } while ((diff_ns / 1000) < event->duration);
t_end = timespec_sub(&t_end, &t_start);
*duration += timespec_to_usec(&t_end);
ldata->duration += timespec_to_usec(&t_end); } break; case rtapp_timer:@@ -322,7 +321,7 @@ static int run_event(event_data_t *event, int dry_run, log_debug("timer %d ", event->duration);
t_period = usec_to_timespec(event->duration);
*c_period += event->duration;
ldata->c_period += event->duration; if (rdata->res.timer.init == 0) { rdata->res.timer.init = 1;@@ -332,15 +331,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); t_slack = timespec_sub(&rdata->res.timer.t_next, &t_now);
*slack += timespec_to_usec_long(&t_slack);
ldata->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); t_wu = timespec_sub(&t_now, &rdata->res.timer.t_next);
*wu_latency = timespec_to_usec(&t_wu);
ldata->wu_latency = timespec_to_usec(&t_wu); } else { clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next);
*wu_latency = 0UL;
ldata->wu_latency = 0UL; } } break;@@ -377,12 +376,11 @@ static int run_event(event_data_t *event, int dry_run, return lock; }
-int run(int ind, phase_data_t *pdata, unsigned long *duration,
rtapp_resource_t *resources,struct timespec *t_first,unsigned long *wu_latency,long *slack,unsigned long *c_period)+int run(int ind,
phase_data_t *pdata,rtapp_resource_t *resources,struct timespec *t_first,log_data_t *ldata){ event_data_t *events = pdata->events; int nbevents = pdata->nbevents; @@ -400,8 +398,7 @@ int run(int ind, phase_data_t *pdata, unsigned long *duration, "[%d] executing %d", ind, i); lock += run_event(&events[i], !continue_running, &perf,
duration, resources, t_first, wu_latency, slack,c_period);
resources, t_first, ldata); } return perf;@@ -446,10 +443,10 @@ void *thread_body(void *arg) { thread_data_t *data = (thread_data_t*) arg; phase_data_t *pdata;
log_data_t ldata; struct sched_param param; struct timespec t_start, t_end, t_first; unsigned long t_start_usec;
unsigned long perf, duration, wu_latency, c_period; long slack; timing_point_t *curr_timing; timing_point_t *timings;@@ -624,10 +621,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 = slack = c_period = 0;
memset(&ldata, 0, sizeof(ldata)); clock_gettime(CLOCK_MONOTONIC, &t_start);
perf = run(data->ind, pdata, &duration, *(data->resources),&t_first, &wu_latency, &slack, &c_period);
ldata.perf = run(data->ind, pdata, *(data->resources),&t_first, &ldata); clock_gettime(CLOCK_MONOTONIC, &t_end); if (timings)@@ -643,11 +640,11 @@ void *thread_body(void *arg) curr_timing->start_time = timespec_to_usec_ull(&t_start); curr_timing->end_time = timespec_to_usec_ull(&t_end); curr_timing->period = timespec_to_usec(&t_diff);
curr_timing->duration = duration;curr_timing->perf = perf;curr_timing->wu_latency = wu_latency;curr_timing->slack = slack;curr_timing->c_period = c_period;
curr_timing->duration = ldata.duration;curr_timing->perf = ldata.perf;curr_timing->wu_latency = ldata.wu_latency;curr_timing->slack = ldata.slack;curr_timing->c_period = ldata.c_period; if (opts.logsize && !timings && continue_running) log_timing(data->log_handler, curr_timing);diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 0ec8781562ee..276bce02d1e6 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -160,6 +160,14 @@ typedef struct _ftrace_data_t { int marker_fd; } ftrace_data_t;
+typedef struct _log_data_t {
unsigned long perf;unsigned long duration;unsigned long wu_latency;unsigned long c_period;long slack;+} log_data_t;
typedef struct _rtapp_options_t { int lock_pages;
-- 2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
Move wu_lat to the end of the log, so that can be easily removed in the future if not needed anymore.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
src/rt-app.c | 6 +++--- src/rt-app_utils.c | 6 +++--- 2 files changed, 6 insertions(+), 6 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 2c2dc1263def..6e80d21c0cf8 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -587,10 +587,10 @@ 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 %10s %8s\n",
fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %8s %10s\n", "#idx", "perf", "run", "period",
"start", "end", "rel_st", "wu_lat", "slack","c_prd");
"start", "end", "rel_st", "slack","c_prd", "wu_lat"); if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index e7cd8a83cec7..747ac2b7d83d 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler,
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10lu %10ld %8lu",
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %8lu %10lu", t->ind, t->perf, t->duration,@@ -148,9 +148,9 @@ log_timing(FILE *handler, timing_point_t *t) t->start_time, t->end_time, t->rel_start_time,
t->wu_latency, t->slack,t->c_period
t->c_period,t->wu_latency ); fprintf(handler, "\n");}
2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
As the name is more understandable.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
src/rt-app.c | 4 ++-- src/rt-app_utils.c | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 6e80d21c0cf8..66ae021cb180 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -587,10 +587,10 @@ 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 %8s %10s\n",
fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s %10s\n", "#idx", "perf", "run", "period", "start", "end", "rel_st", "slack",
"c_prd", "wu_lat");
"c_period", "wu_lat"); if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index 747ac2b7d83d..ea5724d8c523 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler,
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %8lu %10lu",
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %10lu %10lu", t->ind, t->perf, t->duration,-- 2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
Add c_duration (sum of durations of the different events that comes from json configuration file). This is handy for post-processing logs.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
src/rt-app.c | 7 +++++-- src/rt-app_types.h | 2 ++ src/rt-app_utils.c | 3 ++- 3 files changed, 9 insertions(+), 3 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index 66ae021cb180..becc3649f791 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -288,6 +288,7 @@ static int run_event(event_data_t *event, int dry_run, { struct timespec t_start, t_end; log_debug("run %d ", event->duration);
ldata->c_duration += event->duration; clock_gettime(CLOCK_MONOTONIC, &t_start); *perf += loadwait(event->duration); clock_gettime(CLOCK_MONOTONIC, &t_end);@@ -301,6 +302,7 @@ static int run_event(event_data_t *event, int dry_run, int64_t diff_ns;
log_debug("runtime %d ", event->duration);
ldata->c_duration += event->duration; clock_gettime(CLOCK_MONOTONIC, &t_start); do {@@ -587,10 +589,10 @@ 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 %10s %10s\n",
fprintf(data->log_handler, "%s %8s %8s %8s %15s %15s %15s %10s %10s %10s %10s\n", "#idx", "perf", "run", "period", "start", "end", "rel_st", "slack",
"c_period", "wu_lat");
"c_duration", "c_period", "wu_lat"); if (opts.ftrace) log_ftrace(ft_data.marker_fd, "[%d] starts", data->ind);@@ -645,6 +647,7 @@ void *thread_body(void *arg) curr_timing->wu_latency = ldata.wu_latency; curr_timing->slack = ldata.slack; curr_timing->c_period = ldata.c_period;
curr_timing->c_duration = ldata.c_duration; if (opts.logsize && !timings && continue_running) log_timing(data->log_handler, curr_timing);diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 276bce02d1e6..ae088f0f4c4b 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -164,6 +164,7 @@ typedef struct _log_data_t { unsigned long perf; unsigned long duration; unsigned long wu_latency;
unsigned long c_duration; unsigned long c_period; long slack;} log_data_t; @@ -199,6 +200,7 @@ typedef struct _timing_point_t { unsigned long perf; unsigned long duration; unsigned long period;
unsigned long c_duration; unsigned long c_period; unsigned long wu_latency; long slack;diff --git a/src/rt-app_utils.c b/src/rt-app_utils.c index ea5724d8c523..f12f48cffa90 100644 --- a/src/rt-app_utils.c +++ b/src/rt-app_utils.c @@ -140,7 +140,7 @@ void log_timing(FILE *handler, timing_point_t *t) { fprintf(handler,
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %10lu %10lu",
"%4d %8lu %8lu %8lu %15llu %15llu %15llu %10ld %10lu %10lu %10lu", t->ind, t->perf, t->duration,@@ -149,6 +149,7 @@ log_timing(FILE *handler, timing_point_t *t) t->end_time, t->rel_start_time, t->slack,
t->c_duration, t->c_period, t->wu_latency );-- 2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
Don't explicitly manage start/stop of tracing, but assume that the caller does that before starting rt-app. This helps if the caller wants more padding before/after an rt-app execution.
In case tracing is not started and ftrace is enable in the json configuration, rt-app will fail to start.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
src/rt-app.c | 17 ++--------------- 1 file changed, 2 insertions(+), 15 deletions(-)
diff --git a/src/rt-app.c b/src/rt-app.c index becc3649f791..e32dbe413ef4 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -40,7 +40,6 @@ static pthread_barrier_t threads_barrier;
static ftrace_data_t ft_data = { .debugfs = "/sys/kernel/debug",
.trace_fd = -1, .marker_fd = -1,};
@@ -431,10 +430,8 @@ shutdown(int sig) }
if (opts.ftrace) {
log_notice("stopping ftrace"); log_ftrace(ft_data.marker_fd, "main ends\n");log_ftrace(ft_data.trace_fd, "0");close(ft_data.trace_fd);
log_notice("deconfiguring ftrace"); close(ft_data.marker_fd); }@@ -732,21 +729,14 @@ int main(int argc, char* argv[]) log_notice("configuring ftrace"); strcpy(tmp, ft_data.debugfs); strcat(tmp, "/tracing/tracing_on");
ft_data.trace_fd = open(tmp, O_WRONLY);if (ft_data.trace_fd < 0) {log_error("Cannot open trace_fd file %s", tmp);exit(EXIT_FAILURE);}strcpy(tmp, ft_data.debugfs); strcat(tmp, "/tracing/trace_marker"); ft_data.marker_fd = open(tmp, O_WRONLY);if (ft_data.trace_fd < 0) {
if (ft_data.marker_fd < 0) { log_error("Cannot open trace_marker file %s", tmp); exit(EXIT_FAILURE); }
log_ftrace(ft_data.trace_fd, "1"); log_ftrace(ft_data.marker_fd, "main creates threads\n"); }@@ -936,10 +926,7 @@ int main(int argc, char* argv[]) }
if (opts.ftrace) {
log_notice("stopping ftrace"); log_ftrace(ft_data.marker_fd, "main ends\n");log_ftrace(ft_data.trace_fd, "0");close(ft_data.trace_fd); close(ft_data.marker_fd); } exit(EXIT_SUCCESS);-- 2.10.0
On 24 November 2016 at 11:32, Juri Lelli juri.lelli@arm.com wrote:
Implement "relative" (current behavior) and "absolute" working modes for timer events. Text added in doc/tutorial.txt gives more information about the two modes.
Signed-off-by: Juri Lelli juri.lelli@arm.com
Acked-by: Vincent Guittot vincent.guittot@linaro.org
doc/tutorial.txt | 64 +++++++++++++++++++++++++++++++++++++++++++++++ src/rt-app.c | 3 ++- src/rt-app_parse_config.c | 6 +++++ src/rt-app_types.h | 1 + 4 files changed, 73 insertions(+), 1 deletion(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index dfcc40567729..a4455b601cd3 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -321,6 +321,70 @@ below: } }
+Timers can work with a "relative" or an "absolute" reference. By default they +work in "relative" mode, but this mode can also be explicity specified as the +following:
"phases" : {"phase0" : {"loop" : 10,"run0" : 10000,"timer0" : { "ref" : "unique", "period" : 20000, "mode" : "relative" },}+"relative" mode means that the reference for setting the next timer event is +relative to the end of the current phase. This in turn means that if, for some +reason (i.e., clock frequency was too low), events in a certain phase took too +long to execute and the timer of that phase couldn't actually fire at all, the +next phase won't be affected. For example:
- +---- + +-----+ +-------------------+-----+ +---
- |r0 | |r0 | |r0 |r0 | |r0
- | | | | | | | |
- o-----------o-----------o-------------------o-----------o------->
- 0 10 20 30 40 50 60 70 80 100 120
^ ^ ^ ^| | | MISS! |+ + + +Timer0 Timer0 Timer0 Timer0+In this example character "o" denotes when phases finish/start. Third +activation of Timer0 is missed, since r0 executed for more that 20ms. However +the next phase is not affected as Timer0 was set considering the instant of +time when the misbehaving r0 finished executing.
+"absolute" mode is specified as the following:
"phases" : {"phase0" : {"loop" : 10,"run0" : 10000,"timer0" : { "ref" : "unique", "period" : 20000, "mode" : "absolute" },}+"absolute" mode means that the reference for setting the next timer event is +fixed and always consider the starting time of the first phase. This means that +if, for some reason (i.e., clock frequency was too low), events in a certain +phase took too long to execute and the timer of that phase couldn't actually +fire at all, the next phase (and potentially other subsequent phases) _will_ be +affected. For example, considering again the example above:
- +---- + +-----+ +-------------------+-----+-----+ +---
- |r0 | |r0 | |r0 |r0 |r0 | |r0
- | | | | | | | | |
- o-----------o-----------o-------------------o-----o---------o---->
- 0 10 20 30 40 50 60 70 80 100 120
^ ^ ^ ^ ^| | | MISS! | MISS! |+ + + + +Timer0 Timer0 Timer0 Timer0 Timer0+Third activation of Timer0 is missed, since r0 executed for more that 20ms. +Even if 4th activation of r0 executes for 10ms (as specified in the +configuration), 4th Timer0 is still missed because the reference didn't change. +In this example 5th activation of r0 then managed to recover, but in general it +depends on how badly a certain phase misbehaves.
lock : String. Lock the mutex defined by the string value.
unlock : String. Unlock the mutex defined by the string value.
diff --git a/src/rt-app.c b/src/rt-app.c index 93282e0a068c..5b67a935397f 100644 --- a/src/rt-app.c +++ b/src/rt-app.c @@ -339,7 +339,8 @@ static int run_event(event_data_t *event, int dry_run, t_wu = timespec_sub(&t_now, &rdata->res.timer.t_next); ldata->wu_latency = timespec_to_usec(&t_wu); } else {
clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next);
if (rdata->res.timer.relative)clock_gettime(CLOCK_MONOTONIC, &rdata->res.timer.t_next); ldata->wu_latency = 0UL; } }diff --git a/src/rt-app_parse_config.c b/src/rt-app_parse_config.c index b0f302e2ba25..fbc4612b2257 100644 --- a/src/rt-app_parse_config.c +++ b/src/rt-app_parse_config.c @@ -181,6 +181,7 @@ static int init_timer_resource(rtapp_resource_t *data, const rtapp_options_t *op { log_info(PIN3 "Init: %s timer", data->name); data->res.timer.init = 0;
data->res.timer.relative = 1;}
static int init_cond_resource(rtapp_resource_t *data, const rtapp_options_t *opts) @@ -489,6 +490,11 @@ parse_thread_event_data(char *name, struct json_object *obj, rdata = &(opts->resources[data->res]); ddata = &(opts->resources[data->dep]);
tmp = get_string_value_from(obj, "mode", TRUE, "relative");if (!strncmp(tmp, "absolute", strlen("absolute")))rdata->res.timer.relative = 0;free(tmp);log_info(PIN2 "type %d target %s [%d] period %d", data->type, rdata->name, rdata->index, data->duration); return; }diff --git a/src/rt-app_types.h b/src/rt-app_types.h index 89983203f479..718ce7798cc2 100644 --- a/src/rt-app_types.h +++ b/src/rt-app_types.h @@ -87,6 +87,7 @@ struct _rtapp_signal { struct _rtapp_timer { struct timespec t_next; int init;
int relative;};
struct _rtapp_iomem_buf {
2.10.0
Vincent,
I think this is the only one you didn't yet acked (apart from the wu_lat one that I modified locally as you suggested).
Are you OK with this one below as well?
Thanks a lot for your review!
On 24/11/16 10:32, Juri Lelli wrote:
Add descrition for newly introduced log header fiels (slack, c_duration, c_period and wu_lat).
Signed-off-by: Juri Lelli juri.lelli@arm.com
doc/tutorial.txt | 36 +++++++++++++++++++++++++++--------- 1 file changed, 27 insertions(+), 9 deletions(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index 78cd1fe0e2e2..bb6734c0b076 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -430,20 +430,38 @@ metrics are:
- run: time spent by the thread to execute the run events
- period: duration to execute the complte phase
- start/end : absolute start and end time of a phase. Same time base is used in
-ftrace
- ftrace
- rel_st: start time of a phase relatively to the beg of the use case
+- 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.
- taskA ...|-- run5 --|- sleep5 -|-- run5--|..timer20.|-- run5 --|- sleep5 -|-- run6 --|.timer20.|
<--------------- period 20 --------------> <--------------- period 20 --------------><-slack5-> <slack4->- it can also be negative if the execution of a phases' events overshoots the
- current period, e.g.
- taskA ...|-- run5 --|- sleep5 -|------- run30 ------xxxxxxxxxx|
<--------------- period 20 --------------><slack-5>+- c_duration: sum of the configured duration of run/runtime events +- c_period: sum of the timer(s) period(s) +- wu_lat: sum of wakeup latencies after timer events Below is an extract of a log: # Policy : SCHED_OTHER priority : 0 -#idx perf run period start end rel_st -0 500000 34382 114492 175604833899 175604948391 785 -0 500000 29786 109863 175604948437 175605058300 115323 -0 500000 26977 107077 175605058336 175605165413 225223 -0 500000 28667 108771 175605165458 175605274229 332344 -0 500000 26644 106745 175605274274 175605381019 441160 -0 500000 26745 106867 175605381061 175605487928 547947 -0 500000 29513 109620 175605487974 175605597595 654860 +#idx perf run period start end rel_st slack c_duration c_period wu_lat
- 0 92164 19935 98965 504549567051 504549666016 2443 78701 20000 100000 266
- 0 92164 19408 99952 504549666063 504549766015 101455 80217 20000 100000 265
- 0 92164 19428 99952 504549766062 504549866014 201454 80199 20000 100000 264
- 0 92164 19438 99955 504549866060 504549966015 301452 80190 20000 100000 265
- 0 92164 19446 99952 504549966061 504550066013 401453 80093 20000 100000 264
- 0 92164 19415 99953 504550066060 504550166013 501452 80215 20000 100000 263
- 0 92164 19388 99954 504550166059 504550266013 601451 80242 20000 100000 264
- 0 92164 19444 99956 504550266060 504550366015 701452 80185 20000 100000 265
Some gnuplot files are also created to generate charts based on the log files for each thread and for each kind of metrics. The format of the chart that -- 2.10.0
Le 24 nov. 2016 7:35 PM, "Juri Lelli" juri.lelli@arm.com a écrit :
Vincent,
I think this is the only one you didn't yet acked (apart from the wu_lat one that I modified locally as you suggested).
Are you OK with this one below as well?
Yes this one with the modification for wu_lat looks ok
Thanks a lot for your review!
On 24/11/16 10:32, Juri Lelli wrote:
Add descrition for newly introduced log header fiels (slack, c_duration, c_period and wu_lat).
Signed-off-by: Juri Lelli juri.lelli@arm.com
doc/tutorial.txt | 36 +++++++++++++++++++++++++++--------- 1 file changed, 27 insertions(+), 9 deletions(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index 78cd1fe0e2e2..bb6734c0b076 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -430,20 +430,38 @@ metrics are:
- run: time spent by the thread to execute the run events
- period: duration to execute the complte phase
- start/end : absolute start and end time of a phase. Same time base
is used in
-ftrace
- ftrace
- rel_st: start time of a phase relatively to the beg of the use case
+- 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.
- taskA ...|-- run5 --|- sleep5 -|-- run5--|..timer20.|-- run5 --|-
sleep5 -|-- run6 --|.timer20.|
<--------------- period 20 -------------->
<--------------- period 20 -------------->
<-slack5->
<slack4->
- it can also be negative if the execution of a phases' events
overshoots the
- current period, e.g.
- taskA ...|-- run5 --|- sleep5 -|------- run30 ------xxxxxxxxxx|
<--------------- period 20 --------------><slack-5>+- c_duration: sum of the configured duration of run/runtime events +- c_period: sum of the timer(s) period(s) +- wu_lat: sum of wakeup latencies after timer events
Below is an extract of a log:
# Policy : SCHED_OTHER priority : 0 -#idx perf run period start end
rel_st
-0 500000 34382 114492 175604833899 175604948391
785
-0 500000 29786 109863 175604948437 175605058300
115323
-0 500000 26977 107077 175605058336 175605165413
225223
-0 500000 28667 108771 175605165458 175605274229
332344
-0 500000 26644 106745 175605274274 175605381019
441160
-0 500000 26745 106867 175605381061 175605487928
547947
-0 500000 29513 109620 175605487974 175605597595
654860
+#idx perf run period start end
rel_st slack c_duration c_period wu_lat
- 0 92164 19935 98965 504549567051 504549666016
2443 78701 20000 100000 266
- 0 92164 19408 99952 504549666063 504549766015
101455 80217 20000 100000 265
- 0 92164 19428 99952 504549766062 504549866014
201454 80199 20000 100000 264
- 0 92164 19438 99955 504549866060 504549966015
301452 80190 20000 100000 265
- 0 92164 19446 99952 504549966061 504550066013
401453 80093 20000 100000 264
- 0 92164 19415 99953 504550066060 504550166013
501452 80215 20000 100000 263
- 0 92164 19388 99954 504550166059 504550266013
601451 80242 20000 100000 264
- 0 92164 19444 99956 504550266060 504550366015
701452 80185 20000 100000 265
Some gnuplot files are also created to generate charts based on the
log files
for each thread and for each kind of metrics. The format of the chart
that
-- 2.10.0
On 24/11/16 19:48, Vincent Guittot wrote:
Le 24 nov. 2016 7:35 PM, "Juri Lelli" juri.lelli@arm.com a écrit :
Vincent,
I think this is the only one you didn't yet acked (apart from the wu_lat one that I modified locally as you suggested).
Are you OK with this one below as well?
Yes this one with the modification for wu_lat looks ok
OK, great! So tomorrow I'll see what's the best way of merging the set. I guess a pull request and then we merge it.
Thanks a lot for your review!
On 24/11/16 10:32, Juri Lelli wrote:
Add descrition for newly introduced log header fiels (slack, c_duration, c_period and wu_lat).
Signed-off-by: Juri Lelli juri.lelli@arm.com
doc/tutorial.txt | 36 +++++++++++++++++++++++++++--------- 1 file changed, 27 insertions(+), 9 deletions(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index 78cd1fe0e2e2..bb6734c0b076 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -430,20 +430,38 @@ metrics are:
- run: time spent by the thread to execute the run events
- period: duration to execute the complte phase
- start/end : absolute start and end time of a phase. Same time base
is used in
-ftrace
- ftrace
- rel_st: start time of a phase relatively to the beg of the use case
+- 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.
- taskA ...|-- run5 --|- sleep5 -|-- run5--|..timer20.|-- run5 --|-
sleep5 -|-- run6 --|.timer20.|
<--------------- period 20 --------------><--------------- period 20 -------------->
<-slack5-><slack4->
- it can also be negative if the execution of a phases' events
overshoots the
- current period, e.g.
- taskA ...|-- run5 --|- sleep5 -|------- run30 ------xxxxxxxxxx|
<--------------- period 20 --------------><slack-5>+- c_duration: sum of the configured duration of run/runtime events +- c_period: sum of the timer(s) period(s) +- wu_lat: sum of wakeup latencies after timer events
Below is an extract of a log:
# Policy : SCHED_OTHER priority : 0 -#idx perf run period start end
rel_st-0 500000 34382 114492 175604833899 175604948391
785
-0 500000 29786 109863 175604948437 175605058300
115323
-0 500000 26977 107077 175605058336 175605165413
225223
-0 500000 28667 108771 175605165458 175605274229
332344
-0 500000 26644 106745 175605274274 175605381019
441160
-0 500000 26745 106867 175605381061 175605487928
547947
-0 500000 29513 109620 175605487974 175605597595
654860
+#idx perf run period start end
rel_st slack c_duration c_period wu_lat
- 0 92164 19935 98965 504549567051 504549666016
2443 78701 20000 100000 266
- 0 92164 19408 99952 504549666063 504549766015
101455 80217 20000 100000 265
- 0 92164 19428 99952 504549766062 504549866014
201454 80199 20000 100000 264
- 0 92164 19438 99955 504549866060 504549966015
301452 80190 20000 100000 265
- 0 92164 19446 99952 504549966061 504550066013
401453 80093 20000 100000 264
- 0 92164 19415 99953 504550066060 504550166013
501452 80215 20000 100000 263
- 0 92164 19388 99954 504550166059 504550266013
601451 80242 20000 100000 264
- 0 92164 19444 99956 504550266060 504550366015
701452 80185 20000 100000 265
Some gnuplot files are also created to generate charts based on the
log files
for each thread and for each kind of metrics. The format of the chart
that
-- 2.10.0
On 24 November 2016 at 19:53, Juri Lelli juri.lelli@arm.com wrote:
On 24/11/16 19:48, Vincent Guittot wrote:
Le 24 nov. 2016 7:35 PM, "Juri Lelli" juri.lelli@arm.com a écrit :
Vincent,
I think this is the only one you didn't yet acked (apart from the wu_lat one that I modified locally as you suggested).
Are you OK with this one below as well?
Yes this one with the modification for wu_lat looks ok
OK, great! So tomorrow I'll see what's the best way of merging the set. I guess a pull request and then we merge it.
Yes That's seems the simplest way
Thanks a lot for your review!
On 24/11/16 10:32, Juri Lelli wrote:
Add descrition for newly introduced log header fiels (slack, c_duration, c_period and wu_lat).
Signed-off-by: Juri Lelli juri.lelli@arm.com
doc/tutorial.txt | 36 +++++++++++++++++++++++++++--------- 1 file changed, 27 insertions(+), 9 deletions(-)
diff --git a/doc/tutorial.txt b/doc/tutorial.txt index 78cd1fe0e2e2..bb6734c0b076 100644 --- a/doc/tutorial.txt +++ b/doc/tutorial.txt @@ -430,20 +430,38 @@ metrics are:
- run: time spent by the thread to execute the run events
- period: duration to execute the complte phase
- start/end : absolute start and end time of a phase. Same time base
is used in
-ftrace
- ftrace
- rel_st: start time of a phase relatively to the beg of the use case
+- 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.
- taskA ...|-- run5 --|- sleep5 -|-- run5--|..timer20.|-- run5 --|-
sleep5 -|-- run6 --|.timer20.|
<--------------- period 20 --------------><--------------- period 20 -------------->
<-slack5-><slack4->
- it can also be negative if the execution of a phases' events
overshoots the
- current period, e.g.
- taskA ...|-- run5 --|- sleep5 -|------- run30 ------xxxxxxxxxx|
<--------------- period 20 --------------><slack-5>+- c_duration: sum of the configured duration of run/runtime events +- c_period: sum of the timer(s) period(s) +- wu_lat: sum of wakeup latencies after timer events
Below is an extract of a log:
# Policy : SCHED_OTHER priority : 0 -#idx perf run period start end
rel_st-0 500000 34382 114492 175604833899 175604948391
785
-0 500000 29786 109863 175604948437 175605058300
115323
-0 500000 26977 107077 175605058336 175605165413
225223
-0 500000 28667 108771 175605165458 175605274229
332344
-0 500000 26644 106745 175605274274 175605381019
441160
-0 500000 26745 106867 175605381061 175605487928
547947
-0 500000 29513 109620 175605487974 175605597595
654860
+#idx perf run period start end
rel_st slack c_duration c_period wu_lat
- 0 92164 19935 98965 504549567051 504549666016
2443 78701 20000 100000 266
- 0 92164 19408 99952 504549666063 504549766015
101455 80217 20000 100000 265
- 0 92164 19428 99952 504549766062 504549866014
201454 80199 20000 100000 264
- 0 92164 19438 99955 504549866060 504549966015
301452 80190 20000 100000 265
- 0 92164 19446 99952 504549966061 504550066013
401453 80093 20000 100000 264
- 0 92164 19415 99953 504550066060 504550166013
501452 80215 20000 100000 263
- 0 92164 19388 99954 504550166059 504550266013
601451 80242 20000 100000 264
- 0 92164 19444 99956 504550266060 504550366015
701452 80185 20000 100000 265
Some gnuplot files are also created to generate charts based on the
log files
for each thread and for each kind of metrics. The format of the chart
that
-- 2.10.0
-
Juri Lelli -
Vincent Guittot