trace_functions_graph.c 27.8 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
12
13
14
 * 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>
#include <linux/fs.h>

#include "trace.h"
15
#include "trace_output.h"
16

17
struct fgraph_cpu_data {
18
19
	pid_t		last_pid;
	int		depth;
20
21
22
23
24
25
26
27
28
29
30
	int		ignore;
};

struct fgraph_data {
	struct fgraph_cpu_data		*cpu_data;

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

33
#define TRACE_GRAPH_INDENT	2
34

35
/* Flag options */
36
#define TRACE_GRAPH_PRINT_OVERRUN	0x1
37
38
#define TRACE_GRAPH_PRINT_CPU		0x2
#define TRACE_GRAPH_PRINT_OVERHEAD	0x4
39
#define TRACE_GRAPH_PRINT_PROC		0x8
40
41
#define TRACE_GRAPH_PRINT_DURATION	0x10
#define TRACE_GRAPH_PRINT_ABS_TIME	0X20
42

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
58
59
	{ } /* Empty entry */
};

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

66
static struct trace_array *graph_array;
67

68

69
70
/* Add a function return address to the trace stack on thread info.*/
int
71
72
ftrace_push_return_trace(unsigned long ret, unsigned long func, int *depth,
			 unsigned long frame_pointer)
73
{
74
	unsigned long long calltime;
75
76
77
78
79
	int index;

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

80
81
82
83
84
85
	/*
	 * We must make sure the ret_stack is tested before we read
	 * anything else.
	 */
	smp_rmb();

86
87
88
89
90
91
	/* The return trace stack is full */
	if (current->curr_ret_stack == FTRACE_RETFUNC_DEPTH - 1) {
		atomic_inc(&current->trace_overrun);
		return -EBUSY;
	}

92
93
	calltime = trace_clock_local();

94
95
96
97
	index = ++current->curr_ret_stack;
	barrier();
	current->ret_stack[index].ret = ret;
	current->ret_stack[index].func = func;
98
	current->ret_stack[index].calltime = calltime;
99
	current->ret_stack[index].subtime = 0;
100
	current->ret_stack[index].fp = frame_pointer;
101
102
103
104
105
106
	*depth = index;

	return 0;
}

/* Retrieve a function return address to the trace stack on thread info.*/
107
static void
108
109
ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret,
			unsigned long frame_pointer)
110
111
112
113
114
115
116
117
118
119
120
121
122
{
	int index;

	index = current->curr_ret_stack;

	if (unlikely(index < 0)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic, otherwise we have no where to go */
		*ret = (unsigned long)panic;
		return;
	}

123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
#ifdef CONFIG_HAVE_FUNCTION_GRAPH_FP_TEST
	/*
	 * The arch may choose to record the frame pointer used
	 * and check it here to make sure that it is what we expect it
	 * to be. If gcc does not set the place holder of the return
	 * address in the frame pointer, and does a copy instead, then
	 * the function graph trace will fail. This test detects this
	 * case.
	 *
	 * Currently, x86_32 with optimize for size (-Os) makes the latest
	 * gcc do the above.
	 */
	if (unlikely(current->ret_stack[index].fp != frame_pointer)) {
		ftrace_graph_stop();
		WARN(1, "Bad frame pointer: expected %lx, received %lx\n"
138
		     "  from func %ps return to %lx\n",
139
140
141
142
143
144
145
146
147
		     current->ret_stack[index].fp,
		     frame_pointer,
		     (void *)current->ret_stack[index].func,
		     current->ret_stack[index].ret);
		*ret = (unsigned long)panic;
		return;
	}
#endif

148
149
150
151
152
153
154
155
156
157
158
	*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.
 */
159
unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
160
161
162
163
{
	struct ftrace_graph_ret trace;
	unsigned long ret;

164
	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
165
	trace.rettime = trace_clock_local();
166
	ftrace_graph_return(&trace);
167
168
	barrier();
	current->curr_ret_stack--;
169
170
171
172
173
174
175
176
177
178
179

	if (unlikely(!ret)) {
		ftrace_graph_stop();
		WARN_ON(1);
		/* Might as well panic. What else to do? */
		ret = (unsigned long)panic;
	}

	return ret;
}

180
181
182
183
184
185
186
static int __trace_graph_entry(struct trace_array *tr,
				struct ftrace_graph_ent *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_entry;
	struct ring_buffer_event *event;
187
	struct ring_buffer *buffer = tr->buffer;
188
189
	struct ftrace_graph_ent_entry *entry;

190
	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
191
192
		return 0;

193
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
194
195
196
197
198
					  sizeof(*entry), flags, pc);
	if (!event)
		return 0;
	entry	= ring_buffer_event_data(event);
	entry->graph_ent			= *trace;
199
200
	if (!filter_current_check_discard(buffer, call, entry, event))
		ring_buffer_unlock_commit(buffer, event);
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247

	return 1;
}

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;

	if (!ftrace_graph_addr(trace->func))
		return 0;

	local_irq_save(flags);
	cpu = raw_smp_processor_id();
	data = tr->data[cpu];
	disabled = atomic_inc_return(&data->disabled);
	if (likely(disabled == 1)) {
		pc = preempt_count();
		ret = __trace_graph_entry(tr, trace, flags, pc);
	} else {
		ret = 0;
	}
	/* Only do the atomic if it is not already set */
	if (!test_tsk_trace_graph(current))
		set_tsk_trace_graph(current);

	atomic_dec(&data->disabled);
	local_irq_restore(flags);

	return ret;
}

static void __trace_graph_return(struct trace_array *tr,
				struct ftrace_graph_ret *trace,
				unsigned long flags,
				int pc)
{
	struct ftrace_event_call *call = &event_funcgraph_exit;
	struct ring_buffer_event *event;
248
	struct ring_buffer *buffer = tr->buffer;
249
250
	struct ftrace_graph_ret_entry *entry;

251
	if (unlikely(__this_cpu_read(per_cpu_var(ftrace_cpu_disabled))))
252
253
		return;

254
	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_RET,
255
256
257
258
259
					  sizeof(*entry), flags, pc);
	if (!event)
		return;
	entry	= ring_buffer_event_data(event);
	entry->ret				= *trace;
260
261
	if (!filter_current_check_discard(buffer, call, entry, event))
		ring_buffer_unlock_commit(buffer, event);
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
}

void trace_graph_return(struct ftrace_graph_ret *trace)
{
	struct trace_array *tr = graph_array;
	struct trace_array_cpu *data;
	unsigned long flags;
	long disabled;
	int cpu;
	int pc;

	local_irq_save(flags);
	cpu = raw_smp_processor_id();
	data = tr->data[cpu];
	disabled = atomic_inc_return(&data->disabled);
	if (likely(disabled == 1)) {
		pc = preempt_count();
		__trace_graph_return(tr, trace, flags, pc);
	}
	if (!trace->depth)
		clear_tsk_trace_graph(current);
	atomic_dec(&data->disabled);
	local_irq_restore(flags);
}

287
288
289
290
291
292
293
294
295
void set_graph_array(struct trace_array *tr)
{
	graph_array = tr;

	/* Make graph_array visible before we start tracing */

	smp_mb();
}

296
297
static int graph_trace_init(struct trace_array *tr)
{
298
299
	int ret;

300
	set_graph_array(tr);
301
302
	ret = register_ftrace_graph(&trace_graph_return,
				    &trace_graph_entry);
303
304
305
306
307
	if (ret)
		return ret;
	tracing_start_cmdline_record();

	return 0;
308
309
310
311
}

static void graph_trace_reset(struct trace_array *tr)
{
312
313
	tracing_stop_cmdline_record();
	unregister_ftrace_graph();
314
315
}

316
static int max_bytes_for_cpu;
317
318
319
320
321
322

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

323
324
325
326
327
	/*
	 * Start with a space character - to make it stand out
	 * to the right a bit when trace output is pasted into
	 * email:
	 */
328
	ret = trace_seq_printf(s, " %*d) ", max_bytes_for_cpu, cpu);
329
	if (!ret)
330
331
		return TRACE_TYPE_PARTIAL_LINE;

332
333
334
	return TRACE_TYPE_HANDLED;
}

335
336
337
338
339
#define TRACE_GRAPH_PROCINFO_LENGTH	14

static enum print_line_t
print_graph_proc(struct trace_seq *s, pid_t pid)
{
340
	char comm[TASK_COMM_LEN];
341
342
	/* sign + log10(MAX_INT) + '\0' */
	char pid_str[11];
343
344
345
346
	int spaces = 0;
	int ret;
	int len;
	int i;
347

348
	trace_find_cmdline(pid, comm);
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
	comm[7] = '\0';
	sprintf(pid_str, "%d", pid);

	/* 1 stands for the "-" character */
	len = strlen(comm) + strlen(pid_str) + 1;

	if (len < TRACE_GRAPH_PROCINFO_LENGTH)
		spaces = TRACE_GRAPH_PROCINFO_LENGTH - len;

	/* First spaces to align center */
	for (i = 0; i < spaces / 2; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	ret = trace_seq_printf(s, "%s-%s", comm, pid_str);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Last spaces to align center */
	for (i = 0; i < spaces - (spaces / 2); i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
	return TRACE_TYPE_HANDLED;
}

378

379
380
381
static enum print_line_t
print_graph_lat_fmt(struct trace_seq *s, struct trace_entry *entry)
{
382
	if (!trace_seq_putc(s, ' '))
383
384
		return 0;

385
	return trace_print_lat_fmt(s, entry);
386
387
}

388
/* If the pid changed since the last trace, output this event */
389
static enum print_line_t
390
verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
391
{
392
	pid_t prev_pid;
393
	pid_t *last_pid;
394
	int ret;
395

396
	if (!data)
397
398
		return TRACE_TYPE_HANDLED;

399
	last_pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
400
401

	if (*last_pid == pid)
402
		return TRACE_TYPE_HANDLED;
403

404
405
	prev_pid = *last_pid;
	*last_pid = pid;
406

407
408
	if (prev_pid == -1)
		return TRACE_TYPE_HANDLED;
409
410
411
412
413
414
415
416
417
/*
 * Context-switch trace line:

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

 */
	ret = trace_seq_printf(s,
418
		" ------------------------------------------\n");
419
	if (!ret)
420
		return TRACE_TYPE_PARTIAL_LINE;
421
422
423

	ret = print_graph_cpu(s, cpu);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
424
		return TRACE_TYPE_PARTIAL_LINE;
425
426
427

	ret = print_graph_proc(s, prev_pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
428
		return TRACE_TYPE_PARTIAL_LINE;
429
430
431

	ret = trace_seq_printf(s, " => ");
	if (!ret)
432
		return TRACE_TYPE_PARTIAL_LINE;
433
434
435

	ret = print_graph_proc(s, pid);
	if (ret == TRACE_TYPE_PARTIAL_LINE)
436
		return TRACE_TYPE_PARTIAL_LINE;
437
438
439
440

	ret = trace_seq_printf(s,
		"\n ------------------------------------------\n\n");
	if (!ret)
441
		return TRACE_TYPE_PARTIAL_LINE;
442

443
	return TRACE_TYPE_HANDLED;
444
445
}

446
447
static struct ftrace_graph_ret_entry *
get_return_for_leaf(struct trace_iterator *iter,
448
449
		struct ftrace_graph_ent_entry *curr)
{
450
451
	struct fgraph_data *data = iter->private;
	struct ring_buffer_iter *ring_iter = NULL;
452
453
454
	struct ring_buffer_event *event;
	struct ftrace_graph_ret_entry *next;

455
456
457
458
459
460
461
462
	/*
	 * 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 {
463

464
465
466
467
468
469
470
471
472
473
474
475
476
477
		ring_iter = iter->buffer_iter[iter->cpu];

		/* First peek to compare current entry and the next one */
		if (ring_iter)
			event = ring_buffer_iter_peek(ring_iter, NULL);
		else {
			/*
			 * We need to consume the current entry to see
			 * the next one.
			 */
			ring_buffer_consume(iter->tr->buffer, iter->cpu, NULL);
			event = ring_buffer_peek(iter->tr->buffer, iter->cpu,
						 NULL);
		}
478

479
480
481
482
		if (!event)
			return NULL;

		next = ring_buffer_event_data(event);
483

484
485
486
487
488
489
490
491
492
		if (data) {
			/*
			 * Save current and next entries for later reference
			 * if the output fails.
			 */
			data->ent = *curr;
			data->ret = *next;
		}
	}
493
494

	if (next->ent.type != TRACE_GRAPH_RET)
495
		return NULL;
496
497
498

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

501
502
503
504
505
	/* this is a leaf, now advance the iterator */
	if (ring_iter)
		ring_buffer_read(ring_iter, NULL);

	return next;
506
507
}

508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
/* Signal a overhead of time execution to the output */
static int
print_graph_overhead(unsigned long long duration, struct trace_seq *s)
{
	/* If duration disappear, we don't need anything */
	if (!(tracer_flags.val & TRACE_GRAPH_PRINT_DURATION))
		return 1;

	/* Non nested entry or return */
	if (duration == -1)
		return trace_seq_printf(s, "  ");

	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
		/* Duration exceeded 100 msecs */
		if (duration > 100000ULL)
			return trace_seq_printf(s, "! ");

		/* Duration exceeded 10 msecs */
		if (duration > 10000ULL)
			return trace_seq_printf(s, "+ ");
	}

	return trace_seq_printf(s, "  ");
}

533
534
535
536
537
538
539
540
541
542
543
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);
}

544
static enum print_line_t
545
print_graph_irq(struct trace_iterator *iter, unsigned long addr,
546
		enum trace_type type, int cpu, pid_t pid)
547
548
{
	int ret;
549
	struct trace_seq *s = &iter->seq;
550
551
552
553
554

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

555
556
557
558
559
560
561
	/* Absolute time */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

562
563
564
565
566
567
	/* Cpu */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
		ret = print_graph_cpu(s, cpu);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
568

569
570
571
572
573
574
575
576
577
	/* Proc */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
		ret = print_graph_proc(s, pid);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
		ret = trace_seq_printf(s, " | ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
578

579
580
581
582
	/* No overhead */
	ret = print_graph_overhead(-1, s);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
583

584
585
586
587
588
589
590
591
592
593
594
595
	if (type == TRACE_GRAPH_ENT)
		ret = trace_seq_printf(s, "==========>");
	else
		ret = trace_seq_printf(s, "<==========");

	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* Don't close the duration column if haven't one */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
		trace_seq_printf(s, " |");
	ret = trace_seq_printf(s, "\n");
596
597
598
599
600

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

602
603
enum print_line_t
trace_print_graph_duration(unsigned long long duration, struct trace_seq *s)
604
605
{
	unsigned long nsecs_rem = do_div(duration, 1000);
606
607
608
609
610
611
612
613
614
	/* 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 */
615
	ret = trace_seq_printf(s, "%s", msecs_str);
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	len = strlen(msecs_str);

	/* Print nsecs (we don't want to exceed 7 numbers) */
	if (len < 7) {
		snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem);
		ret = trace_seq_printf(s, ".%s", nsecs_str);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
		len += strlen(nsecs_str);
	}

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

	/* Print remaining spaces to fit the row's width */
	for (i = len; i < 7; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
640
641
642
643
644
645
646
647
648
649
650
	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
print_graph_duration(unsigned long long duration, struct trace_seq *s)
{
	int ret;

	ret = trace_print_graph_duration(duration, s);
	if (ret != TRACE_TYPE_HANDLED)
		return ret;
651
652
653
654
655

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

656
	return TRACE_TYPE_HANDLED;
657
658
659
}

/* Case of a leaf function on its call entry */
660
static enum print_line_t
661
print_graph_entry_leaf(struct trace_iterator *iter,
662
663
		struct ftrace_graph_ent_entry *entry,
		struct ftrace_graph_ret_entry *ret_entry, struct trace_seq *s)
664
{
665
	struct fgraph_data *data = iter->private;
666
667
668
	struct ftrace_graph_ret *graph_ret;
	struct ftrace_graph_ent *call;
	unsigned long long duration;
669
	int ret;
670
	int i;
671

672
673
674
675
	graph_ret = &ret_entry->ret;
	call = &entry->graph_ent;
	duration = graph_ret->rettime - graph_ret->calltime;

676
677
	if (data) {
		int cpu = iter->cpu;
678
		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
679
680
681
682
683
684
685
686
687

		/*
		 * Comments display at + 1 to depth. Since
		 * this is a leaf function, keep the comments
		 * equal to this depth.
		 */
		*depth = call->depth - 1;
	}

688
	/* Overhead */
689
690
691
	ret = print_graph_overhead(duration, s);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
692
693

	/* Duration */
694
695
696
697
698
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
		ret = print_graph_duration(duration, s);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
699

700
701
702
703
704
705
706
	/* Function */
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

707
	ret = trace_seq_printf(s, "%ps();\n", (void *)call->func);
708
709
710
711
712
713
714
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}

static enum print_line_t
715
716
717
print_graph_entry_nested(struct trace_iterator *iter,
			 struct ftrace_graph_ent_entry *entry,
			 struct trace_seq *s, int cpu)
718
719
{
	struct ftrace_graph_ent *call = &entry->graph_ent;
720
721
722
723
724
725
	struct fgraph_data *data = iter->private;
	int ret;
	int i;

	if (data) {
		int cpu = iter->cpu;
726
		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
727
728
729

		*depth = call->depth;
	}
730
731

	/* No overhead */
732
733
734
	ret = print_graph_overhead(-1, s);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
735

736
737
	/* No time */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
738
739
740
741
742
		ret = trace_seq_printf(s, "            |  ");
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

743
	/* Function */
744
745
	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
746
747
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
748
749
	}

750
	ret = trace_seq_printf(s, "%ps() {\n", (void *)call->func);
751
752
753
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

754
755
756
757
758
	/*
	 * we already consumed the current entry to check the next one
	 * and see if this is a leaf.
	 */
	return TRACE_TYPE_NO_CONSUME;
759
760
}

761
static enum print_line_t
762
763
print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
		     int type, unsigned long addr)
764
{
765
	struct fgraph_data *data = iter->private;
766
	struct trace_entry *ent = iter->ent;
767
768
	int cpu = iter->cpu;
	int ret;
769

770
	/* Pid */
771
	if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
772
773
		return TRACE_TYPE_PARTIAL_LINE;

774
775
776
777
778
779
	if (type) {
		/* Interrupt */
		ret = print_graph_irq(iter, addr, type, cpu, ent->pid);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
780

781
782
783
784
785
786
787
	/* Absolute time */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
		ret = print_graph_abs_time(iter->ts, s);
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

788
789
790
	/* Cpu */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
		ret = print_graph_cpu(s, cpu);
791
792
793
794
795
796
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Proc */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
797
		ret = print_graph_proc(s, ent->pid);
798
799
800
801
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;

		ret = trace_seq_printf(s, " | ");
802
803
804
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}
805

806
807
808
809
810
811
812
	/* 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;
	}

813
814
815
816
817
818
819
	return 0;
}

static enum print_line_t
print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
			struct trace_iterator *iter)
{
820
	struct fgraph_data *data = iter->private;
821
822
	struct ftrace_graph_ent *call = &field->graph_ent;
	struct ftrace_graph_ret_entry *leaf_ret;
823
824
	static enum print_line_t ret;
	int cpu = iter->cpu;
825
826
827
828

	if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func))
		return TRACE_TYPE_PARTIAL_LINE;

829
830
	leaf_ret = get_return_for_leaf(iter, field);
	if (leaf_ret)
831
		ret = print_graph_entry_leaf(iter, field, leaf_ret, s);
832
	else
833
		ret = print_graph_entry_nested(iter, field, s, cpu);
834

835
836
837
838
839
840
841
842
843
844
845
846
847
	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;
848
849
}

850
851
static enum print_line_t
print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
852
		   struct trace_entry *ent, struct trace_iterator *iter)
853
{
854
	unsigned long long duration = trace->rettime - trace->calltime;
855
856
857
858
859
860
861
862
	struct fgraph_data *data = iter->private;
	pid_t pid = ent->pid;
	int cpu = iter->cpu;
	int ret;
	int i;

	if (data) {
		int cpu = iter->cpu;
863
		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
864
865
866
867
868
869
870
871

		/*
		 * 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.
		 */
		*depth = trace->depth - 1;
	}
872

873
	if (print_graph_prologue(iter, s, 0, 0))
874
875
		return TRACE_TYPE_PARTIAL_LINE;

876
	/* Overhead */
877
878
879
	ret = print_graph_overhead(duration, s);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
880
881

	/* Duration */
882
883
884
885
886
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
		ret = print_graph_duration(duration, s);
		if (ret == TRACE_TYPE_PARTIAL_LINE)
			return TRACE_TYPE_PARTIAL_LINE;
	}
887
888

	/* Closing brace */
889
890
	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
		ret = trace_seq_printf(s, " ");
891
892
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
893
894
	}

895
	ret = trace_seq_printf(s, "}\n");
896
897
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;
898

899
	/* Overrun */
900
901
902
	if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
		ret = trace_seq_printf(s, " (Overruns: %lu)\n",
					trace->overrun);
903
904
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
905
	}
906

907
	ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET, cpu, pid);
908
909
910
	if (ret == TRACE_TYPE_PARTIAL_LINE)
		return TRACE_TYPE_PARTIAL_LINE;

911
912
913
	return TRACE_TYPE_HANDLED;
}

914
static enum print_line_t
915
916
print_graph_comment(struct trace_seq *s,  struct trace_entry *ent,
		    struct trace_iterator *iter)
917
{
918
	unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
919
	struct fgraph_data *data = iter->private;
920
	struct trace_event *event;
921
	int depth = 0;
922
	int ret;
923
924
925
	int i;

	if (data)
926
		depth = per_cpu_ptr(data->cpu_data, iter->cpu)->depth;
927

928
	if (print_graph_prologue(iter, s, 0, 0))
929
930
		return TRACE_TYPE_PARTIAL_LINE;

931
	/* No overhead */
932
933
934
935
936
937
938
	ret = print_graph_overhead(-1, s);
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	/* No time */
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
		ret = trace_seq_printf(s, "            |  ");
939
940
941
942
943
		if (!ret)
			return TRACE_TYPE_PARTIAL_LINE;
	}

	/* Indentation */
944
945
	if (depth > 0)
		for (i = 0; i < (depth + 1) * TRACE_GRAPH_INDENT; i++) {
946
947
948
949
950
951
			ret = trace_seq_printf(s, " ");
			if (!ret)
				return TRACE_TYPE_PARTIAL_LINE;
		}

	/* The comment */
952
953
954
955
	ret = trace_seq_printf(s, "/* ");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
	switch (iter->ent->type) {
	case TRACE_BPRINT:
		ret = trace_print_bprintk_msg_only(iter);
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
		break;
	case TRACE_PRINT:
		ret = trace_print_printk_msg_only(iter);
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
		break;
	default:
		event = ftrace_find_event(ent->type);
		if (!event)
			return TRACE_TYPE_UNHANDLED;

		ret = event->trace(iter, sym_flags);
		if (ret != TRACE_TYPE_HANDLED)
			return ret;
	}
976

977
978
979
980
981
982
	/* Strip ending newline */
	if (s->buffer[s->len - 1] == '\n') {
		s->buffer[s->len - 1] = '\0';
		s->len--;
	}

983
984
985
986
987
988
989
990
	ret = trace_seq_printf(s, " */\n");
	if (!ret)
		return TRACE_TYPE_PARTIAL_LINE;

	return TRACE_TYPE_HANDLED;
}


991
992
993
enum print_line_t
print_graph_function(struct trace_iterator *iter)
{
994
995
	struct ftrace_graph_ent_entry *field;
	struct fgraph_data *data = iter->private;
996
	struct trace_entry *entry = iter->ent;
997
	struct trace_seq *s = &iter->seq;
998
999
1000
1001
1002
1003
1004
1005
1006
1007
1008
1009
1010
1011
1012
1013
1014
1015
1016
1017
1018
1019
1020
	int cpu = iter->cpu;
	int ret;

	if (data && per_cpu_ptr(data->cpu_data, cpu)->ignore) {
		per_cpu_ptr(data->cpu_data, cpu)->ignore = 0;
		return TRACE_TYPE_HANDLED;
	}

	/*
	 * If the last output failed, there's a possibility we need
	 * to print out the missing entry which would never go out.
	 */
	if (data && data->failed) {
		field = &data->ent;
		iter->cpu = data->cpu;
		ret = print_graph_entry(field, s, iter);
		if (ret == TRACE_TYPE_HANDLED && iter->cpu != cpu) {
			per_cpu_ptr(data->cpu_data, iter->cpu)->ignore = 1;
			ret = TRACE_TYPE_NO_CONSUME;
		}
		iter->cpu = cpu;
		return ret;
	}
1021

1022
1023
	switch (entry->type) {
	case TRACE_GRAPH_ENT: {
1024
1025
1026
1027
1028
1029
		/*
		 * print_graph_entry() may consume the current event,
		 * thus @field may become invalid, so we need to save it.
		 * sizeof(struct ftrace_graph_ent_entry) is very small,
		 * it can be safely saved at the stack.
		 */
1030
		struct ftrace_graph_ent_entry saved;
1031
		trace_assign_type(field, entry);
1032
1033
		saved = *field;
		return print_graph_entry(&saved, s, iter);
1034
1035
1036
1037
	}
	case TRACE_GRAPH_RET: {
		struct ftrace_graph_ret_entry *field;
		trace_assign_type(field, entry);
1038
		return print_graph_return(&field->ret, s, entry, iter);
1039
1040
	}
	default:
1041
		return print_graph_comment(s, entry, iter);
1042
	}
1043
1044

	return TRACE_TYPE_HANDLED;
1045
1046
}

1047
1048
1049
1050
1051
1052
1053
1054
1055
1056
1057
1058
1059
1060
1061
1062
1063
1064
static void print_lat_header(struct seq_file *s)
{
	static const char spaces[] = "                "	/* 16 spaces */
		"    "					/* 4 spaces */
		"                 ";			/* 17 spaces */
	int size = 0;

	if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
		size += 16;
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
		size += 4;
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
		size += 17;

	seq_printf(s, "#%.*s  _-----=> irqs-off        \n", size, spaces);
	seq_printf(s, "#%.*s / _----=> need-resched    \n", size, spaces);
	seq_printf(s, "#%.*s| / _---=> hardirq/softirq \n", size, spaces);
	seq_printf(s, "#%.*s|| / _--=> preempt-depth   \n", size, spaces);
1065
1066
	seq_printf(s, "#%.*s||| / _-=> lock-depth      \n", size, spaces);
	seq_printf(s, "#%.*s|||| /                     \n", size, spaces);
1067
1068
}

1069
1070
static void print_graph_headers(struct seq_file *s)
{
1071
1072
1073
1074
1075
	int lat = trace_flags & TRACE_ITER_LATENCY_FMT;

	if (lat)
		print_lat_header(s);

1076
	/* 1st line */
1077
	seq_printf(s, "#");
1078
1079
	if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
		seq_printf(s, "     TIME       ");
1080
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
1081
		seq_printf(s, " CPU");
1082
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
1083
1084
		seq_printf(s, "  TASK/PID       ");
	if (lat)
1085
		seq_printf(s, "|||||");
1086
1087
1088
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
		seq_printf(s, "  DURATION   ");
	seq_printf(s, "               FUNCTION CALLS\n");
1089
1090

	/* 2nd line */
1091
	seq_printf(s, "#");
1092
1093
	if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
		seq_printf(s, "      |         ");
1094
	if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
1095
		seq_printf(s, " |  ");
1096
	if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
1097
1098
		seq_printf(s, "   |    |        ");
	if (lat)
1099
		seq_printf(s, "|||||");
1100
1101
1102
	if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
		seq_printf(s, "   |   |      ");
	seq_printf(s, "               |   |   |   |\n");
1103
}
1104
1105
1106

static void graph_trace_open(struct trace_iterator *iter)
{
1107
	/* pid and depth on the last trace processed */
1108
	struct fgraph_data *data;
1109
1110
	int cpu;

1111
1112
1113
	iter->private = NULL;

	data = kzalloc(sizeof(*data), GFP_KERNEL);
1114
	if (!data)
1115
1116
1117
1118
1119
1120
1121
1122
1123
1124
1125
1126
1127
1128
		goto out_err;

	data->cpu_data = alloc_percpu(struct fgraph_cpu_data);
	if (!data->cpu_data)
		goto out_err_free;

	for_each_possible_cpu(cpu) {
		pid_t *pid = &(per_cpu_ptr(data->cpu_data, cpu)->last_pid);
		int *depth = &(per_cpu_ptr(data->cpu_data, cpu)->depth);
		int *ignore = &(per_cpu_ptr(data->cpu_data, cpu)->ignore);
		*pid = -1;
		*depth = 0;
		*ignore = 0;
	}
1129

1130
	iter->private = data;
1131
1132
1133
1134
1135
1136
1137

	return;

 out_err_free:
	kfree(data);
 out_err:
	pr_warning("function graph tracer: not enough memory\n");
1138
1139
1140
1141
}

static void graph_trace_close(struct trace_iterator *iter)
{
1142
1143
1144
1145
1146
1147
	struct fgraph_data *data = iter->private;

	if (data) {
		free_percpu(data->cpu_data);
		kfree(data);
	}
1148
1149
}

1150
static struct tracer graph_trace __read_mostly = {
1151
	.name		= "function_graph",
1152
	.open		= graph_trace_open,
1153
	.pipe_open	= graph_trace_open,
1154
	.close		= graph_trace_close,
1155
	.pipe_close	= graph_trace_close,
1156
	.wait_pipe	= poll_wait_pipe,
1157
1158
	.init		= graph_trace_init,
	.reset		= graph_trace_reset,
1159
1160
	.print_line	= print_graph_function,
	.print_header	= print_graph_headers,
1161
	.flags		= &tracer_flags,
1162
1163
1164
#ifdef CONFIG_FTRACE_SELFTEST
	.selftest	= trace_selftest_startup_function_graph,
#endif
1165
1166
1167
1168
};

static __init int init_graph_trace(void)
{
1169
1170
	max_bytes_for_cpu = snprintf(NULL, 0, "%d", nr_cpu_ids - 1);

1171
1172
1173
1174
	return register_tracer(&graph_trace);
}

device_initcall(init_graph_trace);