Linux Kernel Tracing Mastery: Ftrace & kprobe for Function-Level Debugging

Kernel Tracing Overview

Kernel tracing exposes key runtime states — function call counts, syscall parameters, disk request latency — when the kernel executes specific code paths. Tracing mechanisms split into static tracing (compile-time instrumentation) and dynamic tracing (runtime probe insertion).

Ftrace Framework: Static Tracing

Ftrace relies on compile-time instrumentation. Enabling CONFIG_FUNCTION_TRACER inserts a jump to mcount (x86_64 uses fentry) at every kernel function entry. When tracing is off, the jump becomes a NOP with near-zero overhead. When enabled, the NOP is replaced with the actual tracing handler that records function name, timestamp, and PID before returning to the original function.

Ftrace Tracers

function tracer : Records each called function's name, timestamp, and PID. Ideal for observing call sequences (e.g., vfs_read → filesystem → block layer).

function_graph tracer : Adds function exit tracing, measures execution duration, and displays nested call relationships as an indented tree. Best for performance bottleneck analysis.

Specialized tracers: irqsoff (interrupt disable latency), wakeup (task wakeup latency), blk (block I/O requests).

Ftrace Operation via tracefs

Ftrace operates through tracefs typically mounted at /sys/kernel/debug/tracing. Complete workflow:

# 1. Mount debugfs (if not mounted)
mount -t debugfs nodev /sys/kernel/debug

# 2. Enter ftrace directory
cd /sys/kernel/debug/tracing

# 3. View available tracers
cat available_tracers

# 4. Select function_graph tracer
echo function_graph > current_tracer

# 5. Filter specific functions (optional, reduces output)
echo 'vfs_read*' > set_ftrace_filter

# 6. Clear previous trace
echo > trace

# 7. Enable tracing
echo 1 > tracing_on

# 8. Execute operation to observe
cat /etc/hostname > /dev/null

# 9. Disable tracing
echo 0 > tracing_on

# 10. View results
cat trace

Output lines contain timestamp, process name/PID, and function name. In function_graph mode, vertical bars and plus signs indicate nesting depth; numbers in parentheses after function names show execution time in microseconds.

kprobe: Dynamic Instrumentation

kprobe inserts probes at any kernel instruction address at runtime. On x86, registering a kprobe replaces the target instruction's first byte with INT3 (0xcc). When CPU hits this breakpoint: registers are saved, kernel preemption disabled, user-registered pre_handler runs; after return, TF (trap flag) is set for single-stepping the original instruction; single-step exception triggers post_handler; finally registers are restored, TF cleared, and execution continues. The probed function's logic remains unchanged.

Three Probe Types

kprobes : Basic type, inserts at any instruction (few architecture-restricted exceptions). Calls pre_handler (before instruction) and post_handler (after). pre_handler reads registers/arguments; post_handler analyzes results and timing.

jprobes : Only at function entry, for argument access. Handler prototype must match probed function exactly; kernel copies registers to pass arguments. Deprecated since Linux 5.0 — use kprobe fetchargs or tracepoints instead.

kretprobes : Triggers on function return to capture return value and measure duration. Kernel replaces return address at entry; on return, enters kretprobe handler, retrieves return value, then jumps to real caller. Requires maxactive setting for max concurrent instances; too small loses events under high concurrency.

Kernel Module Example: Tracing do_sys_open

#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/kprobes.h>
#include <linux/ptrace.h>
#include <linux/fs.h>

static struct kprobe kp;
static struct kretprobe rp;

/* kprobe pre_handler: function entry, fetch arguments */
static int handler_pre(struct kprobe *p, struct pt_regs *regs)
{
    /* x86_64 calling convention: rdi=1st(dfd), rsi=2nd(filename)
     * rdx=3rd(flags), rcx=4th(mode) */
    int dfd = (int)regs->di;
    const char __user *filename = (const char __user *)regs->si;
    int flags = (int)regs->dx;

    pr_info("kprobe: do_sys_open called: dfd=%d, filename=%p, flags=0x%x
",
            dfd, filename, flags);
    return 0;
}

/* kprobe post_handler: after instruction */
static void handler_post(struct kprobe *p, struct pt_regs *regs,
                         unsigned long flags)
{
    pr_info("kprobe: do_sys_open instruction executed
");
}

/* kretprobe handler: function return, fetch return value */
static int ret_handler(struct kretprobe_instance *ri, struct pt_regs *regs)
{
    int retval = (int)regs->ax;
    pr_info("kretprobe: do_sys_open returned: fd=%d
", retval);
    return 0;
}

static int __init kprobe_init(void)
{
    int ret;

    /* Register kprobe at do_sys_open entry */
    kp.symbol_name = "do_sys_open";
    kp.pre_handler = handler_pre;
    kp.post_handler = handler_post;

    ret = register_kprobe(&kp);
    if (ret < 0) {
        pr_err("register_kprobe failed: %d
", ret);
        return ret;
    }
    pr_info("kprobe registered at do_sys_open
");

    /* Register kretprobe for return value */
    rp.kp.symbol_name = "do_sys_open";
    rp.handler = ret_handler;
    rp.maxactive = 64;

    ret = register_kretprobe(&rp);
    if (ret < 0) {
        pr_err("register_kretprobe failed: %d
", ret);
        unregister_kprobe(&kp);
        return ret;
    }
    pr_info("kretprobe registered at do_sys_open
");

    return 0;
}

static void __exit kprobe_exit(void)
{
    unregister_kretprobe(&rp);
    unregister_kprobe(&kp);
    pr_info("kprobe and kretprobe unregistered
");
}

module_init(kprobe_init);
module_exit(kprobe_exit);
MODULE_LICENSE("GPL");
MODULE_DESCRIPTION("kprobe example for do_sys_open");

After compiling and loading the module, run dmesg -w to see output. Each open syscall prints do_sys_open arguments and returned file descriptor.

Combining Ftrace and kprobe: Practical Workflow

Kernel Configuration Check

Verify required configs:

zcat /proc/config.gz | grep -E "CONFIG_KPROBES|CONFIG_KPROBE_EVENTS|CONFIG_FTRACE|CONFIG_FUNCTION_TRACER|CONFIG_DEBUG_FS"

Must be y: CONFIG_KPROBES, CONFIG_KPROBE_EVENTS, CONFIG_FTRACE, CONFIG_FUNCTION_TRACER, CONFIG_DEBUG_FS. If /proc/config.gz missing, check /boot/config-$(uname -r). Recompile kernel if any are missing.

Mount debugfs

mount -t debugfs debugfs /sys/kernel/debug

For persistent mount, add to /etc/fstab:

debugfs /sys/kernel/debug debugfs defaults 0 0

Using kprobe_events Interface (No Kernel Module)

Create probes via /sys/kernel/debug/tracing/kprobe_events.

Command formats:

kprobe: p[:[GRP/]EVENT] [MOD:]SYM[+offs]|MEMADDR [FETCHARGS] kretprobe: r[MAXACTIVE][:[GRP/]EVENT] [MOD:]SYM[+0] [FETCHARGS] Example: trace do_sys_open arguments and return value on x86_64:

cd /sys/kernel/debug/tracing

# Create kprobe for do_sys_open arguments
# x86_64: %di=dfd, %si=filename, %dx=flags, %cx=mode
# +0(%si):string reads string from address in %si
echo 'p:myprobe do_sys_open dfd=%di filename=+0(%si):string flags=%dx mode=%cx' > kprobe_events

# Create kretprobe for return value
echo 'r:myretprobe do_sys_open ret=$retval' >> kprobe_events

# View created probes
cat kprobe_events

# Enable probes
echo 1 > events/kprobes/myprobe/enable
echo 1 > events/kprobes/myretprobe/enable

# Enable tracing
echo 1 > tracing_on

# Trigger open calls
cat /etc/hostname > /dev/null
ls /tmp > /dev/null

# Stop and view
echo 0 > tracing_on
cat trace

FETCHARGS Syntax

%reg

: Read register value (e.g., %di, %si, %ax) +offs($reg): Read from register+offset (e.g., +4(%sp)) $retval: Function return value (kretprobe only) $stack: Stack address

Type suffixes: :string (null-terminated string), :u32, :u64 (unsigned integers)

Architecture-specific argument registers: x86_64 uses rdi, rsi, rdx, rcx, r8, r9; ARM64 uses x0–x7. Adjust register names accordingly.

Trace Output Format

# tracer: nop
#
# entries-in-buffer/entries-written: 4/4  #P:8
#
#           _-----> irqs-off
#          / _----> need-resched
#         | / _---> hardirq/softirq
#         || / _--> preempt-depth
#         ||| /     delay
#         TASK-PID   CPU#  ||||   TIMESTAMP  FUNCTION
#            | |       |    ||||    |         |
    cat-1234  [003] d...  1234.567890: myprobe: (do_sys_open+0x0/0x80) dfd=0xffffff9c filename="/etc/hostname" flags=0x80000 mode=0x1ff
    cat-1234  [003] d...  1234.567920: myretprobe: (do_sys_open+0x0/0x80 <-- SyS_openat+0x14/0x20) ret=0x3

TASK-PID : Process name and PID

CPU# : CPU number

|||| : Interrupt state, scheduling state, hard/softirq context, preempt depth

TIMESTAMP : Event time in seconds (microsecond precision)

FUNCTION : Event name, probe address range, and parameter values

The myprobe line shows do_sys_open arguments: dfd=-100 (AT_FDCWD), filename="/etc/hostname", flags=0x80000 (O_RDONLY | O_LARGEFILE). The myretprobe line shows return value ret=3 (file descriptor 3).

Post-Processing Examples

Count function calls: cat trace | grep myprobe | wc -l Calculate average latency with awk:

cat trace | awk '
/myprobe:/ { start[$2] = $4; next }
/myretprobe:/ {
    pid = $2;
    if (start[pid] != "") {
        diff = $4 - start[pid];
        total += diff;
        count++;
        delete start[pid];
    }
}
END {
    if (count > 0)
        printf("count=%d, avg=%.6f us
", count, total/count*1000000);
}'

Case Study 1: High-Concurrency Network Latency

Server under high network load showed high P99 latency despite normal CPU. Used function_graph on network receive path:

cd /sys/kernel/debug/tracing
echo function_graph > current_tracer
echo 'netif_receive_skb*|ip_rcv*|tcp_v4_rcv*|tcp_*' > set_ftrace_filter
echo > trace
echo 1 > tracing_on
# Run load test 10 seconds
sleep 10
echo 0 > tracing_on
cat trace > /tmp/net_trace.txt

Analysis revealed long latency in tcp_v4_do_rcv calling __lock_sock, indicating socket lock contention. Further used kprobe on lock_sock and release_sock to measure wait time:

echo 'p:lock_enter lock_sock sk=%di' > kprobe_events
echo 'r:lock_exit lock_sock ret=$retval' >> kprobe_events
echo 1 > events/kprobes/lock_enter/enable
echo 1 > events/kprobes/lock_exit/enable

Comparing timestamps confirmed lock wait as primary latency source. Fixed by adjusting application socket usage to reduce multi-threaded contention on same socket.

Case Study 2: Kernel Module Memory Access Error

Character device module caused intermittent Oops in copy_to_user with null pointer access. Random reproduction. Traced kmalloc / kfree with kprobe:

echo 'p:kmalloc_enter kmalloc size=%di flags=%si' > kprobe_events
echo 'r:kmalloc_exit kmalloc ptr=$retval' >> kprobe_events
echo 'p:kfree_enter kfree obj=%di' >> kprobe_events
echo 1 > events/kprobes/kmalloc_enter/enable
echo 1 > events/kprobes/kmalloc_exit/enable
echo 1 > events/kprobes/kfree_enter/enable

Used set_ftrace_pid to filter target process. Trace revealed use-after-free: error path freed memory but later code still accessed via original pointer. Fixed by nulling pointer in error path; Oops disappeared.

Performance Overhead & Pitfalls

Overhead Mitigation

Ftrace and kprobe minimize overhead but can still impact high-concurrency systems. function tracer records every traced function; excessive scope (no set_ftrace_filter) degrades performance. kprobe triggers exception handling and register save on each hit; high-frequency probes increase CPU usage.

Use set_ftrace_filter to limit traced functions

Use set_ftrace_pid to trace specific processes only

Shorten tracing windows — enable only during problem reproduction

Avoid kprobe on scheduler, interrupt handlers, or other extremely hot paths

Recursion Hazard

If a kprobe handler calls the probed function (e.g., printk inside a printk probe), infinite recursion occurs, causing kernel stack overflow and crash.

Never call functions that may hit the same probe in handlers

Use trace_printk instead of printk (writes to ftrace ring buffer, bypasses printk path)

Check context at handler entry; use kprobe disarm to temporarily disable probe if needed

Symbol Resolution Issues

kprobe relies on kernel symbol table. Failures occur when:

Function is static and not in exported symbols — still findable via /proc/kallsyms if present

Function inlined by compiler — no independent entry; must probe caller at offset of inlined code CONFIG_KALLSYMS_ALL=n — only exported symbols visible; unexported functions unresolvable by name

Verify symbol existence: grep ' do_sys_open$' /proc/kallsyms Empty output means symbol unavailable; choose another function or locate address via vmlinux disassembly and register kprobe by address.

Probe Placement Restrictions

kprobe cannot instrument all instruction locations:

x86: Not on int3 itself, middle of jump instructions, certain system instructions

ARM64: Not between ADRP/ADD pairs, load/store exclusive instructions

All arches: Not on kprobe's own handler code paths

Registration returning -EINVAL or -ENOENT usually means unsupported address. Try offset a few bytes from function entry or pick a nearby function.

kretprobe maxactive Sizing

Each concurrent function invocation needs a kretprobe_instance. maxactive sets the limit; exceeding it drops probes and logs warnings. For functions running concurrently on multiple CPUs, set maxactive = num_possible_cpus() * 2 or higher. For functions that may sleep, increase further since instances aren't released during sleep.