What You Will Learn

Prerequisites

To get the most from this free Linux kernel development course lecture, you should have:

• A Linux machine or VM running kernel 5.10 or newer (6.x recommended) with root access.
• Basic familiarity with process context vs interrupt context — covered earlier in this free embedded systems course.
• Awareness of scheduling classes (stop, deadline, real-time, fair) from our previous scheduler lectures.
• Comfort with the shell; all commands below run in a terminal as root or via sudo.

What Is the Ftrace Latency Format?

Ftrace is the tracing framework built directly into the Linux kernel. It can log every kernel function call, scheduler event, and interrupt with almost no setup. When the latency format is enabled, every trace line carries a compact status field — a small group of characters that snapshot the CPU state at the instant of the event.

On modern kernels, Ftrace is exposed through tracefs, normally auto-mounted at /sys/kernel/tracing (the old /sys/kernel/debug/tracing path still works as a compatibility mount, but the new path is preferred). Let us verify it and enable the latency format:

# Confirm tracefs is mounted
mount | grep tracefs

# If not mounted (rare on modern distros):
mount -t tracefs nodev /sys/kernel/tracing

cd /sys/kernel/tracing

# Turn on the latency-format trace option
echo 1 > options/latency-format

# Pick the function_graph tracer
echo function_graph > current_tracer

# Start tracing for a couple of seconds, then stop
echo 1 > tracing_on
sleep 2
echo 0 > tracing_on

# View the captured trace
less trace

Each line in the trace now includes the latency status field. Depending on the tool you use, you will see either a five-character field (trace-cmd style, where the first character is the CPU core number) or a four-character field (raw Ftrace, where the CPU number is printed as a separate left-hand column instead). The remaining four characters mean exactly the same thing in both cases.

A simple rule keeps you sane while reading these fields: apart from the CPU number, a period . nearly always means zero, off, or not applicable. Anything other than a dot is the kernel raising its hand to tell you something.

Decoding Each Character of the Latency Format

Character 1 — CPU Core Number

The core the event executed on. On a quad-core board, you will see 0 through 3. This matters a lot in embedded multicore debugging: a driver interrupt bouncing between cores, or a real-time thread migrating unexpectedly, becomes instantly visible.

Character 2 — Hardware Interrupt Status

• . — hardware interrupts are enabled (the normal, healthy state).
• d — hardware interrupts are currently disabled on this CPU.

Long stretches of d are a red flag when you are chasing latency in a free Linux device drivers course project: a driver that disables interrupts for too long will stall everything else on that core, including timer ticks.

Character 3 — The need_resched Bit

• . — the bit is clear; the scheduler is not being requested.
• N — the TIF_NEED_RESCHED flag in the task’s thread info is set, meaning the kernel wants to reschedule as soon as possible.

Modern kernels also support a lazy variant of this flag (used with the newer preemption models) which some tools render as a lowercase n. Whenever you see N, the very next safe preemption point should trigger a call into the scheduler core.

Character 4 — Interrupt Context Indicator

This character only carries meaning while an interrupt is in flight. Otherwise it is just a dot, telling you the event happened in ordinary process context.

Character 5 — Preemption Depth

A dot means the preemption count is zero: the kernel is in a preemptible state and the scheduler may switch tasks at will (subject to the configured preemption model). A non-zero digit shows how many kernel-level locks or preempt-disable sections are currently held, which forces the kernel into a non-preemptible window. Deep or long-lived non-zero values here are a classic source of scheduling latency on embedded and real-time systems, which is why PREEMPT_RT work focuses so heavily on shrinking them.

Putting It Together: A Worked Example

Suppose a trace line for a shell utility shows the status field 2.N.. just before a call into the scheduler core. Reading left to right: the task ran on CPU core 2; interrupts were enabled; the need_resched bit was set (a reschedule was pending); execution was in plain process context; and preemption depth was zero. In other words, the kernel was fully ready to schedule — and moments later, it did.

Function Duration Markers in function_graph Output

When the function_graph tracer is active, every function exit line carries the time the function took (in microseconds). To make slow functions jump out of thousands of trace lines, Ftrace prefixes the duration with a delay marker. These thresholds are documented in the official kernel tracing documentation and remain the same on current kernels:

In the function-name column at the far right, an opening brace { means the function has just been entered, and a line containing only a closing brace } marks where that same function returned. The braces nest exactly like C source code, which is why function_graph output reads like an indented call tree of the live kernel.

Here is a quick original exercise you can run to see the markers appear. We trace only scheduler-related functions to keep the output small:

cd /sys/kernel/tracing

# Reset any previous state
echo nop > current_tracer
echo > trace

# Trace only functions whose names start with "sched"
echo 'sched*' > set_ftrace_filter
echo function_graph > current_tracer

echo 1 > tracing_on
# Generate some scheduling activity
taskset -c 1 yes > /dev/null &
sleep 1
kill %1
echo 0 > tracing_on

# Look for lines carrying + or ! duration markers
grep -E '\+ |\! ' trace | head -20

# Clean up the filter when done
echo > set_ftrace_filter

What Has Changed on Modern Kernels (6.6 and Later)

Older books and articles describe this material against kernels in the 5.x era. The latency format itself is stable, but the surrounding landscape has moved, and this free Linux kernel development course teaches the current state:

• tracefs location: use /sys/kernel/tracing directly; you no longer need debugfs mounted to reach Ftrace.
• EEVDF replaced CFS: since kernel 6.6, the fair scheduling class is implemented by the EEVDF (Earliest Eligible Virtual Deadline First) algorithm. Traces of the scheduler core now show EEVDF-era internals; anything written about CFS-specific functions such as classic vruntime min-tracking helpers may look different in your output.
• Lazy preemption and PREEMPT_RT mainlined: the real-time preemption model was merged into the mainline kernel (6.12), and newer preemption modes can surface a lazy need-resched indication in traces.
• A new scheduling class: kernel 6.12 also introduced sched_ext, which lets BPF programs implement custom scheduling policies — one more class the core scheduler may consult, as we will see when we interpret a real class walk in the next lecture.

Common Mistakes and Troubleshooting

• Editing files as a normal user: tracefs entries are root-only by default. Use sudo -i or prefix each redirect carefully — sudo echo 1 > file does not work because the redirect happens in your unprivileged shell; use echo 1 | sudo tee file instead.
• Forgetting to clear old state: a leftover set_ftrace_filter from a previous session silently hides most functions. Reset with echo > set_ftrace_filter.
• Misreading dots: remember the rule — a dot is zero/off/not-applicable everywhere except the CPU-number position.
• Confusing the 4-char and 5-char layouts: raw Ftrace prints the CPU in its own column, trace-cmd folds it into the status field. Count the characters before decoding.
• Tracing on a laptop with frequency scaling: duration values fluctuate with CPU frequency. For repeatable latency numbers, pin the governor to performance while experimenting.

Best Practices

• Filter aggressively (set_ftrace_filter, per-event enables) — tracing everything on a busy system generates gigabytes per minute and perturbs the very latency you are measuring.
• Keep trace sessions short and bounded: enable, reproduce, disable, then analyze offline.
• Always note the kernel version alongside saved traces; scheduler internals changed meaningfully at 6.6 and again at 6.12.
• On production embedded devices, prefer snapshot buffers and per-CPU buffer size tuning (buffer_size_kb) so tracing cannot exhaust memory.

Key Takeaways

Conclusion

The latency trace format is the Rosetta Stone of kernel tracing. Once you can read those five characters without thinking, every Ftrace or trace-cmd capture turns from noise into a precise timeline of what each CPU was doing, whether the scheduler was pending, and where preemption was blocked. These are exactly the skills that separate an engineer who runs a tracer from one who understands the trace — and they are foundational for the driver-latency debugging you will do throughout this free Linux device drivers course and the rest of our free embedded systems course track.

In the next lecture, we put this decoding skill to work: we record real scheduler activity with trace-cmd, watch the core scheduler walk its class list (stop → deadline → real-time → fair/EEVDF) live in the report, and explore the trace visually with KernelShark.

Frequently Asked Questions (FAQ)