Kernel Tracing with ftrace and perf: Making Bottlenecks Visible

1. Why classic logging fails on performance problems

Application logging reliably answers what happened, but rarely how long exactly a certain kernel operation took or which system call actually blocked. Kernel tracing addresses exactly this gap: instead of guessing which component is slow, it delivers exact timestamps and call chains straight from the kernel itself, without having to change the application.

For production servers running PHP-FPM, databases or complex I/O paths, kernel tracing is often the only way to truly understand a performance regression instead of narrowing it down by trial and error. ftrace and perf are the two central tools built into the mainline kernel, ready to use immediately without a reboot or additional software. Anyone who masters kernel tracing can trace a latency spike all the way down to a single kernel function, instead of stopping at server load as the explanation.

2. Understanding ftrace: tracers, events and the ring buffer

ftrace is a tracing framework built into the kernel, controlled entirely through the virtual filesystem /sys/kernel/tracing, with no external tools required. At its core, ftrace works with interchangeable tracers, each recording a different kind of event: the function tracer logs every kernel function call, the function_graph tracer additionally records entry and exit times with nesting depth.

Recorded events end up in a per-CPU ring buffer, which is read out on demand without losing data in the meantime. This architecture makes kernel tracing with ftrace particularly lightweight: overhead only occurs for actually enabled tracers and filters, not for the entire kernel at once. Important for practical use: ftrace requires root privileges and usually access to the debugfs or tracefs mount, which on most distributions is already mounted under /sys/kernel/tracing.

3. Function tracing and function graph with ftrace

The easiest entry point into kernel tracing with ftrace is the function_graph tracer, which delivers a call hierarchy with timing per function, similar to a stack trace but with actual runtime instead of just call order. This is especially valuable for finding out which single function in a deep kernel call chain consumes most of the time.

# Mount point for ftrace controls (usually already mounted)
cd /sys/kernel/tracing

# List all available tracers on this kernel
cat available_tracers

# Enable the function_graph tracer to see call hierarchy with timing
echo function_graph > current_tracer

# Restrict tracing to a specific function to reduce noise and overhead
echo vfs_read > set_graph_function

# Start tracing, run the workload, then stop
echo 1 > tracing_on
sleep 2
echo 0 > tracing_on

# Read the captured trace
cat trace | head -50

# Reset tracer state when done
echo nop > current_tracer

The function_graph tracer is especially suited for targeted questions like "why does this filesystem access take so long", because it shows the complete call chain from the system call down to the innermost kernel functions with exact timing. Without a filter, however, this tracer produces an enormous amount of data, which is why set_graph_function and process filters via set_ftrace_pid are almost always necessary in practice.

4. Observing tracepoints and syscalls specifically

Besides generic function tracing, the kernel offers predefined tracepoints, fixed instrumentation points at semantically meaningful locations such as system call entry and exit, scheduler decisions or block I/O events. These tracepoints are more stable across kernel versions than plain function tracing, because they are part of the official kernel API and do not depend on internal function names that can change at any time.

# List available tracepoint categories
ls /sys/kernel/tracing/events/

# Enable all syscall entry/exit tracepoints for a specific syscall
echo 1 > /sys/kernel/tracing/events/syscalls/sys_enter_read/enable
echo 1 > /sys/kernel/tracing/events/syscalls/sys_exit_read/enable

# Trace block I/O events to see actual disk requests
echo 1 > /sys/kernel/tracing/events/block/block_rq_issue/enable

# Filter tracepoints to a specific process by PID
echo $(pgrep -f mysqld | head -1) > /sys/kernel/tracing/set_event_pid

# Capture for a short window and inspect
echo 1 > /sys/kernel/tracing/tracing_on
sleep 1
echo 0 > /sys/kernel/tracing/tracing_on
cat /sys/kernel/tracing/trace | grep -v '^#' | head -30

# Disable tracepoints again
echo 0 > /sys/kernel/tracing/events/enable

For kernel tracing on production servers, tracepoints are usually the better choice over plain function tracing, because their overhead is more predictable and they can be restricted to a single process or syscall without burdening the entire kernel. The trace-cmd tool wraps many of these manual file operations in a more convenient command line, but internally works with the same ftrace mechanisms.

5. perf: sampling profiling for CPU hotspots

While ftrace primarily works event based, perf relies on statistical sampling: at fixed time intervals, the current instruction pointer and stack of every CPU is captured, from which, after enough samples, a statistically solid picture emerges of where CPU time is actually being spent. This approach is especially suited to the question "which function eats the most CPU time across all processes".

# Record system-wide CPU samples for 10 seconds at 99 Hz
sudo perf record -F 99 -a -g -- sleep 10

# Show a text-based summary of where CPU time went
sudo perf report --stdio | head -30

# Profile a specific running process by PID instead of system-wide
sudo perf record -F 99 -p $(pgrep -f php-fpm | head -1) -g -- sleep 10

# Live top-like view of CPU hotspots, refreshed continuously
sudo perf top

# List available hardware and software performance events
perf list | grep -E 'Hardware event|Software event' -A5

The -g parameter enables call graph sampling, which captures not just the currently executing function but the entire call chain. Without this parameter, perf report shows which function consumes CPU time, but not where it was called from, which makes interpreting generic functions such as memcpy significantly harder.

6. Generating flame graphs from perf data

A plain text list of functions and their CPU share is hard to grasp for deep call chains. Flame graphs visualize the same data as stacked bars, where the width of a bar is proportional to the total CPU time spent in that function and all of its subfunctions. This visualization makes the dominant hotspots in a kernel tracing dataset visible at a glance, without manually digging through the raw data.

# Record with call graphs first
sudo perf record -F 99 -a -g -- sleep 30

# Convert perf data into a folded stack format for flame graphs
sudo perf script > out.perf-script

# Clone the standard flamegraph toolkit (Brendan Gregg's scripts)
git clone https://github.com/brendangregg/FlameGraph.git

# Fold stacks and generate an interactive SVG flame graph
./FlameGraph/stackcollapse-perf.pl out.perf-script > out.folded
./FlameGraph/flamegraph.pl out.folded > flamegraph.svg

# Open the SVG in any browser to explore interactively
# Wider bars = more CPU time; hover shows the exact function name

In practice, a flame graph from a PHP-FPM workload often shows unexpectedly wide bars in areas such as garbage collection, regex compilation or JSON serialization, things that were not even on the radar in normal application profiling. Because flame graphs are based on perf data, they reflect both userspace and kernel portions of the CPU time, provided kernel debug symbols are available.

7. Latency analysis: from the application down to the syscall

A common misconception: high CPU utilization and high latency are not the same problem. A request can be slow even though the CPU is nearly idle during it, for example because it is waiting for slow disk I/O or a network response. For these cases, kernel tracing with ftrace tracepoints such as block_rq_issue and block_rq_complete delivers exact timestamps, from which the actual wait time per I/O request can be calculated.

ftrace's irqsoff and preemptoff tracers uncover a different class of latency problems: periods during which interrupts or preemption were disabled, which can cause noticeable delays on real-time sensitive systems. These tracers are more specialized than generic function tracing, but for latency critical workloads they often provide the decisive explanation for why a single request was occasionally significantly slower than the average.

8. Tracing overhead and production operations

Every form of kernel tracing generates overhead, whose size strongly depends on how many events are captured and how finely the filter is set. Unfiltered function tracing across the entire kernel can noticeably impact system performance, while precisely filtered tracepoints or low frequency perf sampling usually go unnoticed on production servers.

# Measure the overhead of a tracing session before trusting results
# Baseline without tracing
time (some_benchmark_command)

# Same benchmark with function_graph tracing enabled and filtered
echo function_graph > /sys/kernel/tracing/current_tracer
echo target_function > /sys/kernel/tracing/set_graph_function
time (some_benchmark_command)

# Always disable tracing explicitly when done
echo 0 > /sys/kernel/tracing/tracing_on
echo nop > /sys/kernel/tracing/current_tracer

# Low-overhead perf sampling suitable for production (low frequency)
sudo perf record -F 19 -a -g -- sleep 60

# Prefer short, targeted tracing windows over long-running sessions

A proven rule of thumb for production use: always deploy kernel tracing with a time limit and as tightly filtered as possible, document results, and then explicitly disable the tracer afterwards. A forgotten, permanently active tracer is a common, unnecessary performance loss that is easily avoided if every tracing session is treated as a closed procedure with a clear start and end.

9. ftrace and perf compared to other tools

Several tools with different strengths are available for kernel tracing. The choice depends on whether a specific question needs answering or continuous monitoring needs to be built.

In practice, these tools complement each other: perf quickly gives an overview of CPU hotspots, ftrace then allows the targeted deep dive into an already identified function or syscall, and eBPF based tools such as bpftrace are suited for permanent, production ready kernel tracing with precisely defined metrics.

10. Summary

Kernel tracing with ftrace and perf makes visible what classic application logging cannot show: exact timing of individual kernel functions, the actual reason for I/O wait times, and the functions that really consume CPU time. ftrace is well suited for targeted call chain analysis and tracepoint based latency measurement, while perf uses statistical sampling to quickly identify CPU hotspots and serves as the foundation for flame graphs.

Discipline around overhead is decisive for production use: always deploy kernel tracing with a time limit, filtered precisely, and with a clear conclusion. Anyone who masters these tools no longer has to guess at the next performance regression, but can trace the actual cause all the way down to a single kernel function.

11. FAQ: Kernel Tracing with ftrace and perf