trace_functions_graph.c 35 KB
Newer Older
1 2 3
/*
 *
 * Function graph tracer.
4
 * Copyright (c) 2008-2009 Frederic Weisbecker <fweisbec@gmail.com>
5 6 7 8 9 10 11
 * Mostly borrowed from function tracer which
 * is Copyright (c) Steven Rostedt <srostedt@redhat.com>
 *
 */
#include <linux/debugfs.h>
#include <linux/uaccess.h>
#include <linux/ftrace.h>
12
#include <linux/slab.h>
13 14 15
#include <linux/fs.h>

#include "trace.h"
16
#include "trace_output.h"
17

18 19 20
/* When set, irq functions will be ignored */
static int ftrace_graph_skip_irqs;

21
struct fgraph_cpu_data {
22 23
	pid_t		last_pid;
	int		depth;
24
	int		depth_irq;
25
	int		ignore;
26
	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
27 28 29
};

struct fgraph_data {
30
	struct fgraph_cpu_data __percpu *cpu_data;
31 32 33 34 35 36

	/* Place to preserve last processed entry. */
	struct ftrace_graph_ent_entry	ent;
	struct ftrace_graph_ret_entry	ret;
	int				failed;
	int				cpu;
37 38
};

39
#define TRACE_GRAPH_INDENT	2
40

41
/* Flag options */
42
#define TRACE_GRAPH_PRINT_OVERRUN	0x1
43 44
#define TRACE_GRAPH_PRINT_CPU		0x2
#define TRACE_GRAPH_PRINT_OVERHEAD	0x4
45
#define TRACE_GRAPH_PRINT_PROC		0x8
46
#define TRACE_GRAPH_PRINT_DURATION	0x10
47
#define TRACE_GRAPH_PRINT_ABS_TIME	0x20
48
#define TRACE_GRAPH_PRINT_IRQS		0x40
49

50
static struct tracer_opt trace_opts[] = {
51
	/* Display overruns? (for self-debug purpose) */
52 53 54 55 56
	{ TRACER_OPT(funcgraph-overrun, TRACE_GRAPH_PRINT_OVERRUN) },
	/* Display CPU ? */
	{ TRACER_OPT(funcgraph-cpu, TRACE_GRAPH_PRINT_CPU) },
	/* Display Overhead ? */
	{ TRACER_OPT(funcgraph-overhead, TRACE_GRAPH_PRINT_OVERHEAD) },
57 58
	/* Display proc name/pid */
	{ TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
59 60 61 62
	/* Display duration of execution */
	{ TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
	/* Display absolute time of an entry */
	{ TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
63 64
	/* Display interrupts */
	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
65 66 67 68
	{ } /* Empty entry */
};

static struct tracer_flags tracer_flags = {
69
	/* Don't display overruns and proc by default */
70
	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
71
	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
72 73 74
	.opts = trace_opts
};

75
static struct trace_array *graph_array;
76

77 78 79 80 81 82 83 84 85 86 87 88 89 90
/*
 * DURATION column is being also used to display IRQ signs,
 * following values are used by print_graph_irq and others
 * to fill in space into DURATION column.
 */
enum {
	DURATION_FILL_FULL  = -1,
	DURATION_FILL_START = -2,
	DURATION_FILL_END   = -3,
};

static enum print_line_t
print_graph_duration(unsigned long long duration, struct trace_seq *s,
		     u32 flags);
91

92 93
/* Add a function return address to the trace stack on thread info.*/
int
94 95
ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
			 unsigned long frame_pointer)
96
{
97
	unsigned long long calltime;
98 99 100 101 102
	int index;

	if (!current->ret_stack)
		return -EBUSY;

103 104 105 106 107 108
	/*
	 * We must make sure the ret_stack is tested before we read
	 * anything else.
	 */
	smp_rmb();

109 110 111 112 113 114
	/* The return trace stack is full */
	if (current->curr_ret_stack == FTRACE_RETFUNC_DEPTH - 1) {
		atomic_inc(&current->trace_overrun);
		return -EBUSY;
	}

115 116
	calltime = trace_clock_local();

117 118 119 120
	index = ++current->curr_ret_stack;
	barrier();
	current->ret_stack[index].ret = ret;
	current->ret_stack[index].func = func;
121
	current->ret_stack[index].calltime = calltime;
122
	current->ret_stack[index].subtime = 0;
123
	current->ret_stack[index].fp = frame_pointer;
124 125 126 127 128 129
	*depth = index;

	return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
130
static void
131 132
ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret,
			unsigned long frame_pointer)
133 134 135 136 137 138 139 140 141 142 143 144 145
{
	int index;

	index = current->curr_ret_stack;

	if (unlikely(index < 0)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic, otherwise we have no where to go */
		*ret = (unsigned long)panic;
		return;
	}

146
#if defined(CONFIG_HAVE_FUNCTION_GRAPH_FP_TEST) && !defined(CC_USING_FENTRY)
147 148 149 150 151 152 153 154 155 156
	/*
	 * The arch may choose to record the frame pointer used
	 * and check it here to make sure that it is what we expect it
	 * to be. If gcc does not set the place holder of the return
	 * address in the frame pointer, and does a copy instead, then
	 * the function graph trace will fail. This test detects this
	 * case.
	 *
	 * Currently, x86_32 with optimize for size (-Os) makes the latest
	 * gcc do the above.
157 158 159
	 *
	 * Note, -mfentry does not use frame pointers, and this test
	 *  is not needed if CC_USING_FENTRY is set.
160 161 162 163
	 */
	if (unlikely(current->ret_stack[index].fp != frame_pointer)) {
		ftrace_graph_stop();
		WARN(1, "Bad frame pointer: expected %lx, received %lx\n"
164
		     "  from func %ps return to %lx\n",
165 166 167 168 169 170 171 172 173
		     current->ret_stack[index].fp,
		     frame_pointer,
		     (void *)current->ret_stack[index].func,
		     current->ret_stack[index].ret);
		*ret = (unsigned long)panic;
		return;
	}
#endif

174 175 176 177 178 179 180 181 182 183 184
	*ret = current->ret_stack[index].ret;
	trace->func = current->ret_stack[index].func;
	trace->calltime = current->ret_stack[index].calltime;
	trace->overrun = atomic_read(&current->trace_overrun);
	trace->depth = index;
}

/*
 * Send the trace to the ring-buffer.
 * @return the original return address.
 */
185
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
186 187 188 189
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

190
	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
191
	trace.rettime = trace_clock_local();
192
	ftrace_graph_return(&trace);
193 194
	barrier();
	current->curr_ret_stack--;
195 196 197 198 199 200 201 202 203 204 205

	if (unlikely(!ret)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic. What else to do? */
		ret = (unsigned long)panic;
	}

	return ret;
}

206
int __trace_graph_entry(struct trace_array *tr,
207 208 209 210 211 212
				struct ftrace_graph_ent *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_entry;
	struct ring_buffer_event *event;
213
	struct ring_buffer *buffer = tr->buffer;
214 215
	struct ftrace_graph_ent_entry *entry;

216
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
217 218
		return 0;

219
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
220 221 222 223 224
					  sizeof(*entry), flags, pc);
	if (!event)
		return 0;
	entry	= ring_buffer_event_data(event);
	entry->graph_ent			= *trace;
225
	if (!filter_current_check_discard(buffer, call, entry, event))
226
		__buffer_unlock_commit(buffer, event);
227 228 229 230

	return 1;
}

231 232
static inline int ftrace_graph_ignore_irqs(void)
{
233
	if (!ftrace_graph_skip_irqs || trace_recursion_test(TRACE_IRQ_BIT))
234 235 236 237 238
		return 0;

	return in_irq();
}

239 240 241 242 243 244 245 246 247 248 249 250 251
int trace_graph_entry(struct ftrace_graph_ent *trace)
{
	struct trace_array *tr = graph_array;
	struct trace_array_cpu *data;
	unsigned long flags;
	long disabled;
	int ret;
	int cpu;
	int pc;

	if (!ftrace_trace_task(current))
		return 0;

252
	/* trace it when it is-nested-in or is a function enabled. */
253 254
	if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
	      ftrace_graph_ignore_irqs())
255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273
		return 0;

	local_irq_save(flags);
	cpu = raw_smp_processor_id();
	data = tr->data[cpu];
	disabled = atomic_inc_return(&data->disabled);
	if (likely(disabled == 1)) {
		pc = preempt_count();
		ret = __trace_graph_entry(tr, trace, flags, pc);
	} else {
		ret = 0;
	}

	atomic_dec(&data->disabled);
	local_irq_restore(flags);

	return ret;
}

274 275 276 277 278 279 280 281
int trace_graph_thresh_entry(struct ftrace_graph_ent *trace)
{
	if (tracing_thresh)
		return 1;
	else
		return trace_graph_entry(trace);
}

282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309
static void
__trace_graph_function(struct trace_array *tr,
		unsigned long ip, unsigned long flags, int pc)
{
	u64 time = trace_clock_local();
	struct ftrace_graph_ent ent = {
		.func  = ip,
		.depth = 0,
	};
	struct ftrace_graph_ret ret = {
		.func     = ip,
		.depth    = 0,
		.calltime = time,
		.rettime  = time,
	};

	__trace_graph_entry(tr, &ent, flags, pc);
	__trace_graph_return(tr, &ret, flags, pc);
}

void
trace_graph_function(struct trace_array *tr,
		unsigned long ip, unsigned long parent_ip,
		unsigned long flags, int pc)
{
	__trace_graph_function(tr, ip, flags, pc);
}

310
void __trace_graph_return(struct trace_array *tr,
311 312 313 314 315 316
				struct ftrace_graph_ret *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_exit;
	struct ring_buffer_event *event;
317
	struct ring_buffer *buffer = tr->buffer;
318 319
	struct ftrace_graph_ret_entry *entry;

320
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
321 322
		return;

323
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
324 325 326 327 328
					  sizeof(*entry), flags, pc);
	if (!event)
		return;
	entry	= ring_buffer_event_data(event);
	entry->ret				= *trace;
329
	if (!filter_current_check_discard(buffer, call, entry, event))
330
		__buffer_unlock_commit(buffer, event);
331 332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353
}

void trace_graph_return(struct ftrace_graph_ret *trace)
{
	struct trace_array *tr = graph_array;
	struct trace_array_cpu *data;
	unsigned long flags;
	long disabled;
	int cpu;
	int pc;

	local_irq_save(flags);
	cpu = raw_smp_processor_id();
	data = tr->data[cpu];
	disabled = atomic_inc_return(&data->disabled);
	if (likely(disabled == 1)) {
		pc = preempt_count();
		__trace_graph_return(tr, trace, flags, pc);
	}
	atomic_dec(&data->disabled);
	local_irq_restore(flags);
}

354 355 356 357 358 359 360 361 362
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

363 364 365 366 367 368 369 370 371
void trace_graph_thresh_return(struct ftrace_graph_ret *trace)
{
	if (tracing_thresh &&
	    (trace->rettime - trace->calltime < tracing_thresh))
		return;
	else
		trace_graph_return(trace);
}

372 373
static int graph_trace_init(struct trace_array *tr)
{
374 375
	int ret;

376
	set_graph_array(tr);
377 378 379 380 381 382
	if (tracing_thresh)
		ret = register_ftrace_graph(&trace_graph_thresh_return,
					    &trace_graph_thresh_entry);
	else
		ret = register_ftrace_graph(&trace_graph_return,
					    &trace_graph_entry);
383 384 385 386 387
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
388 389 390 391
}

static void graph_trace_reset(struct trace_array *tr)
{
392 393
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
394 395
}

396
static int max_bytes_for_cpu;
397 398 399 400 401 402

static enum print_line_t
print_graph_cpu(struct trace_seq *s, int cpu)
{
	int ret;

403 404 405 406 407
	/*
	 * Start with a space character - to make it stand out
	 * to the right a bit when trace output is pasted into
	 * email:
	 */
408
	ret = trace_seq_printf(s, " %*d) ", max_bytes_for_cpu, cpu);
409
	if (!ret)
410 411
		return TRACE_TYPE_PARTIAL_LINE;

412 413 414
	return TRACE_TYPE_HANDLED;
}

415 416 417 418 419
#define TRACE_GRAPH_PROCINFO_LENGTH	14

static enum print_line_t
print_graph_proc(struct trace_seq *s, pid_t pid)
{
420
	char comm[TASK_COMM_LEN];
421 422
	/* sign + log10(MAX_INT) + '\0' */
	char pid_str[11];
423 424 425 426
	int spaces = 0;
	int ret;
	int len;
	int i;
427

428
	trace_find_cmdline(pid, comm);
429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451 452 453 454 455 456 457
	comm[7] = '\0';
	sprintf(pid_str, "%d", pid);

	/* 1 stands for the "-" character */
	len = strlen(comm) + strlen(pid_str) + 1;

	if (len < TRACE_GRAPH_PROCINFO_LENGTH)
		spaces = TRACE_GRAPH_PROCINFO_LENGTH - len;

	/* First spaces to align center */
	for (i = 0; i < spaces / 2; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	ret = trace_seq_printf(s, "%s-%s", comm, pid_str);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Last spaces to align center */
	for (i = 0; i < spaces - (spaces / 2); i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
	return TRACE_TYPE_HANDLED;
}

458

459 460 461
static enum print_line_t
print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
{
462
	if (!trace_seq_putc(s, ' '))
463 464
		return 0;

465
	return trace_print_lat_fmt(s, entry);
466 467
}

468
/* If the pid changed since the last trace, output this event */
469
static enum print_line_t
470
verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
471
{
472
	pid_t prev_pid;
473
	pid_t *last_pid;
474
	int ret;
475

476
	if (!data)
477 478
		return TRACE_TYPE_HANDLED;

479
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
480 481

	if (*last_pid == pid)
482
		return TRACE_TYPE_HANDLED;
483

484 485
	prev_pid = *last_pid;
	*last_pid = pid;
486

487 488
	if (prev_pid == -1)
		return TRACE_TYPE_HANDLED;
489 490 491 492 493 494 495 496 497
/*
 * Context-switch trace line:

 ------------------------------------------
 | 1)  migration/0--1  =>  sshd-1755
 ------------------------------------------

 */
	ret = trace_seq_printf(s,
498
		" ------------------------------------------\n");
499
	if (!ret)
500
		return TRACE_TYPE_PARTIAL_LINE;
501 502 503

	ret = print_graph_cpu(s, cpu);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
504
		return TRACE_TYPE_PARTIAL_LINE;
505 506 507

	ret = print_graph_proc(s, prev_pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
508
		return TRACE_TYPE_PARTIAL_LINE;
509 510 511

	ret = trace_seq_printf(s, " => ");
	if (!ret)
512
		return TRACE_TYPE_PARTIAL_LINE;
513 514 515

	ret = print_graph_proc(s, pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
516
		return TRACE_TYPE_PARTIAL_LINE;
517 518 519 520

	ret = trace_seq_printf(s,
		"\n ------------------------------------------\n\n");
	if (!ret)
521
		return TRACE_TYPE_PARTIAL_LINE;
522

523
	return TRACE_TYPE_HANDLED;
524 525
}

526 527
static struct ftrace_graph_ret_entry *
get_return_for_leaf(struct trace_iterator *iter,
528 529
		struct ftrace_graph_ent_entry *curr)
{
530 531
	struct fgraph_data *data = iter->private;
	struct ring_buffer_iter *ring_iter = NULL;
532 533 534
	struct ring_buffer_event *event;
	struct ftrace_graph_ret_entry *next;

535 536 537 538 539 540 541 542
	/*
	 * If the previous output failed to write to the seq buffer,
	 * then we just reuse the data from before.
	 */
	if (data && data->failed) {
		curr = &data->ent;
		next = &data->ret;
	} else {
543

544
		ring_iter = trace_buffer_iter(iter, iter->cpu);
545 546 547 548 549 550 551 552 553

		/* First peek to compare current entry and the next one */
		if (ring_iter)
			event = ring_buffer_iter_peek(ring_iter, NULL);
		else {
			/*
			 * We need to consume the current entry to see
			 * the next one.
			 */
554 555
			ring_buffer_consume(iter->tr->buffer, iter->cpu,
					    NULL, NULL);
556
			event = ring_buffer_peek(iter->tr->buffer, iter->cpu,
557
						 NULL, NULL);
558
		}
559

560 561 562 563
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
564

565 566 567 568 569 570
		if (data) {
			/*
			 * Save current and next entries for later reference
			 * if the output fails.
			 */
			data->ent = *curr;
571 572 573 574 575 576 577 578 579
			/*
			 * If the next event is not a return type, then
			 * we only care about what type it is. Otherwise we can
			 * safely copy the entire event.
			 */
			if (next->ent.type == TRACE_GRAPH_RET)
				data->ret = *next;
			else
				data->ret.ent.type = next->ent.type;
580 581
		}
	}
582 583

	if (next->ent.type != TRACE_GRAPH_RET)
584
		return NULL;
585 586 587

	if (curr->ent.pid != next->ent.pid ||
			curr->graph_ent.func != next->ret.func)
588
		return NULL;
589

590 591 592 593 594
	/* this is a leaf, now advance the iterator */
	if (ring_iter)
		ring_buffer_read(ring_iter, NULL);

	return next;
595 596
}

597 598 599 600 601 602 603 604 605 606 607
static int print_graph_abs_time(u64 t, struct trace_seq *s)
{
	unsigned long usecs_rem;

	usecs_rem = do_div(t, NSEC_PER_SEC);
	usecs_rem /= 1000;

	return trace_seq_printf(s, "%5lu.%06lu |  ",
			(unsigned long)t, usecs_rem);
}

608
static enum print_line_t
609
print_graph_irq(struct trace_iterator *iter, unsigned long addr,
610
		enum trace_type type, int cpu, pid_t pid, u32 flags)
611 612
{
	int ret;
613
	struct trace_seq *s = &iter->seq;
614 615 616 617 618

	if (addr < (unsigned long)__irqentry_text_start ||
		addr >= (unsigned long)__irqentry_text_end)
		return TRACE_TYPE_UNHANDLED;

619 620 621 622 623 624 625
	if (trace_flags & TRACE_ITER_CONTEXT_INFO) {
		/* Absolute time */
		if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
			ret = print_graph_abs_time(iter->ts, s);
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}
626

627 628 629 630 631 632
		/* Cpu */
		if (flags & TRACE_GRAPH_PRINT_CPU) {
			ret = print_graph_cpu(s, cpu);
			if (ret == TRACE_TYPE_PARTIAL_LINE)
				return TRACE_TYPE_PARTIAL_LINE;
		}
633

634 635 636 637 638 639 640 641 642
		/* Proc */
		if (flags & TRACE_GRAPH_PRINT_PROC) {
			ret = print_graph_proc(s, pid);
			if (ret == TRACE_TYPE_PARTIAL_LINE)
				return TRACE_TYPE_PARTIAL_LINE;
			ret = trace_seq_printf(s, " | ");
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}
643
	}
644

645
	/* No overhead */
646 647 648
	ret = print_graph_duration(DURATION_FILL_START, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
649

650 651 652 653 654 655 656 657
	if (type == TRACE_GRAPH_ENT)
		ret = trace_seq_printf(s, "==========>");
	else
		ret = trace_seq_printf(s, "<==========");

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

658 659 660 661
	ret = print_graph_duration(DURATION_FILL_END, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;

662
	ret = trace_seq_printf(s, "\n");
663 664 665 666 667

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
	return TRACE_TYPE_HANDLED;
}
668

669 670
enum print_line_t
trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
671 672
{
	unsigned long nsecs_rem = do_div(duration, 1000);
673 674 675 676 677 678 679 680 681
	/* log10(ULONG_MAX) + '\0' */
	char msecs_str[21];
	char nsecs_str[5];
	int ret, len;
	int i;

	sprintf(msecs_str, "%lu", (unsigned long) duration);

	/* Print msecs */
682
	ret = trace_seq_printf(s, "%s", msecs_str);
683 684 685 686 687 688 689
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	len = strlen(msecs_str);

	/* Print nsecs (we don't want to exceed 7 numbers) */
	if (len < 7) {
690 691 692
		size_t slen = min_t(size_t, sizeof(nsecs_str), 8UL - len);

		snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
693 694 695 696 697 698 699 700 701 702 703 704 705 706 707 708
		ret = trace_seq_printf(s, ".%s", nsecs_str);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
		len += strlen(nsecs_str);
	}

	ret = trace_seq_printf(s, " us ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Print remaining spaces to fit the row's width */
	for (i = len; i < 7; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
709 710 711 712
	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
713 714
print_graph_duration(unsigned long long duration, struct trace_seq *s,
		     u32 flags)
715
{
716 717
	int ret = -1;

718 719 720
	if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
	    !(trace_flags & TRACE_ITER_CONTEXT_INFO))
			return TRACE_TYPE_HANDLED;
721 722 723 724 725 726 727 728 729 730 731 732 733 734 735 736 737 738 739 740 741 742 743 744 745 746 747 748 749 750 751 752 753 754 755

	/* No real adata, just filling the column with spaces */
	switch (duration) {
	case DURATION_FILL_FULL:
		ret = trace_seq_printf(s, "              |  ");
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
	case DURATION_FILL_START:
		ret = trace_seq_printf(s, "  ");
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
	case DURATION_FILL_END:
		ret = trace_seq_printf(s, " |");
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
	}

	/* Signal a overhead of time execution to the output */
	if (flags & TRACE_GRAPH_PRINT_OVERHEAD) {
		/* Duration exceeded 100 msecs */
		if (duration > 100000ULL)
			ret = trace_seq_printf(s, "! ");
		/* Duration exceeded 10 msecs */
		else if (duration > 10000ULL)
			ret = trace_seq_printf(s, "+ ");
	}

	/*
	 * The -1 means we either did not exceed the duration tresholds
	 * or we dont want to print out the overhead. Either way we need
	 * to fill out the space.
	 */
	if (ret == -1)
		ret = trace_seq_printf(s, "  ");

	/* Catching here any failure happenned above */
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
756 757 758 759

	ret = trace_print_graph_duration(duration, s);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
760 761 762 763 764

	ret = trace_seq_printf(s, "|  ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

765
	return TRACE_TYPE_HANDLED;
766 767 768
}

/* Case of a leaf function on its call entry */
769
static enum print_line_t
770
print_graph_entry_leaf(struct trace_iterator *iter,
771
		struct ftrace_graph_ent_entry *entry,
772 773
		struct ftrace_graph_ret_entry *ret_entry,
		struct trace_seq *s, u32 flags)
774
{
775
	struct fgraph_data *data = iter->private;
776 777 778
	struct ftrace_graph_ret *graph_ret;
	struct ftrace_graph_ent *call;
	unsigned long long duration;
779
	int ret;
780
	int i;
781

782 783 784 785
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

786
	if (data) {
787
		struct fgraph_cpu_data *cpu_data;
788
		int cpu = iter->cpu;
789 790

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
791 792 793 794 795 796

		/*
		 * Comments display at + 1 to depth. Since
		 * this is a leaf function, keep the comments
		 * equal to this depth.
		 */
797 798 799 800 801
		cpu_data->depth = call->depth - 1;

		/* No need to keep this function around for this depth */
		if (call->depth < FTRACE_RETFUNC_DEPTH)
			cpu_data->enter_funcs[call->depth] = 0;
802 803
	}

804 805 806
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
807
		return TRACE_TYPE_PARTIAL_LINE;
808

809 810 811 812 813 814 815
	/* Function */
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

816
	ret = trace_seq_printf(s, "%ps();\n", (void *)call->func);
817 818 819 820 821 822 823
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
824 825
print_graph_entry_nested(struct trace_iterator *iter,
			 struct ftrace_graph_ent_entry *entry,
826
			 struct trace_seq *s, int cpu, u32 flags)
827 828
{
	struct ftrace_graph_ent *call = &entry->graph_ent;
829 830 831 832 833
	struct fgraph_data *data = iter->private;
	int ret;
	int i;

	if (data) {
834
		struct fgraph_cpu_data *cpu_data;
835 836
		int cpu = iter->cpu;

837 838 839 840 841 842
		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
		cpu_data->depth = call->depth;

		/* Save this function pointer to see if the exit matches */
		if (call->depth < FTRACE_RETFUNC_DEPTH)
			cpu_data->enter_funcs[call->depth] = call->func;
843
	}
844

845
	/* No time */
846 847 848
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
849

850
	/* Function */
851 852
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
853 854
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
855 856
	}

857
	ret = trace_seq_printf(s, "%ps() {\n", (void *)call->func);
858 859 860
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

861 862 863 864 865
	/*
	 * we already consumed the current entry to check the next one
	 * and see if this is a leaf.
	 */
	return TRACE_TYPE_NO_CONSUME;
866 867
}

868
static enum print_line_t
869
print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
870
		     int type, unsigned long addr, u32 flags)
871
{
872
	struct fgraph_data *data = iter->private;
873
	struct trace_entry *ent = iter->ent;
874 875
	int cpu = iter->cpu;
	int ret;
876

877
	/* Pid */
878
	if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
879 880
		return TRACE_TYPE_PARTIAL_LINE;

881 882
	if (type) {
		/* Interrupt */
883
		ret = print_graph_irq(iter, addr, type, cpu, ent->pid, flags);
884 885 886
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
887

888 889 890
	if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
		return 0;

891
	/* Absolute time */
892
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
893 894 895 896 897
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

898
	/* Cpu */
899
	if (flags & TRACE_GRAPH_PRINT_CPU) {
900
		ret = print_graph_cpu(s, cpu);
901 902 903 904 905
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
906
	if (flags & TRACE_GRAPH_PRINT_PROC) {
907
		ret = print_graph_proc(s, ent->pid);
908 909 910 911
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

		ret = trace_seq_printf(s, " | ");
912 913 914
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
915

916 917 918 919 920 921 922
	/* Latency format */
	if (trace_flags & TRACE_ITER_LATENCY_FMT) {
		ret = print_graph_lat_fmt(s, ent);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

923 924 925
	return 0;
}

926 927 928 929 930
/*
 * Entry check for irq code
 *
 * returns 1 if
 *  - we are inside irq code
Lucas De Marchi's avatar
Lucas De Marchi committed
931
 *  - we just entered irq code
932 933 934 935 936 937 938 939 940 941
 *
 * retunns 0 if
 *  - funcgraph-interrupts option is set
 *  - we are not inside irq code
 */
static int
check_irq_entry(struct trace_iterator *iter, u32 flags,
		unsigned long addr, int depth)
{
	int cpu = iter->cpu;
942
	int *depth_irq;
943 944
	struct fgraph_data *data = iter->private;

945 946 947 948 949 950 951
	/*
	 * If we are either displaying irqs, or we got called as
	 * a graph event and private data does not exist,
	 * then we bypass the irq check.
	 */
	if ((flags & TRACE_GRAPH_PRINT_IRQS) ||
	    (!data))
952 953
		return 0;

954 955
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

956 957 958 959 960 961 962 963 964 965 966 967 968 969 970 971 972 973 974 975 976 977 978 979 980 981 982 983 984 985 986 987
	/*
	 * We are inside the irq code
	 */
	if (*depth_irq >= 0)
		return 1;

	if ((addr < (unsigned long)__irqentry_text_start) ||
	    (addr >= (unsigned long)__irqentry_text_end))
		return 0;

	/*
	 * We are entering irq code.
	 */
	*depth_irq = depth;
	return 1;
}

/*
 * Return check for irq code
 *
 * returns 1 if
 *  - we are inside irq code
 *  - we just left irq code
 *
 * returns 0 if
 *  - funcgraph-interrupts option is set
 *  - we are not inside irq code
 */
static int
check_irq_return(struct trace_iterator *iter, u32 flags, int depth)
{
	int cpu = iter->cpu;
988
	int *depth_irq;
989 990
	struct fgraph_data *data = iter->private;

991 992 993 994 995 996 997
	/*
	 * If we are either displaying irqs, or we got called as
	 * a graph event and private data does not exist,
	 * then we bypass the irq check.
	 */
	if ((flags & TRACE_GRAPH_PRINT_IRQS) ||
	    (!data))
998 999
		return 0;

1000 1001
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012 1013 1014 1015 1016 1017 1018 1019 1020 1021 1022 1023 1024 1025 1026 1027
	/*
	 * We are not inside the irq code.
	 */
	if (*depth_irq == -1)
		return 0;

	/*
	 * We are inside the irq code, and this is returning entry.
	 * Let's not trace it and clear the entry depth, since
	 * we are out of irq code.
	 *
	 * This condition ensures that we 'leave the irq code' once
	 * we are out of the entry depth. Thus protecting us from
	 * the RETURN entry loss.
	 */
	if (*depth_irq >= depth) {
		*depth_irq = -1;
		return 1;
	}

	/*
	 * We are inside the irq code, and this is not the entry.
	 */
	return 1;
}

1028 1029
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
1030
			struct trace_iterator *iter, u32 flags)
1031
{
1032
	struct fgraph_data *data = iter->private;
1033 1034
	struct ftrace_graph_ent *call = &field->graph_ent;
	struct ftrace_graph_ret_entry *leaf_ret;
1035 1036
	static enum print_line_t ret;
	int cpu = iter->cpu;
1037

1038 1039 1040
	if (check_irq_entry(iter, flags, call->func, call->depth))
		return TRACE_TYPE_HANDLED;

1041
	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
1042 1043
		return TRACE_TYPE_PARTIAL_LINE;

1044 1045
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
1046
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
1047
	else
1048
		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
1049

1050 1051 1052 1053 1054 1055 1056 1057 1058 1059 1060 1061 1062
	if (data) {
		/*
		 * If we failed to write our output, then we need to make
		 * note of it. Because we already consumed our entry.
		 */
		if (s->full) {
			data->failed = 1;
			data->cpu = cpu;
		} else
			data->failed = 0;
	}

	return ret;
1063 1064
}

1065 1066
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
1067 1068
		   struct trace_entry *ent, struct trace_iterator *iter,
		   u32 flags)
1069
{
1070
	unsigned long long duration = trace->rettime - trace->calltime;
1071 1072 1073
	struct fgraph_data *data = iter->private;
	pid_t pid = ent->pid;
	int cpu = iter->cpu;
1074
	int func_match = 1;
1075 1076 1077
	int ret;
	int i;

1078 1079 1080
	if (check_irq_return(iter, flags, trace->depth))
		return TRACE_TYPE_HANDLED;

1081
	if (data) {
1082 1083 1084 1085
		struct fgraph_cpu_data *cpu_data;
		int cpu = iter->cpu;

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
1086 1087 1088 1089 1090 1091

		/*
		 * Comments display at + 1 to depth. This is the
		 * return from a function, we now want the comments
		 * to display at the same level of the bracket.
		 */
1092 1093 1094 1095 1096 1097 1098
		cpu_data->depth = trace->depth - 1;

		if (trace->depth < FTRACE_RETFUNC_DEPTH) {
			if (cpu_data->enter_funcs[trace->depth] != trace->func)
				func_match = 0;
			cpu_data->enter_funcs[trace->depth] = 0;
		}
1099
	}
1100

1101
	if (print_graph_prologue(iter, s, 0, 0, flags))
1102 1103
		return TRACE_TYPE_PARTIAL_LINE;

1104 1105 1106
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
1107
		return TRACE_TYPE_PARTIAL_LINE;
1108

1109
	/* Closing brace */
1110 1111
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
1112 1113
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1114 1115
	}

1116 1117 1118 1119 1120 1121 1122 1123 1124 1125 1126
	/*
	 * If the return function does not have a matching entry,
	 * then the entry was lost. Instead of just printing
	 * the '}' and letting the user guess what function this
	 * belongs to, write out the function name.
	 */
	if (func_match) {
		ret = trace_seq_printf(s, "}\n");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	} else {
1127
		ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
1128 1129 1130
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
1131

1132
	/* Overrun */
1133
	if (flags & TRACE_GRAPH_PRINT_OVERRUN) {
1134 1135
		ret = trace_seq_printf(s, " (Overruns: %lu)\n",
					trace->overrun);
1136 1137
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1138
	}
1139

1140 1141
	ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET,
			      cpu, pid, flags);
1142 1143 1144
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;

1145 1146 1147
	return TRACE_TYPE_HANDLED;
}

1148
static enum print_line_t
1149 1150
print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
		    struct trace_iterator *iter, u32 flags)
1151
{
1152
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
1153
	struct fgraph_data *data = iter->private;
1154
	struct trace_event *event;
1155
	int depth = 0;
1156
	int ret;
1157 1158 1159
	int i;

	if (data)
1160
		depth = per_cpu_ptr(data->cpu_data, iter->cpu)->depth;
1161

1162
	if (print_graph_prologue(iter, s, 0, 0, flags))
1163 1164
		return TRACE_TYPE_PARTIAL_LINE;

1165
	/* No time */
1166 1167 1168
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
1169 1170

	/* Indentation */
1171 1172
	if (depth > 0)
		for (i = 0; i < (depth + 1) * TRACE_GRAPH_INDENT; i++) {
1173 1174 1175 1176 1177 1178
			ret = trace_seq_printf(s, " ");
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}

	/* The comment */
1179 1180 1181 1182
	ret = trace_seq_printf(s, "/* ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

1183 1184 1185 1186 1187 1188 1189 1190 1191 1192 1193 1194 1195 1196 1197 1198
	switch (iter->ent->type) {
	case TRACE_BPRINT:
		ret = trace_print_bprintk_msg_only(iter);
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
		break;
	case TRACE_PRINT:
		ret = trace_print_printk_msg_only(iter);
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
		break;
	default:
		event = ftrace_find_event(ent->type);
		if (!event)
			return TRACE_TYPE_UNHANDLED;

1199
		ret = event->funcs->trace(iter, sym_flags, event);
1200 1201 1202
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
	}
1203

1204 1205 1206 1207 1208 1209
	/* Strip ending newline */
	if (s->buffer[s->len - 1] == '\n') {
		s->buffer[s->len - 1] = '\0';
		s->len--;
	}

1210 1211 1212 1213 1214 1215 1216 1217
	ret = trace_seq_printf(s, " */\n");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}


1218
enum print_line_t
1219
print_graph_function_flags(struct trace_iterator *iter, u32 flags)
1220
{
1221 1222
	struct ftrace_graph_ent_entry *field;
	struct fgraph_data *data = iter->private;
1223
	struct trace_entry *entry = iter->ent;
1224
	struct trace_seq *s = &iter->seq;
1225 1226 1227 1228 1229 1230 1231 1232 1233 1234 1235 1236 1237 1238 1239
	int cpu = iter->cpu;
	int ret;

	if (data && per_cpu_ptr(data->cpu_data, cpu)->ignore) {
		per_cpu_ptr(data->cpu_data, cpu)->ignore = 0;
		return TRACE_TYPE_HANDLED;
	}

	/*
	 * If the last output failed, there's a possibility we need
	 * to print out the missing entry which would never go out.
	 */
	if (data && data->failed) {
		field = &data->ent;
		iter->cpu = data->cpu;
1240
		ret = print_graph_entry(field, s, iter, flags);
1241 1242 1243 1244 1245 1246 1247
		if (ret == TRACE_TYPE_HANDLED && iter->cpu != cpu) {
			per_cpu_ptr(data->cpu_data, iter->cpu)->ignore = 1;
			ret = TRACE_TYPE_NO_CONSUME;
		}
		iter->cpu = cpu;
		return ret;
	}
1248

1249 1250
	switch (entry->type) {
	case TRACE_GRAPH_ENT: {
1251 1252 1253 1254 1255 1256
		/*
		 * print_graph_entry() may consume the current event,
		 * thus @field may become invalid, so we need to save it.
		 * sizeof(struct ftrace_graph_ent_entry) is very small,
		 * it can be safely saved at the stack.
		 */
1257
		struct ftrace_graph_ent_entry saved;
1258
		trace_assign_type(field, entry);
1259
		saved = *field;
1260
		return print_graph_entry(&saved, s, iter, flags);
1261 1262 1263 1264
	}
	case TRACE_GRAPH_RET: {
		struct ftrace_graph_ret_entry *field;
		trace_assign_type(field, entry);