BUG - "scheduling while atomic" on a irq handler (s3c-mci)

BUG - "scheduling while atomic" on a irq handler (s3c-mci)

[Christophe Huriaux]

Hi everyone,

   I am facing a problem while trying to run a rt-patched 3.2.y kernel
with PREEMPT_RT_FULL on a mini2440 board (ARM based s3c2440 SoC) :
whilst a vanilla kernel (with PREEMPT_LL) works like a charm,
PREEMPT_RTB and PREEMPT_RT_FULL makes the MMC/SD driver  (s3cmci)
hang, which result in the kernel waiting indefinitely for the root fs
to mount.

  I think that the IRQ handling of the driver is somehow disturbed by
the changes made by the RT patch. When using PREEMPT_RTB I can see the
following message in the console :

BUG: scheduling while atomic: irq/37-s3c-mci/253/0x00000102
Modules linked in:
Function entered at [<c000e90c>] from [<c029f478>]
Function entered at [<c029f478>] from [<c029fc3c>]
Function entered at [<c029fc3c>] from [<c00559c0>]
Function entered at [<c00559c0>] from [<c01dd4c8>]
Function entered at [<c01dd4c8>] from [<c0024a0c>]
Function entered at [<c0024a0c>] from [<c0024d9c>]
Function entered at [<c0024d9c>] from [<c0024fe8>]
Function entered at [<c0024fe8>] from [<c0025140>]
Function entered at [<c0025140>] from [<c00549f0>]
Function entered at [<c00549f0>] from [<c00547c4>]
Function entered at [<c00547c4>] from [<c0039954>]
Function entered at [<c0039954>] from [<c000a120>]

  When I run the kernel under Qemu, debug through gdb and put a
breakpoint on unwind_backtace the details of the previous backtrace is
:

#0  unwind_backtrace (regs=0x0, tsk=0x0) at arch/arm/kernel/unwind.c:409
#1  0xc029f478 in schedule_debug (prev=<optimized out>) at kernel/sched.c:4357
#2  __schedule () at kernel/sched.c:4537
#3  0xc029fc3c in schedule () at kernel/sched.c:4625
#4  0xc00559c0 in synchronize_irq (irq=<optimized out>) at
kernel/irq/manage.c:73
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

  I don't see the "bug" message with PREEMPT_RT_FULL, the kernel just
hang waiting for the rootfs. The problem did not occur in the 2.6.y
tree AFAIK.

  I'd like to investigate more and fix the s3cmci driver but I don't
know where to begin, could someone give me some hints on what should
be done/not be done for a rt patch compliant device driver/irq handler
?


Regards,
Christophe Huriaux

Re: BUG - "scheduling while atomic" on a irq handler (s3c-mci)

[Uwe Kleine-König]

Hi Christophe,

On Wed, May 09, 2012 at 04:07:13PM +0200, Christophe Huriaux wrote:
>    I am facing a problem while trying to run a rt-patched 3.2.y kernel
> with PREEMPT_RT_FULL on a mini2440 board (ARM based s3c2440 SoC) :
> whilst a vanilla kernel (with PREEMPT_LL) works like a charm,
> PREEMPT_RTB and PREEMPT_RT_FULL makes the MMC/SD driver  (s3cmci)
> hang, which result in the kernel waiting indefinitely for the root fs
> to mount.
> 
>   I think that the IRQ handling of the driver is somehow disturbed by
> the changes made by the RT patch. When using PREEMPT_RTB I can see the
> following message in the console :
> 
> BUG: scheduling while atomic: irq/37-s3c-mci/253/0x00000102
> Modules linked in:
> Function entered at [<c000e90c>] from [<c029f478>]
> Function entered at [<c029f478>] from [<c029fc3c>]
> Function entered at [<c029fc3c>] from [<c00559c0>]
> Function entered at [<c00559c0>] from [<c01dd4c8>]
> Function entered at [<c01dd4c8>] from [<c0024a0c>]
> Function entered at [<c0024a0c>] from [<c0024d9c>]
> Function entered at [<c0024d9c>] from [<c0024fe8>]
> Function entered at [<c0024fe8>] from [<c0025140>]
> Function entered at [<c0025140>] from [<c00549f0>]
> Function entered at [<c00549f0>] from [<c00547c4>]
> Function entered at [<c00547c4>] from [<c0039954>]
> Function entered at [<c0039954>] from [<c000a120>]

If you enable CONFIG_KALLSYMS you get a more usable backtrace.
Alternatively you can use

	$CROSS_COMPILE-addr2line -e vmlinux 0xc000e90c

to get the file and line that resulted in the code at that address.

>   When I run the kernel under Qemu, debug through gdb and put a
> breakpoint on unwind_backtace the details of the previous backtrace is
> :
> 
> #0  unwind_backtrace (regs=0x0, tsk=0x0) at arch/arm/kernel/unwind.c:409
> #1  0xc029f478 in schedule_debug (prev=<optimized out>) at kernel/sched.c:4357
> #2  __schedule () at kernel/sched.c:4537
> #3  0xc029fc3c in schedule () at kernel/sched.c:4625
> #4  0xc00559c0 in synchronize_irq (irq=<optimized out>) at
> kernel/irq/manage.c:73
> Backtrace stopped: previous frame inner to this frame (corrupt stack?)
> 
>   I don't see the "bug" message with PREEMPT_RT_FULL, the kernel just
> hang waiting for the rootfs. The problem did not occur in the 2.6.y
> tree AFAIK.
My guess is that for PREEMPT_RT_FULL the printk just doesn't make it to
your console driver because the data would only be given to it when the
atomic block is done.

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: BUG - "scheduling while atomic" on a irq handler (s3c-mci)

[Christophe Huriaux]

2012/5/9 Uwe Kleine-König <u.kleine-koenig@pengutronix.de>:
> If you enable CONFIG_KALLSYMS you get a more usable backtrace.
> Alternatively you can use
>
>        $CROSS_COMPILE-addr2line -e vmlinux 0xc000e90c
>
> to get the file and line that resulted in the code at that address.
>

  Thanks, I was wondering which config option would enable that. The
complete backtrace is much more usable :

BUG: scheduling while atomic: irq/37-s3c-mci/253/0x00000102
Modules linked in:
[<c000e9fc>] (unwind_backtrace+0x0/0x12c) from [<c029b82c>]
(__schedule+0x58/0x2c0)
[<c029b82c>] (__schedule+0x58/0x2c0) from [<c029bc10>] (schedule+0x8c/0xb0)
[<c029bc10>] (schedule+0x8c/0xb0) from [<c0055614>] (synchronize_irq+0xbc/0xd8)
[<c0055614>] (synchronize_irq+0xbc/0xd8) from [<c01db6b0>]
(pio_tasklet+0x34/0x11c)
[<c01db6b0>] (pio_tasklet+0x34/0x11c) from [<c0024914>]
(__tasklet_action+0x68/0x80)
[<c0024914>] (__tasklet_action+0x68/0x80) from [<c0024ca4>]
(__do_softirq+0x88/0x130)
[<c0024ca4>] (__do_softirq+0x88/0x130) from [<c0024ef0>] (do_softirq+0x48/0x54)
[<c0024ef0>] (do_softirq+0x48/0x54) from [<c0025048>]
(local_bh_enable+0x8c/0xc0)
[<c0025048>] (local_bh_enable+0x8c/0xc0) from [<c0054678>]
(irq_forced_thread_fn+0x4c/0x54)
[<c0054678>] (irq_forced_thread_fn+0x4c/0x54) from [<c0054454>]
(irq_thread+0xa0/0x1c0)
[<c0054454>] (irq_thread+0xa0/0x1c0) from [<c0038628>] (kthread+0x84/0x8c)
[<c0038628>] (kthread+0x84/0x8c) from [<c000a100>] (kernel_thread_exit+0x0/0x8)


> My guess is that for PREEMPT_RT_FULL the printk just doesn't make it to
> your console driver because the data would only be given to it when the
> atomic block is done.

  Indeed : after tracing printk calls in GDB while in PREEMPT_RT_FULL
I can see that there is a lot more data sent than what the serial
driver handles.

  I'm able to fix this problem by replacing disable_irq() calls by
disable_irq_nosync() in s3cmci_enable_irq() and s3cmci_disable_irq()
(see patch below), which does not trigger a schedule. I don't see any
problem so far (at least I can boot !).


From: Christophe Huriaux <c.huriaux@gmail.com>
Subject: [PATCH] Fix scheduling while atomic bug in pio_tasklet
Signed-off-by: Christophe Huriaux <c.huriaux@gmail.com>
---
 drivers/mmc/host/s3cmci.c |    8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/drivers/mmc/host/s3cmci.c b/drivers/mmc/host/s3cmci.c
index 720f993..9978ad6 100644
--- a/drivers/mmc/host/s3cmci.c
+++ b/drivers/mmc/host/s3cmci.c
@@ -329,7 +329,11 @@ static void s3cmci_enable_irq(struct s3cmci_host
*host, bool more)
                if (enable)
                        enable_irq(host->irq);
                else
+#ifdef CONFIG_PREEMPT_RT_BASE
+                       disable_irq_nosync(host->irq);
+#else
                        disable_irq(host->irq);
+#endif
        }

        local_irq_restore(flags);
@@ -350,7 +354,11 @@ static void s3cmci_disable_irq(struct s3cmci_host
*host, bool transfer)

        if (transfer && host->irq_state) {
                host->irq_state = false;
+#ifdef CONFIG_PREEMPT_RT_BASE
+               disable_irq_nosync(host->irq);
+#else
                disable_irq(host->irq);
+#endif
        }

        local_irq_restore(flags);
-- 
1.7.9.5


Regards,
Christophe Huriaux
--
To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: BUG - "scheduling while atomic" on a irq handler (s3c-mci)

[Steven Rostedt]

On Thu, 2012-05-10 at 15:17 +0200, Christophe Huriaux wrote:

> 
> From: Christophe Huriaux <c.huriaux@gmail.com>
> Subject: [PATCH] Fix scheduling while atomic bug in pio_tasklet
> Signed-off-by: Christophe Huriaux <c.huriaux@gmail.com>
> ---
>  drivers/mmc/host/s3cmci.c |    8 ++++++++
>  1 file changed, 8 insertions(+)
> 
> diff --git a/drivers/mmc/host/s3cmci.c b/drivers/mmc/host/s3cmci.c
> index 720f993..9978ad6 100644
> --- a/drivers/mmc/host/s3cmci.c
> +++ b/drivers/mmc/host/s3cmci.c
> @@ -329,7 +329,11 @@ static void s3cmci_enable_irq(struct s3cmci_host
> *host, bool more)
>                 if (enable)
>                         enable_irq(host->irq);
>                 else
> +#ifdef CONFIG_PREEMPT_RT_BASE
> +                       disable_irq_nosync(host->irq);
> +#else
>                         disable_irq(host->irq);
> +#endif
>         }
> 
>         local_irq_restore(flags);
> @@ -350,7 +354,11 @@ static void s3cmci_disable_irq(struct s3cmci_host
> *host, bool transfer)
> 
>         if (transfer && host->irq_state) {
>                 host->irq_state = false;
> +#ifdef CONFIG_PREEMPT_RT_BASE
> +               disable_irq_nosync(host->irq);
> +#else
>                 disable_irq(host->irq);
> +#endif
>         }
> 
>         local_irq_restore(flags);

What happens if you instead convert the local_irq_save/restore() to
local_irq_save_nort/restore_nort()?

Does that work too?

-- Steve

[PATCH] genirq: don't sync irq thread if current happen to be the very irq thread

[Yong Zhang]

On Thu, May 10, 2012 at 03:17:17PM +0200, Christophe Huriaux wrote:
> 2012/5/9 Uwe Kleine-K?nig <u.kleine-koenig@pengutronix.de>:
> > If you enable CONFIG_KALLSYMS you get a more usable backtrace.
> > Alternatively you can use
> >
> > ? ? ? ?$CROSS_COMPILE-addr2line -e vmlinux 0xc000e90c
> >
> > to get the file and line that resulted in the code at that address.
> >
> 
>   Thanks, I was wondering which config option would enable that. The
> complete backtrace is much more usable :

Actually I don't think this is a -rt issue, you could also trigger this
warning with vanilla if you boot your kernel with 'threadirqs'.

Could you pleaes try the follow patch?

Thanks,
Yong

---
From: Yong Zhang <yong.zhang@windriver.com>
Date: Sun, 20 May 2012 12:56:46 +0800
Subject: [PATCH] genirq: don't sync irq thread if current happen to be the very irq thread

Christophe reported against -rt:
BUG: scheduling while atomic: irq/37-s3c-mci/253/0x00000102
Modules linked in:
[<c000e9fc>] (unwind_backtrace+0x0/0x12c) from [<c029b82c>] (__schedule+0x58/0x2c0)
[<c029b82c>] (__schedule+0x58/0x2c0) from [<c029bc10>] (schedule+0x8c/0xb0)
[<c029bc10>] (schedule+0x8c/0xb0) from [<c0055614>] (synchronize_irq+0xbc/0xd8)
[<c0055614>] (synchronize_irq+0xbc/0xd8) from [<c01db6b0>] (pio_tasklet+0x34/0x11c)
[<c01db6b0>] (pio_tasklet+0x34/0x11c) from [<c0024914>] (__tasklet_action+0x68/0x80)
[<c0024914>] (__tasklet_action+0x68/0x80) from [<c0024ca4>] (__do_softirq+0x88/0x130)
[<c0024ca4>] (__do_softirq+0x88/0x130) from [<c0024ef0>] (do_softirq+0x48/0x54)
[<c0024ef0>] (do_softirq+0x48/0x54) from [<c0025048>] (local_bh_enable+0x8c/0xc0)
[<c0025048>] (local_bh_enable+0x8c/0xc0) from [<c0054678>] (irq_forced_thread_fn+0x4c/0x54)
[<c0054678>] (irq_forced_thread_fn+0x4c/0x54) from [<c0054454>] (irq_thread+0xa0/0x1c0)
[<c0054454>] (irq_thread+0xa0/0x1c0) from [<c0038628>] (kthread+0x84/0x8c)
[<c0038628>] (kthread+0x84/0x8c) from [<c000a100>] (kernel_thread_exit+0x0/0x8)

Whe looking at this issue, I find that there is a typical deadlock
scenario with forced treaded irq,

irq_forced_thread_fn()
  local_bh_enable();
    do_softirq();
      disable_irq();
        synchronize_irq();
          wait_event();
          /*DEAD*/

Cure it by unsync if current happen to be the very irq thread.

Reported-by: Christophe Huriaux <c.huriaux@gmail.com>
Signed-off-by: Yong Zhang <yong.zhang0@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
---
 kernel/irq/manage.c |    9 +++++++++
 1 files changed, 9 insertions(+), 0 deletions(-)

diff --git a/kernel/irq/manage.c b/kernel/irq/manage.c
index 89a3ea8..d5b96e7 100644
--- a/kernel/irq/manage.c
+++ b/kernel/irq/manage.c
@@ -41,6 +41,7 @@ early_param("threadirqs", setup_forced_irqthreads);
 void synchronize_irq(unsigned int irq)
 {
 	struct irq_desc *desc = irq_to_desc(irq);
+	struct irqaction *action = desc->action;
 	bool inprogress;
 
 	if (!desc)
@@ -67,7 +68,15 @@ void synchronize_irq(unsigned int irq)
 	/*
 	 * We made sure that no hardirq handler is running. Now verify
 	 * that no threaded handlers are active.
+	 * But for theaded irq, we don't sync if current happens to be
+	 * the irq thread; otherwise we could deadlock.
 	 */
+	while (action) {
+		if (action->thread && action->thread == current)
+			return;
+		action = action->next;
+	}
+
 	wait_event(desc->wait_for_threads, !atomic_read(&desc->threads_active));
 }
 EXPORT_SYMBOL(synchronize_irq);
-- 
1.7.1

[PATCH v2] genirq: don't sync irq thread if current happen to be the very irq thread

[Yong Zhang]

On Sun, May 20, 2012 at 01:27:31PM +0800, Yong Zhang wrote:
> --- a/kernel/irq/manage.c
> +++ b/kernel/irq/manage.c
> @@ -41,6 +41,7 @@ early_param("threadirqs", setup_forced_irqthreads);
>  void synchronize_irq(unsigned int irq)
>  {
>  	struct irq_desc *desc = irq_to_desc(irq);
> +	struct irqaction *action = desc->action;

Bad time for dereferencing *action.

---
From: Yong Zhang <yong.zhang@windriver.com>
Date: Sun, 20 May 2012 12:56:46 +0800
Subject: [PATCH v2] genirq: don't sync irq thread if current happen to be the very irq thread

Christophe reported against -rt http://marc.info/?l=linux-rt-users&m=133665600214984&w=2
BUG: scheduling while atomic: irq/37-s3c-mci/253/0x00000102
Modules linked in:
[<c000e9fc>] (unwind_backtrace+0x0/0x12c) from [<c029b82c>] (__schedule+0x58/0x2c0)
[<c029b82c>] (__schedule+0x58/0x2c0) from [<c029bc10>] (schedule+0x8c/0xb0)
[<c029bc10>] (schedule+0x8c/0xb0) from [<c0055614>] (synchronize_irq+0xbc/0xd8)
[<c0055614>] (synchronize_irq+0xbc/0xd8) from [<c01db6b0>] (pio_tasklet+0x34/0x11c)
[<c01db6b0>] (pio_tasklet+0x34/0x11c) from [<c0024914>] (__tasklet_action+0x68/0x80)
[<c0024914>] (__tasklet_action+0x68/0x80) from [<c0024ca4>] (__do_softirq+0x88/0x130)
[<c0024ca4>] (__do_softirq+0x88/0x130) from [<c0024ef0>] (do_softirq+0x48/0x54)
[<c0024ef0>] (do_softirq+0x48/0x54) from [<c0025048>] (local_bh_enable+0x8c/0xc0)
[<c0025048>] (local_bh_enable+0x8c/0xc0) from [<c0054678>] (irq_forced_thread_fn+0x4c/0x54)
[<c0054678>] (irq_forced_thread_fn+0x4c/0x54) from [<c0054454>] (irq_thread+0xa0/0x1c0)
[<c0054454>] (irq_thread+0xa0/0x1c0) from [<c0038628>] (kthread+0x84/0x8c)
[<c0038628>] (kthread+0x84/0x8c) from [<c000a100>] (kernel_thread_exit+0x0/0x8)

Whe looking at this issue, I find that there is a typical deadlock
scenario with forced treaded irq,

irq_forced_thread_fn()
  local_bh_enable();
    do_softirq();
      disable_irq();
        synchronize_irq();
          wait_event();
          /*DEAD*/

Cure it by unsync if current happen to be the very irq thread.

Reported-by: Christophe Huriaux <c.huriaux@gmail.com>
Signed-off-by: Yong Zhang <yong.zhang0@gmail.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
---
 kernel/irq/manage.c |   10 ++++++++++
 1 files changed, 10 insertions(+), 0 deletions(-)

diff --git a/kernel/irq/manage.c b/kernel/irq/manage.c
index 89a3ea8..7a48f74 100644
--- a/kernel/irq/manage.c
+++ b/kernel/irq/manage.c
@@ -41,6 +41,7 @@ early_param("threadirqs", setup_forced_irqthreads);
 void synchronize_irq(unsigned int irq)
 {
 	struct irq_desc *desc = irq_to_desc(irq);
+	struct irqaction *action;
 	bool inprogress;
 
 	if (!desc)
@@ -67,7 +68,16 @@ void synchronize_irq(unsigned int irq)
 	/*
 	 * We made sure that no hardirq handler is running. Now verify
 	 * that no threaded handlers are active.
+	 * But for theaded irq, we don't sync if current happens to be
+	 * the irq thread; otherwise we could deadlock.
 	 */
+	action = desc->action;
+	while (action) {
+		if (action->thread && action->thread == current)
+			return;
+		action = action->next;
+	}
+
 	wait_event(desc->wait_for_threads, !atomic_read(&desc->threads_active));
 }
 EXPORT_SYMBOL(synchronize_irq);
-- 
1.7.1

Re: [PATCH v2] genirq: don't sync irq thread if current happen to be the very irq thread

[Thomas Gleixner]

On Sun, 20 May 2012, Yong Zhang wrote:
> On Sun, May 20, 2012 at 01:27:31PM +0800, Yong Zhang wrote:
> > --- a/kernel/irq/manage.c
> > +++ b/kernel/irq/manage.c
> > @@ -41,6 +41,7 @@ early_param("threadirqs", setup_forced_irqthreads);
> >  void synchronize_irq(unsigned int irq)
> >  {
> >  	struct irq_desc *desc = irq_to_desc(irq);
> > +	struct irqaction *action = desc->action;
> 
> Bad time for dereferencing *action.

You meant dereferencing *desc :)
 
>  	/*
>  	 * We made sure that no hardirq handler is running. Now verify
>  	 * that no threaded handlers are active.
> +	 * But for theaded irq, we don't sync if current happens to be
> +	 * the irq thread; otherwise we could deadlock.
>  	 */
> +	action = desc->action;

And dereferencing action w/o being protected by desc->lock is buggy.

+	while (action) {
> +		if (action->thread && action->thread == current)
> +			return;
> +		action = action->next;
> +	}
> +

Aside of that I really do not like that change. It'll hide real
deadlocks when disable_irq() is called from the interrupt handler.

Also this will not cure all problems of that MMC driver on RT or with
forced threaded interrupts.

Assume that tasklet code runs from the softirq thread so it will
schedule when desc->threads_active > 0. This will trigger a
"scheduling while atomic" warning.

The irq_enable/disable dance in that driver is amazing. I have no time
at the moment to grok the logic behind this, but it bet this can be
done way simpler and less horrible.

Thanks,

	tglx

Re: [PATCH v2] genirq: don't sync irq thread if current happen to be the very irq thread

[Yong Zhang]

On Tue, May 22, 2012 at 03:50:38PM +0200, Thomas Gleixner wrote:
> On Sun, 20 May 2012, Yong Zhang wrote:
> > On Sun, May 20, 2012 at 01:27:31PM +0800, Yong Zhang wrote:
> > > --- a/kernel/irq/manage.c
> > > +++ b/kernel/irq/manage.c
> > > @@ -41,6 +41,7 @@ early_param("threadirqs", setup_forced_irqthreads);
> > >  void synchronize_irq(unsigned int irq)
> > >  {
> > >  	struct irq_desc *desc = irq_to_desc(irq);
> > > +	struct irqaction *action = desc->action;
> > 
> > Bad time for dereferencing *action.
> 
> You meant dereferencing *desc :)

Ah, yes :)

>  
> >  	/*
> >  	 * We made sure that no hardirq handler is running. Now verify
> >  	 * that no threaded handlers are active.
> > +	 * But for theaded irq, we don't sync if current happens to be
> > +	 * the irq thread; otherwise we could deadlock.
> >  	 */
> > +	action = desc->action;
> 
> And dereferencing action w/o being protected by desc->lock is buggy.
> 
> +	while (action) {
> > +		if (action->thread && action->thread == current)
> > +			return;
> > +		action = action->next;
> > +	}
> > +
> 
> Aside of that I really do not like that change. It'll hide real
> deadlocks when disable_irq() is called from the interrupt handler.
> 
> Also this will not cure all problems of that MMC driver on RT or with
> forced threaded interrupts.
> 
> Assume that tasklet code runs from the softirq thread so it will
> schedule when desc->threads_active > 0. This will trigger a
> "scheduling while atomic" warning.

Yes.

> 
> The irq_enable/disable dance in that driver is amazing. I have no time
> at the moment to grok the logic behind this, but it bet this can be
> done way simpler and less horrible.

I'll reconsider this issue and try to find the simpler way.

Thanks,
Yong