[PATCH RT 0/2][RFC] fix RCU stall warning on ARM

[PATCH RT 0/2][RFC] fix RCU stall warning on ARM

[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.

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.

[PATCH RT 1/2][RFC] ARM version of arch_trigger_all_cpu_backtrace()

[Frank Rowand]

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 <frank.rowand@am.sony.com>
---
 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(-)

Index: b/arch/arm/include/asm/irq.h
===================================================================
--- a/arch/arm/include/asm/irq.h
+++ 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
Index: b/arch/arm/kernel/smp.c
===================================================================
--- a/arch/arm/kernel/smp.c
+++ b/arch/arm/kernel/smp.c
@@ -56,6 +56,7 @@ enum ipi_msg_type {
 	IPI_CALL_FUNC,
 	IPI_CALL_FUNC_SINGLE,
 	IPI_CPU_STOP,
+	IPI_BACKTRACE,
 };
 
 static DECLARE_COMPLETION(cpu_running);
@@ -359,6 +360,7 @@ static const char *ipi_types[NR_IPI] = {
 	S(IPI_CALL_FUNC, "Function call interrupts"),
 	S(IPI_CALL_FUNC_SINGLE, "Single function call interrupts"),
 	S(IPI_CPU_STOP, "CPU stop interrupts"),
+	S(IPI_BACKTRACE, "Trigger all cpu backtrace"),
 };
 
 void show_ipi_list(struct seq_file *p, int prec)
@@ -493,6 +495,70 @@ static void ipi_cpu_stop(unsigned int cp
 		cpu_relax();
 }
 
+#ifdef arch_trigger_all_cpu_backtrace
+/*
+ * Based on arch/x86/kernel/apic/hw_nmi.c:
+ *   arch_trigger_all_cpu_backtrace_handler()
+ *   arch_trigger_all_cpu_backtrace()
+ */
+
+static struct cpumask backtrace_mask;
+
+static unsigned long backtrace_flag;
+static arch_spinlock_t smp_backtrace_lock = __ARCH_SPIN_LOCK_UNLOCKED;
+
+/*
+ * ipi_backtrace - handle IPI from smp_send_backtrace()
+ */
+static void ipi_backtrace(unsigned int cpu, struct pt_regs *regs)
+{
+	/*
+	 * serialize cpus
+	 */
+	arch_spin_lock(&smp_backtrace_lock);
+
+	pr_crit("\nCPU %u\n", cpu);
+
+	if (regs)
+		__show_regs(regs);
+
+	dump_stack();
+
+	cpumask_clear_cpu(cpu, &backtrace_mask);
+
+	arch_spin_unlock(&smp_backtrace_lock);
+}
+
+void arch_trigger_all_cpu_backtrace(void)
+{
+	int i;
+
+	if (test_and_set_bit(0, &backtrace_flag))
+		/*
+		 * If there is already a trigger_all_cpu_backtrace() in progress
+		 * (backtrace_flag == 1), don't output double cpu dump infos.
+		 */
+		return;
+
+	ipi_backtrace(smp_processor_id(), NULL);
+
+	cpumask_copy(&backtrace_mask, cpu_online_mask);
+	cpumask_clear_cpu(smp_processor_id(), &backtrace_mask);
+
+	if (!cpumask_empty(&backtrace_mask))
+		smp_cross_call(&backtrace_mask, IPI_BACKTRACE);
+
+	/* Wait for up to 10 seconds for all CPUs to do the backtrace */
+	for (i = 0; i < 10 * 1000; i++) {
+		if (cpumask_empty(&backtrace_mask))
+			break;
+		mdelay(1);
+	}
+
+	clear_bit(0, &backtrace_flag);
+}
+#endif
+
 /*
  * Main handler for inter-processor interrupts
  */
@@ -538,6 +604,10 @@ void handle_IPI(int ipinr, struct pt_reg
 		irq_exit();
 		break;
 
+	case IPI_BACKTRACE:
+		ipi_backtrace(cpu, regs);
+		break;
+
 	default:
 		printk(KERN_CRIT "CPU%u: Unknown IPI message 0x%x\n",
 		       cpu, ipinr);
Index: b/arch/arm/include/asm/hardirq.h
===================================================================
--- a/arch/arm/include/asm/hardirq.h
+++ 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;

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

[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 <frank.rowand@am.sony.com>
---
 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
===================================================================
--- a/kernel/printk.c
+++ 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
Index: b/kernel/rcutree.c
===================================================================
--- a/kernel/rcutree.c
+++ 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 +

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

[Paul E. McKenney]

On Tue, Dec 04, 2012 at 08:52:21PM -0800, Frank Rowand wrote:
> 
> 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 <frank.rowand@am.sony.com>

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

> ---
>  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
> ===================================================================
> --- a/kernel/printk.c
> +++ 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
> Index: b/kernel/rcutree.c
> ===================================================================
> --- a/kernel/rcutree.c
> +++ 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 +
> 

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

[Frank Rowand]

On 12/10/12 06:29, Paul E. McKenney wrote:
> On Tue, Dec 04, 2012 at 08:52:21PM -0800, Frank Rowand wrote:
>>
>> 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 <frank.rowand@am.sony.com>
> 
> 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

[PATCH RT 0/2][RFC] fix RCU stall warning on ARM

[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 <frank.rowand@am.sony.com>
---
 kernel/rcutree.c |   26 	26 +	0 -	0 !
 kernel/sysctl.c  |   11 	11 +	0 -	0 !
 2 files changed, 37 insertions(+)

Index: b/kernel/rcutree.c
===================================================================
--- a/kernel/rcutree.c
+++ 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;
Index: b/kernel/sysctl.c
===================================================================
--- a/kernel/sysctl.c
+++ 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
 	{ }
 };
 

[PATCH RT 0/2][RFC] fix RCU stall warning on ARM

[Frank Rowand]

On 12/04/12 20:47, Frank Rowand wrote:
> 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