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(no_tracer_msg);
939 		return;
940 	}
941 
942 	if (!found) {
943 		warnx(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], &notracer);
985 		if (notracer)
986 			errx(EXIT_FAILURE, 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(&param, 0, sizeof(param));
1038 	param.sched_priority = sched_pri;
1039 
1040 	pid = getpid();
1041 	r = sched_setscheduler(pid, sched_policy, &param);
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, &param);
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 							     &timestamp);
1528 					print_lostmessage(&timestamp, 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, &timestamp);
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(&timestamp, 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, &timestamp, buffer,
1623 						bufspace, slept, &req);
1624 			else
1625 				print_skipmessage(&resize_msg, &timestamp,
1626 						  buffer, bufspace, &req, true);
1627 		} else {
1628 			print_skipmessage(&resize_msg, &timestamp, 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, &notracer);
1880 			if (notracer)
1881 				errx(EXIT_FAILURE, 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