summaryrefslogtreecommitdiffstats
path: root/tools/tracing/latency/latency-collector.c
diff options
context:
space:
mode:
Diffstat (limited to 'tools/tracing/latency/latency-collector.c')
-rw-r--r--tools/tracing/latency/latency-collector.c2108
1 files changed, 2108 insertions, 0 deletions
diff --git a/tools/tracing/latency/latency-collector.c b/tools/tracing/latency/latency-collector.c
new file mode 100644
index 000000000..59a7f2346
--- /dev/null
+++ b/tools/tracing/latency/latency-collector.c
@@ -0,0 +1,2108 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2017, 2018, 2019, 2021 BMW Car IT GmbH
+ * Author: Viktor Rosendahl (viktor.rosendahl@bmw.de)
+ */
+
+#define _GNU_SOURCE
+#define _POSIX_C_SOURCE 200809L
+
+#include <ctype.h>
+#include <stdbool.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include <err.h>
+#include <errno.h>
+#include <fcntl.h>
+#include <getopt.h>
+#include <sched.h>
+#include <linux/unistd.h>
+#include <signal.h>
+#include <sys/inotify.h>
+#include <unistd.h>
+#include <pthread.h>
+#include <tracefs.h>
+
+static const char *prg_name;
+static const char *prg_unknown = "unknown program name";
+
+static int fd_stdout;
+
+static int sched_policy;
+static bool sched_policy_set;
+
+static int sched_pri;
+static bool sched_pri_set;
+
+static bool trace_enable = true;
+static bool setup_ftrace = true;
+static bool use_random_sleep;
+
+#define TRACE_OPTS \
+ C(FUNC_TR, "function-trace"), \
+ C(DISP_GR, "display-graph"), \
+ C(NR, NULL)
+
+#undef C
+#define C(a, b) OPTIDX_##a
+
+enum traceopt {
+ TRACE_OPTS
+};
+
+#undef C
+#define C(a, b) b
+
+static const char *const optstr[] = {
+ TRACE_OPTS
+};
+
+enum errhandling {
+ ERR_EXIT = 0,
+ ERR_WARN,
+ ERR_CLEANUP,
+};
+
+static bool use_options[OPTIDX_NR];
+
+static char inotify_buffer[655360];
+
+#define likely(x) __builtin_expect(!!(x), 1)
+#define unlikely(x) __builtin_expect(!!(x), 0)
+#define bool2str(x) (x ? "true":"false")
+
+#define DEFAULT_NR_PRINTER_THREADS (3)
+static unsigned int nr_threads = DEFAULT_NR_PRINTER_THREADS;
+
+#define DEFAULT_TABLE_SIZE (2)
+static unsigned int table_startsize = DEFAULT_TABLE_SIZE;
+
+static int verbosity;
+
+#define verbose_sizechange() (verbosity >= 1)
+#define verbose_lostevent() (verbosity >= 2)
+#define verbose_ftrace() (verbosity >= 1)
+
+#define was_changed(ORIG, CUR) (strcmp(ORIG, CUR) != 0)
+#define needs_change(CUR, WANTED) (strcmp(CUR, WANTED) != 0)
+
+static const char *debug_tracefile;
+static const char *debug_tracefile_dflt;
+static const char *debug_maxlat;
+static const char *debug_maxlat_dflt;
+static const char * const DEBUG_NOFILE = "[file not found]";
+
+static const char * const TR_MAXLAT = "tracing_max_latency";
+static const char * const TR_THRESH = "tracing_thresh";
+static const char * const TR_CURRENT = "current_tracer";
+static const char * const TR_OPTIONS = "trace_options";
+
+static const char * const NOP_TRACER = "nop";
+
+static const char * const OPT_NO_PREFIX = "no";
+
+#define DFLT_THRESHOLD_US "0"
+static const char *threshold = DFLT_THRESHOLD_US;
+
+#define DEV_URANDOM "/dev/urandom"
+#define RT_DEFAULT_PRI (99)
+#define DEFAULT_PRI (0)
+
+#define USEC_PER_MSEC (1000L)
+#define NSEC_PER_USEC (1000L)
+#define NSEC_PER_MSEC (USEC_PER_MSEC * NSEC_PER_USEC)
+
+#define MSEC_PER_SEC (1000L)
+#define USEC_PER_SEC (USEC_PER_MSEC * MSEC_PER_SEC)
+#define NSEC_PER_SEC (NSEC_PER_MSEC * MSEC_PER_SEC)
+
+#define SLEEP_TIME_MS_DEFAULT (1000L)
+#define TRY_PRINTMUTEX_MS (1000)
+
+static long sleep_time = (USEC_PER_MSEC * SLEEP_TIME_MS_DEFAULT);
+
+static const char * const queue_full_warning =
+"Could not queue trace for printing. It is likely that events happen faster\n"
+"than what they can be printed. Probably partly because of random sleeping\n";
+
+static const char * const no_tracer_msg =
+"Could not find any tracers! Running this program as root may help!\n";
+
+static const char * const no_latency_tr_msg =
+"No latency tracers are supported by your kernel!\n";
+
+struct policy {
+ const char *name;
+ int policy;
+ int default_pri;
+};
+
+static const struct policy policies[] = {
+ { "other", SCHED_OTHER, DEFAULT_PRI },
+ { "batch", SCHED_BATCH, DEFAULT_PRI },
+ { "idle", SCHED_IDLE, DEFAULT_PRI },
+ { "rr", SCHED_RR, RT_DEFAULT_PRI },
+ { "fifo", SCHED_FIFO, RT_DEFAULT_PRI },
+ { NULL, 0, DEFAULT_PRI }
+};
+
+/*
+ * The default tracer will be the first on this list that is supported by the
+ * currently running Linux kernel.
+ */
+static const char * const relevant_tracers[] = {
+ "preemptirqsoff",
+ "preemptoff",
+ "irqsoff",
+ "wakeup",
+ "wakeup_rt",
+ "wakeup_dl",
+ NULL
+};
+
+/* This is the list of tracers for which random sleep makes sense */
+static const char * const random_tracers[] = {
+ "preemptirqsoff",
+ "preemptoff",
+ "irqsoff",
+ NULL
+};
+
+static const char *current_tracer;
+static bool force_tracer;
+
+struct ftrace_state {
+ char *tracer;
+ char *thresh;
+ bool opt[OPTIDX_NR];
+ bool opt_valid[OPTIDX_NR];
+ pthread_mutex_t mutex;
+};
+
+struct entry {
+ int ticket;
+ int ticket_completed_ref;
+};
+
+struct print_state {
+ int ticket_counter;
+ int ticket_completed;
+ pthread_mutex_t mutex;
+ pthread_cond_t cond;
+ int cnt;
+ pthread_mutex_t cnt_mutex;
+};
+
+struct short_msg {
+ char buf[160];
+ int len;
+};
+
+static struct print_state printstate;
+static struct ftrace_state save_state;
+volatile sig_atomic_t signal_flag;
+
+#define PROB_TABLE_MAX_SIZE (1000)
+
+int probabilities[PROB_TABLE_MAX_SIZE];
+
+struct sleep_table {
+ int *table;
+ int size;
+ pthread_mutex_t mutex;
+};
+
+static struct sleep_table sleeptable;
+
+#define QUEUE_SIZE (10)
+
+struct queue {
+ struct entry entries[QUEUE_SIZE];
+ int next_prod_idx;
+ int next_cons_idx;
+ pthread_mutex_t mutex;
+ pthread_cond_t cond;
+};
+
+#define MAX_THREADS (40)
+
+struct queue printqueue;
+pthread_t printthread[MAX_THREADS];
+pthread_mutex_t print_mtx;
+#define PRINT_BUFFER_SIZE (16 * 1024 * 1024)
+
+static void cleanup_exit(int status);
+static int set_trace_opt(const char *opt, bool value);
+
+static __always_inline void *malloc_or_die(size_t size)
+{
+ void *ptr = malloc(size);
+
+ if (unlikely(ptr == NULL)) {
+ warn("malloc() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+ return ptr;
+}
+
+static __always_inline void *malloc_or_die_nocleanup(size_t size)
+{
+ void *ptr = malloc(size);
+
+ if (unlikely(ptr == NULL))
+ err(0, "malloc() failed");
+ return ptr;
+}
+
+static __always_inline void write_or_die(int fd, const char *buf, size_t count)
+{
+ ssize_t r;
+
+ do {
+ r = write(fd, buf, count);
+ if (unlikely(r < 0)) {
+ if (errno == EINTR)
+ continue;
+ warn("write() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+ count -= r;
+ buf += r;
+ } while (count > 0);
+}
+
+static __always_inline void clock_gettime_or_die(clockid_t clk_id,
+ struct timespec *tp)
+{
+ int r = clock_gettime(clk_id, tp);
+
+ if (unlikely(r != 0))
+ err(EXIT_FAILURE, "clock_gettime() failed");
+}
+
+static __always_inline void sigemptyset_or_die(sigset_t *s)
+{
+ if (unlikely(sigemptyset(s) != 0)) {
+ warn("sigemptyset() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+}
+
+static __always_inline void sigaddset_or_die(sigset_t *s, int signum)
+{
+ if (unlikely(sigaddset(s, signum) != 0)) {
+ warn("sigemptyset() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+}
+
+static __always_inline void sigaction_or_die(int signum,
+ const struct sigaction *act,
+ struct sigaction *oldact)
+{
+ if (unlikely(sigaction(signum, act, oldact) != 0)) {
+ warn("sigaction() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+}
+
+static void open_stdout(void)
+{
+ if (setvbuf(stdout, NULL, _IONBF, 0) != 0)
+ err(EXIT_FAILURE, "setvbuf() failed");
+ fd_stdout = fileno(stdout);
+ if (fd_stdout < 0)
+ err(EXIT_FAILURE, "fileno() failed");
+}
+
+/*
+ * It's not worth it to call cleanup_exit() from mutex functions because
+ * cleanup_exit() uses mutexes.
+ */
+static __always_inline void mutex_lock(pthread_mutex_t *mtx)
+{
+ errno = pthread_mutex_lock(mtx);
+ if (unlikely(errno))
+ err(EXIT_FAILURE, "pthread_mutex_lock() failed");
+}
+
+
+static __always_inline void mutex_unlock(pthread_mutex_t *mtx)
+{
+ errno = pthread_mutex_unlock(mtx);
+ if (unlikely(errno))
+ err(EXIT_FAILURE, "pthread_mutex_unlock() failed");
+}
+
+static __always_inline void cond_signal(pthread_cond_t *cond)
+{
+ errno = pthread_cond_signal(cond);
+ if (unlikely(errno))
+ err(EXIT_FAILURE, "pthread_cond_signal() failed");
+}
+
+static __always_inline void cond_wait(pthread_cond_t *restrict cond,
+ pthread_mutex_t *restrict mutex)
+{
+ errno = pthread_cond_wait(cond, mutex);
+ if (unlikely(errno))
+ err(EXIT_FAILURE, "pthread_cond_wait() failed");
+}
+
+static __always_inline void cond_broadcast(pthread_cond_t *cond)
+{
+ errno = pthread_cond_broadcast(cond);
+ if (unlikely(errno))
+ err(EXIT_FAILURE, "pthread_cond_broadcast() failed");
+}
+
+static __always_inline void
+mutex_init(pthread_mutex_t *mutex,
+ const pthread_mutexattr_t *attr)
+{
+ errno = pthread_mutex_init(mutex, attr);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_mutex_init() failed");
+}
+
+static __always_inline void mutexattr_init(pthread_mutexattr_t *attr)
+{
+ errno = pthread_mutexattr_init(attr);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_mutexattr_init() failed");
+}
+
+static __always_inline void mutexattr_destroy(pthread_mutexattr_t *attr)
+{
+ errno = pthread_mutexattr_destroy(attr);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_mutexattr_destroy() failed");
+}
+
+static __always_inline void mutexattr_settype(pthread_mutexattr_t *attr,
+ int type)
+{
+ errno = pthread_mutexattr_settype(attr, type);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_mutexattr_settype() failed");
+}
+
+static __always_inline void condattr_init(pthread_condattr_t *attr)
+{
+ errno = pthread_condattr_init(attr);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_condattr_init() failed");
+}
+
+static __always_inline void condattr_destroy(pthread_condattr_t *attr)
+{
+ errno = pthread_condattr_destroy(attr);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_condattr_destroy() failed");
+}
+
+static __always_inline void condattr_setclock(pthread_condattr_t *attr,
+ clockid_t clock_id)
+{
+ errno = pthread_condattr_setclock(attr, clock_id);
+ if (unlikely(errno))
+ err(EXIT_FAILURE, "pthread_condattr_setclock() failed");
+}
+
+static __always_inline void cond_init(pthread_cond_t *cond,
+ const pthread_condattr_t *attr)
+{
+ errno = pthread_cond_init(cond, attr);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_cond_init() failed");
+}
+
+static __always_inline int
+cond_timedwait(pthread_cond_t *restrict cond,
+ pthread_mutex_t *restrict mutex,
+ const struct timespec *restrict abstime)
+{
+ errno = pthread_cond_timedwait(cond, mutex, abstime);
+ if (errno && errno != ETIMEDOUT)
+ err(EXIT_FAILURE, "pthread_cond_timedwait() failed");
+ return errno;
+}
+
+static void init_printstate(void)
+{
+ pthread_condattr_t cattr;
+
+ printstate.ticket_counter = 0;
+ printstate.ticket_completed = 0;
+ printstate.cnt = 0;
+
+ mutex_init(&printstate.mutex, NULL);
+
+ condattr_init(&cattr);
+ condattr_setclock(&cattr, CLOCK_MONOTONIC);
+ cond_init(&printstate.cond, &cattr);
+ condattr_destroy(&cattr);
+}
+
+static void init_print_mtx(void)
+{
+ pthread_mutexattr_t mattr;
+
+ mutexattr_init(&mattr);
+ mutexattr_settype(&mattr, PTHREAD_MUTEX_RECURSIVE);
+ mutex_init(&print_mtx, &mattr);
+ mutexattr_destroy(&mattr);
+
+}
+
+static void signal_blocking(int how)
+{
+ sigset_t s;
+
+ sigemptyset_or_die(&s);
+ sigaddset_or_die(&s, SIGHUP);
+ sigaddset_or_die(&s, SIGTERM);
+ sigaddset_or_die(&s, SIGINT);
+
+ errno = pthread_sigmask(how, &s, NULL);
+ if (unlikely(errno)) {
+ warn("pthread_sigmask() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+}
+
+static void signal_handler(int num)
+{
+ signal_flag = num;
+}
+
+static void setup_sig_handler(void)
+{
+ struct sigaction sa;
+
+ memset(&sa, 0, sizeof(sa));
+ sa.sa_handler = signal_handler;
+
+ sigaction_or_die(SIGHUP, &sa, NULL);
+ sigaction_or_die(SIGTERM, &sa, NULL);
+ sigaction_or_die(SIGINT, &sa, NULL);
+}
+
+static void process_signal(int signal)
+{
+ char *name;
+
+ name = strsignal(signal);
+ if (name == NULL)
+ printf("Received signal %d\n", signal);
+ else
+ printf("Received signal %d (%s)\n", signal, name);
+ cleanup_exit(EXIT_SUCCESS);
+}
+
+static __always_inline void check_signals(void)
+{
+ int signal = signal_flag;
+
+ if (unlikely(signal))
+ process_signal(signal);
+}
+
+static __always_inline void get_time_in_future(struct timespec *future,
+ long time_us)
+{
+ long nsec;
+
+ clock_gettime_or_die(CLOCK_MONOTONIC, future);
+ future->tv_sec += time_us / USEC_PER_SEC;
+ nsec = future->tv_nsec + (time_us * NSEC_PER_USEC) % NSEC_PER_SEC;
+ if (nsec >= NSEC_PER_SEC) {
+ future->tv_nsec = nsec % NSEC_PER_SEC;
+ future->tv_sec += 1;
+ }
+}
+
+static __always_inline bool time_has_passed(const struct timespec *time)
+{
+ struct timespec now;
+
+ clock_gettime_or_die(CLOCK_MONOTONIC, &now);
+ if (now.tv_sec > time->tv_sec)
+ return true;
+ if (now.tv_sec < time->tv_sec)
+ return false;
+ return (now.tv_nsec >= time->tv_nsec);
+}
+
+static bool mutex_trylock_limit(pthread_mutex_t *mutex, int time_ms)
+{
+ long time_us = time_ms * USEC_PER_MSEC;
+ struct timespec limit;
+
+ get_time_in_future(&limit, time_us);
+ do {
+ errno = pthread_mutex_trylock(mutex);
+ if (errno && errno != EBUSY)
+ err(EXIT_FAILURE, "pthread_mutex_trylock() failed");
+ } while (errno && !time_has_passed(&limit));
+ return errno == 0;
+}
+
+static void restore_trace_opts(const struct ftrace_state *state,
+ const bool *cur)
+{
+ int i;
+ int r;
+
+ for (i = 0; i < OPTIDX_NR; i++)
+ if (state->opt_valid[i] && state->opt[i] != cur[i]) {
+ r = set_trace_opt(optstr[i], state->opt[i]);
+ if (r < 0)
+ warnx("Failed to restore the %s option to %s",
+ optstr[i], bool2str(state->opt[i]));
+ else if (verbose_ftrace())
+ printf("Restored the %s option in %s to %s\n",
+ optstr[i], TR_OPTIONS,
+ bool2str(state->opt[i]));
+ }
+}
+
+static char *read_file(const char *file, enum errhandling h)
+{
+ int psize;
+ char *r;
+ static const char *emsg = "Failed to read the %s file";
+
+ r = tracefs_instance_file_read(NULL, file, &psize);
+ if (!r) {
+ if (h) {
+ warn(emsg, file);
+ if (h == ERR_CLEANUP)
+ cleanup_exit(EXIT_FAILURE);
+ } else
+ errx(EXIT_FAILURE, emsg, file);
+ }
+
+ if (r && r[psize - 1] == '\n')
+ r[psize - 1] = '\0';
+ return r;
+}
+
+static void restore_file(const char *file, char **saved, const char *cur)
+{
+ if (*saved && was_changed(*saved, cur)) {
+ if (tracefs_instance_file_write(NULL, file, *saved) < 0)
+ warnx("Failed to restore %s to %s!", file, *saved);
+ else if (verbose_ftrace())
+ printf("Restored %s to %s\n", file, *saved);
+ free(*saved);
+ *saved = NULL;
+ }
+}
+
+static void restore_ftrace(void)
+{
+ mutex_lock(&save_state.mutex);
+
+ restore_file(TR_CURRENT, &save_state.tracer, current_tracer);
+ restore_file(TR_THRESH, &save_state.thresh, threshold);
+ restore_trace_opts(&save_state, use_options);
+
+ mutex_unlock(&save_state.mutex);
+}
+
+static void cleanup_exit(int status)
+{
+ char *maxlat;
+
+ if (!setup_ftrace)
+ exit(status);
+
+ /*
+ * We try the print_mtx for 1 sec in order to avoid garbled
+ * output if possible, but if it cannot be obtained we proceed anyway.
+ */
+ mutex_trylock_limit(&print_mtx, TRY_PRINTMUTEX_MS);
+
+ maxlat = read_file(TR_MAXLAT, ERR_WARN);
+ if (maxlat) {
+ printf("The maximum detected latency was: %sus\n", maxlat);
+ free(maxlat);
+ }
+
+ restore_ftrace();
+ /*
+ * We do not need to unlock the print_mtx here because we will exit at
+ * the end of this function. Unlocking print_mtx causes problems if a
+ * print thread happens to be waiting for the mutex because we have
+ * just changed the ftrace settings to the original and thus the
+ * print thread would output incorrect data from ftrace.
+ */
+ exit(status);
+}
+
+static void init_save_state(void)
+{
+ pthread_mutexattr_t mattr;
+
+ mutexattr_init(&mattr);
+ mutexattr_settype(&mattr, PTHREAD_MUTEX_RECURSIVE);
+ mutex_init(&save_state.mutex, &mattr);
+ mutexattr_destroy(&mattr);
+
+ save_state.tracer = NULL;
+ save_state.thresh = NULL;
+ save_state.opt_valid[OPTIDX_FUNC_TR] = false;
+ save_state.opt_valid[OPTIDX_DISP_GR] = false;
+}
+
+static int printstate_next_ticket(struct entry *req)
+{
+ int r;
+
+ r = ++(printstate.ticket_counter);
+ req->ticket = r;
+ req->ticket_completed_ref = printstate.ticket_completed;
+ cond_broadcast(&printstate.cond);
+ return r;
+}
+
+static __always_inline
+void printstate_mark_req_completed(const struct entry *req)
+{
+ if (req->ticket > printstate.ticket_completed)
+ printstate.ticket_completed = req->ticket;
+}
+
+static __always_inline
+bool printstate_has_new_req_arrived(const struct entry *req)
+{
+ return (printstate.ticket_counter != req->ticket);
+}
+
+static __always_inline int printstate_cnt_inc(void)
+{
+ int value;
+
+ mutex_lock(&printstate.cnt_mutex);
+ value = ++printstate.cnt;
+ mutex_unlock(&printstate.cnt_mutex);
+ return value;
+}
+
+static __always_inline int printstate_cnt_dec(void)
+{
+ int value;
+
+ mutex_lock(&printstate.cnt_mutex);
+ value = --printstate.cnt;
+ mutex_unlock(&printstate.cnt_mutex);
+ return value;
+}
+
+static __always_inline int printstate_cnt_read(void)
+{
+ int value;
+
+ mutex_lock(&printstate.cnt_mutex);
+ value = printstate.cnt;
+ mutex_unlock(&printstate.cnt_mutex);
+ return value;
+}
+
+static __always_inline
+bool prev_req_won_race(const struct entry *req)
+{
+ return (printstate.ticket_completed != req->ticket_completed_ref);
+}
+
+static void sleeptable_resize(int size, bool printout, struct short_msg *msg)
+{
+ int bytes;
+
+ if (printout) {
+ msg->len = 0;
+ if (unlikely(size > PROB_TABLE_MAX_SIZE))
+ bytes = snprintf(msg->buf, sizeof(msg->buf),
+"Cannot increase probability table to %d (maximum size reached)\n", size);
+ else
+ bytes = snprintf(msg->buf, sizeof(msg->buf),
+"Increasing probability table to %d\n", size);
+ if (bytes < 0)
+ warn("snprintf() failed");
+ else
+ msg->len = bytes;
+ }
+
+ if (unlikely(size < 0)) {
+ /* Should never happen */
+ warnx("Bad program state at %s:%d", __FILE__, __LINE__);
+ cleanup_exit(EXIT_FAILURE);
+ return;
+ }
+ sleeptable.size = size;
+ sleeptable.table = &probabilities[PROB_TABLE_MAX_SIZE - size];
+}
+
+static void init_probabilities(void)
+{
+ int i;
+ int j = 1000;
+
+ for (i = 0; i < PROB_TABLE_MAX_SIZE; i++) {
+ probabilities[i] = 1000 / j;
+ j--;
+ }
+ mutex_init(&sleeptable.mutex, NULL);
+}
+
+static int table_get_probability(const struct entry *req,
+ struct short_msg *msg)
+{
+ int diff = req->ticket - req->ticket_completed_ref;
+ int rval = 0;
+
+ msg->len = 0;
+ diff--;
+ /* Should never happen...*/
+ if (unlikely(diff < 0)) {
+ warnx("Programmer assumption error at %s:%d\n", __FILE__,
+ __LINE__);
+ cleanup_exit(EXIT_FAILURE);
+ }
+ mutex_lock(&sleeptable.mutex);
+ if (diff >= (sleeptable.size - 1)) {
+ rval = sleeptable.table[sleeptable.size - 1];
+ sleeptable_resize(sleeptable.size + 1, verbose_sizechange(),
+ msg);
+ } else {
+ rval = sleeptable.table[diff];
+ }
+ mutex_unlock(&sleeptable.mutex);
+ return rval;
+}
+
+static void init_queue(struct queue *q)
+{
+ q->next_prod_idx = 0;
+ q->next_cons_idx = 0;
+ mutex_init(&q->mutex, NULL);
+ errno = pthread_cond_init(&q->cond, NULL);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_cond_init() failed");
+}
+
+static __always_inline int queue_len(const struct queue *q)
+{
+ if (q->next_prod_idx >= q->next_cons_idx)
+ return q->next_prod_idx - q->next_cons_idx;
+ else
+ return QUEUE_SIZE - q->next_cons_idx + q->next_prod_idx;
+}
+
+static __always_inline int queue_nr_free(const struct queue *q)
+{
+ int nr_free = QUEUE_SIZE - queue_len(q);
+
+ /*
+ * If there is only one slot left we will anyway lie and claim that the
+ * queue is full because adding an element will make it appear empty
+ */
+ if (nr_free == 1)
+ nr_free = 0;
+ return nr_free;
+}
+
+static __always_inline void queue_idx_inc(int *idx)
+{
+ *idx = (*idx + 1) % QUEUE_SIZE;
+}
+
+static __always_inline void queue_push_to_back(struct queue *q,
+ const struct entry *e)
+{
+ q->entries[q->next_prod_idx] = *e;
+ queue_idx_inc(&q->next_prod_idx);
+}
+
+static __always_inline struct entry queue_pop_from_front(struct queue *q)
+{
+ struct entry e = q->entries[q->next_cons_idx];
+
+ queue_idx_inc(&q->next_cons_idx);
+ return e;
+}
+
+static __always_inline void queue_cond_signal(struct queue *q)
+{
+ cond_signal(&q->cond);
+}
+
+static __always_inline void queue_cond_wait(struct queue *q)
+{
+ cond_wait(&q->cond, &q->mutex);
+}
+
+static __always_inline int queue_try_to_add_entry(struct queue *q,
+ const struct entry *e)
+{
+ int r = 0;
+
+ mutex_lock(&q->mutex);
+ if (queue_nr_free(q) > 0) {
+ queue_push_to_back(q, e);
+ cond_signal(&q->cond);
+ } else
+ r = -1;
+ mutex_unlock(&q->mutex);
+ return r;
+}
+
+static struct entry queue_wait_for_entry(struct queue *q)
+{
+ struct entry e;
+
+ mutex_lock(&q->mutex);
+ while (true) {
+ if (queue_len(&printqueue) > 0) {
+ e = queue_pop_from_front(q);
+ break;
+ }
+ queue_cond_wait(q);
+ }
+ mutex_unlock(&q->mutex);
+
+ return e;
+}
+
+static const struct policy *policy_from_name(const char *name)
+{
+ const struct policy *p = &policies[0];
+
+ while (p->name != NULL) {
+ if (!strcmp(name, p->name))
+ return p;
+ p++;
+ }
+ return NULL;
+}
+
+static const char *policy_name(int policy)
+{
+ const struct policy *p = &policies[0];
+ static const char *rval = "unknown";
+
+ while (p->name != NULL) {
+ if (p->policy == policy)
+ return p->name;
+ p++;
+ }
+ return rval;
+}
+
+static bool is_relevant_tracer(const char *name)
+{
+ unsigned int i;
+
+ for (i = 0; relevant_tracers[i]; i++)
+ if (!strcmp(name, relevant_tracers[i]))
+ return true;
+ return false;
+}
+
+static bool random_makes_sense(const char *name)
+{
+ unsigned int i;
+
+ for (i = 0; random_tracers[i]; i++)
+ if (!strcmp(name, random_tracers[i]))
+ return true;
+ return false;
+}
+
+static void show_available(void)
+{
+ char **tracers;
+ int found = 0;
+ int i;
+
+ tracers = tracefs_tracers(NULL);
+ for (i = 0; tracers && tracers[i]; i++) {
+ if (is_relevant_tracer(tracers[i]))
+ found++;
+ }
+
+ if (!tracers) {
+ warnx(no_tracer_msg);
+ return;
+ }
+
+ if (!found) {
+ warnx(no_latency_tr_msg);
+ tracefs_list_free(tracers);
+ return;
+ }
+
+ printf("The following latency tracers are available on your system:\n");
+ for (i = 0; tracers[i]; i++) {
+ if (is_relevant_tracer(tracers[i]))
+ printf("%s\n", tracers[i]);
+ }
+ tracefs_list_free(tracers);
+}
+
+static bool tracer_valid(const char *name, bool *notracer)
+{
+ char **tracers;
+ int i;
+ bool rval = false;
+
+ *notracer = false;
+ tracers = tracefs_tracers(NULL);
+ if (!tracers) {
+ *notracer = true;
+ return false;
+ }
+ for (i = 0; tracers[i]; i++)
+ if (!strcmp(tracers[i], name)) {
+ rval = true;
+ break;
+ }
+ tracefs_list_free(tracers);
+ return rval;
+}
+
+static const char *find_default_tracer(void)
+{
+ int i;
+ bool notracer;
+ bool valid;
+
+ for (i = 0; relevant_tracers[i]; i++) {
+ valid = tracer_valid(relevant_tracers[i], &notracer);
+ if (notracer)
+ errx(EXIT_FAILURE, no_tracer_msg);
+ if (valid)
+ return relevant_tracers[i];
+ }
+ return NULL;
+}
+
+static bool toss_coin(struct drand48_data *buffer, unsigned int prob)
+{
+ long r;
+
+ if (unlikely(lrand48_r(buffer, &r))) {
+ warnx("lrand48_r() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+ r = r % 1000L;
+ if (r < prob)
+ return true;
+ else
+ return false;
+}
+
+
+static long go_to_sleep(const struct entry *req)
+{
+ struct timespec future;
+ long delay = sleep_time;
+
+ get_time_in_future(&future, delay);
+
+ mutex_lock(&printstate.mutex);
+ while (!printstate_has_new_req_arrived(req)) {
+ cond_timedwait(&printstate.cond, &printstate.mutex, &future);
+ if (time_has_passed(&future))
+ break;
+ }
+
+ if (printstate_has_new_req_arrived(req))
+ delay = -1;
+ mutex_unlock(&printstate.mutex);
+
+ return delay;
+}
+
+
+static void set_priority(void)
+{
+ int r;
+ pid_t pid;
+ struct sched_param param;
+
+ memset(&param, 0, sizeof(param));
+ param.sched_priority = sched_pri;
+
+ pid = getpid();
+ r = sched_setscheduler(pid, sched_policy, &param);
+
+ if (r != 0)
+ err(EXIT_FAILURE, "sched_setscheduler() failed");
+}
+
+pid_t latency_collector_gettid(void)
+{
+ return (pid_t) syscall(__NR_gettid);
+}
+
+static void print_priority(void)
+{
+ pid_t tid;
+ int policy;
+ int r;
+ struct sched_param param;
+
+ tid = latency_collector_gettid();
+ r = pthread_getschedparam(pthread_self(), &policy, &param);
+ if (r != 0) {
+ warn("pthread_getschedparam() failed");
+ cleanup_exit(EXIT_FAILURE);
+ }
+ mutex_lock(&print_mtx);
+ printf("Thread %d runs with scheduling policy %s and priority %d\n",
+ tid, policy_name(policy), param.sched_priority);
+ mutex_unlock(&print_mtx);
+}
+
+static __always_inline
+void __print_skipmessage(const struct short_msg *resize_msg,
+ const struct timespec *timestamp, char *buffer,
+ size_t bufspace, const struct entry *req, bool excuse,
+ const char *str)
+{
+ ssize_t bytes = 0;
+ char *p = &buffer[0];
+ long us, sec;
+ int r;
+
+ sec = timestamp->tv_sec;
+ us = timestamp->tv_nsec / 1000;
+
+ if (resize_msg != NULL && resize_msg->len > 0) {
+ strncpy(p, resize_msg->buf, resize_msg->len);
+ bytes += resize_msg->len;
+ p += resize_msg->len;
+ bufspace -= resize_msg->len;
+ }
+
+ if (excuse)
+ r = snprintf(p, bufspace,
+"%ld.%06ld Latency %d printout skipped due to %s\n",
+ sec, us, req->ticket, str);
+ else
+ r = snprintf(p, bufspace, "%ld.%06ld Latency %d detected\n",
+ sec, us, req->ticket);
+
+ if (r < 0)
+ warn("snprintf() failed");
+ else
+ bytes += r;
+
+ /* These prints could happen concurrently */
+ mutex_lock(&print_mtx);
+ write_or_die(fd_stdout, buffer, bytes);
+ mutex_unlock(&print_mtx);
+}
+
+static void print_skipmessage(const struct short_msg *resize_msg,
+ const struct timespec *timestamp, char *buffer,
+ size_t bufspace, const struct entry *req,
+ bool excuse)
+{
+ __print_skipmessage(resize_msg, timestamp, buffer, bufspace, req,
+ excuse, "random delay");
+}
+
+static void print_lostmessage(const struct timespec *timestamp, char *buffer,
+ size_t bufspace, const struct entry *req,
+ const char *reason)
+{
+ __print_skipmessage(NULL, timestamp, buffer, bufspace, req, true,
+ reason);
+}
+
+static void print_tracefile(const struct short_msg *resize_msg,
+ const struct timespec *timestamp, char *buffer,
+ size_t bufspace, long slept,
+ const struct entry *req)
+{
+ static const int reserve = 256;
+ char *p = &buffer[0];
+ ssize_t bytes = 0;
+ ssize_t bytes_tot = 0;
+ long us, sec;
+ long slept_ms;
+ int trace_fd;
+
+ /* Save some space for the final string and final null char */
+ bufspace = bufspace - reserve - 1;
+
+ if (resize_msg != NULL && resize_msg->len > 0) {
+ bytes = resize_msg->len;
+ strncpy(p, resize_msg->buf, bytes);
+ bytes_tot += bytes;
+ p += bytes;
+ bufspace -= bytes;
+ }
+
+ trace_fd = open(debug_tracefile, O_RDONLY);
+
+ if (trace_fd < 0) {
+ warn("open() failed on %s", debug_tracefile);
+ return;
+ }
+
+ sec = timestamp->tv_sec;
+ us = timestamp->tv_nsec / 1000;
+
+ if (slept != 0) {
+ slept_ms = slept / 1000;
+ bytes = snprintf(p, bufspace,
+"%ld.%06ld Latency %d randomly sleep for %ld ms before print\n",
+ sec, us, req->ticket, slept_ms);
+ } else {
+ bytes = snprintf(p, bufspace,
+ "%ld.%06ld Latency %d immediate print\n", sec,
+ us, req->ticket);
+ }
+
+ if (bytes < 0) {
+ warn("snprintf() failed");
+ return;
+ }
+ p += bytes;
+ bufspace -= bytes;
+ bytes_tot += bytes;
+
+ bytes = snprintf(p, bufspace,
+">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> BEGIN <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n"
+ );
+
+ if (bytes < 0) {
+ warn("snprintf() failed");
+ return;
+ }
+
+ p += bytes;
+ bufspace -= bytes;
+ bytes_tot += bytes;
+
+ do {
+ bytes = read(trace_fd, p, bufspace);
+ if (bytes < 0) {
+ if (errno == EINTR)
+ continue;
+ warn("read() failed on %s", debug_tracefile);
+ if (unlikely(close(trace_fd) != 0))
+ warn("close() failed on %s", debug_tracefile);
+ return;
+ }
+ if (bytes == 0)
+ break;
+ p += bytes;
+ bufspace -= bytes;
+ bytes_tot += bytes;
+ } while (true);
+
+ if (unlikely(close(trace_fd) != 0))
+ warn("close() failed on %s", debug_tracefile);
+
+ printstate_cnt_dec();
+ /* Add the reserve space back to the budget for the final string */
+ bufspace += reserve;
+
+ bytes = snprintf(p, bufspace,
+ ">>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> END <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<\n\n");
+
+ if (bytes < 0) {
+ warn("snprintf() failed");
+ return;
+ }
+
+ bytes_tot += bytes;
+
+ /* These prints could happen concurrently */
+ mutex_lock(&print_mtx);
+ write_or_die(fd_stdout, buffer, bytes_tot);
+ mutex_unlock(&print_mtx);
+}
+
+static char *get_no_opt(const char *opt)
+{
+ char *no_opt;
+ int s;
+
+ s = strlen(opt) + strlen(OPT_NO_PREFIX) + 1;
+ /* We may be called from cleanup_exit() via set_trace_opt() */
+ no_opt = malloc_or_die_nocleanup(s);
+ strcpy(no_opt, OPT_NO_PREFIX);
+ strcat(no_opt, opt);
+ return no_opt;
+}
+
+static char *find_next_optstr(const char *allopt, const char **next)
+{
+ const char *begin;
+ const char *end;
+ char *r;
+ int s = 0;
+
+ if (allopt == NULL)
+ return NULL;
+
+ for (begin = allopt; *begin != '\0'; begin++) {
+ if (isgraph(*begin))
+ break;
+ }
+
+ if (*begin == '\0')
+ return NULL;
+
+ for (end = begin; *end != '\0' && isgraph(*end); end++)
+ s++;
+
+ r = malloc_or_die_nocleanup(s + 1);
+ strncpy(r, begin, s);
+ r[s] = '\0';
+ *next = begin + s;
+ return r;
+}
+
+static bool get_trace_opt(const char *allopt, const char *opt, bool *found)
+{
+ *found = false;
+ char *no_opt;
+ char *str;
+ const char *next = allopt;
+ bool rval = false;
+
+ no_opt = get_no_opt(opt);
+
+ do {
+ str = find_next_optstr(next, &next);
+ if (str == NULL)
+ break;
+ if (!strcmp(str, opt)) {
+ *found = true;
+ rval = true;
+ free(str);
+ break;
+ }
+ if (!strcmp(str, no_opt)) {
+ *found = true;
+ rval = false;
+ free(str);
+ break;
+ }
+ free(str);
+ } while (true);
+ free(no_opt);
+
+ return rval;
+}
+
+static int set_trace_opt(const char *opt, bool value)
+{
+ char *str;
+ int r;
+
+ if (value)
+ str = strdup(opt);
+ else
+ str = get_no_opt(opt);
+
+ r = tracefs_instance_file_write(NULL, TR_OPTIONS, str);
+ free(str);
+ return r;
+}
+
+void save_trace_opts(struct ftrace_state *state)
+{
+ char *allopt;
+ int psize;
+ int i;
+
+ allopt = tracefs_instance_file_read(NULL, TR_OPTIONS, &psize);
+ if (!allopt)
+ errx(EXIT_FAILURE, "Failed to read the %s file\n", TR_OPTIONS);
+
+ for (i = 0; i < OPTIDX_NR; i++)
+ state->opt[i] = get_trace_opt(allopt, optstr[i],
+ &state->opt_valid[i]);
+
+ free(allopt);
+}
+
+static void write_file(const char *file, const char *cur, const char *new,
+ enum errhandling h)
+{
+ int r;
+ static const char *emsg = "Failed to write to the %s file!";
+
+ /* Do nothing if we now that the current and new value are equal */
+ if (cur && !needs_change(cur, new))
+ return;
+
+ r = tracefs_instance_file_write(NULL, file, new);
+ if (r < 0) {
+ if (h) {
+ warnx(emsg, file);
+ if (h == ERR_CLEANUP)
+ cleanup_exit(EXIT_FAILURE);
+ } else
+ errx(EXIT_FAILURE, emsg, file);
+ }
+ if (verbose_ftrace()) {
+ mutex_lock(&print_mtx);
+ printf("%s was set to %s\n", file, new);
+ mutex_unlock(&print_mtx);
+ }
+}
+
+static void reset_max_latency(void)
+{
+ write_file(TR_MAXLAT, NULL, "0", ERR_CLEANUP);
+}
+
+static void save_and_disable_tracer(void)
+{
+ char *orig_th;
+ char *tracer;
+ bool need_nop = false;
+
+ mutex_lock(&save_state.mutex);
+
+ save_trace_opts(&save_state);
+ tracer = read_file(TR_CURRENT, ERR_EXIT);
+ orig_th = read_file(TR_THRESH, ERR_EXIT);
+
+ if (needs_change(tracer, NOP_TRACER)) {
+ mutex_lock(&print_mtx);
+ if (force_tracer) {
+ printf(
+ "The %s tracer is already in use but proceeding anyway!\n",
+ tracer);
+ } else {
+ printf(
+ "The %s tracer is already in use, cowardly bailing out!\n"
+ "This could indicate that another program or instance is tracing.\n"
+ "Use the -F [--force] option to disregard the current tracer.\n", tracer);
+ exit(0);
+ }
+ mutex_unlock(&print_mtx);
+ need_nop = true;
+ }
+
+ save_state.tracer = tracer;
+ save_state.thresh = orig_th;
+
+ if (need_nop)
+ write_file(TR_CURRENT, NULL, NOP_TRACER, ERR_EXIT);
+
+ mutex_unlock(&save_state.mutex);
+}
+
+void set_trace_opts(struct ftrace_state *state, bool *new)
+{
+ int i;
+ int r;
+
+ /*
+ * We only set options if we earlier detected that the option exists in
+ * the trace_options file and that the wanted setting is different from
+ * the one we saw in save_and_disable_tracer()
+ */
+ for (i = 0; i < OPTIDX_NR; i++)
+ if (state->opt_valid[i] &&
+ state->opt[i] != new[i]) {
+ r = set_trace_opt(optstr[i], new[i]);
+ if (r < 0) {
+ warnx("Failed to set the %s option to %s",
+ optstr[i], bool2str(new[i]));
+ cleanup_exit(EXIT_FAILURE);
+ }
+ if (verbose_ftrace()) {
+ mutex_lock(&print_mtx);
+ printf("%s in %s was set to %s\n", optstr[i],
+ TR_OPTIONS, bool2str(new[i]));
+ mutex_unlock(&print_mtx);
+ }
+ }
+}
+
+static void enable_tracer(void)
+{
+ mutex_lock(&save_state.mutex);
+ set_trace_opts(&save_state, use_options);
+
+ write_file(TR_THRESH, save_state.thresh, threshold, ERR_CLEANUP);
+ write_file(TR_CURRENT, NOP_TRACER, current_tracer, ERR_CLEANUP);
+
+ mutex_unlock(&save_state.mutex);
+}
+
+static void tracing_loop(void)
+{
+ int ifd = inotify_init();
+ int wd;
+ const ssize_t bufsize = sizeof(inotify_buffer);
+ const ssize_t istructsize = sizeof(struct inotify_event);
+ char *buf = &inotify_buffer[0];
+ ssize_t nr_read;
+ char *p;
+ int modified;
+ struct inotify_event *event;
+ struct entry req;
+ char *buffer;
+ const size_t bufspace = PRINT_BUFFER_SIZE;
+ struct timespec timestamp;
+
+ print_priority();
+
+ buffer = malloc_or_die(bufspace);
+
+ if (ifd < 0)
+ err(EXIT_FAILURE, "inotify_init() failed!");
+
+
+ if (setup_ftrace) {
+ /*
+ * We must disable the tracer before resetting the max_latency
+ */
+ save_and_disable_tracer();
+ /*
+ * We must reset the max_latency before the inotify_add_watch()
+ * call.
+ */
+ reset_max_latency();
+ }
+
+ wd = inotify_add_watch(ifd, debug_maxlat, IN_MODIFY);
+ if (wd < 0)
+ err(EXIT_FAILURE, "inotify_add_watch() failed!");
+
+ if (setup_ftrace)
+ enable_tracer();
+
+ signal_blocking(SIG_UNBLOCK);
+
+ while (true) {
+ modified = 0;
+ check_signals();
+ nr_read = read(ifd, buf, bufsize);
+ check_signals();
+ if (nr_read < 0) {
+ if (errno == EINTR)
+ continue;
+ warn("read() failed on inotify fd!");
+ cleanup_exit(EXIT_FAILURE);
+ }
+ if (nr_read == bufsize)
+ warnx("inotify() buffer filled, skipping events");
+ if (nr_read < istructsize) {
+ warnx("read() returned too few bytes on inotify fd");
+ cleanup_exit(EXIT_FAILURE);
+ }
+
+ for (p = buf; p < buf + nr_read;) {
+ event = (struct inotify_event *) p;
+ if ((event->mask & IN_MODIFY) != 0)
+ modified++;
+ p += istructsize + event->len;
+ }
+ while (modified > 0) {
+ check_signals();
+ mutex_lock(&printstate.mutex);
+ check_signals();
+ printstate_next_ticket(&req);
+ if (printstate_cnt_read() > 0) {
+ printstate_mark_req_completed(&req);
+ mutex_unlock(&printstate.mutex);
+ if (verbose_lostevent()) {
+ clock_gettime_or_die(CLOCK_MONOTONIC,
+ &timestamp);
+ print_lostmessage(&timestamp, buffer,
+ bufspace, &req,
+ "inotify loop");
+ }
+ break;
+ }
+ mutex_unlock(&printstate.mutex);
+ if (queue_try_to_add_entry(&printqueue, &req) != 0) {
+ /* These prints could happen concurrently */
+ check_signals();
+ mutex_lock(&print_mtx);
+ check_signals();
+ write_or_die(fd_stdout, queue_full_warning,
+ strlen(queue_full_warning));
+ mutex_unlock(&print_mtx);
+ }
+ modified--;
+ }
+ }
+}
+
+static void *do_printloop(void *arg)
+{
+ const size_t bufspace = PRINT_BUFFER_SIZE;
+ char *buffer;
+ long *rseed = (long *) arg;
+ struct drand48_data drandbuf;
+ long slept = 0;
+ struct entry req;
+ int prob = 0;
+ struct timespec timestamp;
+ struct short_msg resize_msg;
+
+ print_priority();
+
+ if (srand48_r(*rseed, &drandbuf) != 0) {
+ warn("srand48_r() failed!\n");
+ cleanup_exit(EXIT_FAILURE);
+ }
+
+ buffer = malloc_or_die(bufspace);
+
+ while (true) {
+ req = queue_wait_for_entry(&printqueue);
+ clock_gettime_or_die(CLOCK_MONOTONIC, &timestamp);
+ mutex_lock(&printstate.mutex);
+ if (prev_req_won_race(&req)) {
+ printstate_mark_req_completed(&req);
+ mutex_unlock(&printstate.mutex);
+ if (verbose_lostevent())
+ print_lostmessage(&timestamp, buffer, bufspace,
+ &req, "print loop");
+ continue;
+ }
+ mutex_unlock(&printstate.mutex);
+
+ /*
+ * Toss a coin to decide if we want to sleep before printing
+ * out the backtrace. The reason for this is that opening
+ * /sys/kernel/debug/tracing/trace will cause a blackout of
+ * hundreds of ms, where no latencies will be noted by the
+ * latency tracer. Thus by randomly sleeping we try to avoid
+ * missing traces systematically due to this. With this option
+ * we will sometimes get the first latency, some other times
+ * some of the later ones, in case of closely spaced traces.
+ */
+ if (trace_enable && use_random_sleep) {
+ slept = 0;
+ prob = table_get_probability(&req, &resize_msg);
+ if (!toss_coin(&drandbuf, prob))
+ slept = go_to_sleep(&req);
+ if (slept >= 0) {
+ /* A print is ongoing */
+ printstate_cnt_inc();
+ /*
+ * We will do the printout below so we have to
+ * mark it as completed while we still have the
+ * mutex.
+ */
+ mutex_lock(&printstate.mutex);
+ printstate_mark_req_completed(&req);
+ mutex_unlock(&printstate.mutex);
+ }
+ }
+ if (trace_enable) {
+ /*
+ * slept < 0 means that we detected another
+ * notification in go_to_sleep() above
+ */
+ if (slept >= 0)
+ /*
+ * N.B. printstate_cnt_dec(); will be called
+ * inside print_tracefile()
+ */
+ print_tracefile(&resize_msg, &timestamp, buffer,
+ bufspace, slept, &req);
+ else
+ print_skipmessage(&resize_msg, &timestamp,
+ buffer, bufspace, &req, true);
+ } else {
+ print_skipmessage(&resize_msg, &timestamp, buffer,
+ bufspace, &req, false);
+ }
+ }
+ return NULL;
+}
+
+static void start_printthread(void)
+{
+ unsigned int i;
+ long *seed;
+ int ufd;
+
+ ufd = open(DEV_URANDOM, O_RDONLY);
+ if (nr_threads > MAX_THREADS) {
+ warnx(
+"Number of requested print threads was %d, max number is %d\n",
+ nr_threads, MAX_THREADS);
+ nr_threads = MAX_THREADS;
+ }
+ for (i = 0; i < nr_threads; i++) {
+ seed = malloc_or_die(sizeof(*seed));
+ if (ufd < 0 ||
+ read(ufd, seed, sizeof(*seed)) != sizeof(*seed)) {
+ printf(
+"Warning! Using trivial random number seed, since %s not available\n",
+ DEV_URANDOM);
+ fflush(stdout);
+ *seed = i;
+ }
+ errno = pthread_create(&printthread[i], NULL, do_printloop,
+ seed);
+ if (errno)
+ err(EXIT_FAILURE, "pthread_create()");
+ }
+ if (ufd > 0 && close(ufd) != 0)
+ warn("close() failed");
+}
+
+static void show_usage(void)
+{
+ printf(
+"Usage: %s [OPTION]...\n\n"
+"Collect closely occurring latencies from %s\n"
+"with any of the following tracers: preemptirqsoff, preemptoff, irqsoff, "
+"wakeup,\nwakeup_dl, or wakeup_rt.\n\n"
+
+"The occurrence of a latency is detected by monitoring the file\n"
+"%s with inotify.\n\n"
+
+"The following options are supported:\n\n"
+
+"-l, --list\t\tList the latency tracers that are supported by the\n"
+"\t\t\tcurrently running Linux kernel. If you don't see the\n"
+"\t\t\ttracer that you want, you will probably need to\n"
+"\t\t\tchange your kernel config and build a new kernel.\n\n"
+
+"-t, --tracer TR\t\tUse the tracer TR. The default is to use the first\n"
+"\t\t\ttracer that is supported by the kernel in the following\n"
+"\t\t\torder of precedence:\n\n"
+"\t\t\tpreemptirqsoff\n"
+"\t\t\tpreemptoff\n"
+"\t\t\tirqsoff\n"
+"\t\t\twakeup\n"
+"\t\t\twakeup_rt\n"
+"\t\t\twakeup_dl\n"
+"\n"
+"\t\t\tIf TR is not on the list above, then a warning will be\n"
+"\t\t\tprinted.\n\n"
+
+"-F, --force\t\tProceed even if another ftrace tracer is active. Without\n"
+"\t\t\tthis option, the program will refuse to start tracing if\n"
+"\t\t\tany other tracer than the nop tracer is active.\n\n"
+
+"-s, --threshold TH\tConfigure ftrace to use a threshold of TH microseconds\n"
+"\t\t\tfor the tracer. The default is 0, which means that\n"
+"\t\t\ttracing_max_latency will be used. tracing_max_latency is\n"
+"\t\t\tset to 0 when the program is started and contains the\n"
+"\t\t\tmaximum of the latencies that have been encountered.\n\n"
+
+"-f, --function\t\tEnable the function-trace option in trace_options. With\n"
+"\t\t\tthis option, ftrace will trace the functions that are\n"
+"\t\t\texecuted during a latency, without it we only get the\n"
+"\t\t\tbeginning, end, and backtrace.\n\n"
+
+"-g, --graph\t\tEnable the display-graph option in trace_option. This\n"
+"\t\t\toption causes ftrace to show the graph of how functions\n"
+"\t\t\tare calling other functions.\n\n"
+
+"-c, --policy POL\tRun the program with scheduling policy POL. POL can be\n"
+"\t\t\tother, batch, idle, rr or fifo. The default is rr. When\n"
+"\t\t\tusing rr or fifo, remember that these policies may cause\n"
+"\t\t\tother tasks to experience latencies.\n\n"
+
+"-p, --priority PRI\tRun the program with priority PRI. The acceptable range\n"
+"\t\t\tof PRI depends on the scheduling policy.\n\n"
+
+"-n, --notrace\t\tIf latency is detected, do not print out the content of\n"
+"\t\t\tthe trace file to standard output\n\n"
+
+"-t, --threads NRTHR\tRun NRTHR threads for printing. Default is %d.\n\n"
+
+"-r, --random\t\tArbitrarily sleep a certain amount of time, default\n"
+"\t\t\t%ld ms, before reading the trace file. The\n"
+"\t\t\tprobabilities for sleep are chosen so that the\n"
+"\t\t\tprobability of obtaining any of a cluster of closely\n"
+"\t\t\toccurring latencies are equal, i.e. we will randomly\n"
+"\t\t\tchoose which one we collect from the trace file.\n\n"
+"\t\t\tThis option is probably only useful with the irqsoff,\n"
+"\t\t\tpreemptoff, and preemptirqsoff tracers.\n\n"
+
+"-a, --nrlat NRLAT\tFor the purpose of arbitrary delay, assume that there\n"
+"\t\t\tare no more than NRLAT clustered latencies. If NRLAT\n"
+"\t\t\tlatencies are detected during a run, this value will\n"
+"\t\t\tautomatically be increased to NRLAT + 1 and then to\n"
+"\t\t\tNRLAT + 2 and so on. The default is %d. This option\n"
+"\t\t\timplies -r. We need to know this number in order to\n"
+"\t\t\tbe able to calculate the probabilities of sleeping.\n"
+"\t\t\tSpecifically, the probabilities of not sleeping, i.e. to\n"
+"\t\t\tdo an immediate printout will be:\n\n"
+"\t\t\t1/NRLAT 1/(NRLAT - 1) ... 1/3 1/2 1\n\n"
+"\t\t\tThe probability of sleeping will be:\n\n"
+"\t\t\t1 - P, where P is from the series above\n\n"
+"\t\t\tThis descending probability will cause us to choose\n"
+"\t\t\tan occurrence at random. Observe that the final\n"
+"\t\t\tprobability is 0, it is when we reach this probability\n"
+"\t\t\tthat we increase NRLAT automatically. As an example,\n"
+"\t\t\twith the default value of 2, the probabilities will be:\n\n"
+"\t\t\t1/2 0\n\n"
+"\t\t\tThis means, when a latency is detected we will sleep\n"
+"\t\t\twith 50%% probability. If we ever detect another latency\n"
+"\t\t\tduring the sleep period, then the probability of sleep\n"
+"\t\t\twill be 0%% and the table will be expanded to:\n\n"
+"\t\t\t1/3 1/2 0\n\n"
+
+"-v, --verbose\t\tIncrease the verbosity. If this option is given once,\n"
+"\t\t\tthen print a message every time that the NRLAT value\n"
+"\t\t\tis automatically increased. It also causes a message to\n"
+"\t\t\tbe printed when the ftrace settings are changed. If this\n"
+"\t\t\toption is given at least twice, then also print a\n"
+"\t\t\twarning for lost events.\n\n"
+
+"-u, --time TIME\t\tArbitrarily sleep for a specified time TIME ms before\n"
+"\t\t\tprinting out the trace from the trace file. The default\n"
+"\t\t\tis %ld ms. This option implies -r.\n\n"
+
+"-x, --no-ftrace\t\tDo not configure ftrace. This assume that the user\n"
+"\t\t\tconfigures the ftrace files in sysfs such as\n"
+"\t\t\t/sys/kernel/tracing/current_tracer or equivalent.\n\n"
+
+"-i, --tracefile FILE\tUse FILE as trace file. The default is\n"
+"\t\t\t%s.\n"
+"\t\t\tThis options implies -x\n\n"
+
+"-m, --max-lat FILE\tUse FILE as tracing_max_latency file. The default is\n"
+"\t\t\t%s.\n"
+"\t\t\tThis options implies -x\n\n"
+,
+prg_name, debug_tracefile_dflt, debug_maxlat_dflt, DEFAULT_NR_PRINTER_THREADS,
+SLEEP_TIME_MS_DEFAULT, DEFAULT_TABLE_SIZE, SLEEP_TIME_MS_DEFAULT,
+debug_tracefile_dflt, debug_maxlat_dflt);
+}
+
+static void find_tracefiles(void)
+{
+ debug_tracefile_dflt = tracefs_get_tracing_file("trace");
+ if (debug_tracefile_dflt == NULL) {
+ /* This is needed in show_usage() */
+ debug_tracefile_dflt = DEBUG_NOFILE;
+ }
+
+ debug_maxlat_dflt = tracefs_get_tracing_file("tracing_max_latency");
+ if (debug_maxlat_dflt == NULL) {
+ /* This is needed in show_usage() */
+ debug_maxlat_dflt = DEBUG_NOFILE;
+ }
+
+ debug_tracefile = debug_tracefile_dflt;
+ debug_maxlat = debug_maxlat_dflt;
+}
+
+bool alldigits(const char *s)
+{
+ for (; *s != '\0'; s++)
+ if (!isdigit(*s))
+ return false;
+ return true;
+}
+
+void check_alldigits(const char *optarg, const char *argname)
+{
+ if (!alldigits(optarg))
+ errx(EXIT_FAILURE,
+ "The %s parameter expects a decimal argument\n", argname);
+}
+
+static void scan_arguments(int argc, char *argv[])
+{
+ int c;
+ int i;
+ int option_idx = 0;
+
+ static struct option long_options[] = {
+ { "list", no_argument, 0, 'l' },
+ { "tracer", required_argument, 0, 't' },
+ { "force", no_argument, 0, 'F' },
+ { "threshold", required_argument, 0, 's' },
+ { "function", no_argument, 0, 'f' },
+ { "graph", no_argument, 0, 'g' },
+ { "policy", required_argument, 0, 'c' },
+ { "priority", required_argument, 0, 'p' },
+ { "help", no_argument, 0, 'h' },
+ { "notrace", no_argument, 0, 'n' },
+ { "random", no_argument, 0, 'r' },
+ { "nrlat", required_argument, 0, 'a' },
+ { "threads", required_argument, 0, 'e' },
+ { "time", required_argument, 0, 'u' },
+ { "verbose", no_argument, 0, 'v' },
+ { "no-ftrace", no_argument, 0, 'x' },
+ { "tracefile", required_argument, 0, 'i' },
+ { "max-lat", required_argument, 0, 'm' },
+ { 0, 0, 0, 0 }
+ };
+ const struct policy *p;
+ int max, min;
+ int value;
+ bool notracer, valid;
+
+ /*
+ * We must do this before parsing the arguments because show_usage()
+ * needs to display these.
+ */
+ find_tracefiles();
+
+ while (true) {
+ c = getopt_long(argc, argv, "lt:Fs:fgc:p:hnra:e:u:vxi:m:",
+ long_options, &option_idx);
+ if (c == -1)
+ break;
+
+ switch (c) {
+ case 'l':
+ show_available();
+ exit(0);
+ break;
+ case 't':
+ current_tracer = strdup(optarg);
+ if (!is_relevant_tracer(current_tracer)) {
+ warnx("%s is not a known latency tracer!\n",
+ current_tracer);
+ }
+ valid = tracer_valid(current_tracer, &notracer);
+ if (notracer)
+ errx(EXIT_FAILURE, no_tracer_msg);
+ if (!valid)
+ errx(EXIT_FAILURE,
+"The tracer %s is not supported by your kernel!\n", current_tracer);
+ break;
+ case 'F':
+ force_tracer = true;
+ break;
+ case 's':
+ check_alldigits(optarg, "-s [--threshold]");
+ threshold = strdup(optarg);
+ break;
+ case 'f':
+ use_options[OPTIDX_FUNC_TR] = true;
+ break;
+ case 'g':
+ use_options[OPTIDX_DISP_GR] = true;
+ break;
+ case 'c':
+ p = policy_from_name(optarg);
+ if (p != NULL) {
+ sched_policy = p->policy;
+ sched_policy_set = true;
+ if (!sched_pri_set) {
+ sched_pri = p->default_pri;
+ sched_pri_set = true;
+ }
+ } else {
+ warnx("Unknown scheduling %s\n", optarg);
+ show_usage();
+ exit(0);
+ }
+ break;
+ case 'p':
+ check_alldigits(optarg, "-p [--priority]");
+ sched_pri = atoi(optarg);
+ sched_pri_set = true;
+ break;
+ case 'h':
+ show_usage();
+ exit(0);
+ break;
+ case 'n':
+ trace_enable = false;
+ use_random_sleep = false;
+ break;
+ case 'e':
+ check_alldigits(optarg, "-e [--threads]");
+ value = atoi(optarg);
+ if (value > 0)
+ nr_threads = value;
+ else {
+ warnx("NRTHR must be > 0\n");
+ show_usage();
+ exit(0);
+ }
+ break;
+ case 'u':
+ check_alldigits(optarg, "-u [--time]");
+ value = atoi(optarg);
+ if (value < 0) {
+ warnx("TIME must be >= 0\n");
+ show_usage();
+ exit(0);
+ }
+ trace_enable = true;
+ use_random_sleep = true;
+ sleep_time = value * USEC_PER_MSEC;
+ break;
+ case 'v':
+ verbosity++;
+ break;
+ case 'r':
+ trace_enable = true;
+ use_random_sleep = true;
+ break;
+ case 'a':
+ check_alldigits(optarg, "-a [--nrlat]");
+ value = atoi(optarg);
+ if (value <= 0) {
+ warnx("NRLAT must be > 0\n");
+ show_usage();
+ exit(0);
+ }
+ trace_enable = true;
+ use_random_sleep = true;
+ table_startsize = value;
+ break;
+ case 'x':
+ setup_ftrace = false;
+ break;
+ case 'i':
+ setup_ftrace = false;
+ debug_tracefile = strdup(optarg);
+ break;
+ case 'm':
+ setup_ftrace = false;
+ debug_maxlat = strdup(optarg);
+ break;
+ default:
+ show_usage();
+ exit(0);
+ break;
+ }
+ }
+
+ if (setup_ftrace) {
+ if (!current_tracer) {
+ current_tracer = find_default_tracer();
+ if (!current_tracer)
+ errx(EXIT_FAILURE,
+"No default tracer found and tracer not specified\n");
+ }
+
+ if (use_random_sleep && !random_makes_sense(current_tracer)) {
+ warnx("WARNING: The tracer is %s and random sleep has",
+ current_tracer);
+ fprintf(stderr,
+"been enabled. Random sleep is intended for the following tracers:\n");
+ for (i = 0; random_tracers[i]; i++)
+ fprintf(stderr, "%s\n", random_tracers[i]);
+ fprintf(stderr, "\n");
+ }
+ }
+
+ if (debug_tracefile == DEBUG_NOFILE ||
+ debug_maxlat == DEBUG_NOFILE)
+ errx(EXIT_FAILURE,
+"Could not find tracing directory e.g. /sys/kernel/tracing\n");
+
+ if (!sched_policy_set) {
+ sched_policy = SCHED_RR;
+ sched_policy_set = true;
+ if (!sched_pri_set) {
+ sched_pri = RT_DEFAULT_PRI;
+ sched_pri_set = true;
+ }
+ }
+
+ max = sched_get_priority_max(sched_policy);
+ min = sched_get_priority_min(sched_policy);
+
+ if (sched_pri < min) {
+ printf(
+"ATTENTION: Increasing priority to minimum, which is %d\n", min);
+ sched_pri = min;
+ }
+ if (sched_pri > max) {
+ printf(
+"ATTENTION: Reducing priority to maximum, which is %d\n", max);
+ sched_pri = max;
+ }
+}
+
+static void show_params(void)
+{
+ printf(
+"\n"
+"Running with scheduling policy %s and priority %d. Using %d print threads.\n",
+ policy_name(sched_policy), sched_pri, nr_threads);
+ if (trace_enable) {
+ if (use_random_sleep) {
+ printf(
+"%s will be printed with random delay\n"
+"Start size of the probability table:\t\t\t%d\n"
+"Print a message when the prob. table changes size:\t%s\n"
+"Print a warning when an event has been lost:\t\t%s\n"
+"Sleep time is:\t\t\t\t\t\t%ld ms\n",
+debug_tracefile,
+table_startsize,
+bool2str(verbose_sizechange()),
+bool2str(verbose_lostevent()),
+sleep_time / USEC_PER_MSEC);
+ } else {
+ printf("%s will be printed immediately\n",
+ debug_tracefile);
+ }
+ } else {
+ printf("%s will not be printed\n",
+ debug_tracefile);
+ }
+ if (setup_ftrace) {
+ printf("Tracer:\t\t\t\t\t\t\t%s\n"
+ "%s option:\t\t\t\t\t%s\n"
+ "%s option:\t\t\t\t\t%s\n",
+ current_tracer,
+ optstr[OPTIDX_FUNC_TR],
+ bool2str(use_options[OPTIDX_FUNC_TR]),
+ optstr[OPTIDX_DISP_GR],
+ bool2str(use_options[OPTIDX_DISP_GR]));
+ if (!strcmp(threshold, "0"))
+ printf("Threshold:\t\t\t\t\t\ttracing_max_latency\n");
+ else
+ printf("Threshold:\t\t\t\t\t\t%s\n", threshold);
+ }
+ printf("\n");
+}
+
+int main(int argc, char *argv[])
+{
+ init_save_state();
+ signal_blocking(SIG_BLOCK);
+ setup_sig_handler();
+ open_stdout();
+
+ if (argc >= 1)
+ prg_name = argv[0];
+ else
+ prg_name = prg_unknown;
+
+ scan_arguments(argc, argv);
+ show_params();
+
+ init_printstate();
+ init_print_mtx();
+ if (use_random_sleep) {
+ init_probabilities();
+ if (verbose_sizechange())
+ printf("Initializing probability table to %d\n",
+ table_startsize);
+ sleeptable_resize(table_startsize, false, NULL);
+ }
+ set_priority();
+ init_queue(&printqueue);
+ start_printthread();
+ tracing_loop();
+ return 0;
+}
generated by cgit v1.2.3 (git 2.39.1) at 2024-12-15 13:31:18 +0000