/* * The alternate latency measurement program based on the Alchemy API. * * Licensed under the LGPL v2.1. */ #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include RT_TASK latency_task, display_task; RT_SEM display_sem; #define TEN_MILLIONS 10000000 unsigned max_relaxed; int32_t minjitter, maxjitter, avgjitter; int32_t gminjitter = TEN_MILLIONS, gmaxjitter = -TEN_MILLIONS, goverrun = 0; int64_t gavgjitter = 0; long long period_ns = 0; int test_duration = 0; /* sec of testing, via -T , 0 is inf */ int data_lines = 21; /* data lines per header line, -l to change */ int quiet = 0; /* suppress printing of RTH, RTD lines when -T given */ int devfd = -1; int freeze_max = 0; int priority = T_HIPRIO; int stop_upon_switch = 0; sig_atomic_t sampling_relaxed = 0; #define USER_TASK 0 #define KERNEL_TASK 1 #define TIMER_HANDLER 2 int test_mode = USER_TASK; const char *test_mode_names[] = { "periodic user-mode task", "in-kernel periodic task", "in-kernel timer handler" }; time_t test_start, test_end; /* report test duration */ int test_loops = 0; /* outer loop count */ /* Warmup time : in order to avoid spurious cache effects on low-end machines. */ #define WARMUP_TIME 1 #define HISTOGRAM_CELLS 300 int histogram_size = HISTOGRAM_CELLS; int32_t *histogram_avg = NULL, *histogram_max = NULL, *histogram_min = NULL; char *do_gnuplot = NULL; int do_histogram = 0, do_stats = 0, finished = 0; int bucketsize = 1000; /* default = 1000ns, -B to override */ #define need_histo() (do_histogram || do_stats || do_gnuplot) static inline void add_histogram(int32_t *histogram, int32_t addval) { /* bucketsize steps */ int inabs = (addval >= 0 ? addval : -addval) / bucketsize; histogram[inabs < histogram_size ? inabs : histogram_size - 1]++; } static void latency(void *cookie) { RTIME expected_ns, start_ns, fault_threshold; unsigned int old_relaxed = 0, new_relaxed; int ret, count, nsamples, warmup = 1; int32_t minj, maxj, dt, overrun, sumj; unsigned long ov; fault_threshold = CONFIG_XENO_DEFAULT_PERIOD; nsamples = (long long)ONE_BILLION / period_ns; start_ns = rt_timer_read() + 1000000; /* 1ms from now */ expected_ns = start_ns; ret = rt_task_set_periodic(NULL, start_ns, period_ns); if (ret) { fprintf(stderr, "altency: failed to set periodic, code %d\n", ret); return; } for (;;) { minj = TEN_MILLIONS; maxj = -TEN_MILLIONS; overrun = 0; test_loops++; for (count = sumj = 0; count < nsamples; count++) { ret = rt_task_wait_period(&ov); dt = (int32_t)(rt_timer_read() - expected_ns); new_relaxed = sampling_relaxed; if (dt > maxj) { if (new_relaxed != old_relaxed && dt > fault_threshold) max_relaxed += new_relaxed - old_relaxed; maxj = dt; } old_relaxed = new_relaxed; if (dt < minj) minj = dt; sumj += dt; if (ret) { if (ret != -ETIMEDOUT) { fprintf(stderr, "altency: wait period failed, code %d\n", ret); exit(EXIT_FAILURE); /* Timer stopped. */ } overrun += ov; expected_ns += period_ns * ov; } expected_ns += period_ns; if (freeze_max && (dt > gmaxjitter) && !(finished || warmup)) { xntrace_user_freeze(dt, 0); gmaxjitter = dt; } if (!(finished || warmup) && need_histo()) add_histogram(histogram_avg, dt); } if (!warmup) { if (!finished && need_histo()) { add_histogram(histogram_max, maxj); add_histogram(histogram_min, minj); } minjitter = minj; if (minj < gminjitter) gminjitter = minj; maxjitter = maxj; if (maxj > gmaxjitter) gmaxjitter = maxj; avgjitter = sumj / nsamples; gavgjitter += avgjitter; goverrun += overrun; rt_sem_v(&display_sem); } if (warmup && test_loops == WARMUP_TIME) { test_loops = 0; warmup = 0; } } } static void display(void *cookie) { char sem_name[16]; int ret, n = 0; time_t start; if (test_mode == USER_TASK) { snprintf(sem_name, sizeof(sem_name), "dispsem-%d", getpid()); ret = rt_sem_create(&display_sem, sem_name, 0, S_FIFO); if (ret) { fprintf(stderr, "altency: cannot create semaphore: %s\n", strerror(-ret)); return; } } else { struct rttst_tmbench_config config; if (test_mode == KERNEL_TASK) config.mode = RTTST_TMBENCH_TASK; else config.mode = RTTST_TMBENCH_HANDLER; config.period = period_ns; config.priority = priority; config.warmup_loops = WARMUP_TIME; config.histogram_size = need_histo() ? histogram_size : 0; config.histogram_bucketsize = bucketsize; config.freeze_max = freeze_max; ret = ioctl(devfd, RTTST_RTIOC_TMBENCH_START, &config); if (ret) { fprintf(stderr, "altency: failed to start in-kernel timer benchmark, code %d\n", ret); return; } } time(&start); if (WARMUP_TIME) printf("warming up...\n"); if (quiet) fprintf(stderr, "running quietly for %d seconds\n", test_duration); for (;;) { int32_t minj, gminj, maxj, gmaxj, avgj; if (test_mode == USER_TASK) { ret = rt_sem_p(&display_sem, TM_INFINITE); if (ret) { if (ret != -EIDRM) fprintf(stderr, "altency: failed to pend on semaphore, code %d\n", ret); return; } minj = minjitter; gminj = gminjitter; avgj = avgjitter; maxj = maxjitter; gmaxj = gmaxjitter; } else { struct rttst_interm_bench_res result; ret = ioctl(devfd, RTTST_RTIOC_INTERM_BENCH_RES, &result); if (ret) { if (ret != -EIDRM) fprintf(stderr, "altency: failed to call RTTST_RTIOC_INTERM_BENCH_RES, %m\n"); return; } minj = result.last.min; gminj = result.overall.min; avgj = result.last.avg; maxj = result.last.max; gmaxj = result.overall.max; goverrun = result.overall.overruns; } if (!quiet) { if (data_lines && (n++ % data_lines) == 0) { time_t now, dt; time(&now); dt = now - start - WARMUP_TIME; printf ("RTT| %.2ld:%.2ld:%.2ld (%s, %Ld us period, " "priority %d)\n", dt / 3600, (dt / 60) % 60, dt % 60, test_mode_names[test_mode], period_ns / 1000, priority); printf("RTH|%11s|%11s|%11s|%8s|%6s|%11s|%11s\n", "----lat min", "----lat avg", "----lat max", "-overrun", "---msw", "---lat best", "--lat worst"); } printf("RTD|%11.3f|%11.3f|%11.3f|%8d|%6u|%11.3f|%11.3f\n", (double)minj / 1000, (double)avgj / 1000, (double)maxj / 1000, goverrun, max_relaxed, (double)gminj / 1000, (double)gmaxj / 1000); } } } static double dump_histogram(int32_t *histogram, char *kind) { int n, total_hits = 0; double avg = 0; /* used to sum hits 1st */ if (do_histogram) printf("---|--param|----range-|--samples\n"); for (n = 0; n < histogram_size; n++) { int32_t hits = histogram[n]; if (hits) { total_hits += hits; avg += n * hits; if (do_histogram) printf("HSD| %s| %3d -%3d | %8d\n", kind, n, n + 1, hits); } } avg /= total_hits; /* compute avg, reuse variable */ return avg; } static void dump_histo_gnuplot(int32_t *histogram) { unsigned start, stop; FILE *f; int n; f = fopen(do_gnuplot, "w"); if (!f) return; for (n = 0; n < histogram_size && histogram[n] == 0L; n++) ; start = n; for (n = histogram_size - 1; n >= 0 && histogram[n] == 0L; n--) ; stop = n; fprintf(f, "%g 1\n", start * bucketsize / 1000.0); for (n = start; n <= stop; n++) fprintf(f, "%g %d\n", (n + 0.5) * bucketsize / 1000.0, histogram[n] + 1); fprintf(f, "%g 1\n", (stop + 1) * bucketsize / 1000.0); fclose(f); } static void dump_stats(int32_t *histogram, char *kind, double avg) { int n, total_hits = 0; double variance = 0; for (n = 0; n < histogram_size; n++) { int32_t hits = histogram[n]; if (hits) { total_hits += hits; variance += hits * (n - avg) * (n - avg); } } /* compute std-deviation (unbiased form) */ if (total_hits > 1) { variance /= total_hits - 1; variance = sqrt(variance); } else variance = 0; printf("HSS| %s| %9d| %10.3f| %10.3f\n", kind, total_hits, avg, variance); } static void dump_hist_stats(void) { double minavg, maxavg, avgavg; /* max is last, where its visible w/o scrolling */ minavg = dump_histogram(histogram_min, "min"); avgavg = dump_histogram(histogram_avg, "avg"); maxavg = dump_histogram(histogram_max, "max"); printf("HSH|--param|--samples-|--average--|---stddev--\n"); dump_stats(histogram_min, "min", minavg); dump_stats(histogram_avg, "avg", avgavg); dump_stats(histogram_max, "max", maxavg); if (do_gnuplot) dump_histo_gnuplot(histogram_avg); } static void cleanup(void) { time_t actual_duration; int32_t gmaxj, gminj, gavgj; if (test_mode == USER_TASK) { rt_sem_delete(&display_sem); gavgjitter /= (test_loops > 1 ? test_loops : 2) - 1; gminj = gminjitter; gmaxj = gmaxjitter; gavgj = gavgjitter; } else { struct rttst_overall_bench_res overall; overall.histogram_min = histogram_min; overall.histogram_max = histogram_max; overall.histogram_avg = histogram_avg; ioctl(devfd, RTTST_RTIOC_TMBENCH_STOP, &overall); gminj = overall.result.min; gmaxj = overall.result.max; gavgj = overall.result.avg; goverrun = overall.result.overruns; } if (devfd >= 0) close(devfd); if (need_histo()) dump_hist_stats(); time(&test_end); actual_duration = test_end - test_start - WARMUP_TIME; if (!test_duration) test_duration = actual_duration; printf ("---|-----------|-----------|-----------|--------|------|-------------------------\n" "RTS|%11.3f|%11.3f|%11.3f|%8d|%6u| %.2ld:%.2ld:%.2ld/%.2d:%.2d:%.2d\n", (double)gminj / 1000, (double)gavgj / 1000, (double)gmaxj / 1000, goverrun, max_relaxed, actual_duration / 3600, (actual_duration / 60) % 60, actual_duration % 60, test_duration / 3600, (test_duration / 60) % 60, test_duration % 60); if (max_relaxed > 0) printf( "Warning! some latency peaks may have been due to involuntary mode switches.\n" "Please contact xenomai@xenomai.org\n"); if (histogram_avg) free(histogram_avg); if (histogram_max) free(histogram_max); if (histogram_min) free(histogram_min); exit(0); } static void faulthand(int sig) { xntrace_user_freeze(0, 1); signal(sig, SIG_DFL); __STD(kill(getpid(), sig)); } #ifdef CONFIG_XENO_COBALT static const char *reason_str[] = { [SIGDEBUG_UNDEFINED] = "received SIGDEBUG for unknown reason", [SIGDEBUG_MIGRATE_SIGNAL] = "received signal", [SIGDEBUG_MIGRATE_SYSCALL] = "invoked syscall", [SIGDEBUG_MIGRATE_FAULT] = "triggered fault", [SIGDEBUG_MIGRATE_PRIOINV] = "affected by priority inversion", [SIGDEBUG_NOMLOCK] = "process memory not locked", [SIGDEBUG_WATCHDOG] = "watchdog triggered (period too short?)", [SIGDEBUG_LOCK_BREAK] = "scheduler lock break", }; static void sigdebug(int sig, siginfo_t *si, void *context) { const char fmt[] = "%s, aborting.\n" "(enabling CONFIG_XENO_OPT_DEBUG_TRACE_RELAX may help)\n"; unsigned int reason = sigdebug_reason(si); int n __attribute__ ((unused)); static char buffer[256]; if (!stop_upon_switch) { ++sampling_relaxed; return; } if (reason > SIGDEBUG_WATCHDOG) reason = SIGDEBUG_UNDEFINED; switch(reason) { case SIGDEBUG_UNDEFINED: case SIGDEBUG_NOMLOCK: case SIGDEBUG_WATCHDOG: n = snprintf(buffer, sizeof(buffer), "altency: %s\n", reason_str[reason]); n = write(STDERR_FILENO, buffer, n); exit(EXIT_FAILURE); } n = snprintf(buffer, sizeof(buffer), fmt, reason_str[reason]); n = write(STDERR_FILENO, buffer, n); signal(sig, SIG_DFL); __STD(kill(getpid(), sig)); } #endif /* CONFIG_XENO_COBALT */ void application_usage(void) { fprintf(stderr, "usage: %s [options]:\n", get_program_name()); fprintf(stderr, "-h print histograms of min, avg, max latencies\n" "-g dump histogram to in gnuplot format\n" "-s print statistics of min, avg, max latencies\n" "-H default = 200, increase if your last bucket is full\n" "-B default = 1000ns, decrease for more resolution\n" "-p sampling period\n" "-l default=21, 0 to supress headers\n" "-T default=0, so ^C to end\n" "-q supresses RTD, RTH lines if -T is used\n" "-D number of testing device, default=0\n" "-t 0=user task (default), 1=kernel task, 2=timer IRQ\n" "-f freeze trace for each new max latency\n" "-c pin measuring task down to given CPU\n" "-P task priority (test mode 0 and 1 only)\n" "-b break upon mode switch\n" ); } int main(int argc, char *const *argv) { struct sigaction sa __attribute__((unused)); int c, ret, sig, cpu = 0; char task_name[32]; cpu_set_t cpus; sigset_t mask; while ((c = getopt(argc, argv, "g:hp:l:T:qH:B:sD:t:fc:P:b")) != EOF) switch (c) { case 'g': do_gnuplot = strdup(optarg); break; case 'h': do_histogram = 1; break; case 's': do_stats = 1; break; case 'H': histogram_size = atoi(optarg); break; case 'B': bucketsize = atoi(optarg); break; case 'p': period_ns = atoi(optarg) * 1000LL; if (period_ns > ONE_BILLION) { fprintf(stderr, "altency: invalid period (> 1s).\n"); exit(2); } break; case 'l': data_lines = atoi(optarg); break; case 'T': test_duration = atoi(optarg); alarm(test_duration + WARMUP_TIME); break; case 'q': quiet = 1; break; case 't': test_mode = atoi(optarg); break; case 'f': freeze_max = 1; break; case 'c': cpu = atoi(optarg); if (cpu < 0 || cpu >= CPU_SETSIZE) { fprintf(stderr, "altency: invalid CPU #%d\n", cpu); return 1; } break; case 'P': priority = atoi(optarg); break; case 'b': stop_upon_switch = 1; break; default: xenomai_usage(); exit(2); } if (!test_duration && quiet) { fprintf(stderr, "altency: -q only works if -T has been given.\n"); quiet = 0; } if ((test_mode < USER_TASK) || (test_mode > TIMER_HANDLER)) { fprintf(stderr, "altency: invalid test mode.\n"); exit(2); } time(&test_start); histogram_avg = calloc(histogram_size, sizeof(int32_t)); histogram_max = calloc(histogram_size, sizeof(int32_t)); histogram_min = calloc(histogram_size, sizeof(int32_t)); if (!(histogram_avg && histogram_max && histogram_min)) cleanup(); if (period_ns == 0) period_ns = CONFIG_XENO_DEFAULT_PERIOD; /* ns */ if (priority <= T_LOPRIO) priority = T_LOPRIO + 1; else if (priority > T_HIPRIO) priority = T_HIPRIO; sigemptyset(&mask); sigaddset(&mask, SIGINT); sigaddset(&mask, SIGTERM); sigaddset(&mask, SIGHUP); sigaddset(&mask, SIGALRM); pthread_sigmask(SIG_BLOCK, &mask, NULL); #ifdef CONFIG_XENO_COBALT sigemptyset(&sa.sa_mask); sa.sa_sigaction = sigdebug; sa.sa_flags = SA_SIGINFO; sigaction(SIGDEBUG, &sa, NULL); #endif if (freeze_max) { /* If something goes wrong, we want to freeze the current trace path to help debugging. */ signal(SIGSEGV, faulthand); signal(SIGBUS, faulthand); } setlinebuf(stdout); printf("== Sampling period: %Ld us\n" "== Test mode: %s\n" "== All results in microseconds\n", period_ns / 1000, test_mode_names[test_mode]); if (test_mode != USER_TASK) { devfd = open("/dev/rtdm/timerbench", O_RDWR); if (devfd < 0) { fprintf(stderr, "altency: failed to open timerbench device, %m\n" "(modprobe xeno_timerbench?)\n"); return 0; } } snprintf(task_name, sizeof(task_name), "alt-display-%d", getpid()); ret = rt_task_create(&display_task, task_name, 0, 0, 0); if (ret) { fprintf(stderr, "altency: failed to create display task, code %d\n", ret); return 0; } ret = rt_task_start(&display_task, &display, NULL); if (ret) { fprintf(stderr, "altency: failed to start display task, code %d\n", ret); return 0; } if (test_mode == USER_TASK) { snprintf(task_name, sizeof(task_name), "alt-sampling-%d", getpid()); ret = rt_task_create(&latency_task, task_name, 0, priority, T_WARNSW); if (ret) { fprintf(stderr, "altency: failed to create sampling task, code %d\n", ret); return 0; } CPU_ZERO(&cpus); CPU_SET(cpu, &cpus); ret = rt_task_set_affinity(&latency_task, &cpus); if (ret) { fprintf(stderr, "altency: failed to set CPU affinity, code %d\n", ret); return 0; } ret = rt_task_start(&latency_task, latency, NULL); if (ret) { fprintf(stderr, "altency: failed to start sampling task, code %d\n", ret); return 0; } } __STD(sigwait(&mask, &sig)); finished = 1; cleanup(); return 0; }