What You Will Learn

Prerequisites

Our Test Subject: an Original Kernel Module

Rather than tracing a random kernel function, let’s build a tiny original driver called ep_iotrace_demo, so we can watch Ftrace follow calls we wrote ourselves. It exposes a debugfs file; writing to it triggers a small chain of function calls.

// ep_iotrace_demo.c
#include <linux/module.h>
#include <linux/debugfs.h>
#include <linux/slab.h>

static struct dentry *ep_dbg_dir;

static noinline void ep_stage_validate(int value)
{
    if (value < 0)
        pr_warn("ep_iotrace_demo: negative value ignored\n");
}

static noinline void ep_stage_transform(int value)
{
    ep_stage_validate(value);
    value *= 2;
    pr_info("ep_iotrace_demo: transformed value = %d\n", value);
}

static noinline void ep_stage_commit(int value)
{
    ep_stage_transform(value);
}

static ssize_t ep_trigger_write(struct file *f, const char __user *buf,
                                 size_t count, loff_t *ppos)
{
    int value;
    char kbuf[16];

    if (count >= sizeof(kbuf))
        return -EINVAL;
    if (copy_from_user(kbuf, buf, count))
        return -EFAULT;
    kbuf[count] = '\0';

    if (kstrtoint(kbuf, 10, &value))
        return -EINVAL;

    ep_stage_commit(value);
    return count;
}

static const struct file_operations ep_trigger_fops = {
    .owner = THIS_MODULE,
    .write = ep_trigger_write,
};

static int __init ep_iotrace_init(void)
{
    ep_dbg_dir = debugfs_create_dir("ep_iotrace_demo", NULL);
    debugfs_create_file("trigger", 0200, ep_dbg_dir, NULL, &ep_trigger_fops);
    pr_info("ep_iotrace_demo: loaded, write an int to /sys/kernel/debug/ep_iotrace_demo/trigger\n");
    return 0;
}

static void __exit ep_iotrace_exit(void)
{
    debugfs_remove_recursive(ep_dbg_dir);
}

module_init(ep_iotrace_init);
module_exit(ep_iotrace_exit);
MODULE_LICENSE("GPL");
MODULE_DESCRIPTION("EmbeddedPathashala Ftrace demo module");

The noinline attribute matters here: without it, the compiler may inline these small functions and Ftrace would never see them as separate call frames. Build and load it:

$ make -C /lib/modules/$(uname -r)/build M=$(pwd) modules
$ sudo insmod ep_iotrace_demo.ko
$ dmesg | tail -1
ep_iotrace_demo: loaded, write an int to /sys/kernel/debug/ep_iotrace_demo/trigger

The Function Tracer

The function tracer is the simplest tracer Ftrace ships: it logs the name of every function entered on every CPU, along with the parent that called it. Nothing else — no timing, no nesting, just a flat list. It is the right starting point because its output is easy to read and its overhead is the lowest among the call-tracing tracers.

Enable it, generate some activity, and disable it:

$ cd /sys/kernel/tracing
$ echo function > current_tracer
$ echo 1 > tracing_on
$ echo 7 > /sys/kernel/debug/ep_iotrace_demo/trigger
$ echo 0 > tracing_on
$ cat trace | grep ep_stage

Expected fragment of the output:

          bash-1842  [001] ...1  4820.221033: ep_stage_commit <-ep_trigger_write
          bash-1842  [001] ...1  4820.221035: ep_stage_transform <-ep_stage_commit
          bash-1842  [001] ...1  4820.221036: ep_stage_validate <-ep_stage_transform

Each line answers one question: which function ran, and who called it. Reading the columns left to right:

Notice the ordering: ep_trigger_write called ep_stage_commit, which called ep_stage_transform, which called ep_stage_validate — exactly the chain we wrote in the module, now visible without adding a single debug print.

The function_graph Tracer

function_graph is the function tracer’s more detailed sibling. Instead of one line per call, it prints an entry line and an exit line, indents nested calls, and measures how long each function took. This turns a flat call list into an actual call graph you can read top to bottom like source code.

$ echo function_graph > current_tracer
$ echo 1 > tracing_on
$ echo 7 > /sys/kernel/debug/ep_iotrace_demo/trigger
$ echo 0 > tracing_on
$ cat trace | grep -A6 ep_stage_commit

 1)               |  ep_stage_commit() {
 1)               |    ep_stage_transform() {
 1)               |      ep_stage_validate();
 1)   0.325 us    |    }
 1)   0.812 us    |  }

Two symbols in the DURATION column are worth memorizing, since they are the first thing an experienced kernel engineer scans for in a long trace:

On a busy system you will see plenty of + markers; a ! next to a function you own is usually the first clue when chasing a latency bug.

Filtering By Duration: tracing_thresh

A full function_graph trace of a busy kernel is enormous, and most of it completes in nanoseconds and is irrelevant to a performance investigation. tracing_thresh tells Ftrace to record only calls that ran longer than a threshold you set, in microseconds.

$ echo 50 > tracing_thresh
$ echo function_graph > current_tracer
$ echo 1 > tracing_on
$ echo 7 > /sys/kernel/debug/ep_iotrace_demo/trigger
$ echo 0 > tracing_on
$ cat trace

With the threshold set to 50, any call chain that finishes in under 50 microseconds — including our whole ep_stage_commit chain in the earlier example — disappears entirely, leaving only genuinely slow functions. This same threshold can be set at boot time on the kernel command line, which is especially useful for catching functions that run long only during early boot:

tracing_thresh=200 ftrace=function_graph

That line traces every function taking longer than 200 microseconds from the moment tracing starts at boot, letting you spot boot-time stalls without instrumenting anything by hand. Remember to reset the threshold afterward:

$ echo 0 > tracing_thresh

Narrowing the Scope: Function Filters

Threshold filtering trims by time; function filters trim by name. Instead of tracing every function in the kernel, set_ftrace_filter restricts tracing to only the functions you list, which keeps the buffer small and the overhead low — important advice for anyone building a free embedded systems course lab around Ftrace on constrained hardware.

$ echo ep_stage_transform > set_ftrace_filter
$ echo function > current_tracer
$ echo 1 > tracing_on
$ echo 7 > /sys/kernel/debug/ep_iotrace_demo/trigger
$ echo 0 > tracing_on
$ cat trace | grep ep_stage

          bash-1901  [000] ...1  5011.884201: ep_stage_transform <-ep_stage_commit

Only ep_stage_transform appears — ep_stage_commit and ep_stage_validate are silently skipped even though they still executed. Clear the filter with an empty write so tracing returns to normal:

$ echo > set_ftrace_filter

set_ftrace_notrace does the opposite: it excludes named functions while tracing everything else. This is handy when one noisy function (a timer callback, a scheduler helper) floods your trace and you just want it gone:

$ echo ep_stage_validate > set_ftrace_notrace
$ echo function > current_tracer
$ echo 1 > tracing_on
$ echo 7 > /sys/kernel/debug/ep_iotrace_demo/trigger
$ echo 0 > tracing_on
$ cat trace | grep ep_stage

          bash-1912  [000] ...1  5090.114420: ep_stage_commit <-ep_trigger_write
          bash-1912  [000] ...1  5090.114422: ep_stage_transform <-ep_stage_commit

ep_stage_validate ran, but it never appears in the trace — the exact inverse of what set_ftrace_filter produced.

Common Mistakes and Troubleshooting

Best Practices

Performance Considerations

function_graph tracing adds measurable overhead on every function call system-wide, because entry and exit are both instrumented. On a busy embedded target this can visibly slow things down and even shift the timing you are trying to measure. Combining tight function filters with a sensible tracing_thresh keeps the buffer relevant and the overhead close to what plain function tracing costs.

Summary and Key Takeaways

Conclusion

The function and function_graph tracers turn “what is my kernel actually doing right now” from a guessing game into a readable log, without adding a single printk to your driver. Once you can filter that log by duration and by function name, Ftrace stops being noisy and becomes a precision tool you will reach for on every debugging session from here on — a core skill in any free linux device drivers course. In the next lecture, we will look at event tracing and trace-cmd, which build directly on the tracer concepts covered here.

Frequently Asked Questions