Path: blob/master/tools/tracing/rtla/src/timerlat_hist.c
26285 views
// SPDX-License-Identifier: GPL-2.01/*2* Copyright (C) 2021 Red Hat Inc, Daniel Bristot de Oliveira <[email protected]>3*/45#define _GNU_SOURCE6#include <getopt.h>7#include <stdlib.h>8#include <string.h>9#include <signal.h>10#include <unistd.h>11#include <stdio.h>12#include <time.h>13#include <sched.h>14#include <pthread.h>1516#include "timerlat.h"17#include "timerlat_aa.h"18#include "timerlat_u.h"19#include "timerlat_bpf.h"2021struct timerlat_hist_cpu {22int *irq;23int *thread;24int *user;2526unsigned long long irq_count;27unsigned long long thread_count;28unsigned long long user_count;2930unsigned long long min_irq;31unsigned long long sum_irq;32unsigned long long max_irq;3334unsigned long long min_thread;35unsigned long long sum_thread;36unsigned long long max_thread;3738unsigned long long min_user;39unsigned long long sum_user;40unsigned long long max_user;41};4243struct timerlat_hist_data {44struct timerlat_hist_cpu *hist;45int entries;46int bucket_size;47int nr_cpus;48};4950/*51* timerlat_free_histogram - free runtime data52*/53static void54timerlat_free_histogram(struct timerlat_hist_data *data)55{56int cpu;5758/* one histogram for IRQ and one for thread, per CPU */59for (cpu = 0; cpu < data->nr_cpus; cpu++) {60if (data->hist[cpu].irq)61free(data->hist[cpu].irq);6263if (data->hist[cpu].thread)64free(data->hist[cpu].thread);6566if (data->hist[cpu].user)67free(data->hist[cpu].user);6869}7071/* one set of histograms per CPU */72if (data->hist)73free(data->hist);7475free(data);76}7778/*79* timerlat_alloc_histogram - alloc runtime data80*/81static struct timerlat_hist_data82*timerlat_alloc_histogram(int nr_cpus, int entries, int bucket_size)83{84struct timerlat_hist_data *data;85int cpu;8687data = calloc(1, sizeof(*data));88if (!data)89return NULL;9091data->entries = entries;92data->bucket_size = bucket_size;93data->nr_cpus = nr_cpus;9495/* one set of histograms per CPU */96data->hist = calloc(1, sizeof(*data->hist) * nr_cpus);97if (!data->hist)98goto cleanup;99100/* one histogram for IRQ and one for thread, per cpu */101for (cpu = 0; cpu < nr_cpus; cpu++) {102data->hist[cpu].irq = calloc(1, sizeof(*data->hist->irq) * (entries + 1));103if (!data->hist[cpu].irq)104goto cleanup;105106data->hist[cpu].thread = calloc(1, sizeof(*data->hist->thread) * (entries + 1));107if (!data->hist[cpu].thread)108goto cleanup;109110data->hist[cpu].user = calloc(1, sizeof(*data->hist->user) * (entries + 1));111if (!data->hist[cpu].user)112goto cleanup;113}114115/* set the min to max */116for (cpu = 0; cpu < nr_cpus; cpu++) {117data->hist[cpu].min_irq = ~0;118data->hist[cpu].min_thread = ~0;119data->hist[cpu].min_user = ~0;120}121122return data;123124cleanup:125timerlat_free_histogram(data);126return NULL;127}128129/*130* timerlat_hist_update - record a new timerlat occurent on cpu, updating data131*/132static void133timerlat_hist_update(struct osnoise_tool *tool, int cpu,134unsigned long long context,135unsigned long long latency)136{137struct timerlat_params *params = tool->params;138struct timerlat_hist_data *data = tool->data;139int entries = data->entries;140int bucket;141int *hist;142143if (params->output_divisor)144latency = latency / params->output_divisor;145146bucket = latency / data->bucket_size;147148if (!context) {149hist = data->hist[cpu].irq;150data->hist[cpu].irq_count++;151update_min(&data->hist[cpu].min_irq, &latency);152update_sum(&data->hist[cpu].sum_irq, &latency);153update_max(&data->hist[cpu].max_irq, &latency);154} else if (context == 1) {155hist = data->hist[cpu].thread;156data->hist[cpu].thread_count++;157update_min(&data->hist[cpu].min_thread, &latency);158update_sum(&data->hist[cpu].sum_thread, &latency);159update_max(&data->hist[cpu].max_thread, &latency);160} else { /* user */161hist = data->hist[cpu].user;162data->hist[cpu].user_count++;163update_min(&data->hist[cpu].min_user, &latency);164update_sum(&data->hist[cpu].sum_user, &latency);165update_max(&data->hist[cpu].max_user, &latency);166}167168if (bucket < entries)169hist[bucket]++;170else171hist[entries]++;172}173174/*175* timerlat_hist_handler - this is the handler for timerlat tracer events176*/177static int178timerlat_hist_handler(struct trace_seq *s, struct tep_record *record,179struct tep_event *event, void *data)180{181struct trace_instance *trace = data;182unsigned long long context, latency;183struct osnoise_tool *tool;184int cpu = record->cpu;185186tool = container_of(trace, struct osnoise_tool, trace);187188tep_get_field_val(s, event, "context", record, &context, 1);189tep_get_field_val(s, event, "timer_latency", record, &latency, 1);190191timerlat_hist_update(tool, cpu, context, latency);192193return 0;194}195196/*197* timerlat_hist_bpf_pull_data - copy data from BPF maps into userspace198*/199static int timerlat_hist_bpf_pull_data(struct osnoise_tool *tool)200{201struct timerlat_hist_data *data = tool->data;202int i, j, err;203long long value_irq[data->nr_cpus],204value_thread[data->nr_cpus],205value_user[data->nr_cpus];206207/* Pull histogram */208for (i = 0; i < data->entries; i++) {209err = timerlat_bpf_get_hist_value(i, value_irq, value_thread,210value_user, data->nr_cpus);211if (err)212return err;213for (j = 0; j < data->nr_cpus; j++) {214data->hist[j].irq[i] = value_irq[j];215data->hist[j].thread[i] = value_thread[j];216data->hist[j].user[i] = value_user[j];217}218}219220/* Pull summary */221err = timerlat_bpf_get_summary_value(SUMMARY_COUNT,222value_irq, value_thread, value_user,223data->nr_cpus);224if (err)225return err;226for (i = 0; i < data->nr_cpus; i++) {227data->hist[i].irq_count = value_irq[i];228data->hist[i].thread_count = value_thread[i];229data->hist[i].user_count = value_user[i];230}231232err = timerlat_bpf_get_summary_value(SUMMARY_MIN,233value_irq, value_thread, value_user,234data->nr_cpus);235if (err)236return err;237for (i = 0; i < data->nr_cpus; i++) {238data->hist[i].min_irq = value_irq[i];239data->hist[i].min_thread = value_thread[i];240data->hist[i].min_user = value_user[i];241}242243err = timerlat_bpf_get_summary_value(SUMMARY_MAX,244value_irq, value_thread, value_user,245data->nr_cpus);246if (err)247return err;248for (i = 0; i < data->nr_cpus; i++) {249data->hist[i].max_irq = value_irq[i];250data->hist[i].max_thread = value_thread[i];251data->hist[i].max_user = value_user[i];252}253254err = timerlat_bpf_get_summary_value(SUMMARY_SUM,255value_irq, value_thread, value_user,256data->nr_cpus);257if (err)258return err;259for (i = 0; i < data->nr_cpus; i++) {260data->hist[i].sum_irq = value_irq[i];261data->hist[i].sum_thread = value_thread[i];262data->hist[i].sum_user = value_user[i];263}264265err = timerlat_bpf_get_summary_value(SUMMARY_OVERFLOW,266value_irq, value_thread, value_user,267data->nr_cpus);268if (err)269return err;270for (i = 0; i < data->nr_cpus; i++) {271data->hist[i].irq[data->entries] = value_irq[i];272data->hist[i].thread[data->entries] = value_thread[i];273data->hist[i].user[data->entries] = value_user[i];274}275276return 0;277}278279/*280* timerlat_hist_header - print the header of the tracer to the output281*/282static void timerlat_hist_header(struct osnoise_tool *tool)283{284struct timerlat_params *params = tool->params;285struct timerlat_hist_data *data = tool->data;286struct trace_seq *s = tool->trace.seq;287char duration[26];288int cpu;289290if (params->no_header)291return;292293get_duration(tool->start_time, duration, sizeof(duration));294trace_seq_printf(s, "# RTLA timerlat histogram\n");295trace_seq_printf(s, "# Time unit is %s (%s)\n",296params->output_divisor == 1 ? "nanoseconds" : "microseconds",297params->output_divisor == 1 ? "ns" : "us");298299trace_seq_printf(s, "# Duration: %s\n", duration);300301if (!params->no_index)302trace_seq_printf(s, "Index");303304for (cpu = 0; cpu < data->nr_cpus; cpu++) {305if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))306continue;307308if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)309continue;310311if (!params->no_irq)312trace_seq_printf(s, " IRQ-%03d", cpu);313314if (!params->no_thread)315trace_seq_printf(s, " Thr-%03d", cpu);316317if (params->user_data)318trace_seq_printf(s, " Usr-%03d", cpu);319}320trace_seq_printf(s, "\n");321322323trace_seq_do_printf(s);324trace_seq_reset(s);325}326327/*328* format_summary_value - format a line of summary value (min, max or avg)329* of hist data330*/331static void format_summary_value(struct trace_seq *seq,332int count,333unsigned long long val,334bool avg)335{336if (count)337trace_seq_printf(seq, "%9llu ", avg ? val / count : val);338else339trace_seq_printf(seq, "%9c ", '-');340}341342/*343* timerlat_print_summary - print the summary of the hist data to the output344*/345static void346timerlat_print_summary(struct timerlat_params *params,347struct trace_instance *trace,348struct timerlat_hist_data *data)349{350int cpu;351352if (params->no_summary)353return;354355if (!params->no_index)356trace_seq_printf(trace->seq, "count:");357358for (cpu = 0; cpu < data->nr_cpus; cpu++) {359if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))360continue;361362if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)363continue;364365if (!params->no_irq)366trace_seq_printf(trace->seq, "%9llu ",367data->hist[cpu].irq_count);368369if (!params->no_thread)370trace_seq_printf(trace->seq, "%9llu ",371data->hist[cpu].thread_count);372373if (params->user_data)374trace_seq_printf(trace->seq, "%9llu ",375data->hist[cpu].user_count);376}377trace_seq_printf(trace->seq, "\n");378379if (!params->no_index)380trace_seq_printf(trace->seq, "min: ");381382for (cpu = 0; cpu < data->nr_cpus; cpu++) {383if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))384continue;385386if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)387continue;388389if (!params->no_irq)390format_summary_value(trace->seq,391data->hist[cpu].irq_count,392data->hist[cpu].min_irq,393false);394395if (!params->no_thread)396format_summary_value(trace->seq,397data->hist[cpu].thread_count,398data->hist[cpu].min_thread,399false);400401if (params->user_data)402format_summary_value(trace->seq,403data->hist[cpu].user_count,404data->hist[cpu].min_user,405false);406}407trace_seq_printf(trace->seq, "\n");408409if (!params->no_index)410trace_seq_printf(trace->seq, "avg: ");411412for (cpu = 0; cpu < data->nr_cpus; cpu++) {413if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))414continue;415416if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)417continue;418419if (!params->no_irq)420format_summary_value(trace->seq,421data->hist[cpu].irq_count,422data->hist[cpu].sum_irq,423true);424425if (!params->no_thread)426format_summary_value(trace->seq,427data->hist[cpu].thread_count,428data->hist[cpu].sum_thread,429true);430431if (params->user_data)432format_summary_value(trace->seq,433data->hist[cpu].user_count,434data->hist[cpu].sum_user,435true);436}437trace_seq_printf(trace->seq, "\n");438439if (!params->no_index)440trace_seq_printf(trace->seq, "max: ");441442for (cpu = 0; cpu < data->nr_cpus; cpu++) {443if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))444continue;445446if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)447continue;448449if (!params->no_irq)450format_summary_value(trace->seq,451data->hist[cpu].irq_count,452data->hist[cpu].max_irq,453false);454455if (!params->no_thread)456format_summary_value(trace->seq,457data->hist[cpu].thread_count,458data->hist[cpu].max_thread,459false);460461if (params->user_data)462format_summary_value(trace->seq,463data->hist[cpu].user_count,464data->hist[cpu].max_user,465false);466}467trace_seq_printf(trace->seq, "\n");468trace_seq_do_printf(trace->seq);469trace_seq_reset(trace->seq);470}471472static void473timerlat_print_stats_all(struct timerlat_params *params,474struct trace_instance *trace,475struct timerlat_hist_data *data)476{477struct timerlat_hist_cpu *cpu_data;478struct timerlat_hist_cpu sum;479int cpu;480481if (params->no_summary)482return;483484memset(&sum, 0, sizeof(sum));485sum.min_irq = ~0;486sum.min_thread = ~0;487sum.min_user = ~0;488489for (cpu = 0; cpu < data->nr_cpus; cpu++) {490if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))491continue;492493if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)494continue;495496cpu_data = &data->hist[cpu];497498sum.irq_count += cpu_data->irq_count;499update_min(&sum.min_irq, &cpu_data->min_irq);500update_sum(&sum.sum_irq, &cpu_data->sum_irq);501update_max(&sum.max_irq, &cpu_data->max_irq);502503sum.thread_count += cpu_data->thread_count;504update_min(&sum.min_thread, &cpu_data->min_thread);505update_sum(&sum.sum_thread, &cpu_data->sum_thread);506update_max(&sum.max_thread, &cpu_data->max_thread);507508sum.user_count += cpu_data->user_count;509update_min(&sum.min_user, &cpu_data->min_user);510update_sum(&sum.sum_user, &cpu_data->sum_user);511update_max(&sum.max_user, &cpu_data->max_user);512}513514if (!params->no_index)515trace_seq_printf(trace->seq, "ALL: ");516517if (!params->no_irq)518trace_seq_printf(trace->seq, " IRQ");519520if (!params->no_thread)521trace_seq_printf(trace->seq, " Thr");522523if (params->user_data)524trace_seq_printf(trace->seq, " Usr");525526trace_seq_printf(trace->seq, "\n");527528if (!params->no_index)529trace_seq_printf(trace->seq, "count:");530531if (!params->no_irq)532trace_seq_printf(trace->seq, "%9llu ",533sum.irq_count);534535if (!params->no_thread)536trace_seq_printf(trace->seq, "%9llu ",537sum.thread_count);538539if (params->user_data)540trace_seq_printf(trace->seq, "%9llu ",541sum.user_count);542543trace_seq_printf(trace->seq, "\n");544545if (!params->no_index)546trace_seq_printf(trace->seq, "min: ");547548if (!params->no_irq)549format_summary_value(trace->seq,550sum.irq_count,551sum.min_irq,552false);553554if (!params->no_thread)555format_summary_value(trace->seq,556sum.thread_count,557sum.min_thread,558false);559560if (params->user_data)561format_summary_value(trace->seq,562sum.user_count,563sum.min_user,564false);565566trace_seq_printf(trace->seq, "\n");567568if (!params->no_index)569trace_seq_printf(trace->seq, "avg: ");570571if (!params->no_irq)572format_summary_value(trace->seq,573sum.irq_count,574sum.sum_irq,575true);576577if (!params->no_thread)578format_summary_value(trace->seq,579sum.thread_count,580sum.sum_thread,581true);582583if (params->user_data)584format_summary_value(trace->seq,585sum.user_count,586sum.sum_user,587true);588589trace_seq_printf(trace->seq, "\n");590591if (!params->no_index)592trace_seq_printf(trace->seq, "max: ");593594if (!params->no_irq)595format_summary_value(trace->seq,596sum.irq_count,597sum.max_irq,598false);599600if (!params->no_thread)601format_summary_value(trace->seq,602sum.thread_count,603sum.max_thread,604false);605606if (params->user_data)607format_summary_value(trace->seq,608sum.user_count,609sum.max_user,610false);611612trace_seq_printf(trace->seq, "\n");613trace_seq_do_printf(trace->seq);614trace_seq_reset(trace->seq);615}616617/*618* timerlat_print_stats - print data for each CPUs619*/620static void621timerlat_print_stats(struct timerlat_params *params, struct osnoise_tool *tool)622{623struct timerlat_hist_data *data = tool->data;624struct trace_instance *trace = &tool->trace;625int bucket, cpu;626int total;627628timerlat_hist_header(tool);629630for (bucket = 0; bucket < data->entries; bucket++) {631total = 0;632633if (!params->no_index)634trace_seq_printf(trace->seq, "%-6d",635bucket * data->bucket_size);636637for (cpu = 0; cpu < data->nr_cpus; cpu++) {638if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))639continue;640641if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)642continue;643644if (!params->no_irq) {645total += data->hist[cpu].irq[bucket];646trace_seq_printf(trace->seq, "%9d ",647data->hist[cpu].irq[bucket]);648}649650if (!params->no_thread) {651total += data->hist[cpu].thread[bucket];652trace_seq_printf(trace->seq, "%9d ",653data->hist[cpu].thread[bucket]);654}655656if (params->user_data) {657total += data->hist[cpu].user[bucket];658trace_seq_printf(trace->seq, "%9d ",659data->hist[cpu].user[bucket]);660}661662}663664if (total == 0 && !params->with_zeros) {665trace_seq_reset(trace->seq);666continue;667}668669trace_seq_printf(trace->seq, "\n");670trace_seq_do_printf(trace->seq);671trace_seq_reset(trace->seq);672}673674if (!params->no_index)675trace_seq_printf(trace->seq, "over: ");676677for (cpu = 0; cpu < data->nr_cpus; cpu++) {678if (params->cpus && !CPU_ISSET(cpu, ¶ms->monitored_cpus))679continue;680681if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)682continue;683684if (!params->no_irq)685trace_seq_printf(trace->seq, "%9d ",686data->hist[cpu].irq[data->entries]);687688if (!params->no_thread)689trace_seq_printf(trace->seq, "%9d ",690data->hist[cpu].thread[data->entries]);691692if (params->user_data)693trace_seq_printf(trace->seq, "%9d ",694data->hist[cpu].user[data->entries]);695}696trace_seq_printf(trace->seq, "\n");697trace_seq_do_printf(trace->seq);698trace_seq_reset(trace->seq);699700timerlat_print_summary(params, trace, data);701timerlat_print_stats_all(params, trace, data);702osnoise_report_missed_events(tool);703}704705/*706* timerlat_hist_usage - prints timerlat top usage message707*/708static void timerlat_hist_usage(char *usage)709{710int i;711712char *msg[] = {713"",714" usage: [rtla] timerlat hist [-h] [-q] [-d s] [-D] [-n] [-a us] [-p us] [-i us] [-T us] [-s us] \\",715" [-t[file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] [-H cpu-list]\\",716" [-P priority] [-E N] [-b N] [--no-irq] [--no-thread] [--no-header] [--no-summary] \\",717" [--no-index] [--with-zeros] [--dma-latency us] [-C[=cgroup_name]] [--no-aa] [--dump-task] [-u|-k]",718" [--warm-up s] [--deepest-idle-state n]",719"",720" -h/--help: print this menu",721" -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit",722" -p/--period us: timerlat period in us",723" -i/--irq us: stop trace if the irq latency is higher than the argument in us",724" -T/--thread us: stop trace if the thread latency is higher than the argument in us",725" -s/--stack us: save the stack trace at the IRQ if a thread latency is higher than the argument in us",726" -c/--cpus cpus: run the tracer only on the given cpus",727" -H/--house-keeping cpus: run rtla control threads only on the given cpus",728" -C/--cgroup[=cgroup_name]: set cgroup, if no cgroup_name is passed, the rtla's cgroup will be inherited",729" -d/--duration time[m|h|d]: duration of the session in seconds",730" --dump-tasks: prints the task running on all CPUs if stop conditions are met (depends on !--no-aa)",731" -D/--debug: print debug info",732" -t/--trace[file]: save the stopped trace to [file|timerlat_trace.txt]",733" -e/--event <sys:event>: enable the <sys:event> in the trace instance, multiple -e are allowed",734" --filter <filter>: enable a trace event filter to the previous -e event",735" --trigger <trigger>: enable a trace event trigger to the previous -e event",736" -n/--nano: display data in nanoseconds",737" --no-aa: disable auto-analysis, reducing rtla timerlat cpu usage",738" -b/--bucket-size N: set the histogram bucket size (default 1)",739" -E/--entries N: set the number of entries of the histogram (default 256)",740" --no-irq: ignore IRQ latencies",741" --no-thread: ignore thread latencies",742" --no-header: do not print header",743" --no-summary: do not print summary",744" --no-index: do not print index",745" --with-zeros: print zero only entries",746" --dma-latency us: set /dev/cpu_dma_latency latency <us> to reduce exit from idle latency",747" -P/--priority o:prio|r:prio|f:prio|d:runtime:period : set scheduling parameters",748" o:prio - use SCHED_OTHER with prio",749" r:prio - use SCHED_RR with prio",750" f:prio - use SCHED_FIFO with prio",751" d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with runtime and period",752" in nanoseconds",753" -u/--user-threads: use rtla user-space threads instead of kernel-space timerlat threads",754" -k/--kernel-threads: use timerlat kernel-space threads instead of rtla user-space threads",755" -U/--user-load: enable timerlat for user-defined user-space workload",756" --warm-up s: let the workload run for s seconds before collecting data",757" --trace-buffer-size kB: set the per-cpu trace buffer size in kB",758" --deepest-idle-state n: only go down to idle state n on cpus used by timerlat to reduce exit from idle latency",759" --on-threshold <action>: define action to be executed at latency threshold, multiple are allowed",760" --on-end <action>: define action to be executed at measurement end, multiple are allowed",761NULL,762};763764if (usage)765fprintf(stderr, "%s\n", usage);766767fprintf(stderr, "rtla timerlat hist: a per-cpu histogram of the timer latency (version %s)\n",768VERSION);769770for (i = 0; msg[i]; i++)771fprintf(stderr, "%s\n", msg[i]);772773if (usage)774exit(EXIT_FAILURE);775776exit(EXIT_SUCCESS);777}778779/*780* timerlat_hist_parse_args - allocs, parse and fill the cmd line parameters781*/782static struct timerlat_params783*timerlat_hist_parse_args(int argc, char *argv[])784{785struct timerlat_params *params;786struct trace_events *tevent;787int auto_thresh;788int retval;789int c;790char *trace_output = NULL;791792params = calloc(1, sizeof(*params));793if (!params)794exit(1);795796actions_init(¶ms->threshold_actions);797actions_init(¶ms->end_actions);798799/* disabled by default */800params->dma_latency = -1;801802/* disabled by default */803params->deepest_idle_state = -2;804805/* display data in microseconds */806params->output_divisor = 1000;807params->bucket_size = 1;808params->entries = 256;809810/* default to BPF mode */811params->mode = TRACING_MODE_BPF;812813while (1) {814static struct option long_options[] = {815{"auto", required_argument, 0, 'a'},816{"cpus", required_argument, 0, 'c'},817{"cgroup", optional_argument, 0, 'C'},818{"bucket-size", required_argument, 0, 'b'},819{"debug", no_argument, 0, 'D'},820{"entries", required_argument, 0, 'E'},821{"duration", required_argument, 0, 'd'},822{"house-keeping", required_argument, 0, 'H'},823{"help", no_argument, 0, 'h'},824{"irq", required_argument, 0, 'i'},825{"nano", no_argument, 0, 'n'},826{"period", required_argument, 0, 'p'},827{"priority", required_argument, 0, 'P'},828{"stack", required_argument, 0, 's'},829{"thread", required_argument, 0, 'T'},830{"trace", optional_argument, 0, 't'},831{"user-threads", no_argument, 0, 'u'},832{"kernel-threads", no_argument, 0, 'k'},833{"user-load", no_argument, 0, 'U'},834{"event", required_argument, 0, 'e'},835{"no-irq", no_argument, 0, '0'},836{"no-thread", no_argument, 0, '1'},837{"no-header", no_argument, 0, '2'},838{"no-summary", no_argument, 0, '3'},839{"no-index", no_argument, 0, '4'},840{"with-zeros", no_argument, 0, '5'},841{"trigger", required_argument, 0, '6'},842{"filter", required_argument, 0, '7'},843{"dma-latency", required_argument, 0, '8'},844{"no-aa", no_argument, 0, '9'},845{"dump-task", no_argument, 0, '\1'},846{"warm-up", required_argument, 0, '\2'},847{"trace-buffer-size", required_argument, 0, '\3'},848{"deepest-idle-state", required_argument, 0, '\4'},849{"on-threshold", required_argument, 0, '\5'},850{"on-end", required_argument, 0, '\6'},851{0, 0, 0, 0}852};853854/* getopt_long stores the option index here. */855int option_index = 0;856857c = getopt_long(argc, argv, "a:c:C::b:d:e:E:DhH:i:knp:P:s:t::T:uU0123456:7:8:9\1\2:\3:",858long_options, &option_index);859860/* detect the end of the options. */861if (c == -1)862break;863864switch (c) {865case 'a':866auto_thresh = get_llong_from_str(optarg);867868/* set thread stop to auto_thresh */869params->stop_total_us = auto_thresh;870params->stop_us = auto_thresh;871872/* get stack trace */873params->print_stack = auto_thresh;874875/* set trace */876trace_output = "timerlat_trace.txt";877878break;879case 'c':880retval = parse_cpu_set(optarg, ¶ms->monitored_cpus);881if (retval)882timerlat_hist_usage("\nInvalid -c cpu list\n");883params->cpus = optarg;884break;885case 'C':886params->cgroup = 1;887if (!optarg) {888/* will inherit this cgroup */889params->cgroup_name = NULL;890} else if (*optarg == '=') {891/* skip the = */892params->cgroup_name = ++optarg;893}894break;895case 'b':896params->bucket_size = get_llong_from_str(optarg);897if ((params->bucket_size == 0) || (params->bucket_size >= 1000000))898timerlat_hist_usage("Bucket size needs to be > 0 and <= 1000000\n");899break;900case 'D':901config_debug = 1;902break;903case 'd':904params->duration = parse_seconds_duration(optarg);905if (!params->duration)906timerlat_hist_usage("Invalid -D duration\n");907break;908case 'e':909tevent = trace_event_alloc(optarg);910if (!tevent) {911err_msg("Error alloc trace event");912exit(EXIT_FAILURE);913}914915if (params->events)916tevent->next = params->events;917918params->events = tevent;919break;920case 'E':921params->entries = get_llong_from_str(optarg);922if ((params->entries < 10) || (params->entries > 9999999))923timerlat_hist_usage("Entries must be > 10 and < 9999999\n");924break;925case 'h':926case '?':927timerlat_hist_usage(NULL);928break;929case 'H':930params->hk_cpus = 1;931retval = parse_cpu_set(optarg, ¶ms->hk_cpu_set);932if (retval) {933err_msg("Error parsing house keeping CPUs\n");934exit(EXIT_FAILURE);935}936break;937case 'i':938params->stop_us = get_llong_from_str(optarg);939break;940case 'k':941params->kernel_workload = 1;942break;943case 'n':944params->output_divisor = 1;945break;946case 'p':947params->timerlat_period_us = get_llong_from_str(optarg);948if (params->timerlat_period_us > 1000000)949timerlat_hist_usage("Period longer than 1 s\n");950break;951case 'P':952retval = parse_prio(optarg, ¶ms->sched_param);953if (retval == -1)954timerlat_hist_usage("Invalid -P priority");955params->set_sched = 1;956break;957case 's':958params->print_stack = get_llong_from_str(optarg);959break;960case 'T':961params->stop_total_us = get_llong_from_str(optarg);962break;963case 't':964if (optarg) {965if (optarg[0] == '=')966trace_output = &optarg[1];967else968trace_output = &optarg[0];969} else if (optind < argc && argv[optind][0] != '-')970trace_output = argv[optind];971else972trace_output = "timerlat_trace.txt";973break;974case 'u':975params->user_workload = 1;976/* fallback: -u implies in -U */977case 'U':978params->user_data = 1;979break;980case '0': /* no irq */981params->no_irq = 1;982break;983case '1': /* no thread */984params->no_thread = 1;985break;986case '2': /* no header */987params->no_header = 1;988break;989case '3': /* no summary */990params->no_summary = 1;991break;992case '4': /* no index */993params->no_index = 1;994break;995case '5': /* with zeros */996params->with_zeros = 1;997break;998case '6': /* trigger */999if (params->events) {1000retval = trace_event_add_trigger(params->events, optarg);1001if (retval) {1002err_msg("Error adding trigger %s\n", optarg);1003exit(EXIT_FAILURE);1004}1005} else {1006timerlat_hist_usage("--trigger requires a previous -e\n");1007}1008break;1009case '7': /* filter */1010if (params->events) {1011retval = trace_event_add_filter(params->events, optarg);1012if (retval) {1013err_msg("Error adding filter %s\n", optarg);1014exit(EXIT_FAILURE);1015}1016} else {1017timerlat_hist_usage("--filter requires a previous -e\n");1018}1019break;1020case '8':1021params->dma_latency = get_llong_from_str(optarg);1022if (params->dma_latency < 0 || params->dma_latency > 10000) {1023err_msg("--dma-latency needs to be >= 0 and < 10000");1024exit(EXIT_FAILURE);1025}1026break;1027case '9':1028params->no_aa = 1;1029break;1030case '\1':1031params->dump_tasks = 1;1032break;1033case '\2':1034params->warmup = get_llong_from_str(optarg);1035break;1036case '\3':1037params->buffer_size = get_llong_from_str(optarg);1038break;1039case '\4':1040params->deepest_idle_state = get_llong_from_str(optarg);1041break;1042case '\5':1043retval = actions_parse(¶ms->threshold_actions, optarg);1044if (retval) {1045err_msg("Invalid action %s\n", optarg);1046exit(EXIT_FAILURE);1047}1048break;1049case '\6':1050retval = actions_parse(¶ms->end_actions, optarg);1051if (retval) {1052err_msg("Invalid action %s\n", optarg);1053exit(EXIT_FAILURE);1054}1055break;1056default:1057timerlat_hist_usage("Invalid option");1058}1059}10601061if (trace_output)1062actions_add_trace_output(¶ms->threshold_actions, trace_output);10631064if (geteuid()) {1065err_msg("rtla needs root permission\n");1066exit(EXIT_FAILURE);1067}10681069if (params->no_irq && params->no_thread)1070timerlat_hist_usage("no-irq and no-thread set, there is nothing to do here");10711072if (params->no_index && !params->with_zeros)1073timerlat_hist_usage("no-index set with with-zeros is not set - it does not make sense");10741075/*1076* Auto analysis only happens if stop tracing, thus:1077*/1078if (!params->stop_us && !params->stop_total_us)1079params->no_aa = 1;10801081if (params->kernel_workload && params->user_workload)1082timerlat_hist_usage("--kernel-threads and --user-threads are mutually exclusive!");10831084/*1085* If auto-analysis or trace output is enabled, switch from BPF mode to1086* mixed mode1087*/1088if (params->mode == TRACING_MODE_BPF &&1089(params->threshold_actions.present[ACTION_TRACE_OUTPUT] ||1090params->end_actions.present[ACTION_TRACE_OUTPUT] || !params->no_aa))1091params->mode = TRACING_MODE_MIXED;10921093return params;1094}10951096/*1097* timerlat_hist_apply_config - apply the hist configs to the initialized tool1098*/1099static int1100timerlat_hist_apply_config(struct osnoise_tool *tool, struct timerlat_params *params)1101{1102int retval;11031104retval = timerlat_apply_config(tool, params);1105if (retval)1106goto out_err;11071108return 0;11091110out_err:1111return -1;1112}11131114/*1115* timerlat_init_hist - initialize a timerlat hist tool with parameters1116*/1117static struct osnoise_tool1118*timerlat_init_hist(struct timerlat_params *params)1119{1120struct osnoise_tool *tool;1121int nr_cpus;11221123nr_cpus = sysconf(_SC_NPROCESSORS_CONF);11241125tool = osnoise_init_tool("timerlat_hist");1126if (!tool)1127return NULL;11281129tool->data = timerlat_alloc_histogram(nr_cpus, params->entries, params->bucket_size);1130if (!tool->data)1131goto out_err;11321133tool->params = params;11341135tep_register_event_handler(tool->trace.tep, -1, "ftrace", "timerlat",1136timerlat_hist_handler, tool);11371138return tool;11391140out_err:1141osnoise_destroy_tool(tool);1142return NULL;1143}11441145static int stop_tracing;1146static struct trace_instance *hist_inst = NULL;1147static void stop_hist(int sig)1148{1149if (stop_tracing) {1150/*1151* Stop requested twice in a row; abort event processing and1152* exit immediately1153*/1154tracefs_iterate_stop(hist_inst->inst);1155return;1156}1157stop_tracing = 1;1158if (hist_inst)1159trace_instance_stop(hist_inst);1160}11611162/*1163* timerlat_hist_set_signals - handles the signal to stop the tool1164*/1165static void1166timerlat_hist_set_signals(struct timerlat_params *params)1167{1168signal(SIGINT, stop_hist);1169if (params->duration) {1170signal(SIGALRM, stop_hist);1171alarm(params->duration);1172}1173}11741175int timerlat_hist_main(int argc, char *argv[])1176{1177struct timerlat_params *params;1178struct osnoise_tool *record = NULL;1179struct timerlat_u_params params_u;1180enum result return_value = ERROR;1181struct osnoise_tool *tool = NULL;1182struct osnoise_tool *aa = NULL;1183struct trace_instance *trace;1184int dma_latency_fd = -1;1185pthread_t timerlat_u;1186int retval;1187int nr_cpus, i;11881189params = timerlat_hist_parse_args(argc, argv);1190if (!params)1191exit(1);11921193tool = timerlat_init_hist(params);1194if (!tool) {1195err_msg("Could not init osnoise hist\n");1196goto out_exit;1197}11981199trace = &tool->trace;1200/*1201* Save trace instance into global variable so that SIGINT can stop1202* the timerlat tracer.1203* Otherwise, rtla could loop indefinitely when overloaded.1204*/1205hist_inst = trace;12061207/*1208* Try to enable BPF, unless disabled explicitly.1209* If BPF enablement fails, fall back to tracefs mode.1210*/1211if (getenv("RTLA_NO_BPF") && strncmp(getenv("RTLA_NO_BPF"), "1", 2) == 0) {1212debug_msg("RTLA_NO_BPF set, disabling BPF\n");1213params->mode = TRACING_MODE_TRACEFS;1214} else if (!tep_find_event_by_name(trace->tep, "osnoise", "timerlat_sample")) {1215debug_msg("osnoise:timerlat_sample missing, disabling BPF\n");1216params->mode = TRACING_MODE_TRACEFS;1217} else {1218retval = timerlat_bpf_init(params);1219if (retval) {1220debug_msg("Could not enable BPF\n");1221params->mode = TRACING_MODE_TRACEFS;1222}1223}12241225retval = timerlat_hist_apply_config(tool, params);1226if (retval) {1227err_msg("Could not apply config\n");1228goto out_free;1229}12301231retval = enable_timerlat(trace);1232if (retval) {1233err_msg("Failed to enable timerlat tracer\n");1234goto out_free;1235}12361237if (params->set_sched) {1238retval = set_comm_sched_attr("timerlat/", ¶ms->sched_param);1239if (retval) {1240err_msg("Failed to set sched parameters\n");1241goto out_free;1242}1243}12441245if (params->cgroup && !params->user_workload) {1246retval = set_comm_cgroup("timerlat/", params->cgroup_name);1247if (!retval) {1248err_msg("Failed to move threads to cgroup\n");1249goto out_free;1250}1251}12521253if (params->dma_latency >= 0) {1254dma_latency_fd = set_cpu_dma_latency(params->dma_latency);1255if (dma_latency_fd < 0) {1256err_msg("Could not set /dev/cpu_dma_latency.\n");1257goto out_free;1258}1259}12601261if (params->deepest_idle_state >= -1) {1262if (!have_libcpupower_support()) {1263err_msg("rtla built without libcpupower, --deepest-idle-state is not supported\n");1264goto out_free;1265}12661267nr_cpus = sysconf(_SC_NPROCESSORS_CONF);12681269for (i = 0; i < nr_cpus; i++) {1270if (params->cpus && !CPU_ISSET(i, ¶ms->monitored_cpus))1271continue;1272if (save_cpu_idle_disable_state(i) < 0) {1273err_msg("Could not save cpu idle state.\n");1274goto out_free;1275}1276if (set_deepest_cpu_idle_state(i, params->deepest_idle_state) < 0) {1277err_msg("Could not set deepest cpu idle state.\n");1278goto out_free;1279}1280}1281}12821283if (params->threshold_actions.present[ACTION_TRACE_OUTPUT] ||1284params->end_actions.present[ACTION_TRACE_OUTPUT]) {1285record = osnoise_init_trace_tool("timerlat");1286if (!record) {1287err_msg("Failed to enable the trace instance\n");1288goto out_free;1289}1290params->threshold_actions.trace_output_inst = record->trace.inst;1291params->end_actions.trace_output_inst = record->trace.inst;12921293if (params->events) {1294retval = trace_events_enable(&record->trace, params->events);1295if (retval)1296goto out_hist;1297}12981299if (params->buffer_size > 0) {1300retval = trace_set_buffer_size(&record->trace, params->buffer_size);1301if (retval)1302goto out_hist;1303}1304}13051306if (!params->no_aa) {1307aa = osnoise_init_tool("timerlat_aa");1308if (!aa)1309goto out_hist;13101311retval = timerlat_aa_init(aa, params->dump_tasks);1312if (retval) {1313err_msg("Failed to enable the auto analysis instance\n");1314goto out_hist;1315}13161317retval = enable_timerlat(&aa->trace);1318if (retval) {1319err_msg("Failed to enable timerlat tracer\n");1320goto out_hist;1321}1322}13231324if (params->user_workload) {1325/* rtla asked to stop */1326params_u.should_run = 1;1327/* all threads left */1328params_u.stopped_running = 0;13291330params_u.set = ¶ms->monitored_cpus;1331if (params->set_sched)1332params_u.sched_param = ¶ms->sched_param;1333else1334params_u.sched_param = NULL;13351336params_u.cgroup_name = params->cgroup_name;13371338retval = pthread_create(&timerlat_u, NULL, timerlat_u_dispatcher, ¶ms_u);1339if (retval)1340err_msg("Error creating timerlat user-space threads\n");1341}13421343if (params->warmup > 0) {1344debug_msg("Warming up for %d seconds\n", params->warmup);1345sleep(params->warmup);1346if (stop_tracing)1347goto out_hist;1348}13491350/*1351* Start the tracers here, after having set all instances.1352*1353* Let the trace instance start first for the case of hitting a stop1354* tracing while enabling other instances. The trace instance is the1355* one with most valuable information.1356*/1357if (record)1358trace_instance_start(&record->trace);1359if (!params->no_aa)1360trace_instance_start(&aa->trace);1361if (params->mode == TRACING_MODE_TRACEFS) {1362trace_instance_start(trace);1363} else {1364retval = timerlat_bpf_attach();1365if (retval) {1366err_msg("Error attaching BPF program\n");1367goto out_hist;1368}1369}13701371tool->start_time = time(NULL);1372timerlat_hist_set_signals(params);13731374if (params->mode == TRACING_MODE_TRACEFS) {1375while (!stop_tracing) {1376sleep(params->sleep_time);13771378retval = tracefs_iterate_raw_events(trace->tep,1379trace->inst,1380NULL,13810,1382collect_registered_events,1383trace);1384if (retval < 0) {1385err_msg("Error iterating on events\n");1386goto out_hist;1387}13881389if (osnoise_trace_is_off(tool, record)) {1390actions_perform(¶ms->threshold_actions);13911392if (!params->threshold_actions.continue_flag)1393/* continue flag not set, break */1394break;13951396/* continue action reached, re-enable tracing */1397if (record)1398trace_instance_start(&record->trace);1399if (!params->no_aa)1400trace_instance_start(&aa->trace);1401trace_instance_start(trace);1402}14031404/* is there still any user-threads ? */1405if (params->user_workload) {1406if (params_u.stopped_running) {1407debug_msg("timerlat user-space threads stopped!\n");1408break;1409}1410}1411}1412} else {1413while (!stop_tracing) {1414timerlat_bpf_wait(-1);14151416if (!stop_tracing) {1417/* Threshold overflow, perform actions on threshold */1418actions_perform(¶ms->threshold_actions);14191420if (!params->threshold_actions.continue_flag)1421/* continue flag not set, break */1422break;14231424/* continue action reached, re-enable tracing */1425if (record)1426trace_instance_start(&record->trace);1427if (!params->no_aa)1428trace_instance_start(&aa->trace);1429timerlat_bpf_restart_tracing();1430}1431}1432}14331434if (params->mode != TRACING_MODE_TRACEFS) {1435timerlat_bpf_detach();1436retval = timerlat_hist_bpf_pull_data(tool);1437if (retval) {1438err_msg("Error pulling BPF data\n");1439goto out_hist;1440}1441}14421443if (params->user_workload && !params_u.stopped_running) {1444params_u.should_run = 0;1445sleep(1);1446}14471448timerlat_print_stats(params, tool);14491450actions_perform(¶ms->end_actions);14511452return_value = PASSED;14531454if (osnoise_trace_is_off(tool, record) && !stop_tracing) {1455printf("rtla timerlat hit stop tracing\n");14561457if (!params->no_aa)1458timerlat_auto_analysis(params->stop_us, params->stop_total_us);14591460return_value = FAILED;1461}14621463out_hist:1464timerlat_aa_destroy();1465if (dma_latency_fd >= 0)1466close(dma_latency_fd);1467if (params->deepest_idle_state >= -1) {1468for (i = 0; i < nr_cpus; i++) {1469if (params->cpus && !CPU_ISSET(i, ¶ms->monitored_cpus))1470continue;1471restore_cpu_idle_disable_state(i);1472}1473}1474trace_events_destroy(&record->trace, params->events);1475params->events = NULL;1476out_free:1477timerlat_free_histogram(tool->data);1478osnoise_destroy_tool(aa);1479osnoise_destroy_tool(record);1480osnoise_destroy_tool(tool);1481actions_destroy(¶ms->threshold_actions);1482actions_destroy(¶ms->end_actions);1483if (params->mode != TRACING_MODE_TRACEFS)1484timerlat_bpf_destroy();1485free(params);1486free_cpu_idle_disable_states();1487out_exit:1488exit(return_value);1489}149014911492