Re: [BUG?] tracing: unexpected behavior trying to keep IRQ code away from traces

[Steven Rostedt <rostedt@goodmis.org>]

On Mon, 7 Sep 2026 09:07:57 +0000
Lahoz Fernando <flahoz@ikerlan.es> wrote:

> Hello,
> 
> It seems that code executed during IRQ entry/exit may be traced as task context
> because HARDIRQ_OFFSET is not reflected in preempt_count until irq_enter_rcu()
> is called. As a result, both in_task() and in_hardirq() may incorrectly classify
> some IRQ-entry code, causing IRQ-related functions to appear even when IRQ
> tracing is disabled.
> 
> 
> I've been developing a minimal syscall tracer using ftrace's api from a kernel
> module. During the process I've tried to prevent interrupt-related code from
> appearing in the trace data, therefore I use the in_task() macro to filter
> everything that is not in running in "task context". However, some functions
> executed in hardirq context bypass the check, as they are executed before
> preempt_count is updated.
> 
> I was not certain whether this was a bug on how the flag is set or the intended
> behaviour, so, I traced the same code using the function-graph-tracer with
> 'funcgraph-irqs' option active, but I saw the same behaviour.

It's a bug that's been know about since 2009 :-/

Yes, because we use preempt_count to determine if an event is in interrupt
context or not, and there's some places that trigger events (function
tracer) before the preempt count is updated, we can report the wrong context.

This is well known, and is the reason behind the TRANSITION_BIT in the
recursion protection lock[1]. The recursion detection tests if an event was
triggered in the same context, and if it is, it drops the event. But it was
reported that not all entry into interrupts were traced, and that's because
if an interrupt went off while it was recording an event in task context,
the recursion would detect it as the same context recursion (not allowed)
and drop it. But once the preempt_count was updated, the rest of the
interrupt events were traced.

> 
> 
> I'm using a fully preemptive kernel, compiled for both aarch64 (this one runs
> on an evaluation board) and riscv (this one runs on qemu). I have not checked
> if it happens in any other arch. I first saw this behaviour in v6.15.5 with
> aarch64, but it's still present in v7.2.2. I have not checked older versions.

It happens on all archs that can trace before preempt_count is updated. I
detected it on x86.

> 
> 
> The root of the problem seems to be that there is instrumentable code that
> executes on every IRQ before and after HARDIRQ_OFFSET is added/substracted to
> preempt_count, so function tracers cannot correctly filter IRQ using in_hardirq().
> 
> 	(All the source I show comes from kernel v7.2.2)
> 
> 	In file: "/arch/arm64/kernel/entry-common.c" (lines 501-513)
> 
> 		static __always_inline void __el1_irq(struct pt_regs *regs,
> 		                                      void (*handler)(struct pt_regs *))
> 		{
> 			irqentry_state_t state;
> 
> 			state = arm64_enter_from_kernel_mode(regs);
> 
> 			irq_enter_rcu();  // <-- `preempt_count_add(HARDIRQ_OFFSET)`
> 			do_interrupt_handler(regs, handler);
> 			irq_exit_rcu();   // <-- `preempt_count_sub(HARDIRQ_OFFSET);`
> 
> 			arm64_exit_to_kernel_mode(regs, state);
> 		}
> 
> I've tried to wrap this function between preempt_count_add(HARDIRQ_OFFSET)
> and preempt_count_sub(HARDIRQ_OFFSET), but kernel won't finish booting up.

And you are now seeing why we haven't fixed it since 2009 ;-)

> 
> Similarly, this also happens in riscv, as it can be seen in file
> "/arch/riscv/kernel/traps.c" (lines 424-445) that irq_enter_rcu is called after
> the equivalent function to arm64_enter_from_kernel_mode.
> 
> 
> Test using function graph tracer:
> 
> As I said, I wanted to check if IRQs also appeared inside the trace file while
> option funcgraph-irqs was disabled. Ftrace's documentation
> (https://docs.kernel.org/trace/ftrace.html) decribes this parameter as follows:
> 
> 	"When disabled, functions that happen inside an interrupt will not be traced."
> 
> so I expected it to remove every function called inside __el1_irq from the trace.
> 
> I isolated CPU 3 for it to run the test program alone with taskset.
> I traced with the following configuration:
> 
> 	TRACEFS="/sys/kernel/tracing"
> 
> 	# Stop tracing and clean buffer
> 	echo 0 > "${TRACEFS}/tracing_on"
> 	: > "${TRACEFS}/trace"
> 
> 	# Trace only CPU 3 with 1GB buffer
> 	echo 8 > "${TRACEFS}/tracing_cpumask"
> 	echo 1048576 > "${TRACEFS}/per_cpu/cpu3/buffer_size_kb"
> 
> 	echo local > "${TRACEFS}/trace_clock"
> 	echo function_graph > "${TRACEFS}/current_tracer"
> 
> 	for opt in 'funcgraph-proc' 'funcgraph-tail' 'irq-info' 'nofuncgraph-irqs'; do
> 		echo "$opt" > "${TRACEFS}/trace_options"
> 	done
> 
> 	# Clean filters and trace only syscalls
> 	: > "${TRACEFS}/set_graph_function"
> 	echo "__arm64_sys_*" > "${TRACEFS}/set_graph_function"
> 
> The resulting trace shows only syscalls code, being sometimes interrupted by
> code inside __el1_irq:
> 
>  ...
>  3) randbyt-14268  |               |            mntput() {                  //__arm64_sys_openat
>  3) randbyt-14268  |               |              mntput_no_expire() {      //__arm64_sys_openat
>  3) randbyt-14268  |   1.180 us    |                __rcu_irq_enter_check_tick(); //IRQ CODE
>  3) randbyt-14268  |   1.900 us    |                irq_enter_rcu();
>  3) randbyt-14268  |   1.340 us    |                idle_cpu();
>  3) randbyt-14268  |               |                tick_nohz_irq_exit() {
>  ...
>  3) randbyt-14268  | + 13.072 us   |                } /* tick_nohz_irq_exit */
>  3) randbyt-14268  |               |                raw_irqentry_exit_cond_resched() {
>  3) randbyt-14268  |               |                  preempt_schedule_irq() {
>  ...
>  3) randbyt-14268  | + 73.637 us   |                  } /* preempt_schedule_irq */
>  3) randbyt-14268  | + 75.938 us   |                } /* raw_irqentry_exit_cond_resched */
>  3) randbyt-14268  |   0.960 us    |                __rcu_read_lock();
>  3) randbyt-14268  |   1.070 us    |                __rcu_read_unlock();    //IRQ CODE
>  3) randbyt-14268  | ! 146.225 us  |              } /* mntput_no_expire */  //__arm64_sys_openat
>  3) randbyt-14268  | ! 148.385 us  |            } /* mntput */              //__arm64_sys_openat
>  ...
> 
> >From here I suspected that funcgraph-irqs' implementation relied on the same  
> flags I checked in my custom tracer, so I searched inside the graph tracer code
> and found this early-exit condition being called from graph_entry:
> 
> 	In file: "/kernel/trace/trace_functions_graph.c" (lines 209-217)
> 
> 		static inline int ftrace_graph_ignore_irqs(struct trace_array *tr)
> 		{
> 			if (!ftrace_graph_skip_irqs || trace_recursion_test(TRACE_IRQ_BIT))
> 				return 0;
> 
> 			if (tracer_flags_is_set(tr, TRACE_GRAPH_PRINT_IRQS))
> 				return 0;
> 
> 			return in_hardirq();
> 		}
> 
> Both in_task() an in_hardirq() macros check preempt_count, which has the fault
> of not being fully set before any code executes on IRQ context.

Correct.

> 
> 
> I do not know whether preempt_count is intended to provide precise context
> information during IRQ entry/exit transitions. If not, would there be a
> recommended mechanism for tracers that need to distinguish task and IRQ contexts
> during these early entry stages?

It would require looking at the hardware flags directly *at every event*,
which would greatly impact performance of the tracer.

> 
> For my tracer I patched __el1_irq in aarch64, making it noinline instead of
> __always_inline. That way I can catch its beginning and end registering a
> ftrace_direct routine with the minimal changes to vanilla Linux.
> I have not tried any fix for riscv.
> 
> Is this behavior intentional, meaning that code executed before irq_enter_rcu()
> is considered outside hardirq context, or is this an unintended limitation of
> tracing based on preempt_count?

It's the limitation of using preempt_count to determine irq context as it
is the fastest way to do so. Basically, we just need to cope with this and
try to find other means to handle it.

Ideally, the preempt_count update would be moved to locations that happen
before any events (function or otherwise) trigger. But that is no easy
task. Maybe something you could do? ;-)

-- Steve


[1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/include/linux/trace_recursion.h#n35