[BUG] hvc_console WARN() on current upstream

[BUG] hvc_console WARN() on current upstream

[Benjamin Herrenschmidt]

Firing that off here in case I don't get a chance to investigate this
week... latest upstream with whatever I'm about to push into
powerpc-next (but I doubt it's the pending stuff that's causing it)
gives me that on a pseries machine:

------------[ cut here ]------------
Badness at /home/benh/kernels/linux-powerpc/kernel/mutex.c:135
NIP: c0000000004fe0dc LR: c0000000004fe0c0 CTR: c0000000002c4304
REGS: c00000000fffb660 TRAP: 0700   Not tainted  (2.6.28-test)
MSR: 8000000000021032 <ME,CE,IR,DR>  CR: 28000082  XER: 20000003
TASK = c0000000007bd340[0] 'swapper' THREAD: c000000000874000 CPU: 0
GPR00: 0000000000000000 c00000000fffb8e0 c000000000877438 0000000000000001 
GPR04: 0000000000000000 c0000000225f0928 0000000000000003 0000000008000001 
GPR08: cf3cf3cf3cf3cf3d c000000000e6edc0 c000000000787634 c0000000008d45ac 
GPR12: 0000000028000082 c0000000008b7300 c00000002254db20 0000000000000001 
GPR16: 0000000000000003 c00000002254d940 c00000002254da70 c0000000225f0828 
GPR20: c0000000225f0929 0000000000000000 c00000002254dee8 0000000000000000 
GPR24: 0000000000000000 c0000000002c2604 0000000000000003 c0000000007bd340 
GPR28: c00000002254dee8 c00000002254d800 c0000000007ef2b8 c00000002254dee8 
NIP [c0000000004fe0dc] .mutex_lock_nested+0x90/0x408
LR [c0000000004fe0c0] .mutex_lock_nested+0x74/0x408
Call Trace:
[c00000000fffb9e0] [c0000000002c2604] .echo_set_canon_col+0x28/0x68
[c00000000fffba70] [c0000000002c4db4] .n_tty_receive_buf+0xcbc/0xfe0
[c00000000fffbc10] [c0000000002c80f8] .flush_to_ldisc+0x18c/0x24c
[c00000000fffbcd0] [c0000000002dd02c] .hvc_poll+0x2d0/0x328
[c00000000fffbde0] [c0000000002dd2e4] .hvc_handle_interrupt+0x14/0x3c
[c00000000fffbe50] [c0000000000999a4] .handle_IRQ_event+0x50/0xc0
[c00000000fffbef0] [c00000000009bdec] .handle_fasteoi_irq+0xf8/0x194
[c00000000fffbf90] [c000000000025950] .call_handle_irq+0x1c/0x2c
[c000000000877a30] [c00000000000cd18] .do_IRQ+0x104/0x1dc
[c000000000877ae0] [c000000000004800] hardware_interrupt_entry+0x18/0x98
--- Exception: 501 at .cpu_idle+0x104/0x190
    LR = .cpu_idle+0x104/0x190
[c000000000877dd0] [c000000000011e58] .cpu_idle+0xf8/0x190 (unreliable)
[c000000000877e60] [c000000000500b24] .rest_init+0x7c/0x94
[c000000000877ee0] [c000000000715aec] .start_kernel+0x3f4/0x414
[c000000000877f90] [c000000000008368] .start_here_common+0x1c/0x34
Instruction dump:
78290464 80090014 5409012f 41820028 4bd5ead5 60000000 2fa30000 419e0018 
e93e8008 80090000 2f800000 409e0008 <0fe00000> 38000000 8b8d01da 980d01da 

The machine still boots, so it's not a show stopper.

Cheers,
Ben.

Re: [BUG] hvc_console WARN() on current upstream

[Christian Borntraeger]

Am Donnerstag, 8. Januar 2009 schrieb Benjamin Herrenschmidt:
> ------------[ cut here ]------------
> Badness at /home/benh/kernels/linux-powerpc/kernel/mutex.c:135
> NIP: c0000000004fe0dc LR: c0000000004fe0c0 CTR: c0000000002c4304
> REGS: c00000000fffb660 TRAP: 0700   Not tainted  (2.6.28-test)
> MSR: 8000000000021032 <ME,CE,IR,DR>  CR: 28000082  XER: 20000003
> TASK = c0000000007bd340[0] 'swapper' THREAD: c000000000874000 CPU: 0
> GPR00: 0000000000000000 c00000000fffb8e0 c000000000877438 0000000000000001 
> GPR04: 0000000000000000 c0000000225f0928 0000000000000003 0000000008000001 
> GPR08: cf3cf3cf3cf3cf3d c000000000e6edc0 c000000000787634 c0000000008d45ac 
> GPR12: 0000000028000082 c0000000008b7300 c00000002254db20 0000000000000001 
> GPR16: 0000000000000003 c00000002254d940 c00000002254da70 c0000000225f0828 
> GPR20: c0000000225f0929 0000000000000000 c00000002254dee8 0000000000000000 
> GPR24: 0000000000000000 c0000000002c2604 0000000000000003 c0000000007bd340 
> GPR28: c00000002254dee8 c00000002254d800 c0000000007ef2b8 c00000002254dee8 
> NIP [c0000000004fe0dc] .mutex_lock_nested+0x90/0x408
> LR [c0000000004fe0c0] .mutex_lock_nested+0x74/0x408
> Call Trace:
> [c00000000fffb9e0] [c0000000002c2604] .echo_set_canon_col+0x28/0x68
> [c00000000fffba70] [c0000000002c4db4] .n_tty_receive_buf+0xcbc/0xfe0
> [c00000000fffbc10] [c0000000002c80f8] .flush_to_ldisc+0x18c/0x24c
> [c00000000fffbcd0] [c0000000002dd02c] .hvc_poll+0x2d0/0x328
> [c00000000fffbde0] [c0000000002dd2e4] .hvc_handle_interrupt+0x14/0x3c
> [c00000000fffbe50] [c0000000000999a4] .handle_IRQ_event+0x50/0xc0
> [c00000000fffbef0] [c00000000009bdec] .handle_fasteoi_irq+0xf8/0x194
> [c00000000fffbf90] [c000000000025950] .call_handle_irq+0x1c/0x2c
> [c000000000877a30] [c00000000000cd18] .do_IRQ+0x104/0x1dc
> [c000000000877ae0] [c000000000004800] hardware_interrupt_entry+0x18/0x98
> --- Exception: 501 at .cpu_idle+0x104/0x190
>     LR = .cpu_idle+0x104/0x190
> [c000000000877dd0] [c000000000011e58] .cpu_idle+0xf8/0x190 (unreliable)
> [c000000000877e60] [c000000000500b24] .rest_init+0x7c/0x94
> [c000000000877ee0] [c000000000715aec] .start_kernel+0x3f4/0x414
> [c000000000877f90] [c000000000008368] .start_here_common+0x1c/0x34
> Instruction dump:
> 78290464 80090014 5409012f 41820028 4bd5ead5 60000000 2fa30000 419e0018 
> e93e8008 80090000 2f800000 409e0008 <0fe00000> 38000000 8b8d01da 980d01da 
> 
> The machine still boots, so it's not a show stopper.


Hmmm,

Seems that we are in interrupt, doing hvc_poll, which does
tty_flip_buffer_push
which calls
flush_to_ldisc
doing a
n_tty_receive_buf
and we will finally take a mutex in echo_set_canon_col 

my first guess is that the following patch triggered the Badness:
git show a88a69c9
commit a88a69c91256418c5907c2f1f8a0ec0a36f9e6cc
Author: Joe Peterson <joe@skyrush.com>
Date:   Fri Jan 2 13:40:53 2009 +0000

    n_tty: Fix loss of echoed characters and remove bkl from n_tty


I have no idea how to fix this.
Joe Peterson CCed.

Christian

Re: [BUG] hvc_console WARN() on current upstream

[Benjamin Herrenschmidt]

Also including Alan, he's the current tty guru

On Thu, 2009-01-08 at 08:57 +0100, Christian Borntraeger wrote:
> Am Donnerstag, 8. Januar 2009 schrieb Benjamin Herrenschmidt:
> > ------------[ cut here ]------------
> > Badness at /home/benh/kernels/linux-powerpc/kernel/mutex.c:135
> > NIP: c0000000004fe0dc LR: c0000000004fe0c0 CTR: c0000000002c4304
> > REGS: c00000000fffb660 TRAP: 0700   Not tainted  (2.6.28-test)
> > MSR: 8000000000021032 <ME,CE,IR,DR>  CR: 28000082  XER: 20000003
> > TASK = c0000000007bd340[0] 'swapper' THREAD: c000000000874000 CPU: 0
> > GPR00: 0000000000000000 c00000000fffb8e0 c000000000877438 0000000000000001 
> > GPR04: 0000000000000000 c0000000225f0928 0000000000000003 0000000008000001 
> > GPR08: cf3cf3cf3cf3cf3d c000000000e6edc0 c000000000787634 c0000000008d45ac 
> > GPR12: 0000000028000082 c0000000008b7300 c00000002254db20 0000000000000001 
> > GPR16: 0000000000000003 c00000002254d940 c00000002254da70 c0000000225f0828 
> > GPR20: c0000000225f0929 0000000000000000 c00000002254dee8 0000000000000000 
> > GPR24: 0000000000000000 c0000000002c2604 0000000000000003 c0000000007bd340 
> > GPR28: c00000002254dee8 c00000002254d800 c0000000007ef2b8 c00000002254dee8 
> > NIP [c0000000004fe0dc] .mutex_lock_nested+0x90/0x408
> > LR [c0000000004fe0c0] .mutex_lock_nested+0x74/0x408
> > Call Trace:
> > [c00000000fffb9e0] [c0000000002c2604] .echo_set_canon_col+0x28/0x68
> > [c00000000fffba70] [c0000000002c4db4] .n_tty_receive_buf+0xcbc/0xfe0
> > [c00000000fffbc10] [c0000000002c80f8] .flush_to_ldisc+0x18c/0x24c
> > [c00000000fffbcd0] [c0000000002dd02c] .hvc_poll+0x2d0/0x328
> > [c00000000fffbde0] [c0000000002dd2e4] .hvc_handle_interrupt+0x14/0x3c
> > [c00000000fffbe50] [c0000000000999a4] .handle_IRQ_event+0x50/0xc0
> > [c00000000fffbef0] [c00000000009bdec] .handle_fasteoi_irq+0xf8/0x194
> > [c00000000fffbf90] [c000000000025950] .call_handle_irq+0x1c/0x2c
> > [c000000000877a30] [c00000000000cd18] .do_IRQ+0x104/0x1dc
> > [c000000000877ae0] [c000000000004800] hardware_interrupt_entry+0x18/0x98
> > --- Exception: 501 at .cpu_idle+0x104/0x190
> >     LR = .cpu_idle+0x104/0x190
> > [c000000000877dd0] [c000000000011e58] .cpu_idle+0xf8/0x190 (unreliable)
> > [c000000000877e60] [c000000000500b24] .rest_init+0x7c/0x94
> > [c000000000877ee0] [c000000000715aec] .start_kernel+0x3f4/0x414
> > [c000000000877f90] [c000000000008368] .start_here_common+0x1c/0x34
> > Instruction dump:
> > 78290464 80090014 5409012f 41820028 4bd5ead5 60000000 2fa30000 419e0018 
> > e93e8008 80090000 2f800000 409e0008 <0fe00000> 38000000 8b8d01da 980d01da 
> > 
> > The machine still boots, so it's not a show stopper.
> 
> 
> Hmmm,
> 
> Seems that we are in interrupt, doing hvc_poll, which does
> tty_flip_buffer_push
> which calls
> flush_to_ldisc
> doing a
> n_tty_receive_buf
> and we will finally take a mutex in echo_set_canon_col 
> 
> my first guess is that the following patch triggered the Badness:
> git show a88a69c9
> commit a88a69c91256418c5907c2f1f8a0ec0a36f9e6cc
> Author: Joe Peterson <joe@skyrush.com>
> Date:   Fri Jan 2 13:40:53 2009 +0000
> 
>     n_tty: Fix loss of echoed characters and remove bkl from n_tty
> 
> 
> I have no idea how to fix this.
> Joe Peterson CCed.
> 
> Christian
> 

Re: [BUG] hvc_console WARN() on current upstream

[Alan Cox]

> > Seems that we are in interrupt, doing hvc_poll, which does
> > tty_flip_buffer_push

Which means that someone has tty->low_latency set and is calling
tty_flip_buffer_push in an IRQ. That has never been allowed or safe, and
now it hurts ;)

/**
 *      tty_flip_buffer_push    -       terminal
 *      @tty: tty to push
 * 
 *      Queue a push of the terminal flip buffers to the line discipline.
This
 *      function must not be called from IRQ context if tty->low_latency
is set *
 *      In the event of the queue being busy for flipping the work will be
 *      held off and retried later.
 *
 *      Locking: tty buffer lock. Driver locks in low latency mode.
 */


That comment has been there for some years in varying formats

[PATCH 0/5] hvc_console updates was Re: [BUG] hvc_console WARN() on current upstream

[Milton Miller]

Alan Cox wrote:
> Benjamin Herrenschmidt wrote:
>> Seems that we are in interrupt, doing hvc_poll, which does
>> tty_flip_buffer_push
>
>Which means that someone has tty->low_latency set and is calling
>tty_flip_buffer_push in an IRQ. That has never been allowed or safe, and
>now it hurts ;)
>
>/**
> *      tty_flip_buffer_push    -       terminal
> *      @tty: tty to push
> * 
> *      Queue a push of the terminal flip buffers to the line discipline.
>This
> *      function must not be called from IRQ context if tty->low_latency
>is set *
> *      In the event of the queue being busy for flipping the work will be
> *      held off and retried later.
> *
> *      Locking: tty buffer lock. Driver locks in low latency mode.
> */
>
>
>That comment has been there for some years in varying formats
>

I actually was preparing a patch for this problem after I had encountered
the a deadlock due to this.  That is in the first patch.   I then found
and made a few more cleanups, although I might have reordered the rest.

The history for setting low_latency is in the changelog of the first patch..

milton

[PATCH 4/4] hvc_console: comment mb and make it an smp_ one

[Milton Miller]

I remember some history on this barrier.  There was a race between
open via /dev/console and the tty being fully setup.  Its also why
there is a temporary variable and the global is assigned at the end
of the function.

Signed-off-by: Milton Miller <miltonm@bga.com>


Index: work.git/drivers/char/hvc_console.c
===================================================================
--- work.git.orig/drivers/char/hvc_console.c	2009-01-08 04:33:39.000000000 -0600
+++ work.git/drivers/char/hvc_console.c	2009-01-08 04:35:09.000000000 -0600
@@ -875,8 +875,11 @@ static int hvc_init(void)
 		goto stop_thread;
 	}
 
-	/* FIXME: This mb() seems completely random.  Remove it. */
-	mb();
+	/*
+	 * Make sure tty is fully registered before allowing it to be
+	 * found by hvc_console_device.
+	 */
+	smp_mb();
 	hvc_driver = drv;
 	return 0;
 

[PATCH 3/4] hvc_console: free_irq only if request_irq was successful

[Milton Miller]

Only call free_irq if we marked the request_irq has having succeeded
instead of whenever the the sub-driver identified the interrupt to use.

Signed-off-by: Milton Miller <miltonm@bga.com>
---
Appears to be a bugfix but might use a bit of time in -next.
This code was created in 2.6.28 to allow s390 to build without adding ifdefs.
Many hvc-console sub-drivers have a single channel and are not modules.

Index: work.git/drivers/char/hvc_irq.c
===================================================================
--- work.git.orig/drivers/char/hvc_irq.c	2009-01-08 04:07:28.000000000 -0600
+++ work.git/drivers/char/hvc_irq.c	2009-01-08 04:07:47.000000000 -0600
@@ -37,7 +37,7 @@ int notifier_add_irq(struct hvc_struct *
 
 void notifier_del_irq(struct hvc_struct *hp, int irq)
 {
-	if (!irq)
+	if (!hp->irq_requested)
 		return;
 	free_irq(irq, hp);
 	hp->irq_requested = 0;

Re: [PATCH 3/4] hvc_console: free_irq only if request_irq was successful

[Christian Borntraeger]

Am Donnerstag, 8. Januar 2009 schrieb Milton Miller:
> Only call free_irq if we marked the request_irq has having succeeded
> instead of whenever the the sub-driver identified the interrupt to use.
> 
> Signed-off-by: Milton Miller <miltonm@bga.com>
> ---
> Appears to be a bugfix but might use a bit of time in -next.
> This code was created in 2.6.28 to allow s390 to build without adding 
ifdefs.
> Many hvc-console sub-drivers have a single channel and are not modules.
> 
> Index: work.git/drivers/char/hvc_irq.c
> ===================================================================
> --- work.git.orig/drivers/char/hvc_irq.c	2009-01-08 04:07:28.000000000 -0600
> +++ work.git/drivers/char/hvc_irq.c	2009-01-08 04:07:47.000000000 -0600
> @@ -37,7 +37,7 @@ int notifier_add_irq(struct hvc_struct *
> 
>  void notifier_del_irq(struct hvc_struct *hp, int irq)
>  {
> -	if (!irq)
> +	if (!hp->irq_requested)
>  		return;
>  	free_irq(irq, hp);
>  	hp->irq_requested = 0;
> 

Looks sane.

Acked-by: Christian Borntraeger <borntraeger@de.ibm.com>

[PATCH 1/4] hvc_console: do not set low_latency

[Milton Miller]

hvc_console is setting low_latency unconditionally, but some clients are
interrupt driven and will call hvc_poll from irq context.  This will cause
tty_flip_buffer_push to be called from irq context, and it very clearly
states it must not be called from IRQ when low_latency is specified.

Looking back through history:
v2.6.16-rc1 via 33f0f88f1c51ae5c2d593d26960c760ea154c2e2
    [PATCH] TTY layer buffering revamp

added this new api.

v2.6.16-rc3 via 8977d929e49021d9a6e031310aab01fa72f849c2
    [PATCH] tty buffering stall fix

claims to fix a stall discovered with hvc_console

v2.6.16-rc5 via fb5c594c2acc441f0d2d8f457484a0e0e9285db3
   [PATCH] Fix race condition in hvc console.

said set this flag to avoid a stall problem, and was merged through
the powerpc arch tree.

Without searching for email discussions, it would appear to be an
overlapping "fix", but one that did not consider all users.

---
This version continues to set low_latency if irqs are not flagged to
be in use, as requested by paulus.   Do all hvc drivers identify the
interrupt this way?  (A quick look at hvc_iucv says they lock to bh
and are not irq driven, the rest would have used the irq before that
patch).

Having the flag set for purely polled drivers will save delaying
the work when receiving input for 1 jiffie.


Index: work.git/drivers/char/hvc_console.c
===================================================================
--- work.git.orig/drivers/char/hvc_console.c	2009-01-08 03:01:24.000000000 -0600
+++ work.git/drivers/char/hvc_console.c	2009-01-08 03:01:51.000000000 -0600
@@ -318,7 +318,8 @@ static int hvc_open(struct tty_struct *t
 	} /* else count == 0 */
 
 	tty->driver_data = hp;
-	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
+	if (!hp->irq_requested)
+		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
 
 	hp->tty = tty;
 

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Alan Cox]

> v2.6.16-rc1 via 33f0f88f1c51ae5c2d593d26960c760ea154c2e2
>     [PATCH] TTY layer buffering revamp
> 
> added this new api.

No - tty_flip_buffer_push is from 2.1.66 and with the same constraints
from the day it was added.


> Having the flag set for purely polled drivers will save delaying
> the work when receiving input for 1 jiffie.
> 
> 
> Index: work.git/drivers/char/hvc_console.c
> ===================================================================
> --- work.git.orig/drivers/char/hvc_console.c	2009-01-08 03:01:24.000000000 -0600
> +++ work.git/drivers/char/hvc_console.c	2009-01-08 03:01:51.000000000 -0600
> @@ -318,7 +318,8 @@ static int hvc_open(struct tty_struct *t
>  	} /* else count == 0 */
>  
>  	tty->driver_data = hp;
> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> +	if (!hp->irq_requested)
> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
>  
>  	hp->tty = tty;

Looks good to me

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Milton Miller]

On Jan 8, 2009, at 6:36 AM, Alan Cox wrote:

>> v2.6.16-rc1 via 33f0f88f1c51ae5c2d593d26960c760ea154c2e2
>>     [PATCH] TTY layer buffering revamp
>>
>> added this new api.
>
> No - tty_flip_buffer_push is from 2.1.66 and with the same constraints
> from the day it was added.
>
Yes but wrappers were added and this this and many ohter drivers were  
converted to use them:

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git; 
a=commitdiff;h=33f0f88f1c51ae5c2d593d26960c760ea154c2e2

And they were slightly buggy leading to the buggy workaround.

>
>> Having the flag set for purely polled drivers will save delaying
>> the work when receiving input for 1 jiffie.
>>
>>
>> Index: work.git/drivers/char/hvc_console.c
>> ===================================================================
>> --- work.git.orig/drivers/char/hvc_console.c	2009-01-08  
>> 03:01:24.000000000 -0600
>> +++ work.git/drivers/char/hvc_console.c	2009-01-08 03:01:51.000000000  
>> -0600
>> @@ -318,7 +318,8 @@ static int hvc_open(struct tty_struct *t
>>  	} /* else count == 0 */
>>
>>  	tty->driver_data = hp;
>> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
>> +	if (!hp->irq_requested)
>> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
>>
>>  	hp->tty = tty;
>
> Looks good to me

Thanks, I guess that is an Ack?

milton

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Christian Borntraeger]

Am Donnerstag 08 Januar 2009 schrieb Milton Miller:
> hvc_console is setting low_latency unconditionally, but some clients are
> interrupt driven and will call hvc_poll from irq context.  This will cause
> tty_flip_buffer_push to be called from irq context, and it very clearly
> states it must not be called from IRQ when low_latency is specified.
> 
> Looking back through history:
> v2.6.16-rc1 via 33f0f88f1c51ae5c2d593d26960c760ea154c2e2
>     [PATCH] TTY layer buffering revamp
> 
> added this new api.
> 
> v2.6.16-rc3 via 8977d929e49021d9a6e031310aab01fa72f849c2
>     [PATCH] tty buffering stall fix
> 
> claims to fix a stall discovered with hvc_console
> 
> v2.6.16-rc5 via fb5c594c2acc441f0d2d8f457484a0e0e9285db3
>    [PATCH] Fix race condition in hvc console.
> 
> said set this flag to avoid a stall problem, and was merged through
> the powerpc arch tree.
> 
> Without searching for email discussions, it would appear to be an
> overlapping "fix", but one that did not consider all users.
> 
> ---
> This version continues to set low_latency if irqs are not flagged to
> be in use, as requested by paulus.   Do all hvc drivers identify the
> interrupt this way?  (A quick look at hvc_iucv says they lock to bh
> and are not irq driven, the rest would have used the irq before that
> patch).
> 
> Having the flag set for purely polled drivers will save delaying
> the work when receiving input for 1 jiffie.
> 
> 
> Index: work.git/drivers/char/hvc_console.c
> ===================================================================
> --- work.git.orig/drivers/char/hvc_console.c	2009-01-08 
03:01:24.000000000 -0600
> +++ work.git/drivers/char/hvc_console.c	2009-01-08 03:01:51.000000000 -0600
> @@ -318,7 +318,8 @@ static int hvc_open(struct tty_struct *t
>  	} /* else count == 0 */
> 
>  	tty->driver_data = hp;
> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> +	if (!hp->irq_requested)
> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> 
>  	hp->tty = tty;
> 
> 

This wont work, since the call to notifier_add is done later:
What about:
---
 drivers/char/hvc_console.c |    5 +++--
 1 file changed, 3 insertions(+), 2 deletions(-)

Index: linux-2.6/drivers/char/hvc_console.c
===================================================================
--- linux-2.6.orig/drivers/char/hvc_console.c
+++ linux-2.6/drivers/char/hvc_console.c
@@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
 	} /* else count == 0 */
 
 	tty->driver_data = hp;
-	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
-
 	hp->tty = tty;
 
 	spin_unlock_irqrestore(&hp->lock, flags);
@@ -327,6 +325,9 @@ static int hvc_open(struct tty_struct *t
 	if (hp->ops->notifier_add)
 		rc = hp->ops->notifier_add(hp, hp->data);
 
+	if (!hp->irq_requested)
+		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
+
 	/*
 	 * If the notifier fails we return an error.  The tty layer
 	 * will call hvc_close() after a failed open but we don't want to clean

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Christian Borntraeger]

Am Dienstag 13 Januar 2009 schrieb Christian Borntraeger:
>  drivers/char/hvc_console.c |    5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
> 
> Index: linux-2.6/drivers/char/hvc_console.c
> ===================================================================
> --- linux-2.6.orig/drivers/char/hvc_console.c
> +++ linux-2.6/drivers/char/hvc_console.c
> @@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
>  	} /* else count == 0 */
> 
>  	tty->driver_data = hp;
> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> -
>  	hp->tty = tty;
> 
>  	spin_unlock_irqrestore(&hp->lock, flags);
> @@ -327,6 +325,9 @@ static int hvc_open(struct tty_struct *t
>  	if (hp->ops->notifier_add)
>  		rc = hp->ops->notifier_add(hp, hp->data);
> 
> +	if (!hp->irq_requested)
> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> +
>  	/*
>  	 * If the notifier fails we return an error.  The tty layer
>  	 * will call hvc_close() after a failed open but we don't want to clean
> 
> 

Just in case:

Signed-off-by: Christian Borntraeger <borntraeger@de.ibm.com>

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Hendrik Brueckner]

Here is yet another bug trace related to the low_latency issue, that is
experienced using the hvc_iucv backend.  The hvc_iucv backend now also uses irq
notifiers.
The bug trace below appears if hvc_kick() is called.

On Tue, Jan 13, 2009 at 10:04:22AM +0100, Christian Borntraeger wrote:
> Am Donnerstag 08 Januar 2009 schrieb Milton Miller:
> > hvc_console is setting low_latency unconditionally, but some clients are
> > interrupt driven and will call hvc_poll from irq context.  This will cause
> > tty_flip_buffer_push to be called from irq context, and it very clearly
> > states it must not be called from IRQ when low_latency is specified.
It seems that if low_latency is set, tty_flip_buffer_push() should also not be
called within an atomic context, because echo_char_raw() and other echo* calls
might sleep.

Christian's patch solves this problem for irq driven backends.
However, there might be still a problem with polled backends since the khvcd()
thread calls hvc_poll() while hvc_structs_lock is held.

I think the hvc_udbg backend is based on polling.
David, could you check if you experience any problems with your hvc_udbg
backend on latest git.

BUG: sleeping function called from invalid context at /root/cvs/linux-2.6.git/kernel/mutex.c:207
in_atomic(): 1, irqs_disabled(): 0, pid: 748, name: khvcd
1 lock held by khvcd/748:
 #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] khvcd+0x58/0x12c
CPU: 0 Not tainted 2.6.29-rc1git #29
Process khvcd (pid: 748, task: 000000002fb9a480, ksp: 000000002f66bd78)
070000000000000a 000000002f66ba00 0000000000000002 (null) 
       000000002f66baa0 000000002f66ba18 000000002f66ba18 0000000000104f08 
       ffffffffffffc000 000000002f66bd78 (null) (null) 
       000000002f66ba00 000000000000000c 000000002f66ba00 000000002f66ba70 
       0000000000466af8 0000000000104f08 000000002f66ba00 000000002f66ba50 
Call Trace:
([<0000000000104e7c>] show_trace+0x138/0x158)
 [<0000000000104f62>] show_stack+0xc6/0xf8
 [<0000000000105740>] dump_stack+0xb0/0xc0
 [<000000000013144a>] __might_sleep+0x14e/0x17c
 [<000000000045e226>] mutex_lock_nested+0x42/0x3b4
 [<00000000002c443e>] echo_char_raw+0x3a/0x9c
 [<00000000002c688c>] n_tty_receive_buf+0x1154/0x1208
 [<00000000002ca0a2>] flush_to_ldisc+0x152/0x220
 [<00000000002ca1da>] tty_flip_buffer_push+0x6a/0x90
 [<00000000002cea74>] hvc_poll+0x244/0x2c8
 [<00000000002ceb68>] khvcd+0x70/0x12c
 [<000000000015bbd0>] kthread+0x68/0xa0
 [<0000000000109d5a>] kernel_thread_starter+0x6/0xc
 [<0000000000109d54>] kernel_thread_starter+0x0/0xc
1 lock held by khvcd/748:
 #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] khvcd+0x58/0x12c

> This wont work, since the call to notifier_add is done later:
> What about:
> ---
>  drivers/char/hvc_console.c |    5 +++--
>  1 file changed, 3 insertions(+), 2 deletions(-)
> 
> Index: linux-2.6/drivers/char/hvc_console.c
> ===================================================================
> --- linux-2.6.orig/drivers/char/hvc_console.c
> +++ linux-2.6/drivers/char/hvc_console.c
> @@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
>  	} /* else count == 0 */
> 
>  	tty->driver_data = hp;
> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> -
>  	hp->tty = tty;
> 
>  	spin_unlock_irqrestore(&hp->lock, flags);
> @@ -327,6 +325,9 @@ static int hvc_open(struct tty_struct *t
>  	if (hp->ops->notifier_add)
>  		rc = hp->ops->notifier_add(hp, hp->data);
> 
> +	if (!hp->irq_requested)
> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> +
>  	/*
>  	 * If the notifier fails we return an error.  The tty layer
>  	 * will call hvc_close() after a failed open but we don't want to clean

Acked-by: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Milton Miller]

On Jan 13, 2009, at 5:35 AM, Hendrik Brueckner wrote:

> Here is yet another bug trace related to the low_latency issue, that is
> experienced using the hvc_iucv backend.  The hvc_iucv backend now also 
> uses irq
> notifiers.
> The bug trace below appears if hvc_kick() is called.
>
> On Tue, Jan 13, 2009 at 10:04:22AM +0100, Christian Borntraeger wrote:
>> Am Donnerstag 08 Januar 2009 schrieb Milton Miller:
>>> hvc_console is setting low_latency unconditionally, but some clients 
>>> are
>>> interrupt driven and will call hvc_poll from irq context.  This will 
>>> cause
>>> tty_flip_buffer_push to be called from irq context, and it very 
>>> clearly
>>> states it must not be called from IRQ when low_latency is specified.
> It seems that if low_latency is set, tty_flip_buffer_push() should 
> also not be
> called within an atomic context, because echo_char_raw() and other 
> echo* calls
> might sleep.
>
> Christian's patch solves this problem for irq driven backends.
> However, there might be still a problem with polled backends since the 
> khvcd()
> thread calls hvc_poll() while hvc_structs_lock is held.
>
> I think the hvc_udbg backend is based on polling.
> David, could you check if you experience any problems with your 
> hvc_udbg
> backend on latest git.
>


So the simplest is to never set it.

milton

> BUG: sleeping function called from invalid context at 
> /root/cvs/linux-2.6.git/kernel/mutex.c:207
> in_atomic(): 1, irqs_disabled(): 0, pid: 748, name: khvcd
> 1 lock held by khvcd/748:
>  #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] 
> khvcd+0x58/0x12c
> CPU: 0 Not tainted 2.6.29-rc1git #29
> Process khvcd (pid: 748, task: 000000002fb9a480, ksp: 000000002f66bd78)
> 070000000000000a 000000002f66ba00 0000000000000002 (null)
>        000000002f66baa0 000000002f66ba18 000000002f66ba18 
> 0000000000104f08
>        ffffffffffffc000 000000002f66bd78 (null) (null)
>        000000002f66ba00 000000000000000c 000000002f66ba00 
> 000000002f66ba70
>        0000000000466af8 0000000000104f08 000000002f66ba00 
> 000000002f66ba50
> Call Trace:
> ([<0000000000104e7c>] show_trace+0x138/0x158)
>  [<0000000000104f62>] show_stack+0xc6/0xf8
>  [<0000000000105740>] dump_stack+0xb0/0xc0
>  [<000000000013144a>] __might_sleep+0x14e/0x17c
>  [<000000000045e226>] mutex_lock_nested+0x42/0x3b4
>  [<00000000002c443e>] echo_char_raw+0x3a/0x9c
>  [<00000000002c688c>] n_tty_receive_buf+0x1154/0x1208
>  [<00000000002ca0a2>] flush_to_ldisc+0x152/0x220
>  [<00000000002ca1da>] tty_flip_buffer_push+0x6a/0x90
>  [<00000000002cea74>] hvc_poll+0x244/0x2c8
>  [<00000000002ceb68>] khvcd+0x70/0x12c
>  [<000000000015bbd0>] kthread+0x68/0xa0
>  [<0000000000109d5a>] kernel_thread_starter+0x6/0xc
>  [<0000000000109d54>] kernel_thread_starter+0x0/0xc
> 1 lock held by khvcd/748:
>  #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] 
> khvcd+0x58/0x12c
>
>> This wont work, since the call to notifier_add is done later:
>> What about:
>> ---
>>  drivers/char/hvc_console.c |    5 +++--
>>  1 file changed, 3 insertions(+), 2 deletions(-)
>>
>> Index: linux-2.6/drivers/char/hvc_console.c
>> ===================================================================
>> --- linux-2.6.orig/drivers/char/hvc_console.c
>> +++ linux-2.6/drivers/char/hvc_console.c
>> @@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
>>  	} /* else count == 0 */
>>
>>  	tty->driver_data = hp;
>> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
>> -
>>  	hp->tty = tty;
>>
>>  	spin_unlock_irqrestore(&hp->lock, flags);
>> @@ -327,6 +325,9 @@ static int hvc_open(struct tty_struct *t
>>  	if (hp->ops->notifier_add)
>>  		rc = hp->ops->notifier_add(hp, hp->data);
>>
>> +	if (!hp->irq_requested)
>> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
>> +
>>  	/*
>>  	 * If the notifier fails we return an error.  The tty layer
>>  	 * will call hvc_close() after a failed open but we don't want to 
>> clean
>
> Acked-by: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>
>

Re: [PATCH 1/4] hvc_console: do not set low_latency

[Benjamin Herrenschmidt]

> So the simplest is to never set it.

I already applied your previous patch. Please send an incremental fix.

Cheers,
Ben.

> milton
> 
> > BUG: sleeping function called from invalid context at 
> > /root/cvs/linux-2.6.git/kernel/mutex.c:207
> > in_atomic(): 1, irqs_disabled(): 0, pid: 748, name: khvcd
> > 1 lock held by khvcd/748:
> >  #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] 
> > khvcd+0x58/0x12c
> > CPU: 0 Not tainted 2.6.29-rc1git #29
> > Process khvcd (pid: 748, task: 000000002fb9a480, ksp: 000000002f66bd78)
> > 070000000000000a 000000002f66ba00 0000000000000002 (null)
> >        000000002f66baa0 000000002f66ba18 000000002f66ba18 
> > 0000000000104f08
> >        ffffffffffffc000 000000002f66bd78 (null) (null)
> >        000000002f66ba00 000000000000000c 000000002f66ba00 
> > 000000002f66ba70
> >        0000000000466af8 0000000000104f08 000000002f66ba00 
> > 000000002f66ba50
> > Call Trace:
> > ([<0000000000104e7c>] show_trace+0x138/0x158)
> >  [<0000000000104f62>] show_stack+0xc6/0xf8
> >  [<0000000000105740>] dump_stack+0xb0/0xc0
> >  [<000000000013144a>] __might_sleep+0x14e/0x17c
> >  [<000000000045e226>] mutex_lock_nested+0x42/0x3b4
> >  [<00000000002c443e>] echo_char_raw+0x3a/0x9c
> >  [<00000000002c688c>] n_tty_receive_buf+0x1154/0x1208
> >  [<00000000002ca0a2>] flush_to_ldisc+0x152/0x220
> >  [<00000000002ca1da>] tty_flip_buffer_push+0x6a/0x90
> >  [<00000000002cea74>] hvc_poll+0x244/0x2c8
> >  [<00000000002ceb68>] khvcd+0x70/0x12c
> >  [<000000000015bbd0>] kthread+0x68/0xa0
> >  [<0000000000109d5a>] kernel_thread_starter+0x6/0xc
> >  [<0000000000109d54>] kernel_thread_starter+0x0/0xc
> > 1 lock held by khvcd/748:
> >  #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] 
> > khvcd+0x58/0x12c
> >
> >> This wont work, since the call to notifier_add is done later:
> >> What about:
> >> ---
> >>  drivers/char/hvc_console.c |    5 +++--
> >>  1 file changed, 3 insertions(+), 2 deletions(-)
> >>
> >> Index: linux-2.6/drivers/char/hvc_console.c
> >> ===================================================================
> >> --- linux-2.6.orig/drivers/char/hvc_console.c
> >> +++ linux-2.6/drivers/char/hvc_console.c
> >> @@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
> >>  	} /* else count == 0 */
> >>
> >>  	tty->driver_data = hp;
> >> -	tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> >> -
> >>  	hp->tty = tty;
> >>
> >>  	spin_unlock_irqrestore(&hp->lock, flags);
> >> @@ -327,6 +325,9 @@ static int hvc_open(struct tty_struct *t
> >>  	if (hp->ops->notifier_add)
> >>  		rc = hp->ops->notifier_add(hp, hp->data);
> >>
> >> +	if (!hp->irq_requested)
> >> +		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> >> +
> >>  	/*
> >>  	 * If the notifier fails we return an error.  The tty layer
> >>  	 * will call hvc_close() after a failed open but we don't want to 
> >> clean
> >
> > Acked-by: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>
> >

Re: [PATCH 1/4 v2] hvc_console: remove tty->low_latency

[Hendrik Brueckner]

On Wed, Jan 14, 2009 at 08:04:04AM +1100, Benjamin Herrenschmidt wrote:
> > So the simplest is to never set it.
> 
> I already applied your previous patch. Please send an incremental fix.
Here is the incremental patch for your powerpc tree along with a summary
as patch description.

Regards,
Hendrik

--
This patch removes the tty->low_latency setting.

For irq based hvc_console backends the tty->low_latency must be set to 0,
because the tty_flip_buffer_push() function must not be called from IRQ context
(see drivers/char/tty_buffer.c).

For polled backends, the low_latency setting causes the bug trace below, because
tty_flip_buffer_push() is called within an atomic context and subsequent calls
might sleep due to mutex_lock.

BUG: sleeping function called from invalid context at /root/cvs/linux-2.6.git/kernel/mutex.c:207
in_atomic(): 1, irqs_disabled(): 0, pid: 748, name: khvcd
1 lock held by khvcd/748:
 #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] khvcd+0x58/0x12c
CPU: 0 Not tainted 2.6.29-rc1git #29
Process khvcd (pid: 748, task: 000000002fb9a480, ksp: 000000002f66bd78)
070000000000000a 000000002f66ba00 0000000000000002 (null) 
       000000002f66baa0 000000002f66ba18 000000002f66ba18 0000000000104f08 
       ffffffffffffc000 000000002f66bd78 (null) (null) 
       000000002f66ba00 000000000000000c 000000002f66ba00 000000002f66ba70 
       0000000000466af8 0000000000104f08 000000002f66ba00 000000002f66ba50 
Call Trace:
([<0000000000104e7c>] show_trace+0x138/0x158)
 [<0000000000104f62>] show_stack+0xc6/0xf8
 [<0000000000105740>] dump_stack+0xb0/0xc0
 [<000000000013144a>] __might_sleep+0x14e/0x17c
 [<000000000045e226>] mutex_lock_nested+0x42/0x3b4
 [<00000000002c443e>] echo_char_raw+0x3a/0x9c
 [<00000000002c688c>] n_tty_receive_buf+0x1154/0x1208
 [<00000000002ca0a2>] flush_to_ldisc+0x152/0x220
 [<00000000002ca1da>] tty_flip_buffer_push+0x6a/0x90
 [<00000000002cea74>] hvc_poll+0x244/0x2c8
 [<00000000002ceb68>] khvcd+0x70/0x12c
 [<000000000015bbd0>] kthread+0x68/0xa0
 [<0000000000109d5a>] kernel_thread_starter+0x6/0xc
 [<0000000000109d54>] kernel_thread_starter+0x0/0xc
1 lock held by khvcd/748:
 #0:  (hvc_structs_lock){--..}, at: [<00000000002ceb50>] khvcd+0x58/0x12c

Signed-off-by: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>
---
 drivers/char/hvc_console.c |    2 --
 1 file changed, 2 deletions(-)

--- a/drivers/char/hvc_console.c
+++ b/drivers/char/hvc_console.c
@@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
 	} /* else count == 0 */
 
 	tty->driver_data = hp;
-	if (!hp->irq_requested)
-		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
 
 	hp->tty = tty;
 

Re: [PATCH 1/4 v2] hvc_console: remove tty->low_latency

[Christian Borntraeger]

> Signed-off-by: Hendrik Brueckner <brueckner@linux.vnet.ibm.com>
> ---
>  drivers/char/hvc_console.c |    2 --
>  1 file changed, 2 deletions(-)
> 
> --- a/drivers/char/hvc_console.c
> +++ b/drivers/char/hvc_console.c
> @@ -318,8 +318,6 @@ static int hvc_open(struct tty_struct *t
>  	} /* else count == 0 */
> 
>  	tty->driver_data = hp;
> -	if (!hp->irq_requested)
> -		tty->low_latency = 1; /* Makes flushes to ldisc synchronous. */
> 
>  	hp->tty = tty;
> 
> 

Acked-by: Christian Borntraeger <borntraeger@de.ibm.com>

[PATCH 2/4] hvc_console: use kzalloc

[Milton Miller]

Replace kmalloc + memset  with kzalloc.

Signed-off-by: Milton Miller <miltonm@bga.com>

Index: work.git/drivers/char/hvc_console.c
===================================================================
--- work.git.orig/drivers/char/hvc_console.c	2009-01-08 04:24:10.000000000 -0600
+++ work.git/drivers/char/hvc_console.c	2009-01-08 04:24:35.000000000 -0600
@@ -765,13 +765,11 @@ struct hvc_struct __devinit *hvc_alloc(u
 			return ERR_PTR(err);
 	}
 
-	hp = kmalloc(ALIGN(sizeof(*hp), sizeof(long)) + outbuf_size,
+	hp = kzalloc(ALIGN(sizeof(*hp), sizeof(long)) + outbuf_size,
 			GFP_KERNEL);
 	if (!hp)
 		return ERR_PTR(-ENOMEM);
 
-	memset(hp, 0x00, sizeof(*hp));
-
 	hp->vtermno = vtermno;
 	hp->data = data;
 	hp->ops = ops;

Re: [BUG] hvc_console WARN() on current upstream

[Benjamin Herrenschmidt]

On Thu, 2009-01-08 at 11:11 +0000, Alan Cox wrote:
> > > Seems that we are in interrupt, doing hvc_poll, which does
> > > tty_flip_buffer_push
> 
> Which means that someone has tty->low_latency set and is calling
> tty_flip_buffer_push in an IRQ. That has never been allowed or safe, and
> now it hurts ;)

Heh, allright :-) I'll see where that flag is set and clear it when
using IRQs.

> That comment has been there for some years in varying formats

Possibly, I didn't write that code, thanks for pointing me to the
problem.

Cheers,
Ben.