Skip to contentSkip to conversation

fix RCU stall warning on ARM

RFC PATCH In review Frank Rowand 2 participants 7 messages Dec 5, 2012 – Dec 10, 2012

Subsystems (2)
Arm (32-bit) Proc sysctl
lore
Share & tools
lore

Frank Rowand

author
#0 lore raw

cover fix RCU stall warning on ARM

The RCU stall warning functions call trigger_all_cpu_backtrace() to print a backtrace on each cpu. This function is only implemented for x86. Add a version for ARM.

With CONFIG_PREEMPT_RT_FULL enabled, flushing the output from printk() is inhibited in some contexts to avoid increasing real time latencies. The RCU stall warnings are inhibited on ARM due to this feature. (I have not tested whether this is also the case on other architectures.) Add back the oops_in_progress flag to allow the RCU stall warnings to print immediately.

A third patch contains test scaffolding to force the stall warnings to occur so that the other patches can be tested. The third patch should __not__ added to the mainline RT PREEMPT patch tree.

These patches apply to 3.6.7-rt18. They do not apply cleanly to 3.0.xx.

author
#1 lore raw

RFC PATCH 1/2 ARM version of arch_trigger_all_cpu_backtrace()

The RCU stall warning functions print_cpu_stall() and print_other_cpu_stall() call trigger_all_cpu_backtrace() to print a backtrace on each cpu. This function is only implemented for x86. Add a version for ARM.

Signed-off-by Frank Rowand <[email protected]>

---

 arch/arm/include/asm/hardirq.h |    2 	1 +	1 -	0 !
 arch/arm/include/asm/irq.h     |    5 	5 +	0 -	0 !
 arch/arm/kernel/smp.c          |   70 	70 +	0 -	0 !
 3 files changed, 76 insertions(+), 1 deletion(-)
arch/arm/include/asm/irq.h +5 -0
Index: b/arch/arm/include/asm/irq.h
===================================================================
@@ -30,6 +30,11 @@ extern void asm_do_IRQ(unsigned int, str
 void handle_IRQ(unsigned int, struct pt_regs *);
 void init_IRQ(void);
 
+#ifdef CONFIG_SMP
+void arch_trigger_all_cpu_backtrace(void);
+#define arch_trigger_all_cpu_backtrace arch_trigger_all_cpu_backtrace
+#endif
+
 #endif
 
 #endif
arch/arm/kernel/smp.c +70 -0

94 lines not on this page · raw message

arch/arm/include/asm/hardirq.h +1 -1
Index: b/arch/arm/include/asm/hardirq.h
===================================================================
@@ -5,7 +5,7 @@
 #include <linux/threads.h>
 #include <asm/irq.h>
 
-#define NR_IPI	5
+#define NR_IPI	6
 
 typedef struct {
 	unsigned int __softirq_pending;
author
#2 lore raw

RFC PATCH 2/2 let RCU stall messages escape with CONFIG_PREEMPT_RT_FULL

In reply to Frank Rowand

The printk()s in RCU stall warnings do not get flushed to the console on ARM. Add the oops_in_progress flag back into the special trylock case in console_trylock_for_printk(), and set the flag using "bust_spinlocks(1)". This allows the printk() output to be flushed to the console.

Signed-off-by Frank Rowand <[email protected]>

---
kernel/printk.c | 5 3 + 2 - 0 !
kernel/rcutree.c | 14 14 + 0 - 0 !

 2 files changed, 17 insertions(+), 2 deletions(-)
kernel/printk.c +3 -2
Index: b/kernel/printk.c
===================================================================
@@ -1390,8 +1390,9 @@ static int console_trylock_for_printk(un
 {
 	int retval = 0, wake = 0;
 #ifdef CONFIG_PREEMPT_RT_FULL
-	int lock = !early_boot_irqs_disabled && !irqs_disabled_flags(flags) &&
-		(preempt_count() <= 1);
+	int lock = oops_in_progress || (
+		!early_boot_irqs_disabled && !irqs_disabled_flags(flags) &&
+		(preempt_count() <= 1));
 #else
 	int lock = 1;
 #endif
kernel/rcutree.c +14 -0
Index: b/kernel/rcutree.c
===================================================================
@@ -758,6 +758,11 @@ static void print_other_cpu_stall(struct
 	raw_spin_unlock_irqrestore(&rnp->lock, flags);
 
 	/*
+	 * Allow printk() to flush to device
+	 */
+	bust_spinlocks(1);
+
+	/*
 	 * OK, time to rat on our buddy...
 	 * See Documentation/RCU/stallwarn.txt for info on how to debug
 	 * RCU CPU stall warnings.

@@ -799,6 +804,8 @@ static void print_other_cpu_stall(struct
 
 	rcu_print_detail_task_stall(rsp);
 
+	bust_spinlocks(0);
+
 	force_quiescent_state(rsp, 0);  /* Kick them all. */
 }
 

@@ -808,6 +815,11 @@ static void print_cpu_stall(struct rcu_s
 	struct rcu_node *rnp = rcu_get_root(rsp);
 
 	/*
+	 * Allow printk() to flush to device
+	 */
+	bust_spinlocks(1);
+
+	/*
 	 * OK, time to rat on ourselves...
 	 * See Documentation/RCU/stallwarn.txt for info on how to debug
 	 * RCU CPU stall warnings.

@@ -820,6 +832,8 @@ static void print_cpu_stall(struct rcu_s
 	if (!trigger_all_cpu_backtrace())
 		dump_stack();
 
+	bust_spinlocks(0);
+
 	raw_spin_lock_irqsave(&rnp->lock, flags);
 	if (ULONG_CMP_GE(jiffies, rsp->jiffies_stall))
 		rsp->jiffies_stall = jiffies +
#3 lore raw

Re: [PATCH RT 2/2][RFC] let RCU stall messages escape with CONFIG_PREEMPT_RT_FULL

Quoted 7 lines · Frank Rowand

The printk()s in RCU stall warnings do not get flushed to the console on ARM. Add the oops_in_progress flag back into the special trylock case in console_trylock_for_printk(), and set the flag using "bust_spinlocks(1)". This allows the printk() output to be flushed to the console.

Signed-off-by Frank Rowand <[email protected]>

Is bust_spinlocks(1) appropriate for all architectures, or should this be conditioned on architectures that need oops_in_progress to be set?

Thanx, Paul

Quoted 68 lines

---
kernel/printk.c | 5 3 + 2 - 0 !
kernel/rcutree.c | 14 14 + 0 - 0 !

 2 files changed, 17 insertions(+), 2 deletions(-)

Index: b/kernel/printk.c
===================================================================

kernel/printk.c +3 -2
@@ -1390,8 +1390,9 @@ static int console_trylock_for_printk(un
 {
 	int retval = 0, wake = 0;
 #ifdef CONFIG_PREEMPT_RT_FULL
-	int lock = !early_boot_irqs_disabled && !irqs_disabled_flags(flags) &&
-		(preempt_count() <= 1);
+	int lock = oops_in_progress || (
+		!early_boot_irqs_disabled && !irqs_disabled_flags(flags) &&
+		(preempt_count() <= 1));
 #else
 	int lock = 1;
 #endif

Index: b/kernel/rcutree.c
===================================================================

kernel/rcutree.c +14 -0
@@ -758,6 +758,11 @@ static void print_other_cpu_stall(struct
 	raw_spin_unlock_irqrestore(&rnp->lock, flags);
 
 	/*
+	 * Allow printk() to flush to device
+	 */
+	bust_spinlocks(1);
+
+	/*
 	 * OK, time to rat on our buddy...
 	 * See Documentation/RCU/stallwarn.txt for info on how to debug
 	 * RCU CPU stall warnings.

@@ -799,6 +804,8 @@ static void print_other_cpu_stall(struct
 
 	rcu_print_detail_task_stall(rsp);
 
+	bust_spinlocks(0);
+
 	force_quiescent_state(rsp, 0);  /* Kick them all. */
 }
 

@@ -808,6 +815,11 @@ static void print_cpu_stall(struct rcu_s
 	struct rcu_node *rnp = rcu_get_root(rsp);
 
 	/*
+	 * Allow printk() to flush to device
+	 */
+	bust_spinlocks(1);
+
+	/*
 	 * OK, time to rat on ourselves...
 	 * See Documentation/RCU/stallwarn.txt for info on how to debug
 	 * RCU CPU stall warnings.

@@ -820,6 +832,8 @@ static void print_cpu_stall(struct rcu_s
 	if (!trigger_all_cpu_backtrace())
 		dump_stack();
 
+	bust_spinlocks(0);
+
 	raw_spin_lock_irqsave(&rnp->lock, flags);
 	if (ULONG_CMP_GE(jiffies, rsp->jiffies_stall))
 		rsp->jiffies_stall = jiffies +
author
#4 lore raw

Re: [PATCH RT 2/2][RFC] let RCU stall messages escape with CONFIG_PREEMPT_RT_FULL

Quoted 7 lines · Paul E. McKenney
Quoted 6 lines · Frank Rowand

The printk()s in RCU stall warnings do not get flushed to the console on ARM. Add the oops_in_progress flag back into the special trylock case in console_trylock_for_printk(), and set the flag using "bust_spinlocks(1)". This allows the printk() output to be flushed to the console.

Quoted 6 lines
Quoted 1 line
Signed-off-by Frank Rowand <[email protected]>

Is bust_spinlocks(1) appropriate for all architectures, or should this be conditioned on architectures that need oops_in_progress to be set?

Thanx, Paul

Good question. I don't know if the architectures that do not set oops_in_progress do not need it, or if they just overlooked it. I'll have to look a little bit deeper.

-Frank

author
#5 lore raw
In reply to Frank Rowand

This patch should __not__ be committed to the RT_PREEMPT tree.

Test scaffolding to force printing of rcu detected stall. Each time the specified value is echoed into the proc file, the routine to be tested will be called one time, from the context it would normally be called from.

   # test print_cpu_stall()
   echo 1 > /proc/sys/kernel/zzz_debug_print_stall_once
   # test print_other_cpu_stall()
   echo 2 > /proc/sys/kernel/zzz_debug_print_stall_once
Signed-off-by Frank Rowand <[email protected]>

---

 kernel/rcutree.c |   26 	26 +	0 -	0 !
 kernel/sysctl.c  |   11 	11 +	0 -	0 !
 2 files changed, 37 insertions(+)
kernel/rcutree.c +26 -0
Index: b/kernel/rcutree.c
===================================================================
@@ -738,6 +738,7 @@ static void record_gp_stall_check_time(s
 	rsp->jiffies_stall = jiffies + jiffies_till_stall_check();
 }
 
+int zzz_debug_print_other_cpu_stall;
 static void print_other_cpu_stall(struct rcu_state *rsp)
 {
 	int cpu;

@@ -750,10 +751,12 @@ static void print_other_cpu_stall(struct
 
 	raw_spin_lock_irqsave(&rnp->lock, flags);
 	delta = jiffies - rsp->jiffies_stall;
+if (!zzz_debug_print_other_cpu_stall) {
 	if (delta < RCU_STALL_RAT_DELAY || !rcu_gp_in_progress(rsp)) {
 		raw_spin_unlock_irqrestore(&rnp->lock, flags);
 		return;
 	}
+}
 	rsp->jiffies_stall = jiffies + 3 * jiffies_till_stall_check() + 3;
 	raw_spin_unlock_irqrestore(&rnp->lock, flags);
 

@@ -792,6 +795,10 @@ static void print_other_cpu_stall(struct
 	ndetected += rcu_print_task_stall(rnp);
 	raw_spin_unlock_irqrestore(&rnp->lock, flags);
 
+if (zzz_debug_print_other_cpu_stall) {
+	ndetected += 1;
+}
+
 	print_cpu_stall_info_end();
 	printk(KERN_CONT "(detected by %d, t=%ld jiffies)\n",
 	       smp_processor_id(), (long)(jiffies - rsp->gp_start));

@@ -843,6 +850,7 @@ static void print_cpu_stall(struct rcu_s
 	set_need_resched();  /* kick ourselves to get things going. */
 }
 
+int zzz_debug_print_stall_once;
 static void check_cpu_stall(struct rcu_state *rsp, struct rcu_data *rdp)
 {
 	unsigned long j;

@@ -851,6 +859,24 @@ static void check_cpu_stall(struct rcu_s
 
 	if (rcu_cpu_stall_suppress)
 		return;
+
+	if (zzz_debug_print_stall_once) {
+		int tmp = zzz_debug_print_stall_once;
+		zzz_debug_print_stall_once = 0;
+		if (tmp & 0x1) {
+			pr_crit("\n\n*****  DEBUG -- test print_cpu_stall():\n\n");
+			print_cpu_stall(rsp);
+		}
+		if (tmp & 0x2) {
+			pr_crit("\n\n*****  DEBUG -- test print_other_cpu_stall():\n\n");
+			zzz_debug_print_other_cpu_stall = 1;
+			print_other_cpu_stall(rsp);
+			zzz_debug_print_other_cpu_stall = 0;
+		}
+
+		return;
+	}
+
 	j = ACCESS_ONCE(jiffies);
 	js = ACCESS_ONCE(rsp->jiffies_stall);
 	rnp = rdp->mynode;
kernel/sysctl.c +11 -0
Index: b/kernel/sysctl.c
===================================================================
@@ -132,6 +132,8 @@ static int one_hundred = 100;
 static int ten_thousand = 10000;
 #endif
 
+extern int zzz_debug_print_stall_once;
+
 /* this is needed for the proc_doulongvec_minmax of vm_dirty_bytes */
 static unsigned long dirty_bytes_min = 2 * PAGE_SIZE;
 

@@ -1000,6 +1002,15 @@ static struct ctl_table kern_table[] = {
 		.proc_handler	= proc_dointvec,
 	},
 #endif
+#ifdef CONFIG_SMP
+	{
+		.procname	= "zzz_debug_print_stall_once",
+		.data		= &zzz_debug_print_stall_once,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= &proc_dointvec,
+	},
+#endif
 	{ }
 };
author
#6 lore raw
In reply to Frank Rowand
Quoted 11 lines · Frank Rowand

The RCU stall warning functions call trigger_all_cpu_backtrace() to print a backtrace on each cpu. This function is only implemented for x86. Add a version for ARM.

With CONFIG_PREEMPT_RT_FULL enabled, flushing the output from printk() is inhibited in some contexts to avoid increasing real time latencies. The RCU stall warnings are inhibited on ARM due to this feature. (I have not tested whether this is also the case on other architectures.) Add back the oops_in_progress flag to allow the RCU stall warnings to print immediately.

When I first implemented these patches on a locally modified 3.0.27-rt67, the call to "bust_spinlocks(0)" that I added to print_cpu_stall() led to LOCKDEP warning of inconsistent lock state from a trylock in serial_omap_console_write():

else if (oops_in_progress)
locked = spin_trylock_irqsave(&up->port.lock, flags);

If I understand correctly, the warning is triggered on the slow lock path. Some more of the warning is:

inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. swapper/1/0 [HC1[1]:SC0[0]:HE0:SE1] takes:

    (&(&(&port->lock)->lock)->wait_lock){?.+...}, at: [<c0478ed0>] rt_spin_trylock_irqsave+0x24/0xe0

...

other info that might help us debug this:

    Possible unsafe locking scenario:
          CPU0
          ----
     lock(&(&(&port->lock)->lock)->wait_lock);
     <Interrupt>
       lock(&(&(&port->lock)->lock)->wait_lock);

I have not been able to trigger the warning on recent versions of the patches, but I suspect the latent problem might still exist.

-Frank