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

43
static struct tracer_opt trace_opts[] = {
44
	/* Display overruns? (for self-debug purpose) */
45 46 47 48 49
	{ 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) },
50 51
	/* Display proc name/pid */
	{ TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
52 53 54 55
	/* 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) },
56 57
	/* Display interrupts */
	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
58 59 60 61
	{ } /* Empty entry */
};

static struct tracer_flags tracer_flags = {
62
	/* Don't display overruns and proc by default */
63
	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
64
	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS,
65 66 67
	.opts = trace_opts
};

68
static struct trace_array *graph_array;
69

70 71 72 73 74 75
/*
 * 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 {
76 77 78
	FLAGS_FILL_FULL  = 1 << TRACE_GRAPH_PRINT_FILL_SHIFT,
	FLAGS_FILL_START = 2 << TRACE_GRAPH_PRINT_FILL_SHIFT,
	FLAGS_FILL_END   = 3 << TRACE_GRAPH_PRINT_FILL_SHIFT,
79 80 81 82 83
};

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

85 86
/* Add a function return address to the trace stack on thread info.*/
int
87 88
ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
			 unsigned long frame_pointer)
89
{
90
	unsigned long long calltime;
91 92 93 94 95
	int index;

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

96 97 98 99 100 101
	/*
	 * We must make sure the ret_stack is tested before we read
	 * anything else.
	 */
	smp_rmb();

102 103 104 105 106 107
	/* The return trace stack is full */
	if (current->curr_ret_stack == FTRACE_RETFUNC_DEPTH - 1) {
		atomic_inc(&current->trace_overrun);
		return -EBUSY;
	}

108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126
	/*
	 * The curr_ret_stack is an index to ftrace return stack of
	 * current task.  Its value should be in [0, FTRACE_RETFUNC_
	 * DEPTH) when the function graph tracer is used.  To support
	 * filtering out specific functions, it makes the index
	 * negative by subtracting huge value (FTRACE_NOTRACE_DEPTH)
	 * so when it sees a negative index the ftrace will ignore
	 * the record.  And the index gets recovered when returning
	 * from the filtered function by adding the FTRACE_NOTRACE_
	 * DEPTH and then it'll continue to record functions normally.
	 *
	 * The curr_ret_stack is initialized to -1 and get increased
	 * in this function.  So it can be less than -1 only if it was
	 * filtered out via ftrace_graph_notrace_addr() which can be
	 * set from set_graph_notrace file in debugfs by user.
	 */
	if (current->curr_ret_stack < -1)
		return -EBUSY;

127 128
	calltime = trace_clock_local();

129
	index = ++current->curr_ret_stack;
130 131
	if (ftrace_graph_notrace_addr(func))
		current->curr_ret_stack -= FTRACE_NOTRACE_DEPTH;
132 133 134
	barrier();
	current->ret_stack[index].ret = ret;
	current->ret_stack[index].func = func;
135
	current->ret_stack[index].calltime = calltime;
136
	current->ret_stack[index].subtime = 0;
137
	current->ret_stack[index].fp = frame_pointer;
138
	*depth = current->curr_ret_stack;
139 140 141 142 143

	return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
144
static void
145 146
ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret,
			unsigned long frame_pointer)
147 148 149 150 151
{
	int index;

	index = current->curr_ret_stack;

152 153 154 155 156 157 158 159 160 161 162
	/*
	 * A negative index here means that it's just returned from a
	 * notrace'd function.  Recover index to get an original
	 * return address.  See ftrace_push_return_trace().
	 *
	 * TODO: Need to check whether the stack gets corrupted.
	 */
	if (index < 0)
		index += FTRACE_NOTRACE_DEPTH;

	if (unlikely(index < 0 || index >= FTRACE_RETFUNC_DEPTH)) {
163 164 165 166 167 168 169
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic, otherwise we have no where to go */
		*ret = (unsigned long)panic;
		return;
	}

170
#if defined(CONFIG_HAVE_FUNCTION_GRAPH_FP_TEST) && !defined(CC_USING_FENTRY)
171 172 173 174 175 176 177 178 179 180
	/*
	 * 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.
181 182 183
	 *
	 * Note, -mfentry does not use frame pointers, and this test
	 *  is not needed if CC_USING_FENTRY is set.
184 185 186 187
	 */
	if (unlikely(current->ret_stack[index].fp != frame_pointer)) {
		ftrace_graph_stop();
		WARN(1, "Bad frame pointer: expected %lx, received %lx\n"
188
		     "  from func %ps return to %lx\n",
189 190 191 192 193 194 195 196 197
		     current->ret_stack[index].fp,
		     frame_pointer,
		     (void *)current->ret_stack[index].func,
		     current->ret_stack[index].ret);
		*ret = (unsigned long)panic;
		return;
	}
#endif

198 199 200 201 202 203 204 205 206 207 208
	*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.
 */
209
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
210 211 212 213
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

214
	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
215
	trace.rettime = trace_clock_local();
216 217
	barrier();
	current->curr_ret_stack--;
218 219 220 221 222 223 224 225 226
	/*
	 * The curr_ret_stack can be less than -1 only if it was
	 * filtered out and it's about to return from the function.
	 * Recover the index and continue to trace normal functions.
	 */
	if (current->curr_ret_stack < -1) {
		current->curr_ret_stack += FTRACE_NOTRACE_DEPTH;
		return ret;
	}
227

228 229 230 231 232 233 234
	/*
	 * 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);

235 236 237 238 239 240 241 242 243 244
	if (unlikely(!ret)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic. What else to do? */
		ret = (unsigned long)panic;
	}

	return ret;
}

245
int __trace_graph_entry(struct trace_array *tr,
246 247 248 249 250 251
				struct ftrace_graph_ent *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_entry;
	struct ring_buffer_event *event;
252
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
253 254
	struct ftrace_graph_ent_entry *entry;

255
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
256 257
		return 0;

258
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
259 260 261 262 263
					  sizeof(*entry), flags, pc);
	if (!event)
		return 0;
	entry	= ring_buffer_event_data(event);
	entry->graph_ent			= *trace;
264
	if (!call_filter_check_discard(call, entry, buffer, event))
265
		__buffer_unlock_commit(buffer, event);
266 267 268 269

	return 1;
}

270 271
static inline int ftrace_graph_ignore_irqs(void)
{
272
	if (!ftrace_graph_skip_irqs || trace_recursion_test(TRACE_IRQ_BIT))
273 274 275 276 277
		return 0;

	return in_irq();
}

278 279 280 281 282 283 284 285 286 287 288 289 290
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;

291
	/* trace it when it is-nested-in or is a function enabled. */
292
	if ((!(trace->depth || ftrace_graph_addr(trace->func)) ||
293
	     ftrace_graph_ignore_irqs()) || (trace->depth < 0) ||
294
	    (max_depth && trace->depth >= max_depth))
295 296
		return 0;

297 298 299 300 301 302 303 304 305 306
	/*
	 * Do not trace a function if it's filtered by set_graph_notrace.
	 * Make the index of ret stack negative to indicate that it should
	 * ignore further functions.  But it needs its own ret stack entry
	 * to recover the original index in order to continue tracing after
	 * returning from the function.
	 */
	if (ftrace_graph_notrace_addr(trace->func))
		return 1;

307 308
	local_irq_save(flags);
	cpu = raw_smp_processor_id();
309
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
310 311 312 313 314 315 316 317 318 319 320 321 322 323
	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;
}

324 325 326 327 328 329 330 331
int trace_graph_thresh_entry(struct ftrace_graph_ent *trace)
{
	if (tracing_thresh)
		return 1;
	else
		return trace_graph_entry(trace);
}

332 333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 348 349 350 351 352 353 354 355 356 357 358 359
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);
}

360
void __trace_graph_return(struct trace_array *tr,
361 362 363 364 365 366
				struct ftrace_graph_ret *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_exit;
	struct ring_buffer_event *event;
367
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
368 369
	struct ftrace_graph_ret_entry *entry;

370
	if (unlikely(__this_cpu_read(ftrace_cpu_disabled)))
371 372
		return;

373
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
374 375 376 377 378
					  sizeof(*entry), flags, pc);
	if (!event)
		return;
	entry	= ring_buffer_event_data(event);
	entry->ret				= *trace;
379
	if (!call_filter_check_discard(call, entry, buffer, event))
380
		__buffer_unlock_commit(buffer, event);
381 382 383 384 385 386 387 388 389 390 391 392 393
}

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();
394
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
395 396 397 398 399 400 401 402 403
	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);
}

404 405 406 407 408 409 410 411 412
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

413 414 415 416 417 418 419 420 421
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);
}

422 423
static int graph_trace_init(struct trace_array *tr)
{
424 425
	int ret;

426
	set_graph_array(tr);
427 428 429 430 431 432
	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);
433 434 435 436 437
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
438 439 440 441
}

static void graph_trace_reset(struct trace_array *tr)
{
442 443
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
444 445
}

446
static int max_bytes_for_cpu;
447 448 449 450 451 452

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

453 454 455 456 457
	/*
	 * Start with a space character - to make it stand out
	 * to the right a bit when trace output is pasted into
	 * email:
	 */
458
	ret = trace_seq_printf(s, " %*d) ", max_bytes_for_cpu, cpu);
459
	if (!ret)
460 461
		return TRACE_TYPE_PARTIAL_LINE;

462 463 464
	return TRACE_TYPE_HANDLED;
}

465 466 467 468 469
#define TRACE_GRAPH_PROCINFO_LENGTH	14

static enum print_line_t
print_graph_proc(struct trace_seq *s, pid_t pid)
{
470
	char comm[TASK_COMM_LEN];
471 472
	/* sign + log10(MAX_INT) + '\0' */
	char pid_str[11];
473 474 475 476
	int spaces = 0;
	int ret;
	int len;
	int i;
477

478
	trace_find_cmdline(pid, comm);
479 480 481 482 483 484 485 486 487 488 489
	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++) {
490
		ret = trace_seq_putc(s, ' ');
491 492 493 494 495 496 497 498 499 500
		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++) {
501
		ret = trace_seq_putc(s, ' ');
502 503 504 505 506 507
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
	return TRACE_TYPE_HANDLED;
}

508

509 510 511
static enum print_line_t
print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
{
512
	if (!trace_seq_putc(s, ' '))
513 514
		return 0;

515
	return trace_print_lat_fmt(s, entry);
516 517
}

518
/* If the pid changed since the last trace, output this event */
519
static enum print_line_t
520
verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
521
{
522
	pid_t prev_pid;
523
	pid_t *last_pid;
524
	int ret;
525

526
	if (!data)
527 528
		return TRACE_TYPE_HANDLED;

529
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
530 531

	if (*last_pid == pid)
532
		return TRACE_TYPE_HANDLED;
533

534 535
	prev_pid = *last_pid;
	*last_pid = pid;
536

537 538
	if (prev_pid == -1)
		return TRACE_TYPE_HANDLED;
539 540 541 542 543 544 545 546
/*
 * Context-switch trace line:

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

 */
547
	ret = trace_seq_puts(s,
548
		" ------------------------------------------\n");
549
	if (!ret)
550
		return TRACE_TYPE_PARTIAL_LINE;
551 552 553

	ret = print_graph_cpu(s, cpu);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
554
		return TRACE_TYPE_PARTIAL_LINE;
555 556 557

	ret = print_graph_proc(s, prev_pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
558
		return TRACE_TYPE_PARTIAL_LINE;
559

560
	ret = trace_seq_puts(s, " => ");
561
	if (!ret)
562
		return TRACE_TYPE_PARTIAL_LINE;
563 564 565

	ret = print_graph_proc(s, pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
566
		return TRACE_TYPE_PARTIAL_LINE;
567

568
	ret = trace_seq_puts(s,
569 570
		"\n ------------------------------------------\n\n");
	if (!ret)
571
		return TRACE_TYPE_PARTIAL_LINE;
572

573
	return TRACE_TYPE_HANDLED;
574 575
}

576 577
static struct ftrace_graph_ret_entry *
get_return_for_leaf(struct trace_iterator *iter,
578 579
		struct ftrace_graph_ent_entry *curr)
{
580 581
	struct fgraph_data *data = iter->private;
	struct ring_buffer_iter *ring_iter = NULL;
582 583 584
	struct ring_buffer_event *event;
	struct ftrace_graph_ret_entry *next;

585 586 587 588 589 590 591 592
	/*
	 * 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 {
593

594
		ring_iter = trace_buffer_iter(iter, iter->cpu);
595 596 597 598 599 600 601 602 603

		/* 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.
			 */
604
			ring_buffer_consume(iter->trace_buffer->buffer, iter->cpu,
605
					    NULL, NULL);
606
			event = ring_buffer_peek(iter->trace_buffer->buffer, iter->cpu,
607
						 NULL, NULL);
608
		}
609

610 611 612 613
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
614

615 616 617 618 619 620
		if (data) {
			/*
			 * Save current and next entries for later reference
			 * if the output fails.
			 */
			data->ent = *curr;
621 622 623 624 625 626 627 628 629
			/*
			 * 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;
630 631
		}
	}
632 633

	if (next->ent.type != TRACE_GRAPH_RET)
634
		return NULL;
635 636 637

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

640 641 642 643 644
	/* this is a leaf, now advance the iterator */
	if (ring_iter)
		ring_buffer_read(ring_iter, NULL);

	return next;
645 646
}

647 648 649 650 651 652 653 654 655 656 657
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);
}

658
static enum print_line_t
659
print_graph_irq(struct trace_iterator *iter, unsigned long addr,
660
		enum trace_type type, int cpu, pid_t pid, u32 flags)
661 662
{
	int ret;
663
	struct trace_seq *s = &iter->seq;
664 665 666 667 668

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

669 670 671 672 673 674 675
	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;
		}
676

677 678 679 680 681 682
		/* Cpu */
		if (flags & TRACE_GRAPH_PRINT_CPU) {
			ret = print_graph_cpu(s, cpu);
			if (ret == TRACE_TYPE_PARTIAL_LINE)
				return TRACE_TYPE_PARTIAL_LINE;
		}
683

684 685 686 687 688
		/* Proc */
		if (flags & TRACE_GRAPH_PRINT_PROC) {
			ret = print_graph_proc(s, pid);
			if (ret == TRACE_TYPE_PARTIAL_LINE)
				return TRACE_TYPE_PARTIAL_LINE;
689
			ret = trace_seq_puts(s, " | ");
690 691 692
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}
693
	}
694

695
	/* No overhead */
696
	ret = print_graph_duration(0, s, flags | FLAGS_FILL_START);
697 698
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
699

700
	if (type == TRACE_GRAPH_ENT)
701
		ret = trace_seq_puts(s, "==========>");
702
	else
703
		ret = trace_seq_puts(s, "<==========");
704 705 706 707

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

708
	ret = print_graph_duration(0, s, flags | FLAGS_FILL_END);
709 710 711
	if (ret != TRACE_TYPE_HANDLED)
		return ret;

712
	ret = trace_seq_putc(s, '\n');
713 714 715 716 717

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

719 720
enum print_line_t
trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
721 722
{
	unsigned long nsecs_rem = do_div(duration, 1000);
723 724 725 726 727 728 729 730 731
	/* 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 */
732
	ret = trace_seq_printf(s, "%s", msecs_str);
733 734 735 736 737 738 739
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	len = strlen(msecs_str);

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

		snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
743 744 745 746 747 748
		ret = trace_seq_printf(s, ".%s", nsecs_str);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
		len += strlen(nsecs_str);
	}

749
	ret = trace_seq_puts(s, " us ");
750 751 752 753 754
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Print remaining spaces to fit the row's width */
	for (i = len; i < 7; i++) {
755
		ret = trace_seq_putc(s, ' ');
756 757 758
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
759 760 761 762
	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
763 764
print_graph_duration(unsigned long long duration, struct trace_seq *s,
		     u32 flags)
765
{
766 767
	int ret = -1;

768 769 770
	if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
	    !(trace_flags & TRACE_ITER_CONTEXT_INFO))
			return TRACE_TYPE_HANDLED;
771 772

	/* No real adata, just filling the column with spaces */
773 774
	switch (flags & TRACE_GRAPH_PRINT_FILL_MASK) {
	case FLAGS_FILL_FULL:
775
		ret = trace_seq_puts(s, "              |  ");
776
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
777
	case FLAGS_FILL_START:
778
		ret = trace_seq_puts(s, "  ");
779
		return ret ? TRACE_TYPE_HANDLED : TRACE_TYPE_PARTIAL_LINE;
780
	case FLAGS_FILL_END:
781
		ret = trace_seq_puts(s, " |");
782 783 784 785 786 787 788
		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)
789
			ret = trace_seq_puts(s, "! ");
790 791
		/* Duration exceeded 10 msecs */
		else if (duration > 10000ULL)
792
			ret = trace_seq_puts(s, "+ ");
793 794 795 796 797 798 799 800
	}

	/*
	 * 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)
801
		ret = trace_seq_puts(s, "  ");
802 803 804 805

	/* Catching here any failure happenned above */
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
806 807 808 809

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

811
	ret = trace_seq_puts(s, "|  ");
812 813 814
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

815
	return TRACE_TYPE_HANDLED;
816 817 818
}

/* Case of a leaf function on its call entry */
819
static enum print_line_t
820
print_graph_entry_leaf(struct trace_iterator *iter,
821
		struct ftrace_graph_ent_entry *entry,
822 823
		struct ftrace_graph_ret_entry *ret_entry,
		struct trace_seq *s, u32 flags)
824
{
825
	struct fgraph_data *data = iter->private;
826 827 828
	struct ftrace_graph_ret *graph_ret;
	struct ftrace_graph_ent *call;
	unsigned long long duration;
829
	int ret;
830
	int i;
831

832 833 834 835
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

836
	if (data) {
837
		struct fgraph_cpu_data *cpu_data;
838
		int cpu = iter->cpu;
839 840

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
841 842 843 844 845 846

		/*
		 * Comments display at + 1 to depth. Since
		 * this is a leaf function, keep the comments
		 * equal to this depth.
		 */
847 848 849 850 851
		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;
852 853
	}

854 855 856
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
857
		return TRACE_TYPE_PARTIAL_LINE;
858

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

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

	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
874 875
print_graph_entry_nested(struct trace_iterator *iter,
			 struct ftrace_graph_ent_entry *entry,
876
			 struct trace_seq *s, int cpu, u32 flags)
877 878
{
	struct ftrace_graph_ent *call = &entry->graph_ent;
879 880 881 882 883
	struct fgraph_data *data = iter->private;
	int ret;
	int i;

	if (data) {
884
		struct fgraph_cpu_data *cpu_data;
885 886
		int cpu = iter->cpu;

887 888 889 890 891 892
		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;
893
	}
894

895
	/* No time */
896
	ret = print_graph_duration(0, s, flags | FLAGS_FILL_FULL);
897 898
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
899

900
	/* Function */
901
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
902
		ret = trace_seq_putc(s, ' ');
903 904
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
905 906
	}

907
	ret = trace_seq_printf(s, "%ps() {\n", (void *)call->func);
908 909 910
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

911 912 913 914 915
	/*
	 * we already consumed the current entry to check the next one
	 * and see if this is a leaf.
	 */
	return TRACE_TYPE_NO_CONSUME;
916 917
}

918
static enum print_line_t
919
print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
920
		     int type, unsigned long addr, u32 flags)
921
{
922
	struct fgraph_data *data = iter->private;
923
	struct trace_entry *ent = iter->ent;
924 925
	int cpu = iter->cpu;
	int ret;
926

927
	/* Pid */
928
	if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
929 930
		return TRACE_TYPE_PARTIAL_LINE;

931 932
	if (type) {
		/* Interrupt */
933
		ret = print_graph_irq(iter, addr, type, cpu, ent->pid, flags);
934 935 936
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
937

938 939 940
	if (!(trace_flags & TRACE_ITER_CONTEXT_INFO))
		return 0;

941
	/* Absolute time */
942
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME) {
943 944 945 946 947
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

948
	/* Cpu */
949
	if (flags & TRACE_GRAPH_PRINT_CPU) {
950
		ret = print_graph_cpu(s, cpu);
951 952 953 954 955
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
956
	if (flags & TRACE_GRAPH_PRINT_PROC) {
957
		ret = print_graph_proc(s, ent->pid);
958 959 960
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

961
		ret = trace_seq_puts(s, " | ");
962 963 964
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
965

966 967 968 969 970 971 972
	/* 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;
	}

973 974 975
	return 0;
}

976 977 978 979 980
/*
 * Entry check for irq code
 *
 * returns 1 if
 *  - we are inside irq code
Lucas De Marchi's avatar
Lucas De Marchi committed
981
 *  - we just entered irq code
982 983 984 985 986 987 988 989 990 991
 *
 * 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;
992
	int *depth_irq;
993 994
	struct fgraph_data *data = iter->private;

995 996 997 998 999 1000 1001
	/*
	 * 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))
1002 1003
		return 0;

1004 1005
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

1006 1007 1008 1009 1010 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 1037
	/*
	 * 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;
1038
	int *depth_irq;
1039 1040
	struct fgraph_data *data = iter->private;

1041 1042 1043 1044 1045 1046 1047
	/*
	 * 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))
1048 1049
		return 0;

1050 1051
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

1052 1053 1054 1055 1056 1057 1058 1059 1060 1061 1062 1063 1064 1065 1066 1067 1068 1069 1070 1071 1072 1073 1074 1075 1076 1077
	/*
	 * 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;
}

1078 1079
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
1080
			struct trace_iterator *iter, u32 flags)
1081
{
1082
	struct fgraph_data *data = iter->private;
1083 1084
	struct ftrace_graph_ent *call = &field->graph_ent;
	struct ftrace_graph_ret_entry *leaf_ret;
1085 1086
	static enum print_line_t ret;
	int cpu = iter->cpu;
1087

1088 1089 1090
	if (check_irq_entry(iter, flags, call->func, call->depth))
		return TRACE_TYPE_HANDLED;

1091
	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags))
1092 1093
		return TRACE_TYPE_PARTIAL_LINE;

1094 1095
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
1096
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
1097
	else
1098
		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
1099

1100 1101 1102 1103 1104 1105 1106 1107 1108 1109 1110 1111 1112
	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;
1113 1114
}

1115 1116
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
1117 1118
		   struct trace_entry *ent, struct trace_iterator *iter,
		   u32 flags)
1119
{
1120
	unsigned long long duration = trace->rettime - trace->calltime;
1121 1122 1123
	struct fgraph_data *data = iter->private;
	pid_t pid = ent->pid;
	int cpu = iter->cpu;
1124
	int func_match = 1;
1125 1126 1127
	int ret;
	int i;

1128 1129 1130
	if (check_irq_return(iter, flags, trace->depth))
		return TRACE_TYPE_HANDLED;

1131
	if (data) {
1132 1133 1134 1135
		struct fgraph_cpu_data *cpu_data;
		int cpu = iter->cpu;

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
1136 1137 1138 1139 1140 1141

		/*
		 * 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.
		 */
1142 1143 1144 1145 1146 1147 1148
		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;
		}
1149
	}
1150

1151
	if (print_graph_prologue(iter, s, 0, 0, flags))
1152 1153
		return TRACE_TYPE_PARTIAL_LINE;

1154 1155 1156
	/* Overhead and duration */
	ret = print_graph_duration(duration, s, flags);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
1157
		return TRACE_TYPE_PARTIAL_LINE;
1158

1159
	/* Closing brace */
1160
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
1161
		ret = trace_seq_putc(s, ' ');
1162 1163
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1164 1165
	}

1166 1167 1168 1169 1170 1171 1172
	/*
	 * 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) {
1173
		ret = trace_seq_puts(s, "}\n");
1174 1175 1176
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	} else {
1177
		ret = trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
1178 1179 1180
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
1181

1182
	/* Overrun */
1183
	if (flags & TRACE_GRAPH_PRINT_OVERRUN) {
1184 1185
		ret = trace_seq_printf(s, " (Overruns: %lu)\n",
					trace->overrun);
1186 1187
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
1188
	}
1189

1190 1191
	ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET,
			      cpu, pid, flags);
1192 1193 1194
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;