'ftrace' essentially refers to everything included in the /tracing directory of the mounted debugfs filesystem (Yocto follows the standard convention and mounts it at /sys/kernel/debug). Here's a listing of all the files found in /sys/kernel/debug/tracing on a Yocto system.:
root@sugarbay:/sys/kernel/debug/tracing# ls README kprobe_events trace available_events kprobe_profile trace_clock available_filter_functions options trace_marker available_tracers per_cpu trace_options buffer_size_kb printk_formats trace_pipe buffer_total_size_kb saved_cmdlines tracing_cpumask current_tracer set_event tracing_enabled dyn_ftrace_total_info set_ftrace_filter tracing_on enabled_functions set_ftrace_notrace tracing_thresh events set_ftrace_pid free_buffer set_graph_function
The files listed above are used for various purposes - some relate directly to the tracers themselves, others are used to set tracing options, and yet others actually contain the tracing output when a tracer is in effect. Some of the functions can be guessed from their names, others need explanation; in any case, we'll cover some of the files we see here below but for an explanation of the others, please see the ftrace documentation.
We'll start by looking at some of the available built-in tracers.
cat'ing the 'available_tracers' file lists the set of available tracers:
root@sugarbay:/sys/kernel/debug/tracing# cat available_tracers blk function_graph function nop
The 'current_tracer' file contains the tracer currently in effect:
root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer nop
The above listing of current_tracer shows that the 'nop' tracer is in effect, which is just another way of saying that there's actually no tracer currently in effect.
echo'ing one of the available_tracers into current_tracer makes the specified tracer the current tracer:
root@sugarbay:/sys/kernel/debug/tracing# echo function > current_tracer root@sugarbay:/sys/kernel/debug/tracing# cat current_tracer function
The above sets the current tracer to be the 'function tracer'. This tracer traces every function call in the kernel and makes it available as the contents of the 'trace' file. Reading the 'trace' file lists the currently buffered function calls that have been traced by the function tracer:
root@sugarbay:/sys/kernel/debug/tracing# cat trace | less # tracer: function # # entries-in-buffer/entries-written: 310629/766471 #P:8 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | <idle>-0 [004] d..1 470.867169: ktime_get_real <-intel_idle <idle>-0 [004] d..1 470.867170: getnstimeofday <-ktime_get_real <idle>-0 [004] d..1 470.867171: ns_to_timeval <-intel_idle <idle>-0 [004] d..1 470.867171: ns_to_timespec <-ns_to_timeval <idle>-0 [004] d..1 470.867172: smp_apic_timer_interrupt <-apic_timer_interrupt <idle>-0 [004] d..1 470.867172: native_apic_mem_write <-smp_apic_timer_interrupt <idle>-0 [004] d..1 470.867172: irq_enter <-smp_apic_timer_interrupt <idle>-0 [004] d..1 470.867172: rcu_irq_enter <-irq_enter <idle>-0 [004] d..1 470.867173: rcu_idle_exit_common.isra.33 <-rcu_irq_enter <idle>-0 [004] d..1 470.867173: local_bh_disable <-irq_enter <idle>-0 [004] d..1 470.867173: add_preempt_count <-local_bh_disable <idle>-0 [004] d.s1 470.867174: tick_check_idle <-irq_enter <idle>-0 [004] d.s1 470.867174: tick_check_oneshot_broadcast <-tick_check_idle <idle>-0 [004] d.s1 470.867174: ktime_get <-tick_check_idle <idle>-0 [004] d.s1 470.867174: tick_nohz_stop_idle <-tick_check_idle <idle>-0 [004] d.s1 470.867175: update_ts_time_stats <-tick_nohz_stop_idle <idle>-0 [004] d.s1 470.867175: nr_iowait_cpu <-update_ts_time_stats <idle>-0 [004] d.s1 470.867175: tick_do_update_jiffies64 <-tick_check_idle <idle>-0 [004] d.s1 470.867175: _raw_spin_lock <-tick_do_update_jiffies64 <idle>-0 [004] d.s1 470.867176: add_preempt_count <-_raw_spin_lock <idle>-0 [004] d.s2 470.867176: do_timer <-tick_do_update_jiffies64 <idle>-0 [004] d.s2 470.867176: _raw_spin_lock <-do_timer <idle>-0 [004] d.s2 470.867176: add_preempt_count <-_raw_spin_lock <idle>-0 [004] d.s3 470.867177: ntp_tick_length <-do_timer <idle>-0 [004] d.s3 470.867177: _raw_spin_lock_irqsave <-ntp_tick_length . . .
Each line in the trace above shows what was happening in the kernel on a given cpu, to the level of detail of function calls. Each entry shows the function called, followed by its caller (after the arrow).
The function tracer gives you an extremely detailed idea of what the kernel was doing at the point in time the trace was taken, and is a great way to learn about how the kernel code works in a dynamic sense.
It is a little more difficult to follow the call chains than it needs to be - luckily there's a variant of the function tracer that displays the callchains explicitly, called the 'function_graph' tracer:
root@sugarbay:/sys/kernel/debug/tracing# echo function_graph > current_tracer root@sugarbay:/sys/kernel/debug/tracing# cat trace | less tracer: function_graph CPU DURATION FUNCTION CALLS | | | | | | | 7) 0.046 us | pick_next_task_fair(); 7) 0.043 us | pick_next_task_stop(); 7) 0.042 us | pick_next_task_rt(); 7) 0.032 us | pick_next_task_fair(); 7) 0.030 us | pick_next_task_idle(); 7) | _raw_spin_unlock_irq() { 7) 0.033 us | sub_preempt_count(); 7) 0.258 us | } 7) 0.032 us | sub_preempt_count(); 7) + 13.341 us | } /* __schedule */ 7) 0.095 us | } /* sub_preempt_count */ 7) | schedule() { 7) | __schedule() { 7) 0.060 us | add_preempt_count(); 7) 0.044 us | rcu_note_context_switch(); 7) | _raw_spin_lock_irq() { 7) 0.033 us | add_preempt_count(); 7) 0.247 us | } 7) | idle_balance() { 7) | _raw_spin_unlock() { 7) 0.031 us | sub_preempt_count(); 7) 0.246 us | } 7) | update_shares() { 7) 0.030 us | __rcu_read_lock(); 7) 0.029 us | __rcu_read_unlock(); 7) 0.484 us | } 7) 0.030 us | __rcu_read_lock(); 7) | load_balance() { 7) | find_busiest_group() { 7) 0.031 us | idle_cpu(); 7) 0.029 us | idle_cpu(); 7) 0.035 us | idle_cpu(); 7) 0.906 us | } 7) 1.141 us | } 7) 0.022 us | msecs_to_jiffies(); 7) | load_balance() { 7) | find_busiest_group() { 7) 0.031 us | idle_cpu(); . . . 4) 0.062 us | msecs_to_jiffies(); 4) 0.062 us | __rcu_read_unlock(); 4) | _raw_spin_lock() { 4) 0.073 us | add_preempt_count(); 4) 0.562 us | } 4) + 17.452 us | } 4) 0.108 us | put_prev_task_fair(); 4) 0.102 us | pick_next_task_fair(); 4) 0.084 us | pick_next_task_stop(); 4) 0.075 us | pick_next_task_rt(); 4) 0.062 us | pick_next_task_fair(); 4) 0.066 us | pick_next_task_idle(); ------------------------------------------ 4) kworker-74 => <idle>-0 ------------------------------------------ 4) | finish_task_switch() { 4) | _raw_spin_unlock_irq() { 4) 0.100 us | sub_preempt_count(); 4) 0.582 us | } 4) 1.105 us | } 4) 0.088 us | sub_preempt_count(); 4) ! 100.066 us | } . . . 3) | sys_ioctl() { 3) 0.083 us | fget_light(); 3) | security_file_ioctl() { 3) 0.066 us | cap_file_ioctl(); 3) 0.562 us | } 3) | do_vfs_ioctl() { 3) | drm_ioctl() { 3) 0.075 us | drm_ut_debug_printk(); 3) | i915_gem_pwrite_ioctl() { 3) | i915_mutex_lock_interruptible() { 3) 0.070 us | mutex_lock_interruptible(); 3) 0.570 us | } 3) | drm_gem_object_lookup() { 3) | _raw_spin_lock() { 3) 0.080 us | add_preempt_count(); 3) 0.620 us | } 3) | _raw_spin_unlock() { 3) 0.085 us | sub_preempt_count(); 3) 0.562 us | } 3) 2.149 us | } 3) 0.133 us | i915_gem_object_pin(); 3) | i915_gem_object_set_to_gtt_domain() { 3) 0.065 us | i915_gem_object_flush_gpu_write_domain(); 3) 0.065 us | i915_gem_object_wait_rendering(); 3) 0.062 us | i915_gem_object_flush_cpu_write_domain(); 3) 1.612 us | } 3) | i915_gem_object_put_fence() { 3) 0.097 us | i915_gem_object_flush_fence.constprop.36(); 3) 0.645 us | } 3) 0.070 us | add_preempt_count(); 3) 0.070 us | sub_preempt_count(); 3) 0.073 us | i915_gem_object_unpin(); 3) 0.068 us | mutex_unlock(); 3) 9.924 us | } 3) + 11.236 us | } 3) + 11.770 us | } 3) + 13.784 us | } 3) | sys_ioctl() {
As you can see, the function_graph display is much easier to follow. Also note that in addition to the function calls and associated braces, other events such as scheduler events are displayed in context. In fact, you can freely include any tracepoint available in the trace events subsystem described in the next section by simply enabling those events, and they'll appear in context in the function graph display. Quite a powerful tool for understanding kernel dynamics.
Also notice that there are various annotations on the left hand side of the display. For example if the total time it took for a given function to execute is above a certain threshold, and exclamation point or plus sign appears on the left hand side. Please see the ftrace documentation for details on all these fields.