A high latency number tells you a problem exists, not where it comes from. This final part of the series covers tracing latency sources with ftrace: the built-in latency tracers (irqsoff, preemptoff, preemptirqsoff, wakeup, wakeup_rt), how to capture the exact moment of a spike with cyclictest --breaktrace, and how to read the resulting trace so you can point at the code path responsible.
Across this series you measured latency with cyclictest (Part 1), built and booted a PREEMPT_RT kernel (Part 2), pinned real-time work with SCHED_FIFO and CPU isolation (Part 3), and wrote real-time-safe user-space code (Part 4). At this point you can produce a maximum latency figure and keep it reasonably low. The remaining skill is diagnosis: when a spike appears, you need to find its cause. This part is about tracing latency sources with ftrace, the tracer built into every modern Linux kernel, so a bad number turns into a specific function or code path you can act on.
What you need
You need the PREEMPT_RT kernel from Part 2, built with tracing support. The relevant configuration symbols are CONFIG_FTRACE, CONFIG_FUNCTION_TRACER, CONFIG_FUNCTION_GRAPH_TRACER, CONFIG_IRQSOFF_TRACER, CONFIG_PREEMPT_TRACER, and CONFIG_SCHED_TRACER (the last one provides the wakeup and wakeup_rt tracers). You also need root access, and cyclictest from the rt-tests package. On a modern kernel the tracing interface is at /sys/kernel/tracing (the tracefs filesystem). Older systems expose it at /sys/kernel/debug/tracing; the examples below use the newer path.
Why a latency number is only the start
A latency tracer answers a narrow question: during a window when something was blocked, what was the kernel doing? The two windows that matter most for real-time work are the time interrupts were disabled and the time preemption was disabled, because both delay a high-priority task from running. A third window is scheduling latency: the gap between a task becoming runnable and the CPU actually running it. ftrace has a dedicated tracer for each of these windows, and each one records the single worst case it has seen since you reset it.
The tracing interface: tracefs
Everything is controlled through plain files. A few files matter for latency work: available_tracers lists what your kernel supports, current_tracer selects one, tracing_on starts and stops recording, trace shows the captured trace, and tracing_max_latency holds the worst latency seen so far in microseconds.
raghu@techveda.org:~$ cd /sys/kernel/tracing
raghu@techveda.org:~$ sudo cat available_tracers
function_graph wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nopThe exact list depends on how the kernel was configured, but the latency tracers you want should be present. Writing nop to current_tracer turns tracing off again.
The latency tracers and what each one measures
- irqsoff — records the longest continuous window during which interrupts were disabled.
- preemptoff — records the longest window during which preemption was disabled.
- preemptirqsoff — records the longest window during which interrupts or preemption were disabled. This is the widest net and a good place to start.
- wakeup — records the largest scheduling latency for the highest-priority task, across all task types.
- wakeup_rt — records the largest scheduling latency for real-time tasks only. On a PREEMPT_RT system this is usually the one you care about, because your latency-sensitive work runs at real-time priority.
Each of these keeps a running maximum. When it observes a window longer than the current value in tracing_max_latency, it saves that trace and updates the maximum. To reset, write 0 to tracing_max_latency.
A first latency trace with wakeup_rt
Start with a controlled example so you can see the mechanism before applying it to a real workload. The following selects wakeup_rt, resets the maximum, runs a short real-time task with chrt, then reads the trace. Disabling options/function-trace first keeps the overhead low.
raghu@techveda.org:~$ cd /sys/kernel/tracing
raghu@techveda.org:~$ sudo sh -c 'echo 0 > options/function-trace'
raghu@techveda.org:~$ sudo sh -c 'echo wakeup_rt > current_tracer'
raghu@techveda.org:~$ sudo sh -c 'echo 1 > tracing_on'
raghu@techveda.org:~$ sudo sh -c 'echo 0 > tracing_max_latency'
raghu@techveda.org:~$ sudo chrt -f 5 sleep 1
raghu@techveda.org:~$ sudo sh -c 'echo 0 > tracing_on'
raghu@techveda.org:~$ sudo cat traceThe trace begins with a header in the latency format. The example output below is representative; your numbers will differ:
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 6.12.0-rt
# --------------------------------------------------------------------
# latency: 12 us, #4/4, CPU#2 | (M:preempt_rt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-1234 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 2d..3 0us : 0:120:R + [002] 1234: 94:R sleep
<idle>-0 2d..3 12us : __schedule <-scheduleThe line that matters is latency: 12 us: that is the worst wakeup latency for the real-time task since you reset the maximum. The columns below it decode the per-event state — the CPU number, whether interrupts were off, whether a reschedule was pending, and the preempt depth — so you can see what the CPU was doing between the task becoming runnable and actually running.
Tracing latency sources under load with cyclictest
A quiet system rarely reproduces the worst case. To catch a real spike, combine a latency tracer with cyclictest. The --breaktrace option stops the trace and ends the run the moment a measured latency exceeds a limit you set, and --tracemark writes a marker into the trace buffer at that instant so you can find it. ftrace must be started before you run cyclictest.
First measure the overhead. Tracing slows the system down, so latencies grow while it is active. Select a tracer, then run with a break limit far above the real maximum so the run does not actually stop, and note the inflated maximum:
raghu@techveda.org:~$ sudo sh -c 'echo preemptirqsoff > /sys/kernel/tracing/current_tracer'
raghu@techveda.org:~$ sudo cyclictest --mlockall --smp --priority=80 --interval=200 --distance=0 --breaktrace=2000 --tracemarkSuppose that run reports a maximum of about 190 us with tracing active, while the untraced maximum was around 130 us. Now set the break limit slightly below the traced maximum, so the run stops exactly when the worst case happens:
raghu@techveda.org:~$ sudo cyclictest --mlockall --smp --priority=80 --interval=200 --distance=0 --breaktrace=180 --tracemarkWhen the latency exceeds 180 us, cyclictest writes its marker, stops tracing, and exits. The trace buffer now holds the events leading up to the spike. Read it and search backwards from the marker:
raghu@techveda.org:~$ sudo cat /sys/kernel/tracing/trace | lessGoing deeper, then cleaning up
Start with the least detail and add more only when needed. preemptirqsoff alone tells you whether a long interrupts-off or preemption-off window is the cause. If it is, turn on function tracing to see the functions inside that window:
raghu@techveda.org:~$ sudo sh -c 'echo 1 > /sys/kernel/tracing/options/function-trace'That split is worth keeping straight: the latency tracers answer when the kernel was blocked, while the function tracer answers what it was executing. The mechanics of the function tracer, its filters and the function-graph output are covered separately in Function Tracing with ftrace.
Function tracing is detailed but expensive, and the added overhead can hide the very spike you are chasing, so use it only after the coarse tracers have narrowed the search. For offline analysis, trace-cmd records a trace to a trace.dat file that you can inspect later with trace-cmd report or the KernelShark graphical viewer:
raghu@techveda.org:~$ sudo trace-cmd record -p function_graph sleep 1
raghu@techveda.org:~$ trace-cmd report | lessWhen you are finished, restore the system so tracing is not left running in the background:
raghu@techveda.org:~$ sudo sh -c 'echo nop > /sys/kernel/tracing/current_tracer'
raghu@techveda.org:~$ sudo sh -c 'echo 0 > /sys/kernel/tracing/options/function-trace'
raghu@techveda.org:~$ sudo sh -c 'echo 0 > /sys/kernel/tracing/tracing_on'
raghu@techveda.org:~$ sudo sh -c 'echo > /sys/kernel/tracing/trace'Key takeaways
- Latency tracers record the single worst window:
irqsoff,preemptoff, andpreemptirqsofffor disabled interrupts or preemption,wakeupandwakeup_rtfor scheduling latency. tracing_max_latencyholds the worst case in microseconds; reset it withecho 0before each measurement.- Use
cyclictest --breaktrace=USEC --tracemark, with ftrace started first, to stop the trace at the exact moment of a spike. - Always measure the tracing overhead first, then set the break limit just below the inflated maximum.
- Begin with a coarse tracer such as
preemptirqsoff; add function tracing only when you need to see inside the window.
What’s next in this series
This completes the five-part Real-Time Linux with PREEMPT_RT series: measuring latency, building an RT kernel, tuning priorities and CPU isolation, writing real-time-safe code, and now finding the source of a latency spike. The next hands-on series on this blog is Buildroot for Embedded Linux, which starts by building a bootable root filesystem from source.
Frequently asked questions
Why does my latency get worse as soon as I enable tracing?
Tracing adds work to the kernel, so measured latencies increase while it is active. This is expected. Measure the inflated maximum first by running with a very high break limit, then set your real break limit just below that value.
Which latency tracer should I start with?
Start with preemptirqsoff, which captures the longest window with interrupts or preemption disabled and gives a broad view with modest overhead. Use wakeup_rt when you specifically want the scheduling latency of real-time tasks.
Where is the tracing interface on a current kernel?
On modern kernels it is the tracefs filesystem at /sys/kernel/tracing. Older systems expose the same files under /sys/kernel/debug/tracing.
How do I capture the trace at the exact moment of a spike?
Start a latency tracer, then run cyclictest with --breaktrace set to your latency limit and --tracemark. When a latency exceeds the limit, cyclictest writes a marker into the buffer and stops tracing, leaving the events that led to the spike.
