On Fri, Apr 17, 2020 at 03:53:27PM +0900, Masami Hiramatsu wrote:
> Hello,
>
> It seems that *arm/arm64 specific* IPI trace event has caused this issue.
> From the stacktrace, __update_max_tr() is invoked from do_idle() context.
>
> ------
> __update_max_tr(struct trace_array *tr, struct task_struct *tsk, int cpu)
> {
> [SNIP]
> /* record this tasks comm */
> tracing_record_cmdline(tsk);
> latency_fsnotify(tr); <<------here
> }
> ------
> And via latency_fsnotify(), it calls irq_work_queue().
>
> ------
> void latency_fsnotify(struct trace_array *tr)
> {
> if (!fsnotify_wq)
> return;
> /*
> * We cannot call queue_work(&tr->fsnotify_work) from here because it's
> * possible that we are called from __schedule() or do_idle(), which
> * could cause a deadlock.
> */
> irq_work_queue(&tr->fsnotify_irqwork); <<------- here
> }
> ------
> Please NOTE(*) that the above comment said that irq_work_queue()
> should be SAFE from calling in do_idle(), this means it doesn't touch
> any RCU.
>
> And the irq_work_queue() finally kicks IPI via arch_irq_work_raise()
> which causes an IPI.
>
> --------<arm64: arch/arm64/kernel/smp.c>--------
> #ifdef CONFIG_IRQ_WORK
> void arch_irq_work_raise(void)
> {
> if (__smp_cross_call)
> smp_cross_call(cpumask_of(smp_processor_id()), IPI_IRQ_WORK);
> }
> #endif
>
> static void smp_cross_call(const struct cpumask *target, unsigned int ipinr)
> {
> trace_ipi_raise(target, ipi_types[ipinr]); <<----- This
> causes a warning!
> __smp_cross_call(target, ipinr);
> }
> -------
> And trace_* macro touch the RCU. See include/linux/tracepoint.h:231
> ------
> #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \
> extern struct tracepoint __tracepoint_##name; \
> static inline void trace_##name(proto) \
> { \
> if (static_key_false(&__tracepoint_##name.key)) \
> __DO_TRACE(&__tracepoint_##name, \
> TP_PROTO(data_proto), \
> TP_ARGS(data_args), \
> TP_CONDITION(cond), 0); \
> if (IS_ENABLED(CONFIG_LOCKDEP) && (cond)) { \
> rcu_read_lock_sched_notrace(); \
> rcu_dereference_sched(__tracepoint_##name.funcs);\
> rcu_read_unlock_sched_notrace(); \
> } \
> }
> ------
>
> BTW, this ipi_raise trace event is only used in arm/arm64.
>
> $ git grep trace_ipi_raise
> arch/arm/kernel/smp.c: trace_ipi_raise_rcuidle(target, ipi_types[ipinr]);
> arch/arm64/kernel/smp.c: trace_ipi_raise(target, ipi_types[ipinr]);
> include/trace/events/ipi.h: * __tracepoint_string, ideally the same as
> used with trace_ipi_raise
> include/trace/events/ipi.h: * __tracepoint_string, ideally the same as
> used with trace_ipi_raise for
>
> Thus, this only occurs on arm64 platform, but not on x86.
>
> To fix this, maybe we need to remove this event or mark this is under
> rcu watched (but is it really watched?)
Good analysis, Masami :)
Seems to me, Arm64 should study Arm platform to change using
trace_ipi_raise_rcuidle() to work around the restriction so can allow the
event to work in idle context?
Thanks,
Leo
> 2020年4月8日(水) 18:31 Naresh Kamboju <naresh.kamboju@xxxxxxxxxx>:
>
> >
> > On arm64 qemu_arm64, juno-r2 and dragonboard-410c while running kselftest ftrace
> > on stable rc 5.5.1-rc1 to till today 5.5.16-rc2 and 5.6 found this
> > kernel warning.
> >
> > [ 386.349099] kselftest: Running tests in ftrace
> > [ 393.984018]
> > [ 393.984290] =============================
> > [ 393.984781] WARNING: suspicious RCU usage
> > [ 393.988690] 5.6.3-rc2 #1 Not tainted
> > [ 393.992679] -----------------------------
> > [ 393.996327] /usr/src/kernel/include/trace/events/ipi.h:36
> > suspicious rcu_dereference_check() usage!
> > [ 394.000241]
> > [ 394.000241] other info that might help us debug this:
> > [ 394.000241]
> > [ 394.009094]
> > [ 394.009094] RCU used illegally from idle CPU!
> > [ 394.009094] rcu_scheduler_active = 2, debug_locks = 1
> > [ 394.017084] RCU used illegally from extended quiescent state!
> > [ 394.028187] 1 lock held by swapper/3/0:
> > [ 394.033826] #0: ffff80001237b6a8 (max_trace_lock){....}, at:
> > check_critical_timing+0x7c/0x1a8
> > [ 394.037480]
> > [ 394.037480] stack backtrace:
> > [ 394.046158] CPU: 3 PID: 0 Comm: swapper/3 Not tainted 5.6.3-rc2 #1
> > [ 394.050584] Hardware name: Qualcomm Technologies, Inc. APQ 8016 SBC (DT)
> > [ 394.056663] Call trace:
> > [ 394.063515] dump_backtrace+0x0/0x1e0
> > [ 394.065686] show_stack+0x24/0x30
> > [ 394.069505] dump_stack+0xe8/0x150
> > [ 394.072805] lockdep_rcu_suspicious+0xcc/0x110
> > [ 394.076106] arch_irq_work_raise+0x208/0x210
> > [ 394.080533] __irq_work_queue_local+0x5c/0x80
> > [ 394.084959] irq_work_queue+0x38/0x78
> > [ 394.089212] __update_max_tr+0x150/0x218
> > [ 394.092858] update_max_tr_single.part.82+0x98/0x100
> > [ 394.096851] update_max_tr_single+0x1c/0x28
> > [ 394.101798] check_critical_timing+0x198/0x1a8
> > [ 394.105705] stop_critical_timings+0x128/0x148
> > [ 394.110221] cpuidle_enter_state+0x74/0x4f8
> > [ 394.114645] cpuidle_enter+0x3c/0x50
> > [ 394.118726] call_cpuidle+0x44/0x80
> > [ 394.122542] do_idle+0x22c/0x2d0
> > [ 394.125755] cpu_startup_entry+0x28/0x48
> > [ 394.129229] secondary_start_kernel+0x1b4/0x210
> >
> >
> > metadata:
> > git branch: linux-5.5.y and linux-5.6.y
> > git repo: https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux-stable-rc.git
> > kernel-config:
> > http://snapshots.linaro.org/openembedded/lkft/lkft/sumo/juno/lkft/linux-stable-rc-5.5/65/config
> >
> > Full test log,
> > 5.6 test logs,
> > https://lkft.validation.linaro.org/scheduler/job/1350627#L12612
> > https://lkft.validation.linaro.org/scheduler/job/1350731#L9509
> >
> > 5.5 test logs,
> > https://lkft.validation.linaro.org/scheduler/job/1322704#L9777
> > https://lkft.validation.linaro.org/scheduler/job/1153369#L9745
> > https://lkft.validation.linaro.org/scheduler/job/1351155#L8982
> > https://lkft.validation.linaro.org/scheduler/job/1351065#L12349
> >
> > --
> > Linaro LKFT
> > https://lkft.linaro.org
>
>
>
> --
> Masami Hiramatsu
