Trace Kernel Function Latency with ftrace

When a Linux system feels slow but the usual graphs look ordinary, the missing signal is often buried below user space. This is where ftrace becomes useful. For engineers working on hosting infrastructure, low-level platforms, or latency-sensitive services, ftrace exposes how the kernel actually walks through a code path, where time is spent, and whether delay comes from scheduling, interrupts, file operations, or network handling. Instead of guessing from surface symptoms, you can inspect execution flow close to the metal and build a precise theory of what the machine is doing.

Why ftrace matters for kernel latency work

ftrace is built into the Linux kernel tracing stack and is designed to observe kernel behavior directly through tracefs. The kernel documentation describes it as a framework rather than a single tracer, with support for function tracing, function graph tracing, event tracing, and latency-focused modes. Modern systems typically expose control files under /sys/kernel/tracing, while older layouts may still appear through a debug path for compatibility. The practical takeaway is simple: if you need to inspect kernel-side delay, ftrace is already close at hand on many server builds.

What makes it especially attractive is its ability to focus on call paths instead of broad averages. A generic monitor can tell you that response time is unstable. ftrace can show that a request entered a kernel path, called a specific function, descended into a deeper branch, and then returned later than expected. That visibility is useful when the problem is intermittent, narrow, and resistant to coarse profiling.

• It traces kernel functions at entry, and with graph mode, also at exit.
• It helps isolate where latency begins rather than only where it becomes visible.
• It is strong at debugging strange jitter, not just obvious throughput collapse.
• It can be narrowed to selected functions so the trace remains readable.

Typical server cases where ftrace pays off

Kernel tracing is not something you enable just because a dashboard turned red. It is most valuable when the system misbehaves in a way that looks real to users but vague to tools. The common pattern is that application logs suggest a stall, yet CPU usage, memory pressure, and storage counters do not fully explain it.

1. Request path jitter: latency spikes appear under concurrency, but worker processes do not show a stable user-space hotspot.
2. I/O stalls: read or write paths occasionally pause long enough to hurt tail latency, while the queue view looks modest.
3. Network handling delays: packets arrive, yet processing through the stack seems uneven.
4. Scheduler oddities: threads wake up but do not run when expected.
5. Interrupt-related disruption: a system shows bursts of timing noise that hint at disabled interrupts or delayed handling.

In these situations, ftrace is not replacing ordinary observability. It is the step you take after you have framed the symptom and need to inspect the kernel path that carries it.

How ftrace works under the hood

The function tracer records kernel function entry. The function_graph tracer records both entry and return, which allows it to estimate execution duration and draw a call graph shaped like structured code. According to the kernel documentation, this graph mode is particularly useful when you are chasing unusual latency or trying to understand which path a function actually took. That is why most delay investigations start with graph mode rather than plain function mode.

The trace is controlled through files in tracefs. You switch the active tracer, enable or disable collection, optionally filter the functions of interest, trigger the workload, and then inspect the generated output. Because the control interface is file-based, the process is scriptable and easy to integrate into an incident workflow. The kernel documentation also notes that trace data is buffered in memory pages, which is another reason to keep the scope tight and the capture window short.

Prepare the environment before tracing

Before capturing anything, confirm that tracing is available and that you are using the correct filesystem path. Current kernel documentation points to /sys/kernel/tracing as the standard tracefs location, with older compatibility exposure under the debug path. If tracefs is not mounted, it can be mounted directly. That matters because many older guides still assume only the legacy layout.

• Use a privileged shell.
• Check that tracefs exists and is mounted.
• Read available_tracers to confirm graph tracing support.
• Plan a short reproduction window.
• Decide whether you need a function filter or a PID filter.

On a production-like machine, caution matters more than cleverness. Tracing everything for too long can distort the very timing you want to measure. A short, targeted capture is usually more informative than a giant trace you cannot reason about.

A practical workflow to trace kernel function latency

The cleanest method is to treat tracing like a controlled experiment. Start empty, define the scope, reproduce the issue once, stop immediately, then read the trace with a narrow question in mind.

1. Reset state: clear old trace output and make sure tracing is off.
2. Select graph mode: write function_graph into current_tracer.
3. Limit the target: use set_ftrace_filter to include only the relevant function or path.
4. Optionally narrow by process: use the PID filter when the issue is tied to one workload.
5. Enable tracing: turn tracing on only when ready to trigger the problem.
6. Reproduce once: run the shortest workload that shows the symptom.
7. Stop tracing: disable capture immediately and read the trace file.

This flow aligns well with the official tracing model, which exposes dedicated files for the active tracer, function filters, trace buffers, and tracing state. The documentation explicitly notes that functions listed in the filter file restrict what the graph tracer follows, including the functions they call, which is exactly what makes graph mode manageable in real debugging.

A geeky but useful habit is to build a hypothesis before the capture. For example: “I expect delay between wakeup and actual execution,” or “I expect time to disappear inside the file path.” With that framing, you are not just collecting a graph; you are testing an explanation.

Reading the trace without fooling yourself

The raw output can look intimidating at first because it reflects nesting, timing, and execution context all at once. The key is not to stare at the whole trace. Start with the slow return blocks and work outward. In graph mode, long durations attached to a parent do not always mean the parent itself is slow. The time may belong to a child call, a scheduling interruption, or a wait that happened while the call frame remained open.

• Look for unexpectedly long returns in a path you already suspect.
• Compare siblings under the same parent to see where the branch diverges.
• Notice whether delay repeats in the same function or migrates across layers.
• Correlate with context clues such as wakeups, interrupts, or storage events if enabled.

The kernel documentation also describes latency-oriented tracers and options that add more contextual formatting to the trace, including fields helpful for understanding scheduling and interrupt state. When plain function tracing is too noisy, mixing in event-based context can reveal why a long interval occurred without tracing every function in the system.

Function tracer vs function graph tracer

Both modes are useful, but they answer different questions. The basic function tracer is best when you want to see that a path was entered. The graph tracer is better when you want to know how long that path stayed active and how the nested calls unfolded. Official documentation states that graph tracing records entry and exit and is intended for measuring execution time and producing a reliable call graph. In latency work, that is usually the winning feature.

• Use function mode when the first goal is path discovery.
• Use graph mode when the goal is duration and structure.
• Use event context when timing alone does not explain the pause.

Real-world debugging patterns

A useful pattern for storage-related delay is to filter around the file or block path and inspect where the graph opens up. If one branch repeatedly stretches while others return quickly, you have a candidate layer for deeper inspection. A similar approach works for networking: start near receive or transmit handling, then see whether time expands in stack processing, queue movement, or wakeup behavior.

For scheduler-like issues, plain graph output may not tell the whole story. That is where latency tracers or scheduler-related events become valuable. The kernel tracing documentation includes dedicated latency modes for wakeup and interrupt-related analysis, which can reveal whether a task was ready but not running, or whether timing was perturbed by interrupt state.

Common mistakes when tracing servers

Most bad traces fail for human reasons rather than technical ones. Either the scope is too wide, the experiment runs too long, or the reader confuses a symptom with a cause. Good tracing is selective.

1. Tracing the entire kernel: this produces too much noise and adds overhead.
2. Capturing for too long: a huge buffer makes interpretation harder, not easier.
3. Filtering the wrong symbol: naming, inlining, or kernel variation can hide the path you expected.
4. Ignoring context: a long function may reflect waiting below it rather than work inside it.
5. Skipping reproduction discipline: if the workload changes between runs, comparison becomes weak.

One subtle point from the documentation is that tracing features and exact files can vary by kernel capabilities and configuration. So if a guide seems slightly different from your system, inspect what your tracefs tree actually exposes rather than forcing commands copied from a mismatched environment.

Where ftrace fits among other kernel observability tools

ftrace shines when you need structured kernel path visibility with minimal ceremony. Sampling-oriented tools are strong for hotspot discovery, and programmable tracing frameworks are stronger when you need custom probes or long-running observability logic. But when the question is “which kernel path is slow right now and why does it look this way,” ftrace remains one of the sharpest tools available because it gets straight to control flow.

For hosting and colocation operations, that distinction matters. Infrastructure engineers often do not need a permanent tracing platform for every node. They need a reliable incident tool that can move from symptom to kernel path quickly, preserve rigor, and stay understandable under pressure.

Best practices for low-risk tracing

• Prefer a narrow function filter over global capture.
• Trace only long enough to reproduce the issue once.
• Save the trace immediately and annotate the workload that triggered it.
• Correlate findings with scheduler, I/O, and network observations outside the trace.
• Repeat the experiment after each hypothesis change instead of interpreting one giant capture forever.

Engineers who treat ftrace as a surgical instrument usually get better results than those who treat it as a dragnet. Precision keeps the system readable and keeps your own reasoning honest.

Conclusion

ftrace gives you a direct way to inspect kernel function latency when server behavior feels wrong but broad metrics stay vague. By using tracefs carefully, preferring function_graph for duration analysis, and filtering the capture to a suspected path, you can move from hand-waving to evidence. For teams responsible for hosting performance, noisy multi-tenant environments, or latency-sensitive compute nodes, this style of tracing is less about collecting more data and more about collecting the right kernel story at the right time. That is why ftrace remains such a practical instrument for serious Linux debugging.