3 * Function graph tracer.
4 * Copyright (c) 2008-2009 Frederic Weisbecker <fweisbec@gmail.com>
5 * Mostly borrowed from function tracer which
6 * is Copyright (c) Steven Rostedt <srostedt@redhat.com>
9 #include <linux/debugfs.h>
10 #include <linux/uaccess.h>
11 #include <linux/ftrace.h>
15 #include "trace_output.h"
22 #define TRACE_GRAPH_INDENT 2
25 #define TRACE_GRAPH_PRINT_OVERRUN 0x1
26 #define TRACE_GRAPH_PRINT_CPU 0x2
27 #define TRACE_GRAPH_PRINT_OVERHEAD 0x4
28 #define TRACE_GRAPH_PRINT_PROC 0x8
29 #define TRACE_GRAPH_PRINT_DURATION 0x10
30 #define TRACE_GRAPH_PRINT_ABS_TIME 0X20
32 static struct tracer_opt trace_opts[] = {
33 /* Display overruns? (for self-debug purpose) */
34 { TRACER_OPT(funcgraph-overrun, TRACE_GRAPH_PRINT_OVERRUN) },
36 { TRACER_OPT(funcgraph-cpu, TRACE_GRAPH_PRINT_CPU) },
37 /* Display Overhead ? */
38 { TRACER_OPT(funcgraph-overhead, TRACE_GRAPH_PRINT_OVERHEAD) },
39 /* Display proc name/pid */
40 { TRACER_OPT(funcgraph-proc, TRACE_GRAPH_PRINT_PROC) },
41 /* Display duration of execution */
42 { TRACER_OPT(funcgraph-duration, TRACE_GRAPH_PRINT_DURATION) },
43 /* Display absolute time of an entry */
44 { TRACER_OPT(funcgraph-abstime, TRACE_GRAPH_PRINT_ABS_TIME) },
48 static struct tracer_flags tracer_flags = {
49 /* Don't display overruns and proc by default */
50 .val = TRACE_GRAPH_PRINT_CPU | TRACE_GRAPH_PRINT_OVERHEAD |
51 TRACE_GRAPH_PRINT_DURATION,
55 /* pid on the last trace processed */
58 /* Add a function return address to the trace stack on thread info.*/
60 ftrace_push_return_trace(unsigned long ret, unsigned long long time,
61 unsigned long func, int *depth)
65 if (!current->ret_stack)
68 /* The return trace stack is full */
69 if (current->curr_ret_stack == FTRACE_RETFUNC_DEPTH - 1) {
70 atomic_inc(¤t->trace_overrun);
74 index = ++current->curr_ret_stack;
76 current->ret_stack[index].ret = ret;
77 current->ret_stack[index].func = func;
78 current->ret_stack[index].calltime = time;
84 /* Retrieve a function return address to the trace stack on thread info.*/
86 ftrace_pop_return_trace(struct ftrace_graph_ret *trace, unsigned long *ret)
90 index = current->curr_ret_stack;
92 if (unlikely(index < 0)) {
95 /* Might as well panic, otherwise we have no where to go */
96 *ret = (unsigned long)panic;
100 *ret = current->ret_stack[index].ret;
101 trace->func = current->ret_stack[index].func;
102 trace->calltime = current->ret_stack[index].calltime;
103 trace->overrun = atomic_read(¤t->trace_overrun);
104 trace->depth = index;
106 current->curr_ret_stack--;
111 * Send the trace to the ring-buffer.
112 * @return the original return address.
114 unsigned long ftrace_return_to_handler(void)
116 struct ftrace_graph_ret trace;
119 ftrace_pop_return_trace(&trace, &ret);
120 trace.rettime = trace_clock_local();
121 ftrace_graph_return(&trace);
123 if (unlikely(!ret)) {
126 /* Might as well panic. What else to do? */
127 ret = (unsigned long)panic;
133 static int graph_trace_init(struct trace_array *tr)
135 int ret = register_ftrace_graph(&trace_graph_return,
139 tracing_start_cmdline_record();
144 static void graph_trace_reset(struct trace_array *tr)
146 tracing_stop_cmdline_record();
147 unregister_ftrace_graph();
150 static inline int log10_cpu(int nb)
159 static enum print_line_t
160 print_graph_cpu(struct trace_seq *s, int cpu)
164 int log10_this = log10_cpu(cpu);
165 int log10_all = log10_cpu(cpumask_weight(cpu_online_mask));
169 * Start with a space character - to make it stand out
170 * to the right a bit when trace output is pasted into
173 ret = trace_seq_printf(s, " ");
176 * Tricky - we space the CPU field according to the max
177 * number of online CPUs. On a 2-cpu system it would take
178 * a maximum of 1 digit - on a 128 cpu system it would
179 * take up to 3 digits:
181 for (i = 0; i < log10_all - log10_this; i++) {
182 ret = trace_seq_printf(s, " ");
184 return TRACE_TYPE_PARTIAL_LINE;
186 ret = trace_seq_printf(s, "%d) ", cpu);
188 return TRACE_TYPE_PARTIAL_LINE;
190 return TRACE_TYPE_HANDLED;
193 #define TRACE_GRAPH_PROCINFO_LENGTH 14
195 static enum print_line_t
196 print_graph_proc(struct trace_seq *s, pid_t pid)
198 char comm[TASK_COMM_LEN];
199 /* sign + log10(MAX_INT) + '\0' */
206 trace_find_cmdline(pid, comm);
208 sprintf(pid_str, "%d", pid);
210 /* 1 stands for the "-" character */
211 len = strlen(comm) + strlen(pid_str) + 1;
213 if (len < TRACE_GRAPH_PROCINFO_LENGTH)
214 spaces = TRACE_GRAPH_PROCINFO_LENGTH - len;
216 /* First spaces to align center */
217 for (i = 0; i < spaces / 2; i++) {
218 ret = trace_seq_printf(s, " ");
220 return TRACE_TYPE_PARTIAL_LINE;
223 ret = trace_seq_printf(s, "%s-%s", comm, pid_str);
225 return TRACE_TYPE_PARTIAL_LINE;
227 /* Last spaces to align center */
228 for (i = 0; i < spaces - (spaces / 2); i++) {
229 ret = trace_seq_printf(s, " ");
231 return TRACE_TYPE_PARTIAL_LINE;
233 return TRACE_TYPE_HANDLED;
237 /* If the pid changed since the last trace, output this event */
238 static enum print_line_t
239 verif_pid(struct trace_seq *s, pid_t pid, int cpu, struct fgraph_data *data)
246 return TRACE_TYPE_HANDLED;
248 last_pid = &(per_cpu_ptr(data, cpu)->last_pid);
250 if (*last_pid == pid)
251 return TRACE_TYPE_HANDLED;
253 prev_pid = *last_pid;
257 return TRACE_TYPE_HANDLED;
259 * Context-switch trace line:
261 ------------------------------------------
262 | 1) migration/0--1 => sshd-1755
263 ------------------------------------------
266 ret = trace_seq_printf(s,
267 " ------------------------------------------\n");
269 return TRACE_TYPE_PARTIAL_LINE;
271 ret = print_graph_cpu(s, cpu);
272 if (ret == TRACE_TYPE_PARTIAL_LINE)
273 return TRACE_TYPE_PARTIAL_LINE;
275 ret = print_graph_proc(s, prev_pid);
276 if (ret == TRACE_TYPE_PARTIAL_LINE)
277 return TRACE_TYPE_PARTIAL_LINE;
279 ret = trace_seq_printf(s, " => ");
281 return TRACE_TYPE_PARTIAL_LINE;
283 ret = print_graph_proc(s, pid);
284 if (ret == TRACE_TYPE_PARTIAL_LINE)
285 return TRACE_TYPE_PARTIAL_LINE;
287 ret = trace_seq_printf(s,
288 "\n ------------------------------------------\n\n");
290 return TRACE_TYPE_PARTIAL_LINE;
292 return TRACE_TYPE_HANDLED;
295 static struct ftrace_graph_ret_entry *
296 get_return_for_leaf(struct trace_iterator *iter,
297 struct ftrace_graph_ent_entry *curr)
299 struct ring_buffer_iter *ring_iter;
300 struct ring_buffer_event *event;
301 struct ftrace_graph_ret_entry *next;
303 ring_iter = iter->buffer_iter[iter->cpu];
305 /* First peek to compare current entry and the next one */
307 event = ring_buffer_iter_peek(ring_iter, NULL);
309 /* We need to consume the current entry to see the next one */
310 ring_buffer_consume(iter->tr->buffer, iter->cpu, NULL);
311 event = ring_buffer_peek(iter->tr->buffer, iter->cpu,
318 next = ring_buffer_event_data(event);
320 if (next->ent.type != TRACE_GRAPH_RET)
323 if (curr->ent.pid != next->ent.pid ||
324 curr->graph_ent.func != next->ret.func)
327 /* this is a leaf, now advance the iterator */
329 ring_buffer_read(ring_iter, NULL);
334 /* Signal a overhead of time execution to the output */
336 print_graph_overhead(unsigned long long duration, struct trace_seq *s)
338 /* If duration disappear, we don't need anything */
339 if (!(tracer_flags.val & TRACE_GRAPH_PRINT_DURATION))
342 /* Non nested entry or return */
344 return trace_seq_printf(s, " ");
346 if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERHEAD) {
347 /* Duration exceeded 100 msecs */
348 if (duration > 100000ULL)
349 return trace_seq_printf(s, "! ");
351 /* Duration exceeded 10 msecs */
352 if (duration > 10000ULL)
353 return trace_seq_printf(s, "+ ");
356 return trace_seq_printf(s, " ");
359 static int print_graph_abs_time(u64 t, struct trace_seq *s)
361 unsigned long usecs_rem;
363 usecs_rem = do_div(t, NSEC_PER_SEC);
366 return trace_seq_printf(s, "%5lu.%06lu | ",
367 (unsigned long)t, usecs_rem);
370 static enum print_line_t
371 print_graph_irq(struct trace_iterator *iter, unsigned long addr,
372 enum trace_type type, int cpu, pid_t pid)
375 struct trace_seq *s = &iter->seq;
377 if (addr < (unsigned long)__irqentry_text_start ||
378 addr >= (unsigned long)__irqentry_text_end)
379 return TRACE_TYPE_UNHANDLED;
382 if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
383 ret = print_graph_abs_time(iter->ts, s);
385 return TRACE_TYPE_PARTIAL_LINE;
389 if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
390 ret = print_graph_cpu(s, cpu);
391 if (ret == TRACE_TYPE_PARTIAL_LINE)
392 return TRACE_TYPE_PARTIAL_LINE;
395 if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
396 ret = print_graph_proc(s, pid);
397 if (ret == TRACE_TYPE_PARTIAL_LINE)
398 return TRACE_TYPE_PARTIAL_LINE;
399 ret = trace_seq_printf(s, " | ");
401 return TRACE_TYPE_PARTIAL_LINE;
405 ret = print_graph_overhead(-1, s);
407 return TRACE_TYPE_PARTIAL_LINE;
409 if (type == TRACE_GRAPH_ENT)
410 ret = trace_seq_printf(s, "==========>");
412 ret = trace_seq_printf(s, "<==========");
415 return TRACE_TYPE_PARTIAL_LINE;
417 /* Don't close the duration column if haven't one */
418 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
419 trace_seq_printf(s, " |");
420 ret = trace_seq_printf(s, "\n");
423 return TRACE_TYPE_PARTIAL_LINE;
424 return TRACE_TYPE_HANDLED;
427 static enum print_line_t
428 print_graph_duration(unsigned long long duration, struct trace_seq *s)
430 unsigned long nsecs_rem = do_div(duration, 1000);
431 /* log10(ULONG_MAX) + '\0' */
437 sprintf(msecs_str, "%lu", (unsigned long) duration);
440 ret = trace_seq_printf(s, "%s", msecs_str);
442 return TRACE_TYPE_PARTIAL_LINE;
444 len = strlen(msecs_str);
446 /* Print nsecs (we don't want to exceed 7 numbers) */
448 snprintf(nsecs_str, 8 - len, "%03lu", nsecs_rem);
449 ret = trace_seq_printf(s, ".%s", nsecs_str);
451 return TRACE_TYPE_PARTIAL_LINE;
452 len += strlen(nsecs_str);
455 ret = trace_seq_printf(s, " us ");
457 return TRACE_TYPE_PARTIAL_LINE;
459 /* Print remaining spaces to fit the row's width */
460 for (i = len; i < 7; i++) {
461 ret = trace_seq_printf(s, " ");
463 return TRACE_TYPE_PARTIAL_LINE;
466 ret = trace_seq_printf(s, "| ");
468 return TRACE_TYPE_PARTIAL_LINE;
469 return TRACE_TYPE_HANDLED;
473 /* Case of a leaf function on its call entry */
474 static enum print_line_t
475 print_graph_entry_leaf(struct trace_iterator *iter,
476 struct ftrace_graph_ent_entry *entry,
477 struct ftrace_graph_ret_entry *ret_entry, struct trace_seq *s)
479 struct fgraph_data *data = iter->private;
480 struct ftrace_graph_ret *graph_ret;
481 struct ftrace_graph_ent *call;
482 unsigned long long duration;
486 graph_ret = &ret_entry->ret;
487 call = &entry->graph_ent;
488 duration = graph_ret->rettime - graph_ret->calltime;
492 int *depth = &(per_cpu_ptr(data, cpu)->depth);
495 * Comments display at + 1 to depth. Since
496 * this is a leaf function, keep the comments
497 * equal to this depth.
499 *depth = call->depth - 1;
503 ret = print_graph_overhead(duration, s);
505 return TRACE_TYPE_PARTIAL_LINE;
508 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
509 ret = print_graph_duration(duration, s);
510 if (ret == TRACE_TYPE_PARTIAL_LINE)
511 return TRACE_TYPE_PARTIAL_LINE;
515 for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
516 ret = trace_seq_printf(s, " ");
518 return TRACE_TYPE_PARTIAL_LINE;
521 ret = seq_print_ip_sym(s, call->func, 0);
523 return TRACE_TYPE_PARTIAL_LINE;
525 ret = trace_seq_printf(s, "();\n");
527 return TRACE_TYPE_PARTIAL_LINE;
529 return TRACE_TYPE_HANDLED;
532 static enum print_line_t
533 print_graph_entry_nested(struct trace_iterator *iter,
534 struct ftrace_graph_ent_entry *entry,
535 struct trace_seq *s, int cpu)
537 struct ftrace_graph_ent *call = &entry->graph_ent;
538 struct fgraph_data *data = iter->private;
544 int *depth = &(per_cpu_ptr(data, cpu)->depth);
546 *depth = call->depth;
550 ret = print_graph_overhead(-1, s);
552 return TRACE_TYPE_PARTIAL_LINE;
555 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
556 ret = trace_seq_printf(s, " | ");
558 return TRACE_TYPE_PARTIAL_LINE;
562 for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++) {
563 ret = trace_seq_printf(s, " ");
565 return TRACE_TYPE_PARTIAL_LINE;
568 ret = seq_print_ip_sym(s, call->func, 0);
570 return TRACE_TYPE_PARTIAL_LINE;
572 ret = trace_seq_printf(s, "() {\n");
574 return TRACE_TYPE_PARTIAL_LINE;
577 * we already consumed the current entry to check the next one
578 * and see if this is a leaf.
580 return TRACE_TYPE_NO_CONSUME;
583 static enum print_line_t
584 print_graph_prologue(struct trace_iterator *iter, struct trace_seq *s,
585 int type, unsigned long addr)
587 struct fgraph_data *data = iter->private;
588 struct trace_entry *ent = iter->ent;
593 if (verif_pid(s, ent->pid, cpu, data) == TRACE_TYPE_PARTIAL_LINE)
594 return TRACE_TYPE_PARTIAL_LINE;
598 ret = print_graph_irq(iter, addr, type, cpu, ent->pid);
599 if (ret == TRACE_TYPE_PARTIAL_LINE)
600 return TRACE_TYPE_PARTIAL_LINE;
604 if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME) {
605 ret = print_graph_abs_time(iter->ts, s);
607 return TRACE_TYPE_PARTIAL_LINE;
611 if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU) {
612 ret = print_graph_cpu(s, cpu);
613 if (ret == TRACE_TYPE_PARTIAL_LINE)
614 return TRACE_TYPE_PARTIAL_LINE;
618 if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC) {
619 ret = print_graph_proc(s, ent->pid);
620 if (ret == TRACE_TYPE_PARTIAL_LINE)
621 return TRACE_TYPE_PARTIAL_LINE;
623 ret = trace_seq_printf(s, " | ");
625 return TRACE_TYPE_PARTIAL_LINE;
631 static enum print_line_t
632 print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
633 struct trace_iterator *iter)
636 struct ftrace_graph_ent *call = &field->graph_ent;
637 struct ftrace_graph_ret_entry *leaf_ret;
639 if (print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func))
640 return TRACE_TYPE_PARTIAL_LINE;
642 leaf_ret = get_return_for_leaf(iter, field);
644 return print_graph_entry_leaf(iter, field, leaf_ret, s);
646 return print_graph_entry_nested(iter, field, s, cpu);
650 static enum print_line_t
651 print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
652 struct trace_entry *ent, struct trace_iterator *iter)
654 unsigned long long duration = trace->rettime - trace->calltime;
655 struct fgraph_data *data = iter->private;
656 pid_t pid = ent->pid;
663 int *depth = &(per_cpu_ptr(data, cpu)->depth);
666 * Comments display at + 1 to depth. This is the
667 * return from a function, we now want the comments
668 * to display at the same level of the bracket.
670 *depth = trace->depth - 1;
673 if (print_graph_prologue(iter, s, 0, 0))
674 return TRACE_TYPE_PARTIAL_LINE;
677 ret = print_graph_overhead(duration, s);
679 return TRACE_TYPE_PARTIAL_LINE;
682 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
683 ret = print_graph_duration(duration, s);
684 if (ret == TRACE_TYPE_PARTIAL_LINE)
685 return TRACE_TYPE_PARTIAL_LINE;
689 for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++) {
690 ret = trace_seq_printf(s, " ");
692 return TRACE_TYPE_PARTIAL_LINE;
695 ret = trace_seq_printf(s, "}\n");
697 return TRACE_TYPE_PARTIAL_LINE;
700 if (tracer_flags.val & TRACE_GRAPH_PRINT_OVERRUN) {
701 ret = trace_seq_printf(s, " (Overruns: %lu)\n",
704 return TRACE_TYPE_PARTIAL_LINE;
707 ret = print_graph_irq(iter, trace->func, TRACE_GRAPH_RET, cpu, pid);
708 if (ret == TRACE_TYPE_PARTIAL_LINE)
709 return TRACE_TYPE_PARTIAL_LINE;
711 return TRACE_TYPE_HANDLED;
714 static enum print_line_t
715 print_graph_comment(struct trace_seq *s, struct trace_entry *ent,
716 struct trace_iterator *iter)
718 unsigned long sym_flags = (trace_flags & TRACE_ITER_SYM_MASK);
719 struct fgraph_data *data = iter->private;
720 struct trace_event *event;
726 depth = per_cpu_ptr(data, iter->cpu)->depth;
728 if (print_graph_prologue(iter, s, 0, 0))
729 return TRACE_TYPE_PARTIAL_LINE;
732 ret = print_graph_overhead(-1, s);
734 return TRACE_TYPE_PARTIAL_LINE;
737 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION) {
738 ret = trace_seq_printf(s, " | ");
740 return TRACE_TYPE_PARTIAL_LINE;
745 for (i = 0; i < (depth + 1) * TRACE_GRAPH_INDENT; i++) {
746 ret = trace_seq_printf(s, " ");
748 return TRACE_TYPE_PARTIAL_LINE;
752 ret = trace_seq_printf(s, "/* ");
754 return TRACE_TYPE_PARTIAL_LINE;
756 switch (iter->ent->type) {
758 ret = trace_print_bprintk_msg_only(iter);
759 if (ret != TRACE_TYPE_HANDLED)
763 ret = trace_print_printk_msg_only(iter);
764 if (ret != TRACE_TYPE_HANDLED)
768 event = ftrace_find_event(ent->type);
770 return TRACE_TYPE_UNHANDLED;
772 ret = event->trace(iter, sym_flags);
773 if (ret != TRACE_TYPE_HANDLED)
777 /* Strip ending newline */
778 if (s->buffer[s->len - 1] == '\n') {
779 s->buffer[s->len - 1] = '\0';
783 ret = trace_seq_printf(s, " */\n");
785 return TRACE_TYPE_PARTIAL_LINE;
787 return TRACE_TYPE_HANDLED;
792 print_graph_function(struct trace_iterator *iter)
794 struct trace_entry *entry = iter->ent;
795 struct trace_seq *s = &iter->seq;
797 switch (entry->type) {
798 case TRACE_GRAPH_ENT: {
799 struct ftrace_graph_ent_entry *field;
800 trace_assign_type(field, entry);
801 return print_graph_entry(field, s, iter);
803 case TRACE_GRAPH_RET: {
804 struct ftrace_graph_ret_entry *field;
805 trace_assign_type(field, entry);
806 return print_graph_return(&field->ret, s, entry, iter);
809 return print_graph_comment(s, entry, iter);
812 return TRACE_TYPE_HANDLED;
815 static void print_graph_headers(struct seq_file *s)
819 if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
820 seq_printf(s, " TIME ");
821 if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
822 seq_printf(s, "CPU");
823 if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
824 seq_printf(s, " TASK/PID ");
825 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
826 seq_printf(s, " DURATION ");
827 seq_printf(s, " FUNCTION CALLS\n");
831 if (tracer_flags.val & TRACE_GRAPH_PRINT_ABS_TIME)
832 seq_printf(s, " | ");
833 if (tracer_flags.val & TRACE_GRAPH_PRINT_CPU)
835 if (tracer_flags.val & TRACE_GRAPH_PRINT_PROC)
836 seq_printf(s, " | | ");
837 if (tracer_flags.val & TRACE_GRAPH_PRINT_DURATION)
838 seq_printf(s, " | | ");
839 seq_printf(s, " | | | |\n");
842 static void graph_trace_open(struct trace_iterator *iter)
844 /* pid and depth on the last trace processed */
845 struct fgraph_data *data = alloc_percpu(struct fgraph_data);
849 pr_warning("function graph tracer: not enough memory\n");
851 for_each_possible_cpu(cpu) {
852 pid_t *pid = &(per_cpu_ptr(data, cpu)->last_pid);
853 int *depth = &(per_cpu_ptr(data, cpu)->depth);
858 iter->private = data;
861 static void graph_trace_close(struct trace_iterator *iter)
863 free_percpu(iter->private);
866 static struct tracer graph_trace __read_mostly = {
867 .name = "function_graph",
868 .open = graph_trace_open,
869 .close = graph_trace_close,
870 .wait_pipe = poll_wait_pipe,
871 .init = graph_trace_init,
872 .reset = graph_trace_reset,
873 .print_line = print_graph_function,
874 .print_header = print_graph_headers,
875 .flags = &tracer_flags,
876 #ifdef CONFIG_FTRACE_SELFTEST
877 .selftest = trace_selftest_startup_function_graph,
881 static __init int init_graph_trace(void)
883 return register_tracer(&graph_trace);
886 device_initcall(init_graph_trace);