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
 * 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 122
ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
			 unsigned long frame_pointer)
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
	current->ret_stack[index].fp = frame_pointer;
175
	*depth = current->curr_ret_stack;
176 177 178 179 180

	return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
181
static void
182 183
ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret,
			unsigned long frame_pointer)
184 185 186 187 188
{
	int index;

	index = current->curr_ret_stack;

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

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

235 236 237 238 239 240 241 242 243 244 245
	*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.
 */
246
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
247 248 249 250
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

251
	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
252
	trace.rettime = trace_clock_local();
253 254
	barrier();
	current->curr_ret_stack--;
255 256 257 258 259 260 261 262 263
	/*
	 * 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;
	}
264

265 266 267 268 269 270 271
	/*
	 * 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);

272 273 274 275 276 277 278 279 280 281
	if (unlikely(!ret)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic. What else to do? */
		ret = (unsigned long)panic;
	}

	return ret;
}

282
int __trace_graph_entry(struct trace_array *tr,
283 284 285 286
				struct ftrace_graph_ent *trace,
				unsigned long flags,
				int pc)
{
287
	struct trace_event_call *call = &event_funcgraph_entry;
288
	struct ring_buffer_event *event;
289
	struct ring_buffer *buffer = tr->trace_buffer.buffer;
290 291
	struct ftrace_graph_ent_entry *entry;

292
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
293 294 295 296 297
					  sizeof(*entry), flags, pc);
	if (!event)
		return 0;
	entry	= ring_buffer_event_data(event);
	entry->graph_ent			= *trace;
298
	if (!call_filter_check_discard(call, entry, buffer, event))
299
		__buffer_unlock_commit(buffer, event);
300 301 302 303

	return 1;
}

304 305
static inline int ftrace_graph_ignore_irqs(void)
{
306
	if (!ftrace_graph_skip_irqs || trace_recursion_test(TRACE_IRQ_BIT))
307 308 309 310 311
		return 0;

	return in_irq();
}

312 313 314 315 316 317 318 319 320 321
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;

322
	if (!ftrace_trace_task(tr))
323 324
		return 0;

325
	/* trace it when it is-nested-in or is a function enabled. */
326
	if ((!(trace->depth || ftrace_graph_addr(trace->func)) ||
327
	     ftrace_graph_ignore_irqs()) || (trace->depth < 0) ||
328
	    (max_depth && trace->depth >= max_depth))
329 330
		return 0;

331 332 333 334 335 336 337 338 339 340
	/*
	 * 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;

341 342
	local_irq_save(flags);
	cpu = raw_smp_processor_id();
343
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
344 345 346 347 348 349 350 351 352 353 354 355 356 357
	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;
}

358
static int trace_graph_thresh_entry(struct ftrace_graph_ent *trace)
359 360 361 362 363 364 365
{
	if (tracing_thresh)
		return 1;
	else
		return trace_graph_entry(trace);
}

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

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

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

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();
425
	data = per_cpu_ptr(tr->trace_buffer.data, cpu);
426 427 428 429 430 431 432 433 434
	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);
}

435 436 437 438 439 440 441 442 443
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

444
static void trace_graph_thresh_return(struct ftrace_graph_ret *trace)
445 446 447 448 449 450 451 452
{
	if (tracing_thresh &&
	    (trace->rettime - trace->calltime < tracing_thresh))
		return;
	else
		trace_graph_return(trace);
}

453 454
static int graph_trace_init(struct trace_array *tr)
{
455 456
	int ret;

457
	set_graph_array(tr);
458 459 460 461 462 463
	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);
464 465 466 467 468
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
469 470 471 472
}

static void graph_trace_reset(struct trace_array *tr)
{
473 474
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
475 476
}

477
static int graph_trace_update_thresh(struct trace_array *tr)
478 479 480 481 482
{
	graph_trace_reset(tr);
	return graph_trace_init(tr);
}

483
static int max_bytes_for_cpu;
484

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

495 496
#define TRACE_GRAPH_PROCINFO_LENGTH	14

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

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

520
	trace_seq_printf(s, "%s-%s", comm, pid_str);
521 522

	/* Last spaces to align center */
523 524
	for (i = 0; i < spaces - (spaces / 2); i++)
		trace_seq_putc(s, ' ');
525 526
}

527

528
static void print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
529
{
530 531
	trace_seq_putc(s, ' ');
	trace_print_lat_fmt(s, entry);
532 533
}

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

541
	if (!data)
542
		return;
543

544
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
545 546

	if (*last_pid == pid)
547
		return;
548

549 550
	prev_pid = *last_pid;
	*last_pid = pid;
551

552
	if (prev_pid == -1)
553
		return;
554 555 556 557 558 559 560 561
/*
 * Context-switch trace line:

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

 */
562 563 564 565 566 567
	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");
568 569
}

570 571
static struct ftrace_graph_ret_entry *
get_return_for_leaf(struct trace_iterator *iter,
572 573
		struct ftrace_graph_ent_entry *curr)
{
574 575
	struct fgraph_data *data = iter->private;
	struct ring_buffer_iter *ring_iter = NULL;
576 577 578
	struct ring_buffer_event *event;
	struct ftrace_graph_ret_entry *next;

579 580 581 582 583 584 585 586
	/*
	 * 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 {
587

588
		ring_iter = trace_buffer_iter(iter, iter->cpu);
589 590 591 592 593 594 595 596 597

		/* 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.
			 */
598
			ring_buffer_consume(iter->trace_buffer->buffer, iter->cpu,
599
					    NULL, NULL);
600
			event = ring_buffer_peek(iter->trace_buffer->buffer, iter->cpu,
601
						 NULL, NULL);
602
		}
603

604 605 606 607
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
608

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

	if (next->ent.type != TRACE_GRAPH_RET)
628
		return NULL;
629 630 631

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

634 635 636 637 638
	/* this is a leaf, now advance the iterator */
	if (ring_iter)
		ring_buffer_read(ring_iter, NULL);

	return next;
639 640
}

641
static void print_graph_abs_time(u64 t, struct trace_seq *s)
642 643 644 645 646 647
{
	unsigned long usecs_rem;

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

648 649
	trace_seq_printf(s, "%5lu.%06lu |  ",
			 (unsigned long)t, usecs_rem);
650 651
}

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

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

664
	if (tr->trace_flags & TRACE_ITER_CONTEXT_INFO) {
665
		/* Absolute time */
666 667
		if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
			print_graph_abs_time(iter->ts, s);
668

669
		/* Cpu */
670 671
		if (flags & TRACE_GRAPH_PRINT_CPU)
			print_graph_cpu(s, cpu);
672

673 674
		/* Proc */
		if (flags & TRACE_GRAPH_PRINT_PROC) {
675 676
			print_graph_proc(s, pid);
			trace_seq_puts(s, " | ");
677
		}
678 679

		/* Latency format */
680
		if (tr->trace_flags & TRACE_ITER_LATENCY_FMT)
681
			print_graph_lat_fmt(s, ent);
682
	}
683

684
	/* No overhead */
685
	print_graph_duration(tr, 0, s, flags | FLAGS_FILL_START);
686

687
	if (type == TRACE_GRAPH_ENT)
688
		trace_seq_puts(s, "==========>");
689
	else
690
		trace_seq_puts(s, "<==========");
691

692
	print_graph_duration(tr, 0, s, flags | FLAGS_FILL_END);
693
	trace_seq_putc(s, '\n');
694
}
695

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

706
	sprintf(usecs_str, "%lu", (unsigned long) duration);
707 708

	/* Print msecs */
709
	trace_seq_printf(s, "%s", usecs_str);
710

711
	len = strlen(usecs_str);
712 713 714

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

		snprintf(nsecs_str, slen, "%03lu", nsecs_rem);
718
		trace_seq_printf(s, ".%s", nsecs_str);
719
		len += strlen(nsecs_str) + 1;
720 721
	}

722
	trace_seq_puts(s, " us ");
723 724

	/* Print remaining spaces to fit the row's width */
725
	for (i = len; i < 8; i++)
726
		trace_seq_putc(s, ' ');
727 728
}

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

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

	/* Signal a overhead of time execution to the output */
751 752 753
	if (flags & TRACE_GRAPH_PRINT_OVERHEAD)
		trace_seq_printf(s, "%c ", trace_find_mark(duration));
	else
754
		trace_seq_puts(s, "  ");
755

756 757
	trace_print_graph_duration(duration, s);
	trace_seq_puts(s, "|  ");
758 759 760
}

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

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

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

		cpu_data = per_cpu_ptr(data->cpu_data, cpu);
783 784 785 786 787 788

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

796
	/* Overhead and duration */
797
	print_graph_duration(tr, duration, s, flags);
798

799
	/* Function */
800 801
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
		trace_seq_putc(s, ' ');
802

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

805
	return trace_handle_return(s);
806 807 808
}

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

	if (data) {
819
		struct fgraph_cpu_data *cpu_data;
820 821
		int cpu = iter->cpu;

822 823 824 825 826 827
		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;
828
	}
829

830
	/* No time */
831
	print_graph_duration(tr, 0, s, flags | FLAGS_FILL_FULL);
832

833
	/* Function */
834 835 836 837
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
		trace_seq_putc(s, ' ');

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

839
	if (trace_seq_has_overflowed(s))
840 841
		return TRACE_TYPE_PARTIAL_LINE;

842 843 844 845 846
	/*
	 * we already consumed the current entry to check the next one
	 * and see if this is a leaf.
	 */
	return TRACE_TYPE_NO_CONSUME;
847 848
}

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

858
	/* Pid */
859
	verif_pid(s, ent->pid, cpu, data);
860

861
	if (type)
862
		/* Interrupt */
863
		print_graph_irq(iter, addr, type, cpu, ent->pid, flags);
864

865
	if (!(tr->trace_flags & TRACE_ITER_CONTEXT_INFO))
866
		return;
867

868
	/* Absolute time */
869 870
	if (flags & TRACE_GRAPH_PRINT_ABS_TIME)
		print_graph_abs_time(iter->ts, s);
871

872
	/* Cpu */
873 874
	if (flags & TRACE_GRAPH_PRINT_CPU)
		print_graph_cpu(s, cpu);
875 876

	/* Proc */
877
	if (flags & TRACE_GRAPH_PRINT_PROC) {
878 879
		print_graph_proc(s, ent->pid);
		trace_seq_puts(s, " | ");
880
	}
881

882
	/* Latency format */
883
	if (tr->trace_flags & TRACE_ITER_LATENCY_FMT)
884
		print_graph_lat_fmt(s, ent);
885

886
	return;
887 888
}

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

908 909 910 911 912 913 914
	/*
	 * 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))
915 916
		return 0;

917 918
	depth_irq = &(per_cpu_ptr(data->cpu_data, cpu)->depth_irq);

919 920 921 922 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
	/*
	 * 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;
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
	/*
	 * 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;
}

991 992
static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
993
			struct trace_iterator *iter, u32 flags)