Linux ftrace — Complete Learning Notes & Output Guide

ftrace (Function Tracer) is the internal tracer built directly into the Linux kernel. It is designed to help developers and system administrators see what is happening inside the kernel, trace function call graphs, record interrupts, measure scheduling latency, and debug performance bottlenecks without adding external modules or third-party dependencies.

---

1. What is ftrace?

ftrace stands for:

Function Tracer

Unlike user-space tracing utilities (strace, ltrace), ftrace lives entirely inside the Linux kernel. It is controlled via standard filesystem operations (reading and writing text files) exposed through the tracefs (or debugfs) virtual filesystem mounted at:

/sys/kernel/tracing
# or (older legacy kernels)
/sys/kernel/debug/tracing

It answers critical low-level kernel questions:

• What exact sequence of kernel functions was executed by a specific system call or interrupt?
• How long did a specific kernel routine (e.g., page allocation, packet transmission, or block I/O submission) take to execute?
• Which kernel function disabled interrupts or preemption, causing latency spikes?
• What is the full call hierarchy (call graph) beneath a kernel event?
• Why is a kernel lock or mutex causing thread scheduling delays?

---

2. Kernel Configuration & Front-Ends

ftrace requires a kernel built with standard tracing options enabled (default on almost all modern distributions: Ubuntu, Debian, RHEL, Fedora, Arch).

Confirm that tracing is mounted:

mount -t tracefs nodev /sys/kernel/tracing 2>/dev/null || mount | grep tracing

Direct tracefs vs. Front-End Tools

While you can drive ftrace using plain echo and cat into /sys/kernel/tracing, production engineers and SREs often use official front-ends:

• trace-cmd: The command-line manager for ftrace.
• KernelShark: The GUI visualization tool for trace-cmd dat files.

Install trace-cmd:

Debian / Ubuntu

sudo apt update
sudo apt install trace-cmd

RHEL / Rocky / AlmaLinux / CentOS

sudo dnf install trace-cmd

Arch Linux

sudo pacman -S trace-cmd

---

3. Available Tracers in ftrace

To view the tracing plugins compiled into your kernel:

cat /sys/kernel/tracing/available_tracers

Common tracers include:

Tracer Name	Description	Diagnostic Focus
function	Traces entry points of all supported kernel functions.	Low-overhead execution tracking.
function_graph	Traces both entry and exit of kernel functions, rendering a visual call tree with timing.	Function latency and execution flow.
irqsoff	Traces sections where hardware interrupts are disabled.	Finding causes of real-time latency spikes.
preemptoff	Traces sections where preemption is disabled.	Scheduling jitter analysis.
wakeup	Traces how long the highest priority task takes to wake up.	Real-time scheduler latency.
blk	Traces block I/O requests and queue activity (underlying engine for blktrace).	Storage layer queuing.
nop	No tracing; disables active plugin without disabling event collection.	Reset state.

---

4. Standard function Tracer Output Breakdown

Let's configure the standard function tracer:

cd /sys/kernel/tracing
sudo sh -c 'echo nop > current_tracer'
sudo sh -c 'echo function > current_tracer'
sudo sh -c 'echo do_sys_openat2 > set_ftrace_filter'
sudo sh -c 'echo 1 > tracing_on'
# ... perform workload ...
sudo sh -c 'echo 0 > tracing_on'
cat trace | head -n 25

Raw Output Example

# tracer: function
#
# entries-in-buffer: 4  bytes-per-cpu: 4096
#
#           TASK-PID     CPU#  |||||  TIMESTAMP  FUNCTION
#              | |         |   |||||      |         |
           python3-4512    [002] ..... 15024.102345: do_sys_openat2 <-__x64_sys_openat
           python3-4512    [002] ..... 15024.102350: filename_lookup <-do_sys_openat2
              sshd-1280    [000] d.h.. 15024.102410: do_sys_openat2 <-__x64_sys_openat

Detailed Breakdown of Headings

4.1 TASK-PID

• Format: <command>-<PID> (e.g., python3-4512, sshd-1280).
• Meaning: The executable name of the task and its Process ID that triggered the kernel function. If the event was executed by an interrupt handler or kernel thread, it will show names like kworker/u16:1-891 or swapper/0-0 (the idle task).

4.2 CPU#

• Format: [002]
• Meaning: The zero-indexed logical CPU core on which the function was executed.

4.3 Kernel Latency Flags (|||||)

This 4-to-5 character status field provides kernel context at the moment the tracepoint was hit:

12345
|||||
||||+--- need-resched:  'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED set,
||||                    'n' only TIF_NEED_RESCHED set,
||||                    'p' only PREEMPT_NEED_RESCHED set,
||||                    '.' otherwise.
|||+---- hardirq/softirq: 'H' in hardirq context, 'h' in software interrupt (softirq) context,
|||                       's' in softirq handler, '.' otherwise.
||+----- irqs-off:      'd' interrupts are disabled, '.' interrupts are enabled.
|+------ preempt-depth: 'p' preemption disabled, '.' preemption enabled. (or numeric depth)
+------- trace-irq:     'X' default context.

• d in column 1: Hardware interrupts were disabled when this function ran.
• h or H in column 2: Code was executing within an interrupt handler, not standard process context.

4.4 TIMESTAMP

• Format: Seconds.Microseconds (e.g., 15024.102345).
• Meaning: The system uptime monotonic clock timestamp when the function entered.

4.5 FUNCTION

• Format: <called_function> <- <caller_function>
• Meaning: The function being traced (do_sys_openat2), followed by the arrow <-, followed by the parent function that called it (__x64_sys_openat).

---

5. function_graph Tracer Output Breakdown

The function_graph tracer is one of ftrace's most powerful capabilities: it reconstructs C call graphs with opening { and closing } braces and prints the execution duration.

Command Setup

cd /sys/kernel/tracing
sudo sh -c 'echo nop > current_tracer'
sudo sh -c 'echo function_graph > current_tracer'
sudo sh -c 'echo do_sys_openat2 > set_graph_function'
sudo sh -c 'echo 1 > tracing_on'
ls /tmp > /dev/null
sudo sh -c 'echo 0 > tracing_on'
cat trace | head -n 35

Raw Output Example

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
  2)               |  do_sys_openat2() {
  2)               |    getname_flags() {
  2)   0.180 us    |      kmem_cache_alloc();
  2)   0.720 us    |    }
  2)               |    filename_lookup() {
  2)   0.120 us    |      path_init();
  2)   1.240 us    |      link_path_walk();
  2) + 12.450 us   |      lookup_fast();
  2)   14.210 us   |    }
  2)   0.110 us    |    putname();
  2) ! 128.520 us  |  }

Detailed Breakdown of Headings & Markers

5.1 CPU

• Meaning: The CPU core number running the call (e.g., 2)).

5.2 DURATION

• Meaning: The real execution time spent inside the function, measured in microseconds (us) or milliseconds (ms). Leaf functions show their duration on the same line; compound functions show the cumulative duration at the closing brace }.

Latency Warning Markers

ftrace prefixes durations with visual latency flags to highlight slow kernel calls:

Marker	Duration Threshold	Significance
(blank)	$< 10\,\mu\text{s}$	Normal, fast kernel execution.
+	$\ge 10\,\mu\text{s}$	Execution took greater than 10 microseconds.
!	$\ge 100\,\mu\text{s}$	Execution took greater than 100 microseconds (latency alert).
#	$\ge 1000\,\mu\text{s}$ ($1\,\text{ms}$)	Severe delay inside kernel function.
*	$\ge 10000\,\mu\text{s}$ ($10\,\text{ms}$)	Critical kernel latency bubble (investigate immediately).

5.3 FUNCTION CALLS

• Meaning: The hierarchical call tree showing function invocations, nested functions, and exits. A semicolon ; denotes a leaf function; curly braces { } encompass child function executions.

---

6. Trace Events Subsystem (/sys/kernel/tracing/events)

Beyond raw functions, ftrace houses the kernel's Static Tracepoints across all subsystems (scheduling, block I/O, network, memory).

Exploring Available Events

ls /sys/kernel/tracing/events
# Shows categories: block, kmem, net, sched, syscalls, etc.

Enabling Trace Events

To enable scheduling switch events without changing the tracer plugin:

sudo sh -c 'echo 1 > /sys/kernel/tracing/events/sched/sched_switch/enable'
sudo sh -c 'echo 1 > /sys/kernel/tracing/tracing_on'
# ... work ...
sudo sh -c 'echo 0 > /sys/kernel/tracing/tracing_on'
cat /sys/kernel/tracing/trace | tail -n 10

Event trace output line format:

kworker/0:1-120  [000] d.h.. 15025.102345: sched_switch: prev_comm=kworker/0:1 prev_pid=120 prev_prio=120 prev_state=I ==> next_comm=sshd next_pid=4210 next_prio=120

---

7. Using trace-cmd: Practical Front-End Workflow

Direct manipulation of /sys/kernel/tracing requires administrative file redirects. In everyday production diagnostics, trace-cmd provides a cleaner interface.

Command	Action
sudo trace-cmd record -p function -l do_sys_openat2 <command>	Record specific function calls while executing a command.
sudo trace-cmd record -p function_graph -g vfs_read -F ls /	Record a function graph filtered to the ls process (-F).
sudo trace-cmd record -e sched:sched_switch -e sched:sched_wakeup	Record kernel scheduling wakeups and context switches.
trace-cmd report	Read and format trace.dat data in the terminal.
trace-cmd report --stat	Show buffer statistics and dropped events count.

---

8. ftrace vs. strace vs. perf vs. eBPF

+-------------------------------------------------------------+
|                          strace                             |
|  * User space only.                                         |
|  * Intercepts boundary system calls via ptrace.             |
|  * Cannot see what the kernel does after the syscall starts.|
+-------------------------------------------------------------+
                               |
                               v
+-------------------------------------------------------------+
|                          ftrace                             |
|  * Native kernel infrastructure. Zero modules needed.       |
|  * Specializes in kernel function call-graphs & latency.    |
|  * Built-in file-based control (/sys/kernel/tracing).       |
+-------------------------------------------------------------+
                               |
                               v
+-------------------------------------------------------------+
|                     perf & eBPF (BCC/bpftrace)              |
|  * perf: Hardware counters, PMCs, CPU sampling profiles.   |
|  * eBPF: Custom in-kernel programmable logic & aggregations.|
+-------------------------------------------------------------+

Dimension	ftrace	strace	perf	eBPF (bpftrace)
Instrumentation Target	Kernel internals & tracepoints	Syscalls at user boundary	Hardware PMUs, CPU sampling, tracepoints	Kprobes, Uprobes, Tracepoints
Overhead	Very Low	Very High ($10\times - 100\times$)	Low	Extremely Low
Dependencies	None (Kernel built-in)	Standard userland utility	linux-tools package	LLVM/Clang runtime, root
Call Graph Support	Built-in (function_graph)	None	Call stack unwinding via frame pointers/DWARF	Custom stack unwinding
Programmability	Filters and triggers only	None	Scripting interfaces	Full custom C/C-like bytecode

---

9. Real-World Troubleshooting Scenarios

Scenario A: Measuring Why a System Call Takes Milliseconds

An application encounters an occasional 50ms latency spike on fdatasync():

Record the call graph using trace-cmd:

sudo trace-cmd record -p function_graph -g vfs_fsync -F ./my_app

Read the report:

trace-cmd report | grep -E "(\+|!|\#|\*)"

Output:

2)               |  vfs_fsync() {
2)               |    ext4_sync_file() {
2)               |      jbd2_log_wait_commit() {
2) * 48210.12 us |        wait_for_completion();
2) * 48220.45 us |      }
2) * 48250.10 us |    }
2) * 48260.05 us |  }

Diagnosis: The application wasn't blocked on CPU work. The * 48ms duration was spent inside jbd2_log_wait_commit() waiting on journaling locks on the underlying block device.

---

Scenario B: Diagnosing Hardware Interrupt Latency Spikes

A low-latency network trading engine suffers from jitter:

Enable the irqsoff tracer:

cd /sys/kernel/tracing
sudo sh -c 'echo nop > current_tracer'
sudo sh -c 'echo irqsoff > current_tracer'
sudo sh -c 'echo 1 > tracing_on'
sleep 5
sudo sh -c 'echo 0 > tracing_on'
cat trace | head -n 25

Diagnosis: trace prints the exact kernel function that held interrupts disabled for the longest duration, pointing to inefficient driver routines or spinlock contention.

---

10. Important Interview Questions & Answers

Q: How does ftrace achieve near-zero overhead when tracing is disabled?

Answer: ftrace uses Dynamic Ftrace (CONFIG_DYNAMIC_FTRACE). When the kernel is compiled with -pg / -mfentry, the compiler inserts a 5-byte call __fentry__ stub at the beginning of every single C kernel function. During kernel boot, ftrace inspects the kernel text segment and overwrites all those 5-byte call sites with machine NOP (no-operation) instructions. When a function is filtered and enabled for tracing, ftrace hot-patches only that specific function's NOP back into a call to the tracing engine, ensuring that untraced functions execute with zero interception overhead.

Q: What does the ! marker signify in function_graph output?

Answer: In the function_graph tracer, the ! symbol is a latency indicator placed next to the execution duration of a function. It indicates that the function's execution time equaled or exceeded $100\,\mu\text{s}$ ($0.1\,\text{ms}$), helping engineers visually spot slow operations without having to parse timestamps manually.

Q: What is the purpose of the set_ftrace_pid control file?

Answer: The /sys/kernel/tracing/set_ftrace_pid file allows you to restrict kernel function tracing strictly to a specific Process ID (PID) or set of PIDs. Writing a PID into this file instructs ftrace to ignore calls made by other processes, reducing buffer noise and performance impact on multi-tenant production systems.

---