?  search:
summary | log | graphiclog1 | graphiclog2 | commit | commitdiff | tree | refs | edit | fork
blame | history | raw | HEAD
bfin: remove inline keyword
[xenomai-head.git] / src / testsuite / latency / latency.c
blobb1481291df09a037ebccf3b3a99224a5cea12e3d
1 #include <stdlib.h>
2 #include <math.h>
3 #include <stdio.h>
4 #include <string.h>
5 #include <signal.h>
6 #include <time.h>
7
8 #include <sys/mman.h>
9 #include <sys/time.h>
10 #include <unistd.h>
11
12 #ifndef __UCLIBC__
13 #include <execinfo.h>
14 #endif /* !__UCLIBC__ */
15
16 #include <native/task.h>
17 #include <native/timer.h>
18 #include <native/sem.h>
19 #include <rtdm/rttesting.h>
20
21 RT_TASK latency_task, display_task;
22
23 RT_SEM display_sem;
24
25 #define ONE_BILLION 1000000000
26 #define TEN_MILLION 10000000
27
28 unsigned max_relaxed;
29 long minjitter, maxjitter, avgjitter;
30 long gminjitter = TEN_MILLION, gmaxjitter = -TEN_MILLION, goverrun = 0;
31 long long gavgjitter = 0;
32
33 long long period_ns = 0;
34 int test_duration = 0; /* sec of testing, via -T <sec>, 0 is inf */
35 int data_lines = 21; /* data lines per header line, -l <lines> to change */
36 int quiet = 0; /* suppress printing of RTH, RTD lines when -T given */
37 int benchdev_no = 0;
38 int benchdev = -1;
39 int freeze_max = 0;
40 int priority = T_HIPRIO;
41 int stop_upon_switch = 0;
42 sig_atomic_t sampling_relaxed = 0;
43
44 #define USER_TASK 0
45 #define KERNEL_TASK 1
46 #define TIMER_HANDLER 2
47
48 int test_mode = USER_TASK;
49 const char *test_mode_names[] = {
50 "periodic user-mode task",
51 "in-kernel periodic task",
52 "in-kernel timer handler"
53 };
54
55 time_t test_start, test_end; /* report test duration */
56 int test_loops = 0; /* outer loop count */
57
58 #define MEASURE_PERIOD ONE_BILLION
59 #define SAMPLE_COUNT (MEASURE_PERIOD / period_ns)
60
61 /* Warmup time : in order to avoid spurious cache effects on low-end machines. */
62 #define WARMUP_TIME 1
63 #define HISTOGRAM_CELLS 300
64 int histogram_size = HISTOGRAM_CELLS;
65 long *histogram_avg = NULL, *histogram_max = NULL, *histogram_min = NULL;
66
67 char *do_gnuplot = NULL;
68 int do_histogram = 0, do_stats = 0, finished = 0;
69 int bucketsize = 1000; /* default = 1000ns, -B <size> to override */
70
71 #define need_histo() (do_histogram || do_stats || do_gnuplot)
72
73 static inline void add_histogram(long *histogram, long addval)
74 {
75 /* bucketsize steps */
76 long inabs =
77 rt_timer_tsc2ns(addval >= 0 ? addval : -addval) / bucketsize;
78 histogram[inabs < histogram_size ? inabs : histogram_size - 1]++;
79 }
80
81 void latency(void *cookie)
82 {
83 int err, count, nsamples, warmup = 1;
84 RTIME expected_tsc, period_tsc, start_ticks, fault_threshold;
85 RT_TIMER_INFO timer_info;
86 unsigned old_relaxed = 0;
87
88 err = rt_timer_inquire(&timer_info);
89
90 if (err) {
91 fprintf(stderr, "latency: rt_timer_inquire, code %d\n", err);
92 return;
93 }
94
95 fault_threshold = rt_timer_ns2tsc(CONFIG_XENO_DEFAULT_PERIOD);
96 nsamples = ONE_BILLION / period_ns;
97 period_tsc = rt_timer_ns2tsc(period_ns);
98 /* start time: one millisecond from now. */
99 start_ticks = timer_info.date + rt_timer_ns2ticks(1000000);
100 expected_tsc = timer_info.tsc + rt_timer_ns2tsc(1000000);
101
102 err =
103 rt_task_set_periodic(NULL, start_ticks,
104 rt_timer_ns2ticks(period_ns));
105
106 if (err) {
107 fprintf(stderr, "latency: failed to set periodic, code %d\n",
108 err);
109 return;
110 }
111
112 for (;;) {
113 long minj = TEN_MILLION, maxj = -TEN_MILLION, dt;
114 long overrun = 0;
115 long long sumj;
116 test_loops++;
117
118 for (count = sumj = 0; count < nsamples; count++) {
119 unsigned new_relaxed;
120 unsigned long ov;
121
122 expected_tsc += period_tsc;
123 err = rt_task_wait_period(&ov);
124
125 dt = (long)(rt_timer_tsc() - expected_tsc);
126 new_relaxed = sampling_relaxed;
127 if (dt > maxj) {
128 if (new_relaxed != old_relaxed
129 && dt > fault_threshold)
130 max_relaxed +=
131 new_relaxed - old_relaxed;
132 maxj = dt;
133 }
134 old_relaxed = new_relaxed;
135 if (dt < minj)
136 minj = dt;
137 sumj += dt;
138
139 if (err) {
140 if (err != -ETIMEDOUT) {
141 fprintf(stderr,
142 "latency: wait period failed, code %d\n",
143 err);
144 exit(EXIT_FAILURE); /* Timer stopped. */
145 }
146
147 overrun += ov;
148 expected_tsc += period_tsc * ov;
149 }
150
151 if (freeze_max && (dt > gmaxjitter)
152 && !(finished || warmup)) {
153 xntrace_user_freeze(rt_timer_tsc2ns(dt), 0);
154 gmaxjitter = dt;
155 }
156
157 if (!(finished || warmup) && need_histo())
158 add_histogram(histogram_avg, dt);
159 }
160
161 if (!warmup) {
162 if (!finished && need_histo()) {
163 add_histogram(histogram_max, maxj);
164 add_histogram(histogram_min, minj);
165 }
166
167 minjitter = minj;
168 if (minj < gminjitter)
169 gminjitter = minj;
170
171 maxjitter = maxj;
172 if (maxj > gmaxjitter)
173 gmaxjitter = maxj;
174
175 avgjitter = sumj / nsamples;
176 gavgjitter += avgjitter;
177 goverrun += overrun;
178 rt_sem_v(&display_sem);
179 }
180
181 if (warmup && test_loops == WARMUP_TIME) {
182 test_loops = 0;
183 warmup = 0;
184 }
185 }
186 }
187
188 void display(void *cookie)
189 {
190 int err, n = 0;
191 time_t start;
192 char sem_name[16];
193
194 if (test_mode == USER_TASK) {
195 snprintf(sem_name, sizeof(sem_name), "dispsem-%d", getpid());
196 err = rt_sem_create(&display_sem, sem_name, 0, S_FIFO);
197
198 if (err) {
199 fprintf(stderr,
200 "latency: cannot create semaphore: %s\n",
201 strerror(-err));
202 return;
203 }
204
205 } else {
206 struct rttst_tmbench_config config;
207
208 if (test_mode == KERNEL_TASK)
209 config.mode = RTTST_TMBENCH_TASK;
210 else
211 config.mode = RTTST_TMBENCH_HANDLER;
212
213 config.period = period_ns;
214 config.priority = priority;
215 config.warmup_loops = WARMUP_TIME;
216 config.histogram_size = need_histo() ? histogram_size : 0;
217 config.histogram_bucketsize = bucketsize;
218 config.freeze_max = freeze_max;
219
220 err =
221 rt_dev_ioctl(benchdev, RTTST_RTIOC_TMBENCH_START, &config);
222
223 if (err) {
224 fprintf(stderr,
225 "latency: failed to start in-kernel timer benchmark, code %d\n",
226 err);
227 return;
228 }
229 }
230
231 time(&start);
232
233 if (WARMUP_TIME)
234 printf("warming up...\n");
235
236 if (quiet)
237 fprintf(stderr, "running quietly for %d seconds\n",
238 test_duration);
239
240 for (;;) {
241 long minj, gminj, maxj, gmaxj, avgj;
242
243 if (test_mode == USER_TASK) {
244 err = rt_sem_p(&display_sem, TM_INFINITE);
245
246 if (err) {
247 if (err != -EIDRM)
248 fprintf(stderr,
249 "latency: failed to pend on semaphore, code %d\n",
250 err);
251
252 return;
253 }
254
255 /* convert jitters to nanoseconds. */
256 minj = rt_timer_tsc2ns(minjitter);
257 gminj = rt_timer_tsc2ns(gminjitter);
258 avgj = rt_timer_tsc2ns(avgjitter);
259 maxj = rt_timer_tsc2ns(maxjitter);
260 gmaxj = rt_timer_tsc2ns(gmaxjitter);
261
262 } else {
263 struct rttst_interm_bench_res result;
264
265 err =
266 rt_dev_ioctl(benchdev, RTTST_RTIOC_INTERM_BENCH_RES,
267 &result);
268
269 if (err) {
270 if (err != -EIDRM)
271 fprintf(stderr,
272 "latency: failed to call RTTST_RTIOC_INTERM_BENCH_RES, code %d\n",
273 err);
274
275 return;
276 }
277
278 minj = result.last.min;
279 gminj = result.overall.min;
280 avgj = result.last.avg;
281 maxj = result.last.max;
282 gmaxj = result.overall.max;
283 goverrun = result.overall.overruns;
284 }
285
286 if (!quiet) {
287 if (data_lines && (n++ % data_lines) == 0) {
288 time_t now, dt;
289 time(&now);
290 dt = now - start - WARMUP_TIME;
291 printf
292 ("RTT| %.2ld:%.2ld:%.2ld (%s, %Ld us period, "
293 "priority %d)\n", dt / 3600,
294 (dt / 60) % 60, dt % 60,
295 test_mode_names[test_mode],
296 period_ns / 1000, priority);
297 printf("RTH|%11s|%11s|%11s|%8s|%6s|%11s|%11s\n",
298 "----lat min", "----lat avg",
299 "----lat max", "-overrun", "---msw",
300 "---lat best", "--lat worst");
301 }
302 printf("RTD|%11.3f|%11.3f|%11.3f|%8ld|%6u|%11.3f|%11.3f\n",
303 (double)minj / 1000,
304 (double)avgj / 1000,
305 (double)maxj / 1000,
306 goverrun,
307 max_relaxed,
308 (double)gminj / 1000, (double)gmaxj / 1000);
309 }
310 }
311 }
312
313 double dump_histogram(long *histogram, char *kind)
314 {
315 int n, total_hits = 0;
316 double avg = 0; /* used to sum hits 1st */
317
318 if (do_histogram)
319 printf("---|--param|----range-|--samples\n");
320
321 for (n = 0; n < histogram_size; n++) {
322 long hits = histogram[n];
323
324 if (hits) {
325 total_hits += hits;
326 avg += n * hits;
327 if (do_histogram)
328 printf("HSD| %s| %3d -%3d | %8ld\n",
329 kind, n, n + 1, hits);
330 }
331 }
332
333 avg /= total_hits; /* compute avg, reuse variable */
334
335 return avg;
336 }
337
338 void dump_histo_gnuplot(long *histogram)
339 {
340 unsigned start, stop;
341 FILE *f;
342 int n;
343
344 f = fopen(do_gnuplot, "w");
345 if (!f)
346 return;
347
348 for (n = 0; n < histogram_size && histogram[n] == 0L; n++)
349 ;
350 start = n;
351
352 for (n = histogram_size - 1; n >= 0 && histogram[n] == 0L; n--)
353 ;
354 stop = n;
355
356 fprintf(f, "%g 1\n", start * bucketsize / 1000.0);
357 for (n = start; n <= stop; n++)
358 fprintf(f, "%g %ld\n",
359 (n + 0.5) * bucketsize / 1000.0, histogram[n] + 1);
360 fprintf(f, "%g 1\n", (stop + 1) * bucketsize / 1000.0);
361
362 fclose(f);
363 }
364
365 void dump_stats(long *histogram, char *kind, double avg)
366 {
367 int n, total_hits = 0;
368 double variance = 0;
369
370 for (n = 0; n < histogram_size; n++) {
371 long hits = histogram[n];
372
373 if (hits) {
374 total_hits += hits;
375 variance += hits * (n - avg) * (n - avg);
376 }
377 }
378
379 /* compute std-deviation (unbiased form) */
380 if (total_hits > 1) {
381 variance /= total_hits - 1;
382 variance = sqrt(variance);
383 } else
384 variance = 0;
385
386 printf("HSS| %s| %9d| %10.3f| %10.3f\n",
387 kind, total_hits, avg, variance);
388 }
389
390 void dump_hist_stats(void)
391 {
392 double minavg, maxavg, avgavg;
393
394 /* max is last, where its visible w/o scrolling */
395 minavg = dump_histogram(histogram_min, "min");
396 avgavg = dump_histogram(histogram_avg, "avg");
397 maxavg = dump_histogram(histogram_max, "max");
398
399 printf("HSH|--param|--samples-|--average--|---stddev--\n");
400
401 dump_stats(histogram_min, "min", minavg);
402 dump_stats(histogram_avg, "avg", avgavg);
403 dump_stats(histogram_max, "max", maxavg);
404
405 if (do_gnuplot)
406 dump_histo_gnuplot(histogram_avg);
407 }
408
409 void cleanup(void)
410 {
411 time_t actual_duration;
412 long gmaxj, gminj, gavgj;
413
414 if (test_mode == USER_TASK) {
415 rt_sem_delete(&display_sem);
416
417 gavgjitter /= (test_loops > 1 ? test_loops : 2) - 1;
418
419 gminj = rt_timer_tsc2ns(gminjitter);
420 gmaxj = rt_timer_tsc2ns(gmaxjitter);
421 gavgj = rt_timer_tsc2ns(gavgjitter);
422 } else {
423 struct rttst_overall_bench_res overall;
424
425 overall.histogram_min = histogram_min;
426 overall.histogram_max = histogram_max;
427 overall.histogram_avg = histogram_avg;
428
429 rt_dev_ioctl(benchdev, RTTST_RTIOC_TMBENCH_STOP, &overall);
430
431 gminj = overall.result.min;
432 gmaxj = overall.result.max;
433 gavgj = overall.result.avg;
434 goverrun = overall.result.overruns;
435 }
436
437 if (benchdev >= 0)
438 rt_dev_close(benchdev);
439
440 if (need_histo())
441 dump_hist_stats();
442
443 time(&test_end);
444 actual_duration = test_end - test_start - WARMUP_TIME;
445 if (!test_duration)
446 test_duration = actual_duration;
447
448 printf
449 ("---|-----------|-----------|-----------|--------|------|-------------------------\n"
450 "RTS|%11.3f|%11.3f|%11.3f|%8ld|%6u| %.2ld:%.2ld:%.2ld/%.2d:%.2d:%.2d\n",
451 (double)gminj / 1000, (double)gavgj / 1000, (double)gmaxj / 1000,
452 goverrun, max_relaxed, actual_duration / 3600, (actual_duration / 60) % 60,
453 actual_duration % 60, test_duration / 3600,
454 (test_duration / 60) % 60, test_duration % 60);
455 if (max_relaxed > 0)
456 printf(
457 "Warning! some latency maxima may have been due to involuntary mode switches.\n"
458 "Please contact xenomai@xenomai.org\n");
459
460 if (histogram_avg)
461 free(histogram_avg);
462 if (histogram_max)
463 free(histogram_max);
464 if (histogram_min)
465 free(histogram_min);
466
467 exit(0);
468 }
469
470 void faulthand(int sig)
471 {
472 xntrace_user_freeze(0, 1);
473 signal(sig, SIG_DFL);
474 kill(getpid(), sig);
475 }
476
477 static const char *reason_str[] = {
478 [SIGDEBUG_UNDEFINED] = "latency: received SIGXCPU for unknown reason",
479 [SIGDEBUG_MIGRATE_SIGNAL] = "received signal",
480 [SIGDEBUG_MIGRATE_SYSCALL] = "invoked syscall",
481 [SIGDEBUG_MIGRATE_FAULT] = "triggered fault",
482 [SIGDEBUG_MIGRATE_PRIOINV] = "affected by priority inversion",
483 [SIGDEBUG_NOMLOCK] = "Xenomai: process memory not locked "
484 "(missing mlockall?)",
485 [SIGDEBUG_WATCHDOG] = "Xenomai: watchdog triggered "
486 "(period too short?)",
487 };
488
489 static char buffer[256];
490
491 void sigdebug(int sig, siginfo_t *si, void *context)
492 {
493 #ifndef __UCLIBC__
494 const char fmt[] = "Mode switch (reason: %s), aborting. Backtrace:\n";
495 static void *bt[200];
496 #else /* __UCLIBC__ */
497 const char fmt[] = "Mode switch (reason: %s), aborting."
498 " Backtrace unavailable with uclibc.\n";
499 #endif /* __UCLIBC__ */
500 unsigned int reason = si->si_value.sival_int;
501 unsigned n;
502
503 if (reason > SIGDEBUG_WATCHDOG)
504 reason = SIGDEBUG_UNDEFINED;
505
506 switch(reason) {
507 case SIGDEBUG_UNDEFINED:
508 case SIGDEBUG_NOMLOCK:
509 case SIGDEBUG_WATCHDOG:
510 n = snprintf(buffer, sizeof(buffer),
511 "%s\n", reason_str[reason]);
512 write(STDERR_FILENO, buffer, n);
513 exit(EXIT_FAILURE);
514 }
515
516 if (!stop_upon_switch) {
517 ++sampling_relaxed;
518 return;
519 }
520
521 n = snprintf(buffer, sizeof(buffer), fmt, reason_str[reason]);
522 n = write(STDERR_FILENO, buffer, n);
523 #ifndef __UCLIBC__
524 n = backtrace(bt, sizeof(bt)/sizeof(bt[0]));
525 backtrace_symbols_fd(bt, n, STDERR_FILENO);
526 #endif /* !__UCLIBC__ */
527
528 signal(sig, SIG_DFL);
529 kill(getpid(), sig);
530 }
531
532 int main(int argc, char **argv)
533 {
534 int cpu = 0, c, err, sig;
535 struct sigaction sa;
536 char task_name[16];
537 sigset_t mask;
538
539 while ((c = getopt(argc, argv, "g:hp:l:T:qH:B:sD:t:fc:P:b")) != EOF)
540 switch (c) {
541 case 'g':
542 do_gnuplot = strdup(optarg);
543 break;
544
545 case 'h':
546
547 do_histogram = 1;
548 break;
549
550 case 's':
551
552 do_stats = 1;
553 break;
554
555 case 'H':
556
557 histogram_size = atoi(optarg);
558 break;
559
560 case 'B':
561
562 bucketsize = atoi(optarg);
563 break;
564
565 case 'p':
566
567 period_ns = atoi(optarg) * 1000LL;
568 break;
569
570 case 'l':
571
572 data_lines = atoi(optarg);
573 break;
574
575 case 'T':
576
577 test_duration = atoi(optarg);
578 alarm(test_duration + WARMUP_TIME);
579 break;
580
581 case 'q':
582
583 quiet = 1;
584 break;
585
586 case 'D':
587
588 benchdev_no = atoi(optarg);
589 break;
590
591 case 't':
592
593 test_mode = atoi(optarg);
594 break;
595
596 case 'f':
597
598 freeze_max = 1;
599 break;
600
601 case 'c':
602 cpu = T_CPU(atoi(optarg));
603 break;
604
605 case 'P':
606 priority = atoi(optarg);
607 break;
608
609 case 'b':
610 stop_upon_switch = 1;
611 break;
612
613 default:
614
615 fprintf(stderr,
616 "usage: latency [options]\n"
617 " [-h] # print histograms of min, avg, max latencies\n"
618 " [-g <file>] # dump histogram to <file> in gnuplot format\n"
619 " [-s] # print statistics of min, avg, max latencies\n"
620 " [-H <histogram-size>] # default = 200, increase if your last bucket is full\n"
621 " [-B <bucket-size>] # default = 1000ns, decrease for more resolution\n"
622 " [-p <period_us>] # sampling period\n"
623 " [-l <data-lines per header>] # default=21, 0 to suppress headers\n"
624 " [-T <test_duration_seconds>] # default=0, so ^C to end\n"
625 " [-q] # suppresses RTD, RTH lines if -T is used\n"
626 " [-D <testing_device_no>] # number of testing device, default=0\n"
627 " [-t <test_mode>] # 0=user task (default), 1=kernel task, 2=timer IRQ\n"
628 " [-f] # freeze trace for each new max latency\n"
629 " [-c <cpu>] # pin measuring task down to given CPU\n"
630 " [-P <priority>] # task priority (test mode 0 and 1 only)\n"
631 " [-b] # break upon mode switch\n"
632 );
633 exit(2);
634 }
635
636 if (!test_duration && quiet) {
637 fprintf(stderr,
638 "latency: -q only works if -T has been given.\n");
639 quiet = 0;
640 }
641
642 if ((test_mode < USER_TASK) || (test_mode > TIMER_HANDLER)) {
643 fprintf(stderr, "latency: invalid test mode.\n");
644 exit(2);
645 }
646
647 time(&test_start);
648
649 histogram_avg = calloc(histogram_size, sizeof(long));
650 histogram_max = calloc(histogram_size, sizeof(long));
651 histogram_min = calloc(histogram_size, sizeof(long));
652
653 if (!(histogram_avg && histogram_max && histogram_min))
654 cleanup();
655
656 if (period_ns == 0)
657 period_ns = CONFIG_XENO_DEFAULT_PERIOD; /* ns */
658
659 if (priority <= T_LOPRIO)
660 priority = T_LOPRIO + 1;
661 else if (priority > T_HIPRIO)
662 priority = T_HIPRIO;
663
664 sigemptyset(&mask);
665 sigaddset(&mask, SIGINT);
666 sigaddset(&mask, SIGTERM);
667 sigaddset(&mask, SIGHUP);
668 sigaddset(&mask, SIGALRM);
669 pthread_sigmask(SIG_BLOCK, &mask, NULL);
670
671 sigemptyset(&sa.sa_mask);
672 sa.sa_sigaction = sigdebug;
673 sa.sa_flags = SA_SIGINFO;
674 sigaction(SIGDEBUG, &sa, NULL);
675
676 if (freeze_max) {
677 /* If something goes wrong, we want to freeze the current
678 trace path to help debugging. */
679 signal(SIGSEGV, faulthand);
680 signal(SIGBUS, faulthand);
681 }
682
683 setlinebuf(stdout);
684
685 printf("== Sampling period: %Ld us\n"
686 "== Test mode: %s\n"
687 "== All results in microseconds\n",
688 period_ns / 1000, test_mode_names[test_mode]);
689
690 mlockall(MCL_CURRENT | MCL_FUTURE);
691
692 if (test_mode != USER_TASK) {
693 char devname[RTDM_MAX_DEVNAME_LEN];
694
695 snprintf(devname, RTDM_MAX_DEVNAME_LEN, "rttest-timerbench%d",
696 benchdev_no);
697 benchdev = rt_dev_open(devname, O_RDWR);
698
699 if (benchdev < 0) {
700 fprintf(stderr,
701 "latency: failed to open benchmark device, code %d\n"
702 "(modprobe xeno_timerbench?)\n", benchdev);
703 return 0;
704 }
705 }
706
707 rt_timer_set_mode(TM_ONESHOT); /* Force aperiodic timing. */
708
709 snprintf(task_name, sizeof(task_name), "display-%d", getpid());
710 err = rt_task_create(&display_task, task_name, 0, 0, T_FPU);
711
712 if (err) {
713 fprintf(stderr,
714 "latency: failed to create display task, code %d\n",
715 err);
716 return 0;
717 }
718
719 err = rt_task_start(&display_task, &display, NULL);
720
721 if (err) {
722 fprintf(stderr,
723 "latency: failed to start display task, code %d\n",
724 err);
725 return 0;
726 }
727
728 if (test_mode == USER_TASK) {
729 snprintf(task_name, sizeof(task_name), "sampling-%d", getpid());
730 err =
731 rt_task_create(&latency_task, task_name, 0, priority,
732 T_FPU | cpu | T_WARNSW);
733
734 if (err) {
735 fprintf(stderr,
736 "latency: failed to create latency task, code %d\n",
737 err);
738 return 0;
739 }
740
741 err = rt_task_start(&latency_task, &latency, NULL);
742
743 if (err) {
744 fprintf(stderr,
745 "latency: failed to start latency task, code %d\n",
746 err);
747 return 0;
748 }
749 }
750
751 sigwait(&mask, &sig);
752 finished = 1;
753
754 cleanup();
755
756 return 0;
757 }
Real-time framework for Linux (backup clone)