From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932700AbbLNTHS (ORCPT ); Mon, 14 Dec 2015 14:07:18 -0500 Received: from mail-pa0-f43.google.com ([209.85.220.43]:35244 "EHLO mail-pa0-f43.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932099AbbLNTHO (ORCPT ); Mon, 14 Dec 2015 14:07:14 -0500 Date: Mon, 14 Dec 2015 11:07:09 -0800 From: Philipp Schrader To: linux-kernel@vger.kernel.org Cc: mingo@kernel.org, tglx@linutronix.de, philipp@peloton-tech.com Subject: [PATCH v3] tracing: Fix rcu splat from idle CPU on boot. Message-ID: <20151214190709.GA19861@philipp-x250.peloton-tech.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1441397364-16883-1-git-send-email-philipp@peloton-tech.com> User-Agent: Mutt/1.5.23 (2014-03-12) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org With PREEMPT_RT and most of the lockdep-related options enabled I encountered this splat when booting our DRA7 evaluation module: [ 0.055073] [ 0.055076] =============================== [ 0.055079] [ INFO: suspicious RCU usage. ] [ 0.055084] 4.1.6+ #2 Not tainted [ 0.055086] ------------------------------- [ 0.055090] include/trace/events/hist.h:31 suspicious rcu_dereference_check() usage! [ 0.055093] [ 0.055093] other info that might help us debug this: [ 0.055093] [ 0.055097] [ 0.055097] RCU used illegally from idle CPU! [ 0.055097] rcu_scheduler_active = 1, debug_locks = 1 [ 0.055100] RCU used illegally from extended quiescent state! [ 0.055104] no locks held by swapper/0/0. [ 0.055106] [ 0.055106] stack backtrace: [ 0.055112] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.1.6+ #2 [ 0.055116] Hardware name: Generic DRA74X (Flattened Device Tree) [ 0.055130] [] (unwind_backtrace) from [] (show_stack+0x20/0x24) [ 0.055146] [] (show_stack) from [] (dump_stack+0x84/0xa0) [ 0.055160] [] (dump_stack) from [] (lockdep_rcu_suspicious+0xb0/0x110) [ 0.055172] [] (lockdep_rcu_suspicious) from [] (time_hardirqs_off+0x2b8/0x3c8) [ 0.055184] [] (time_hardirqs_off) from [] (trace_hardirqs_off_caller+0x2c/0xf4) [ 0.055194] [] (trace_hardirqs_off_caller) from [] (trace_hardirqs_off+0x14/0x18) [ 0.055204] [] (trace_hardirqs_off) from [] (rcu_idle_enter+0x78/0xcc) [ 0.055213] [] (rcu_idle_enter) from [] (cpu_startup_entry+0x190/0x518) [ 0.055222] [] (cpu_startup_entry) from [] (rest_init+0x13c/0x17c) [ 0.055231] [] (rest_init) from [] (start_kernel+0x320/0x380) [ 0.055238] [] (start_kernel) from [<8000807c>] (0x8000807c) As per Steve Rotstedt's suggestion I changed the trace_* calls to trace_*_rcuidle calls. He pointed out that the trace points were getting triggered when rcu wasn't watching. Signed-off-by: Philipp Schrader Acked-by: Paul E. McKenney --- kernel/trace/trace_irqsoff.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index aaade2e..d0e1d0e 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -450,7 +450,7 @@ EXPORT_SYMBOL_GPL(stop_critical_timings); #ifdef CONFIG_PROVE_LOCKING void time_hardirqs_on(unsigned long a0, unsigned long a1) { - trace_preemptirqsoff_hist(IRQS_ON, 0); + trace_preemptirqsoff_hist_rcuidle(IRQS_ON, 0); if (!preempt_trace() && irq_trace()) stop_critical_timing(a0, a1); } @@ -459,7 +459,7 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1) { if (!preempt_trace() && irq_trace()) start_critical_timing(a0, a1); - trace_preemptirqsoff_hist(IRQS_OFF, 1); + trace_preemptirqsoff_hist_rcuidle(IRQS_OFF, 1); } #else /* !CONFIG_PROVE_LOCKING */ -- 2.1.4