PREV_LEC | NEXT_LEC

What You Will Learn

• How to control whether printk timestamps are shown, without touching whether they’re logged
• What Ftrace actually is, who built it, and why it lives inside the kernel rather than as an external tool
• The kernel config options Ftrace depends on, and how to check them on a running system
• How tracefs gets mounted and what each important file under it does
• How to read the list of available tracers and pick the right one for a debugging session
• How to build, load, and trace an original demo module with function_graph

Prerequisites

• Comfortable building and loading out-of-tree kernel modules (insmod/rmmod)
• Familiarity with pr_*() logging and dmesg, covered in the previous lecture of this chapter
• Root access on a Linux machine or VM running a reasonably recent (6.x) kernel with CONFIG_DEBUG_FS enabled

Finishing the printk timestamp story

One detail is easy to misread: the knob at /sys/module/printk/parameters/time does
not decide whether a timestamp gets attached to a kernel message. Every line in the
kernel log buffer already carries a monotonic timestamp (seconds.microseconds since the kernel’s
internal clock started, i.e. since the bootloader handed off control) regardless of this setting.
What the knob controls is purely a display decision — whether that stored timestamp is
printed when the buffer is dumped, whether that’s at boot, on the console, or through dmesg.

# check current state
cat /sys/module/printk/parameters/time

# disable timestamp printing (log buffer keeps recording them internally either way)
echo 0 > /sys/module/printk/parameters/time

# re-enable
echo 1 > /sys/module/printk/parameters/time

On boot-constrained embedded targets, some teams disable this print step to shave a small amount
of time off log rendering — a micro-optimization worth knowing about, not one to chase unless you’ve
actually profiled boot time and found it matters.

What Ftrace actually is

Ftrace (“Function Trace”) is a tracing framework that has shipped in the mainline kernel since
2.6.27 (2008), originally authored by Steven Rostedt. Despite the name, it is not limited to tracing
function calls — that’s just the tracer it started with. Today the same framework backs function
tracing, function-graph (call/return) tracing, scheduling latency tracers, interrupt/preemption-off
latency tracers, block I/O tracing, and the event-tracing subsystem that tools like perf
and trace-cmd build on top of.

The core idea is simple: Ftrace maintains an in-kernel ring buffer. Depending on which tracer is
active, entries get written into that buffer as events happen — a function entered, an IRQ disabled,
a task woken up. You read the buffer back out through a pseudo-filesystem interface, not through a
separate daemon or agent, which is why Ftrace has near-zero setup cost compared to external profilers.

Kernel configuration Ftrace depends on

Ftrace’s individual tracers are gated by separate config symbols, so what you can use depends on
how the running kernel was built. The commonly needed ones:

These in turn rely on architecture support flags — CONFIG_HAVE_FUNCTION_TRACER,
CONFIG_HAVE_FUNCTION_GRAPH_TRACER, and CONFIG_HAVE_DYNAMIC_FTRACE — which is
why Ftrace’s feature set can differ slightly between architectures. On x86-64 and arm64 distro
kernels, all of the above are typically already built in.

# confirm the running kernel has them, without rebuilding anything
grep -E 'CONFIG_(FUNCTION_TRACER|FUNCTION_GRAPH_TRACER|DYNAMIC_FTRACE)' /boot/config-$(uname -r)

Mounting tracefs

Ftrace’s control interface lives on its own pseudo-filesystem, tracefs, historically
nested under debugfs. Most modern distributions mount it automatically at boot, but it’s
worth knowing how to do it yourself for minimal embedded root filesystems.

Persistent, via /etc/fstab:

tracefs   /sys/kernel/debug/tracing   tracefs   defaults   0   0

Or on demand, at runtime (root only):

mount -t tracefs nodev /sys/kernel/debug/tracing

Once mounted, everything happens by reading and writing plain files under
/sys/kernel/debug/tracing/ — no special ioctl or netlink protocol involved.

The files that matter first

The tracefs directory has dozens of entries; most of them are for advanced filtering. As a
beginner you only need a handful to get productive:

The tracing_cpumask file deserves a quick example since the hex encoding trips people
up: it’s a plain bitmask, one bit per CPU. To trace only CPU 0, write 1. For CPU 1 alone,
write 2. For CPU 3 alone, write 8. To trace CPUs 0 and 1 together, write
3 (bit 0 + bit 1).

Reading the available tracers

Before picking a tracer, check what your kernel actually offers:

cat /sys/kernel/debug/tracing/available_tracers

A typical distro kernel output looks like this — the exact list depends on your config and
architecture:

blk function_graph wakeup_dl wakeup_rt wakeup irqsoff function nop

irqsoff, preemptoff, and preemptirqsoff are grouped together
as the latency tracers: instead of logging every event, each keeps only the single worst-case
interval it has observed since being enabled, which makes them cheap to leave running for a long time
while hunting an intermittent spike.

Original demo: tracing a small module with function_graph

Rather than trace the whole kernel, let’s build a tiny original module and watch Ftrace follow its
own call chain. The module (ep_ftrace_demo) deliberately calls through three nested
functions on load, so the graph tracer has something visible to show.

// ep_ftrace_demo.c
#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>

static noinline void ep_step_c(void)
{
    pr_info("ep_ftrace_demo: reached step C\n");
}

static noinline void ep_step_b(void)
{
    ep_step_c();
}

static noinline void ep_step_a(void)
{
    ep_step_b();
}

static int __init ep_ftrace_demo_init(void)
{
    pr_info("ep_ftrace_demo: loaded, calling step chain\n");
    ep_step_a();
    return 0;
}

static void __exit ep_ftrace_demo_exit(void)
{
    pr_info("ep_ftrace_demo: unloaded\n");
}

module_init(ep_ftrace_demo_init);
module_exit(ep_ftrace_demo_exit);
MODULE_LICENSE("GPL");
MODULE_DESCRIPTION("EmbeddedPathashala Ftrace demo module");

// Makefile
obj-m += ep_ftrace_demo.o

all:
	make -C /lib/modules/$(shell uname -r)/build M=$(PWD) modules

clean:
	make -C /lib/modules/$(shell uname -r)/build M=$(PWD) clean

noinline is important here — without it the compiler may inline the whole chain into
one function, and there would be nothing left for the graph tracer to show.

Build and set up tracing before loading it, so the very first call chain gets captured:

# build
make

# select the function_graph tracer
echo function_graph > /sys/kernel/debug/tracing/current_tracer

# restrict tracing to only our functions, so the trace stays readable
echo 'ep_step_*' > /sys/kernel/debug/tracing/set_ftrace_filter

# clear any old data and enable recording
echo > /sys/kernel/debug/tracing/trace
echo 1 > /sys/kernel/debug/tracing/tracing_on

# now load the module
insmod ep_ftrace_demo.ko

# stop recording and read the result
echo 0 > /sys/kernel/debug/tracing/tracing_on
cat /sys/kernel/debug/tracing/trace

Expected output (durations will vary run to run):

 1)               |  ep_step_a() {
 1)               |    ep_step_b() {
 1)   0.196 us    |      ep_step_c();
 1)   0.512 us    |    }
 1)   0.781 us    |  }

Clean up afterward:

rmmod ep_ftrace_demo
echo nop > /sys/kernel/debug/tracing/current_tracer
echo > /sys/kernel/debug/tracing/set_ftrace_filter

Common mistakes and troubleshooting

• Forgetting to reset set_ftrace_filter — an old filter silently
  hides everything outside it in your next session. Clear it with an empty write when you’re done.
• Reading available_tracers and assuming every listed tracer is always
  usable — some (like wakeup_dl) need CONFIG_SCHED_TRACER and only
  make sense with real-time or deadline-scheduled tasks present.
• Leaving tracing_on at 1 with a busy tracer like plain
  function — the ring buffer fills fast on a busy system; check
  buffer_size_kb if traces look truncated.
• Expecting trace_pipe to behave like trace —
  trace_pipe consumes entries as they’re read (like a real pipe), so reading it twice
  won’t show the same data twice.

Best practices

• Always narrow scope with set_ftrace_filter or tracing_cpumask before
  tracing on production or resource-constrained targets.
• Prefer the latency tracers (irqsoff/wakeup) over raw
  function tracing when you only care about worst-case timing, not every call.
• Reset current_tracer to nop and clear filters when you’re finished —
  don’t leave heavier tracers running unattended.
• On constrained embedded targets, check buffer_size_kb before a long tracing
  session; the default per-CPU buffer size can be adjusted to fit available RAM.

Performance considerations

Thanks to CONFIG_DYNAMIC_FTRACE, function tracing costs essentially nothing when
disabled — the kernel patches call sites back to no-ops. Once enabled, function_graph
costs more than plain function tracing because it instruments both entry and return;
on a busy system this is measurable and worth confining to a filtered function set.

Security considerations

Tracefs is only reachable by root by default, which is intentional — function tracing exposes
kernel internals (addresses, call timing, scheduling behavior) that shouldn’t be handed to
unprivileged users. Don’t relax the permissions on /sys/kernel/debug on a production or
multi-user system.

Interview Questions

Summary and Key Takeaways

• Printk’s timestamp knob is a display setting, not a logging setting — timestamps are always recorded.
• Ftrace is a built-in kernel tracing framework, no external daemon required, driven entirely through tracefs files.
• CONFIG_FUNCTION_TRACER, CONFIG_FUNCTION_GRAPH_TRACER, and
  CONFIG_DYNAMIC_FTRACE are the config options that matter most for getting started.
• current_tracer, tracing_on, and trace are the three files
  you’ll touch in almost every session.
• Filtering with set_ftrace_filter and tracing_cpumask keeps traces
  readable and cheap on real hardware.

Conclusion

Ftrace turns “I think this function is slow” into a measured call graph with real numbers, without
installing anything or leaving the kernel you’re already running. The workflow you practiced here —
pick a tracer, filter it down, enable, capture, disable, read — is the same workflow you’ll reuse for
every real debugging session, whether you’re chasing an interrupt latency spike or a misbehaving
driver’s call sequence. The next lecture in this chapter builds on this foundation with event
tracing and trace_printk() for finer-grained instrumentation of your own drivers.

Frequently Asked Questions

PREV_LEC | NEXT_LEC