1 // SPDX-License-Identifier: GPL-2.0 2 /* 3 * Copyright (C) 2017, 2018, 2019, 2021 BMW Car IT GmbH 4 * Author: Viktor Rosendahl (viktor.rosendahl@bmw.de) 5 */ 6 7 #define _GNU_SOURCE 8 #define _POSIX_C_SOURCE 200809L 9 10 #include <ctype.h> 11 #include <stdbool.h> 12 #include <stdio.h> 13 #include <stdlib.h> 14 #include <string.h> 15 16 #include <err.h> 17 #include <errno.h> 18 #include <fcntl.h> 19 #include <getopt.h> 20 #include <sched.h> 21 #include <linux/unistd.h> 22 #include <signal.h> 23 #include <sys/inotify.h> 24 #include <unistd.h> 25 #include <pthread.h> 26 #include <tracefs.h> 27 28 static const char *prg_name; 29 static const char *prg_unknown = "unknown program name"; 30 31 static int fd_stdout; 32 33 static int sched_policy; 34 static bool sched_policy_set; 35 36 static int sched_pri; 37 static bool sched_pri_set; 38 39 static bool trace_enable = true; 40 static bool setup_ftrace = true; 41 static bool use_random_sleep; 42 43 #define TRACE_OPTS \ 44 C(FUNC_TR, "function-trace"), \ 45 C(DISP_GR, "display-graph"), \ 46 C(NR, NULL) 47 48 #undef C 49 #define C(a, b) OPTIDX_##a 50 51 enum traceopt { 52 TRACE_OPTS 53 }; 54 55 #undef C 56 #define C(a, b) b 57 58 static const char *const optstr[] = { 59 TRACE_OPTS 60 }; 61 62 enum errhandling { 63 ERR_EXIT = 0, 64 ERR_WARN, 65 ERR_CLEANUP, 66 }; 67 68 static bool use_options[OPTIDX_NR]; 69 70 static char inotify_buffer[655360]; 71 72 #define likely(x) __builtin_expect(!!(x), 1) 73 #define unlikely(x) __builtin_expect(!!(x), 0) 74 #define bool2str(x) (x ? "true":"false") 75 76 #define DEFAULT_NR_PRINTER_THREADS (3) 77 static unsigned int nr_threads = DEFAULT_NR_PRINTER_THREADS; 78 79 #define DEFAULT_TABLE_SIZE (2) 80 static unsigned int table_startsize = DEFAULT_TABLE_SIZE; 81 82 static int verbosity; 83 84 #define verbose_sizechange() (verbosity >= 1) 85 #define verbose_lostevent() (verbosity >= 2) 86 #define verbose_ftrace() (verbosity >= 1) 87 88 #define was_changed(ORIG, CUR) (strcmp(ORIG, CUR) != 0) 89 #define needs_change(CUR, WANTED) (strcmp(CUR, WANTED) != 0) 90 91 static const char *debug_tracefile; 92 static const char *debug_tracefile_dflt; 93 static const char *debug_maxlat; 94 static const char *debug_maxlat_dflt; 95 static const char * const DEBUG_NOFILE = "[file not found]"; 96 97 static const char * const TR_MAXLAT = "tracing_max_latency"; 98 static const char * const TR_THRESH = "tracing_thresh"; 99 static const char * const TR_CURRENT = "current_tracer"; 100 static const char * const TR_OPTIONS = "trace_options"; 101 102 static const char * const NOP_TRACER = "nop"; 103 104 static const char * const OPT_NO_PREFIX = "no"; 105 106 #define DFLT_THRESHOLD_US "0" 107 static const char *threshold = DFLT_THRESHOLD_US; 108 109 #define DEV_URANDOM "/dev/urandom" 110 #define RT_DEFAULT_PRI (99) 111 #define DEFAULT_PRI (0) 112 113 #define USEC_PER_MSEC (1000L) 114 #define NSEC_PER_USEC (1000L) 115 #define NSEC_PER_MSEC (USEC_PER_MSEC * NSEC_PER_USEC) 116 117 #define MSEC_PER_SEC (1000L) 118 #define USEC_PER_SEC (USEC_PER_MSEC * MSEC_PER_SEC) 119 #define NSEC_PER_SEC (NSEC_PER_MSEC * MSEC_PER_SEC) 120 121 #define SLEEP_TIME_MS_DEFAULT (1000L) 122 #define TRY_PRINTMUTEX_MS (1000) 123 124 static long sleep_time = (USEC_PER_MSEC * SLEEP_TIME_MS_DEFAULT); 125 126 static const char * const queue_full_warning = 127 "Could not queue trace for printing. It is likely that events happen faster\n" 128 "than what they can be printed. Probably partly because of random sleeping\n"; 129 130 static const char * const no_tracer_msg = 131 "Could not find any tracers! Running this program as root may help!\n"; 132 133 static const char * const no_latency_tr_msg = 134 "No latency tracers are supported by your kernel!\n"; 135 136 struct policy { 137 const char *name; 138 int policy; 139 int default_pri; 140 }; 141 142 static const struct policy policies[] = { 143 { "other", SCHED_OTHER, DEFAULT_PRI }, 144 { "batch", SCHED_BATCH, DEFAULT_PRI }, 145 { "idle", SCHED_IDLE, DEFAULT_PRI }, 146 { "rr", SCHED_RR, RT_DEFAULT_PRI }, 147 { "fifo", SCHED_FIFO, RT_DEFAULT_PRI }, 148 { NULL, 0, DEFAULT_PRI } 149 }; 150 151 /* 152 * The default tracer will be the first on this list that is supported by the 153 * currently running Linux kernel. 154 */ 155 static const char * const relevant_tracers[] = { 156 "preemptirqsoff", 157 "preemptoff", 158 "irqsoff", 159 "wakeup", 160 "wakeup_rt", 161 "wakeup_dl", 162 NULL 163 }; 164 165 /* This is the list of tracers for which random sleep makes sense */ 166 static const char * const random_tracers[] = { 167 "preemptirqsoff", 168 "preemptoff", 169 "irqsoff", 170 NULL 171 }; 172 173 static const char *current_tracer; 174 static bool force_tracer; 175 176 struct ftrace_state { 177 char *tracer; 178 char *thresh; 179 bool opt[OPTIDX_NR]; 180 bool opt_valid[OPTIDX_NR]; 181 pthread_mutex_t mutex; 182 }; 183 184 struct entry { 185 int ticket; 186 int ticket_completed_ref; 187 }; 188 189 struct print_state { 190 int ticket_counter; 191 int ticket_completed; 192 pthread_mutex_t mutex; 193 pthread_cond_t cond; 194 int cnt; 195 pthread_mutex_t cnt_mutex; 196 }; 197 198 struct short_msg { 199 char buf[160]; 200 int len; 201 }; 202 203 static struct print_state printstate; 204 static struct ftrace_state save_state; 205 volatile sig_atomic_t signal_flag; 206 207 #define PROB_TABLE_MAX_SIZE (1000) 208 209 int probabilities[PROB_TABLE_MAX_SIZE]; 210 211 struct sleep_table { 212 int *table; 213 int size; 214 pthread_mutex_t mutex; 215 }; 216 217 static struct sleep_table sleeptable; 218 219 #define QUEUE_SIZE (10) 220 221 struct queue { 222 struct entry entries[QUEUE_SIZE]; 223 int next_prod_idx; 224 int next_cons_idx; 225 pthread_mutex_t mutex; 226 pthread_cond_t cond; 227 }; 228 229 #define MAX_THREADS (40) 230 231 struct queue printqueue; 232 pthread_t printthread[MAX_THREADS]; 233 pthread_mutex_t print_mtx; 234 #define PRINT_BUFFER_SIZE (16 * 1024 * 1024) 235 236 static void cleanup_exit(int status); 237 static int set_trace_opt(const char *opt, bool value); 238 239 static __always_inline void *malloc_or_die(size_t size) 240 { 241 void *ptr = malloc(size); 242 243 if (unlikely(ptr == NULL)) { 244 warn("malloc() failed"); 245 cleanup_exit(EXIT_FAILURE); 246 } 247 return ptr; 248 } 249 250 static __always_inline void *malloc_or_die_nocleanup(size_t size) 251 { 252 void *ptr = malloc(size); 253 254 if (unlikely(ptr == NULL)) 255 err(0, "malloc() failed"); 256 return ptr; 257 } 258 259 static __always_inline void write_or_die(int fd, const char *buf, size_t count) 260 { 261 ssize_t r; 262 263 do { 264 r = write(fd, buf, count); 265 if (unlikely(r < 0)) { 266 if (errno == EINTR) 267 continue; 268 warn("write() failed"); 269 cleanup_exit(EXIT_FAILURE); 270 } 271 count -= r; 272 buf += r; 273 } while (count > 0); 274 } 275 276 static __always_inline void clock_gettime_or_die(clockid_t clk_id, 277 struct timespec *tp) 278 { 279 int r = clock_gettime(clk_id, tp); 280 281 if (unlikely(r != 0)) 282 err(EXIT_FAILURE, "clock_gettime() failed"); 283 } 284 285 static __always_inline void sigemptyset_or_die(sigset_t *s) 286 { 287 if (unlikely(sigemptyset(s) != 0)) { 288 warn("sigemptyset() failed"); 289 cleanup_exit(EXIT_FAILURE); 290 } 291 } 292 293 static __always_inline void sigaddset_or_die(sigset_t *s, int signum) 294 { 295 if (unlikely(sigaddset(s, signum) != 0)) { 296 warn("sigemptyset() failed"); 297 cleanup_exit(EXIT_FAILURE); 298 } 299 } 300 301 static __always_inline void sigaction_or_die(int signum, 302 const struct sigaction *act, 303 struct sigaction *oldact) 304 { 305 if (unlikely(sigaction(signum, act, oldact) != 0)) { 306 warn("sigaction() failed"); 307 cleanup_exit(EXIT_FAILURE); 308 } 309 } 310 311 static void open_stdout(void) 312 { 313 if (setvbuf(stdout, NULL, _IONBF, 0) != 0) 314 err(EXIT_FAILURE, "setvbuf() failed"); 315 fd_stdout = fileno(stdout); 316 if (fd_stdout < 0) 317 err(EXIT_FAILURE, "fileno() failed"); 318 } 319 320 /* 321 * It's not worth it to call cleanup_exit() from mutex functions because 322 * cleanup_exit() uses mutexes. 323 */ 324 static __always_inline void mutex_lock(pthread_mutex_t *mtx) 325 { 326 errno = pthread_mutex_lock(mtx); 327 if (unlikely(errno)) 328 err(EXIT_FAILURE, "pthread_mutex_lock() failed"); 329 } 330 331 332 static __always_inline void mutex_unlock(pthread_mutex_t *mtx) 333 { 334 errno = pthread_mutex_unlock(mtx); 335 if (unlikely(errno)) 336 err(EXIT_FAILURE, "pthread_mutex_unlock() failed"); 337 } 338 339 static __always_inline void cond_signal(pthread_cond_t *cond) 340 { 341 errno = pthread_cond_signal(cond); 342 if (unlikely(errno)) 343 err(EXIT_FAILURE, "pthread_cond_signal() failed"); 344 } 345 346 static __always_inline void cond_wait(pthread_cond_t *restrict cond, 347 pthread_mutex_t *restrict mutex) 348 { 349 errno = pthread_cond_wait(cond, mutex); 350 if (unlikely(errno)) 351 err(EXIT_FAILURE, "pthread_cond_wait() failed"); 352 } 353 354 static __always_inline void cond_broadcast(pthread_cond_t *cond) 355 { 356 errno = pthread_cond_broadcast(cond); 357 if (unlikely(errno)) 358 err(EXIT_FAILURE, "pthread_cond_broadcast() failed"); 359 } 360 361 static __always_inline void 362 mutex_init(pthread_mutex_t *mutex, 363 const pthread_mutexattr_t *attr) 364 { 365 errno = pthread_mutex_init(mutex, attr); 366 if (errno) 367 err(EXIT_FAILURE, "pthread_mutex_init() failed"); 368 } 369 370 static __always_inline void mutexattr_init(pthread_mutexattr_t *attr) 371 { 372 errno = pthread_mutexattr_init(attr); 373 if (errno) 374 err(EXIT_FAILURE, "pthread_mutexattr_init() failed"); 375 } 376 377 static __always_inline void mutexattr_destroy(pthread_mutexattr_t *attr) 378 { 379 errno = pthread_mutexattr_destroy(attr); 380 if (errno) 381 err(EXIT_FAILURE, "pthread_mutexattr_destroy() failed"); 382 } 383 384 static __always_inline void mutexattr_settype(pthread_mutexattr_t *attr, 385 int type) 386 { 387 errno = pthread_mutexattr_settype(attr, type); 388 if (errno) 389 err(EXIT_FAILURE, "pthread_mutexattr_settype() failed"); 390 } 391 392 static __always_inline void condattr_init(pthread_condattr_t *attr) 393 { 394 errno = pthread_condattr_init(attr); 395 if (errno) 396 err(EXIT_FAILURE, "pthread_condattr_init() failed"); 397 } 398 399 static __always_inline void condattr_destroy(pthread_condattr_t *attr) 400 { 401 errno = pthread_condattr_destroy(attr); 402 if (errno) 403 err(EXIT_FAILURE, "pthread_condattr_destroy() failed"); 404 } 405 406 static __always_inline void condattr_setclock(pthread_condattr_t *attr, 407 clockid_t clock_id) 408 { 409 errno = pthread_condattr_setclock(attr, clock_id); 410 if (unlikely(errno)) 411 err(EXIT_FAILURE, "pthread_condattr_setclock() failed"); 412 } 413 414 static __always_inline void cond_init(pthread_cond_t *cond, 415 const pthread_condattr_t *attr) 416 { 417 errno = pthread_cond_init(cond, attr); 418 if (errno) 419 err(EXIT_FAILURE, "pthread_cond_init() failed"); 420 } 421 422 static __always_inline int 423 cond_timedwait(pthread_cond_t *restrict cond, 424 pthread_mutex_t *restrict mutex, 425 const struct timespec *restrict abstime) 426 { 427 errno = pthread_cond_timedwait(cond, mutex, abstime); 428 if (errno && errno != ETIMEDOUT) 429 err(EXIT_FAILURE, "pthread_cond_timedwait() failed"); 430 return errno; 431 } 432 433 static void init_printstate(void) 434 { 435 pthread_condattr_t cattr; 436 437 printstate.ticket_counter = 0; 438 printstate.ticket_completed = 0; 439 printstate.cnt = 0; 440 441 mutex_init(&printstate.mutex, NULL); 442 443 condattr_init(&cattr); 444 condattr_setclock(&cattr, CLOCK_MONOTONIC); 445 cond_init(&printstate.cond, &cattr); 446 condattr_destroy(&cattr); 447 } 448 449 static void init_print_mtx(void) 450 { 451 pthread_mutexattr_t mattr; 452 453 mutexattr_init(&mattr); 454 mutexattr_settype(&mattr, PTHREAD_MUTEX_RECURSIVE); 455 mutex_init(&print_mtx, &mattr); 456 mutexattr_destroy(&mattr); 457 458 } 459 460 static void signal_blocking(int how) 461 { 462 sigset_t s; 463 464 sigemptyset_or_die(&s); 465 sigaddset_or_die(&s, SIGHUP); 466 sigaddset_or_die(&s, SIGTERM); 467 sigaddset_or_die(&s, SIGINT); 468 469 errno = pthread_sigmask(how, &s, NULL); 470 if (unlikely(errno)) { 471 warn("pthread_sigmask() failed"); 472 cleanup_exit(EXIT_FAILURE); 473 } 474 } 475 476 static void signal_handler(int num) 477 { 478 signal_flag = num; 479 } 480 481 static void setup_sig_handler(void) 482 { 483 struct sigaction sa; 484 485 memset(&sa, 0, sizeof(sa)); 486 sa.sa_handler = signal_handler; 487 488 sigaction_or_die(SIGHUP, &sa, NULL); 489 sigaction_or_die(SIGTERM, &sa, NULL); 490 sigaction_or_die(SIGINT, &sa, NULL); 491 } 492 493 static void process_signal(int signal) 494 { 495 char *name; 496 497 name = strsignal(signal); 498 if (name == NULL) 499 printf("Received signal %d\n", signal); 500 else 501 printf("Received signal %d (%s)\n", signal, name); 502 cleanup_exit(EXIT_SUCCESS); 503 } 504 505 static __always_inline void check_signals(void) 506 { 507 int signal = signal_flag; 508 509 if (unlikely(signal)) 510 process_signal(signal); 511 } 512 513 static __always_inline void get_time_in_future(struct timespec *future, 514 long time_us) 515 { 516 long nsec; 517 518 clock_gettime_or_die(CLOCK_MONOTONIC, future); 519 future->tv_sec += time_us / USEC_PER_SEC; 520 nsec = future->tv_nsec + (time_us * NSEC_PER_USEC) % NSEC_PER_SEC; 521 if (nsec >= NSEC_PER_SEC) { 522 future->tv_nsec = nsec % NSEC_PER_SEC; 523 future->tv_sec += 1; 524 } 525 } 526 527 static __always_inline bool time_has_passed(const struct timespec *time) 528 { 529 struct timespec now; 530 531 clock_gettime_or_die(CLOCK_MONOTONIC, &now); 532 if (now.tv_sec > time->tv_sec) 533 return true; 534 if (now.tv_sec < time->tv_sec) 535 return false; 536 return (now.tv_nsec >= time->tv_nsec); 537 } 538 539 static bool mutex_trylock_limit(pthread_mutex_t *mutex, int time_ms) 540 { 541 long time_us = time_ms * USEC_PER_MSEC; 542 struct timespec limit; 543 544 get_time_in_future(&limit, time_us); 545 do { 546 errno = pthread_mutex_trylock(mutex); 547 if (errno && errno != EBUSY) 548 err(EXIT_FAILURE, "pthread_mutex_trylock() failed"); 549 } while (errno && !time_has_passed(&limit)); 550 return errno == 0; 551 } 552 553 static void restore_trace_opts(const struct ftrace_state *state, 554 const bool *cur) 555 { 556 int i; 557 int r; 558 559 for (i = 0; i < OPTIDX_NR; i++) 560 if (state->opt_valid[i] && state->opt[i] != cur[i]) { 561 r = set_trace_opt(optstr[i], state->opt[i]); 562 if (r < 0) 563 warnx("Failed to restore the %s option to %s", 564 optstr[i], bool2str(state->opt[i])); 565 else if (verbose_ftrace()) 566 printf("Restored the %s option in %s to %s\n", 567 optstr[i], TR_OPTIONS, 568 bool2str(state->opt[i])); 569 } 570 } 571 572 static char *read_file(const char *file, enum errhandling h) 573 { 574 int psize; 575 char *r; 576 static const char *emsg = "Failed to read the %s file"; 577 578 r = tracefs_instance_file_read(NULL, file, &psize); 579 if (!r) { 580 if (h) { 581 warn(emsg, file); 582 if (h == ERR_CLEANUP) 583 cleanup_exit(EXIT_FAILURE); 584 } else 585 errx(EXIT_FAILURE, emsg, file); 586 } 587 588 if (r && r[psize - 1] == '\n') 589 r[psize - 1] = '\0'; 590 return r; 591 } 592 593 static void restore_file(const char *file, char **saved, const char *cur) 594 { 595 if (*saved && was_changed(*saved, cur)) { 596 if (tracefs_instance_file_write(NULL, file, *saved) < 0) 597 warnx("Failed to restore %s to %s!", file, *saved); 598 else if (verbose_ftrace()) 599 printf("Restored %s to %s\n", file, *saved); 600 free(*saved); 601 *saved = NULL; 602 } 603 } 604 605 static void restore_ftrace(void) 606 { 607 mutex_lock(&save_state.mutex); 608 609 restore_file(TR_CURRENT, &save_state.tracer, current_tracer); 610 restore_file(TR_THRESH, &save_state.thresh, threshold); 611 restore_trace_opts(&save_state, use_options); 612 613 mutex_unlock(&save_state.mutex); 614 } 615 616 static void cleanup_exit(int status) 617 { 618 char *maxlat; 619 620 if (!setup_ftrace) 621 exit(status); 622 623 /* 624 * We try the print_mtx for 1 sec in order to avoid garbled 625 * output if possible, but if it cannot be obtained we proceed anyway. 626 */ 627 mutex_trylock_limit(&print_mtx, TRY_PRINTMUTEX_MS); 628 629 maxlat = read_file(TR_MAXLAT, ERR_WARN); 630 if (maxlat) { 631 printf("The maximum detected latency was: %sus\n", maxlat); 632 free(maxlat); 633 } 634 635 restore_ftrace(); 636 /* 637 * We do not need to unlock the print_mtx here because we will exit at 638 * the end of this function. Unlocking print_mtx causes problems if a 639 * print thread happens to be waiting for the mutex because we have 640 * just changed the ftrace settings to the original and thus the 641 * print thread would output incorrect data from ftrace. 642 */ 643 exit(status); 644 } 645 646 static void init_save_state(void) 647 { 648 pthread_mutexattr_t mattr; 649 650 mutexattr_init(&mattr); 651 mutexattr_settype(&mattr, PTHREAD_MUTEX_RECURSIVE); 652 mutex_init(&save_state.mutex, &mattr); 653 mutexattr_destroy(&mattr); 654 655 save_state.tracer = NULL; 656 save_state.thresh = NULL; 657 save_state.opt_valid[OPTIDX_FUNC_TR] = false; 658 save_state.opt_valid[OPTIDX_DISP_GR] = false; 659 } 660 661 static int printstate_next_ticket(struct entry *req) 662 { 663 int r; 664 665 r = ++(printstate.ticket_counter); 666 req->ticket = r; 667 req->ticket_completed_ref = printstate.ticket_completed; 668 cond_broadcast(&printstate.cond); 669 return r; 670 } 671 672 static __always_inline 673 void printstate_mark_req_completed(const struct entry *req) 674 { 675 if (req->ticket > printstate.ticket_completed) 676 printstate.ticket_completed = req->ticket; 677 } 678 679 static __always_inline 680 bool printstate_has_new_req_arrived(const struct entry *req) 681 { 682 return (printstate.ticket_counter != req->ticket); 683 } 684 685 static __always_inline int printstate_cnt_inc(void) 686 { 687 int value; 688 689 mutex_lock(&printstate.cnt_mutex); 690 value = ++printstate.cnt; 691 mutex_unlock(&printstate.cnt_mutex); 692 return value; 693 } 694 695 static __always_inline int printstate_cnt_dec(void) 696 { 697 int value; 698 699 mutex_lock(&printstate.cnt_mutex); 700 value = --printstate.cnt; 701 mutex_unlock(&printstate.cnt_mutex); 702 return value; 703 } 704 705 static __always_inline int printstate_cnt_read(void) 706 { 707 int value; 708 709 mutex_lock(&printstate.cnt_mutex); 710 value = printstate.cnt; 711 mutex_unlock(&printstate.cnt_mutex); 712 return value; 713 } 714 715 static __always_inline 716 bool prev_req_won_race(const struct entry *req) 717 { 718 return (printstate.ticket_completed != req->ticket_completed_ref); 719 } 720 721 static void sleeptable_resize(int size, bool printout, struct short_msg *msg) 722 { 723 int bytes; 724 725 if (printout) { 726 msg->len = 0; 727 if (unlikely(size > PROB_TABLE_MAX_SIZE)) 728 bytes = snprintf(msg->buf, sizeof(msg->buf), 729 "Cannot increase probability table to %d (maximum size reached)\n", size); 730 else 731 bytes = snprintf(msg->buf, sizeof(msg->buf), 732 "Increasing probability table to %d\n", size); 733 if (bytes < 0) 734 warn("snprintf() failed"); 735 else 736 msg->len = bytes; 737 } 738 739 if (unlikely(size < 0)) { 740 /* Should never happen */ 741 warnx("Bad program state at %s:%d", __FILE__, __LINE__); 742 cleanup_exit(EXIT_FAILURE); 743 return; 744 } 745 sleeptable.size = size; 746 sleeptable.table = &probabilities[PROB_TABLE_MAX_SIZE - size]; 747 } 748 749 static void init_probabilities(void) 750 { 751 int i; 752 int j = 1000; 753 754 for (i = 0; i < PROB_TABLE_MAX_SIZE; i++) { 755 probabilities[i] = 1000 / j; 756 j--; 757 } 758 mutex_init(&sleeptable.mutex, NULL); 759 } 760 761 static int table_get_probability(const struct entry *req, 762 struct short_msg *msg) 763 { 764 int diff = req->ticket - req->ticket_completed_ref; 765 int rval = 0; 766 767 msg->len = 0; 768 diff--; 769 /* Should never happen...*/ 770 if (unlikely(diff < 0)) { 771 warnx("Programmer assumption error at %s:%d\n", __FILE__, 772 __LINE__); 773 cleanup_exit(EXIT_FAILURE); 774 } 775 mutex_lock(&sleeptable.mutex); 776 if (diff >= (sleeptable.size - 1)) { 777 rval = sleeptable.table[sleeptable.size - 1]; 778 sleeptable_resize(sleeptable.size + 1, verbose_sizechange(), 779 msg); 780 } else { 781 rval = sleeptable.table[diff]; 782 } 783 mutex_unlock(&sleeptable.mutex); 784 return rval; 785 } 786 787 static void init_queue(struct queue *q) 788 { 789 q->next_prod_idx = 0; 790 q->next_cons_idx = 0; 791 mutex_init(&q->mutex, NULL); 792 errno = pthread_cond_init(&q->cond, NULL); 793 if (errno) 794 err(EXIT_FAILURE, "pthread_cond_init() failed"); 795 } 796 797 static __always_inline int queue_len(const struct queue *q) 798 { 799 if (q->next_prod_idx >= q->next_cons_idx) 800 return q->next_prod_idx - q->next_cons_idx; 801 else 802 return QUEUE_SIZE - q->next_cons_idx + q->next_prod_idx; 803 } 804 805 static __always_inline int queue_nr_free(const struct queue *q) 806 { 807 int nr_free = QUEUE_SIZE - queue_len(q); 808 809 /* 810 * If there is only one slot left we will anyway lie and claim that the 811 * queue is full because adding an element will make it appear empty 812 */ 813 if (nr_free == 1) 814 nr_free = 0; 815 return nr_free; 816 } 817 818 static __always_inline void queue_idx_inc(int *idx) 819 { 820 *idx = (*idx + 1) % QUEUE_SIZE; 821 } 822 823 static __always_inline void queue_push_to_back(struct queue *q, 824 const struct entry *e) 825 { 826 q->entries[q->next_prod_idx] = *e; 827 queue_idx_inc(&q->next_prod_idx); 828 } 829 830 static __always_inline struct entry queue_pop_from_front(struct queue *q) 831 { 832 struct entry e = q->entries[q->next_cons_idx]; 833 834 queue_idx_inc(&q->next_cons_idx); 835 return e; 836 } 837 838 static __always_inline void queue_cond_signal(struct queue *q) 839 { 840 cond_signal(&q->cond); 841 } 842 843 static __always_inline void queue_cond_wait(struct queue *q) 844 { 845 cond_wait(&q->cond, &q->mutex); 846 } 847 848 static __always_inline int queue_try_to_add_entry(struct queue *q, 849 const struct entry *e) 850 { 851 int r = 0; 852 853 mutex_lock(&q->mutex); 854 if (queue_nr_free(q) > 0) { 855 queue_push_to_back(q, e); 856 cond_signal(&q->cond); 857 } else 858 r = -1; 859 mutex_unlock(&q->mutex); 860 return r; 861 } 862 863 static struct entry queue_wait_for_entry(struct queue *q) 864 { 865 struct entry e; 866 867 mutex_lock(&q->mutex); 868 while (true) { 869 if (queue_len(&printqueue) > 0) { 870 e = queue_pop_from_front(q); 871 break; 872 } 873 queue_cond_wait(q); 874 } 875 mutex_unlock(&q->mutex); 876 877 return e; 878 } 879 880 static const struct policy *policy_from_name(const char *name) 881 { 882 const struct policy *p = &policies[0]; 883 884 while (p->name != NULL) { 885 if (!strcmp(name, p->name)) 886 return p; 887 p++; 888 } 889 return NULL; 890 } 891 892 static const char *policy_name(int policy) 893 { 894 const struct policy *p = &policies[0]; 895 static const char *rval = "unknown"; 896 897 while (p->name != NULL) { 898 if (p->policy == policy) 899 return p->name; 900 p++; 901 } 902 return rval; 903 } 904 905 static bool is_relevant_tracer(const char *name) 906 { 907 unsigned int i; 908 909 for (i = 0; relevant_tracers[i]; i++) 910 if (!strcmp(name, relevant_tracers[i])) 911 return true; 912 return false; 913 } 914 915 static bool random_makes_sense(const char *name) 916 { 917 unsigned int i; 918 919 for (i = 0; random_tracers[i]; i++) 920 if (!strcmp(name, random_tracers[i])) 921 return true; 922 return false; 923 } 924 925 static void show_available(void) 926 { 927 char **tracers; 928 int found = 0; 929 int i; 930 931 tracers = tracefs_tracers(NULL); 932 for (i = 0; tracers && tracers[i]; i++) { 933 if (is_relevant_tracer(tracers[i])) 934 found++; 935 } 936 937 if (!tracers) { 938 warnx("%s", no_tracer_msg); 939 return; 940 } 941 942 if (!found) { 943 warnx("%s", no_latency_tr_msg); 944 tracefs_list_free(tracers); 945 return; 946 } 947 948 printf("The following latency tracers are available on your system:\n"); 949 for (i = 0; tracers[i]; i++) { 950 if (is_relevant_tracer(tracers[i])) 951 printf("%s\n", tracers[i]); 952 } 953 tracefs_list_free(tracers); 954 } 955 956 static bool tracer_valid(const char *name, bool *notracer) 957 { 958 char **tracers; 959 int i; 960 bool rval = false; 961 962 *notracer = false; 963 tracers = tracefs_tracers(NULL); 964 if (!tracers) { 965 *notracer = true; 966 return false; 967 } 968 for (i = 0; tracers[i]; i++) 969 if (!strcmp(tracers[i], name)) { 970 rval = true; 971 break; 972 } 973 tracefs_list_free(tracers); 974 return rval; 975 } 976 977 static const char *find_default_tracer(void) 978 { 979 int i; 980 bool notracer; 981 bool valid; 982 983 for (i = 0; relevant_tracers[i]; i++) { 984 valid = tracer_valid(relevant_tracers[i], ¬racer); 985 if (notracer) 986 errx(EXIT_FAILURE, "%s", no_tracer_msg); 987 if (valid) 988 return relevant_tracers[i]; 989 } 990 return NULL; 991 } 992 993 static bool toss_coin(struct drand48_data *buffer, unsigned int prob) 994 { 995 long r; 996 997 if (unlikely(lrand48_r(buffer, &r))) { 998 warnx("lrand48_r() failed"); 999 cleanup_exit(EXIT_FAILURE); 1000 } 1001 r = r % 1000L; 1002 if (r < prob) 1003 return true; 1004 else 1005 return false; 1006 } 1007 1008 1009 static long go_to_sleep(const struct entry *req) 1010 { 1011 struct timespec future; 1012 long delay = sleep_time; 1013 1014 get_time_in_future(&future, delay); 1015 1016 mutex_lock(&printstate.mutex); 1017 while (!printstate_has_new_req_arrived(req)) { 1018 cond_timedwait(&printstate.cond, &printstate.mutex, &future); 1019 if (time_has_passed(&future)) 1020 break; 1021 } 1022 1023 if (printstate_has_new_req_arrived(req)) 1024 delay = -1; 1025 mutex_unlock(&printstate.mutex); 1026 1027 return delay; 1028 } 1029 1030 1031 static void set_priority(void) 1032 { 1033 int r; 1034 pid_t pid; 1035 struct sched_param param; 1036 1037 memset(¶m, 0, sizeof(param)); 1038 param.sched_priority = sched_pri; 1039 1040 pid = getpid(); 1041 r = sched_setscheduler(pid, sched_policy, ¶m); 1042 1043 if (r != 0) 1044 err(EXIT_FAILURE, "sched_setscheduler() failed"); 1045 } 1046 1047 pid_t latency_collector_gettid(void) 1048 { 1049 return (pid_t) syscall(__NR_gettid); 1050 } 1051 1052 static void print_priority(void) 1053 { 1054 pid_t tid; 1055 int policy; 1056 int r; 1057 struct sched_param param; 1058 1059 tid = latency_collector_gettid(); 1060 r = pthread_getschedparam(pthread_self(), &policy, ¶m); 1061 if (r != 0) { 1062 warn("pthread_getschedparam() failed"); 1063 cleanup_exit(EXIT_FAILURE); 1064 } 1065 mutex_lock(&print_mtx); 1066 printf("Thread %d runs with scheduling policy %s and priority %d\n", 1067 tid, policy_name(policy), param.sched_priority); 1068 mutex_unlock(&print_mtx); 1069 } 1070 1071 static __always_inline 1072 void __print_skipmessage(const struct short_msg *resize_msg, 1073 const struct timespec *timestamp, char *buffer, 1074 size_t bufspace, const struct entry *req, bool excuse, 1075 const char *str) 1076 { 1077 ssize_t bytes = 0; 1078 char *p = &buffer[0]; 1079 long us, sec; 1080 int r; 1081 1082 sec = timestamp->tv_sec; 1083 us = timestamp->tv_nsec / 1000; 1084 1085 if (resize_msg != NULL && resize_msg->len > 0) { 1086 strncpy(p, resize_msg->buf, resize_msg->len); 1087 bytes += resize_msg->len; 1088 p += resize_msg->len; 1089 bufspace -= resize_msg->len; 1090 } 1091 1092 if (excuse) 1093 r = snprintf(p, bufspace, 1094 "%ld.%06ld Latency %d printout skipped due to %s\n", 1095 sec, us, req->ticket, str); 1096 else 1097 r = snprintf(p, bufspace, "%ld.%06ld Latency %d detected\n", 1098 sec, us, req->ticket); 1099 1100 if (r < 0) 1101 warn("snprintf() failed"); 1102 else 1103 bytes += r; 1104 1105 /* These prints could happen concurrently */ 1106 mutex_lock(&print_mtx); 1107 write_or_die(fd_stdout, buffer, bytes); 1108 mutex_unlock(&print_mtx); 1109 } 1110 1111 static void print_skipmessage(const struct short_msg *resize_msg, 1112 const struct timespec *timestamp, char *buffer, 1113 size_t bufspace, const struct entry *req, 1114 bool excuse) 1115 { 1116 __print_skipmessage(resize_msg, timestamp, buffer, bufspace, req, 1117 excuse, "random delay"); 1118 } 1119 1120 static void print_lostmessage(const struct timespec *timestamp, char *buffer, 1121 size_t bufspace, const struct entry *req, 1122 const char *reason) 1123 { 1124 __print_skipmessage(NULL, timestamp, buffer, bufspace, req, true, 1125 reason); 1126 } 1127 1128 static void print_tracefile(const struct short_msg *resize_msg, 1129 const struct timespec *timestamp, char *buffer, 1130 size_t bufspace, long slept, 1131 const struct entry *req) 1132 { 1133 static const int reserve = 256; 1134 char *p = &buffer[0]; 1135 ssize_t bytes = 0; 1136 ssize_t bytes_tot = 0; 1137 long us, sec; 1138 long slept_ms; 1139 int trace_fd; 1140 1141 /* Save some space for the final string and final null char */ 1142 bufspace = bufspace - reserve - 1; 1143 1144 if (resize_msg != NULL && resize_msg->len > 0) { 1145 bytes = resize_msg->len; 1146 strncpy(p, resize_msg->buf, bytes); 1147 bytes_tot += bytes; 1148 p += bytes; 1149 bufspace -= bytes; 1150 } 1151 1152 trace_fd = open(debug_tracefile, O_RDONLY); 1153 1154 if (trace_fd < 0) { 1155 warn("open() failed on %s", debug_tracefile); 1156 return; 1157 } 1158 1159 sec = timestamp->tv_sec; 1160 us = timestamp->tv_nsec / 1000; 1161 1162 if (slept != 0) { 1163 slept_ms = slept / 1000; 1164 bytes = snprintf(p, bufspace, 1165 "%ld.%06ld Latency %d randomly sleep for %ld ms before print\n", 1166 sec, us, req->ticket, slept_ms); 1167 } else { 1168 bytes = snprintf(p, bufspace, 1169 "%ld.%06ld Latency %d immediate print\n", sec, 1170 us, req->ticket); 1171 } 1172 1173 if (bytes < 0) { 1174 warn("snprintf() failed"); 1175 return; 1176 } 1177 p += bytes; 1178 bufspace -= bytes; 1179 bytes_tot += bytes; 1180 1181 bytes = snprintf(p, bufspace, 1182 ">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> BEGIN <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n" 1183 ); 1184 1185 if (bytes < 0) { 1186 warn("snprintf() failed"); 1187 return; 1188 } 1189 1190 p += bytes; 1191 bufspace -= bytes; 1192 bytes_tot += bytes; 1193 1194 do { 1195 bytes = read(trace_fd, p, bufspace); 1196 if (bytes < 0) { 1197 if (errno == EINTR) 1198 continue; 1199 warn("read() failed on %s", debug_tracefile); 1200 if (unlikely(close(trace_fd) != 0)) 1201 warn("close() failed on %s", debug_tracefile); 1202 return; 1203 } 1204 if (bytes == 0) 1205 break; 1206 p += bytes; 1207 bufspace -= bytes; 1208 bytes_tot += bytes; 1209 } while (true); 1210 1211 if (unlikely(close(trace_fd) != 0)) 1212 warn("close() failed on %s", debug_tracefile); 1213 1214 printstate_cnt_dec(); 1215 /* Add the reserve space back to the budget for the final string */ 1216 bufspace += reserve; 1217 1218 bytes = snprintf(p, bufspace, 1219 ">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> END <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n\n"); 1220 1221 if (bytes < 0) { 1222 warn("snprintf() failed"); 1223 return; 1224 } 1225 1226 bytes_tot += bytes; 1227 1228 /* These prints could happen concurrently */ 1229 mutex_lock(&print_mtx); 1230 write_or_die(fd_stdout, buffer, bytes_tot); 1231 mutex_unlock(&print_mtx); 1232 } 1233 1234 static char *get_no_opt(const char *opt) 1235 { 1236 char *no_opt; 1237 int s; 1238 1239 s = strlen(opt) + strlen(OPT_NO_PREFIX) + 1; 1240 /* We may be called from cleanup_exit() via set_trace_opt() */ 1241 no_opt = malloc_or_die_nocleanup(s); 1242 strcpy(no_opt, OPT_NO_PREFIX); 1243 strcat(no_opt, opt); 1244 return no_opt; 1245 } 1246 1247 static char *find_next_optstr(const char *allopt, const char **next) 1248 { 1249 const char *begin; 1250 const char *end; 1251 char *r; 1252 int s = 0; 1253 1254 if (allopt == NULL) 1255 return NULL; 1256 1257 for (begin = allopt; *begin != '\0'; begin++) { 1258 if (isgraph(*begin)) 1259 break; 1260 } 1261 1262 if (*begin == '\0') 1263 return NULL; 1264 1265 for (end = begin; *end != '\0' && isgraph(*end); end++) 1266 s++; 1267 1268 r = malloc_or_die_nocleanup(s + 1); 1269 strncpy(r, begin, s); 1270 r[s] = '\0'; 1271 *next = begin + s; 1272 return r; 1273 } 1274 1275 static bool get_trace_opt(const char *allopt, const char *opt, bool *found) 1276 { 1277 *found = false; 1278 char *no_opt; 1279 char *str; 1280 const char *next = allopt; 1281 bool rval = false; 1282 1283 no_opt = get_no_opt(opt); 1284 1285 do { 1286 str = find_next_optstr(next, &next); 1287 if (str == NULL) 1288 break; 1289 if (!strcmp(str, opt)) { 1290 *found = true; 1291 rval = true; 1292 free(str); 1293 break; 1294 } 1295 if (!strcmp(str, no_opt)) { 1296 *found = true; 1297 rval = false; 1298 free(str); 1299 break; 1300 } 1301 free(str); 1302 } while (true); 1303 free(no_opt); 1304 1305 return rval; 1306 } 1307 1308 static int set_trace_opt(const char *opt, bool value) 1309 { 1310 char *str; 1311 int r; 1312 1313 if (value) 1314 str = strdup(opt); 1315 else 1316 str = get_no_opt(opt); 1317 1318 r = tracefs_instance_file_write(NULL, TR_OPTIONS, str); 1319 free(str); 1320 return r; 1321 } 1322 1323 void save_trace_opts(struct ftrace_state *state) 1324 { 1325 char *allopt; 1326 int psize; 1327 int i; 1328 1329 allopt = tracefs_instance_file_read(NULL, TR_OPTIONS, &psize); 1330 if (!allopt) 1331 errx(EXIT_FAILURE, "Failed to read the %s file\n", TR_OPTIONS); 1332 1333 for (i = 0; i < OPTIDX_NR; i++) 1334 state->opt[i] = get_trace_opt(allopt, optstr[i], 1335 &state->opt_valid[i]); 1336 1337 free(allopt); 1338 } 1339 1340 static void write_file(const char *file, const char *cur, const char *new, 1341 enum errhandling h) 1342 { 1343 int r; 1344 static const char *emsg = "Failed to write to the %s file!"; 1345 1346 /* Do nothing if we now that the current and new value are equal */ 1347 if (cur && !needs_change(cur, new)) 1348 return; 1349 1350 r = tracefs_instance_file_write(NULL, file, new); 1351 if (r < 0) { 1352 if (h) { 1353 warnx(emsg, file); 1354 if (h == ERR_CLEANUP) 1355 cleanup_exit(EXIT_FAILURE); 1356 } else 1357 errx(EXIT_FAILURE, emsg, file); 1358 } 1359 if (verbose_ftrace()) { 1360 mutex_lock(&print_mtx); 1361 printf("%s was set to %s\n", file, new); 1362 mutex_unlock(&print_mtx); 1363 } 1364 } 1365 1366 static void reset_max_latency(void) 1367 { 1368 write_file(TR_MAXLAT, NULL, "0", ERR_CLEANUP); 1369 } 1370 1371 static void save_and_disable_tracer(void) 1372 { 1373 char *orig_th; 1374 char *tracer; 1375 bool need_nop = false; 1376 1377 mutex_lock(&save_state.mutex); 1378 1379 save_trace_opts(&save_state); 1380 tracer = read_file(TR_CURRENT, ERR_EXIT); 1381 orig_th = read_file(TR_THRESH, ERR_EXIT); 1382 1383 if (needs_change(tracer, NOP_TRACER)) { 1384 mutex_lock(&print_mtx); 1385 if (force_tracer) { 1386 printf( 1387 "The %s tracer is already in use but proceeding anyway!\n", 1388 tracer); 1389 } else { 1390 printf( 1391 "The %s tracer is already in use, cowardly bailing out!\n" 1392 "This could indicate that another program or instance is tracing.\n" 1393 "Use the -F [--force] option to disregard the current tracer.\n", tracer); 1394 exit(0); 1395 } 1396 mutex_unlock(&print_mtx); 1397 need_nop = true; 1398 } 1399 1400 save_state.tracer = tracer; 1401 save_state.thresh = orig_th; 1402 1403 if (need_nop) 1404 write_file(TR_CURRENT, NULL, NOP_TRACER, ERR_EXIT); 1405 1406 mutex_unlock(&save_state.mutex); 1407 } 1408 1409 void set_trace_opts(struct ftrace_state *state, bool *new) 1410 { 1411 int i; 1412 int r; 1413 1414 /* 1415 * We only set options if we earlier detected that the option exists in 1416 * the trace_options file and that the wanted setting is different from 1417 * the one we saw in save_and_disable_tracer() 1418 */ 1419 for (i = 0; i < OPTIDX_NR; i++) 1420 if (state->opt_valid[i] && 1421 state->opt[i] != new[i]) { 1422 r = set_trace_opt(optstr[i], new[i]); 1423 if (r < 0) { 1424 warnx("Failed to set the %s option to %s", 1425 optstr[i], bool2str(new[i])); 1426 cleanup_exit(EXIT_FAILURE); 1427 } 1428 if (verbose_ftrace()) { 1429 mutex_lock(&print_mtx); 1430 printf("%s in %s was set to %s\n", optstr[i], 1431 TR_OPTIONS, bool2str(new[i])); 1432 mutex_unlock(&print_mtx); 1433 } 1434 } 1435 } 1436 1437 static void enable_tracer(void) 1438 { 1439 mutex_lock(&save_state.mutex); 1440 set_trace_opts(&save_state, use_options); 1441 1442 write_file(TR_THRESH, save_state.thresh, threshold, ERR_CLEANUP); 1443 write_file(TR_CURRENT, NOP_TRACER, current_tracer, ERR_CLEANUP); 1444 1445 mutex_unlock(&save_state.mutex); 1446 } 1447 1448 static void tracing_loop(void) 1449 { 1450 int ifd = inotify_init(); 1451 int wd; 1452 const ssize_t bufsize = sizeof(inotify_buffer); 1453 const ssize_t istructsize = sizeof(struct inotify_event); 1454 char *buf = &inotify_buffer[0]; 1455 ssize_t nr_read; 1456 char *p; 1457 int modified; 1458 struct inotify_event *event; 1459 struct entry req; 1460 char *buffer; 1461 const size_t bufspace = PRINT_BUFFER_SIZE; 1462 struct timespec timestamp; 1463 1464 print_priority(); 1465 1466 buffer = malloc_or_die(bufspace); 1467 1468 if (ifd < 0) 1469 err(EXIT_FAILURE, "inotify_init() failed!"); 1470 1471 1472 if (setup_ftrace) { 1473 /* 1474 * We must disable the tracer before resetting the max_latency 1475 */ 1476 save_and_disable_tracer(); 1477 /* 1478 * We must reset the max_latency before the inotify_add_watch() 1479 * call. 1480 */ 1481 reset_max_latency(); 1482 } 1483 1484 wd = inotify_add_watch(ifd, debug_maxlat, IN_MODIFY); 1485 if (wd < 0) 1486 err(EXIT_FAILURE, "inotify_add_watch() failed!"); 1487 1488 if (setup_ftrace) 1489 enable_tracer(); 1490 1491 signal_blocking(SIG_UNBLOCK); 1492 1493 while (true) { 1494 modified = 0; 1495 check_signals(); 1496 nr_read = read(ifd, buf, bufsize); 1497 check_signals(); 1498 if (nr_read < 0) { 1499 if (errno == EINTR) 1500 continue; 1501 warn("read() failed on inotify fd!"); 1502 cleanup_exit(EXIT_FAILURE); 1503 } 1504 if (nr_read == bufsize) 1505 warnx("inotify() buffer filled, skipping events"); 1506 if (nr_read < istructsize) { 1507 warnx("read() returned too few bytes on inotify fd"); 1508 cleanup_exit(EXIT_FAILURE); 1509 } 1510 1511 for (p = buf; p < buf + nr_read;) { 1512 event = (struct inotify_event *) p; 1513 if ((event->mask & IN_MODIFY) != 0) 1514 modified++; 1515 p += istructsize + event->len; 1516 } 1517 while (modified > 0) { 1518 check_signals(); 1519 mutex_lock(&printstate.mutex); 1520 check_signals(); 1521 printstate_next_ticket(&req); 1522 if (printstate_cnt_read() > 0) { 1523 printstate_mark_req_completed(&req); 1524 mutex_unlock(&printstate.mutex); 1525 if (verbose_lostevent()) { 1526 clock_gettime_or_die(CLOCK_MONOTONIC, 1527 ×tamp); 1528 print_lostmessage(×tamp, buffer, 1529 bufspace, &req, 1530 "inotify loop"); 1531 } 1532 break; 1533 } 1534 mutex_unlock(&printstate.mutex); 1535 if (queue_try_to_add_entry(&printqueue, &req) != 0) { 1536 /* These prints could happen concurrently */ 1537 check_signals(); 1538 mutex_lock(&print_mtx); 1539 check_signals(); 1540 write_or_die(fd_stdout, queue_full_warning, 1541 strlen(queue_full_warning)); 1542 mutex_unlock(&print_mtx); 1543 } 1544 modified--; 1545 } 1546 } 1547 } 1548 1549 static void *do_printloop(void *arg) 1550 { 1551 const size_t bufspace = PRINT_BUFFER_SIZE; 1552 char *buffer; 1553 long *rseed = (long *) arg; 1554 struct drand48_data drandbuf; 1555 long slept = 0; 1556 struct entry req; 1557 int prob = 0; 1558 struct timespec timestamp; 1559 struct short_msg resize_msg; 1560 1561 print_priority(); 1562 1563 if (srand48_r(*rseed, &drandbuf) != 0) { 1564 warn("srand48_r() failed!\n"); 1565 cleanup_exit(EXIT_FAILURE); 1566 } 1567 1568 buffer = malloc_or_die(bufspace); 1569 1570 while (true) { 1571 req = queue_wait_for_entry(&printqueue); 1572 clock_gettime_or_die(CLOCK_MONOTONIC, ×tamp); 1573 mutex_lock(&printstate.mutex); 1574 if (prev_req_won_race(&req)) { 1575 printstate_mark_req_completed(&req); 1576 mutex_unlock(&printstate.mutex); 1577 if (verbose_lostevent()) 1578 print_lostmessage(×tamp, buffer, bufspace, 1579 &req, "print loop"); 1580 continue; 1581 } 1582 mutex_unlock(&printstate.mutex); 1583 1584 /* 1585 * Toss a coin to decide if we want to sleep before printing 1586 * out the backtrace. The reason for this is that opening 1587 * /sys/kernel/tracing/trace will cause a blackout of 1588 * hundreds of ms, where no latencies will be noted by the 1589 * latency tracer. Thus by randomly sleeping we try to avoid 1590 * missing traces systematically due to this. With this option 1591 * we will sometimes get the first latency, some other times 1592 * some of the later ones, in case of closely spaced traces. 1593 */ 1594 if (trace_enable && use_random_sleep) { 1595 slept = 0; 1596 prob = table_get_probability(&req, &resize_msg); 1597 if (!toss_coin(&drandbuf, prob)) 1598 slept = go_to_sleep(&req); 1599 if (slept >= 0) { 1600 /* A print is ongoing */ 1601 printstate_cnt_inc(); 1602 /* 1603 * We will do the printout below so we have to 1604 * mark it as completed while we still have the 1605 * mutex. 1606 */ 1607 mutex_lock(&printstate.mutex); 1608 printstate_mark_req_completed(&req); 1609 mutex_unlock(&printstate.mutex); 1610 } 1611 } 1612 if (trace_enable) { 1613 /* 1614 * slept < 0 means that we detected another 1615 * notification in go_to_sleep() above 1616 */ 1617 if (slept >= 0) 1618 /* 1619 * N.B. printstate_cnt_dec(); will be called 1620 * inside print_tracefile() 1621 */ 1622 print_tracefile(&resize_msg, ×tamp, buffer, 1623 bufspace, slept, &req); 1624 else 1625 print_skipmessage(&resize_msg, ×tamp, 1626 buffer, bufspace, &req, true); 1627 } else { 1628 print_skipmessage(&resize_msg, ×tamp, buffer, 1629 bufspace, &req, false); 1630 } 1631 } 1632 return NULL; 1633 } 1634 1635 static void start_printthread(void) 1636 { 1637 unsigned int i; 1638 long *seed; 1639 int ufd; 1640 1641 ufd = open(DEV_URANDOM, O_RDONLY); 1642 if (nr_threads > MAX_THREADS) { 1643 warnx( 1644 "Number of requested print threads was %d, max number is %d\n", 1645 nr_threads, MAX_THREADS); 1646 nr_threads = MAX_THREADS; 1647 } 1648 for (i = 0; i < nr_threads; i++) { 1649 seed = malloc_or_die(sizeof(*seed)); 1650 if (ufd < 0 || 1651 read(ufd, seed, sizeof(*seed)) != sizeof(*seed)) { 1652 printf( 1653 "Warning! Using trivial random number seed, since %s not available\n", 1654 DEV_URANDOM); 1655 fflush(stdout); 1656 *seed = i; 1657 } 1658 errno = pthread_create(&printthread[i], NULL, do_printloop, 1659 seed); 1660 if (errno) 1661 err(EXIT_FAILURE, "pthread_create()"); 1662 } 1663 if (ufd > 0 && close(ufd) != 0) 1664 warn("close() failed"); 1665 } 1666 1667 static void show_usage(void) 1668 { 1669 printf( 1670 "Usage: %s [OPTION]...\n\n" 1671 "Collect closely occurring latencies from %s\n" 1672 "with any of the following tracers: preemptirqsoff, preemptoff, irqsoff, " 1673 "wakeup,\nwakeup_dl, or wakeup_rt.\n\n" 1674 1675 "The occurrence of a latency is detected by monitoring the file\n" 1676 "%s with inotify.\n\n" 1677 1678 "The following options are supported:\n\n" 1679 1680 "-l, --list\t\tList the latency tracers that are supported by the\n" 1681 "\t\t\tcurrently running Linux kernel. If you don't see the\n" 1682 "\t\t\ttracer that you want, you will probably need to\n" 1683 "\t\t\tchange your kernel config and build a new kernel.\n\n" 1684 1685 "-t, --tracer TR\t\tUse the tracer TR. The default is to use the first\n" 1686 "\t\t\ttracer that is supported by the kernel in the following\n" 1687 "\t\t\torder of precedence:\n\n" 1688 "\t\t\tpreemptirqsoff\n" 1689 "\t\t\tpreemptoff\n" 1690 "\t\t\tirqsoff\n" 1691 "\t\t\twakeup\n" 1692 "\t\t\twakeup_rt\n" 1693 "\t\t\twakeup_dl\n" 1694 "\n" 1695 "\t\t\tIf TR is not on the list above, then a warning will be\n" 1696 "\t\t\tprinted.\n\n" 1697 1698 "-F, --force\t\tProceed even if another ftrace tracer is active. Without\n" 1699 "\t\t\tthis option, the program will refuse to start tracing if\n" 1700 "\t\t\tany other tracer than the nop tracer is active.\n\n" 1701 1702 "-s, --threshold TH\tConfigure ftrace to use a threshold of TH microseconds\n" 1703 "\t\t\tfor the tracer. The default is 0, which means that\n" 1704 "\t\t\ttracing_max_latency will be used. tracing_max_latency is\n" 1705 "\t\t\tset to 0 when the program is started and contains the\n" 1706 "\t\t\tmaximum of the latencies that have been encountered.\n\n" 1707 1708 "-f, --function\t\tEnable the function-trace option in trace_options. With\n" 1709 "\t\t\tthis option, ftrace will trace the functions that are\n" 1710 "\t\t\texecuted during a latency, without it we only get the\n" 1711 "\t\t\tbeginning, end, and backtrace.\n\n" 1712 1713 "-g, --graph\t\tEnable the display-graph option in trace_option. This\n" 1714 "\t\t\toption causes ftrace to show the graph of how functions\n" 1715 "\t\t\tare calling other functions.\n\n" 1716 1717 "-c, --policy POL\tRun the program with scheduling policy POL. POL can be\n" 1718 "\t\t\tother, batch, idle, rr or fifo. The default is rr. When\n" 1719 "\t\t\tusing rr or fifo, remember that these policies may cause\n" 1720 "\t\t\tother tasks to experience latencies.\n\n" 1721 1722 "-p, --priority PRI\tRun the program with priority PRI. The acceptable range\n" 1723 "\t\t\tof PRI depends on the scheduling policy.\n\n" 1724 1725 "-n, --notrace\t\tIf latency is detected, do not print out the content of\n" 1726 "\t\t\tthe trace file to standard output\n\n" 1727 1728 "-t, --threads NRTHR\tRun NRTHR threads for printing. Default is %d.\n\n" 1729 1730 "-r, --random\t\tArbitrarily sleep a certain amount of time, default\n" 1731 "\t\t\t%ld ms, before reading the trace file. The\n" 1732 "\t\t\tprobabilities for sleep are chosen so that the\n" 1733 "\t\t\tprobability of obtaining any of a cluster of closely\n" 1734 "\t\t\toccurring latencies are equal, i.e. we will randomly\n" 1735 "\t\t\tchoose which one we collect from the trace file.\n\n" 1736 "\t\t\tThis option is probably only useful with the irqsoff,\n" 1737 "\t\t\tpreemptoff, and preemptirqsoff tracers.\n\n" 1738 1739 "-a, --nrlat NRLAT\tFor the purpose of arbitrary delay, assume that there\n" 1740 "\t\t\tare no more than NRLAT clustered latencies. If NRLAT\n" 1741 "\t\t\tlatencies are detected during a run, this value will\n" 1742 "\t\t\tautomatically be increased to NRLAT + 1 and then to\n" 1743 "\t\t\tNRLAT + 2 and so on. The default is %d. This option\n" 1744 "\t\t\timplies -r. We need to know this number in order to\n" 1745 "\t\t\tbe able to calculate the probabilities of sleeping.\n" 1746 "\t\t\tSpecifically, the probabilities of not sleeping, i.e. to\n" 1747 "\t\t\tdo an immediate printout will be:\n\n" 1748 "\t\t\t1/NRLAT 1/(NRLAT - 1) ... 1/3 1/2 1\n\n" 1749 "\t\t\tThe probability of sleeping will be:\n\n" 1750 "\t\t\t1 - P, where P is from the series above\n\n" 1751 "\t\t\tThis descending probability will cause us to choose\n" 1752 "\t\t\tan occurrence at random. Observe that the final\n" 1753 "\t\t\tprobability is 0, it is when we reach this probability\n" 1754 "\t\t\tthat we increase NRLAT automatically. As an example,\n" 1755 "\t\t\twith the default value of 2, the probabilities will be:\n\n" 1756 "\t\t\t1/2 0\n\n" 1757 "\t\t\tThis means, when a latency is detected we will sleep\n" 1758 "\t\t\twith 50%% probability. If we ever detect another latency\n" 1759 "\t\t\tduring the sleep period, then the probability of sleep\n" 1760 "\t\t\twill be 0%% and the table will be expanded to:\n\n" 1761 "\t\t\t1/3 1/2 0\n\n" 1762 1763 "-v, --verbose\t\tIncrease the verbosity. If this option is given once,\n" 1764 "\t\t\tthen print a message every time that the NRLAT value\n" 1765 "\t\t\tis automatically increased. It also causes a message to\n" 1766 "\t\t\tbe printed when the ftrace settings are changed. If this\n" 1767 "\t\t\toption is given at least twice, then also print a\n" 1768 "\t\t\twarning for lost events.\n\n" 1769 1770 "-u, --time TIME\t\tArbitrarily sleep for a specified time TIME ms before\n" 1771 "\t\t\tprinting out the trace from the trace file. The default\n" 1772 "\t\t\tis %ld ms. This option implies -r.\n\n" 1773 1774 "-x, --no-ftrace\t\tDo not configure ftrace. This assume that the user\n" 1775 "\t\t\tconfigures the ftrace files in sysfs such as\n" 1776 "\t\t\t/sys/kernel/tracing/current_tracer or equivalent.\n\n" 1777 1778 "-i, --tracefile FILE\tUse FILE as trace file. The default is\n" 1779 "\t\t\t%s.\n" 1780 "\t\t\tThis options implies -x\n\n" 1781 1782 "-m, --max-lat FILE\tUse FILE as tracing_max_latency file. The default is\n" 1783 "\t\t\t%s.\n" 1784 "\t\t\tThis options implies -x\n\n" 1785 , 1786 prg_name, debug_tracefile_dflt, debug_maxlat_dflt, DEFAULT_NR_PRINTER_THREADS, 1787 SLEEP_TIME_MS_DEFAULT, DEFAULT_TABLE_SIZE, SLEEP_TIME_MS_DEFAULT, 1788 debug_tracefile_dflt, debug_maxlat_dflt); 1789 } 1790 1791 static void find_tracefiles(void) 1792 { 1793 debug_tracefile_dflt = tracefs_get_tracing_file("trace"); 1794 if (debug_tracefile_dflt == NULL) { 1795 /* This is needed in show_usage() */ 1796 debug_tracefile_dflt = DEBUG_NOFILE; 1797 } 1798 1799 debug_maxlat_dflt = tracefs_get_tracing_file("tracing_max_latency"); 1800 if (debug_maxlat_dflt == NULL) { 1801 /* This is needed in show_usage() */ 1802 debug_maxlat_dflt = DEBUG_NOFILE; 1803 } 1804 1805 debug_tracefile = debug_tracefile_dflt; 1806 debug_maxlat = debug_maxlat_dflt; 1807 } 1808 1809 bool alldigits(const char *s) 1810 { 1811 for (; *s != '\0'; s++) 1812 if (!isdigit(*s)) 1813 return false; 1814 return true; 1815 } 1816 1817 void check_alldigits(const char *optarg, const char *argname) 1818 { 1819 if (!alldigits(optarg)) 1820 errx(EXIT_FAILURE, 1821 "The %s parameter expects a decimal argument\n", argname); 1822 } 1823 1824 static void scan_arguments(int argc, char *argv[]) 1825 { 1826 int c; 1827 int i; 1828 int option_idx = 0; 1829 1830 static struct option long_options[] = { 1831 { "list", no_argument, 0, 'l' }, 1832 { "tracer", required_argument, 0, 't' }, 1833 { "force", no_argument, 0, 'F' }, 1834 { "threshold", required_argument, 0, 's' }, 1835 { "function", no_argument, 0, 'f' }, 1836 { "graph", no_argument, 0, 'g' }, 1837 { "policy", required_argument, 0, 'c' }, 1838 { "priority", required_argument, 0, 'p' }, 1839 { "help", no_argument, 0, 'h' }, 1840 { "notrace", no_argument, 0, 'n' }, 1841 { "random", no_argument, 0, 'r' }, 1842 { "nrlat", required_argument, 0, 'a' }, 1843 { "threads", required_argument, 0, 'e' }, 1844 { "time", required_argument, 0, 'u' }, 1845 { "verbose", no_argument, 0, 'v' }, 1846 { "no-ftrace", no_argument, 0, 'x' }, 1847 { "tracefile", required_argument, 0, 'i' }, 1848 { "max-lat", required_argument, 0, 'm' }, 1849 { 0, 0, 0, 0 } 1850 }; 1851 const struct policy *p; 1852 int max, min; 1853 int value; 1854 bool notracer, valid; 1855 1856 /* 1857 * We must do this before parsing the arguments because show_usage() 1858 * needs to display these. 1859 */ 1860 find_tracefiles(); 1861 1862 while (true) { 1863 c = getopt_long(argc, argv, "lt:Fs:fgc:p:hnra:e:u:vxi:m:", 1864 long_options, &option_idx); 1865 if (c == -1) 1866 break; 1867 1868 switch (c) { 1869 case 'l': 1870 show_available(); 1871 exit(0); 1872 break; 1873 case 't': 1874 current_tracer = strdup(optarg); 1875 if (!is_relevant_tracer(current_tracer)) { 1876 warnx("%s is not a known latency tracer!\n", 1877 current_tracer); 1878 } 1879 valid = tracer_valid(current_tracer, ¬racer); 1880 if (notracer) 1881 errx(EXIT_FAILURE, "%s", no_tracer_msg); 1882 if (!valid) 1883 errx(EXIT_FAILURE, 1884 "The tracer %s is not supported by your kernel!\n", current_tracer); 1885 break; 1886 case 'F': 1887 force_tracer = true; 1888 break; 1889 case 's': 1890 check_alldigits(optarg, "-s [--threshold]"); 1891 threshold = strdup(optarg); 1892 break; 1893 case 'f': 1894 use_options[OPTIDX_FUNC_TR] = true; 1895 break; 1896 case 'g': 1897 use_options[OPTIDX_DISP_GR] = true; 1898 break; 1899 case 'c': 1900 p = policy_from_name(optarg); 1901 if (p != NULL) { 1902 sched_policy = p->policy; 1903 sched_policy_set = true; 1904 if (!sched_pri_set) { 1905 sched_pri = p->default_pri; 1906 sched_pri_set = true; 1907 } 1908 } else { 1909 warnx("Unknown scheduling %s\n", optarg); 1910 show_usage(); 1911 exit(0); 1912 } 1913 break; 1914 case 'p': 1915 check_alldigits(optarg, "-p [--priority]"); 1916 sched_pri = atoi(optarg); 1917 sched_pri_set = true; 1918 break; 1919 case 'h': 1920 show_usage(); 1921 exit(0); 1922 break; 1923 case 'n': 1924 trace_enable = false; 1925 use_random_sleep = false; 1926 break; 1927 case 'e': 1928 check_alldigits(optarg, "-e [--threads]"); 1929 value = atoi(optarg); 1930 if (value > 0) 1931 nr_threads = value; 1932 else { 1933 warnx("NRTHR must be > 0\n"); 1934 show_usage(); 1935 exit(0); 1936 } 1937 break; 1938 case 'u': 1939 check_alldigits(optarg, "-u [--time]"); 1940 value = atoi(optarg); 1941 if (value < 0) { 1942 warnx("TIME must be >= 0\n"); 1943 show_usage(); 1944 exit(0); 1945 } 1946 trace_enable = true; 1947 use_random_sleep = true; 1948 sleep_time = value * USEC_PER_MSEC; 1949 break; 1950 case 'v': 1951 verbosity++; 1952 break; 1953 case 'r': 1954 trace_enable = true; 1955 use_random_sleep = true; 1956 break; 1957 case 'a': 1958 check_alldigits(optarg, "-a [--nrlat]"); 1959 value = atoi(optarg); 1960 if (value <= 0) { 1961 warnx("NRLAT must be > 0\n"); 1962 show_usage(); 1963 exit(0); 1964 } 1965 trace_enable = true; 1966 use_random_sleep = true; 1967 table_startsize = value; 1968 break; 1969 case 'x': 1970 setup_ftrace = false; 1971 break; 1972 case 'i': 1973 setup_ftrace = false; 1974 debug_tracefile = strdup(optarg); 1975 break; 1976 case 'm': 1977 setup_ftrace = false; 1978 debug_maxlat = strdup(optarg); 1979 break; 1980 default: 1981 show_usage(); 1982 exit(0); 1983 break; 1984 } 1985 } 1986 1987 if (setup_ftrace) { 1988 if (!current_tracer) { 1989 current_tracer = find_default_tracer(); 1990 if (!current_tracer) 1991 errx(EXIT_FAILURE, 1992 "No default tracer found and tracer not specified\n"); 1993 } 1994 1995 if (use_random_sleep && !random_makes_sense(current_tracer)) { 1996 warnx("WARNING: The tracer is %s and random sleep has", 1997 current_tracer); 1998 fprintf(stderr, 1999 "been enabled. Random sleep is intended for the following tracers:\n"); 2000 for (i = 0; random_tracers[i]; i++) 2001 fprintf(stderr, "%s\n", random_tracers[i]); 2002 fprintf(stderr, "\n"); 2003 } 2004 } 2005 2006 if (debug_tracefile == DEBUG_NOFILE || 2007 debug_maxlat == DEBUG_NOFILE) 2008 errx(EXIT_FAILURE, 2009 "Could not find tracing directory e.g. /sys/kernel/tracing\n"); 2010 2011 if (!sched_policy_set) { 2012 sched_policy = SCHED_RR; 2013 sched_policy_set = true; 2014 if (!sched_pri_set) { 2015 sched_pri = RT_DEFAULT_PRI; 2016 sched_pri_set = true; 2017 } 2018 } 2019 2020 max = sched_get_priority_max(sched_policy); 2021 min = sched_get_priority_min(sched_policy); 2022 2023 if (sched_pri < min) { 2024 printf( 2025 "ATTENTION: Increasing priority to minimum, which is %d\n", min); 2026 sched_pri = min; 2027 } 2028 if (sched_pri > max) { 2029 printf( 2030 "ATTENTION: Reducing priority to maximum, which is %d\n", max); 2031 sched_pri = max; 2032 } 2033 } 2034 2035 static void show_params(void) 2036 { 2037 printf( 2038 "\n" 2039 "Running with scheduling policy %s and priority %d. Using %d print threads.\n", 2040 policy_name(sched_policy), sched_pri, nr_threads); 2041 if (trace_enable) { 2042 if (use_random_sleep) { 2043 printf( 2044 "%s will be printed with random delay\n" 2045 "Start size of the probability table:\t\t\t%d\n" 2046 "Print a message when the prob. table changes size:\t%s\n" 2047 "Print a warning when an event has been lost:\t\t%s\n" 2048 "Sleep time is:\t\t\t\t\t\t%ld ms\n", 2049 debug_tracefile, 2050 table_startsize, 2051 bool2str(verbose_sizechange()), 2052 bool2str(verbose_lostevent()), 2053 sleep_time / USEC_PER_MSEC); 2054 } else { 2055 printf("%s will be printed immediately\n", 2056 debug_tracefile); 2057 } 2058 } else { 2059 printf("%s will not be printed\n", 2060 debug_tracefile); 2061 } 2062 if (setup_ftrace) { 2063 printf("Tracer:\t\t\t\t\t\t\t%s\n" 2064 "%s option:\t\t\t\t\t%s\n" 2065 "%s option:\t\t\t\t\t%s\n", 2066 current_tracer, 2067 optstr[OPTIDX_FUNC_TR], 2068 bool2str(use_options[OPTIDX_FUNC_TR]), 2069 optstr[OPTIDX_DISP_GR], 2070 bool2str(use_options[OPTIDX_DISP_GR])); 2071 if (!strcmp(threshold, "0")) 2072 printf("Threshold:\t\t\t\t\t\ttracing_max_latency\n"); 2073 else 2074 printf("Threshold:\t\t\t\t\t\t%s\n", threshold); 2075 } 2076 printf("\n"); 2077 } 2078 2079 int main(int argc, char *argv[]) 2080 { 2081 init_save_state(); 2082 signal_blocking(SIG_BLOCK); 2083 setup_sig_handler(); 2084 open_stdout(); 2085 2086 if (argc >= 1) 2087 prg_name = argv[0]; 2088 else 2089 prg_name = prg_unknown; 2090 2091 scan_arguments(argc, argv); 2092 show_params(); 2093 2094 init_printstate(); 2095 init_print_mtx(); 2096 if (use_random_sleep) { 2097 init_probabilities(); 2098 if (verbose_sizechange()) 2099 printf("Initializing probability table to %d\n", 2100 table_startsize); 2101 sleeptable_resize(table_startsize, false, NULL); 2102 } 2103 set_priority(); 2104 init_queue(&printqueue); 2105 start_printthread(); 2106 tracing_loop(); 2107 return 0; 2108 } 2109