Translate

Image of XSLT 2.0 and XPath 2.0 Programmer's Reference (Programmer to Programmer)
Image of Advanced Programming in the UNIX Environment, Second Edition (Addison-Wesley Professional Computing Series)
Image of Android Wireless Application Development
Image of Linux Kernel Development (3rd Edition)

Kernel Tracing Using Ftrace

Ftrace is one of those useful “kernel debugging” tools which you turn to when other debugging tools fail to reveal the underlying problem. Ftrace is a Linux kernel internals tracing tool that was first included in the 2.6.27 kernel in 2008. The main developer was (and still is) Steven Rostedt who is currently a Red Hat employee with responsiblity for the real-time patches in the Linux kernel.

The name ftrace comes from the term function tracer, which was the original purpose of the tool, but nowadays it can do a lot more than just trace function calls. Over the years, various additional tracers have been added to look at things like context switches, how long interrupts are disabled, how long it takes for high-priority tasks to run after they have been woken up, and more. Ftrace includes a plugable framework that allows new tracers to be added relatively easily. Currently over 700 events throughout the kernel can be traced.

For my examples in this blog post, I am using ftrace on Fedora 20. Linux kernels must be built with tracing enabled. As you can see, Fedora 20 was built with tracing enabled.

# grep TRACER /boot/config-3.14.2-200.fc20.x86_64
# CONFIG_ATH5K_TRACER is not set
CONFIG_NOP_TRACER=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_TRACER_MAX_TRACE=y
CONFIG_CONTEXT_SWITCH_TRACER=y
CONFIG_GENERIC_TRACER=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
# CONFIG_IRQSOFF_TRACER is not set
CONFIG_SCHED_TRACER=y
CONFIG_TRACER_SNAPSHOT=y
# CONFIG_TRACER_SNAPSHOT_PER_CPU_SWAP is not set
CONFIG_STACK_TRACER=y


For some unknown reason, however, not all tracers were enabled. Red Hat Enterprise Linux 6.4 has the same config settings.. By way of contrast, Red Hat MRG provides the following tracers: events wakeup preemptirqsoff preemptoff irqsoff ftrace sched_switch none, once the trace variant of the MRG Realtime kernel is installed and in use.

The main ftrace documentation is available in the Linux kernel source at …/root/Documentation/trace/ftrace.txt. It was last updated for the 3.10 kernel. In the same directory, there are a number of other interesting documents including ftrace-design.txt by Mike Frysinger which focuses on architecture implementation details. The actual tracemoint implementation mechanism is detailed by Mathieu Desnoyers in tracepoints.txt.

A tracepoint placed in code provides a hook to call a function (probe) that you can provide at runtime. A tracepoint can be “on” (a probe is connected to it) or “off” (no probe is attached). When a tracepoint is “off” it has no effect, except for adding a tiny time penalty (checking a condition for a branch) and space penalty (adding a few bytes for the function call at the end of the instrumented function and adds a data structure in a separate section). When a tracepoint is “on”, the function you provide is called each time the tracepoint is executed, in the execution context of the caller. When the function provided ends its execution, it returns to the caller (continuing from the tracepoint site).

The default location for ftrace is /sys/kerenel/debug. You may have to mount the debug filesystem.

# mount -t debugfs nodev /sys/kernel/debug
# cat /sys/kernel/debug/tracing/available_tracers
blk function_graph wakeup_dl wakeup_rt wakeup function nop

# cd /sys/kernel/debug
# ls
acpi         cleancache  dynamic_debug  hid        mce               regmap          tracing         xen
bdi          clk         extfrag        ieee80211  pinctrl           sched_features  usb
bluetooth    dma_buf     frontswap      kprobes    pkg_temp_thermal  sleep_time      wakeup_sources
boot_params  dri         gpio           lpfc       pstate_snb        suspend_stats   x86

# cd tracing
# ls
available_events            instances          set_ftrace_notrace  trace_options
available_filter_functions  kprobe_events      set_ftrace_pid      trace_pipe
available_tracers           kprobe_profile     set_graph_function  trace_stat
buffer_size_kb              max_graph_depth    set_graph_notrace   tracing_cpumask
buffer_total_size_kb        options            snapshot            tracing_max_latency
current_tracer              per_cpu            stack_max_size      tracing_on
dyn_ftrace_total_info       printk_formats     stack_trace         tracing_thresh
enabled_functions           README             stack_trace_filter  uprobe_events
events                      saved_cmdlines     trace               uprobe_profile
free_buffer                 set_event          trace_clock
function_profile_enabled    set_ftrace_filter  trace_marker

The ftrace framework is one of the many improvements to come out of the Linux kernel realtime effort. Unlike SystemTap, it does not attempt to be a comprehensive, scriptable facility. There is a set of virtual files in a debugfs directory which can be used to enable specific tracers and see the results. The function call tracer after which ftrace is named simply outputs each kernel function called as it happens. Other tracers can look at wakeup latency, events, enabling and disabling interrupts, preemption, task switches, and more.

Kernel function call tracing (the original purpose of ftrace) is enabled as follows:

# echo function > /sys/kernel/debug/tracing/current_tracer
# echo 1 > /sys/kernel/debug/tracing/tracing_on


Note that older ftrace documentation examples refer to tracing_enabled rather than tracing_on

Events which are available for tracing are listed in /sys/kernel/debug/tracing/available_events. To enable a particular event, such as sched_wakeup, simply echo it to /sys/kernel/debug/tracing/set_event. For example:

# echo sched_wakeup >> /sys/kernel/debug/tracing/set_event


The append (“>>”) operator is required to avoid overwriting existing events.

To disable an event, echo the event name to the set_event file prefixed with an exclamation point:

# echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event

To disable all events, echo an empty line to the set_event file:

# echo > /sys/kernel/debug/tracing/set_event

To enable all events, echo ‘*:*’ or ‘*:’ to the set_event file:

# echo *:* > /sys/kernel/debug/tracing/set_event

Events are organized into subsystems, such as ext4, irq, or sched, and a full event name looks like this: <subsystem>:<event>. The subsystem name is optional, but it is displayed in the available_events file. All of the events in a subsystem can be specified via the syntax <subsystem>:*. For example, to enable all irq events:

# echo 'irq:*' > /sys/kernel/debug/tracing/set_event


You can drill down and enable or disable individual events under the events directory:

# pwd
/sys/kernel/debug/tracing/events
# ls
block       gpio          kmem     pagemap       scsi      vmscan
btrfs       hda           kvm      power         signal    vsyscall
cfg80211    hda_intel     kvmmmu   printk        skb       workqueue
compaction  header_event  mce      random        sock      writeback
drm         header_page   migrate  ras           sunrpc    xen
enable      i915          module   raw_syscalls  swiotlb   xhci-hcd
exceptions  iommu         napi     rcu           syscalls
ext4        irq           net      regmap        task
filemap     irq_vectors   nmi      rpm           timer
ftrace      jbd2          oom      sched         udp

# cd sched
# ls
enable                  sched_process_exit  sched_stat_wait
filter                  sched_process_fork  sched_stick_numa
sched_kthread_stop      sched_process_free  sched_swap_numa
sched_kthread_stop_ret  sched_process_wait  sched_switch
sched_migrate_task      sched_stat_blocked  sched_wait_task
sched_move_numa         sched_stat_iowait   sched_wakeup
sched_pi_setprio        sched_stat_runtime  sched_wakeup_new
sched_process_exec      sched_stat_sleep

# cd sched_wakeup
# ls -ltotal 0
-rw-r--r--. 1 root root 0 May  8 11:23 enable
-rw-r--r--. 1 root root 0 May  8 11:23 filter
-r--r--r--. 1 root root 0 May  8 11:23 format
-r--r--r--. 1 root root 0 May  8 11:23 id
-rw-r--r--. 1 root root 0 May  8 11:23 trigger


For example to enable the sched_wakeup event:

# echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable


To disable the sched_wakeup event:

# echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable


There is lots more to events than I have room to detail in this blog. For example, you can control the output format of events, filter specific events, and invoke specific scriptable actions when events are triggered. Read the ftrace documentation for all the details.

Ftrace uses a custom kernel ring buffer to store event information. The ring buffer can be used in either an overwrite mode or in producer/consumer mode. Producer/consumer mode is where if the producer were to fill up the ring buffer before the consumer could free up anything, the producer will stop writing to the buffer. This will cause the most recent events to be lost. Overwrite mode is where if the producer were to fill up the buffer before the consumer could free up anything, the producer will
overwrite the older data. This will cause loss of the oldest events. The size of the ring buffer is configurable.

# pwd
/sys/kernel/debug/tracing
# cat buffer_total_size_kb
28 (expanded: 5632)
]# cat buffer_size_kb
7 (expanded: 1408)


A trace marker enables some coordination between what is happening in user space and inside the kernel by providing a way to write into the ftrace kernel ring buffer from user space. This marker will then appear in the trace output to give a location where a specific event occurred. Here is an example of setting a trace marker:

# echo "FINN" > /sys/kernel/debug/tracing/trace_marker

One of the annoying things about ftrace for most first time users of the tool is that it does not provide an easy mechanism to invoke an executable and just trace that executable. Here is a simple shell script which provides that functionality:

#!/bin/bash

DEBUGFS=`grep debugfs /proc/mounts | awk '{ print $2; }'`

echo $$ > $DEBUGFS/tracing/set_ftrace_pid
echo function > $DEBUGFS/tracing/current_tracer
echo 1 > $DEBUGFS/tracing/tracing_on
exec $*
echo 0 > $DEBUGFS/tracing/tracing_on

The function call tracer (function) traces entry into all kernel functions.

Here is what is recorded in /sys/kernel/debug/tracing/trace when the above script is used to invoke ls ( ./script ls):

# tracer: function
#
# entries-in-buffer/entries-written: 364/27769   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
              ls-5080  [003] .... 42387.930906: SyS_rt_sigaction < -system_call_fastpath
              ls-5080  [003] .... 42387.930907: do_sigaction <-SyS_rt_sigaction
              ls-5080  [003] .... 42387.930907: _raw_spin_lock_irq <-do_sigaction
              ls-5080  [003] d... 42387.930907: rm_from_queue_full <-do_sigaction
              ls-5080  [003] d... 42387.930907: rm_from_queue_full <-do_sigaction
              ls-5080  [003] .... 42387.930907: __audit_syscall_exit <-sysret_audit
              ls-5080  [003] .... 42387.930907: path_put <-__audit_syscall_exit
              ls-5080  [003] .... 42387.930907: dput <-path_put
              ls-5080  [003] .... 42387.930907: mntput <-path_put
              ls-5080  [003] .... 42387.930907: unroll_tree_refs <-__audit_syscall_exit
              ls-5080  [003] .... 42387.930907: kfree <-__audit_syscall_exit
              ls-5080  [003] .... 42387.930908: __audit_syscall_entry <-auditsys
              ls-5080  [003] .... 42387.930908: current_kernel_time <-__audit_syscall_entry
              ls-5080  [003] .... 42387.930908: SyS_execve <-stub_execve
              ls-5080  [003] .... 42387.930908: getname <-SyS_execve
              ls-5080  [003] .... 42387.930908: getname_flags <-getname
              ls-5080  [003] .... 42387.930908: kmem_cache_alloc <-getname_flags
              ls-5080  [003] .... 42387.930909: _cond_resched <-kmem_cache_alloc
              ls-5080  [003] .... 42387.930909: do_execve_common.isra.24 <-SyS_execve
              ls-5080  [003] .... 42387.930909: unshare_files <-do_execve_common.isra.24
              ls-5080  [003] .... 42387.930909: unshare_fd <-unshare_files
              ls-5080  [003] .... 42387.930909: kmem_cache_alloc_trace <-do_execve_common.isra.24
              ls-5080  [003] .... 42387.930909: _cond_resched <-kmem_cache_alloc_trace
              ls-5080  [003] .... 42387.930909: __slab_alloc <-kmem_cache_alloc_trace
              ls-5080  [003] .... 42387.930910: prepare_bprm_creds <-do_execve_common.isra.24
              ls-5080  [003] .... 42387.930910: mutex_lock_interruptible <-prepare_bprm_creds
              ls-5080  [003] .... 42387.930910: _cond_resched <-mutex_lock_interruptible
              ls-5080  [003] .... 42387.930910: prepare_exec_creds <-prepare_bprm_creds
              ls-5080  [003] .... 42387.930910: prepare_creds <-prepare_exec_creds
              ls-5080  [003] .... 42387.930910: kmem_cache_alloc <-prepare_creds
              ls-5080  [003] .... 42387.930910: _cond_resched <-kmem_cache_alloc
              ls-5080  [003] .... 42387.930911: security_prepare_creds <-prepare_creds
              ls-5080  [003] .... 42387.930911: selinux_cred_prepare <-security_prepare_creds
              ls-5080  [003] .... 42387.930911: kmemdup <-selinux_cred_prepare
              ls-5080  [003] .... 42387.930911: __kmalloc_track_caller <-kmemdup
              ls-5080  [003] .... 42387.930911: kmalloc_slab <-__kmalloc_track_caller
              ls-5080  [003] .... 42387.930911: _cond_resched <-__kmalloc_track_caller
              ls-5080  [003] .... 42387.930911: key_put <-prepare_exec_creds
              ls-5080  [003] .... 42387.930911: key_put <-prepare_exec_creds
              ls-5080  [003] .... 42387.930911: _raw_spin_lock <-do_execve_common.isra.24
              ls-5080  [003] .... 42387.930911: do_open_exec <-do_execve_common.isra.24
              ls-5080  [003] .... 42387.930912: do_filp_open <-do_open_exec
              ls-5080  [003] .... 42387.930912: path_openat <-do_filp_open
              ls-5080  [003] .... 42387.930912: get_empty_filp <-path_openat
              ls-5080  [003] .... 42387.930912: kmem_cache_alloc <-get_empty_filp
              ls-5080  [003] .... 42387.930912: _cond_resched <-kmem_cache_alloc
              ls-5080  [003] .... 42387.930912: __slab_alloc <-kmem_cache_alloc
              ls-5080  [003] .... 42387.930912: security_file_alloc <-get_empty_filp
              ls-5080  [003] .... 42387.930912: selinux_file_alloc_security <-security_file_alloc
              ls-5080  [003] .... 42387.930912: kmem_cache_alloc_trace <-selinux_file_alloc_security
              ls-5080  [003] .... 42387.930913: _cond_resched <-kmem_cache_alloc_trace
              ls-5080  [003] .... 42387.930913: __mutex_init <-get_empty_filp
              ls-5080  [003] .... 42387.930913: path_init <-path_openat
              ls-5080  [003] .... 42387.930913: link_path_walk <-path_openat
              ls-5080  [003] .... 42387.930913: inode_permission <-link_path_walk
              ls-5080  [003] .... 42387.930913: __inode_permission <-inode_permission
              ls-5080  [003] .... 42387.930913: btrfs_permission <-__inode_permission
              ls-5080  [003] .... 42387.930913: generic_permission <-btrfs_permission
              ls-5080  [003] .... 42387.930913: security_inode_permission <-__inode_permission
              ls-5080  [003] .... 42387.930913: selinux_inode_permission <-security_inode_permission
              ls-5080  [003] .... 42387.930913: lookup_fast <-link_path_walk
              ls-5080  [003] .... 42387.930914: __d_lookup_rcu <-lookup_fast
              ls-5080  [003] .... 42387.930914: unlazy_walk <-link_path_walk
              ls-5080  [003] .... 42387.930914: legitimize_mnt <-unlazy_walk
              ls-5080  [003] .... 42387.930914: _raw_spin_lock <-unlazy_walk
              ls-5080  [003] .... 42387.930914: path_get <-unlazy_walk
              ls-5080  [003] .... 42387.930914: mntget <-path_get
              ls-5080  [003] .... 42387.930914: mntget <-link_path_walk
              ls-5080  [003] .... 42387.930914: _cond_resched <-link_path_walk
              ls-5080  [003] .... 42387.930914: touch_atime <-link_path_walk
              ls-5080  [003] .... 42387.930914: current_fs_time <-touch_atime
              ls-5080  [003] .... 42387.930914: current_kernel_time <-current_fs_time
              ls-5080  [003] .... 42387.930914: security_inode_follow_link <-link_path_walk
              ls-5080  [003] .... 42387.930915: selinux_inode_follow_link <-security_inode_follow_link
              ls-5080  [003] .... 42387.930915: inode_has_perm.isra.32 <-selinux_inode_follow_link
              ls-5080  [003] .... 42387.930915: avc_has_perm <-inode_has_perm.isra.32
              ls-5080  [003] .... 42387.930915: page_follow_link_light <-link_path_walk
              ls-5080  [003] .... 42387.930915: page_getlink.isra.28.constprop.37 <-page_follow_link_light
              ls-5080  [003] .... 42387.930915: read_cache_page <-page_getlink.isra.28.constprop.37
              ls-5080  [003] .... 42387.930915: do_read_cache_page <-read_cache_page
              ls-5080  [003] .... 42387.930915: find_get_page <-do_read_cache_page
              ls-5080  [003] .... 42387.930915: mark_page_accessed <-do_read_cache_page
              ls-5080  [003] .... 42387.930915: wait_on_page_read <-read_cache_page
              ls-5080  [003] .... 42387.930915: _cond_resched <-page_getlink.isra.28.constprop.37
              ls-5080  [003] .... 42387.930915: link_path_walk <-link_path_walk
              ls-5080  [003] .... 42387.930915: inode_permission <-link_path_walk
              ls-5080  [003] .... 42387.930916: __inode_permission <-inode_permission
              ls-5080  [003] .... 42387.930916: btrfs_permission <-__inode_permission
              ls-5080  [003] .... 42387.930916: generic_permission <-btrfs_permission
              ls-5080  [003] .... 42387.930916: security_inode_permission <-__inode_permission
              ls-5080  [003] .... 42387.930916: selinux_inode_permission <-security_inode_permission
              ls-5080  [003] .... 42387.930916: lookup_fast <-link_path_walk
              ls-5080  [003] .... 42387.930916: __d_lookup <-lookup_fast
              ls-5080  [003] .... 42387.930916: _raw_spin_lock <-__d_lookup
              ls-5080  [003] .... 42387.930916: follow_managed <-lookup_fast
              ls-5080  [003] .... 42387.930916: dput <-link_path_walk
              ls-5080  [003] .... 42387.930917: inode_permission <-link_path_walk
              ls-5080  [003] .... 42387.930917: __inode_permission <-inode_permission
              ls-5080  [003] .... 42387.930917: btrfs_permission <-__inode_permission
              ls-5080  [003] .... 42387.930917: generic_permission <-btrfs_permission
              ls-5080  [003] .... 42387.930917: security_inode_permission <-__inode_permission
              ls-5080  [003] .... 42387.930917: selinux_inode_permission <-security_inode_permission
              ls-5080  [003] .... 42387.930917: lookup_fast <-link_path_walk
              ls-5080  [003] .... 42387.930917: __d_lookup <-lookup_fast
              ls-5080  [003] .... 42387.930917: _raw_spin_lock <-__d_lookup
              ls-5080  [003] .... 42387.930917: follow_managed <-lookup_fast
              ls-5080  [003] .... 42387.930917: dput <-link_path_walk
              ls-5080  [003] .... 42387.930917: page_put_link <-link_path_walk
              ls-5080  [003] .... 42387.930917: put_page <-page_put_link
              ls-5080  [003] .... 42387.930918: dput <-link_path_walk
              ls-5080  [003] .... 42387.930918: _raw_spin_lock <-lockref_put_or_lock
              ls-5080  [003] .... 42387.930918: btrfs_dentry_delete <-dput
              ls-5080  [003] .... 42387.930918: mntput <-link_path_walk
              ls-5080  [003] .... 42387.930918: mntput_no_expire <-mntput
              ls-5080  [003] .... 42387.930918: inode_permission <-link_path_walk
              ls-5080  [003] .... 42387.930918: __inode_permission <-inode_permission
              ls-5080  [003] .... 42387.930918: btrfs_permission <-__inode_permission
              ls-5080  [003] .... 42387.930918: generic_permission <-btrfs_permission
              ls-5080  [003] .... 42387.930918: security_inode_permission <-__inode_permission
              ls-5080  [003] .... 42387.930918: selinux_inode_permission <-security_inode_permission
              ls-5080  [003] .... 42387.930918: do_last <-path_openat
              ls-5080  [003] .... 42387.930919: lookup_fast <-do_last
              ls-5080  [003] .... 42387.930919: __d_lookup <-lookup_fast
              ls-5080  [003] .... 42387.930919: _raw_spin_lock <-__d_lookup
              ls-5080  [003] .... 42387.930919: follow_managed <-lookup_fast
              ls-5080  [003] .... 42387.930919: mntget <-do_last
              ls-5080  [003] .... 42387.930919: complete_walk <-do_last
              ls-5080  [003] .... 42387.930919: may_open <-do_last
              ls-5080  [003] .... 42387.930919: inode_permission <-may_open
              ls-5080  [003] .... 42387.930919: __inode_permission <-inode_permission
              ls-5080  [003] .... 42387.930919: btrfs_permission <-__inode_permission
              ls-5080  [003] .... 42387.930920: generic_permission <-btrfs_permission
              ls-5080  [003] .... 42387.930920: security_inode_permission <-__inode_permission
              ls-5080  [003] .... 42387.930920: selinux_inode_permission <-security_inode_permission
              ls-5080  [003] .... 42387.930920: finish_open <-do_last
              ls-5080  [003] .... 42387.930920: do_dentry_open <-finish_open
              ls-5080  [003] .... 42387.930920: path_get <-do_dentry_open
              ls-5080  [003] .... 42387.930920: mntget <-path_get
              ls-5080  [003] .... 42387.930920: try_module_get <-do_dentry_open
              ls-5080  [003] .... 42387.930920: security_file_open <-do_dentry_open
              ls-5080  [003] .... 42387.930920: selinux_file_open <-security_file_open
              ls-5080  [003] .... 42387.930921: avc_policy_seqno <-selinux_file_open
              ls-5080  [003] .... 42387.930921: inode_has_perm.isra.32 <-selinux_file_open
              ls-5080  [003] .... 42387.930921: avc_has_perm <-inode_has_perm.isra.32
              ls-5080  [003] .... 42387.930921: __fsnotify_parent <-security_file_open
              ls-5080  [003] .... 42387.930921: fsnotify <-security_file_open
              ls-5080  [003] .... 42387.930921: generic_file_open <-do_dentry_open
              ls-5080  [003] .... 42387.930921: file_ra_state_init <-do_dentry_open
              ls-5080  [003] .... 42387.930921: open_check_o_direct <-do_last
              ls-5080  [003] .... 42387.930922: dput <-do_last
              ls-5080  [003] .... 42387.930922: mntput <-do_last
              ls-5080  [003] .... 42387.930922: mntput_no_expire <-mntput
              ls-5080  [003] .... 42387.930922: terminate_walk <-do_last
              ls-5080  [003] .... 42387.930922: dput <-terminate_walk
              ls-5080  [003] .... 42387.930922: mntput <-terminate_walk
              ls-5080  [003] .... 42387.930922: mntput_no_expire <-mntput
              ls-5080  [003] .... 42387.930922: dput <-path_openat
              ls-5080  [003] .... 42387.930922: mntput <-path_openat
              ls-5080  [003] .... 42387.930922: mntput_no_expire <-mntput
              ls-5080  [003] .... 42387.930922: __fsnotify_parent <-do_open_exec
              ls-5080  [003] .... 42387.930922: fsnotify <-do_open_exec
              ls-5080  [003] .... 42387.930923: sched_exec <-do_execve_common.isra.24
              ls-5080  [003] .... 42387.930923: _raw_spin_lock_irqsave <-sched_exec
              ls-5080  [003] d... 42387.930923: select_task_rq_fair <-sched_exec
              ls-5080  [003] d... 42387.930923: source_load <-select_task_rq_fair
              ls-5080  [003] d... 42387.930923: target_load <-select_task_rq_fair
              ls-5080  [003] d... 42387.930923: target_load <-select_task_rq_fair
              ls-5080  [003] d... 42387.930924: target_load <-select_task_rq_fair
              ls-5080  [003] d... 42387.930924: _raw_spin_unlock_irqrestore <-sched_exec
              ls-5080  [003] .... 42387.930924: stop_one_cpu <-sched_exec
              ls-5080  [003] .... 42387.930924: cpu_stop_init_done <-stop_one_cpu
              ls-5080  [003] .... 42387.930924: __init_waitqueue_head <-cpu_stop_init_done
              ls-5080  [003] .... 42387.930924: cpu_stop_queue_work <-stop_one_cpu
              ls-5080  [003] .... 42387.930924: _raw_spin_lock_irqsave <-cpu_stop_queue_work
              ls-5080  [003] d... 42387.930924: wake_up_process <-cpu_stop_queue_work
              ls-5080  [003] d... 42387.930925: try_to_wake_up <-wake_up_process
              ls-5080  [003] d... 42387.930925: _raw_spin_lock_irqsave <-try_to_wake_up
              ls-5080  [003] d... 42387.930925: select_task_rq_stop <-try_to_wake_up
              ls-5080  [003] d... 42387.930925: _raw_spin_lock <-try_to_wake_up
              ls-5080  [003] d... 42387.930925: ttwu_do_activate.constprop.95 <-try_to_wake_up
              ls-5080  [003] d... 42387.930925: activate_task <-ttwu_do_activate.constprop.95
              ls-5080  [003] d... 42387.930925: enqueue_task <-activate_task
              ls-5080  [003] d... 42387.930925: update_rq_clock.part.83 <-enqueue_task
              ls-5080  [003] d... 42387.930925: enqueue_task_stop <-enqueue_task
              ls-5080  [003] d... 42387.930926: ttwu_do_wakeup <-ttwu_do_activate.constprop.95
              ls-5080  [003] d... 42387.930926: check_preempt_curr <-ttwu_do_wakeup
              ls-5080  [003] d... 42387.930926: resched_task <-check_preempt_curr
              ls-5080  [003] dN.. 42387.930926: _raw_spin_unlock_irqrestore <-try_to_wake_up
              ls-5080  [003] dN.. 42387.930926: _raw_spin_unlock_irqrestore <-cpu_stop_queue_work
              ls-5080  [003] .N.. 42387.930926: wait_for_completion <-stop_one_cpu
              ls-5080  [003] .N.. 42387.930926: _cond_resched <-wait_for_completion
              ls-5080  [003] .N.. 42387.930927: __schedule <-_cond_resched
              ls-5080  [003] .N.. 42387.930927: rcu_note_context_switch <-__schedule
              ls-5080  [003] .N.. 42387.930927: _raw_spin_lock_irq <-__schedule
              ls-5080  [003] dN.. 42387.930927: put_prev_task_fair <-__schedule
              ls-5080  [003] dN.. 42387.930927: update_curr <-put_prev_task_fair
              ls-5080  [003] dN.. 42387.930927: update_min_vruntime <-update_curr
              ls-5080  [003] dN.. 42387.930927: cpuacct_charge <-update_curr
              ls-5080  [003] dN.. 42387.930927: __enqueue_entity <-put_prev_task_fair
              ls-5080  [003] dN.. 42387.930928: update_curr <-put_prev_task_fair
              ls-5080  [003] dN.. 42387.930928: update_min_vruntime <-update_curr
              ls-5080  [003] dN.. 42387.930928: __enqueue_entity <-put_prev_task_fair
              ls-5080  [003] dN.. 42387.930928: pick_next_task_stop <-__schedule
##### CPU 0 buffer started ####
              ls-5080  [000] d... 42387.933572: update_min_vruntime <-update_curr
              ls-5080  [000] d... 42387.933572: cpuacct_charge <-update_curr
              ls-5080  [000] d... 42387.933573: update_cfs_rq_blocked_load <-dequeue_entity
              ls-5080  [000] d... 42387.933573: clear_buddies <-dequeue_entity
              ls-5080  [000] d... 42387.933573: account_entity_dequeue <-dequeue_entity
              ls-5080  [000] d... 42387.933573: update_min_vruntime <-dequeue_entity
              ls-5080  [000] d... 42387.933573: update_cfs_shares <-dequeue_entity
              ls-5080  [000] d... 42387.933573: update_curr <-update_cfs_shares
              ls-5080  [000] d... 42387.933573: update_min_vruntime <-update_curr
              ls-5080  [000] d... 42387.933573: account_entity_dequeue <-update_cfs_shares
              ls-5080  [000] d... 42387.933573: account_entity_enqueue <-update_cfs_shares
              ls-5080  [000] d... 42387.933573: dequeue_entity <-dequeue_task_fair
              ls-5080  [000] d... 42387.933573: update_curr <-dequeue_entity
              ls-5080  [000] d... 42387.933574: update_cfs_rq_blocked_load <-dequeue_entity
              ls-5080  [000] d... 42387.933574: clear_buddies <-dequeue_entity
              ls-5080  [000] d... 42387.933574: account_entity_dequeue <-dequeue_entity
              ls-5080  [000] d... 42387.933574: update_min_vruntime <-dequeue_entity
              ls-5080  [000] d... 42387.933574: update_cfs_shares <-dequeue_entity
              ls-5080  [000] d... 42387.933574: hrtick_update <-dequeue_task_fair
              ls-5080  [000] d... 42387.933574: put_prev_task_fair <-sched_move_task
              ls-5080  [000] d... 42387.933574: task_wants_autogroup <-sched_move_task
              ls-5080  [000] d... 42387.933575: task_move_group_fair <-sched_move_task
              ls-5080  [000] d... 42387.933575: set_curr_task_fair <-sched_move_task
              ls-5080  [000] d... 42387.933575: enqueue_task <-sched_move_task
              ls-5080  [000] d... 42387.933575: update_rq_clock.part.83 <-enqueue_task
              ls-5080  [000] d... 42387.933575: enqueue_task_fair <-enqueue_task
              ls-5080  [000] d... 42387.933575: enqueue_entity <-enqueue_task_fair
              ls-5080  [000] d... 42387.933575: update_curr <-enqueue_entity
              ls-5080  [000] d... 42387.933575: update_min_vruntime <-update_curr
              ls-5080  [000] d... 42387.933575: cpuacct_charge <-update_curr
              ls-5080  [000] d... 42387.933575: update_cfs_rq_blocked_load <-enqueue_entity
              ls-5080  [000] d... 42387.933575: account_entity_enqueue <-enqueue_entity
              ls-5080  [000] d... 42387.933575: update_cfs_shares <-enqueue_entity
              ls-5080  [000] d... 42387.933576: hrtick_update <-enqueue_task_fair
              ls-5080  [000] d... 42387.933576: _raw_spin_unlock_irqrestore <-sched_move_task
              ls-5080  [000] .... 42387.933576: smp_call_function_single <-task_function_call
              ls-5080  [000] .... 42387.933577: __put_css_set <-cgroup_exit
              ls-5080  [000] .... 42387.933577: module_put <-do_exit
              ls-5080  [000] .... 42387.933577: proc_exit_connector <-do_exit
              ls-5080  [000] .... 42387.933578: flush_ptrace_hw_breakpoint <-do_exit
              ls-5080  [000] .... 42387.933578: unregister_hw_breakpoint <-flush_ptrace_hw_breakpoint
              ls-5080  [000] .... 42387.933578: unregister_hw_breakpoint <-flush_ptrace_hw_breakpoint
              ls-5080  [000] .... 42387.933578: unregister_hw_breakpoint <-flush_ptrace_hw_breakpoint
              ls-5080  [000] .... 42387.933578: unregister_hw_breakpoint <-flush_ptrace_hw_breakpoint
              ls-5080  [000] .... 42387.933578: _raw_write_lock_irq <-do_exit
              ls-5080  [000] d... 42387.933578: exit_ptrace <-do_exit
              ls-5080  [000] d... 42387.933578: task_active_pid_ns <-do_exit
              ls-5080  [000] .... 42387.933578: _raw_write_lock_irq <-do_exit
              ls-5080  [000] d... 42387.933578: kill_orphaned_pgrp <-do_exit
              ls-5080  [000] d... 42387.933579: will_become_orphaned_pgrp <-kill_orphaned_pgrp
              ls-5080  [000] d... 42387.933579: do_notify_parent <-do_exit
              ls-5080  [000] d... 42387.933579: task_active_pid_ns <-do_notify_parent
              ls-5080  [000] d... 42387.933579: __task_pid_nr_ns <-do_notify_parent
              ls-5080  [000] d... 42387.933579: from_kuid_munged <-do_notify_parent
              ls-5080  [000] d... 42387.933579: map_id_up <-from_kuid_munged
              ls-5080  [000] d... 42387.933580: jiffies_to_clock_t <-do_notify_parent
              ls-5080  [000] d... 42387.933580: jiffies_to_clock_t <-do_notify_parent
              ls-5080  [000] d... 42387.933580: _raw_spin_lock_irqsave <-do_notify_parent
              ls-5080  [000] d... 42387.933580: send_signal <-do_notify_parent
              ls-5080  [000] d... 42387.933580: __send_signal <-send_signal
              ls-5080  [000] d... 42387.933580: prepare_signal <-__send_signal
              ls-5080  [000] d... 42387.933581: __sigqueue_alloc <-__send_signal
              ls-5080  [000] d... 42387.933581: kmem_cache_alloc <-__sigqueue_alloc
              ls-5080  [000] d... 42387.933581: complete_signal <-__send_signal
              ls-5080  [000] d... 42387.933581: __wake_up_parent <-do_notify_parent
              ls-5080  [000] d... 42387.933581: __wake_up_sync_key <-__wake_up_parent
              ls-5080  [000] d... 42387.933581: _raw_spin_lock_irqsave <-__wake_up_sync_key
              ls-5080  [000] d... 42387.933581: __wake_up_common <-__wake_up_sync_key
              ls-5080  [000] d... 42387.933582: child_wait_callback <-__wake_up_common
              ls-5080  [000] d... 42387.933582: default_wake_function <-child_wait_callback
              ls-5080  [000] d... 42387.933582: try_to_wake_up <-default_wake_function
              ls-5080  [000] d... 42387.933582: _raw_spin_lock_irqsave <-try_to_wake_up
              ls-5080  [000] d... 42387.933582: task_waking_fair <-try_to_wake_up
              ls-5080  [000] d... 42387.933583: select_task_rq_fair <-try_to_wake_up
              ls-5080  [000] d... 42387.933583: source_load <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: target_load <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: effective_load.isra.40 <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: effective_load.isra.40 <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: idle_cpu <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: cpus_share_cache <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: idle_cpu <-select_task_rq_fair
              ls-5080  [000] d... 42387.933583: _raw_spin_lock <-try_to_wake_up
              ls-5080  [000] d... 42387.933584: ttwu_do_activate.constprop.95 <-try_to_wake_up
              ls-5080  [000] d... 42387.933584: activate_task <-ttwu_do_activate.constprop.95
              ls-5080  [000] d... 42387.933584: enqueue_task <-activate_task
              ls-5080  [000] d... 42387.933584: update_rq_clock.part.83 <-enqueue_task
              ls-5080  [000] d... 42387.933584: enqueue_task_fair <-enqueue_task
              ls-5080  [000] d... 42387.933584: enqueue_entity <-enqueue_task_fair
              ls-5080  [000] d... 42387.933584: update_curr <-enqueue_entity
              ls-5080  [000] d... 42387.933585: __compute_runnable_contrib.part.58 <-enqueue_entity
              ls-5080  [000] d... 42387.933585: update_cfs_rq_blocked_load <-enqueue_entity
              ls-5080  [000] d... 42387.933585: account_entity_enqueue <-enqueue_entity
              ls-5080  [000] d... 42387.933585: update_cfs_shares <-enqueue_entity
              ls-5080  [000] d... 42387.933585: place_entity <-enqueue_entity
              ls-5080  [000] d... 42387.933585: __enqueue_entity <-enqueue_entity
              ls-5080  [000] d... 42387.933585: enqueue_entity <-enqueue_task_fair
              ls-5080  [000] d... 42387.933585: update_curr <-enqueue_entity
              ls-5080  [000] d... 42387.933586: update_cfs_rq_blocked_load <-enqueue_entity
              ls-5080  [000] d... 42387.933586: account_entity_enqueue <-enqueue_entity
              ls-5080  [000] d... 42387.933586: update_cfs_shares <-enqueue_entity
              ls-5080  [000] d... 42387.933586: place_entity <-enqueue_entity
              ls-5080  [000] d... 42387.933586: __enqueue_entity <-enqueue_entity
              ls-5080  [000] d... 42387.933586: hrtick_update <-enqueue_task_fair
              ls-5080  [000] d... 42387.933586: ttwu_do_wakeup <-ttwu_do_activate.constprop.95
              ls-5080  [000] d... 42387.933586: check_preempt_curr <-ttwu_do_wakeup
              ls-5080  [000] d... 42387.933586: resched_task <-check_preempt_curr
              ls-5080  [000] d... 42387.933586: _raw_spin_unlock_irqrestore <-try_to_wake_up
              ls-5080  [000] d... 42387.933587: _raw_spin_unlock_irqrestore <-__wake_up_sync_key
              ls-5080  [000] d... 42387.933587: _raw_spin_unlock_irqrestore <-do_notify_parent
              ls-5080  [000] .... 42387.933587: _raw_spin_lock <-do_exit
              ls-5080  [000] .... 42387.933587: exit_rcu <-do_exit
              ls-5080  [000] .... 42387.933587: schedule <-do_exit
              ls-5080  [000] .... 42387.933587: __schedule <-schedule
              ls-5080  [000] .... 42387.933587: rcu_note_context_switch <-__schedule
              ls-5080  [000] .... 42387.933587: _raw_spin_lock_irq <-__schedule
              ls-5080  [000] d... 42387.933587: deactivate_task <-__schedule
              ls-5080  [000] d... 42387.933588: dequeue_task <-deactivate_task
              ls-5080  [000] d... 42387.933588: update_rq_clock.part.83 <-dequeue_task
              ls-5080  [000] d... 42387.933588: dequeue_task_fair <-dequeue_task
              ls-5080  [000] d... 42387.933588: dequeue_entity <-dequeue_task_fair
              ls-5080  [000] d... 42387.933588: update_curr <-dequeue_entity
              ls-5080  [000] d... 42387.933588: update_min_vruntime <-update_curr
              ls-5080  [000] d... 42387.933588: cpuacct_charge <-update_curr
              ls-5080  [000] d... 42387.933588: update_cfs_rq_blocked_load <-dequeue_entity
              ls-5080  [000] d... 42387.933588: clear_buddies <-dequeue_entity
              ls-5080  [000] d... 42387.933588: account_entity_dequeue <-dequeue_entity
              ls-5080  [000] d... 42387.933588: update_min_vruntime <-dequeue_entity
              ls-5080  [000] d... 42387.933588: update_cfs_shares <-dequeue_entity
              ls-5080  [000] d... 42387.933589: hrtick_update <-dequeue_task_fair
              ls-5080  [000] d... 42387.933589: idle_balance <-__schedule
              ls-5080  [000] d... 42387.933589: update_blocked_averages <-idle_balance
              ls-5080  [000] d... 42387.933589: _raw_spin_lock_irqsave <-update_blocked_averages
              ls-5080  [000] d... 42387.933589: update_rq_clock <-update_blocked_averages
              ls-5080  [000] d... 42387.933589: update_rq_clock.part.83 <-update_rq_clock
              ls-5080  [000] d... 42387.933589: update_cfs_rq_blocked_load <-update_blocked_averages
              ls-5080  [000] d... 42387.933589: update_cfs_rq_blocked_load <-update_blocked_averages
              ls-5080  [000] d... 42387.933590: update_cfs_rq_blocked_load <-update_blocked_averages
              ls-5080  [000] d... 42387.933590: update_cfs_rq_blocked_load <-update_blocked_averages
              ls-5080  [000] d... 42387.933590: _raw_spin_unlock_irqrestore <-update_blocked_averages
              ls-5080  [000] d... 42387.933590: load_balance <-idle_balance
              ls-5080  [000] d... 42387.933590: find_busiest_group <-load_balance
              ls-5080  [000] d... 42387.933590: update_group_power <-find_busiest_group
              ls-5080  [000] d... 42387.933590: msecs_to_jiffies <-update_group_power
              ls-5080  [000] d... 42387.933591: arch_scale_freq_power <-update_group_power
              ls-5080  [000] d... 42387.933591: target_load <-find_busiest_group
              ls-5080  [000] d... 42387.933591: idle_cpu <-find_busiest_group
              ls-5080  [000] d... 42387.933591: source_load <-find_busiest_group
              ls-5080  [000] d... 42387.933591: idle_cpu <-find_busiest_group
              ls-5080  [000] d... 42387.933591: source_load <-find_busiest_group
              ls-5080  [000] d... 42387.933591: idle_cpu <-find_busiest_group
              ls-5080  [000] d... 42387.933592: source_load <-find_busiest_group
              ls-5080  [000] d... 42387.933592: idle_cpu <-find_busiest_group
              ls-5080  [000] d... 42387.933592: msecs_to_jiffies <-idle_balance
              ls-5080  [000] d... 42387.933592: _raw_spin_lock <-idle_balance
              ls-5080  [000] d... 42387.933592: put_prev_task_fair <-__schedule
              ls-5080  [000] d... 42387.933592: pick_next_task_fair <-__schedule
              ls-5080  [000] d... 42387.933592: pick_next_task_stop <-__schedule
              ls-5080  [000] d... 42387.933593: pick_next_task_dl <-__schedule
              ls-5080  [000] d... 42387.933593: pick_next_task_rt <-__schedule
              ls-5080  [000] d... 42387.933593: pick_next_task_fair <-__schedule
              ls-5080  [000] d... 42387.933593: pick_next_task_idle <-__schedule


As you can see, quite a lot of output is produced even for a single invocation of ls.

The volume of date outputted by ftrace can be enormous. Consider the following simple Hello World C language program compiled with GCC 4.8.2:

#include <stdio.h>

int main()
{
    printf("hello world\n");
}


When traced with the above ftrace script, over 11000 lines of tracing data was produced!

In the next example, the function call tracer is replaced with the function_graph call tracer. This tracer traces entry into and exit from kernel functions and provides the ability to draw a graph of kernal function calls that were invoked.

#!/bin/bash

DEBUGFS=`grep debugfs /proc/mounts | awk '{ print $2; }'`

echo $$ > $DEBUGFS/tracing/set_ftrace_pid
echo function_graph > $DEBUGFS/tracing/current_tracer
echo 1 > $DEBUGFS/tracing/tracing_on
exec $*
echo 0 > $DEBUGFS/tracing/tracing_on

Here is the new output:

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)   0.038 us    |              mntput_no_expire();
 0)   0.310 us    |            } /* mntput */
 0) + 35.884 us   |          } /* path_openat */
 0) + 36.234 us   |        } /* do_filp_open */
 0)   0.038 us    |        __fsnotify_parent();
 0)   0.044 us    |        fsnotify();
 0) + 37.168 us   |      } /* do_open_exec */
 0)               |      sched_exec() {
 0)   0.039 us    |        _raw_spin_lock_irqsave();
 0)               |        select_task_rq_fair() {
 0)   0.043 us    |          source_load();
 0)   0.044 us    |          target_load();
 0)   0.044 us    |          target_load();
 0)   0.038 us    |          target_load();
 0)   1.990 us    |        }
 0)   0.044 us    |        _raw_spin_unlock_irqrestore();
 0)               |        stop_one_cpu() {
 0)               |          cpu_stop_init_done() {
 0)   0.036 us    |            __init_waitqueue_head();
 0)   0.388 us    |          }
 0)               |          cpu_stop_queue_work() {
 0)   0.036 us    |            _raw_spin_lock_irqsave();
 0)               |            wake_up_process() {
 0)               |              try_to_wake_up() {
 0)   0.094 us    |                _raw_spin_lock_irqsave();
 0)   0.101 us    |                select_task_rq_stop();
 0)   0.042 us    |                _raw_spin_lock();
 0)               |                ttwu_do_activate.constprop.95() {
 0)               |                  activate_task() {
 0)               |                    enqueue_task() {
 0)   0.066 us    |                      update_rq_clock.part.83();
 0)   0.029 us    |                      enqueue_task_stop();
 0)   0.660 us    |                    }
 0)   0.951 us    |                  }
 0)               |                  ttwu_do_wakeup() {
 0)               |                    check_preempt_curr() {
 0)   0.039 us    |                      resched_task();
 0)   0.339 us    |                    }
 0)   0.753 us    |                  }
 0)   2.242 us    |                }
 0)   0.046 us    |                _raw_spin_unlock_irqrestore();
 0)   4.537 us    |              }
 0)   5.156 us    |            }
 0)   0.044 us    |            _raw_spin_unlock_irqrestore();
 0)   6.171 us    |          }
 0)               |          wait_for_completion() {
 0)               |            _cond_resched() {
 0)               |              __schedule() {
 0)   0.049 us    |                rcu_note_context_switch();
 0)   0.038 us    |                _raw_spin_lock_irq();
 0)               |                put_prev_task_fair() {
 0)               |                  update_curr() {
 0)   0.029 us    |                    update_min_vruntime();
 0)   0.074 us    |                    cpuacct_charge();
 0)   0.658 us    |                  }
 0)   0.052 us    |                  __enqueue_entity();
 0)               |                  update_curr() {
 0)   0.036 us    |                    update_min_vruntime();
 0)   0.326 us    |                  }
 0)   0.039 us    |                  __enqueue_entity();
 0)   2.463 us    |                }
 0)   0.053 us    |                pick_next_task_stop();
 1)   8.842 us    |                          } /* enqueue_task */
 1)   9.424 us    |                        } /* activate_task */
 1)               |                        ttwu_do_wakeup() {
 1)               |                          check_preempt_curr() {
 1)   0.152 us    |                            resched_task();
 1)   0.617 us    |                          }
 1)   1.093 us    |                        }
 1) + 11.337 us   |                      } /* ttwu_do_activate.constprop.95 */
 1)   0.068 us    |                      _raw_spin_unlock_irqrestore();
 1) + 17.778 us   |                    } /* try_to_wake_up */
 1) + 18.213 us   |                  } /* default_wake_function */
 1) + 18.734 us   |                } /* child_wait_callback */
 1) + 19.313 us   |              } /* __wake_up_common */
 1)   0.076 us    |              _raw_spin_unlock_irqrestore();
 1) + 20.689 us   |            } /* __wake_up_sync_key */
 1) + 21.126 us   |          } /* __wake_up_parent */
 1)   0.067 us    |          _raw_spin_unlock_irqrestore();
 1) + 29.656 us   |        } /* do_notify_parent */
 1)   0.053 us    |        _raw_spin_lock();
 1)   0.052 us    |        exit_rcu();
 1)               |        schedule() {
 1)               |          __schedule() {
 1)   0.053 us    |            rcu_note_context_switch();
 1)   0.051 us    |            _raw_spin_lock_irq();
 1)               |            deactivate_task() {
 1)               |              dequeue_task() {
 1)   0.103 us    |                update_rq_clock.part.83();
 1)               |                dequeue_task_fair() {
 1)               |                  dequeue_entity() {
 1)               |                    update_curr() {
 1)   0.056 us    |                      update_min_vruntime();
 1)   0.058 us    |                      cpuacct_charge();
 1)   0.933 us    |                    }
 1)   0.083 us    |                    update_cfs_rq_blocked_load();
 1)   0.049 us    |                    clear_buddies();
 1)   0.096 us    |                    account_entity_dequeue();
 1)   0.072 us    |                    update_min_vruntime();
 1)   0.051 us    |                    update_cfs_shares();
 1)   3.705 us    |                  }
 1)   0.049 us    |                  hrtick_update();
 1)   4.626 us    |                }
 1)   5.519 us    |              }
 1)   5.952 us    |            }
 1)               |            idle_balance() {
 1)               |              update_blocked_averages() {
 1)   0.055 us    |                _raw_spin_lock_irqsave();
 1)               |                update_rq_clock() {
 1)   0.114 us    |                  update_rq_clock.part.83();
 1)   0.534 us    |                }
 1)   0.089 us    |                update_cfs_rq_blocked_load();
 1)   0.114 us    |                update_cfs_rq_blocked_load();
 1)   0.100 us    |                update_cfs_rq_blocked_load();
 1)   0.199 us    |                update_cfs_rq_blocked_load();
 1)   0.080 us    |                update_cfs_rq_blocked_load();
 1)   0.063 us    |                _raw_spin_unlock_irqrestore();
 1)   5.311 us    |              }
 1)               |              load_balance() {
 1)               |                find_busiest_group() {
 1)               |                  update_group_power() {
 1)   0.051 us    |                    msecs_to_jiffies();
 1)   0.052 us    |                    arch_scale_freq_power();
 1)   1.098 us    |                  }
 1)   0.056 us    |                  target_load();
 1)   0.052 us    |                  idle_cpu();
 1)   0.059 us    |                  source_load();
 1)   0.102 us    |                  idle_cpu();
 1)   0.068 us    |                  source_load();
 1)   0.086 us    |                  idle_cpu();
 1)   0.053 us    |                  source_load();
 1)   0.058 us    |                  idle_cpu();
 1)   6.578 us    |                }
 1)   7.267 us    |              }
 1)   0.054 us    |              msecs_to_jiffies();
 1)   0.051 us    |              _raw_spin_lock();
 1) + 14.520 us   |            }
 1)   0.094 us    |            put_prev_task_fair();
 1)   0.077 us    |            pick_next_task_fair();
 1)   0.073 us    |            pick_next_task_stop();
 1)   0.094 us    |            pick_next_task_dl();
 1)   0.136 us    |            pick_next_task_rt();
 1)   0.073 us    |            pick_next_task_fair();
 1)   0.051 us    |            pick_next_task_idle();

To simplify the use of ftrace, Rostedt has written two tools – trace-cmd and kernelshark. These are available as standard repo RPMs in Fedora 20. Trace-cmd is a binary command line tool which acts as a user interface to ftrace whereas Kernelshark is a graphical consumer of trace-cmd output.

#  trace-cmd record -e sched ls
....
#  ls -al trace.dat
-rw-r--r--. 1 root root 4136960 May  8 16:44 trace.dat
# wc -l trace.dat
94909 trace.dat


By default, output is written to a file called trace.dat in the current directory.

Here I show kernelsmark using the above trace.dat file to display the collected tracing data:

As you can see below, this data can be filtered in numerous ways to reduce screen clutter and eliminate extraneous output:

You can read a good tutorial on kernelshark here. It takes a bit of effort to understand either the raw output of ftrace or what is displayed using kernelshark but the effort is worth it when you are dealing with difficult kernel timing or locking issues.

Well, that is all for this particular blog post. Note that there is far more to ftrace than what I have managed to include in this blog. It is an incredibly powerful tool which most Linux system administrators and developers seem to be unaware of.

Comments are closed.