[RFC patch powerpc,trace] Avoid suspicious RCU usage reporting for some tracepoints

There are a few tracepoints in the interrupt code path, which is before
irq_enter(), or after irq_exit(), like
trace_irq_entry()/trace_irq_exit() in do_IRQ(),
trace_timer_interrupt_entry()/trace_timer_interrupt_exit() in
timer_interrupt(). 

If the interrupt is from idle(), and because tracepoint contains RCU
read-side critical section, we could see following suspicious RCU usage
reported:

[  145.127743] ===============================
[  145.127747] [ INFO: suspicious RCU usage. ]
[  145.127752] 3.6.0-rc3+ #1 Not tainted
[  145.127755] -------------------------------
[  145.127759] /root/.workdir/linux/arch/powerpc/include/asm/trace.h:33
suspicious rcu_dereference_check() usage!
[  145.127765] 
[  145.127765] other info that might help us debug this:
[  145.127765] 
[  145.127771] 
[  145.127771] RCU used illegally from idle CPU!
[  145.127771] rcu_scheduler_active = 1, debug_locks = 0
[  145.127777] RCU used illegally from extended quiescent state!
[  145.127781] no locks held by swapper/0/0.
[  145.127785] 
[  145.127785] stack backtrace:
[  145.127789] Call Trace:
[  145.127796] [c00000000108b530] [c000000000013c40] .show_stack
+0x70/0x1c0 (unreliable)
[  145.127806] [c00000000108b5e0]
[c0000000000f59d8] .lockdep_rcu_suspicious+0x118/0x150
[  145.127813] [c00000000108b680] [c00000000000fc58] .do_IRQ+0x498/0x500
[  145.127820] [c00000000108b750] [c000000000003950]
hardware_interrupt_common+0x150/0x180
[  145.127828] --- Exception: 501 at .plpar_hcall_norets+0x84/0xd4
[  145.127828]     LR = .check_and_cede_processor+0x38/0x70
[  145.127836] [c00000000108bab0] [c0000000000665dc] .shared_cede_loop
+0x5c/0x100
[  145.127844] [c00000000108bb70] [c000000000588ab0] .cpuidle_enter
+0x30/0x50
[  145.127850] [c00000000108bbe0]
[c000000000588b0c] .cpuidle_enter_state+0x3c/0xb0
[  145.127857] [c00000000108bc60] [c000000000589730] .cpuidle_idle_call
+0x150/0x6c0
[  145.127863] [c00000000108bd30] [c000000000058440] .pSeries_idle
+0x10/0x40
[  145.127870] [c00000000108bda0] [c00000000001683c] .cpu_idle
+0x18c/0x2d0
[  145.127876] [c00000000108be60] [c00000000000b434] .rest_init
+0x124/0x1b0
[  145.127884] [c00000000108bef0] [c0000000009d0d28] .start_kernel
+0x568/0x588
[  145.127890] [c00000000108bf90] [c000000000009660] .start_here_common
+0x20/0x40

This is because the RCU usage in interrupt context should be used in
area marked by rcu_irq_enter()/rcu_irq_exit(), called in
irq_enter()/irq_exit() respectively. 

Could we add a new tracepoint trace_***_rcuirq, like trace_***_rcuidle
to avoid the report? like the code attached below.

Or could we just move these tracepoints inside the
irq_enter()/irq_exit() area? (Seems not good for the timer_interrupt
case). 

Thanks, Zhong

Signed-off-by: Li Zhong <redacted>
---
 arch/powerpc/kernel/irq.c  |    4 ++--
 arch/powerpc/kernel/time.c |    4 ++--
 include/linux/tracepoint.h |   10 ++++++++++
 3 files changed, 14 insertions(+), 4 deletions(-)

diff --git a/arch/powerpc/kernel/irq.c b/arch/powerpc/kernel/irq.c
index 1f017bb..f0ac4e7 100644
--- a/arch/powerpc/kernel/irq.c
+++ b/arch/powerpc/kernel/irq.c

@@ -489,7 +489,7 @@ void do_IRQ(struct pt_regs *regs)
 	struct pt_regs *old_regs = set_irq_regs(regs);
 	unsigned int irq;
 
-	trace_irq_entry(regs);
+	trace_irq_entry_rcuirq(regs);
 
 	irq_enter();
 

@@ -514,7 +514,7 @@ void do_IRQ(struct pt_regs *regs)
 	irq_exit();
 	set_irq_regs(old_regs);
 
-	trace_irq_exit(regs);
+	trace_irq_exit_rcuirq(regs);
 }
 
 void __init init_IRQ(void)

diff --git a/arch/powerpc/kernel/time.c b/arch/powerpc/kernel/time.c
index e49e931..cbd6607 100644
--- a/arch/powerpc/kernel/time.c
+++ b/arch/powerpc/kernel/time.c

@@ -493,7 +493,7 @@ void timer_interrupt(struct pt_regs * regs)
 	 */
 	may_hard_irq_enable();
 
-	trace_timer_interrupt_entry(regs);
+	trace_timer_interrupt_entry_rcuirq(regs);
 
 	__get_cpu_var(irq_stat).timer_irqs++;
 

@@ -532,7 +532,7 @@ void timer_interrupt(struct pt_regs * regs)
 	irq_exit();
 	set_irq_regs(old_regs);
 
-	trace_timer_interrupt_exit(regs);
+	trace_timer_interrupt_exit_rcuirq(regs);
 }
 
 /*

diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index 802de56..f7672d5 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h

@@ -161,6 +161,16 @@ static inline void tracepoint_synchronize_unregister(void)
 				rcu_idle_exit(),			\
 				rcu_idle_enter());			\
 	}								\
+	static inline void trace_##name##_rcuirq(proto)			\
+	{								\
+		if (static_key_false(&__tracepoint_##name.key))		\
+			__DO_TRACE(&__tracepoint_##name,		\
+				TP_PROTO(data_proto),			\
+				TP_ARGS(data_args),			\
+				TP_CONDITION(cond),			\
+				rcu_irq_enter(),			\
+				rcu_irq_exit());			\
+	}								\
 	static inline int						\
 	register_trace_##name(void (*probe)(data_proto), void *data)	\
 	{								\

-- 
1.7.1

On Mon, 2012-09-10 at 12:58 +0800, Li Zhong wrote:

There are a few tracepoints in the interrupt code path, which is before
irq_enter(), or after irq_exit(), like
trace_irq_entry()/trace_irq_exit() in do_IRQ(),
trace_timer_interrupt_entry()/trace_timer_interrupt_exit() in
timer_interrupt(). 

If the interrupt is from idle(), and because tracepoint contains RCU
read-side critical section, we could see following suspicious RCU usage
reported:

 .../...

This is because the RCU usage in interrupt context should be used in
area marked by rcu_irq_enter()/rcu_irq_exit(), called in
irq_enter()/irq_exit() respectively. 

Could we add a new tracepoint trace_***_rcuirq, like trace_***_rcuidle
to avoid the report? like the code attached below.

Or could we just move these tracepoints inside the
irq_enter()/irq_exit() area? (Seems not good for the timer_interrupt
case). 

I'd say just move them in. Anton, any objection ?

On Mon, 2012-09-10 at 15:10 +1000, Benjamin Herrenschmidt wrote:

On Mon, 2012-09-10 at 12:58 +0800, Li Zhong wrote:

quoted

There are a few tracepoints in the interrupt code path, which is before
irq_enter(), or after irq_exit(), like
trace_irq_entry()/trace_irq_exit() in do_IRQ(),
trace_timer_interrupt_entry()/trace_timer_interrupt_exit() in
timer_interrupt(). 

If the interrupt is from idle(), and because tracepoint contains RCU
read-side critical section, we could see following suspicious RCU usage
reported:

 .../...

quoted

This is because the RCU usage in interrupt context should be used in
area marked by rcu_irq_enter()/rcu_irq_exit(), called in
irq_enter()/irq_exit() respectively. 

Could we add a new tracepoint trace_***_rcuirq, like trace_***_rcuidle
to avoid the report? like the code attached below.

Or could we just move these tracepoints inside the
irq_enter()/irq_exit() area? (Seems not good for the timer_interrupt
case). 

I'd say just move them in. Anton, any objection ?

I agree too. I'm a bit concerned about the lack of coverage the
irq_enter() and irq_exit() have in the timer interrupt:

	may_hard_irq_enable();

	trace_timer_interrupt_entry(regs);

	__get_cpu_var(irq_stat).timer_irqs++;

#if defined(CONFIG_PPC32) && defined(CONFIG_PMAC)
	if (atomic_read(&ppc_n_lost_interrupts) != 0)
		do_IRQ(regs);
#endif

	old_regs = set_irq_regs(regs);
	irq_enter();


I'm guessing that call to do_IRQ() has to do with lazy irq handling?

Anyway, there may be a reason to have the tracepoint before this call,
but I'm not sure it really is that important. It should probably be best
to move it after the irq_enter(). There's side-effects with calling
things from interrupt context outside of irq_enter/exit().

-- Steve

On Mon, 2012-09-10 at 10:02 -0400, Steven Rostedt wrote:

I agree too. I'm a bit concerned about the lack of coverage the
irq_enter() and irq_exit() have in the timer interrupt:

	may_hard_irq_enable();

	trace_timer_interrupt_entry(regs);

	__get_cpu_var(irq_stat).timer_irqs++;

#if defined(CONFIG_PPC32) && defined(CONFIG_PMAC)
	if (atomic_read(&ppc_n_lost_interrupts) != 0)
		do_IRQ(regs);
#endif

	old_regs = set_irq_regs(regs);
	irq_enter();


I'm guessing that call to do_IRQ() has to do with lazy irq handling?

Not exactly. may_hard_irq_enable() does, it will hard-enable interrupts
(while keeping them soft-disabled) if there isn't a recorded "level"
interrupt pending already (in which case it's pointless, we'll just be
interrupted again and re-disable).

The do_IRQ() hack is an old hack for ancient 32-bit powermacs who could
lose interrupts, it's a sideband mechanism we have to re-emit them,
which nowadays could probably be replaced with something more modern,
it's just that nobody ever wants to touch that code.

Anyway, there may be a reason to have the tracepoint before this call,
but I'm not sure it really is that important. It should probably be best
to move it after the irq_enter(). There's side-effects with calling
things from interrupt context outside of irq_enter/exit().

Cheers,
Ben.

Hi Ben,

quoted

Or could we just move these tracepoints inside the
irq_enter()/irq_exit() area? (Seems not good for the timer_interrupt
case). 

I'd say just move them in. Anton, any objection ?

Sounds reasonable, no objections from me.

Anton

Thank you all, this is the updated patch for your review:

There are a few tracepoints in the interrupt code path, which is before
irq_enter(), or after irq_exit(), like
trace_irq_entry()/trace_irq_exit() in do_IRQ(),
trace_timer_interrupt_entry()/trace_timer_interrupt_exit() in
timer_interrupt(). 

If the interrupt is from idle(), and because tracepoint contains RCU
read-side critical section, we could see following suspicious RCU usage
reported:

[  145.127743] ===============================
[  145.127747] [ INFO: suspicious RCU usage. ]
[  145.127752] 3.6.0-rc3+ #1 Not tainted
[  145.127755] -------------------------------
[  145.127759] /root/.workdir/linux/arch/powerpc/include/asm/trace.h:33
suspicious rcu_dereference_check() usage!
[  145.127765] 
[  145.127765] other info that might help us debug this:
[  145.127765] 
[  145.127771] 
[  145.127771] RCU used illegally from idle CPU!
[  145.127771] rcu_scheduler_active = 1, debug_locks = 0
[  145.127777] RCU used illegally from extended quiescent state!
[  145.127781] no locks held by swapper/0/0.
[  145.127785] 
[  145.127785] stack backtrace:
[  145.127789] Call Trace:
[  145.127796] [c00000000108b530] [c000000000013c40] .show_stack
+0x70/0x1c0 (unreliable)
[  145.127806] [c00000000108b5e0]
[c0000000000f59d8] .lockdep_rcu_suspicious+0x118/0x150
[  145.127813] [c00000000108b680] [c00000000000fc58] .do_IRQ+0x498/0x500
[  145.127820] [c00000000108b750] [c000000000003950]
hardware_interrupt_common+0x150/0x180
[  145.127828] --- Exception: 501 at .plpar_hcall_norets+0x84/0xd4
[  145.127828]     LR = .check_and_cede_processor+0x38/0x70
[  145.127836] [c00000000108bab0] [c0000000000665dc] .shared_cede_loop
+0x5c/0x100
[  145.127844] [c00000000108bb70] [c000000000588ab0] .cpuidle_enter
+0x30/0x50
[  145.127850] [c00000000108bbe0]
[c000000000588b0c] .cpuidle_enter_state+0x3c/0xb0
[  145.127857] [c00000000108bc60] [c000000000589730] .cpuidle_idle_call
+0x150/0x6c0
[  145.127863] [c00000000108bd30] [c000000000058440] .pSeries_idle
+0x10/0x40
[  145.127870] [c00000000108bda0] [c00000000001683c] .cpu_idle
+0x18c/0x2d0
[  145.127876] [c00000000108be60] [c00000000000b434] .rest_init
+0x124/0x1b0
[  145.127884] [c00000000108bef0] [c0000000009d0d28] .start_kernel
+0x568/0x588
[  145.127890] [c00000000108bf90] [c000000000009660] .start_here_common
+0x20/0x40

This is because the RCU usage in interrupt context should be used in
area marked by rcu_irq_enter()/rcu_irq_exit(), called in
irq_enter()/irq_exit() respectively. 

Move them into the irq_enter()/irq_exit() area to avoid the reporting.

Signed-off-by: Li Zhong <redacted>
---
 arch/powerpc/kernel/irq.c  |    8 ++++----
 arch/powerpc/kernel/time.c |    8 ++++----
 2 files changed, 8 insertions(+), 8 deletions(-)

diff --git a/arch/powerpc/kernel/irq.c b/arch/powerpc/kernel/irq.c
index 1f017bb..71413f4 100644
--- a/arch/powerpc/kernel/irq.c
+++ b/arch/powerpc/kernel/irq.c

@@ -489,10 +489,10 @@ void do_IRQ(struct pt_regs *regs)
 	struct pt_regs *old_regs = set_irq_regs(regs);
 	unsigned int irq;
 
-	trace_irq_entry(regs);
-
 	irq_enter();
 
+	trace_irq_entry(regs);
+
 	check_stack_overflow();
 
 	/*

@@ -511,10 +511,10 @@ void do_IRQ(struct pt_regs *regs)
 	else
 		__get_cpu_var(irq_stat).spurious_irqs++;
 
+	trace_irq_exit(regs);
+
 	irq_exit();
 	set_irq_regs(old_regs);
-
-	trace_irq_exit(regs);
 }
 
 void __init init_IRQ(void)

diff --git a/arch/powerpc/kernel/time.c b/arch/powerpc/kernel/time.c
index e49e931..bd693a1 100644
--- a/arch/powerpc/kernel/time.c
+++ b/arch/powerpc/kernel/time.c

@@ -493,8 +493,6 @@ void timer_interrupt(struct pt_regs * regs)
 	 */
 	may_hard_irq_enable();
 
-	trace_timer_interrupt_entry(regs);
-
 	__get_cpu_var(irq_stat).timer_irqs++;
 
 #if defined(CONFIG_PPC32) && defined(CONFIG_PMAC)

@@ -505,6 +503,8 @@ void timer_interrupt(struct pt_regs * regs)
 	old_regs = set_irq_regs(regs);
 	irq_enter();
 
+	trace_timer_interrupt_entry(regs);
+
 	if (test_irq_work_pending()) {
 		clear_irq_work_pending();
 		irq_work_run();

@@ -529,10 +529,10 @@ void timer_interrupt(struct pt_regs * regs)
 	}
 #endif
 
+	trace_timer_interrupt_exit(regs);
+
 	irq_exit();
 	set_irq_regs(old_regs);
-
-	trace_timer_interrupt_exit(regs);
 }
 
 /*

-- 
1.7.1