builtin-trace.c 22.5 KB
Newer Older
1
#include <traceevent/event-parse.h>
A
Arnaldo Carvalho de Melo 已提交
2
#include "builtin.h"
3
#include "util/color.h"
4
#include "util/debug.h"
A
Arnaldo Carvalho de Melo 已提交
5
#include "util/evlist.h"
6 7
#include "util/machine.h"
#include "util/thread.h"
A
Arnaldo Carvalho de Melo 已提交
8
#include "util/parse-options.h"
9
#include "util/strlist.h"
A
Arnaldo Carvalho de Melo 已提交
10 11 12 13 14
#include "util/thread_map.h"

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

15 16 17 18 19
static size_t syscall_arg__scnprintf_hex(char *bf, size_t size, unsigned long arg)
{
	return scnprintf(bf, size, "%#lx", arg);
}

20 21
#define SCA_HEX syscall_arg__scnprintf_hex

A
Arnaldo Carvalho de Melo 已提交
22 23
static struct syscall_fmt {
	const char *name;
24
	const char *alias;
25
	size_t	   (*arg_scnprintf[6])(char *bf, size_t size, unsigned long arg);
A
Arnaldo Carvalho de Melo 已提交
26 27
	bool	   errmsg;
	bool	   timeout;
28
	bool	   hexret;
A
Arnaldo Carvalho de Melo 已提交
29
} syscall_fmts[] = {
30
	{ .name	    = "access",	    .errmsg = true, },
31
	{ .name	    = "arch_prctl", .errmsg = true, .alias = "prctl", },
32 33
	{ .name	    = "brk",	    .hexret = true,
	  .arg_scnprintf = { [0] = SCA_HEX, /* brk */ }, },
34
	{ .name	    = "mmap",	    .hexret = true, },
35
	{ .name	    = "connect",    .errmsg = true, },
36 37 38
	{ .name	    = "fstat",	    .errmsg = true, .alias = "newfstat", },
	{ .name	    = "fstatat",    .errmsg = true, .alias = "newfstatat", },
	{ .name	    = "futex",	    .errmsg = true, },
39 40
	{ .name	    = "ioctl",	    .errmsg = true,
	  .arg_scnprintf = { [2] = SCA_HEX, /* arg */ }, },
41
	{ .name	    = "lstat",	    .errmsg = true, .alias = "newlstat", },
42 43 44 45
	{ .name	    = "mmap",	    .hexret = true,
	  .arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
	{ .name	    = "mprotect",   .errmsg = true,
	  .arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
46
	{ .name	    = "mremap",	    .hexret = true, },
47 48
	{ .name	    = "munmap",	    .errmsg = true,
	  .arg_scnprintf = { [0] = SCA_HEX, /* addr */ }, },
49
	{ .name	    = "open",	    .errmsg = true, },
50 51
	{ .name	    = "poll",	    .errmsg = true, .timeout = true, },
	{ .name	    = "ppoll",	    .errmsg = true, .timeout = true, },
52 53
	{ .name	    = "pread",	    .errmsg = true, .alias = "pread64", },
	{ .name	    = "pwrite",	    .errmsg = true, .alias = "pwrite64", },
54 55 56
	{ .name	    = "read",	    .errmsg = true, },
	{ .name	    = "recvfrom",   .errmsg = true, },
	{ .name	    = "select",	    .errmsg = true, .timeout = true, },
57
	{ .name	    = "socket",	    .errmsg = true, },
58
	{ .name	    = "stat",	    .errmsg = true, .alias = "newstat", },
59
	{ .name	    = "uname",	    .errmsg = true, .alias = "newuname", },
A
Arnaldo Carvalho de Melo 已提交
60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76
};

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;
77
	bool		    filtered;
A
Arnaldo Carvalho de Melo 已提交
78
	struct syscall_fmt  *fmt;
79
	size_t		    (**arg_scnprintf)(char *bf, size_t size, unsigned long arg);
A
Arnaldo Carvalho de Melo 已提交
80 81
};

82 83 84 85 86 87 88 89 90 91 92
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);
93
	return printed + fprintf(fp, "): ");
94 95
}

96 97 98 99
struct thread_trace {
	u64		  entry_time;
	u64		  exit_time;
	bool		  entry_pending;
100
	unsigned long	  nr_events;
101
	char		  *entry_str;
102
	double		  runtime_ms;
103 104 105 106 107 108 109
};

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

110
static struct thread_trace *thread__trace(struct thread *thread, FILE *fp)
111
{
112 113
	struct thread_trace *ttrace;

114 115 116 117 118
	if (thread == NULL)
		goto fail;

	if (thread->priv == NULL)
		thread->priv = thread_trace__new();
119
		
120 121 122
	if (thread->priv == NULL)
		goto fail;

123 124 125 126
	ttrace = thread->priv;
	++ttrace->nr_events;

	return ttrace;
127
fail:
128
	color_fprintf(fp, PERF_COLOR_RED,
129 130 131 132
		      "WARNING: not enough memory, dropping samples!\n");
	return NULL;
}

A
Arnaldo Carvalho de Melo 已提交
133
struct trace {
134
	struct perf_tool	tool;
A
Arnaldo Carvalho de Melo 已提交
135 136 137 138 139 140
	int			audit_machine;
	struct {
		int		max;
		struct syscall  *table;
	} syscalls;
	struct perf_record_opts opts;
141 142
	struct machine		host;
	u64			base_time;
143
	FILE			*output;
144
	unsigned long		nr_events;
145 146
	struct strlist		*ev_qualifier;
	bool			not_ev_qualifier;
147
	bool			sched;
148
	bool			multiple_threads;
149
	double			duration_filter;
150
	double			runtime_ms;
A
Arnaldo Carvalho de Melo 已提交
151 152
};

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

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

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

165 166 167 168 169 170 171
static bool done = false;

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

172
static size_t trace__fprintf_entry_head(struct trace *trace, struct thread *thread,
173
					u64 duration, u64 tstamp, FILE *fp)
174 175
{
	size_t printed = trace__fprintf_tstamp(trace, tstamp, fp);
176
	printed += fprintf_duration(duration, fp);
177 178

	if (trace->multiple_threads)
179
		printed += fprintf(fp, "%d ", thread->tid);
180 181 182 183

	return printed;
}

184 185
static int trace__process_event(struct trace *trace, struct machine *machine,
				union perf_event *event)
186 187 188 189 190
{
	int ret = 0;

	switch (event->header.type) {
	case PERF_RECORD_LOST:
191
		color_fprintf(trace->output, PERF_COLOR_RED,
192 193 194 195 196 197 198 199 200 201
			      "LOST %" PRIu64 " events!\n", event->lost.lost);
		ret = machine__process_lost_event(machine, event);
	default:
		ret = machine__process_event(machine, event);
		break;
	}

	return ret;
}

202
static int trace__tool_process(struct perf_tool *tool,
203 204 205 206
			       union perf_event *event,
			       struct perf_sample *sample __maybe_unused,
			       struct machine *machine)
{
207 208
	struct trace *trace = container_of(tool, struct trace, tool);
	return trace__process_event(trace, machine, event);
209 210 211 212 213 214 215 216 217 218 219 220 221
}

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)) {
222
		err = perf_event__synthesize_thread_map(&trace->tool, evlist->threads,
223 224 225
							trace__tool_process,
							&trace->host);
	} else {
226
		err = perf_event__synthesize_threads(&trace->tool, trace__tool_process,
227 228 229 230 231 232 233 234 235
						     &trace->host);
	}

	if (err)
		symbol__exit();

	return err;
}

236 237 238 239 240 241 242 243 244 245
static int syscall__set_arg_fmts(struct syscall *sc)
{
	struct format_field *field;
	int idx = 0;

	sc->arg_scnprintf = calloc(sc->tp_format->format.nr_fields - 1, sizeof(void *));
	if (sc->arg_scnprintf == NULL)
		return -1;

	for (field = sc->tp_format->format.fields->next; field; field = field->next) {
246 247 248
		if (sc->fmt && sc->fmt->arg_scnprintf[idx])
			sc->arg_scnprintf[idx] = sc->fmt->arg_scnprintf[idx];
		else if (field->flags & FIELD_IS_POINTER)
249 250 251 252 253 254 255
			sc->arg_scnprintf[idx] = syscall_arg__scnprintf_hex;
		++idx;
	}

	return 0;
}

A
Arnaldo Carvalho de Melo 已提交
256 257 258 259
static int trace__read_syscall_info(struct trace *trace, int id)
{
	char tp_name[128];
	struct syscall *sc;
260 261 262 263
	const char *name = audit_syscall_to_name(id, trace->audit_machine);

	if (name == NULL)
		return -1;
A
Arnaldo Carvalho de Melo 已提交
264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282

	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;
283
	sc->name = name;
284

285 286 287 288 289 290 291 292 293 294 295
	if (trace->ev_qualifier) {
		bool in = strlist__find(trace->ev_qualifier, name) != NULL;

		if (!(in ^ trace->not_ev_qualifier)) {
			sc->filtered = true;
			/*
			 * No need to do read tracepoint information since this will be
			 * filtered out.
			 */
			return 0;
		}
296 297
	}

298
	sc->fmt  = syscall_fmt__find(sc->name);
A
Arnaldo Carvalho de Melo 已提交
299

300
	snprintf(tp_name, sizeof(tp_name), "sys_enter_%s", sc->name);
A
Arnaldo Carvalho de Melo 已提交
301
	sc->tp_format = event_format__new("syscalls", tp_name);
302 303 304 305 306

	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);
	}
A
Arnaldo Carvalho de Melo 已提交
307

308 309 310 311
	if (sc->tp_format == NULL)
		return -1;

	return syscall__set_arg_fmts(sc);
A
Arnaldo Carvalho de Melo 已提交
312 313
}

314 315
static size_t syscall__scnprintf_args(struct syscall *sc, char *bf, size_t size,
				      unsigned long *args)
A
Arnaldo Carvalho de Melo 已提交
316 317 318 319 320 321 322 323
{
	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) {
324
			printed += scnprintf(bf + printed, size - printed,
325 326 327 328 329 330 331 332
					     "%s%s: ", printed ? ", " : "", field->name);

			if (sc->arg_scnprintf && sc->arg_scnprintf[i])
				printed += sc->arg_scnprintf[i](bf + printed, size - printed, args[i]);
			else
				printed += scnprintf(bf + printed, size - printed,
						     "%ld", args[i]);
                       ++i;
A
Arnaldo Carvalho de Melo 已提交
333 334 335
		}
	} else {
		while (i < 6) {
336 337 338
			printed += scnprintf(bf + printed, size - printed,
					     "%sarg%d: %ld",
					     printed ? ", " : "", i, args[i]);
A
Arnaldo Carvalho de Melo 已提交
339 340 341 342 343 344 345
			++i;
		}
	}

	return printed;
}

346 347 348 349 350 351 352 353 354 355
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) {
356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371

		/*
		 * XXX: Noticed on x86_64, reproduced as far back as 3.0.36, haven't tried
		 * before that, leaving at a higher verbosity level till that is
		 * explained. Reproduced with plain ftrace with:
		 *
		 * echo 1 > /t/events/raw_syscalls/sys_exit/enable
		 * grep "NR -1 " /t/trace_pipe
		 *
		 * After generating some load on the machine.
 		 */
		if (verbose > 1) {
			static u64 n;
			fprintf(trace->output, "Invalid syscall %d id, skipping (%s, %" PRIu64 ") ...\n",
				id, perf_evsel__name(evsel), ++n);
		}
372 373 374 375 376 377 378 379 380 381 382 383 384
		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:
385 386 387 388 389 390
	if (verbose) {
		fprintf(trace->output, "Problems reading syscall %d", id);
		if (id <= trace->syscalls.max && trace->syscalls.table[id].name != NULL)
			fprintf(trace->output, "(%s)", trace->syscalls.table[id].name);
		fputs(" information\n", trace->output);
	}
391 392 393 394 395 396
	return NULL;
}

static int trace__sys_enter(struct trace *trace, struct perf_evsel *evsel,
			    struct perf_sample *sample)
{
397
	char *msg;
398
	void *args;
399
	size_t printed = 0;
400
	struct thread *thread;
401
	struct syscall *sc = trace__syscall_info(trace, evsel, sample);
402 403 404 405
	struct thread_trace *ttrace;

	if (sc == NULL)
		return -1;
406

407 408 409 410
	if (sc->filtered)
		return 0;

	thread = machine__findnew_thread(&trace->host, sample->tid);
411
	ttrace = thread__trace(thread, trace->output);
412
	if (ttrace == NULL)
413 414 415 416
		return -1;

	args = perf_evsel__rawptr(evsel, sample, "args");
	if (args == NULL) {
417
		fprintf(trace->output, "Problems reading syscall arguments\n");
418 419 420
		return -1;
	}

421 422 423 424 425 426 427 428 429 430 431 432 433 434 435
	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")) {
436
		if (!trace->duration_filter) {
437 438
			trace__fprintf_entry_head(trace, thread, 1, sample->time, trace->output);
			fprintf(trace->output, "%-70s\n", ttrace->entry_str);
439
		}
440 441
	} else
		ttrace->entry_pending = true;
442 443 444 445 446 447 448 449

	return 0;
}

static int trace__sys_exit(struct trace *trace, struct perf_evsel *evsel,
			   struct perf_sample *sample)
{
	int ret;
450
	u64 duration = 0;
451
	struct thread *thread;
452
	struct syscall *sc = trace__syscall_info(trace, evsel, sample);
453 454 455 456
	struct thread_trace *ttrace;

	if (sc == NULL)
		return -1;
457

458 459 460 461
	if (sc->filtered)
		return 0;

	thread = machine__findnew_thread(&trace->host, sample->tid);
462
	ttrace = thread__trace(thread, trace->output);
463
	if (ttrace == NULL)
464 465 466 467
		return -1;

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

468 469 470 471
	ttrace = thread->priv;

	ttrace->exit_time = sample->time;

472
	if (ttrace->entry_time) {
473
		duration = sample->time - ttrace->entry_time;
474 475 476 477
		if (trace__filter_duration(trace, duration))
			goto out;
	} else if (trace->duration_filter)
		goto out;
478

479
	trace__fprintf_entry_head(trace, thread, duration, sample->time, trace->output);
480 481

	if (ttrace->entry_pending) {
482
		fprintf(trace->output, "%-70s", ttrace->entry_str);
483
	} else {
484 485 486
		fprintf(trace->output, " ... [");
		color_fprintf(trace->output, PERF_COLOR_YELLOW, "continued");
		fprintf(trace->output, "]: %s()", sc->name);
487 488
	}

489 490 491 492
	if (sc->fmt == NULL) {
signed_print:
		fprintf(trace->output, ") = %d", ret);
	} else if (ret < 0 && sc->fmt->errmsg) {
493 494 495 496
		char bf[256];
		const char *emsg = strerror_r(-ret, bf, sizeof(bf)),
			   *e = audit_errno_to_name(-ret);

497
		fprintf(trace->output, ") = -1 %s %s", e, emsg);
498
	} else if (ret == 0 && sc->fmt->timeout)
499
		fprintf(trace->output, ") = 0 Timeout");
500 501
	else if (sc->fmt->hexret)
		fprintf(trace->output, ") = %#x", ret);
502
	else
503
		goto signed_print;
504

505
	fputc('\n', trace->output);
506
out:
507 508
	ttrace->entry_pending = false;

509 510 511
	return 0;
}

512 513 514 515 516 517
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);
518
	struct thread_trace *ttrace = thread__trace(thread, trace->output);
519 520 521 522 523 524 525 526 527

	if (ttrace == NULL)
		goto out_dump;

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

out_dump:
528
	fprintf(trace->output, "%s: comm=%s,pid=%u,runtime=%" PRIu64 ",vruntime=%" PRIu64 ")\n",
529 530 531 532 533 534 535 536
	       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;
}

537
static int trace__run(struct trace *trace, int argc, const char **argv)
A
Arnaldo Carvalho de Melo 已提交
538
{
539
	struct perf_evlist *evlist = perf_evlist__new();
540
	struct perf_evsel *evsel;
541 542
	int err = -1, i;
	unsigned long before;
543
	const bool forks = argc > 0;
A
Arnaldo Carvalho de Melo 已提交
544 545

	if (evlist == NULL) {
546
		fprintf(trace->output, "Not enough memory to run!\n");
A
Arnaldo Carvalho de Melo 已提交
547 548 549
		goto out;
	}

550 551
	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)) {
552
		fprintf(trace->output, "Couldn't read the raw_syscalls tracepoints information!\n");
A
Arnaldo Carvalho de Melo 已提交
553 554 555
		goto out_delete_evlist;
	}

556 557 558
	if (trace->sched &&
	    perf_evlist__add_newtp(evlist, "sched", "sched_stat_runtime",
				   trace__sched_stat_runtime)) {
559
		fprintf(trace->output, "Couldn't read the sched_stat_runtime tracepoint information!\n");
560 561 562
		goto out_delete_evlist;
	}

A
Arnaldo Carvalho de Melo 已提交
563 564
	err = perf_evlist__create_maps(evlist, &trace->opts.target);
	if (err < 0) {
565
		fprintf(trace->output, "Problems parsing the target to trace, check your options!\n");
A
Arnaldo Carvalho de Melo 已提交
566 567 568
		goto out_delete_evlist;
	}

569 570
	err = trace__symbols_init(trace, evlist);
	if (err < 0) {
571
		fprintf(trace->output, "Problems initializing symbol libraries!\n");
572
		goto out_delete_maps;
573 574
	}

575
	perf_evlist__config(evlist, &trace->opts);
A
Arnaldo Carvalho de Melo 已提交
576

577 578 579 580
	signal(SIGCHLD, sig_handler);
	signal(SIGINT, sig_handler);

	if (forks) {
581
		err = perf_evlist__prepare_workload(evlist, &trace->opts.target,
582
						    argv, false, false);
583
		if (err < 0) {
584
			fprintf(trace->output, "Couldn't run the workload!\n");
585
			goto out_delete_maps;
586 587 588
		}
	}

A
Arnaldo Carvalho de Melo 已提交
589 590
	err = perf_evlist__open(evlist);
	if (err < 0) {
591
		fprintf(trace->output, "Couldn't create the events: %s\n", strerror(errno));
592
		goto out_delete_maps;
A
Arnaldo Carvalho de Melo 已提交
593 594 595 596
	}

	err = perf_evlist__mmap(evlist, UINT_MAX, false);
	if (err < 0) {
597
		fprintf(trace->output, "Couldn't mmap the events: %s\n", strerror(errno));
598
		goto out_close_evlist;
A
Arnaldo Carvalho de Melo 已提交
599 600 601
	}

	perf_evlist__enable(evlist);
602 603 604 605

	if (forks)
		perf_evlist__start_workload(evlist);

606
	trace->multiple_threads = evlist->threads->map[0] == -1 || evlist->threads->nr > 1;
A
Arnaldo Carvalho de Melo 已提交
607
again:
608
	before = trace->nr_events;
A
Arnaldo Carvalho de Melo 已提交
609 610 611 612 613 614

	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;
615
			tracepoint_handler handler;
A
Arnaldo Carvalho de Melo 已提交
616 617
			struct perf_sample sample;

618
			++trace->nr_events;
A
Arnaldo Carvalho de Melo 已提交
619 620 621

			err = perf_evlist__parse_sample(evlist, event, &sample);
			if (err) {
622
				fprintf(trace->output, "Can't parse sample, err = %d, skipping...\n", err);
A
Arnaldo Carvalho de Melo 已提交
623 624 625
				continue;
			}

626 627 628 629
			if (trace->base_time == 0)
				trace->base_time = sample.time;

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

A
Arnaldo Carvalho de Melo 已提交
634 635
			evsel = perf_evlist__id2evsel(evlist, sample.id);
			if (evsel == NULL) {
636
				fprintf(trace->output, "Unknown tp ID %" PRIu64 ", skipping...\n", sample.id);
A
Arnaldo Carvalho de Melo 已提交
637 638 639
				continue;
			}

640
			if (sample.raw_data == NULL) {
641
				fprintf(trace->output, "%s sample with no payload for tid: %d, cpu %d, raw_size=%d, skipping...\n",
642 643 644 645 646
				       perf_evsel__name(evsel), sample.tid,
				       sample.cpu, sample.raw_size);
				continue;
			}

647 648
			handler = evsel->handler.func;
			handler(trace, evsel, &sample);
A
Arnaldo Carvalho de Melo 已提交
649 650 651
		}
	}

652
	if (trace->nr_events == before) {
653
		if (done)
654
			goto out_unmap_evlist;
655

A
Arnaldo Carvalho de Melo 已提交
656
		poll(evlist->pollfd, evlist->nr_fds, -1);
657 658 659 660
	}

	if (done)
		perf_evlist__disable(evlist);
A
Arnaldo Carvalho de Melo 已提交
661 662 663

	goto again;

664 665 666 667 668 669
out_unmap_evlist:
	perf_evlist__munmap(evlist);
out_close_evlist:
	perf_evlist__close(evlist);
out_delete_maps:
	perf_evlist__delete_maps(evlist);
A
Arnaldo Carvalho de Melo 已提交
670 671 672 673 674 675
out_delete_evlist:
	perf_evlist__delete(evlist);
out:
	return err;
}

676 677 678 679 680 681 682 683 684 685 686 687 688 689 690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708 709 710 711 712
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);
713
		printed += fprintf(fp, " - %-5d :%11lu   [", thread->tid, ttrace->nr_events);
714 715 716 717 718 719 720
		printed += color_fprintf(fp, color, "%5.1f%%", ratio);
		printed += fprintf(fp, " ] %10.3f ms\n", ttrace->runtime_ms);
	}

	return printed;
}

721 722 723 724 725 726 727 728 729
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;
}

730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746
static int trace__open_output(struct trace *trace, const char *filename)
{
	struct stat st;

	if (!stat(filename, &st) && st.st_size) {
		char oldname[PATH_MAX];

		scnprintf(oldname, sizeof(oldname), "%s.old", filename);
		unlink(oldname);
		rename(filename, oldname);
	}

	trace->output = fopen(filename, "w");

	return trace->output == NULL ? -errno : 0;
}

A
Arnaldo Carvalho de Melo 已提交
747 748 749
int cmd_trace(int argc, const char **argv, const char *prefix __maybe_unused)
{
	const char * const trace_usage[] = {
750 751
		"perf trace [<options>] [<command>]",
		"perf trace [<options>] -- <command> [<options>]",
A
Arnaldo Carvalho de Melo 已提交
752 753 754 755 756 757 758 759 760 761 762 763 764 765 766 767 768
		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,
		},
769
		.output = stdout,
A
Arnaldo Carvalho de Melo 已提交
770
	};
771
	const char *output_name = NULL;
772
	const char *ev_qualifier_str = NULL;
A
Arnaldo Carvalho de Melo 已提交
773
	const struct option trace_options[] = {
774 775
	OPT_STRING('e', "expr", &ev_qualifier_str, "expr",
		    "list of events to trace"),
776
	OPT_STRING('o', "output", &output_name, "file", "output file name"),
A
Arnaldo Carvalho de Melo 已提交
777 778
	OPT_STRING('p', "pid", &trace.opts.target.pid, "pid",
		    "trace events on existing process id"),
779
	OPT_STRING('t', "tid", &trace.opts.target.tid, "tid",
A
Arnaldo Carvalho de Melo 已提交
780
		    "trace events on existing thread id"),
781
	OPT_BOOLEAN('a', "all-cpus", &trace.opts.target.system_wide,
A
Arnaldo Carvalho de Melo 已提交
782
		    "system-wide collection from all CPUs"),
783
	OPT_STRING('C', "cpu", &trace.opts.target.cpu_list, "cpu",
A
Arnaldo Carvalho de Melo 已提交
784
		    "list of cpus to monitor"),
785
	OPT_BOOLEAN('i', "no-inherit", &trace.opts.no_inherit,
A
Arnaldo Carvalho de Melo 已提交
786
		    "child tasks do not inherit counters"),
787
	OPT_UINTEGER('m', "mmap-pages", &trace.opts.mmap_pages,
A
Arnaldo Carvalho de Melo 已提交
788
		     "number of mmap data pages"),
789
	OPT_STRING('u', "uid", &trace.opts.target.uid_str, "user",
A
Arnaldo Carvalho de Melo 已提交
790
		   "user to profile"),
791 792 793
	OPT_CALLBACK(0, "duration", &trace, "float",
		     "show only events with duration > N.M ms",
		     trace__set_duration),
794
	OPT_BOOLEAN(0, "sched", &trace.sched, "show blocking scheduler events"),
795
	OPT_INCR('v', "verbose", &verbose, "be more verbose"),
A
Arnaldo Carvalho de Melo 已提交
796 797 798
	OPT_END()
	};
	int err;
799
	char bf[BUFSIZ];
A
Arnaldo Carvalho de Melo 已提交
800 801 802

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

803 804 805 806 807 808 809 810
	if (output_name != NULL) {
		err = trace__open_output(&trace, output_name);
		if (err < 0) {
			perror("failed to create output file");
			goto out;
		}
	}

811
	if (ev_qualifier_str != NULL) {
812 813 814 815 816 817
		const char *s = ev_qualifier_str;

		trace.not_ev_qualifier = *s == '!';
		if (trace.not_ev_qualifier)
			++s;
		trace.ev_qualifier = strlist__new(true, s);
818
		if (trace.ev_qualifier == NULL) {
819 820 821 822
			fputs("Not enough memory to parse event qualifier",
			      trace.output);
			err = -ENOMEM;
			goto out_close;
823 824 825
		}
	}

826 827 828
	err = perf_target__validate(&trace.opts.target);
	if (err) {
		perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
829 830
		fprintf(trace.output, "%s", bf);
		goto out_close;
831 832
	}

A
Arnaldo Carvalho de Melo 已提交
833 834 835
	err = perf_target__parse_uid(&trace.opts.target);
	if (err) {
		perf_target__strerror(&trace.opts.target, err, bf, sizeof(bf));
836 837
		fprintf(trace.output, "%s", bf);
		goto out_close;
A
Arnaldo Carvalho de Melo 已提交
838 839
	}

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

843 844 845
	err = trace__run(&trace, argc, argv);

	if (trace.sched && !err)
846
		trace__fprintf_thread_summary(&trace, trace.output);
847

848 849 850 851
out_close:
	if (output_name != NULL)
		fclose(trace.output);
out:
852
	return err;
A
Arnaldo Carvalho de Melo 已提交
853
}