trace_functions_graph.c 36.3 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 51
static unsigned int max_depth;

52
static struct tracer_opt trace_opts[] = {
53
	/* Display overruns? (for self-debug purpose) */
54 55 56 57 58
	{ 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) },
59 60
	/* Display proc name/pid */
	{ TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
61 62 63 64
	/* 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) },
65 66
	/* Display interrupts */
	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
67 68 69 70
	{ } /* Empty entry */
};

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

77
static struct trace_array *graph_array;
78

79 80 81 82 83 84 85 86 87 88 89 90 91 92
/*
 * 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);
93

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

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

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

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

117 118
	calltime = trace_clock_local();

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

	return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
132
static void
133 134
ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret,
			unsigned long frame_pointer)
135 136 137 138 139 140 141 142 143 144 145 146 147
{
	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;
	}

148
#if defined(CONFIG_HAVE_FUNCTION_GRAPH_FP_TEST) && !defined(CC_USING_FENTRY)
149 150 151 152 153 154 155 156 157 158
	/*
	 * 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.
159 160 161
	 *
	 * Note, -mfentry does not use frame pointers, and this test
	 *  is not needed if CC_USING_FENTRY is set.
162 163 164 165
	 */
	if (unlikely(current->ret_stack[index].fp != frame_pointer)) {
		ftrace_graph_stop();
		WARN(1, "Bad frame pointer: expected %lx, received %lx\n"
166
		     "  from func %ps return to %lx\n",
167 168 169 170 171 172 173 174 175
		     current->ret_stack[index].fp,
		     frame_pointer,
		     (void *)current->ret_stack[index].func,
		     current->ret_stack[index].ret);
		*ret = (unsigned long)panic;
		return;
	}
#endif

176 177 178 179 180 181 182 183 184 185 186
	*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.
 */
187
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
188 189 190 191
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

192
	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
193
	trace.rettime = trace_clock_local();
194 195
	barrier();
	current->curr_ret_stack--;
196

197 198 199 200 201 202 203
	/*
	 * The trace should run after decrementing the ret counter
	 * in case an interrupt were to come in. We don't want to
	 * lose the interrupt if max_depth is set.
	 */
	ftrace_graph_return(&trace);

204 205 206 207 208 209 210 211 212 213
	if (unlikely(!ret)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic. What else to do? */
		ret = (unsigned long)panic;
	}

	return ret;
}

214
int __trace_graph_entry(struct trace_array *tr,
215 216 217 218 219 220
				struct ftrace_graph_ent *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_entry;
	struct ring_buffer_event *event;
221
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
222 223
	struct ftrace_graph_ent_entry *entry;

224
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
225 226
		return 0;

227
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
228 229 230 231 232
					  sizeof(*entry), flags, pc);
	if (!event)
		return 0;
	entry	= ring_buffer_event_data(event);
	entry->graph_ent			= *trace;
233
	if (!filter_current_check_discard(buffer, call, entry, event))
234
		__buffer_unlock_commit(buffer, event);
235 236 237 238

	return 1;
}

239 240
static inline int ftrace_graph_ignore_irqs(void)
{
241
	if (!ftrace_graph_skip_irqs || trace_recursion_test(TRACE_IRQ_BIT))
242 243 244 245 246
		return 0;

	return in_irq();
}

247 248 249 250 251 252 253 254 255 256 257 258 259
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;

260
	/* trace it when it is-nested-in or is a function enabled. */
261 262 263
	if ((!(trace->depth || ftrace_graph_addr(trace->func)) ||
	     ftrace_graph_ignore_irqs()) ||
	    (max_depth && trace->depth >= max_depth))
264 265 266 267
		return 0;

	local_irq_save(flags);
	cpu = raw_smp_processor_id();
268
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
269 270 271 272 273 274 275 276 277 278 279 280 281 282
	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;
}

283 284 285 286 287 288 289 290
int trace_graph_thresh_entry(struct ftrace_graph_ent *trace)
{
	if (tracing_thresh)
		return 1;
	else
		return trace_graph_entry(trace);
}

291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315 316 317 318
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);
}

319
void __trace_graph_return(struct trace_array *tr,
320 321 322 323 324 325
				struct ftrace_graph_ret *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_exit;
	struct ring_buffer_event *event;
326
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
327 328
	struct ftrace_graph_ret_entry *entry;

329
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
330 331
		return;

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

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();
353
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
354 355 356 357 358 359 360 361 362
	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);
}

363 364 365 366 367 368 369 370 371
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

372 373 374 375 376 377 378 379 380
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);
}

381 382
static int graph_trace_init(struct trace_array *tr)
{
383 384
	int ret;

385
	set_graph_array(tr);
386 387 388 389 390 391
	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);
392 393 394 395 396
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
397 398 399 400
}

static void graph_trace_reset(struct trace_array *tr)
{
401 402
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
403 404
}

405
static int max_bytes_for_cpu;
406 407 408 409 410 411

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

412 413 414 415 416
	/*
	 * Start with a space character - to make it stand out
	 * to the right a bit when trace output is pasted into
	 * email:
	 */
417
	ret = trace_seq_printf(s, " %*d) ", max_bytes_for_cpu, cpu);
418
	if (!ret)
419 420
		return TRACE_TYPE_PARTIAL_LINE;

421 422 423
	return TRACE_TYPE_HANDLED;
}

424 425 426 427 428
#define TRACE_GRAPH_PROCINFO_LENGTH	14

static enum print_line_t
print_graph_proc(struct trace_seq *s, pid_t pid)
{
429
	char comm[TASK_COMM_LEN];
430 431
	/* sign + log10(MAX_INT) + '\0' */
	char pid_str[11];
432 433 434 435
	int spaces = 0;
	int ret;
	int len;
	int i;
436

437
	trace_find_cmdline(pid, comm);
438 439 440 441 442 443 444 445 446 447 448
	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++) {
449
		ret = trace_seq_putc(s, ' ');
450 451 452 453 454 455 456 457 458 459
		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++) {
460
		ret = trace_seq_putc(s, ' ');
461 462 463 464 465 466
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
	return TRACE_TYPE_HANDLED;
}

467

468 469 470
static enum print_line_t
print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
{
471
	if (!trace_seq_putc(s, ' '))
472 473
		return 0;

474
	return trace_print_lat_fmt(s, entry);
475 476
}

477
/* If the pid changed since the last trace, output this event */
478
static enum print_line_t
479
verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
480
{
481
	pid_t prev_pid;
482
	pid_t *last_pid;
483
	int ret;
484

485
	if (!data)
486 487
		return TRACE_TYPE_HANDLED;

488
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
489 490

	if (*last_pid == pid)
491
		return TRACE_TYPE_HANDLED;
492

493 494
	prev_pid = *last_pid;
	*last_pid = pid;
495

496 497
	if (prev_pid == -1)
		return TRACE_TYPE_HANDLED;
498 499 500 501 502 503 504 505
/*
 * Context-switch trace line:

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

 */
506
	ret = trace_seq_puts(s,
507
		" ------------------------------------------\n");
508
	if (!ret)
509
		return TRACE_TYPE_PARTIAL_LINE;
510 511 512

	ret = print_graph_cpu(s, cpu);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
513
		return TRACE_TYPE_PARTIAL_LINE;
514 515 516

	ret = print_graph_proc(s, prev_pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
517
		return TRACE_TYPE_PARTIAL_LINE;
518

519
	ret = trace_seq_puts(s, " => ");
520
	if (!ret)
521
		return TRACE_TYPE_PARTIAL_LINE;
522 523 524

	ret = print_graph_proc(s, pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
525
		return TRACE_TYPE_PARTIAL_LINE;
526

527
	ret = trace_seq_puts(s,
528 529
		"\n ------------------------------------------\n\n");
	if (!ret)
530
		return TRACE_TYPE_PARTIAL_LINE;
531

532
	return TRACE_TYPE_HANDLED;
533 534
}

535 536
static struct ftrace_graph_ret_entry *
get_return_for_leaf(struct trace_iterator *iter,
537 538
		struct ftrace_graph_ent_entry *curr)
{
539 540
	struct fgraph_data *data = iter->private;
	struct ring_buffer_iter *ring_iter = NULL;
541 542 543
	struct ring_buffer_event *event;
	struct ftrace_graph_ret_entry *next;

544 545 546 547 548 549 550 551
	/*
	 * 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 {
552

553
		ring_iter = trace_buffer_iter(iter, iter->cpu);
554 555 556 557 558 559 560 561 562

		/* 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.
			 */
563
			ring_buffer_consume(iter->trace_buffer->buffer, iter->cpu,
564
					    NULL, NULL);
565
			event = ring_buffer_peek(iter->trace_buffer->buffer, iter->cpu,
566
						 NULL, NULL);
567
		}
568

569 570 571 572
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
573

574 575 576 577 578 579
		if (data) {
			/*
			 * Save current and next entries for later reference
			 * if the output fails.
			 */
			data->ent = *curr;
580 581 582 583 584 585 586 587 588
			/*
			 * 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;
589 590
		}
	}
591 592

	if (next->ent.type != TRACE_GRAPH_RET)
593
		return NULL;
594 595 596

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

599 600 601 602 603
	/* this is a leaf, now advance the iterator */
	if (ring_iter)
		ring_buffer_read(ring_iter, NULL);

	return next;
604 605
}

606 607 608 609 610 611 612 613 614 615 616
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);
}

617
static enum print_line_t
618
print_graph_irq(struct trace_iterator *iter, unsigned long addr,
619
		enum trace_type type, int cpu, pid_t pid, u32 flags)
620 621
{
	int ret;
622
	struct trace_seq *s = &iter->seq;
623 624 625 626 627

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

628 629 630 631 632 633 634
	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;
		}
635

636 637 638 639 640 641
		/* Cpu */
		if (flags & TRACE_GRAPH_PRINT_CPU) {
			ret = print_graph_cpu(s, cpu);
			if (ret == TRACE_TYPE_PARTIAL_LINE)
				return TRACE_TYPE_PARTIAL_LINE;
		}
642

643 644 645 646 647
		/* Proc */
		if (flags & TRACE_GRAPH_PRINT_PROC) {
			ret = print_graph_proc(s, pid);
			if (ret == TRACE_TYPE_PARTIAL_LINE)
				return TRACE_TYPE_PARTIAL_LINE;
648
			ret = trace_seq_puts(s, " | ");
649 650 651
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}
652
	}
653

654
	/* No overhead */
655 656 657
	ret = print_graph_duration(DURATION_FILL_START, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
658

659
	if (type == TRACE_GRAPH_ENT)
660
		ret = trace_seq_puts(s, "==========>");
661
	else
662
		ret = trace_seq_puts(s, "<==========");
663 664 665 666

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

667 668 669 670
	ret = print_graph_duration(DURATION_FILL_END, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;

671
	ret = trace_seq_putc(s, '\n');
672 673 674 675 676

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

678 679
enum print_line_t
trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
680 681
{
	unsigned long nsecs_rem = do_div(duration, 1000);
682 683 684 685 686 687 688 689 690
	/* 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 */
691
	ret = trace_seq_printf(s, "%s", msecs_str);
692 693 694 695 696 697 698
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	len = strlen(msecs_str);

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

		snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
702 703 704 705 706 707
		ret = trace_seq_printf(s, ".%s", nsecs_str);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
		len += strlen(nsecs_str);
	}

708
	ret = trace_seq_puts(s, " us ");
709 710 711 712 713
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Print remaining spaces to fit the row's width */
	for (i = len; i < 7; i++) {
714
		ret = trace_seq_putc(s, ' ');
715 716 717
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
718 719 720 721
	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
722 723
print_graph_duration(unsigned long long duration, struct trace_seq *s,
		     u32 flags)
724
{
725 726
	int ret = -1;

727 728 729
	if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
	    !(trace_flags & TRACE_ITER_CONTEXT_INFO))
			return TRACE_TYPE_HANDLED;
730 731 732 733

	/* No real adata, just filling the column with spaces */
	switch (duration) {
	case DURATION_FILL_FULL:
734
		ret = trace_seq_puts(s, "              |  ");
735 736
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
	case DURATION_FILL_START:
737
		ret = trace_seq_puts(s, "  ");
738 739
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
	case DURATION_FILL_END:
740
		ret = trace_seq_puts(s, " |");
741 742 743 744 745 746 747
		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)
748
			ret = trace_seq_puts(s, "! ");
749 750
		/* Duration exceeded 10 msecs */
		else if (duration > 10000ULL)
751
			ret = trace_seq_puts(s, "+ ");
752 753 754 755 756 757 758 759
	}

	/*
	 * 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)
760
		ret = trace_seq_puts(s, "  ");
761 762 763 764

	/* Catching here any failure happenned above */
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
765 766 767 768

	ret = trace_print_graph_duration(duration, s);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
769

770
	ret = trace_seq_puts(s, "|  ");
771 772 773
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

774
	return TRACE_TYPE_HANDLED;
775 776 777
}

/* Case of a leaf function on its call entry */
778
static enum print_line_t
779
print_graph_entry_leaf(struct trace_iterator *iter,
780
		struct ftrace_graph_ent_entry *entry,
781 782
		struct ftrace_graph_ret_entry *ret_entry,
		struct trace_seq *s, u32 flags)
783
{
784
	struct fgraph_data *data = iter->private;
785 786 787
	struct ftrace_graph_ret *graph_ret;
	struct ftrace_graph_ent *call;
	unsigned long long duration;
788
	int ret;
789
	int i;
790

791 792 793 794
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

795
	if (data) {
796
		struct fgraph_cpu_data *cpu_data;
797
		int cpu = iter->cpu;
798 799

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
800 801 802 803 804 805

		/*
		 * Comments display at + 1 to depth. Since
		 * this is a leaf function, keep the comments
		 * equal to this depth.
		 */
806 807 808 809 810
		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;
811 812
	}

813 814 815
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
816
		return TRACE_TYPE_PARTIAL_LINE;
817

818 819
	/* Function */
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
820
		ret = trace_seq_putc(s, ' ');
821 822 823 824
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

825
	ret = trace_seq_printf(s, "%ps();\n", (void *)call->func);
826 827 828 829 830 831 832
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
833 834
print_graph_entry_nested(struct trace_iterator *iter,
			 struct ftrace_graph_ent_entry *entry,
835
			 struct trace_seq *s, int cpu, u32 flags)
836 837
{
	struct ftrace_graph_ent *call = &entry->graph_ent;
838 839 840 841 842
	struct fgraph_data *data = iter->private;
	int ret;
	int i;

	if (data) {
843
		struct fgraph_cpu_data *cpu_data;
844 845
		int cpu = iter->cpu;

846 847 848 849 850 851
		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;
852
	}
853

854
	/* No time */
855 856 857
	ret = print_graph_duration(DURATION_FILL_FULL, s, flags);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
858

859
	/* Function */
860
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
861
		ret = trace_seq_putc(s, ' ');
862 863
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
864 865
	}

866
	ret = trace_seq_printf(s, "%ps() {\n", (void *)call->func);
867 868 869
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

870 871 872 873 874
	/*
	 * we already consumed the current entry to check the next one
	 * and see if this is a leaf.
	 */
	return TRACE_TYPE_NO_CONSUME;
875 876
}

877
static enum print_line_t
878
print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
879
		     int type, unsigned long addr, u32 flags)
880
{
881
	struct fgraph_data *data = iter->private;
882
	struct trace_entry *ent = iter->ent;
883 884
	int cpu = iter->cpu;
	int ret;
885

886
	/* Pid */
887
	if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
888 889
		return TRACE_TYPE_PARTIAL_LINE;

890 891
	if (type) {
		/* Interrupt */
892
		ret = print_graph_irq(iter, addr, type, cpu, ent->pid, flags);
893 894 895
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
896

897 898 899
	if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
		return 0;

900
	/* Absolute time */
901
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
902 903 904 905 906
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

907
	/* Cpu */
908
	if (flags & TRACE_GRAPH_PRINT_CPU) {
909
		ret = print_graph_cpu(s, cpu);
910 911 912 913 914
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
915
	if (flags & TRACE_GRAPH_PRINT_PROC) {
916
		ret = print_graph_proc(s, ent->pid);
917 918 919
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

920
		ret = trace_seq_puts(s, " | ");
921 922 923
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
924

925 926 927 928 929 930 931
	/* 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;
	}

932 933 934
	return 0;
}

935 936 937 938 939
/*
 * Entry check for irq code
 *
 * returns 1 if
 *  - we are inside irq code
Lucas De Marchi's avatar
Lucas De Marchi committed
940
 *  - we just entered irq code
941 942 943 944 945 946 947 948 949 950
 *
 * 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;
951
	int *depth_irq;
952 953
	struct fgraph_data *data = iter->private;

954 955 956 957 958 959 960
	/*
	 * 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))
961 962
		return 0;

963 964
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

965 966 967 968 969 970 971 972 973 974 975 976 977 978 979 980 981 982 983 984 985 986 987 988 989 990 991 992 993 994 995 996
	/*
	 * 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;
997
	int *depth_irq;
998 999
	struct fgraph_data *data = iter->private;

1000 1001 1002 1003 1004 1005 1006
	/*
	 * 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))
1007 1008
		return 0;

1009 1010
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

1011 1012 1013 1014 1015 1016 1017 1018 1019 1020 1021 1022 1023 1024 1025 1026 1027 1028 1029 1030 1031 1032 1033 1034 1035 1036
	/*
	 * 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;
}

1037 1038
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
1039
			struct trace_iterator *iter, u32 flags)
1040
{
1041
	struct fgraph_data *data = iter->private;
1042 1043
	struct ftrace_graph_ent *call = &field->graph_ent;
	struct ftrace_graph_ret_entry *leaf_ret;
1044 1045
	static enum print_line_t ret;
	int cpu = iter->cpu;
1046

1047 1048 1049
	if (check_irq_entry(iter, flags, call->func, call->depth))
		return TRACE_TYPE_HANDLED;

1050
	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
1051 1052
		return TRACE_TYPE_PARTIAL_LINE;

1053 1054
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
1055
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
1056
	else
1057
		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
1058

1059 1060 1061 1062 1063 1064 1065 1066 1067 1068 1069 1070 1071
	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;
1072 1073
}

1074 1075
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
1076 1077
		   struct trace_entry *ent, struct trace_iterator *iter,
		   u32 flags)
1078
{
1079
	unsigned long long duration = trace->rettime - trace->calltime;
1080 1081 1082
	struct fgraph_data *data = iter->private;
	pid_t pid = ent->pid;
	int cpu = iter->cpu;
1083
	int func_match = 1;
1084 1085 1086
	int ret;
	int i;

1087 1088 1089
	if (check_irq_return(iter, flags, trace->depth))
		return TRACE_TYPE_HANDLED;

1090
	if (data) {
1091 1092 1093 1094
		struct fgraph_cpu_data *cpu_data;
		int cpu = iter->cpu;

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
1095 1096 1097 1098 1099 1100

		/*
		 * 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.
		 */
1101 1102 1103 1104 1105 1106 1107
		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;
		}
1108
	}
1109

1110
	if (print_graph_prologue(iter, s, 0, 0, flags))
1111 1112
		return TRACE_TYPE_PARTIAL_LINE;

1113 1114 1115
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
1116
		return TRACE_TYPE_PARTIAL_LINE;
1117

1118
	/* Closing brace */
1119
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
1120
		ret = trace_seq_putc(s, ' ');
1121 1122
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1123 1124
	}

1125 1126 1127 1128 1129 1130 1131
	/*
	 * 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) {
1132
		ret = trace_seq_puts(s, "}\n");
1133 1134 1135
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	} else {
1136
		ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
1137 1138 1139
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
1140

1141
	/* Overrun */
1142
	if (flags & TRACE_GRAPH_PRINT_OVERRUN) {
1143 1144
		ret = trace_seq_printf(s, " (Overruns: %lu)\n",
					trace->overrun);
1145 1146
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1147
	}
1148

1149 1150
	ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET,
			      cpu, pid, flags);
1151 1152 1153
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;

1154 1155 1156
	return TRACE_TYPE_HANDLED;
}

1157
static enum print_line_t
1158 1159
print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
		    struct trace_iterator *iter, u32 flags)
1160
{
1161
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
1162
	struct fgraph_data *data = iter->private;
1163
	struct trace_event *event;
1164
	int depth = 0;
1165
	int ret;
1166 1167 1168
	int i;

	if (data)
1169
		depth = per_cpu_ptr(data->cpu_data, iter->cpu)->depth;
1170

1171
	if (print_graph_prologue(iter, s, 0, 0, flags))
1172 1173
		return TRACE_TYPE_PARTIAL_LINE;

1174
	/* No time */