trace_functions_graph.c 34.6 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
	/* Absolute time */
617
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
618 619 620 621 622
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

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

630
	/* Proc */
631
	if (flags & TRACE_GRAPH_PRINT_PROC) {
632 633 634 635 636 637 638
		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;
	}
639

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

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

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

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

657
	ret = trace_seq_printf(s, "\n");
658 659 660 661 662

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

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

	len = strlen(msecs_str);

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

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

static enum print_line_t
708 709
print_graph_duration(unsigned long long duration, struct trace_seq *s,
		     u32 flags)
710
{
711 712 713 714 715 716 717 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
	int ret = -1;

	if (!(flags & TRACE_GRAPH_PRINT_DURATION))
		return TRACE_TYPE_HANDLED;

	/* 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;
750 751 752 753

	ret = trace_print_graph_duration(duration, s);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
754 755 756 757 758

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

759
	return TRACE_TYPE_HANDLED;
760 761 762
}

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

776 777 778 779
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

780
	if (data) {
781
		struct fgraph_cpu_data *cpu_data;
782
		int cpu = iter->cpu;
783 784

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
785 786 787 788 789 790

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

798 799 800
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
801
		return TRACE_TYPE_PARTIAL_LINE;
802

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

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

	return TRACE_TYPE_HANDLED;
}

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

	if (data) {
828
		struct fgraph_cpu_data *cpu_data;
829 830
		int cpu = iter->cpu;

831 832 833 834 835 836
		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;
837
	}
838

839
	/* No time */
840 841 842
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
843

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

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

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

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

871
	/* Pid */
872
	if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
873 874
		return TRACE_TYPE_PARTIAL_LINE;

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

882
	/* Absolute time */
883
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
884 885 886 887 888
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

889
	/* Cpu */
890
	if (flags & TRACE_GRAPH_PRINT_CPU) {
891
		ret = print_graph_cpu(s, cpu);
892 893 894 895 896
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
897
	if (flags & TRACE_GRAPH_PRINT_PROC) {
898
		ret = print_graph_proc(s, ent->pid);
899 900 901 902
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

		ret = trace_seq_printf(s, " | ");
903 904 905
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
906

907 908 909 910 911 912 913
	/* 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;
	}

914 915 916
	return 0;
}

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

936 937 938 939 940 941 942
	/*
	 * 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))
943 944
		return 0;

945 946
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

947 948 949 950 951 952 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
	/*
	 * 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;
979
	int *depth_irq;
980 981
	struct fgraph_data *data = iter->private;

982 983 984 985 986 987 988
	/*
	 * 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))
989 990
		return 0;

991 992
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

993 994 995 996 997 998 999 1000 1001 1002 1003 1004 1005 1006 1007 1008 1009 1010 1011 1012 1013 1014 1015 1016 1017 1018
	/*
	 * 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;
}

1019 1020
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
1021
			struct trace_iterator *iter, u32 flags)
1022
{
1023
	struct fgraph_data *data = iter->private;
1024 1025
	struct ftrace_graph_ent *call = &field->graph_ent;
	struct ftrace_graph_ret_entry *leaf_ret;
1026 1027
	static enum print_line_t ret;
	int cpu = iter->cpu;
1028

1029 1030 1031
	if (check_irq_entry(iter, flags, call->func, call->depth))
		return TRACE_TYPE_HANDLED;

1032
	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
1033 1034
		return TRACE_TYPE_PARTIAL_LINE;

1035 1036
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
1037
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
1038
	else
1039
		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
1040

1041 1042 1043 1044 1045 1046 1047 1048 1049 1050 1051 1052 1053
	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;
1054 1055
}

1056 1057
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
1058 1059
		   struct trace_entry *ent, struct trace_iterator *iter,
		   u32 flags)
1060
{
1061
	unsigned long long duration = trace->rettime - trace->calltime;
1062 1063 1064
	struct fgraph_data *data = iter->private;
	pid_t pid = ent->pid;
	int cpu = iter->cpu;
1065
	int func_match = 1;
1066 1067 1068
	int ret;
	int i;

1069 1070 1071
	if (check_irq_return(iter, flags, trace->depth))
		return TRACE_TYPE_HANDLED;

1072
	if (data) {
1073 1074 1075 1076
		struct fgraph_cpu_data *cpu_data;
		int cpu = iter->cpu;

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
1077 1078 1079 1080 1081 1082

		/*
		 * 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.
		 */
1083 1084 1085 1086 1087 1088 1089
		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;
		}
1090
	}
1091

1092
	if (print_graph_prologue(iter, s, 0, 0, flags))
1093 1094
		return TRACE_TYPE_PARTIAL_LINE;

1095 1096 1097
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
1098
		return TRACE_TYPE_PARTIAL_LINE;
1099

1100
	/* Closing brace */
1101 1102
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
1103 1104
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1105 1106
	}

1107 1108 1109 1110 1111 1112 1113 1114 1115 1116 1117
	/*
	 * 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 {
1118
		ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
1119 1120 1121
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
1122

1123
	/* Overrun */
1124
	if (flags & TRACE_GRAPH_PRINT_OVERRUN) {
1125 1126
		ret = trace_seq_printf(s, " (Overruns: %lu)\n",
					trace->overrun);
1127 1128
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1129
	}
1130

1131 1132
	ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET,
			      cpu, pid, flags);
1133 1134 1135
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;

1136 1137 1138
	return TRACE_TYPE_HANDLED;
}

1139
static enum print_line_t
1140 1141
print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
		    struct trace_iterator *iter, u32 flags)
1142
{
1143
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
1144
	struct fgraph_data *data = iter->private;
1145
	struct trace_event *event;
1146
	int depth = 0;
1147
	int ret;
1148 1149 1150
	int i;

	if (data)
1151
		depth = per_cpu_ptr(data->cpu_data, iter->cpu)->depth;
1152

1153
	if (print_graph_prologue(iter, s, 0, 0, flags))
1154 1155
		return TRACE_TYPE_PARTIAL_LINE;

1156
	/* No time */
1157 1158 1159
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
1160 1161

	/* Indentation */
1162 1163
	if (depth > 0)
		for (i = 0; i < (depth + 1) * TRACE_GRAPH_INDENT; i++) {
1164 1165 1166 1167 1168 1169
			ret = trace_seq_printf(s, " ");
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}

	/* The comment */
1170 1171 1172 1173
	ret = trace_seq_printf(s, "/* ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

1174 1175 1176 1177 1178 1179 1180 1181 1182 1183 1184 1185 1186 1187 1188 1189
	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;

1190
		ret = event->funcs->trace(iter, sym_flags, event);
1191 1192 1193
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
	}
1194

1195 1196 1197 1198 1199 1200
	/* Strip ending newline */
	if (s->buffer[s->len - 1] == '\n') {
		s->buffer[s->len - 1] = '\0';
		s->len--;
	}

1201 1202 1203 1204 1205 1206 1207 1208
	ret = trace_seq_printf(s, " */\n");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}


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

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

1263
	default:
1264
		return print_graph_comment(s, entry, iter, flags);
1265
	}