On Fri, 22 Sep 2017 15:54:55 -0700
"Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx> wrote:
> On Fri, Sep 22, 2017 at 06:15:47PM -0400, Steven Rostedt wrote:
> > From: "Steven Rostedt (VMware)" <rostedt@xxxxxxxxxxx>
> >
> > While debugging some RCU issues with the stack tracer, it was discovered
> > that the problem was much more than with the stack tracer itself, but with
> > the saving of the stack trace, which could happen from any WARN() as well.
> > The problem was fixed within kernel_text_address().
> >
> > One of the bugs that was discovered was that the stack tracer called
> > rcu_enter_irq() unconditionally. Paul McKenney said that could cause issues
> > as well. Instead of adding logic to only call rcu_enter_irq() if RCU is not
> > watching from within the stack tracer, since the core issue has been fixed
> > (within save_stack_trace()), we can simply remove all the logic in the stack
> > tracer that deals with RCU work arounds.
>
> I must confess that I am having some difficulty parsing this paragraph,
> especially the last sentence...
>
> Does this capture it?
>
> One problem is that the stack tracer called rcu_irq_enter()
> unconditionally, which is problematic if RCU's last
> not-watching-to-watching transition was carried out by
> rcu_nmi_enter. In that case, rcu_irq_enter() actually switches
I thought the rcu_irq_enter() after rcu_nmi_enter() was a separate bug.
Your original complaint was that I called rcu_irq_enter()
unconditionally, and wanted me to only call it if RCU wasn't watching.
But, the new code could possibly have this get called after
rcu_nmi_enter() because we are calling it without in_nmi() being set.
> RCU back to the not-watching state for this CPU, which results
> in lockdep splats complaining about rcu_read_lock() being
> used on an idle (not-watched) CPU. The first patch of this
> series addressed this problem by having rcu_irq_enter() and
> rcu_irq_exit() refrain from doing anything when rcu_nmi_enter()
> caused RCU to start watching this CPU. The third patch in this
> series caused save_stack_trace() to invoke rcu_nmi_enter() and
> rcu_nmi_exit() as needed, so this fourth patch now removes the
> rcu_irq_enter() and rcu_irq_exit() from within the stack tracer.
>
> One further question... Can I now remove the rcu_irq_enter_disabled()
> logic?
After this goes in. Yes. But that doesn't need to be a stable change.
>
> > Cc: "Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx>
> > Cc: stable@xxxxxxxxxxxxxxx
> > Fixes: 0be964be0 ("module: Sanitize RCU usage and locking")
> > Suggested-by: "Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx>
> > Signed-off-by: Steven Rostedt (VMware) <rostedt@xxxxxxxxxxx>
>
> With the hard-to-parse paragraph fixed:
>
> Acked-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
Thanks, but we may need to go back and forth a bit to get the change
log correct.
Remember the first bug. The one that was fixed by changing
rcu_irq_enter() to rcu_nmi_enter()?
=============================
WARNING: suspicious RCU usage
4.13.0-rc7-test+ #117 Tainted: G W
-----------------------------
/work/git/linux-trace.git/arch/x86/kernel/traps.c:305 entry code didn't wake RCU!
other info that might help us debug this:
RCU used illegally from idle CPU!
rcu_scheduler_active = 2, debug_locks = 1
RCU used illegally from extended quiescent state!
no locks held by swapper/1/0.
stack backtrace:
CPU: 1 PID: 0 Comm: swapper/1 Tainted: G W 4.13.0-rc7-test+ #117
Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
Call Trace:
dump_stack+0x86/0xcf
lockdep_rcu_suspicious+0xc5/0x100
do_error_trap+0x125/0x130
? do_error_trap+0x5/0x130
? trace_hardirqs_off_thunk+0x1a/0x1c
? do_invalid_op+0x5/0x30
do_invalid_op+0x20/0x30
invalid_op+0x1e/0x30
RIP: 0010:module_assert_mutex_or_preempt+0x34/0x40
RSP: 0018:ffffc900006abc58 EFLAGS: 00010046
RAX: 0000000000000000 RBX: ffffffffa000a077 RCX: 0000000000000002
RDX: 0000000000000000 RSI: 00000000ffffffff RDI: 0000000000000046
RBP: ffffc900006abc58 R08: ffffc900006abf40 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: ffff8801188d8040 R15: ffffffff81ed5720
? 0xffffffffa000a077
? module_assert_mutex_or_preempt+0x30/0x40
__module_address+0x2c/0xf0
? 0xffffffffa000a077
__module_text_address+0x12/0x60
? 0xffffffffa000a077
is_module_text_address+0x1f/0x50
? 0xffffffffa000a077
__kernel_text_address+0x30/0x90
unwind_get_return_address+0x1f/0x30
__save_stack_trace+0x83/0xd0
? 0xffffffffa000a077
? rcu_dynticks_eqs_exit+0x5/0x40
save_stack_trace+0x1b/0x20
check_stack+0xf8/0x2f0
? rcu_dynticks_eqs_enter+0x30/0x30
stack_trace_call+0x6e/0x80
0xffffffffa000a077
? ftrace_graph_caller+0x78/0xa8
? rcu_dynticks_eqs_exit+0x5/0x40
rcu_dynticks_eqs_exit+0x5/0x40
rcu_idle_exit+0xdf/0xf0
? rcu_dynticks_eqs_exit+0x5/0x40
? rcu_idle_exit+0xdf/0xf0
do_idle+0x128/0x200
cpu_startup_entry+0x1d/0x20
start_secondary+0x108/0x130
secondary_startup_64+0x9f/0x9f
This was caused by just using rcu_irq_enter(). Not sure if this will
still be an issue or not. But because we now add an rcu_nmi_enter()
without being in_nmi(), we probably should do this. This code doesn't
run if in_nmi() is true, but it could run from the stack trace dump
itself, and that now calls rcu_nmi_enter().
Actually, thinking about this more, this doesn't need to go in stable.
As recursive rcu_irq_enter() calls should not hurt, and you now allow
rcu_irq_enter() to be called even after a rcu_nmi_enter() right?
-- Steve