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.
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.
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.
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.
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?
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?
