Alexandre Vicenzirtla: Fix tracer namef1432cd4 years agoHistory
914 lines · 22.5 KB · C
RawDownload
// SPDX-License-Identifier: GPL-2.0/* * Copyright (C) 2021 Red Hat Inc, Daniel Bristot de Oliveira <bristot@kernel.org> */ #include <getopt.h>#include <stdlib.h>#include <string.h>#include <signal.h>#include <unistd.h>#include <stdio.h>#include <time.h> #include "utils.h"#include "osnoise.h"#include "timerlat.h" struct timerlat_hist_params {	char			*cpus;	char			*monitored_cpus;	char			*trace_output;	unsigned long long	runtime;	long long		stop_us;	long long		stop_total_us;	long long		timerlat_period_us;	long long		print_stack;	int			sleep_time;	int			output_divisor;	int			duration;	int			set_sched;	int			dma_latency;	struct sched_attr	sched_param;	struct trace_events	*events; 	char			no_irq;	char			no_thread;	char			no_header;	char			no_summary;	char			no_index;	char			with_zeros;	int			bucket_size;	int			entries;}; struct timerlat_hist_cpu {	int			*irq;	int			*thread; 	int			irq_count;	int			thread_count; 	unsigned long long	min_irq;	unsigned long long	sum_irq;	unsigned long long	max_irq; 	unsigned long long	min_thread;	unsigned long long	sum_thread;	unsigned long long	max_thread;}; struct timerlat_hist_data {	struct timerlat_hist_cpu	*hist;	int				entries;	int				bucket_size;	int				nr_cpus;}; /* * timerlat_free_histogram - free runtime data */static voidtimerlat_free_histogram(struct timerlat_hist_data *data){	int cpu; 	/* one histogram for IRQ and one for thread, per CPU */	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (data->hist[cpu].irq)			free(data->hist[cpu].irq); 		if (data->hist[cpu].thread)			free(data->hist[cpu].thread);	} 	/* one set of histograms per CPU */	if (data->hist)		free(data->hist); 	free(data);} /* * timerlat_alloc_histogram - alloc runtime data */static struct timerlat_hist_data*timerlat_alloc_histogram(int nr_cpus, int entries, int bucket_size){	struct timerlat_hist_data *data;	int cpu; 	data = calloc(1, sizeof(*data));	if (!data)		return NULL; 	data->entries = entries;	data->bucket_size = bucket_size;	data->nr_cpus = nr_cpus; 	/* one set of histograms per CPU */	data->hist = calloc(1, sizeof(*data->hist) * nr_cpus);	if (!data->hist)		goto cleanup; 	/* one histogram for IRQ and one for thread, per cpu */	for (cpu = 0; cpu < nr_cpus; cpu++) {		data->hist[cpu].irq = calloc(1, sizeof(*data->hist->irq) * (entries + 1));		if (!data->hist[cpu].irq)			goto cleanup;		data->hist[cpu].thread = calloc(1, sizeof(*data->hist->thread) * (entries + 1));		if (!data->hist[cpu].thread)			goto cleanup;	} 	/* set the min to max */	for (cpu = 0; cpu < nr_cpus; cpu++) {		data->hist[cpu].min_irq = ~0;		data->hist[cpu].min_thread = ~0;	} 	return data; cleanup:	timerlat_free_histogram(data);	return NULL;} /* * timerlat_hist_update - record a new timerlat occurent on cpu, updating data */static voidtimerlat_hist_update(struct osnoise_tool *tool, int cpu,		     unsigned long long thread,		     unsigned long long latency){	struct timerlat_hist_params *params = tool->params;	struct timerlat_hist_data *data = tool->data;	int entries = data->entries;	int bucket;	int *hist; 	if (params->output_divisor)		latency = latency / params->output_divisor; 	if (data->bucket_size)		bucket = latency / data->bucket_size; 	if (!thread) {		hist = data->hist[cpu].irq;		data->hist[cpu].irq_count++;		update_min(&data->hist[cpu].min_irq, &latency);		update_sum(&data->hist[cpu].sum_irq, &latency);		update_max(&data->hist[cpu].max_irq, &latency);	} else {		hist = data->hist[cpu].thread;		data->hist[cpu].thread_count++;		update_min(&data->hist[cpu].min_thread, &latency);		update_sum(&data->hist[cpu].sum_thread, &latency);		update_max(&data->hist[cpu].max_thread, &latency);	} 	if (bucket < entries)		hist[bucket]++;	else		hist[entries]++;} /* * timerlat_hist_handler - this is the handler for timerlat tracer events */static inttimerlat_hist_handler(struct trace_seq *s, struct tep_record *record,		     struct tep_event *event, void *data){	struct trace_instance *trace = data;	unsigned long long thread, latency;	struct osnoise_tool *tool;	int cpu = record->cpu; 	tool = container_of(trace, struct osnoise_tool, trace); 	tep_get_field_val(s, event, "context", record, &thread, 1);	tep_get_field_val(s, event, "timer_latency", record, &latency, 1); 	timerlat_hist_update(tool, cpu, thread, latency); 	return 0;} /* * timerlat_hist_header - print the header of the tracer to the output */static void timerlat_hist_header(struct osnoise_tool *tool){	struct timerlat_hist_params *params = tool->params;	struct timerlat_hist_data *data = tool->data;	struct trace_seq *s = tool->trace.seq;	char duration[26];	int cpu; 	if (params->no_header)		return; 	get_duration(tool->start_time, duration, sizeof(duration));	trace_seq_printf(s, "# RTLA timerlat histogram\n");	trace_seq_printf(s, "# Time unit is %s (%s)\n",			params->output_divisor == 1 ? "nanoseconds" : "microseconds",			params->output_divisor == 1 ? "ns" : "us"); 	trace_seq_printf(s, "# Duration: %s\n", duration); 	if (!params->no_index)		trace_seq_printf(s, "Index"); 	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (params->cpus && !params->monitored_cpus[cpu])			continue; 		if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)			continue; 		if (!params->no_irq)			trace_seq_printf(s, "   IRQ-%03d", cpu); 		if (!params->no_thread)			trace_seq_printf(s, "   Thr-%03d", cpu);	}	trace_seq_printf(s, "\n");  	trace_seq_do_printf(s);	trace_seq_reset(s);} /* * timerlat_print_summary - print the summary of the hist data to the output */static voidtimerlat_print_summary(struct timerlat_hist_params *params,		       struct trace_instance *trace,		       struct timerlat_hist_data *data){	int cpu; 	if (params->no_summary)		return; 	if (!params->no_index)		trace_seq_printf(trace->seq, "count:"); 	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (params->cpus && !params->monitored_cpus[cpu])			continue; 		if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)			continue; 		if (!params->no_irq)			trace_seq_printf(trace->seq, "%9d ",					data->hist[cpu].irq_count); 		if (!params->no_thread)			trace_seq_printf(trace->seq, "%9d ",					data->hist[cpu].thread_count);	}	trace_seq_printf(trace->seq, "\n"); 	if (!params->no_index)		trace_seq_printf(trace->seq, "min:  "); 	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (params->cpus && !params->monitored_cpus[cpu])			continue; 		if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)			continue; 		if (!params->no_irq)			trace_seq_printf(trace->seq, "%9llu ",					data->hist[cpu].min_irq); 		if (!params->no_thread)			trace_seq_printf(trace->seq, "%9llu ",					data->hist[cpu].min_thread);	}	trace_seq_printf(trace->seq, "\n"); 	if (!params->no_index)		trace_seq_printf(trace->seq, "avg:  "); 	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (params->cpus && !params->monitored_cpus[cpu])			continue; 		if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)			continue; 		if (!params->no_irq) {			if (data->hist[cpu].irq_count)				trace_seq_printf(trace->seq, "%9llu ",						 data->hist[cpu].sum_irq / data->hist[cpu].irq_count);			else				trace_seq_printf(trace->seq, "        - ");		} 		if (!params->no_thread) {			if (data->hist[cpu].thread_count)				trace_seq_printf(trace->seq, "%9llu ",						data->hist[cpu].sum_thread / data->hist[cpu].thread_count);			else				trace_seq_printf(trace->seq, "        - ");		}	}	trace_seq_printf(trace->seq, "\n"); 	if (!params->no_index)		trace_seq_printf(trace->seq, "max:  "); 	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (params->cpus && !params->monitored_cpus[cpu])			continue; 		if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)			continue; 		if (!params->no_irq)			trace_seq_printf(trace->seq, "%9llu ",					data->hist[cpu].max_irq); 		if (!params->no_thread)			trace_seq_printf(trace->seq, "%9llu ",					data->hist[cpu].max_thread);	}	trace_seq_printf(trace->seq, "\n");	trace_seq_do_printf(trace->seq);	trace_seq_reset(trace->seq);} /* * timerlat_print_stats - print data for all CPUs */static voidtimerlat_print_stats(struct timerlat_hist_params *params, struct osnoise_tool *tool){	struct timerlat_hist_data *data = tool->data;	struct trace_instance *trace = &tool->trace;	int bucket, cpu;	int total; 	timerlat_hist_header(tool); 	for (bucket = 0; bucket < data->entries; bucket++) {		total = 0; 		if (!params->no_index)			trace_seq_printf(trace->seq, "%-6d",					 bucket * data->bucket_size); 		for (cpu = 0; cpu < data->nr_cpus; cpu++) {			if (params->cpus && !params->monitored_cpus[cpu])				continue; 			if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)				continue; 			if (!params->no_irq) {				total += data->hist[cpu].irq[bucket];				trace_seq_printf(trace->seq, "%9d ",						data->hist[cpu].irq[bucket]);			} 			if (!params->no_thread) {				total += data->hist[cpu].thread[bucket];				trace_seq_printf(trace->seq, "%9d ",						data->hist[cpu].thread[bucket]);			} 		} 		if (total == 0 && !params->with_zeros) {			trace_seq_reset(trace->seq);			continue;		} 		trace_seq_printf(trace->seq, "\n");		trace_seq_do_printf(trace->seq);		trace_seq_reset(trace->seq);	} 	if (!params->no_index)		trace_seq_printf(trace->seq, "over: "); 	for (cpu = 0; cpu < data->nr_cpus; cpu++) {		if (params->cpus && !params->monitored_cpus[cpu])			continue; 		if (!data->hist[cpu].irq_count && !data->hist[cpu].thread_count)			continue; 		if (!params->no_irq)			trace_seq_printf(trace->seq, "%9d ",					 data->hist[cpu].irq[data->entries]); 		if (!params->no_thread)			trace_seq_printf(trace->seq, "%9d ",					 data->hist[cpu].thread[data->entries]);	}	trace_seq_printf(trace->seq, "\n");	trace_seq_do_printf(trace->seq);	trace_seq_reset(trace->seq); 	timerlat_print_summary(params, trace, data);} /* * timerlat_hist_usage - prints timerlat top usage message */static void timerlat_hist_usage(char *usage){	int i; 	char *msg[] = {		"",		"  usage: [rtla] timerlat hist [-h] [-q] [-d s] [-D] [-n] [-a us] [-p us] [-i us] [-T us] [-s us] \\",		"         [-t[=file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] \\",		"	  [-P priority] [-E N] [-b N] [--no-irq] [--no-thread] [--no-header] [--no-summary] \\",		"	  [--no-index] [--with-zeros] [--dma-latency us]",		"",		"	  -h/--help: print this menu",		"	  -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit",		"	  -p/--period us: timerlat period in us",		"	  -i/--irq us: stop trace if the irq latency is higher than the argument in us",		"	  -T/--thread us: stop trace if the thread latency is higher than the argument in us",		"	  -s/--stack us: save the stack trace at the IRQ if a thread latency is higher than the argument in us",		"	  -c/--cpus cpus: run the tracer only on the given cpus",		"	  -d/--duration time[m|h|d]: duration of the session in seconds",		"	  -D/--debug: print debug info",		"	  -t/--trace[=file]: save the stopped trace to [file|timerlat_trace.txt]",		"	  -e/--event <sys:event>: enable the <sys:event> in the trace instance, multiple -e are allowed",		"	     --filter <filter>: enable a trace event filter to the previous -e event",		"	     --trigger <trigger>: enable a trace event trigger to the previous -e event",		"	  -n/--nano: display data in nanoseconds",		"	  -b/--bucket-size N: set the histogram bucket size (default 1)",		"	  -E/--entries N: set the number of entries of the histogram (default 256)",		"	     --no-irq: ignore IRQ latencies",		"	     --no-thread: ignore thread latencies",		"	     --no-header: do not print header",		"	     --no-summary: do not print summary",		"	     --no-index: do not print index",		"	     --with-zeros: print zero only entries",		"	     --dma-latency us: set /dev/cpu_dma_latency latency <us> to reduce exit from idle latency",		"	  -P/--priority o:prio|r:prio|f:prio|d:runtime:period : set scheduling parameters",		"		o:prio - use SCHED_OTHER with prio",		"		r:prio - use SCHED_RR with prio",		"		f:prio - use SCHED_FIFO with prio",		"		d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with runtime and period",		"						       in nanoseconds",		NULL,	}; 	if (usage)		fprintf(stderr, "%s\n", usage); 	fprintf(stderr, "rtla timerlat hist: a per-cpu histogram of the timer latency (version %s)\n",			VERSION); 	for (i = 0; msg[i]; i++)		fprintf(stderr, "%s\n", msg[i]);	exit(1);} /* * timerlat_hist_parse_args - allocs, parse and fill the cmd line parameters */static struct timerlat_hist_params*timerlat_hist_parse_args(int argc, char *argv[]){	struct timerlat_hist_params *params;	struct trace_events *tevent;	int auto_thresh;	int retval;	int c; 	params = calloc(1, sizeof(*params));	if (!params)		exit(1); 	/* disabled by default */	params->dma_latency = -1; 	/* display data in microseconds */

Lines 1–500 of 914.