lkml.org 
[lkml]   [2009]   [Jul]   [17]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: tty related hangs with 2.6.31-rc3
At Wed, 15 Jul 2009 16:11:42 +0100,
Alan Cox wrote:
>
> On Wed, 15 Jul 2009 18:59:56 +0530
> "Aneesh Kumar K.V" <aneesh.kumar@linux.vnet.ibm.com> wrote:
>
> > Hi,
> >
> > I am finding tty related hangs with 2.6.31-rc3. This didn't happen
> > before. This happen when i close the emacs session. The /proc/<pid>/stack
> > content is below
>
> Thanks - nice clear trace. Looks like a bug in the n_tty locking changes
> from a few releases back that the pty changes are triggering.
>
> Basically process_echoes calls tty_put_char which if it thinks a device
> queue was full and now has a bit of space will call tty_wakeup which can
> call process_echoes and thus deadlock. With a physical serial device we
> will even sometimes call tty_wakeup() from the serial transmit path
> which is an irq path (which makes this doubly wrong as it then takes
> mutexes)
>
> Emacs presumably uses fasync which is the trigger for this. You need the
> right timing combined with the new pty behaviour combined with FASYNC to
> trigger it.
>
>
> > [<c0362c5b>] process_echoes+0x2b/0x2e0
> [which tries to take the lock we already hold (end A)]
> > [<c03638cb>] n_tty_write_wakeup+0xb/0x40
> [which processes our ldisc wakeup (end A)]
> > [<c0360a88>] tty_wakeup+0x58/0x70
> [which wakes up our tty (end A)]
> > [<c0368347>] pty_write+0x67/0x70
> [our write method is for tty/pty pairs end A output, queued to end B]
> > [<c035f1cb>] tty_put_char+0x2b/0x40
> [calls tty_put_char to write the echoed byte to end A output]
> > [<c036291f>] do_output_char+0xef/0x200
> [the fake typed character is echoed back towards end B]
> > [<c0362d4e>] process_echoes+0x11e/0x2e0
> [tries to process echo characters on end A]
> > [<c0364292>] n_tty_receive_char+0x102/0x710
> [ receives a byte that we've faked typing to end A input]
> > [<c0364ac0>] n_tty_receive_buf+0x220/0x410
> [ioctl method calls the ld->ops->receive_buf for n_tty (unsafely but that
> bug is old]
> > [<c036059c>] tiocsti+0x8c/0xa0
> > [<c0361aca>] tty_ioctl+0x25a/0x310
> > [<c01e52c8>] vfs_ioctl+0x28/0x80
> > [<c01e54f4>] do_vfs_ioctl+0x64/0x1c0
> > [<c01e56a3>] sys_ioctl+0x53/0x70
> > [<c0102e3c>] sysenter_do_call+0x12/0x28
> > [<ffffffff>] 0xffffffff
>
> Do you have the lock validator enabled and if so did it have anything
> useful to report ?

I hit the same bug. The log is attached below.


> Please try the following. I suspect this is the real fix:
>
> n_tty: Fix echo race
>
> From: Alan Cox <alan@linux.intel.com>
>
> If a tty in N_TTY mode with echo enabled manages to get itself into a state
> where
> - echo characters are pending
> - FASYNC is enabled
> - tty_write_wakeup is called from either
> - a device write path (pty)
> - an IRQ (serial)
>
> then it either deadlocks or explodes taking a mutex in the IRQ path.
>
> On the serial side it is almost impossible to reproduce because you have to
> go from a full serial port to a near empty one with echo characters
> pending. The pty case happens to have become possible to trigger using
> emacs and ptys, the pty changes having created a scenario which shows up
> this bug.
>
> The code path is
>
> n_tty:process_echoes() (takes mutex)
> tty_io:tty_put_char()
> pty:pty_write (or serial paths)
> tty_wakeup (from pty_write or serial IRQ)
> n_tty_write_wakeup()
> process_echoes()
> *KABOOM*
>
> Signed-off-by: Alan Cox <alan@linux.intel.com>

The patch seems to fix the problem indeed.
Thanks!

Tested-by: Takashi Iwai <tiwai@suse.de>


Takashi

=============================================
[ INFO: possible recursive locking detected ]
2.6.31-rc3-test #43
---------------------------------------------
events/3/18 is trying to acquire lock:
(&tty->output_lock){+.+...}, at: [<ffffffff81245af7>] process_echoes+0x45/0x2bf

but task is already holding lock:
(&tty->output_lock){+.+...}, at: [<ffffffff81245af7>] process_echoes+0x45/0x2bf

other info that might help us debug this:
4 locks held by events/3/18:
#0: (events){+.+.+.}, at: [<ffffffff8107000f>] worker_thread+0x1c5/0x330
#1: (&(&tty->buf.work)->work){+.+...}, at: [<ffffffff8107000f>] worker_thread+0x1c5/0x330
#2: (&tty->output_lock){+.+...}, at: [<ffffffff81245af7>] process_echoes+0x45/0x2bf
#3: (&tty->echo_lock){+.+...}, at: [<ffffffff81245b0c>] process_echoes+0x5a/0x2bf

stack backtrace:
Pid: 18, comm: events/3 Not tainted 2.6.31-rc3-test #43
Call Trace:
[<ffffffff8108b1fb>] __lock_acquire+0x14d6/0x157d
[<ffffffff810879f7>] ? save_trace+0x4e/0xc0
[<ffffffff81087af9>] ? add_lock_to_list+0x90/0xeb
[<ffffffff81245af7>] ? process_echoes+0x45/0x2bf
[<ffffffff8108b390>] lock_acquire+0xee/0x12e
[<ffffffff81245af7>] ? process_echoes+0x45/0x2bf
[<ffffffff81249a4f>] ? tty_ldisc_try+0x2b/0x6f
[<ffffffff81245af7>] ? process_echoes+0x45/0x2bf
[<ffffffff81334b6f>] mutex_lock_nested+0x66/0x2f2
[<ffffffff81245af7>] ? process_echoes+0x45/0x2bf
[<ffffffff81088b6c>] ? mark_held_locks+0x65/0x9b
[<ffffffff81336926>] ? _spin_unlock_irqrestore+0x55/0x7a
[<ffffffff81245af7>] process_echoes+0x45/0x2bf
[<ffffffff81245d91>] n_tty_write_wakeup+0x20/0x6a
[<ffffffff8124402e>] tty_wakeup+0x44/0x84
[<ffffffff8124bfcb>] pty_write+0x62/0x82
[<ffffffff81245b0c>] ? process_echoes+0x5a/0x2bf
[<ffffffff81241ba8>] tty_put_char+0x3c/0x52
[<ffffffff81245a84>] do_output_char+0x1ce/0x1fc
[<ffffffff81245cbd>] process_echoes+0x20b/0x2bf
[<ffffffff813345ec>] ? mutex_unlock+0x1c/0x32
[<ffffffff8124783d>] n_tty_receive_buf+0x33e/0xf1e
[<ffffffff81088b6c>] ? mark_held_locks+0x65/0x9b
[<ffffffff81336926>] ? _spin_unlock_irqrestore+0x55/0x7a
[<ffffffff81088e78>] ? trace_hardirqs_on_caller+0x124/0x15e
[<ffffffff81088ed2>] ? trace_hardirqs_on+0x20/0x36
[<ffffffff8124ade7>] flush_to_ldisc+0x119/0x1c0
[<ffffffff8124acce>] ? flush_to_ldisc+0x0/0x1c0
[<ffffffff81070061>] worker_thread+0x217/0x330
[<ffffffff8107000f>] ? worker_thread+0x1c5/0x330
[<ffffffff81088e78>] ? trace_hardirqs_on_caller+0x124/0x15e
[<ffffffff81075d40>] ? autoremove_wake_function+0x0/0x5a
[<ffffffff8106fe4a>] ? worker_thread+0x0/0x330
[<ffffffff81075900>] kthread+0x94/0x9c
[<ffffffff8101402a>] child_rip+0xa/0x20
[<ffffffff81013990>] ? restore_args+0x0/0x30
[<ffffffff8107586c>] ? kthread+0x0/0x9c
[<ffffffff81014020>] ? child_rip+0x0/0x20


\
 
 \ /
  Last update: 2009-07-17 13:09    [W:4.170 / U:0.016 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site