builtin-annotate.c 16.1 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12
/*
 * builtin-annotate.c
 *
 * Builtin annotate command: Analyze the perf.data input file,
 * look up and read DSOs and symbol information and display
 * a histogram of results, along various sorting keys.
 */
#include "builtin.h"

#include "util/util.h"

#include "util/color.h"
13
#include <linux/list.h>
14
#include "util/cache.h"
15
#include <linux/rbtree.h>
16 17 18 19
#include "util/symbol.h"
#include "util/string.h"

#include "perf.h"
20
#include "util/debug.h"
21 22 23

#include "util/parse-options.h"
#include "util/parse-events.h"
24
#include "util/thread.h"
25
#include "util/sort.h"
26
#include "util/hist.h"
27
#include "util/process_events.h"
28 29 30

static char		const *input_name = "perf.data";

31
static int		force;
32 33
static int		input;

34 35
static int		full_paths;

36 37
static int		print_line;

38 39 40
static unsigned long	page_size;
static unsigned long	mmap_window = 32;

41 42 43 44 45
struct sym_hist {
	u64		sum;
	u64		ip[0];
};

46
struct sym_ext {
47
	struct rb_node	node;
48 49 50 51
	double		percent;
	char		*path;
};

52 53 54 55 56
struct sym_priv {
	struct sym_hist	*hist;
	struct sym_ext	*ext;
};

57 58 59 60 61
static struct symbol_conf symbol_conf = {
	.priv_size	  = sizeof(struct sym_priv),
	.try_vmlinux_path = true,
};

62 63
static const char *sym_hist_filter;

64
static int symbol_filter(struct map *map __used, struct symbol *sym)
65
{
66 67
	if (sym_hist_filter == NULL ||
	    strcmp(sym->name, sym_hist_filter) == 0) {
68
		struct sym_priv *priv = symbol__priv(sym);
69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84
		const int size = (sizeof(*priv->hist) +
				  (sym->end - sym->start) * sizeof(u64));

		priv->hist = malloc(size);
		if (priv->hist)
			memset(priv->hist, 0, size);
		return 0;
	}
	/*
	 * FIXME: We should really filter it out, as we don't want to go thru symbols
	 * we're not interested, and if a DSO ends up with no symbols, delete it too,
	 * but right now the kernel loading routines in symbol.c bail out if no symbols
	 * are found, fix it later.
	 */
	return 0;
}
85

86 87 88
/*
 * collect histogram counts
 */
89
static void hist_hit(struct hist_entry *he, u64 ip)
90
{
91 92
	unsigned int sym_size, offset;
	struct symbol *sym = he->sym;
93 94
	struct sym_priv *priv;
	struct sym_hist *h;
95

96
	he->count++;
97

98 99 100
	if (!sym || !he->map)
		return;

101
	priv = symbol__priv(sym);
102
	if (!priv->hist)
103
		return;
104

105 106
	sym_size = sym->end - sym->start;
	offset = ip - sym->start;
107

108 109 110 111
	if (verbose)
		fprintf(stderr, "%s: ip=%Lx\n", __func__,
			he->map->unmap_ip(he->map, ip));

112 113
	if (offset >= sym_size)
		return;
114

115 116 117
	h = priv->hist;
	h->sum++;
	h->ip[offset]++;
118

119 120
	if (verbose >= 3)
		printf("%p %s: count++ [ip: %p, %08Lx] => %Ld\n",
121
			(void *)(unsigned long)he->sym->start,
122
			he->sym->name,
123
			(void *)(unsigned long)ip, ip - he->sym->start,
124
			h->ip[offset]);
125 126
}

127 128
static int hist_entry__add(struct thread *thread, struct map *map,
			   struct symbol *sym, u64 ip, u64 count, char level)
129
{
130 131 132 133
	bool hit;
	struct hist_entry *he = __hist_entry__add(thread, map, sym, NULL, ip,
						  count, level, &hit);
	if (he == NULL)
134
		return -ENOMEM;
135
	hist_hit(he, ip);
136 137 138 139
	return 0;
}

static int
140
process_sample_event(event_t *event, unsigned long offset, unsigned long head)
141 142
{
	char level;
143
	u64 ip = event->ip.ip;
144
	struct map *map = NULL;
145
	struct symbol *sym = NULL;
146
	struct thread *thread = threads__findnew(event->ip.pid);
147

148
	dump_printf("%p [%p]: PERF_EVENT (IP, %d): %d: %p\n",
149 150 151 152 153 154 155 156 157 158 159 160
		(void *)(offset + head),
		(void *)(long)(event->header.size),
		event->header.misc,
		event->ip.pid,
		(void *)(long)ip);

	if (thread == NULL) {
		fprintf(stderr, "problem processing %d event, skipping it.\n",
			event->header.type);
		return -1;
	}

161 162
	dump_printf(" ... thread: %s:%d\n", thread->comm, thread->pid);

163
	if (event->header.misc & PERF_RECORD_MISC_KERNEL) {
164
		level = 'k';
165
		sym = kernel_maps__find_symbol(ip, &map, symbol_filter);
166 167
		dump_printf(" ...... dso: %s\n",
			    map ? map->dso->long_name : "<not found>");
168
	} else if (event->header.misc & PERF_RECORD_MISC_USER) {
169 170 171
		level = '.';
		map = thread__find_map(thread, ip);
		if (map != NULL) {
172
got_map:
173
			ip = map->map_ip(map, ip);
174
			sym = map__find_symbol(map, ip, symbol_filter);
175 176 177 178 179
		} else {
			/*
			 * If this is outside of all known maps,
			 * and is a negative address, try to look it
			 * up in the kernel dso, as it might be a
180 181 182 183 184
			 * vsyscall or vdso (which executes in user-mode).
			 *
			 * XXX This is nasty, we should have a symbol list in
			 * the "[vdso]" dso, but for now lets use the old
			 * trick of looking in the whole kernel symbol list.
185
			 */
186 187 188 189
			if ((long long)ip < 0) {
				map = kernel_map;
				goto got_map;
			}
190
		}
191 192
		dump_printf(" ...... dso: %s\n",
			    map ? map->dso->long_name : "<not found>");
193 194
	} else {
		level = 'H';
195
		dump_printf(" ...... dso: [hypervisor]\n");
196 197
	}

198 199 200 201
	if (hist_entry__add(thread, map, sym, ip, 1, level)) {
		fprintf(stderr, "problem incrementing symbol count, "
				"skipping event\n");
		return -1;
202 203 204 205 206 207 208 209 210
	}
	total++;

	return 0;
}

static int
process_comm_event(event_t *event, unsigned long offset, unsigned long head)
{
211
	struct thread *thread = threads__findnew(event->comm.pid);
212

213
	dump_printf("%p [%p]: PERF_RECORD_COMM: %s:%d\n",
214 215 216 217 218 219
		(void *)(offset + head),
		(void *)(long)(event->header.size),
		event->comm.comm, event->comm.pid);

	if (thread == NULL ||
	    thread__set_comm(thread, event->comm.comm)) {
220
		dump_printf("problem processing PERF_RECORD_COMM, skipping event.\n");
221 222 223 224 225 226 227 228 229 230 231
		return -1;
	}
	total_comm++;

	return 0;
}

static int
process_event(event_t *event, unsigned long offset, unsigned long head)
{
	switch (event->header.type) {
232
	case PERF_RECORD_SAMPLE:
233 234
		return process_sample_event(event, offset, head);

235
	case PERF_RECORD_MMAP:
236 237
		return process_mmap_event(event, offset, head);

238
	case PERF_RECORD_COMM:
239 240
		return process_comm_event(event, offset, head);

241
	case PERF_RECORD_FORK:
242
		return process_task_event(event, offset, head);
243 244 245 246
	/*
	 * We dont process them right now but they are fine:
	 */

247 248
	case PERF_RECORD_THROTTLE:
	case PERF_RECORD_UNTHROTTLE:
249 250 251 252 253 254 255 256 257
		return 0;

	default:
		return -1;
	}

	return 0;
}

258
static int parse_line(FILE *file, struct hist_entry *he, u64 len)
259
{
260
	struct symbol *sym = he->sym;
261
	char *line = NULL, *tmp, *tmp2;
262 263
	static const char *prev_line;
	static const char *prev_color;
264 265
	unsigned int offset;
	size_t line_len;
266
	u64 start;
267
	s64 line_ip;
268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302
	int ret;
	char *c;

	if (getline(&line, &line_len, file) < 0)
		return -1;
	if (!line)
		return -1;

	c = strchr(line, '\n');
	if (c)
		*c = 0;

	line_ip = -1;
	offset = 0;
	ret = -2;

	/*
	 * Strip leading spaces:
	 */
	tmp = line;
	while (*tmp) {
		if (*tmp != ' ')
			break;
		tmp++;
	}

	if (*tmp) {
		/*
		 * Parse hexa addresses followed by ':'
		 */
		line_ip = strtoull(tmp, &tmp2, 16);
		if (*tmp2 != ':')
			line_ip = -1;
	}

303 304
	start = he->map->unmap_ip(he->map, sym->start);

305
	if (line_ip != -1) {
306
		const char *path = NULL;
307 308
		unsigned int hits = 0;
		double percent = 0.0;
309
		const char *color;
310
		struct sym_priv *priv = symbol__priv(sym);
311 312
		struct sym_ext *sym_ext = priv->ext;
		struct sym_hist *h = priv->hist;
313

314
		offset = line_ip - start;
315
		if (offset < len)
316
			hits = h->ip[offset];
317

318
		if (offset < len && sym_ext) {
319 320
			path = sym_ext[offset].path;
			percent = sym_ext[offset].percent;
321 322
		} else if (h->sum)
			percent = 100.0 * hits / h->sum;
323

324
		color = get_percent_color(percent);
325

326 327 328 329 330 331 332 333 334 335 336 337 338 339
		/*
		 * Also color the filename and line if needed, with
		 * the same color than the percentage. Don't print it
		 * twice for close colored ip with the same filename:line
		 */
		if (path) {
			if (!prev_line || strcmp(prev_line, path)
				       || color != prev_color) {
				color_fprintf(stdout, color, " %s", path);
				prev_line = path;
				prev_color = color;
			}
		}

340 341 342 343 344 345 346 347 348 349 350 351 352
		color_fprintf(stdout, color, " %7.2f", percent);
		printf(" :	");
		color_fprintf(stdout, PERF_COLOR_BLUE, "%s\n", line);
	} else {
		if (!*line)
			printf("         :\n");
		else
			printf("         :	%s\n", line);
	}

	return 0;
}

353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374
static struct rb_root root_sym_ext;

static void insert_source_line(struct sym_ext *sym_ext)
{
	struct sym_ext *iter;
	struct rb_node **p = &root_sym_ext.rb_node;
	struct rb_node *parent = NULL;

	while (*p != NULL) {
		parent = *p;
		iter = rb_entry(parent, struct sym_ext, node);

		if (sym_ext->percent > iter->percent)
			p = &(*p)->rb_left;
		else
			p = &(*p)->rb_right;
	}

	rb_link_node(&sym_ext->node, parent, p);
	rb_insert_color(&sym_ext->node, &root_sym_ext);
}

375
static void free_source_line(struct hist_entry *he, int len)
376
{
377
	struct sym_priv *priv = symbol__priv(he->sym);
378
	struct sym_ext *sym_ext = priv->ext;
379 380 381 382 383 384 385 386 387
	int i;

	if (!sym_ext)
		return;

	for (i = 0; i < len; i++)
		free(sym_ext[i].path);
	free(sym_ext);

388
	priv->ext = NULL;
389
	root_sym_ext = RB_ROOT;
390 391 392
}

/* Get the filename:line for the colored entries */
393
static void
394
get_source_line(struct hist_entry *he, int len, const char *filename)
395
{
396 397
	struct symbol *sym = he->sym;
	u64 start;
398 399 400
	int i;
	char cmd[PATH_MAX * 2];
	struct sym_ext *sym_ext;
401
	struct sym_priv *priv = symbol__priv(sym);
402
	struct sym_hist *h = priv->hist;
403

404
	if (!h->sum)
405 406
		return;

407 408
	sym_ext = priv->ext = calloc(len, sizeof(struct sym_ext));
	if (!priv->ext)
409 410
		return;

411
	start = he->map->unmap_ip(he->map, sym->start);
412 413 414 415

	for (i = 0; i < len; i++) {
		char *path = NULL;
		size_t line_len;
416
		u64 offset;
417 418
		FILE *fp;

419
		sym_ext[i].percent = 100.0 * h->ip[i] / h->sum;
420 421 422
		if (sym_ext[i].percent <= 0.5)
			continue;

423
		offset = start + i;
424
		sprintf(cmd, "addr2line -e %s %016llx", filename, offset);
425 426 427 428 429 430 431
		fp = popen(cmd, "r");
		if (!fp)
			continue;

		if (getline(&path, &line_len, fp) < 0 || !line_len)
			goto next;

432
		sym_ext[i].path = malloc(sizeof(char) * line_len + 1);
433 434 435 436
		if (!sym_ext[i].path)
			goto next;

		strcpy(sym_ext[i].path, path);
437
		insert_source_line(&sym_ext[i]);
438 439 440 441 442 443

	next:
		pclose(fp);
	}
}

444
static void print_summary(const char *filename)
445 446 447 448 449 450 451 452 453 454 455 456 457 458 459
{
	struct sym_ext *sym_ext;
	struct rb_node *node;

	printf("\nSorted summary for file %s\n", filename);
	printf("----------------------------------------------\n\n");

	if (RB_EMPTY_ROOT(&root_sym_ext)) {
		printf(" Nothing higher than %1.1f%%\n", MIN_GREEN);
		return;
	}

	node = rb_first(&root_sym_ext);
	while (node) {
		double percent;
460
		const char *color;
461 462 463 464
		char *path;

		sym_ext = rb_entry(node, struct sym_ext, node);
		percent = sym_ext->percent;
465
		color = get_percent_color(percent);
466 467 468 469 470 471 472
		path = sym_ext->path;

		color_fprintf(stdout, color, " %7.2f %s", percent, path);
		node = rb_next(node);
	}
}

473
static void annotate_sym(struct hist_entry *he)
474
{
475 476 477
	struct map *map = he->map;
	struct dso *dso = map->dso;
	struct symbol *sym = he->sym;
478 479
	const char *filename = dso->long_name, *d_filename;
	u64 len;
480 481 482 483 484
	char command[PATH_MAX*2];
	FILE *file;

	if (!filename)
		return;
485

486 487 488 489 490 491
	if (verbose)
		fprintf(stderr, "%s: filename=%s, sym=%s, start=%Lx, end=%Lx\n",
			__func__, filename, sym->name,
			map->unmap_ip(map, sym->start),
			map->unmap_ip(map, sym->end));

492 493 494 495
	if (full_paths)
		d_filename = filename;
	else
		d_filename = basename(filename);
496 497 498

	len = sym->end - sym->start;

499
	if (print_line) {
500
		get_source_line(he, len, filename);
501 502 503 504
		print_summary(filename);
	}

	printf("\n\n------------------------------------------------\n");
505
	printf(" Percent |	Source code & Disassembly of %s\n", d_filename);
506 507 508
	printf("------------------------------------------------\n");

	if (verbose >= 2)
509 510
		printf("annotating [%p] %30s : [%p] %30s\n",
		       dso, dso->long_name, sym, sym->name);
511

512
	sprintf(command, "objdump --start-address=0x%016Lx --stop-address=0x%016Lx -dS %s|grep -v %s",
513 514
		map->unmap_ip(map, sym->start), map->unmap_ip(map, sym->end),
		filename, filename);
515 516 517 518 519 520 521 522 523

	if (verbose >= 3)
		printf("doing: %s\n", command);

	file = popen(command, "r");
	if (!file)
		return;

	while (!feof(file)) {
524
		if (parse_line(file, he, len) < 0)
525 526 527 528
			break;
	}

	pclose(file);
529
	if (print_line)
530
		free_source_line(he, len);
531 532 533 534 535 536
}

static void find_annotations(void)
{
	struct rb_node *nd;

537 538
	for (nd = rb_first(&output_hists); nd; nd = rb_next(nd)) {
		struct hist_entry *he = rb_entry(nd, struct hist_entry, rb_node);
539
		struct sym_priv *priv;
540

541 542
		if (he->sym == NULL)
			continue;
543

544
		priv = symbol__priv(he->sym);
545 546 547 548 549 550 551 552 553 554
		if (priv->hist == NULL)
			continue;

		annotate_sym(he);
		/*
		 * Since we have a hist_entry per IP for the same symbol, free
		 * he->sym->hist to signal we already processed this symbol.
		 */
		free(priv->hist);
		priv->hist = NULL;
555 556 557
	}
}

558 559 560 561 562
static int __cmd_annotate(void)
{
	int ret, rc = EXIT_FAILURE;
	unsigned long offset = 0;
	unsigned long head = 0;
563
	struct stat input_stat;
564 565 566 567
	event_t *event;
	uint32_t size;
	char *buf;

568
	register_idle_thread();
569 570 571 572 573 574 575

	input = open(input_name, O_RDONLY);
	if (input < 0) {
		perror("failed to open file");
		exit(-1);
	}

576
	ret = fstat(input, &input_stat);
577 578 579 580 581
	if (ret < 0) {
		perror("failed to stat file");
		exit(-1);
	}

582 583
	if (!force && input_stat.st_uid && (input_stat.st_uid != geteuid())) {
		fprintf(stderr, "file: %s not owned by current user or root\n", input_name);
584 585 586
		exit(-1);
	}

587
	if (!input_stat.st_size) {
588 589 590 591 592 593 594 595 596 597 598 599 600 601 602 603 604 605 606 607 608
		fprintf(stderr, "zero-sized file, nothing to do!\n");
		exit(0);
	}

remap:
	buf = (char *)mmap(NULL, page_size * mmap_window, PROT_READ,
			   MAP_SHARED, input, offset);
	if (buf == MAP_FAILED) {
		perror("failed to mmap file");
		exit(-1);
	}

more:
	event = (event_t *)(buf + head);

	size = event->header.size;
	if (!size)
		size = 8;

	if (head + event->header.size >= page_size * mmap_window) {
		unsigned long shift = page_size * (head / page_size);
609
		int munmap_ret;
610

611 612
		munmap_ret = munmap(buf, page_size * mmap_window);
		assert(munmap_ret == 0);
613 614 615 616 617 618 619 620

		offset += shift;
		head -= shift;
		goto remap;
	}

	size = event->header.size;

621
	dump_printf("%p [%p]: event: %d\n",
622 623 624 625 626 627
			(void *)(offset + head),
			(void *)(long)event->header.size,
			event->header.type);

	if (!size || process_event(event, offset, head) < 0) {

628
		dump_printf("%p [%p]: skipping unknown header type: %d\n",
629 630 631 632 633 634 635 636 637 638 639 640 641 642 643 644 645 646 647
			(void *)(offset + head),
			(void *)(long)(event->header.size),
			event->header.type);

		total_unknown++;

		/*
		 * assume we lost track of the stream, check alignment, and
		 * increment a single u64 in the hope to catch on again 'soon'.
		 */

		if (unlikely(head & 7))
			head &= ~7ULL;

		size = 8;
	}

	head += size;

648
	if (offset + head < (unsigned long)input_stat.st_size)
649 650 651 652 653
		goto more;

	rc = EXIT_SUCCESS;
	close(input);

654 655 656 657 658
	dump_printf("      IP events: %10ld\n", total);
	dump_printf("    mmap events: %10ld\n", total_mmap);
	dump_printf("    comm events: %10ld\n", total_comm);
	dump_printf("    fork events: %10ld\n", total_fork);
	dump_printf(" unknown events: %10ld\n", total_unknown);
659 660 661 662

	if (dump_trace)
		return 0;

663
	if (verbose > 3)
664
		threads__fprintf(stdout);
665

666
	if (verbose > 2)
667 668 669
		dsos__fprintf(stdout);

	collapse__resort();
670
	output__resort(total);
671 672

	find_annotations();
673 674 675 676 677 678 679 680 681 682 683 684

	return rc;
}

static const char * const annotate_usage[] = {
	"perf annotate [<options>] <command>",
	NULL
};

static const struct option options[] = {
	OPT_STRING('i', "input", &input_name, "file",
		    "input file name"),
685
	OPT_STRING('s', "symbol", &sym_hist_filter, "symbol",
686
		    "symbol to annotate"),
687
	OPT_BOOLEAN('f', "force", &force, "don't complain, do it"),
688 689 690 691
	OPT_BOOLEAN('v', "verbose", &verbose,
		    "be more verbose (show symbol address, etc)"),
	OPT_BOOLEAN('D', "dump-raw-trace", &dump_trace,
		    "dump raw trace in ASCII"),
692 693 694
	OPT_STRING('k', "vmlinux", &symbol_conf.vmlinux_name,
		   "file", "vmlinux pathname"),
	OPT_BOOLEAN('m', "modules", &symbol_conf.use_modules,
695
		    "load module symbols - WARNING: use only with -k and LIVE kernel"),
696 697
	OPT_BOOLEAN('l', "print-line", &print_line,
		    "print matching source lines (may be slow)"),
698 699
	OPT_BOOLEAN('P', "full-paths", &full_paths,
		    "Don't shorten the displayed pathnames"),
700 701 702 703 704 705 706 707 708 709 710 711 712 713 714 715 716 717
	OPT_END()
};

static void setup_sorting(void)
{
	char *tmp, *tok, *str = strdup(sort_order);

	for (tok = strtok_r(str, ", ", &tmp);
			tok; tok = strtok_r(NULL, ", ", &tmp)) {
		if (sort_dimension__add(tok) < 0) {
			error("Unknown --sort key: `%s'", tok);
			usage_with_options(annotate_usage, options);
		}
	}

	free(str);
}

718
int cmd_annotate(int argc, const char **argv, const char *prefix __used)
719
{
720 721
	if (symbol__init(&symbol_conf) < 0)
		return -1;
722 723 724 725 726 727 728

	page_size = getpagesize();

	argc = parse_options(argc, argv, options, annotate_usage, 0);

	setup_sorting();

729 730 731 732 733 734 735 736 737 738 739
	if (argc) {
		/*
		 * Special case: if there's an argument left then assume tha
		 * it's a symbol filter:
		 */
		if (argc > 1)
			usage_with_options(annotate_usage, options);

		sym_hist_filter = argv[0];
	}

740 741
	setup_pager();

742 743 744 745 746 747
	if (field_sep && *field_sep == '.') {
		fputs("'.' is the only non valid --field-separator argument\n",
				stderr);
		exit(129);
	}

748 749
	return __cmd_annotate();
}