trace_functions_graph.c 36.4 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
 * Mostly borrowed from function tracer which
 * is Copyright (c) Steven Rostedt <srostedt@redhat.com>
 *
 */
#include <linux/uaccess.h>
#include <linux/ftrace.h>
11
#include <linux/interrupt.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 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44
static bool kill_ftrace_graph;

/**
 * ftrace_graph_is_dead - returns true if ftrace_graph_stop() was called
 *
 * ftrace_graph_stop() is called when a severe error is detected in
 * the function graph tracing. This function is called by the critical
 * paths of function graph to keep those paths from doing any more harm.
 */
bool ftrace_graph_is_dead(void)
{
	return kill_ftrace_graph;
}

/**
 * ftrace_graph_stop - set to permanently disable function graph tracincg
 *
 * In case of an error int function graph tracing, this is called
 * to try to keep function graph tracing from causing any more harm.
 * Usually this is pretty severe and this is called to try to at least
 * get a warning out to the user.
 */
void ftrace_graph_stop(void)
{
	kill_ftrace_graph = true;
}

45 46 47
/* When set, irq functions will be ignored */
static int ftrace_graph_skip_irqs;

48
struct fgraph_cpu_data {
49 50
	pid_t		last_pid;
	int		depth;
51
	int		depth_irq;
52
	int		ignore;
53
	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
54 55 56
};

struct fgraph_data {
57
	struct fgraph_cpu_data __percpu *cpu_data;
58 59 60 61 62 63

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

66
#define TRACE_GRAPH_INDENT	2
67

68 69
static unsigned int max_depth;

70
static struct tracer_opt trace_opts[] = {
71
	/* Display overruns? (for self-debug purpose) */
72 73 74 75 76
	{ 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) },
77 78
	/* Display proc name/pid */
	{ TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
79 80 81 82
	/* 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) },
83 84
	/* Display interrupts */
	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
85 86
	/* Display function name after trailing } */
	{ TRACER_OPT(funcgraph-tail, TRACE_GRAPH_PRINT_TAIL) },
87 88 89 90
	/* Include sleep time (scheduled out) between entry and return */
	{ TRACER_OPT(sleep-time, TRACE_GRAPH_SLEEP_TIME) },
	/* Include time within nested functions */
	{ TRACER_OPT(graph-time, TRACE_GRAPH_GRAPH_TIME) },
91 92 93 94
	{ } /* Empty entry */
};

static struct tracer_flags tracer_flags = {
95
	/* Don't display overruns, proc, or tail by default */
96
	.val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
97 98
	       TRACE_GRAPH_PRINT_DURATION | TRACE_GRAPH_PRINT_IRQS |
	       TRACE_GRAPH_SLEEP_TIME | TRACE_GRAPH_GRAPH_TIME,
99 100 101
	.opts = trace_opts
};

102
static struct trace_array *graph_array;
103

104 105 106 107 108 109
/*
 * 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 {
110 111 112
	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,
113 114
};

115
static void
116 117
print_graph_duration(struct trace_array *tr, unsigned long long duration,
		     struct trace_seq *s, u32 flags);
118

119 120
/* Add a function return address to the trace stack on thread info.*/
int
121
ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
122
			 unsigned long frame_pointer, unsigned long *retp)
123
{
124
	unsigned long long calltime;
125 126
	int index;

127 128 129
	if (unlikely(ftrace_graph_is_dead()))
		return -EBUSY;

130 131 132
	if (!current->ret_stack)
		return -EBUSY;

133 134 135 136 137 138
	/*
	 * We must make sure the ret_stack is tested before we read
	 * anything else.
	 */
	smp_rmb();

139 140 141 142 143 144
	/* The return trace stack is full */
	if (current->curr_ret_stack == FTRACE_RETFUNC_DEPTH - 1) {
		atomic_inc(&current->trace_overrun);
		return -EBUSY;
	}

145 146 147 148 149 150 151 152 153 154 155 156 157 158
	/*
	 * 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
159
	 * set from set_graph_notrace file in tracefs by user.
160 161 162 163
	 */
	if (current->curr_ret_stack < -1)
		return -EBUSY;

164 165
	calltime = trace_clock_local();

166
	index = ++current->curr_ret_stack;
167 168
	if (ftrace_graph_notrace_addr(func))
		current->curr_ret_stack -= FTRACE_NOTRACE_DEPTH;
169 170 171
	barrier();
	current->ret_stack[index].ret = ret;
	current->ret_stack[index].func = func;
172
	current->ret_stack[index].calltime = calltime;
173
	current->ret_stack[index].subtime = 0;
174
#ifdef HAVE_FUNCTION_GRAPH_FP_TEST
175
	current->ret_stack[index].fp = frame_pointer;
176 177 178
#endif
#ifdef HAVE_FUNCTION_GRAPH_RET_ADDR_PTR
	current->ret_stack[index].retp = retp;
179
#endif
180
	*depth = current->curr_ret_stack;
181 182 183 184 185

	return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
186
static void
187 188
ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret,
			unsigned long frame_pointer)
189 190 191 192 193
{
	int index;

	index = current->curr_ret_stack;

194 195 196 197 198 199 200 201 202 203 204
	/*
	 * 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)) {
205 206 207 208 209 210 211
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic, otherwise we have no where to go */
		*ret = (unsigned long)panic;
		return;
	}

212
#ifdef HAVE_FUNCTION_GRAPH_FP_TEST
213 214 215 216 217 218 219 220 221 222
	/*
	 * 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.
223 224 225
	 *
	 * Note, -mfentry does not use frame pointers, and this test
	 *  is not needed if CC_USING_FENTRY is set.
226 227 228 229
	 */
	if (unlikely(current->ret_stack[index].fp != frame_pointer)) {
		ftrace_graph_stop();
		WARN(1, "Bad frame pointer: expected %lx, received %lx\n"
230
		     "  from func %ps return to %lx\n",
231 232 233 234 235 236 237 238 239
		     current->ret_stack[index].fp,
		     frame_pointer,
		     (void *)current->ret_stack[index].func,
		     current->ret_stack[index].ret);
		*ret = (unsigned long)panic;
		return;
	}
#endif

240 241 242 243 244 245 246 247 248 249 250
	*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.
 */
251
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
252 253 254 255
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

256
	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
257
	trace.rettime = trace_clock_local();
258 259
	barrier();
	current->curr_ret_stack--;
260 261 262 263 264 265 266 267 268
	/*
	 * 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;
	}
269

270 271 272 273 274 275 276
	/*
	 * 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);

277 278 279 280 281 282 283 284 285 286
	if (unlikely(!ret)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic. What else to do? */
		ret = (unsigned long)panic;
	}

	return ret;
}

287
int __trace_graph_entry(struct trace_array *tr,
288 289 290 291
				struct ftrace_graph_ent *trace,
				unsigned long flags,
				int pc)
{
292
	struct trace_event_call *call = &event_funcgraph_entry;
293
	struct ring_buffer_event *event;
294
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
295 296
	struct ftrace_graph_ent_entry *entry;

297
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
298 299 300 301 302
					  sizeof(*entry), flags, pc);
	if (!event)
		return 0;
	entry	= ring_buffer_event_data(event);
	entry->graph_ent			= *trace;
303
	if (!call_filter_check_discard(call, entry, buffer, event))
304
		__buffer_unlock_commit(buffer, event);
305 306 307 308

	return 1;
}

309 310
static inline int ftrace_graph_ignore_irqs(void)
{
311
	if (!ftrace_graph_skip_irqs || trace_recursion_test(TRACE_IRQ_BIT))
312 313 314 315 316
		return 0;

	return in_irq();
}

317 318 319 320 321 322 323 324 325 326
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;

327
	if (!ftrace_trace_task(tr))
328 329
		return 0;

330
	/* trace it when it is-nested-in or is a function enabled. */
331
	if ((!(trace->depth || ftrace_graph_addr(trace->func)) ||
332
	     ftrace_graph_ignore_irqs()) || (trace->depth < 0) ||
333
	    (max_depth && trace->depth >= max_depth))
334 335
		return 0;

336 337 338 339 340 341 342 343 344 345
	/*
	 * 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;

346 347 348 349 350 351 352
	/*
	 * Stop here if tracing_threshold is set. We only write function return
	 * events to the ring buffer.
	 */
	if (tracing_thresh)
		return 1;

353 354
	local_irq_save(flags);
	cpu = raw_smp_processor_id();
355
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
356 357 358 359 360 361 362 363 364 365 366 367 368 369
	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;
}

370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397
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);
}

398
void __trace_graph_return(struct trace_array *tr,
399 400 401 402
				struct ftrace_graph_ret *trace,
				unsigned long flags,
				int pc)
{
403
	struct trace_event_call *call = &event_funcgraph_exit;
404
	struct ring_buffer_event *event;
405
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
406 407
	struct ftrace_graph_ret_entry *entry;

408
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
409 410 411 412 413
					  sizeof(*entry), flags, pc);
	if (!event)
		return;
	entry	= ring_buffer_event_data(event);
	entry->ret				= *trace;
414
	if (!call_filter_check_discard(call, entry, buffer, event))
415
		__buffer_unlock_commit(buffer, event);
416 417 418 419 420 421 422 423 424 425 426 427 428
}

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();
429
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
430 431 432 433 434 435 436 437 438
	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);
}

439 440 441 442 443 444 445 446 447
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

448
static void trace_graph_thresh_return(struct ftrace_graph_ret *trace)
449 450 451 452 453 454 455 456
{
	if (tracing_thresh &&
	    (trace->rettime - trace->calltime < tracing_thresh))
		return;
	else
		trace_graph_return(trace);
}

457 458
static int graph_trace_init(struct trace_array *tr)
{
459 460
	int ret;

461
	set_graph_array(tr);
462 463
	if (tracing_thresh)
		ret = register_ftrace_graph(&trace_graph_thresh_return,
464
					    &trace_graph_entry);
465 466 467
	else
		ret = register_ftrace_graph(&trace_graph_return,
					    &trace_graph_entry);
468 469 470 471 472
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
473 474 475 476
}

static void graph_trace_reset(struct trace_array *tr)
{
477 478
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
479 480
}

481
static int graph_trace_update_thresh(struct trace_array *tr)
482 483 484 485 486
{
	graph_trace_reset(tr);
	return graph_trace_init(tr);
}

487
static int max_bytes_for_cpu;
488

489
static void print_graph_cpu(struct trace_seq *s, int cpu)
490
{
491 492 493 494 495
	/*
	 * Start with a space character - to make it stand out
	 * to the right a bit when trace output is pasted into
	 * email:
	 */
496
	trace_seq_printf(s, " %*d) ", max_bytes_for_cpu, cpu);
497 498
}

499 500
#define TRACE_GRAPH_PROCINFO_LENGTH	14

501
static void print_graph_proc(struct trace_seq *s, pid_t pid)
502
{
503
	char comm[TASK_COMM_LEN];
504 505
	/* sign + log10(MAX_INT) + '\0' */
	char pid_str[11];
506 507 508
	int spaces = 0;
	int len;
	int i;
509

510
	trace_find_cmdline(pid, comm);
511 512 513 514 515 516 517 518 519 520
	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 */
521 522
	for (i = 0; i < spaces / 2; i++)
		trace_seq_putc(s, ' ');
523

524
	trace_seq_printf(s, "%s-%s", comm, pid_str);
525 526

	/* Last spaces to align center */
527 528
	for (i = 0; i < spaces - (spaces / 2); i++)
		trace_seq_putc(s, ' ');
529 530
}

531

532
static void print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
533
{
534 535
	trace_seq_putc(s, ' ');
	trace_print_lat_fmt(s, entry);
536 537
}

538
/* If the pid changed since the last trace, output this event */
539
static void
540
verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
541
{
542
	pid_t prev_pid;
543
	pid_t *last_pid;
544

545
	if (!data)
546
		return;
547

548
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
549 550

	if (*last_pid == pid)
551
		return;
552

553 554
	prev_pid = *last_pid;
	*last_pid = pid;
555

556
	if (prev_pid == -1)
557
		return;
558 559 560 561 562 563 564 565
/*
 * Context-switch trace line:

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

 */
566 567 568 569 570 571
	trace_seq_puts(s, " ------------------------------------------\n");
	print_graph_cpu(s, cpu);
	print_graph_proc(s, prev_pid);
	trace_seq_puts(s, " => ");
	print_graph_proc(s, pid);
	trace_seq_puts(s, "\n ------------------------------------------\n\n");
572 573
}

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

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

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

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

608 609 610 611
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
612

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

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

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

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

	return next;
643 644
}

645
static void print_graph_abs_time(u64 t, struct trace_seq *s)
646 647 648 649 650 651
{
	unsigned long usecs_rem;

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

652 653
	trace_seq_printf(s, "%5lu.%06lu |  ",
			 (unsigned long)t, usecs_rem);
654 655
}

656
static void
657
print_graph_irq(struct trace_iterator *iter, unsigned long addr,
658
		enum trace_type type, int cpu, pid_t pid, u32 flags)
659
{
660
	struct trace_array *tr = iter->tr;
661
	struct trace_seq *s = &iter->seq;
662
	struct trace_entry *ent = iter->ent;
663 664 665

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

668
	if (tr->trace_flags & TRACE_ITER_CONTEXT_INFO) {
669
		/* Absolute time */
670 671
		if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
			print_graph_abs_time(iter->ts, s);
672

673
		/* Cpu */
674 675
		if (flags & TRACE_GRAPH_PRINT_CPU)
			print_graph_cpu(s, cpu);
676

677 678
		/* Proc */
		if (flags & TRACE_GRAPH_PRINT_PROC) {
679 680
			print_graph_proc(s, pid);
			trace_seq_puts(s, " | ");
681
		}
682 683

		/* Latency format */
684
		if (tr->trace_flags & TRACE_ITER_LATENCY_FMT)
685
			print_graph_lat_fmt(s, ent);
686
	}
687

688
	/* No overhead */
689
	print_graph_duration(tr, 0, s, flags | FLAGS_FILL_START);
690

691
	if (type == TRACE_GRAPH_ENT)
692
		trace_seq_puts(s, "==========>");
693
	else
694
		trace_seq_puts(s, "<==========");
695

696
	print_graph_duration(tr, 0, s, flags | FLAGS_FILL_END);
697
	trace_seq_putc(s, '\n');
698
}
699

700
void
701
trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
702 703
{
	unsigned long nsecs_rem = do_div(duration, 1000);
704
	/* log10(ULONG_MAX) + '\0' */
705
	char usecs_str[21];
706
	char nsecs_str[5];
707
	int len;
708 709
	int i;

710
	sprintf(usecs_str, "%lu", (unsigned long) duration);
711 712

	/* Print msecs */
713
	trace_seq_printf(s, "%s", usecs_str);
714

715
	len = strlen(usecs_str);
716 717 718

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

		snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
722
		trace_seq_printf(s, ".%s", nsecs_str);
723
		len += strlen(nsecs_str) + 1;
724 725
	}

726
	trace_seq_puts(s, " us ");
727 728

	/* Print remaining spaces to fit the row's width */
729
	for (i = len; i < 8; i++)
730
		trace_seq_putc(s, ' ');
731 732
}

733
static void
734 735
print_graph_duration(struct trace_array *tr, unsigned long long duration,
		     struct trace_seq *s, u32 flags)
736
{
737
	if (!(flags & TRACE_GRAPH_PRINT_DURATION) ||
738
	    !(tr->trace_flags & TRACE_ITER_CONTEXT_INFO))
739
		return;
740 741

	/* No real adata, just filling the column with spaces */
742 743
	switch (flags & TRACE_GRAPH_PRINT_FILL_MASK) {
	case FLAGS_FILL_FULL:
744 745
		trace_seq_puts(s, "              |  ");
		return;
746
	case FLAGS_FILL_START:
747 748
		trace_seq_puts(s, "  ");
		return;
749
	case FLAGS_FILL_END:
750 751
		trace_seq_puts(s, " |");
		return;
752 753 754
	}

	/* Signal a overhead of time execution to the output */
755 756 757
	if (flags & TRACE_GRAPH_PRINT_OVERHEAD)
		trace_seq_printf(s, "%c ", trace_find_mark(duration));
	else
758
		trace_seq_puts(s, "  ");
759

760 761
	trace_print_graph_duration(duration, s);
	trace_seq_puts(s, "|  ");
762 763 764
}

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

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

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

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

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

800
	/* Overhead and duration */
801
	print_graph_duration(tr, duration, s, flags);
802

803
	/* Function */
804 805
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
		trace_seq_putc(s, ' ');
806

807
	trace_seq_printf(s, "%ps();\n", (void *)call->func);
808

809
	return trace_handle_return(s);
810 811 812
}

static enum print_line_t
813 814
print_graph_entry_nested(struct trace_iterator *iter,
			 struct ftrace_graph_ent_entry *entry,
815
			 struct trace_seq *s, int cpu, u32 flags)
816 817
{
	struct ftrace_graph_ent *call = &entry->graph_ent;
818
	struct fgraph_data *data = iter->private;
819
	struct trace_array *tr = iter->tr;
820 821 822
	int i;

	if (data) {
823
		struct fgraph_cpu_data *cpu_data;
824 825
		int cpu = iter->cpu;

826 827 828 829 830 831
		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;
832
	}
833

834
	/* No time */
835
	print_graph_duration(tr, 0, s, flags | FLAGS_FILL_FULL);
836

837
	/* Function */
838 839 840 841
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
		trace_seq_putc(s, ' ');

	trace_seq_printf(s, "%ps() {\n", (void *)call->func);
842

843
	if (trace_seq_has_overflowed(s))
844 845
		return TRACE_TYPE_PARTIAL_LINE;

846 847 848 849 850
	/*
	 * we already consumed the current entry to check the next one
	 * and see if this is a leaf.
	 */
	return TRACE_TYPE_NO_CONSUME;
851 852
}

853
static void
854
print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
855
		     int type, unsigned long addr, u32 flags)
856
{
857
	struct fgraph_data *data = iter->private;
858
	struct trace_entry *ent = iter->ent;
859
	struct trace_array *tr = iter->tr;
860
	int cpu = iter->cpu;
861

862
	/* Pid */
863
	verif_pid(s, ent->pid, cpu, data);
864

865
	if (type)
866
		/* Interrupt */
867
		print_graph_irq(iter, addr, type, cpu, ent->pid, flags);
868

869
	if (!(tr->trace_flags & TRACE_ITER_CONTEXT_INFO))
870
		return;
871

872
	/* Absolute time */
873 874
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
		print_graph_abs_time(iter->ts, s);
875

876
	/* Cpu */
877 878
	if (flags & TRACE_GRAPH_PRINT_CPU)
		print_graph_cpu(s, cpu);
879 880

	/* Proc */
881
	if (flags & TRACE_GRAPH_PRINT_PROC) {
882 883
		print_graph_proc(s, ent->pid);
		trace_seq_puts(s, " | ");
884
	}
885

886
	/* Latency format */
887
	if (tr->trace_flags & TRACE_ITER_LATENCY_FMT)
888
		print_graph_lat_fmt(s, ent);
889

890
	return;
891 892
}

893 894 895 896 897
/*
 * Entry check for irq code
 *
 * returns 1 if
 *  - we are inside irq code
Lucas De Marchi's avatar
Lucas De Marchi committed
898
 *  - we just entered irq code
899 900 901 902 903 904 905 906 907 908
 *
 * 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;
909
	int *depth_irq;
910 911
	struct fgraph_data *data = iter->private;

912 913 914 915 916 917 918
	/*
	 * 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))
919 920
		return 0;

921 922
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

923 924 925 926 927 928 929 930 931 932 933 934 935 936 937 938 939 940 941 942 943 944 945 946 947 948 949 950 951 952 953 954
	/*
	 * 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;
955
	int *depth_irq;
956 957
	struct fgraph_data *data = iter->private;

958 959 960 961 962 963 964
	/*
	 * 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))
965 966
		return 0;

967 968
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

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
	/*
	 * 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;
}

995 996
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
997
			struct trace_iterator *iter, u32 flags)
998
{
999
	struct fgraph_data *data = iter->private;
1000 1001
	struct ftrace_graph_ent *call = &field->graph_ent;
	struct ftrace_graph_ret_entry *leaf_ret;
1002 1003
	static enum print_line_t ret;
	int cpu = iter->cpu;
1004

1005 1006 1007
	if (check_irq_entry(iter, flags, call->func, call->depth))
		return TRACE_TYPE_HANDLED;

1008
	print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags);
1009

1010 1011
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
1012
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
1013
	else
1014
		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
1015

1016 1017 1018 1019 1020 1021 1022 1023 1024 1025 1026 1027 1028
	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;
1029 1030
}

1031 1032
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
1033 1034
		   struct trace_entry *ent, struct trace_iterator *iter,
		   u32 flags)
1035
{
1036
	unsigned long long duration = trace->rettime - trace->calltime;
1037
	struct fgraph_data *data = iter->private;
1038
	struct trace_array *tr = iter->tr;
1039 1040
	pid_t pid = ent->pid;
	int cpu = iter->cpu;
1041
	int func_match = 1;
1042 1043
	int i;

1044 1045 1046
	if (check_irq_return(iter, flags, trace->depth))
		return TRACE_TYPE_HANDLED;

1047
	if (data) {
1048 1049 1050 1051
		struct fgraph_cpu_data *cpu_data;
		int cpu = iter->cpu;

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
1052 1053 1054 1055 1056 1057

		/*
		 * 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.
		 */
1058 1059 1060 1061 1062 1063 1064
		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;
		}
1065
	}
1066

1067
	print_graph_prologue(iter, s, 0, 0, flags);
1068

1069
	/* Overhead and duration */
1070
	print_graph_duration(tr, duration, s, flags);
1071

1072
	/* Closing brace */
1073 1074
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++)
		trace_seq_putc(s, ' ');
1075

1076 1077 1078 1079
	/*
	 * 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
1080 1081
	 * belongs to, write out the function name. Always do
	 * that if the funcgraph-tail option is enabled.
1082
	 */
1083 1084 1085 1086
	if (func_match && !(flags & TRACE_GRAPH_PRINT_TAIL))
		trace_seq_puts(s, "}\n");
	else
		trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
1087

1088
	/* Overrun */
1089 1090 1091
	if (flags & TRACE_GRAPH_PRINT_OVERRUN)
		trace_seq_printf(s, " (Overruns: %lu)\n",
				 trace->overrun);