[deliverable/linux.git] / tools / perf / builtin-trace.c

#include <traceevent/event-parse.h>
#include "builtin.h"
#include "util/color.h"
#include "util/evlist.h"
#include "util/machine.h"
#include "util/thread.h"
#include "util/parse-options.h"
#include "util/thread_map.h"

#include <libaudit.h>
#include <stdlib.h>

static struct syscall_fmt {
	const char *name;
	const char *alias;
	bool	   errmsg;
	bool	   timeout;
} syscall_fmts[] = {
	{ .name	    = "access",	    .errmsg = true, },
	{ .name	    = "arch_prctl", .errmsg = true, .alias = "prctl", },
	{ .name	    = "fstat",	    .errmsg = true, .alias = "newfstat", },
	{ .name	    = "fstatat",    .errmsg = true, .alias = "newfstatat", },
	{ .name	    = "futex",	    .errmsg = true, },
	{ .name	    = "open",	    .errmsg = true, },
	{ .name	    = "poll",	    .errmsg = true, .timeout = true, },
	{ .name	    = "ppoll",	    .errmsg = true, .timeout = true, },
	{ .name	    = "read",	    .errmsg = true, },
	{ .name	    = "recvfrom",   .errmsg = true, },
	{ .name	    = "select",	    .errmsg = true, .timeout = true, },
	{ .name	    = "socket",	    .errmsg = true, },
	{ .name	    = "stat",	    .errmsg = true, .alias = "newstat", },
};

static int syscall_fmt__cmp(const void *name, const void *fmtp)
{
	const struct syscall_fmt *fmt = fmtp;
	return strcmp(name, fmt->name);
}

static struct syscall_fmt *syscall_fmt__find(const char *name)
{
	const int nmemb = ARRAY_SIZE(syscall_fmts);
	return bsearch(name, syscall_fmts, nmemb, sizeof(struct syscall_fmt), syscall_fmt__cmp);
}

struct syscall {
	struct event_format *tp_format;
	const char	    *name;
	struct syscall_fmt  *fmt;
};

static size_t fprintf_duration(unsigned long t, FILE *fp)
{
	double duration = (double)t / NSEC_PER_MSEC;
	size_t printed = fprintf(fp, "(");

	if (duration >= 1.0)
		printed += color_fprintf(fp, PERF_COLOR_RED, "%6.3f ms", duration);
	else if (duration >= 0.01)
		printed += color_fprintf(fp, PERF_COLOR_YELLOW, "%6.3f ms", duration);
	else
		printed += color_fprintf(fp, PERF_COLOR_NORMAL, "%6.3f ms", duration);
	return printed + fprintf(stdout, "): ");
}

struct thread_trace {
	u64		  entry_time;
	u64		  exit_time;
	bool		  entry_pending;
	unsigned long	  nr_events;
	char		  *entry_str;
	double		  runtime_ms;
};

static struct thread_trace *thread_trace__new(void)
{
	return zalloc(sizeof(struct thread_trace));
}

static struct thread_trace *thread__trace(struct thread *thread)
{
	struct thread_trace *ttrace;

	if (thread == NULL)
		goto fail;

	if (thread->priv == NULL)
		thread->priv = thread_trace__new();
		
	if (thread->priv == NULL)
		goto fail;

	ttrace = thread->priv;
	++ttrace->nr_events;

	return ttrace;
fail:
	color_fprintf(stdout, PERF_COLOR_RED,
		      "WARNING: not enough memory, dropping samples!\n");
	return NULL;
}

struct trace {
	int			audit_machine;
	struct {
		int		max;
		struct syscall  *table;
	} syscalls;
	struct perf_record_opts opts;
	struct machine		host;
	u64			base_time;
	unsigned long		nr_events;
	bool			sched;
	bool			multiple_threads;
	double			duration_filter;
	double			runtime_ms;
};

static bool trace__filter_duration(struct trace *trace, double t)
{
	return t < (trace->duration_filter * NSEC_PER_MSEC);
}

static size_t trace__fprintf_tstamp(struct trace *trace, u64 tstamp, FILE *fp)
{
	double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;

	return fprintf(fp, "%10.3f ", ts);
}

static bool done = false;

static void sig_handler(int sig __maybe_unused)
{
	done = true;
}

static size_t trace__fprintf_entry_head(struct trace *trace, struct thread *thread,
					u64 duration, u64 tstamp, FILE *fp)
{
	size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
	printed += fprintf_duration(duration, fp);

	if (trace->multiple_threads)
		printed += fprintf(fp, "%d ", thread->pid);

	return printed;
}

static int trace__process_event(struct machine *machine, union perf_event *event)
{
	int ret = 0;

	switch (event->header.type) {
	case PERF_RECORD_LOST:
		color_fprintf(stdout, PERF_COLOR_RED,
			      "LOST %" PRIu64 " events!\n", event->lost.lost);
		ret = machine__process_lost_event(machine, event);
	default:
		ret = machine__process_event(machine, event);
		break;
	}

	return ret;
}

static int trace__tool_process(struct perf_tool *tool __maybe_unused,
			       union perf_event *event,
			       struct perf_sample *sample __maybe_unused,
			       struct machine *machine)
{
	return trace__process_event(machine, event);
}

static int trace__symbols_init(struct trace *trace, struct perf_evlist *evlist)
{
	int err = symbol__init();

	if (err)
		return err;

	machine__init(&trace->host, "", HOST_KERNEL_ID);
	machine__create_kernel_maps(&trace->host);

	if (perf_target__has_task(&trace->opts.target)) {
		err = perf_event__synthesize_thread_map(NULL, evlist->threads,
							trace__tool_process,
							&trace->host);
	} else {
		err = perf_event__synthesize_threads(NULL, trace__tool_process,
						     &trace->host);
	}

	if (err)
		symbol__exit();

	return err;
}

static int trace__read_syscall_info(struct trace *trace, int id)
{
	char tp_name[128];
	struct syscall *sc;
	const char *name = audit_syscall_to_name(id, trace->audit_machine);

	if (name == NULL)
		return -1;

	if (id > trace->syscalls.max) {
		struct syscall *nsyscalls = realloc(trace->syscalls.table, (id + 1) * sizeof(*sc));

		if (nsyscalls == NULL)
			return -1;

		if (trace->syscalls.max != -1) {
			memset(nsyscalls + trace->syscalls.max + 1, 0,
			       (id - trace->syscalls.max) * sizeof(*sc));
		} else {
			memset(nsyscalls, 0, (id + 1) * sizeof(*sc));
		}

		trace->syscalls.table = nsyscalls;
		trace->syscalls.max   = id;
	}

	sc = trace->syscalls.table + id;
	sc->name = name;
	sc->fmt  = syscall_fmt__find(sc->name);

	snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->name);
	sc->tp_format = event_format__new("syscalls", tp_name);

	if (sc->tp_format == NULL && sc->fmt && sc->fmt->alias) {
		snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->fmt->alias);
		sc->tp_format = event_format__new("syscalls", tp_name);
	}

	return sc->tp_format != NULL ? 0 : -1;
}

static size_t syscall__scnprintf_args(struct syscall *sc, char *bf, size_t size,
				      unsigned long *args)
{
	int i = 0;
	size_t printed = 0;

	if (sc->tp_format != NULL) {
		struct format_field *field;

		for (field = sc->tp_format->format.fields->next; field; field = field->next) {
			printed += scnprintf(bf + printed, size - printed,
					     "%s%s: %ld", printed ? ", " : "",
					     field->name, args[i++]);
		}
	} else {
		while (i < 6) {
			printed += scnprintf(bf + printed, size - printed,
					     "%sarg%d: %ld",
					     printed ? ", " : "", i, args[i]);
			++i;
		}
	}

	return printed;
}

typedef int (*tracepoint_handler)(struct trace *trace, struct perf_evsel *evsel,
				  struct perf_sample *sample);

static struct syscall *trace__syscall_info(struct trace *trace,
					   struct perf_evsel *evsel,
					   struct perf_sample *sample)
{
	int id = perf_evsel__intval(evsel, sample, "id");

	if (id < 0) {
		printf("Invalid syscall %d id, skipping...\n", id);
		return NULL;
	}

	if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL) &&
	    trace__read_syscall_info(trace, id))
		goto out_cant_read;

	if ((id > trace->syscalls.max || trace->syscalls.table[id].name == NULL))
		goto out_cant_read;

	return &trace->syscalls.table[id];

out_cant_read:
	printf("Problems reading syscall %d", id);
	if (id <= trace->syscalls.max && trace->syscalls.table[id].name != NULL)
		printf("(%s)", trace->syscalls.table[id].name);
	puts(" information");
	return NULL;
}

static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
			    struct perf_sample *sample)
{
	char *msg;
	void *args;
	size_t printed = 0;
	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
	struct syscall *sc = trace__syscall_info(trace, evsel, sample);
	struct thread_trace *ttrace = thread__trace(thread);

	if (ttrace == NULL || sc == NULL)
		return -1;

	args = perf_evsel__rawptr(evsel, sample, "args");
	if (args == NULL) {
		printf("Problems reading syscall arguments\n");
		return -1;
	}

	ttrace = thread->priv;

	if (ttrace->entry_str == NULL) {
		ttrace->entry_str = malloc(1024);
		if (!ttrace->entry_str)
			return -1;
	}

	ttrace->entry_time = sample->time;
	msg = ttrace->entry_str;
	printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);

	printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed,  args);

	if (!strcmp(sc->name, "exit_group") || !strcmp(sc->name, "exit")) {
		if (!trace->duration_filter) {
			trace__fprintf_entry_head(trace, thread, 1, sample->time, stdout);
			printf("%-70s\n", ttrace->entry_str);
		}
	} else
		ttrace->entry_pending = true;

	return 0;
}

static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
			   struct perf_sample *sample)
{
	int ret;
	u64 duration = 0;
	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
	struct thread_trace *ttrace = thread__trace(thread);
	struct syscall *sc = trace__syscall_info(trace, evsel, sample);

	if (ttrace == NULL || sc == NULL)
		return -1;

	ret = perf_evsel__intval(evsel, sample, "ret");

	ttrace = thread->priv;

	ttrace->exit_time = sample->time;

	if (ttrace->entry_time) {
		duration = sample->time - ttrace->entry_time;
		if (trace__filter_duration(trace, duration))
			goto out;
	} else if (trace->duration_filter)
		goto out;

	trace__fprintf_entry_head(trace, thread, duration, sample->time, stdout);

	if (ttrace->entry_pending) {
		printf("%-70s", ttrace->entry_str);
	} else {
		printf(" ... [");
		color_fprintf(stdout, PERF_COLOR_YELLOW, "continued");
		printf("]: %s()", sc->name);
	}

	if (ret < 0 && sc->fmt && sc->fmt->errmsg) {
		char bf[256];
		const char *emsg = strerror_r(-ret, bf, sizeof(bf)),
			   *e = audit_errno_to_name(-ret);

		printf(") = -1 %s %s", e, emsg);
	} else if (ret == 0 && sc->fmt && sc->fmt->timeout)
		printf(") = 0 Timeout");
	else
		printf(") = %d", ret);

	putchar('\n');
out:
	ttrace->entry_pending = false;

	return 0;
}

static int trace__sched_stat_runtime(struct trace *trace, struct perf_evsel *evsel,
				     struct perf_sample *sample)
{
        u64 runtime = perf_evsel__intval(evsel, sample, "runtime");
	double runtime_ms = (double)runtime / NSEC_PER_MSEC;
	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
	struct thread_trace *ttrace = thread__trace(thread);

	if (ttrace == NULL)
		goto out_dump;

	ttrace->runtime_ms += runtime_ms;
	trace->runtime_ms += runtime_ms;
	return 0;

out_dump:
	printf("%s: comm=%s,pid=%u,runtime=%" PRIu64 ",vruntime=%" PRIu64 ")\n",
	       evsel->name,
	       perf_evsel__strval(evsel, sample, "comm"),
	       (pid_t)perf_evsel__intval(evsel, sample, "pid"),
	       runtime,
	       perf_evsel__intval(evsel, sample, "vruntime"));
	return 0;
}

static int trace__run(struct trace *trace, int argc, const char **argv)
{
	struct perf_evlist *evlist = perf_evlist__new();
	struct perf_evsel *evsel;
	int err = -1, i;
	unsigned long before;
	const bool forks = argc > 0;

	if (evlist == NULL) {
		printf("Not enough memory to run!\n");
		goto out;
	}

	if (perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_enter", trace__sys_enter) ||
	    perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_exit", trace__sys_exit)) {
		printf("Couldn't read the raw_syscalls tracepoints information!\n");
		goto out_delete_evlist;
	}

	if (trace->sched &&
	    perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
				   trace__sched_stat_runtime)) {
		printf("Couldn't read the sched_stat_runtime tracepoint information!\n");
		goto out_delete_evlist;
	}

	err = perf_evlist__create_maps(evlist, &trace->opts.target);
	if (err < 0) {
		printf("Problems parsing the target to trace, check your options!\n");
		goto out_delete_evlist;
	}

	err = trace__symbols_init(trace, evlist);
	if (err < 0) {
		printf("Problems initializing symbol libraries!\n");
		goto out_delete_maps;
	}

	perf_evlist__config(evlist, &trace->opts);

	signal(SIGCHLD, sig_handler);
	signal(SIGINT, sig_handler);

	if (forks) {
		err = perf_evlist__prepare_workload(evlist, &trace->opts.target,
						    argv, false, false);
		if (err < 0) {
			printf("Couldn't run the workload!\n");
			goto out_delete_maps;
		}
	}

	err = perf_evlist__open(evlist);
	if (err < 0) {
		printf("Couldn't create the events: %s\n", strerror(errno));
		goto out_delete_maps;
	}

	err = perf_evlist__mmap(evlist, UINT_MAX, false);
	if (err < 0) {
		printf("Couldn't mmap the events: %s\n", strerror(errno));
		goto out_close_evlist;
	}

	perf_evlist__enable(evlist);

	if (forks)
		perf_evlist__start_workload(evlist);

	trace->multiple_threads = evlist->threads->map[0] == -1 || evlist->threads->nr > 1;
again:
	before = trace->nr_events;

	for (i = 0; i < evlist->nr_mmaps; i++) {
		union perf_event *event;

		while ((event = perf_evlist__mmap_read(evlist, i)) != NULL) {
			const u32 type = event->header.type;
			tracepoint_handler handler;
			struct perf_sample sample;

			++trace->nr_events;

			err = perf_evlist__parse_sample(evlist, event, &sample);
			if (err) {
				printf("Can't parse sample, err = %d, skipping...\n", err);
				continue;
			}

			if (trace->base_time == 0)
				trace->base_time = sample.time;

			if (type != PERF_RECORD_SAMPLE) {
				trace__process_event(&trace->host, event);
				continue;
			}

			evsel = perf_evlist__id2evsel(evlist, sample.id);
			if (evsel == NULL) {
				printf("Unknown tp ID %" PRIu64 ", skipping...\n", sample.id);
				continue;
			}

			if (sample.raw_data == NULL) {
				printf("%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
				       perf_evsel__name(evsel), sample.tid,
				       sample.cpu, sample.raw_size);
				continue;
			}

			handler = evsel->handler.func;
			handler(trace, evsel, &sample);
		}
	}

	if (trace->nr_events == before) {
		if (done)
			goto out_unmap_evlist;

		poll(evlist->pollfd, evlist->nr_fds, -1);
	}

	if (done)
		perf_evlist__disable(evlist);

	goto again;

out_unmap_evlist:
	perf_evlist__munmap(evlist);
out_close_evlist:
	perf_evlist__close(evlist);
out_delete_maps:
	perf_evlist__delete_maps(evlist);
out_delete_evlist:
	perf_evlist__delete(evlist);
out:
	return err;
}

static size_t trace__fprintf_threads_header(FILE *fp)
{
	size_t printed;

	printed  = fprintf(fp, "\n _____________________________________________________________________\n");
	printed += fprintf(fp," __)    Summary of events    (__\n\n");
	printed += fprintf(fp,"              [ task - pid ]     [ events ] [ ratio ]  [ runtime ]\n");
	printed += fprintf(fp," _____________________________________________________________________\n\n");

	return printed;
}

static size_t trace__fprintf_thread_summary(struct trace *trace, FILE *fp)
{
	size_t printed = trace__fprintf_threads_header(fp);
	struct rb_node *nd;

	for (nd = rb_first(&trace->host.threads); nd; nd = rb_next(nd)) {
		struct thread *thread = rb_entry(nd, struct thread, rb_node);
		struct thread_trace *ttrace = thread->priv;
		const char *color;
		double ratio;

		if (ttrace == NULL)
			continue;

		ratio = (double)ttrace->nr_events / trace->nr_events * 100.0;

		color = PERF_COLOR_NORMAL;
		if (ratio > 50.0)
			color = PERF_COLOR_RED;
		else if (ratio > 25.0)
			color = PERF_COLOR_GREEN;
		else if (ratio > 5.0)
			color = PERF_COLOR_YELLOW;

		printed += color_fprintf(fp, color, "%20s", thread->comm);
		printed += fprintf(fp, " - %-5d :%11lu   [", thread->pid, ttrace->nr_events);
		printed += color_fprintf(fp, color, "%5.1f%%", ratio);
		printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
	}

	return printed;
}

static int trace__set_duration(const struct option *opt, const char *str,
			       int unset __maybe_unused)
{
	struct trace *trace = opt->value;

	trace->duration_filter = atof(str);
	return 0;
}

int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
{
	const char * const trace_usage[] = {
		"perf trace [<options>] [<command>]",
		"perf trace [<options>] -- <command> [<options>]",
		NULL
	};
	struct trace trace = {
		.audit_machine = audit_detect_machine(),
		.syscalls = {
			. max = -1,
		},
		.opts = {
			.target = {
				.uid	   = UINT_MAX,
				.uses_mmap = true,
			},
			.user_freq     = UINT_MAX,
			.user_interval = ULLONG_MAX,
			.no_delay      = true,
			.mmap_pages    = 1024,
		},
	};
	const struct option trace_options[] = {
	OPT_STRING('p', "pid", &trace.opts.target.pid, "pid",
		    "trace events on existing process id"),
	OPT_STRING(0, "tid", &trace.opts.target.tid, "tid",
		    "trace events on existing thread id"),
	OPT_BOOLEAN(0, "all-cpus", &trace.opts.target.system_wide,
		    "system-wide collection from all CPUs"),
	OPT_STRING(0, "cpu", &trace.opts.target.cpu_list, "cpu",
		    "list of cpus to monitor"),
	OPT_BOOLEAN(0, "no-inherit", &trace.opts.no_inherit,
		    "child tasks do not inherit counters"),
	OPT_UINTEGER(0, "mmap-pages", &trace.opts.mmap_pages,
		     "number of mmap data pages"),
	OPT_STRING(0, "uid", &trace.opts.target.uid_str, "user",
		   "user to profile"),
	OPT_CALLBACK(0, "duration", &trace, "float",
		     "show only events with duration > N.M ms",
		     trace__set_duration),
	OPT_BOOLEAN(0, "sched", &trace.sched, "show blocking scheduler events"),
	OPT_END()
	};
	int err;
	char bf[BUFSIZ];

	argc = parse_options(argc, argv, trace_options, trace_usage, 0);

	err = perf_target__validate(&trace.opts.target);
	if (err) {
		perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
		printf("%s", bf);
		return err;
	}

	err = perf_target__parse_uid(&trace.opts.target);
	if (err) {
		perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
		printf("%s", bf);
		return err;
	}

	if (!argc && perf_target__none(&trace.opts.target))
		trace.opts.target.system_wide = true;

	err = trace__run(&trace, argc, argv);

	if (trace.sched && !err)
		trace__fprintf_thread_summary(&trace, stdout);

	return err;
}
Commit	Line	Data
4e319027	1	#include <traceevent/event-parse.h>
514f1c67	2	#include "builtin.h"
752fde44	3	#include "util/color.h"
514f1c67	4	#include "util/evlist.h"
752fde44 ACM	5	#include "util/machine.h"
752fde44 ACM	6	#include "util/thread.h"
514f1c67 ACM	7	#include "util/parse-options.h"
514f1c67 ACM	8	#include "util/thread_map.h"
514f1c67 ACM	9
	10	#include <libaudit.h>
	11	#include <stdlib.h>
	12
	13	static struct syscall_fmt {
	14	const char *name;
aec1930b	15	const char *alias;
514f1c67 ACM	16	bool errmsg;
	17	bool timeout;
	18	} syscall_fmts[] = {
8b745263	19	{ .name = "access", .errmsg = true, },
aec1930b ACM	20	{ .name = "arch_prctl", .errmsg = true, .alias = "prctl", },
	21	{ .name = "fstat", .errmsg = true, .alias = "newfstat", },
	22	{ .name = "fstatat", .errmsg = true, .alias = "newfstatat", },
	23	{ .name = "futex", .errmsg = true, },
8b745263	24	{ .name = "open", .errmsg = true, },
aec1930b ACM	25	{ .name = "poll", .errmsg = true, .timeout = true, },
	26	{ .name = "ppoll", .errmsg = true, .timeout = true, },
	27	{ .name = "read", .errmsg = true, },
	28	{ .name = "recvfrom", .errmsg = true, },
	29	{ .name = "select", .errmsg = true, .timeout = true, },
8b745263	30	{ .name = "socket", .errmsg = true, },
aec1930b	31	{ .name = "stat", .errmsg = true, .alias = "newstat", },
514f1c67 ACM	32	};
	33
	34	static int syscall_fmt__cmp(const void name, const void fmtp)
	35	{
	36	const struct syscall_fmt *fmt = fmtp;
	37	return strcmp(name, fmt->name);
	38	}
	39
	40	static struct syscall_fmt syscall_fmt__find(const char name)
	41	{
	42	const int nmemb = ARRAY_SIZE(syscall_fmts);
	43	return bsearch(name, syscall_fmts, nmemb, sizeof(struct syscall_fmt), syscall_fmt__cmp);
	44	}
	45
	46	struct syscall {
	47	struct event_format *tp_format;
	48	const char *name;
	49	struct syscall_fmt *fmt;
	50	};
	51
60c907ab ACM	52	static size_t fprintf_duration(unsigned long t, FILE *fp)
	53	{
	54	double duration = (double)t / NSEC_PER_MSEC;
	55	size_t printed = fprintf(fp, "(");
	56
	57	if (duration >= 1.0)
	58	printed += color_fprintf(fp, PERF_COLOR_RED, "%6.3f ms", duration);
	59	else if (duration >= 0.01)
	60	printed += color_fprintf(fp, PERF_COLOR_YELLOW, "%6.3f ms", duration);
	61	else
	62	printed += color_fprintf(fp, PERF_COLOR_NORMAL, "%6.3f ms", duration);
	63	return printed + fprintf(stdout, "): ");
	64	}
	65
752fde44 ACM	66	struct thread_trace {
	67	u64 entry_time;
	68	u64 exit_time;
	69	bool entry_pending;
efd5745e	70	unsigned long nr_events;
752fde44	71	char *entry_str;
1302d88e	72	double runtime_ms;
752fde44 ACM	73	};
	74
	75	static struct thread_trace *thread_trace__new(void)
	76	{
	77	return zalloc(sizeof(struct thread_trace));
	78	}
	79
	80	static struct thread_trace thread__trace(struct thread thread)
	81	{
efd5745e ACM	82	struct thread_trace *ttrace;
efd5745e ACM	83
752fde44 ACM	84	if (thread == NULL)
	85	goto fail;
	86
	87	if (thread->priv == NULL)
	88	thread->priv = thread_trace__new();
efd5745e	89
752fde44 ACM	90	if (thread->priv == NULL)
	91	goto fail;
	92
efd5745e ACM	93	ttrace = thread->priv;
	94	++ttrace->nr_events;
	95
	96	return ttrace;
752fde44 ACM	97	fail:
	98	color_fprintf(stdout, PERF_COLOR_RED,
	99	"WARNING: not enough memory, dropping samples!\n");
	100	return NULL;
	101	}
	102
514f1c67 ACM	103	struct trace {
	104	int audit_machine;
	105	struct {
	106	int max;
	107	struct syscall *table;
	108	} syscalls;
	109	struct perf_record_opts opts;
752fde44 ACM	110	struct machine host;
752fde44 ACM	111	u64 base_time;
efd5745e	112	unsigned long nr_events;
1302d88e	113	bool sched;
752fde44	114	bool multiple_threads;
ae9ed035	115	double duration_filter;
1302d88e	116	double runtime_ms;
514f1c67 ACM	117	};
514f1c67 ACM	118
ae9ed035 ACM	119	static bool trace__filter_duration(struct trace *trace, double t)
	120	{
	121	return t < (trace->duration_filter * NSEC_PER_MSEC);
	122	}
	123
752fde44 ACM	124	static size_t trace__fprintf_tstamp(struct trace trace, u64 tstamp, FILE fp)
	125	{
	126	double ts = (double)(tstamp - trace->base_time) / NSEC_PER_MSEC;
	127
60c907ab	128	return fprintf(fp, "%10.3f ", ts);
752fde44 ACM	129	}
752fde44 ACM	130
f15eb531 NK	131	static bool done = false;
	132
	133	static void sig_handler(int sig __maybe_unused)
	134	{
	135	done = true;
	136	}
	137
752fde44	138	static size_t trace__fprintf_entry_head(struct trace trace, struct thread thread,
60c907ab	139	u64 duration, u64 tstamp, FILE *fp)
752fde44 ACM	140	{
752fde44 ACM	141	size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
60c907ab	142	printed += fprintf_duration(duration, fp);
752fde44 ACM	143
	144	if (trace->multiple_threads)
	145	printed += fprintf(fp, "%d ", thread->pid);
	146
	147	return printed;
	148	}
	149
	150	static int trace__process_event(struct machine machine, union perf_event event)
	151	{
	152	int ret = 0;
	153
	154	switch (event->header.type) {
	155	case PERF_RECORD_LOST:
	156	color_fprintf(stdout, PERF_COLOR_RED,
	157	"LOST %" PRIu64 " events!\n", event->lost.lost);
	158	ret = machine__process_lost_event(machine, event);
	159	default:
	160	ret = machine__process_event(machine, event);
	161	break;
	162	}
	163
	164	return ret;
	165	}
	166
	167	static int trace__tool_process(struct perf_tool *tool __maybe_unused,
	168	union perf_event *event,
	169	struct perf_sample *sample __maybe_unused,
	170	struct machine *machine)
	171	{
	172	return trace__process_event(machine, event);
	173	}
	174
	175	static int trace__symbols_init(struct trace trace, struct perf_evlist evlist)
	176	{
	177	int err = symbol__init();
	178
	179	if (err)
	180	return err;
	181
	182	machine__init(&trace->host, "", HOST_KERNEL_ID);
	183	machine__create_kernel_maps(&trace->host);
	184
	185	if (perf_target__has_task(&trace->opts.target)) {
	186	err = perf_event__synthesize_thread_map(NULL, evlist->threads,
	187	trace__tool_process,
	188	&trace->host);
	189	} else {
	190	err = perf_event__synthesize_threads(NULL, trace__tool_process,
	191	&trace->host);
	192	}
	193
	194	if (err)
	195	symbol__exit();
	196
	197	return err;
	198	}
	199
514f1c67 ACM	200	static int trace__read_syscall_info(struct trace *trace, int id)
	201	{
	202	char tp_name[128];
	203	struct syscall *sc;
3a531260 ACM	204	const char *name = audit_syscall_to_name(id, trace->audit_machine);
	205
	206	if (name == NULL)
	207	return -1;
514f1c67 ACM	208
	209	if (id > trace->syscalls.max) {
	210	struct syscall nsyscalls = realloc(trace->syscalls.table, (id + 1) sizeof(*sc));
	211
	212	if (nsyscalls == NULL)
	213	return -1;
	214
	215	if (trace->syscalls.max != -1) {
	216	memset(nsyscalls + trace->syscalls.max + 1, 0,
	217	(id - trace->syscalls.max) * sizeof(*sc));
	218	} else {
	219	memset(nsyscalls, 0, (id + 1) * sizeof(*sc));
	220	}
	221
	222	trace->syscalls.table = nsyscalls;
	223	trace->syscalls.max = id;
	224	}
	225
	226	sc = trace->syscalls.table + id;
3a531260 ACM	227	sc->name = name;
3a531260 ACM	228	sc->fmt = syscall_fmt__find(sc->name);
514f1c67	229
aec1930b	230	snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->name);
514f1c67	231	sc->tp_format = event_format__new("syscalls", tp_name);
aec1930b ACM	232
	233	if (sc->tp_format == NULL && sc->fmt && sc->fmt->alias) {
	234	snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->fmt->alias);
	235	sc->tp_format = event_format__new("syscalls", tp_name);
	236	}
514f1c67 ACM	237
	238	return sc->tp_format != NULL ? 0 : -1;
	239	}
	240
752fde44 ACM	241	static size_t syscall__scnprintf_args(struct syscall sc, char bf, size_t size,
752fde44 ACM	242	unsigned long *args)
514f1c67 ACM	243	{
	244	int i = 0;
	245	size_t printed = 0;
	246
	247	if (sc->tp_format != NULL) {
	248	struct format_field *field;
	249
	250	for (field = sc->tp_format->format.fields->next; field; field = field->next) {
752fde44 ACM	251	printed += scnprintf(bf + printed, size - printed,
	252	"%s%s: %ld", printed ? ", " : "",
	253	field->name, args[i++]);
514f1c67 ACM	254	}
	255	} else {
	256	while (i < 6) {
752fde44 ACM	257	printed += scnprintf(bf + printed, size - printed,
	258	"%sarg%d: %ld",
	259	printed ? ", " : "", i, args[i]);
514f1c67 ACM	260	++i;
	261	}
	262	}
	263
	264	return printed;
	265	}
	266
ba3d7dee ACM	267	typedef int (tracepoint_handler)(struct trace trace, struct perf_evsel *evsel,
	268	struct perf_sample *sample);
	269
	270	static struct syscall trace__syscall_info(struct trace trace,
	271	struct perf_evsel *evsel,
	272	struct perf_sample *sample)
	273	{
	274	int id = perf_evsel__intval(evsel, sample, "id");
	275
	276	if (id < 0) {
	277	printf("Invalid syscall %d id, skipping...\n", id);
	278	return NULL;
	279	}
	280
	281	if ((id > trace->syscalls.max \|\| trace->syscalls.table[id].name == NULL) &&
	282	trace__read_syscall_info(trace, id))
	283	goto out_cant_read;
	284
	285	if ((id > trace->syscalls.max \|\| trace->syscalls.table[id].name == NULL))
	286	goto out_cant_read;
	287
	288	return &trace->syscalls.table[id];
	289
	290	out_cant_read:
814d7a4d ACM	291	printf("Problems reading syscall %d", id);
	292	if (id <= trace->syscalls.max && trace->syscalls.table[id].name != NULL)
	293	printf("(%s)", trace->syscalls.table[id].name);
	294	puts(" information");
ba3d7dee ACM	295	return NULL;
	296	}
	297
	298	static int trace__sys_enter(struct trace trace, struct perf_evsel evsel,
	299	struct perf_sample *sample)
	300	{
752fde44	301	char *msg;
ba3d7dee	302	void *args;
752fde44 ACM	303	size_t printed = 0;
752fde44 ACM	304	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
ba3d7dee	305	struct syscall *sc = trace__syscall_info(trace, evsel, sample);
752fde44	306	struct thread_trace *ttrace = thread__trace(thread);
ba3d7dee	307
752fde44	308	if (ttrace == NULL \|\| sc == NULL)
ba3d7dee ACM	309	return -1;
	310
	311	args = perf_evsel__rawptr(evsel, sample, "args");
	312	if (args == NULL) {
	313	printf("Problems reading syscall arguments\n");
	314	return -1;
	315	}
	316
752fde44 ACM	317	ttrace = thread->priv;
	318
	319	if (ttrace->entry_str == NULL) {
	320	ttrace->entry_str = malloc(1024);
	321	if (!ttrace->entry_str)
	322	return -1;
	323	}
	324
	325	ttrace->entry_time = sample->time;
	326	msg = ttrace->entry_str;
	327	printed += scnprintf(msg + printed, 1024 - printed, "%s(", sc->name);
	328
	329	printed += syscall__scnprintf_args(sc, msg + printed, 1024 - printed, args);
	330
	331	if (!strcmp(sc->name, "exit_group") \|\| !strcmp(sc->name, "exit")) {
ae9ed035 ACM	332	if (!trace->duration_filter) {
	333	trace__fprintf_entry_head(trace, thread, 1, sample->time, stdout);
	334	printf("%-70s\n", ttrace->entry_str);
	335	}
752fde44 ACM	336	} else
752fde44 ACM	337	ttrace->entry_pending = true;
ba3d7dee ACM	338
	339	return 0;
	340	}
	341
	342	static int trace__sys_exit(struct trace trace, struct perf_evsel evsel,
	343	struct perf_sample *sample)
	344	{
	345	int ret;
60c907ab	346	u64 duration = 0;
752fde44 ACM	347	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
752fde44 ACM	348	struct thread_trace *ttrace = thread__trace(thread);
ba3d7dee ACM	349	struct syscall *sc = trace__syscall_info(trace, evsel, sample);
ba3d7dee ACM	350
752fde44	351	if (ttrace == NULL \|\| sc == NULL)
ba3d7dee ACM	352	return -1;
	353
	354	ret = perf_evsel__intval(evsel, sample, "ret");
	355
752fde44 ACM	356	ttrace = thread->priv;
	357
	358	ttrace->exit_time = sample->time;
	359
ae9ed035	360	if (ttrace->entry_time) {
60c907ab	361	duration = sample->time - ttrace->entry_time;
ae9ed035 ACM	362	if (trace__filter_duration(trace, duration))
	363	goto out;
	364	} else if (trace->duration_filter)
	365	goto out;
60c907ab ACM	366
60c907ab ACM	367	trace__fprintf_entry_head(trace, thread, duration, sample->time, stdout);
752fde44 ACM	368
	369	if (ttrace->entry_pending) {
	370	printf("%-70s", ttrace->entry_str);
	371	} else {
	372	printf(" ... [");
	373	color_fprintf(stdout, PERF_COLOR_YELLOW, "continued");
	374	printf("]: %s()", sc->name);
	375	}
	376
ba3d7dee ACM	377	if (ret < 0 && sc->fmt && sc->fmt->errmsg) {
	378	char bf[256];
	379	const char *emsg = strerror_r(-ret, bf, sizeof(bf)),
	380	*e = audit_errno_to_name(-ret);
	381
	382	printf(") = -1 %s %s", e, emsg);
	383	} else if (ret == 0 && sc->fmt && sc->fmt->timeout)
	384	printf(") = 0 Timeout");
	385	else
	386	printf(") = %d", ret);
	387
	388	putchar('\n');
ae9ed035	389	out:
752fde44 ACM	390	ttrace->entry_pending = false;
752fde44 ACM	391
ba3d7dee ACM	392	return 0;
	393	}
	394
1302d88e ACM	395	static int trace__sched_stat_runtime(struct trace trace, struct perf_evsel evsel,
	396	struct perf_sample *sample)
	397	{
	398	u64 runtime = perf_evsel__intval(evsel, sample, "runtime");
	399	double runtime_ms = (double)runtime / NSEC_PER_MSEC;
	400	struct thread *thread = machine__findnew_thread(&trace->host, sample->tid);
	401	struct thread_trace *ttrace = thread__trace(thread);
	402
	403	if (ttrace == NULL)
	404	goto out_dump;
	405
	406	ttrace->runtime_ms += runtime_ms;
	407	trace->runtime_ms += runtime_ms;
	408	return 0;
	409
	410	out_dump:
	411	printf("%s: comm=%s,pid=%u,runtime=%" PRIu64 ",vruntime=%" PRIu64 ")\n",
	412	evsel->name,
	413	perf_evsel__strval(evsel, sample, "comm"),
	414	(pid_t)perf_evsel__intval(evsel, sample, "pid"),
	415	runtime,
	416	perf_evsel__intval(evsel, sample, "vruntime"));
	417	return 0;
	418	}
	419
f15eb531	420	static int trace__run(struct trace trace, int argc, const char *argv)
514f1c67	421	{
334fe7a3	422	struct perf_evlist *evlist = perf_evlist__new();
ba3d7dee	423	struct perf_evsel *evsel;
efd5745e ACM	424	int err = -1, i;
efd5745e ACM	425	unsigned long before;
f15eb531	426	const bool forks = argc > 0;
514f1c67 ACM	427
	428	if (evlist == NULL) {
	429	printf("Not enough memory to run!\n");
	430	goto out;
	431	}
	432
39876e7d ACM	433	if (perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_enter", trace__sys_enter) \|\|
	434	perf_evlist__add_newtp(evlist, "raw_syscalls", "sys_exit", trace__sys_exit)) {
	435	printf("Couldn't read the raw_syscalls tracepoints information!\n");
514f1c67 ACM	436	goto out_delete_evlist;
	437	}
	438
1302d88e ACM	439	if (trace->sched &&
	440	perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
	441	trace__sched_stat_runtime)) {
	442	printf("Couldn't read the sched_stat_runtime tracepoint information!\n");
	443	goto out_delete_evlist;
	444	}
	445
514f1c67 ACM	446	err = perf_evlist__create_maps(evlist, &trace->opts.target);
	447	if (err < 0) {
	448	printf("Problems parsing the target to trace, check your options!\n");
	449	goto out_delete_evlist;
	450	}
	451
752fde44 ACM	452	err = trace__symbols_init(trace, evlist);
	453	if (err < 0) {
	454	printf("Problems initializing symbol libraries!\n");
3beb0861	455	goto out_delete_maps;
752fde44 ACM	456	}
752fde44 ACM	457
f77a9518	458	perf_evlist__config(evlist, &trace->opts);
514f1c67	459
f15eb531 NK	460	signal(SIGCHLD, sig_handler);
	461	signal(SIGINT, sig_handler);
	462
	463	if (forks) {
6ef73ec4	464	err = perf_evlist__prepare_workload(evlist, &trace->opts.target,
55e162ea	465	argv, false, false);
f15eb531 NK	466	if (err < 0) {
f15eb531 NK	467	printf("Couldn't run the workload!\n");
3beb0861	468	goto out_delete_maps;
f15eb531 NK	469	}
	470	}
	471
514f1c67 ACM	472	err = perf_evlist__open(evlist);
	473	if (err < 0) {
	474	printf("Couldn't create the events: %s\n", strerror(errno));
3beb0861	475	goto out_delete_maps;
514f1c67 ACM	476	}
	477
	478	err = perf_evlist__mmap(evlist, UINT_MAX, false);
	479	if (err < 0) {
	480	printf("Couldn't mmap the events: %s\n", strerror(errno));
3beb0861	481	goto out_close_evlist;
514f1c67 ACM	482	}
	483
	484	perf_evlist__enable(evlist);
f15eb531 NK	485
	486	if (forks)
	487	perf_evlist__start_workload(evlist);
	488
752fde44	489	trace->multiple_threads = evlist->threads->map[0] == -1 \|\| evlist->threads->nr > 1;
514f1c67	490	again:
efd5745e	491	before = trace->nr_events;
514f1c67 ACM	492
	493	for (i = 0; i < evlist->nr_mmaps; i++) {
	494	union perf_event *event;
	495
	496	while ((event = perf_evlist__mmap_read(evlist, i)) != NULL) {
	497	const u32 type = event->header.type;
ba3d7dee	498	tracepoint_handler handler;
514f1c67	499	struct perf_sample sample;
514f1c67	500
efd5745e	501	++trace->nr_events;
514f1c67	502
514f1c67 ACM	503	err = perf_evlist__parse_sample(evlist, event, &sample);
	504	if (err) {
	505	printf("Can't parse sample, err = %d, skipping...\n", err);
	506	continue;
	507	}
	508
752fde44 ACM	509	if (trace->base_time == 0)
	510	trace->base_time = sample.time;
	511
	512	if (type != PERF_RECORD_SAMPLE) {
	513	trace__process_event(&trace->host, event);
	514	continue;
	515	}
	516
514f1c67 ACM	517	evsel = perf_evlist__id2evsel(evlist, sample.id);
	518	if (evsel == NULL) {
	519	printf("Unknown tp ID %" PRIu64 ", skipping...\n", sample.id);
	520	continue;
	521	}
	522
fc551f8d ACM	523	if (sample.raw_data == NULL) {
	524	printf("%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
	525	perf_evsel__name(evsel), sample.tid,
	526	sample.cpu, sample.raw_size);
	527	continue;
	528	}
	529
ba3d7dee ACM	530	handler = evsel->handler.func;
ba3d7dee ACM	531	handler(trace, evsel, &sample);
514f1c67 ACM	532	}
	533	}
	534
efd5745e	535	if (trace->nr_events == before) {
f15eb531	536	if (done)
3beb0861	537	goto out_unmap_evlist;
f15eb531	538
514f1c67	539	poll(evlist->pollfd, evlist->nr_fds, -1);
f15eb531 NK	540	}
	541
	542	if (done)
	543	perf_evlist__disable(evlist);
514f1c67 ACM	544
	545	goto again;
	546
3beb0861 NK	547	out_unmap_evlist:
	548	perf_evlist__munmap(evlist);
	549	out_close_evlist:
	550	perf_evlist__close(evlist);
	551	out_delete_maps:
	552	perf_evlist__delete_maps(evlist);
514f1c67 ACM	553	out_delete_evlist:
	554	perf_evlist__delete(evlist);
	555	out:
	556	return err;
	557	}
	558
1302d88e ACM	559	static size_t trace__fprintf_threads_header(FILE *fp)
	560	{
	561	size_t printed;
	562
	563	printed = fprintf(fp, "\n _____________________________________________________________________\n");
	564	printed += fprintf(fp," __) Summary of events (__\n\n");
	565	printed += fprintf(fp," [ task - pid ] [ events ] [ ratio ] [ runtime ]\n");
	566	printed += fprintf(fp," _____________________________________________________________________\n\n");
	567
	568	return printed;
	569	}
	570
	571	static size_t trace__fprintf_thread_summary(struct trace trace, FILE fp)
	572	{
	573	size_t printed = trace__fprintf_threads_header(fp);
	574	struct rb_node *nd;
	575
	576	for (nd = rb_first(&trace->host.threads); nd; nd = rb_next(nd)) {
	577	struct thread *thread = rb_entry(nd, struct thread, rb_node);
	578	struct thread_trace *ttrace = thread->priv;
	579	const char *color;
	580	double ratio;
	581
	582	if (ttrace == NULL)
	583	continue;
	584
	585	ratio = (double)ttrace->nr_events / trace->nr_events * 100.0;
	586
	587	color = PERF_COLOR_NORMAL;
	588	if (ratio > 50.0)
	589	color = PERF_COLOR_RED;
	590	else if (ratio > 25.0)
	591	color = PERF_COLOR_GREEN;
	592	else if (ratio > 5.0)
	593	color = PERF_COLOR_YELLOW;
	594
	595	printed += color_fprintf(fp, color, "%20s", thread->comm);
	596	printed += fprintf(fp, " - %-5d :%11lu [", thread->pid, ttrace->nr_events);
	597	printed += color_fprintf(fp, color, "%5.1f%%", ratio);
	598	printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
	599	}
	600
	601	return printed;
	602	}
	603
ae9ed035 ACM	604	static int trace__set_duration(const struct option opt, const char str,
	605	int unset __maybe_unused)
	606	{
	607	struct trace *trace = opt->value;
	608
	609	trace->duration_filter = atof(str);
	610	return 0;
	611	}
	612
514f1c67 ACM	613	int cmd_trace(int argc, const char *argv, const char prefix __maybe_unused)
	614	{
	615	const char * const trace_usage[] = {
f15eb531 NK	616	"perf trace [<options>] [<command>]",
f15eb531 NK	617	"perf trace [<options>] -- <command> [<options>]",
514f1c67 ACM	618	NULL
	619	};
	620	struct trace trace = {
	621	.audit_machine = audit_detect_machine(),
	622	.syscalls = {
	623	. max = -1,
	624	},
	625	.opts = {
	626	.target = {
	627	.uid = UINT_MAX,
	628	.uses_mmap = true,
	629	},
	630	.user_freq = UINT_MAX,
	631	.user_interval = ULLONG_MAX,
	632	.no_delay = true,
	633	.mmap_pages = 1024,
	634	},
	635	};
	636	const struct option trace_options[] = {
	637	OPT_STRING('p', "pid", &trace.opts.target.pid, "pid",
	638	"trace events on existing process id"),
	639	OPT_STRING(0, "tid", &trace.opts.target.tid, "tid",
	640	"trace events on existing thread id"),
	641	OPT_BOOLEAN(0, "all-cpus", &trace.opts.target.system_wide,
	642	"system-wide collection from all CPUs"),
	643	OPT_STRING(0, "cpu", &trace.opts.target.cpu_list, "cpu",
	644	"list of cpus to monitor"),
	645	OPT_BOOLEAN(0, "no-inherit", &trace.opts.no_inherit,
	646	"child tasks do not inherit counters"),
	647	OPT_UINTEGER(0, "mmap-pages", &trace.opts.mmap_pages,
	648	"number of mmap data pages"),
	649	OPT_STRING(0, "uid", &trace.opts.target.uid_str, "user",
	650	"user to profile"),
ae9ed035 ACM	651	OPT_CALLBACK(0, "duration", &trace, "float",
	652	"show only events with duration > N.M ms",
	653	trace__set_duration),
1302d88e	654	OPT_BOOLEAN(0, "sched", &trace.sched, "show blocking scheduler events"),
514f1c67 ACM	655	OPT_END()
	656	};
	657	int err;
32caf0d1	658	char bf[BUFSIZ];
514f1c67 ACM	659
514f1c67 ACM	660	argc = parse_options(argc, argv, trace_options, trace_usage, 0);
514f1c67	661
32caf0d1 NK	662	err = perf_target__validate(&trace.opts.target);
	663	if (err) {
	664	perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
	665	printf("%s", bf);
	666	return err;
	667	}
	668
514f1c67 ACM	669	err = perf_target__parse_uid(&trace.opts.target);
514f1c67 ACM	670	if (err) {
514f1c67 ACM	671	perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
	672	printf("%s", bf);
	673	return err;
	674	}
	675
f15eb531	676	if (!argc && perf_target__none(&trace.opts.target))
ee76120e NK	677	trace.opts.target.system_wide = true;
ee76120e NK	678
1302d88e ACM	679	err = trace__run(&trace, argc, argv);
	680
	681	if (trace.sched && !err)
	682	trace__fprintf_thread_summary(&trace, stdout);
	683
	684	return err;
514f1c67	685	}