Kernel-Tracing mit ftrace und perf: Bottlenecks sichtbar machen

1. Warum klassisches Logging bei Performance-Problemen scheitert

Anwendungs-Logging beantwortet zuverlässig, was passiert ist, aber selten, wie lange genau eine bestimmte Kernel-Operation gedauert hat oder welcher Systemaufruf tatsächlich blockierte. Kernel-Tracing setzt genau an dieser Lücke an: Statt eine Vermutung zu haben, welche Komponente langsam ist, liefert es exakte Zeitstempel und Aufrufketten direkt aus dem Kernel selbst, ohne die Anwendung ändern zu müssen.

Für Produktivserver mit PHP-FPM, Datenbanken oder komplexen I/O-Pfaden ist Kernel-Tracing oft der einzige Weg, eine Performance-Regression wirklich zu verstehen, statt sie durch Ausprobieren einzugrenzen. ftrace und perf sind dabei die zwei zentralen, im Mainline-Kernel eingebauten Werkzeuge, die ohne Neustart und ohne Zusatzsoftware sofort einsatzbereit sind. Wer Kernel-Tracing beherrscht, kann eine Latenzspitze bis auf die einzelne Funktion im Kernel zurückverfolgen, statt bei der Server-Last als Erklärung stehen zu bleiben.

2. ftrace verstehen: Tracer, Events und der Ringpuffer

ftrace ist ein im Kernel eingebautes Tracing-Framework, das über das virtuelle Dateisystem /sys/kernel/tracing gesteuert wird, komplett ohne externe Tools. Im Kern arbeitet ftrace mit austauschbaren Tracern, von denen jeder eine andere Art von Ereignis aufzeichnet: der function-Tracer protokolliert jeden Kernel-Funktionsaufruf, der function_graph-Tracer zusätzlich Ein- und Austrittszeiten mit Verschachtelungstiefe.

Aufgezeichnete Ereignisse landen in einem Ringpuffer pro CPU, der bei Bedarf ausgelesen wird, ohne dass währenddessen Daten verloren gehen. Diese Architektur macht Kernel-Tracing mit ftrace besonders leichtgewichtig: Der Overhead entsteht nur für tatsächlich aktivierte Tracer und Filter, nicht für den gesamten Kernel gleichzeitig. Wichtig für den Praxiseinsatz: ftrace erfordert Root-Rechte und meist Zugriff auf das debugfs- oder tracefs-Mount, das auf den meisten Distributionen bereits unter /sys/kernel/tracing eingebunden ist.

3. Function Tracing und Function Graph mit ftrace

Der einfachste Einstieg in Kernel-Tracing mit ftrace ist der function_graph-Tracer, der eine Aufrufhierarchie mit Zeitangaben pro Funktion liefert, ähnlich einem Stacktrace, aber mit tatsächlicher Laufzeit statt nur der Aufrufreihenfolge. Das ist besonders wertvoll, um herauszufinden, welche einzelne Funktion in einer tiefen Kernel-Aufrufkette den Großteil der Zeit verbraucht.

# 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

Der function_graph-Tracer eignet sich besonders für gezielte Fragen wie "warum dauert dieser Dateisystem-Zugriff so lange", weil er die komplette Aufrufkette vom Systemaufruf bis zu den innersten Kernel-Funktionen mit exakten Zeiten zeigt. Ohne Filter erzeugt dieser Tracer allerdings eine enorme Datenmenge, weshalb set_graph_function und Prozessfilter über set_ftrace_pid in der Praxis fast immer nötig sind.

4. Tracepoints und Syscalls gezielt beobachten

Neben dem generischen Function Tracing bietet der Kernel vordefinierte Tracepoints, feste Instrumentierungspunkte an semantisch bedeutsamen Stellen wie Systemaufruf-Ein- und Austritten, Scheduler-Entscheidungen oder Block-I/O-Events. Diese Tracepoints sind stabiler über Kernel-Versionen hinweg als reines Function Tracing, weil sie Teil der offiziellen Kernel-API sind und nicht von internen Funktionsnamen abhängen, die sich jederzeit ändern können.

# 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

Für Kernel-Tracing auf Produktivservern sind Tracepoints meist die bessere Wahl als reines Function Tracing, weil ihr Overhead vorhersagbarer ist und sie gezielt auf einen einzelnen Prozess oder Syscall eingeschränkt werden können, ohne den gesamten Kernel zu belasten. Das Werkzeug trace-cmd kapselt viele dieser manuellen Dateizugriffe in einer komfortableren Kommandozeile, arbeitet intern aber mit denselben ftrace-Mechanismen.

5. perf: Sampling-Profiling für CPU-Hotspots

Während ftrace primär ereignisbasiert arbeitet, setzt perf auf statistisches Sampling: In festen Zeitintervallen wird der aktuelle Instruction Pointer und Stack jeder CPU erfasst, woraus sich nach ausreichend vielen Samples ein statistisch belastbares Bild ergibt, wo tatsächlich CPU-Zeit verbraucht wird. Dieser Ansatz eignet sich besonders für die Frage "welche Funktion frisst am meisten CPU-Zeit über alle Prozesse hinweg".

# 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

Der Parameter -g aktiviert Call-Graph-Sampling, das nicht nur die aktuell ausgeführte Funktion, sondern die gesamte Aufrufkette erfasst. Ohne diesen Parameter zeigt perf report zwar, welche Funktion CPU-Zeit verbraucht, aber nicht, von wo sie aufgerufen wurde, was die Interpretation bei generischen Funktionen wie memcpy deutlich erschwert.

6. Flame Graphs aus perf-Daten erzeugen

Eine reine Textliste von Funktionen und ihrem CPU-Anteil ist bei tiefen Aufrufketten schwer zu überblicken. Flame Graphs visualisieren dieselben Daten als gestapelte Balken, bei denen die Breite eines Balkens proportional zur gesamten CPU-Zeit ist, die in dieser Funktion und allen ihren Unterfunktionen verbracht wurde. Diese Visualisierung macht die dominierenden Hotspots in einem Kernel-Tracing-Datensatz auf einen Blick sichtbar, ganz ohne die Rohdaten manuell zu durchsuchen.

# 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 der Praxis zeigt ein Flame Graph aus einem PHP-FPM-Workload häufig unerwartet breite Balken in Bereichen wie Garbage Collection, Regex-Kompilierung oder JSON-Serialisierung, die im normalen Anwendungs-Profiling gar nicht auf dem Radar waren. Weil Flame Graphs auf perf-Daten basieren, spiegeln sie sowohl Userspace- als auch Kernel-Anteile der CPU-Zeit wider, sofern Kernel-Debug-Symbole verfügbar sind.

7. Latenz-Analyse: von der Anwendung bis zum Syscall

Ein häufiges Missverständnis: Hohe CPU-Auslastung und hohe Latenz sind nicht dasselbe Problem. Ein Request kann langsam sein, obwohl die CPU dabei fast untätig ist, etwa weil er auf einen langsamen Disk-I/O oder eine Netzwerkantwort wartet. Für diese Fälle liefert Kernel-Tracing mit ftrace-Tracepoints wie block_rq_issue und block_rq_complete exakte Zeitstempel, aus denen sich die tatsächliche Wartezeit pro I/O-Anfrage berechnen lässt.

Der irqsoff- und der preemptoff-Tracer von ftrace decken eine andere Klasse von Latenzproblemen auf: Zeiten, in denen Interrupts oder Preemption deaktiviert waren, was auf Echtzeit-sensiblen Systemen zu spürbaren Verzögerungen führen kann. Diese Tracer sind spezialisierter als das generische Function Tracing, liefern aber für latenzkritische Workloads oft die entscheidende Erklärung, warum ein einzelner Request gelegentlich deutlich langsamer war als der Durchschnitt.

8. Tracing-Overhead und Produktionsbetrieb

Jede Form von Kernel-Tracing erzeugt Overhead, dessen Größe stark davon abhängt, wie viele Ereignisse erfasst werden und wie fein der Filter eingestellt ist. Ungefiltertes Function Tracing über den gesamten Kernel kann die Systemleistung spürbar beeinträchtigen, während gezielt gefilterte Tracepoints oder ein perf-Sampling mit niedriger Frequenz auf Produktivservern meist unbemerkt bleiben.

# 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

Eine bewährte Faustregel für den Produktivbetrieb: Kernel-Tracing immer zeitlich begrenzt und so eng wie möglich gefiltert einsetzen, Ergebnisse dokumentieren und Tracer danach explizit wieder deaktivieren. Ein vergessener, dauerhaft aktiver Tracer ist ein häufiger, unnötiger Performance-Verlust, der sich leicht vermeiden lässt, wenn jede Tracing-Sitzung als abgeschlossener Vorgang mit klarem Anfang und Ende behandelt wird.

9. ftrace und perf im Vergleich zu anderen Werkzeugen

Für Kernel-Tracing stehen mehrere Werkzeuge mit unterschiedlichen Stärken zur Verfügung. Die Wahl hängt davon ab, ob eine punktuelle Frage beantwortet oder ein kontinuierliches Monitoring aufgebaut werden soll.

In der Praxis ergänzen sich diese Werkzeuge: perf liefert schnell einen Überblick über CPU-Hotspots, ftrace erlaubt danach die gezielte Tiefenanalyse einer bereits identifizierten Funktion oder eines Syscalls, und eBPF-basierte Werkzeuge wie bpftrace eignen sich für dauerhaftes, produktionstaugliches Kernel-Tracing mit vorher genau definierten Metriken.

10. Zusammenfassung

Kernel-Tracing mit ftrace und perf macht sichtbar, was klassisches Anwendungs-Logging nicht zeigen kann: exakte Zeiten einzelner Kernel-Funktionen, den tatsächlichen Grund für I/O-Wartezeiten und die Funktionen, die wirklich CPU-Zeit verbrauchen. ftrace eignet sich für gezielte Aufrufketten-Analyse und Tracepoint-basierte Latenzmessung, während perf über statistisches Sampling schnell CPU-Hotspots identifiziert und als Grundlage für Flame Graphs dient.

Entscheidend für den produktiven Einsatz ist Disziplin beim Overhead: Kernel-Tracing immer zeitlich begrenzt, gezielt gefiltert und mit klarem Abschluss betreiben. Wer diese Werkzeuge beherrscht, muss bei der nächsten Performance-Regression nicht mehr raten, sondern kann die tatsächliche Ursache bis auf die einzelne Kernel-Funktion zurückverfolgen.

11. FAQ: Kernel-Tracing mit ftrace und perf