real time hang w/ latency tracing

real time hang w/ latency tracing

[Daniel Walker]

With 2.6.21-rc5-rt8 / i386 . If I disable wakeup timing , and enable
interrupt off timing with latency tracing I can cause,

BUG: scheduling with irqs disabled: IRQ-16/0x00000000/909
caller is rt_spin_lock_slowlock+0x94/0x190
 [<c010577a>] show_trace_log_lvl+0x3a/0x60
 [<c0105fdd>] show_trace+0x2d/0x30
 [<c01060c7>] dump_stack+0x27/0x30
 [<c03f52db>] schedule+0x12b/0x130
 [<c03f6314>] rt_spin_lock_slowlock+0x94/0x190
 [<c03f6b35>] rt_spin_lock+0x25/0x30
 [<c02f19bf>] serial8250_console_write+0x16f/0x190
 [<c012b3aa>] __call_console_drivers+0x7a/0xa0
 [<c012b427>] _call_console_drivers+0x57/0xa0
 [<c012b58d>] release_console_sem+0xdd/0x1e0
 [<c012bd46>] vprintk+0x226/0x3b0
 [<c012bef0>] printk+0x20/0x30
 [<c0158d29>] print_traces+0x49/0x100
 [<c0105792>] show_trace_log_lvl+0x52/0x60
 [<c0105fdd>] show_trace+0x2d/0x30
 [<c01060c7>] dump_stack+0x27/0x30
 [<c0158481>] check_critical_timing+0x2b1/0x380
 [<c01585f6>] trace_hardirqs_on+0xa6/0xc0
 [<c01046e5>] restore_nocheck+0x12/0x15
 =======================

I do this by running,

echo 1 > /proc/sys/kernel/preempt_thresh

which clearly causes loads of output .. Then while the output is
screaming along I hold down the left arrow key and eventually the
message above starts to appear often .. Then the system hangs.

Also I'm using an NFS root which might help to bring out the error ..

Daniel

Re: real time hang w/ latency tracing

[Daniel Walker]

On Tue, 2007-04-03 at 11:57 -0700, Daniel Walker wrote:
> With 2.6.21-rc5-rt8 / i386 . If I disable wakeup timing , and enable
> interrupt off timing with latency tracing I can cause,
> 
> BUG: scheduling with irqs disabled: IRQ-16/0x00000000/909
> caller is rt_spin_lock_slowlock+0x94/0x190
>  [<c010577a>] show_trace_log_lvl+0x3a/0x60
>  [<c0105fdd>] show_trace+0x2d/0x30
>  [<c01060c7>] dump_stack+0x27/0x30
>  [<c03f52db>] schedule+0x12b/0x130
>  [<c03f6314>] rt_spin_lock_slowlock+0x94/0x190
>  [<c03f6b35>] rt_spin_lock+0x25/0x30
>  [<c02f19bf>] serial8250_console_write+0x16f/0x190
>  [<c012b3aa>] __call_console_drivers+0x7a/0xa0
>  [<c012b427>] _call_console_drivers+0x57/0xa0
>  [<c012b58d>] release_console_sem+0xdd/0x1e0
>  [<c012bd46>] vprintk+0x226/0x3b0
>  [<c012bef0>] printk+0x20/0x30
>  [<c0158d29>] print_traces+0x49/0x100
>  [<c0105792>] show_trace_log_lvl+0x52/0x60
>  [<c0105fdd>] show_trace+0x2d/0x30
>  [<c01060c7>] dump_stack+0x27/0x30
>  [<c0158481>] check_critical_timing+0x2b1/0x380
>  [<c01585f6>] trace_hardirqs_on+0xa6/0xc0
>  [<c01046e5>] restore_nocheck+0x12/0x15

This allows the system to continue printing ..

Signed-Off-By: Daniel Walker <dwalker@mvista.com>

---
 include/linux/serial_core.h |    4 ++++
 1 file changed, 4 insertions(+)

Index: linux-2.6.20/include/linux/serial_core.h
===================================================================
--- linux-2.6.20.orig/include/linux/serial_core.h
+++ linux-2.6.20/include/linux/serial_core.h
@@ -213,7 +213,11 @@ struct uart_icount {
 typedef unsigned int __bitwise__ upf_t;
 
 struct uart_port {
+#ifdef CONFIG_LATENCY_TIMING
+	raw_spinlock_t		lock;			/* port lock */
+#else
 	spinlock_t		lock;			/* port lock */
+#endif
 	unsigned int		iobase;			/* in/out[bwl] */
 	unsigned char __iomem	*membase;		/* read/write[bwl] */
 	unsigned int		irq;			/* irq number */

Re: real time hang w/ latency tracing

[Ingo Molnar]

* Daniel Walker <dwalker@mvista.com> wrote:

> Index: linux-2.6.20/include/linux/serial_core.h
> ===================================================================
> --- linux-2.6.20.orig/include/linux/serial_core.h
> +++ linux-2.6.20/include/linux/serial_core.h
> @@ -213,7 +213,11 @@ struct uart_icount {
>  typedef unsigned int __bitwise__ upf_t;
>  
>  struct uart_port {
> +#ifdef CONFIG_LATENCY_TIMING
> +	raw_spinlock_t		lock;			/* port lock */
> +#else
>  	spinlock_t		lock;			/* port lock */
> +#endif

ugh - this will only cause other problems if anyone else is trying to 
use the serial code. This needs a cleaner fix - such as not doing that 
printk from atomic context.

	Ingo

Re: real time hang w/ latency tracing

[Daniel Walker]

On Wed, 2007-04-04 at 10:51 +0200, Ingo Molnar wrote:
> * Daniel Walker <dwalker@mvista.com> wrote:
> 
> > Index: linux-2.6.20/include/linux/serial_core.h
> > ===================================================================
> > --- linux-2.6.20.orig/include/linux/serial_core.h
> > +++ linux-2.6.20/include/linux/serial_core.h
> > @@ -213,7 +213,11 @@ struct uart_icount {
> >  typedef unsigned int __bitwise__ upf_t;
> >  
> >  struct uart_port {
> > +#ifdef CONFIG_LATENCY_TIMING
> > +	raw_spinlock_t		lock;			/* port lock */
> > +#else
> >  	spinlock_t		lock;			/* port lock */
> > +#endif
> 
> ugh - this will only cause other problems if anyone else is trying to 
> use the serial code. This needs a cleaner fix - such as not doing that 
> printk from atomic context.

I assumed this fix wasn't totally right .. Interrupts could be enabled
just before printing , after any critical stuff has happened then
disabled again after printing .. Or are you thinking of something more
complex?

Daniel

Re: real time hang w/ latency tracing

[Ingo Molnar]

* Daniel Walker <dwalker@mvista.com> wrote:

> > >  struct uart_port {
> > > +#ifdef CONFIG_LATENCY_TIMING
> > > +	raw_spinlock_t		lock;			/* port lock */
> > > +#else
> > >  	spinlock_t		lock;			/* port lock */
> > > +#endif
> > 
> > ugh - this will only cause other problems if anyone else is trying 
> > to use the serial code. This needs a cleaner fix - such as not doing 
> > that printk from atomic context.
> 
> I assumed this fix wasn't totally right .. Interrupts could be enabled 
> just before printing , after any critical stuff has happened then 
> disabled again after printing .. Or are you thinking of something more 
> complex?

i mean non-printk related breakages to the normal serial driver - which 
is now surprised by this raw lock in an -rt kernel.

this is a hard issue and there's no easy solution i can see. neither 
having it as a raw lock is a good solution, nor having it as a 
preemptible lock is a good solution.

	Ingo

Re: real time hang w/ latency tracing

[Daniel Walker]

On Wed, 2007-04-04 at 17:42 +0200, Ingo Molnar wrote:

> i mean non-printk related breakages to the normal serial driver - which 
> is now surprised by this raw lock in an -rt kernel.
> 
> this is a hard issue and there's no easy solution i can see. neither 
> having it as a raw lock is a good solution, nor having it as a 
> preemptible lock is a good solution.

The machine that I'm using is relatively fast, but on slower machine
it's possible to reproduce this same hang just by running,

echo 0 > /proc/sys/kernel/preempt_max_latency

then pressing enter a few times .. Which would be a fairly common
happening with people using latency tracing an a serial port I would
imagine..

The other fix I test was using the hack for sysrq,

        if (up->port.sysrq || oops_in_progress)

in serial8250_console_write to then also check "irqs_disabled()" , but
I'm sure mass usage of the serial port would cause some issues with
that.. Although both fixes I tested resulted in the serial port becoming
garbled after about 10 min. with the preempt_thresh at 1 .

Daniel