* [PATCH] tracing: Fix rcu splat from idle CPU on boot.
@ 2015-09-03 21:29 Philipp Schrader
2015-09-04 20:09 ` [PATCH v2] " Philipp Schrader
0 siblings, 1 reply; 5+ messages in thread
From: Philipp Schrader @ 2015-09-03 21:29 UTC (permalink / raw)
To: linux-kernel; +Cc: ingo, tglx, Philipp Schrader
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] [<c00196b8>] (unwind_backtrace) from [<c001515c>]
(show_stack+0x20/0x24)
[ 0.055146] [<c001515c>] (show_stack) from [<c07bc408>]
(dump_stack+0x84/0xa0)
[ 0.055160] [<c07bc408>] (dump_stack) from [<c009bc38>]
(lockdep_rcu_suspicious+0xb0/0x110)
[ 0.055172] [<c009bc38>] (lockdep_rcu_suspicious) from [<c01246c4>]
(time_hardirqs_off+0x2b8/0x3c8)
[ 0.055184] [<c01246c4>] (time_hardirqs_off) from [<c009a218>]
(trace_hardirqs_off_caller+0x2c/0xf4)
[ 0.055194] [<c009a218>] (trace_hardirqs_off_caller) from
[<c009a2f4>] (trace_hardirqs_off+0x14/0x18)
[ 0.055204] [<c009a2f4>] (trace_hardirqs_off) from [<c00c7ecc>]
(rcu_idle_enter+0x78/0xcc)
[ 0.055213] [<c00c7ecc>] (rcu_idle_enter) from [<c0093eb0>]
(cpu_startup_entry+0x190/0x518)
[ 0.055222] [<c0093eb0>] (cpu_startup_entry) from [<c07b95b4>]
(rest_init+0x13c/0x17c)
[ 0.055231] [<c07b95b4>] (rest_init) from [<c0b32c74>]
(start_kernel+0x320/0x380)
[ 0.055238] [<c0b32c74>] (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.
---
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH v2] tracing: Fix rcu splat from idle CPU on boot.
2015-09-03 21:29 [PATCH] tracing: Fix rcu splat from idle CPU on boot Philipp Schrader
@ 2015-09-04 20:09 ` Philipp Schrader
2015-12-14 19:07 ` [PATCH v3] " Philipp Schrader
0 siblings, 1 reply; 5+ messages in thread
From: Philipp Schrader @ 2015-09-04 20:09 UTC (permalink / raw)
To: linux-kernel; +Cc: mingo, tglx, Philipp Schrader
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] [<c00196b8>] (unwind_backtrace) from [<c001515c>]
(show_stack+0x20/0x24)
[ 0.055146] [<c001515c>] (show_stack) from [<c07bc408>]
(dump_stack+0x84/0xa0)
[ 0.055160] [<c07bc408>] (dump_stack) from [<c009bc38>]
(lockdep_rcu_suspicious+0xb0/0x110)
[ 0.055172] [<c009bc38>] (lockdep_rcu_suspicious) from [<c01246c4>]
(time_hardirqs_off+0x2b8/0x3c8)
[ 0.055184] [<c01246c4>] (time_hardirqs_off) from [<c009a218>]
(trace_hardirqs_off_caller+0x2c/0xf4)
[ 0.055194] [<c009a218>] (trace_hardirqs_off_caller) from
[<c009a2f4>] (trace_hardirqs_off+0x14/0x18)
[ 0.055204] [<c009a2f4>] (trace_hardirqs_off) from [<c00c7ecc>]
(rcu_idle_enter+0x78/0xcc)
[ 0.055213] [<c00c7ecc>] (rcu_idle_enter) from [<c0093eb0>]
(cpu_startup_entry+0x190/0x518)
[ 0.055222] [<c0093eb0>] (cpu_startup_entry) from [<c07b95b4>]
(rest_init+0x13c/0x17c)
[ 0.055231] [<c07b95b4>] (rest_init) from [<c0b32c74>]
(start_kernel+0x320/0x380)
[ 0.055238] [<c0b32c74>] (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 <philipp@peloton-tech.com>
---
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* [PATCH v3] tracing: Fix rcu splat from idle CPU on boot.
2015-09-04 20:09 ` [PATCH v2] " Philipp Schrader
@ 2015-12-14 19:07 ` Philipp Schrader
2015-12-14 19:12 ` Philipp Schrader
2015-12-22 14:46 ` Sebastian Andrzej Siewior
0 siblings, 2 replies; 5+ messages in thread
From: Philipp Schrader @ 2015-12-14 19:07 UTC (permalink / raw)
To: linux-kernel; +Cc: mingo, tglx, philipp
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] [<c00196b8>] (unwind_backtrace) from [<c001515c>]
(show_stack+0x20/0x24)
[ 0.055146] [<c001515c>] (show_stack) from [<c07bc408>]
(dump_stack+0x84/0xa0)
[ 0.055160] [<c07bc408>] (dump_stack) from [<c009bc38>]
(lockdep_rcu_suspicious+0xb0/0x110)
[ 0.055172] [<c009bc38>] (lockdep_rcu_suspicious) from [<c01246c4>]
(time_hardirqs_off+0x2b8/0x3c8)
[ 0.055184] [<c01246c4>] (time_hardirqs_off) from [<c009a218>]
(trace_hardirqs_off_caller+0x2c/0xf4)
[ 0.055194] [<c009a218>] (trace_hardirqs_off_caller) from
[<c009a2f4>] (trace_hardirqs_off+0x14/0x18)
[ 0.055204] [<c009a2f4>] (trace_hardirqs_off) from [<c00c7ecc>]
(rcu_idle_enter+0x78/0xcc)
[ 0.055213] [<c00c7ecc>] (rcu_idle_enter) from [<c0093eb0>]
(cpu_startup_entry+0x190/0x518)
[ 0.055222] [<c0093eb0>] (cpu_startup_entry) from [<c07b95b4>]
(rest_init+0x13c/0x17c)
[ 0.055231] [<c07b95b4>] (rest_init) from [<c0b32c74>]
(start_kernel+0x320/0x380)
[ 0.055238] [<c0b32c74>] (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 <philipp@peloton-tech.com>
Acked-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
---
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
^ permalink raw reply related [flat|nested] 5+ messages in thread
* Re: [PATCH v3] tracing: Fix rcu splat from idle CPU on boot.
2015-12-14 19:07 ` [PATCH v3] " Philipp Schrader
@ 2015-12-14 19:12 ` Philipp Schrader
2015-12-22 14:46 ` Sebastian Andrzej Siewior
1 sibling, 0 replies; 5+ messages in thread
From: Philipp Schrader @ 2015-12-14 19:12 UTC (permalink / raw)
To: linux-kernel
Cc: mingo, Thomas Gleixner, Philipp Schrader, Paul McKenney,
Sebastian Andrzej Siewior
On Mon, Dec 14, 2015 at 11:07 AM, Philipp Schrader
<philipp@peloton-tech.com> wrote:
> 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] [<c00196b8>] (unwind_backtrace) from [<c001515c>]
> (show_stack+0x20/0x24)
> [ 0.055146] [<c001515c>] (show_stack) from [<c07bc408>]
> (dump_stack+0x84/0xa0)
> [ 0.055160] [<c07bc408>] (dump_stack) from [<c009bc38>]
> (lockdep_rcu_suspicious+0xb0/0x110)
> [ 0.055172] [<c009bc38>] (lockdep_rcu_suspicious) from [<c01246c4>]
> (time_hardirqs_off+0x2b8/0x3c8)
> [ 0.055184] [<c01246c4>] (time_hardirqs_off) from [<c009a218>]
> (trace_hardirqs_off_caller+0x2c/0xf4)
> [ 0.055194] [<c009a218>] (trace_hardirqs_off_caller) from
> [<c009a2f4>] (trace_hardirqs_off+0x14/0x18)
> [ 0.055204] [<c009a2f4>] (trace_hardirqs_off) from [<c00c7ecc>]
> (rcu_idle_enter+0x78/0xcc)
> [ 0.055213] [<c00c7ecc>] (rcu_idle_enter) from [<c0093eb0>]
> (cpu_startup_entry+0x190/0x518)
> [ 0.055222] [<c0093eb0>] (cpu_startup_entry) from [<c07b95b4>]
> (rest_init+0x13c/0x17c)
> [ 0.055231] [<c07b95b4>] (rest_init) from [<c0b32c74>]
> (start_kernel+0x320/0x380)
> [ 0.055238] [<c0b32c74>] (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 <philipp@peloton-tech.com>
> Acked-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> ---
> 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
>
Including Paul E. McKenney and Sebastian Andrzej Siewior.
^ permalink raw reply [flat|nested] 5+ messages in thread
* Re: [PATCH v3] tracing: Fix rcu splat from idle CPU on boot.
2015-12-14 19:07 ` [PATCH v3] " Philipp Schrader
2015-12-14 19:12 ` Philipp Schrader
@ 2015-12-22 14:46 ` Sebastian Andrzej Siewior
1 sibling, 0 replies; 5+ messages in thread
From: Sebastian Andrzej Siewior @ 2015-12-22 14:46 UTC (permalink / raw)
To: Philipp Schrader; +Cc: linux-kernel, mingo, tglx, paulmck, rostedt
On 2015-12-14 11:07:09 [-0800], Philipp Schrader wrote:
> 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!
…
> 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 <philipp@peloton-tech.com>
> Acked-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
I'm taking this for -RT. Is my assumption correct, that this goes into
the v4.5 merge window once everybody is back from holidays?
Sebastian
^ permalink raw reply [flat|nested] 5+ messages in thread
end of thread, other threads:[~2015-12-22 14:46 UTC | newest]
Thread overview: 5+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2015-09-03 21:29 [PATCH] tracing: Fix rcu splat from idle CPU on boot Philipp Schrader
2015-09-04 20:09 ` [PATCH v2] " Philipp Schrader
2015-12-14 19:07 ` [PATCH v3] " Philipp Schrader
2015-12-14 19:12 ` Philipp Schrader
2015-12-22 14:46 ` Sebastian Andrzej Siewior
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox