From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753159AbdIURQn (ORCPT ); Thu, 21 Sep 2017 13:16:43 -0400 Received: from mx0b-001b2d01.pphosted.com ([148.163.158.5]:37119 "EHLO mx0a-001b2d01.pphosted.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1751809AbdIURQk (ORCPT ); Thu, 21 Sep 2017 13:16:40 -0400 Date: Thu, 21 Sep 2017 10:16:36 -0700 From: "Paul E. McKenney" To: Steven Rostedt Cc: LKML , Ingo Molnar Subject: Re: [PATCH] tracing: Have stack tracer call rcu_nmi_enter() only when RCU is not watching Reply-To: paulmck@linux.vnet.ibm.com References: <20170921131038.4e7a12f6@gandalf.local.home> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20170921131038.4e7a12f6@gandalf.local.home> User-Agent: Mutt/1.5.21 (2010-09-15) X-TM-AS-GCONF: 00 x-cbid: 17092117-0008-0000-0000-000002841647 X-IBM-SpamModules-Scores: X-IBM-SpamModules-Versions: BY=3.00007773; HX=3.00000241; KW=3.00000007; PH=3.00000004; SC=3.00000231; SDB=6.00920320; UDB=6.00462439; IPR=6.00700542; BA=6.00005601; NDR=6.00000001; ZLA=6.00000005; ZF=6.00000009; ZB=6.00000000; ZP=6.00000000; ZH=6.00000000; ZU=6.00000002; MB=3.00017238; XFM=3.00000015; UTC=2017-09-21 17:16:37 X-IBM-AV-DETECTION: SAVI=unused REMOTE=unused XFE=unused x-cbparentid: 17092117-0009-0000-0000-000036C6B353 Message-Id: <20170921171636.GL3521@linux.vnet.ibm.com> X-Proofpoint-Virus-Version: vendor=fsecure engine=2.50.10432:,, definitions=2017-09-21_04:,, signatures=0 X-Proofpoint-Spam-Details: rule=outbound_notspam policy=outbound score=0 spamscore=0 suspectscore=0 malwarescore=0 phishscore=0 adultscore=0 bulkscore=0 classifier=spam adjust=0 reason=mlx scancount=1 engine=8.0.1-1707230000 definitions=main-1709210233 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thu, Sep 21, 2017 at 01:10:38PM -0400, Steven Rostedt wrote: > > Testing some other code, this RCU splat triggered: > > ============================= > WARNING: suspicious RCU usage > 4.13.0-rc7-test+ #117 Tainted: G W > ----------------------------- > 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 > > What happened, was that the CPU was coming out of idle, and > rcu_dynticks_eqs_exit() was traced by the stack tracer. The stack was bigger > than the current recorded max stack so the stack tracer triggered a stack > trace calling save_stack_trace(). As save_stack_trace() performs RCU logic, > the stack tracer called rcu_irq_enter() before calling save_stack_trace(). > There is two problems here. > > 1) rcu_irq_enter() is called unconditionally > > Talking with Paul McKenney, it should only be called if rcu_is_watching() > returns false. > > 2) rcu_irq_enter() appears to not function well in this location of the RCU > internal logic (tracing rcu_dynticks_eqs_exit()), and causes this bug. > > The solution is two fold. > > 1) check if RCU is watching, and only wake RCU if it is not > (solves the first issue) > > 2) call rcu_nmi_enter() instead of rcu_irq_enter(). It makes more sense as > tracing acts more like NMIs and not IRQs (can be called when interrupts > are disabled. (solves the second issue). > > Suggested-by: "Paul E. McKenney" > Signed-off-by: Steven Rostedt (VMware) Looks good! Acked-by: "Paul E. McKenney" > --- > kernel/trace/trace_stack.c | 10 ++++++++-- > 1 file changed, 8 insertions(+), 2 deletions(-) > > diff --git a/kernel/trace/trace_stack.c b/kernel/trace/trace_stack.c > index a4df67c..2462e11 100644 > --- a/kernel/trace/trace_stack.c > +++ b/kernel/trace/trace_stack.c > @@ -77,6 +77,7 @@ check_stack(unsigned long ip, unsigned long *stack) > { > unsigned long this_size, flags; unsigned long *p, *top, *start; > static int tracer_frame; > + bool no_rcu; > int frame_size = ACCESS_ONCE(tracer_frame); > int i, x; > > @@ -104,14 +105,18 @@ check_stack(unsigned long ip, unsigned long *stack) > if (unlikely(rcu_irq_enter_disabled())) > return; > > + no_rcu = !rcu_is_watching(); > + > local_irq_save(flags); > arch_spin_lock(&stack_trace_max_lock); > > /* > * RCU may not be watching, make it see us. > * The stack trace code uses rcu_sched. > + * Note, tracing acts more like an NMI than an IRQ. > */ > - rcu_irq_enter(); > + if (no_rcu) > + rcu_nmi_enter(); > > /* In case another CPU set the tracer_frame on us */ > if (unlikely(!frame_size)) > @@ -205,7 +210,8 @@ check_stack(unsigned long ip, unsigned long *stack) > } > > out: > - rcu_irq_exit(); > + if (no_rcu) > + rcu_nmi_exit(); > arch_spin_unlock(&stack_trace_max_lock); > local_irq_restore(flags); > } > -- > 2.9.5 >