Messages in this thread | | | Date | Fri, 17 Jul 2009 13:06:45 +0200 | From | Takashi Iwai <> | Subject | Re: 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
| |