trace_functions_graph.c 34.8 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 147 148 149 150 151 152 153 154 155 156 157 158 159 160
#ifdef CONFIG_HAVE_FUNCTION_GRAPH_FP_TEST
	/*
	 * 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.
	 */
	if (unlikely(current->ret_stack[index].fp != frame_pointer)) {
		ftrace_graph_stop();
		WARN(1, "Bad frame pointer: expected %lx, received %lx\n"
161
		     "  from func %ps return to %lx\n",
162 163 164 165 166 167 168 169 170
		     current->ret_stack[index].fp,
		     frame_pointer,
		     (void *)current->ret_stack[index].func,
		     current->ret_stack[index].ret);
		*ret = (unsigned long)panic;
		return;
	}
#endif

171 172 173 174 175 176 177 178 179 180 181
	*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.
 */
182
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
183 184 185 186
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

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

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

	return ret;
}

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

213
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
214 215
		return 0;

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

	return 1;
}

228 229 230 231 232 233 234 235
static inline int ftrace_graph_ignore_irqs(void)
{
	if (!ftrace_graph_skip_irqs)
		return 0;

	return in_irq();
}

236 237 238 239 240 241 242 243 244 245 246 247 248
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;

249
	/* trace it when it is-nested-in or is a function enabled. */
250 251
	if (!(trace->depth || ftrace_graph_addr(trace->func)) ||
	      ftrace_graph_ignore_irqs())
252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270
		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;
}

271 272 273 274 275 276 277 278
int trace_graph_thresh_entry(struct ftrace_graph_ent *trace)
{
	if (tracing_thresh)
		return 1;
	else
		return trace_graph_entry(trace);
}

279 280 281 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
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);
}

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

317
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
318 319
		return;

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

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);
}

351 352 353 354 355 356 357 358 359
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

360 361 362 363 364 365 366 367 368
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);
}

369 370
static int graph_trace_init(struct trace_array *tr)
{
371 372
	int ret;

373
	set_graph_array(tr);
374 375 376 377 378 379
	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);
380 381 382 383 384
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
385 386 387 388
}

static void graph_trace_reset(struct trace_array *tr)
{
389 390
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
391 392
}

393
static int max_bytes_for_cpu;
394 395 396 397 398 399

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

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

409 410 411
	return TRACE_TYPE_HANDLED;
}

412 413 414 415 416
#define TRACE_GRAPH_PROCINFO_LENGTH	14

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

425
	trace_find_cmdline(pid, comm);
426 427 428 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
	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;
}

455

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

462
	return trace_print_lat_fmt(s, entry);
463 464
}

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

473
	if (!data)
474 475
		return TRACE_TYPE_HANDLED;

476
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
477 478

	if (*last_pid == pid)
479
		return TRACE_TYPE_HANDLED;
480

481 482
	prev_pid = *last_pid;
	*last_pid = pid;
483

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

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

 */
	ret = trace_seq_printf(s,
495
		" ------------------------------------------\n");
496
	if (!ret)
497
		return TRACE_TYPE_PARTIAL_LINE;
498 499 500

	ret = print_graph_cpu(s, cpu);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
501
		return TRACE_TYPE_PARTIAL_LINE;
502 503 504

	ret = print_graph_proc(s, prev_pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
505
		return TRACE_TYPE_PARTIAL_LINE;
506 507 508

	ret = trace_seq_printf(s, " => ");
	if (!ret)
509
		return TRACE_TYPE_PARTIAL_LINE;
510 511 512

	ret = print_graph_proc(s, pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
513
		return TRACE_TYPE_PARTIAL_LINE;
514 515 516 517

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

520
	return TRACE_TYPE_HANDLED;
521 522
}

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

532 533 534 535 536 537 538 539
	/*
	 * 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 {
540

541 542 543 544 545 546 547 548 549 550
		ring_iter = iter->buffer_iter[iter->cpu];

		/* 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.
			 */
551 552
			ring_buffer_consume(iter->tr->buffer, iter->cpu,
					    NULL, NULL);
553
			event = ring_buffer_peek(iter->tr->buffer, iter->cpu,
554
						 NULL, NULL);
555
		}
556

557 558 559 560
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
561

562 563 564 565 566 567
		if (data) {
			/*
			 * Save current and next entries for later reference
			 * if the output fails.
			 */
			data->ent = *curr;
568 569 570 571 572 573 574 575 576
			/*
			 * 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;
577 578
		}
	}
579 580

	if (next->ent.type != TRACE_GRAPH_RET)
581
		return NULL;
582 583 584

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

587 588 589 590 591
	/* this is a leaf, now advance the iterator */
	if (ring_iter)
		ring_buffer_read(ring_iter, NULL);

	return next;
592 593
}

594 595 596 597 598 599 600 601 602 603 604
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);
}

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

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

616 617 618 619 620 621 622
	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;
		}
623

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

631 632 633 634 635 636 637 638 639
		/* 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;
		}
640
	}
641

642
	/* No overhead */
643 644 645
	ret = print_graph_duration(DURATION_FILL_START, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
646

647 648 649 650 651 652 653 654
	if (type == TRACE_GRAPH_ENT)
		ret = trace_seq_printf(s, "==========>");
	else
		ret = trace_seq_printf(s, "<==========");

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

655 656 657 658
	ret = print_graph_duration(DURATION_FILL_END, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;

659
	ret = trace_seq_printf(s, "\n");
660 661 662 663 664

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

666 667
enum print_line_t
trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
668 669
{
	unsigned long nsecs_rem = do_div(duration, 1000);
670 671 672 673 674 675 676 677 678
	/* 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 */
679
	ret = trace_seq_printf(s, "%s", msecs_str);
680 681 682 683 684 685 686
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	len = strlen(msecs_str);

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

		snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
690 691 692 693 694 695 696 697 698 699 700 701 702 703 704 705
		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;
	}
706 707 708 709
	return TRACE_TYPE_HANDLED;
}

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

715 716 717
	if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
	    !(trace_flags & TRACE_ITER_CONTEXT_INFO))
			return TRACE_TYPE_HANDLED;
718 719 720 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

	/* 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;
753 754 755 756

	ret = trace_print_graph_duration(duration, s);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
757 758 759 760 761

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

762
	return TRACE_TYPE_HANDLED;
763 764 765
}

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

779 780 781 782
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

783
	if (data) {
784
		struct fgraph_cpu_data *cpu_data;
785
		int cpu = iter->cpu;
786 787

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
788 789 790 791 792 793

		/*
		 * Comments display at + 1 to depth. Since
		 * this is a leaf function, keep the comments
		 * equal to this depth.
		 */
794 795 796 797 798
		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;
799 800
	}

801 802 803
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
804
		return TRACE_TYPE_PARTIAL_LINE;
805

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

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

	return TRACE_TYPE_HANDLED;
}

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

	if (data) {
831
		struct fgraph_cpu_data *cpu_data;
832 833
		int cpu = iter->cpu;

834 835 836 837 838 839
		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;
840
	}
841

842
	/* No time */
843 844 845
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
846

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

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

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

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

874
	/* Pid */
875
	if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
876 877
		return TRACE_TYPE_PARTIAL_LINE;

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

885 886 887
	if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
		return 0;

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

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

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

		ret = trace_seq_printf(s, " | ");
909 910 911
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
912

913 914 915 916 917 918 919
	/* 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;
	}

920 921 922
	return 0;
}

923 924 925 926 927
/*
 * Entry check for irq code
 *
 * returns 1 if
 *  - we are inside irq code
Lucas De Marchi's avatar
Lucas De Marchi committed
928
 *  - we just entered irq code
929 930 931 932 933 934 935 936 937 938
 *
 * 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;
939
	int *depth_irq;
940 941
	struct fgraph_data *data = iter->private;

942 943 944 945 946 947 948
	/*
	 * 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))
949 950
		return 0;

951 952
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

953 954 955 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
	/*
	 * 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;
985
	int *depth_irq;
986 987
	struct fgraph_data *data = iter->private;

988 989 990 991 992 993 994
	/*
	 * 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))
995 996
		return 0;

997 998
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

999 1000 1001 1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012 1013 1014 1015 1016 1017 1018 1019 1020 1021 1022 1023 1024
	/*
	 * 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;
}

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

1035 1036 1037
	if (check_irq_entry(iter, flags, call->func, call->depth))
		return TRACE_TYPE_HANDLED;

1038
	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
1039 1040
		return TRACE_TYPE_PARTIAL_LINE;

1041 1042
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
1043
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
1044
	else
1045
		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
1046

1047 1048 1049 1050 1051 1052 1053 1054 1055 1056 1057 1058 1059
	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;
1060 1061
}

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

1075 1076 1077
	if (check_irq_return(iter, flags, trace->depth))
		return TRACE_TYPE_HANDLED;

1078
	if (data) {
1079 1080 1081 1082
		struct fgraph_cpu_data *cpu_data;
		int cpu = iter->cpu;

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
1083 1084 1085 1086 1087 1088

		/*
		 * 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.
		 */
1089 1090 1091 1092 1093 1094 1095
		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;
		}
1096
	}
1097

1098
	if (print_graph_prologue(iter, s, 0, 0, flags))
1099 1100
		return TRACE_TYPE_PARTIAL_LINE;

1101 1102 1103
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
1104
		return TRACE_TYPE_PARTIAL_LINE;
1105

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

1113 1114 1115 1116 1117 1118 1119 1120 1121 1122 1123
	/*
	 * 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 {
1124
		ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
1125 1126 1127
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
1128

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

1137 1138
	ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET,
			      cpu, pid, flags);
1139 1140 1141
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;

1142 1143 1144
	return TRACE_TYPE_HANDLED;
}

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

	if (data)
1157
		depth = per_cpu_ptr(data->cpu_data, iter->cpu)->depth;
1158

1159
	if (print_graph_prologue(iter, s, 0, 0, flags))
1160 1161
		return TRACE_TYPE_PARTIAL_LINE;

1162
	/* No time */
1163 1164 1165
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
1166 1167

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

	/* The comment */
1176 1177 1178 1179
	ret = trace_seq_printf(s, "/* ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

1180 1181 1182 1183 1184 1185 1186 1187 1188 1189 1190 1191 1192 1193 1194 1195
	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;

1196
		ret = event->funcs->trace(iter, sym_flags, event);
1197 1198 1199
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
	}
1200

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

1207 1208 1209 1210 1211 1212 1213 1214
	ret = trace_seq_printf(s, " */\n");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}


1215
enum print_line_t
1216
print_graph_function_flags(struct trace_iterator *iter, u32 flags)
1217
{
1218 1219
	struct ftrace_graph_ent_entry *field;
	struct fgraph_data *data = iter->private;
1220
	struct trace_entry *entry = iter->ent;
1221
	struct trace_seq *s = &iter->seq;
1222 1223 1224 1225 1226 1227 1228 1229 1230 1231 1232 1233 1234 1235 1236
	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;
1237
		ret = print_graph_entry(field, s, iter, flags);
1238 1239 1240 1241 1242 1243 1244
		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;
	}
1245

1246 1247
	switch (entry->type) {
	case TRACE_GRAPH_ENT: {
1248 1249 1250 1251 1252 1253
		/*
		 * 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.
		 */
1254
		struct ftrace_graph_ent_entry saved;
1255
		trace_assign_type(field, entry);
1256
		saved = *field;
1257
		return print_graph_entry(&saved, s, iter, flags);
1258 1259 1260 1261
	}
	case TRACE_GRAPH_RET: {
		struct ftrace_graph_ret_entry *field;
		trace_assign_type(field, entry);
1262
		return print_graph_return(&field->ret, s, entry, iter, flags);
1263
	}
1264 1265 1266 1267 1268
	case TRACE_STACK:
	case TRACE_FN:
		/* dont trace stack and functions as comments */
		return TRACE_TYPE_UNHANDLED;

1269
	default:
1270
		return print_graph_comment(s, entry, iter, flags);
1271
	}