DEV Community

Cover image for [ftrace] echo: write error: Invalid argument
Chris Choe
Chris Choe

Posted on

[ftrace] echo: write error: Invalid argument

#ftrace #kernel #raspberrypi

🐧 Debugging ftrace Filter Issue on Raspberry Pi Kernel 6.12

I was debugging the interrupt handling path on Raspberry Pi kernel 6.12 when something unexpected happened β€” a command that worked perfectly on 4.19 suddenly failed.

I tried to inspect the call stack of the show_interrupts() function by running cat /proc/interrupts.

πŸ”§ My Setup

  • Board: Raspberry Pi 4 Model B (8GB)
  • Storage: NVMe 256GB (via USB enclosure)
  • Kernel: 6.12 (built on Ubuntu host with GCC 12)
  • Build script: build_rpi_kernel_arm64_on_host.sh

❌ The Problem

I ran a script, but encountered the following issue:

echo secondary_start_kernel > /sys/kernel/debug/tracing/set_ftrace_filter

# output
echo: write error: Invalid argument
Enter fullscreen mode Exit fullscreen mode

πŸ” Investigation

βœ… Step 1: Check if the function exists in ftrace filter list

I checked several points step by step to identify the root cause:

  • Does available_filter_functions include secondary_start_kernel? 
$ sudo cat /sys/kernel/debug/tracing/available_filter_functions | grep secondary_start_kernel

# output : nothing
# No result means the function is not traceable by default.
# secondary_start_kernel should be present in available_filter_functions, but this symbol was not present in Raspberry pi kernel 6.12.
Enter fullscreen mode Exit fullscreen mode

  • I also checked whether the notrace attribute was enabled.

  • Notice the notrace attribute. It tells ftrace:

    β€œDon’t even think about tracing this function.”

So, the function was excluded from available_filter_functions because of notrace.

// raspberry pi 4.19 arm

/*
 * This is the secondary CPU boot entry.  We're using this CPUs
 * idle thread stack, but a set of temporary page tables.
 */
asmlinkage void secondary_start_kernel(void)
{
    struct mm_struct *mm = &init_mm;
    unsigned int cpu;
Enter fullscreen mode Exit fullscreen mode 
// raspberry pi 4.19, 6.12 arm64 : notrace option has been added

/*
 * This is the secondary CPU boot entry.  We're using this CPUs
 * idle thread stack, but a set of temporary page tables.
 */
asmlinkage notrace void secondary_start_kernel(void)
{
    u64 mpidr = read_cpuid_mpidr() & MPIDR_HWID_BITMASK;
    struct mm_struct *mm = &init_mm;
    unsigned int cpu;
Enter fullscreen mode Exit fullscreen mode

βœ… Step 2: Investigate notrace Attribute

I removed the notrace attribute from smp.c on arm64, rebuilt the kernel image, and ran the script again on the Raspberry Pi.

/*
 * This is the secondary CPU boot entry.  We're using this CPUs
 * idle thread stack, but a set of temporary page tables.
 */
asmlinkage void secondary_start_kernel(void)
{
Enter fullscreen mode Exit fullscreen mode

After removing the notrace attribute and rebuilding, the command worked as expected.

⚠ Another Problem...

Even after fixing that, the custom function rpi_get_interrupt_info() wasn’t showing in the trace log, even though the function was called from show_interrupts():

void rpi_get_interrupt_info(struct irqaction *action_p)
{
    unsigned int irq_num = action_p->irq;
    void *irq_handler = NULL;

    if (action_p->handler) {
        irq_handler = (void*)action_p->handler;
    }

    if (irq_handler) {
        trace_printk("[%s] %d: %s, irq_handler: %pS \n",
                        current->comm, irq_num, action_p->name, irq_handler);
    }
}

int show_interrupts(struct seq_file *p, void *v)
{
    static int prec;

    unsigned long flags, any_count = 0;
...
    action = desc->action;

// calling rpi_get_interrupt_info() here
    if (action)
        rpi_get_interrupt_info(action);

    if (action) {
        seq_printf(p, "  %s", action->name);
        while ((action = action->next) != NULL)
            seq_printf(p, ", %s", action->name);
    }
Enter fullscreen mode Exit fullscreen mode

I expected the rpi_get_interrupt_info() function to appear in the ftrace log, but only the show_interrupts() function was printed.

        <idle>-0       [003] d..2.  1285.195760: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sudo next_pid=1362 next_prio=120
            sudo-1362    [003] d..2.  1285.195814: sched_switch: prev_comm=sudo prev_pid=1362 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
             cat-1363    [000] d..1.  1285.196899: show_interrupts+0x278/0x3b8: [cat] 9: vgic, irq_handler: vgic_maintenance_handler+0x0/0x18 
             cat-1363    [000] d..1.  1285.196911: show_interrupts+0x278/0x3b8: [cat] 11: arch_timer, irq_handler: arch_timer_handler_phys+0x0/0x58 
             cat-1363    [000] d..1.  1285.196918: show_interrupts+0x278/0x3b8: [cat] 12: kvm guest vtimer, irq_handler: kvm_arch_timer_handler+0x0/0xf0 
             cat-1363    [000] d..1.  1285.196927: show_interrupts+0x278/0x3b8: [cat] 14: fe00b880.mailbox, irq_handler: bcm2835_mbox_irq+0x0/0xc0 
...
Enter fullscreen mode Exit fullscreen mode

βœ… Step 3: Why was rpi_get_interrupt_info() missing?

I also looked into why the rpi_get_interrupt_info() function did not show up in the ftrace log.

  • First, I verified if it was present in available_filter_functions.
    • It was present, confirming that the function itself was traceable. 
sudo cat /sys/kernel/debug/tracing/available_filter_functions | grep rpi_get_interrupt_info

# output
rpi_get_interrupt_info
Enter fullscreen mode Exit fullscreen mode
  • To gather more insights, I consulted Google and ChatGPT.
    • ChatGPT offered suggestions on various approaches I could try. 
# check trace buffer after cat /proc/interrupts, log streams were printed.
$ sudo cat /sys/kernel/debug/tracing/trace
Enter fullscreen mode Exit fullscreen mode 
// add noinline attribute to avoid that compiler handles the function as inline function during optimization step

noinline void rpi_get_interrupt_info(struct irqaction *action_p)
{
    ...
Enter fullscreen mode Exit fullscreen mode

βœ… Step 4: The Fix: Add noinline and Rebuild

After building and running the new kernel image, I was finally able to capture the complete ftrace log I was looking for.

...
             cat-876     [001] d..1.   757.580744: rpi_get_interrupt_info+0x4/0x80 <-show_interrupts+0x27c/0x398
             cat-876     [001] d..1.   757.580748: <stack trace>
 => rpi_get_interrupt_info+0x8/0x80
 => show_interrupts+0x27c/0x398
 => seq_read_iter+0x34c/0x460
 => proc_reg_read_iter+0x8c/0xe8
 => vfs_read+0x27c/0x330
 => ksys_read+0x78/0x118
 => __arm64_sys_read+0x24/0x38
 => invoke_syscall+0x50/0x120
 => el0_svc_common.constprop.0+0x48/0xf0
 => do_el0_svc+0x24/0x38
 => el0_svc+0x30/0x100
 => el0t_64_sync_handler+0x100/0x130
 => el0t_64_sync+0x190/0x198
             cat-876     [001] d..1.   757.580753: rpi_get_interrupt_info+0x24/0x80: [cat] 9: vgic, irq_handler: vgic_maintenance_handler+0x0/0x18 
             cat-876     [001] d..1.   757.580758: rpi_get_interrupt_info+0x4/0x80 <-show_interrupts+0x27c/0x398
             cat-876     [001] d..1.   757.580758: <stack trace>
Enter fullscreen mode Exit fullscreen mode

πŸ“ Key Takeaways

βœ” If echo function > set_ftrace_filter fails β†’ check for notrace
βœ” If function doesn’t appear in logs β†’ add noinline

πŸ“š Reference Book

In my learning journey, I’ve been guided by the Korean book Learning the Structure and Principles of the Linux Kernel Through Debugging (Part 1). This book walks me through the 4.19 kernel step-by-step on a Raspberry Pi, explaining subsystems and debugging in a hands-on style.

πŸ”₯ What’s next?

I’m planning to explore CONFIG_LTO impacts on ftrace and new compiler optimizations in kernel 6.x.
Stay tuned! πŸš€

Top comments (0)