Re: open() on /dev/tty takes 30 seconds on 2.6.36

[Arnd Bergmann <arnd@arndb.de>]

On Saturday 30 October 2010, Andrew Morton wrote:
> > static int ptmx_open(struct inode *inode, struct file *filp)
> > {
> >     struct tty_struct *tty;
> >     int retval;
> >     int index;
> > 
> >     nonseekable_open(inode, filp);
> > 
> >     /* find a device that is not in use. */
> >     printk(KERN_ALERT  "34: ptmx_open to lock\n");
> >     tty_lock();
> >     printk(KERN_ALERT  "35: ptmx_open locked\n");
> > 
> > [snipped here]
> > 
> > And then found in my /var/log/messages (no log lines between these two):
> > Oct 29 16:14:58 ocho kernel: 34: ptmx_open to lock
> > Oct 29 16:15:13 ocho kernel: 35: ptmx_open locked
> > 
> > So we can see it took 15 seconds to acquire a lock in this case. In all 
> > other pairs of lock messages there was no time difference. To me it 
> > looks like 15 seconds in order to acquire a lock in the kernel is a 
> > smoking gun.

Agreed. When I changed the locking to use a mutex instead of the BKL,
I intentionally left it locked across sleeping functions, but none of
them are supposed to sleep for multiple seconds.

> 
> Odd.  Presumably someone else was holding big_tty_mutex for 15 seconds.
> 
> We can find out who, with the sysrq-d command if you have the time
> please.  You'll need to enable lockdep and magic sysrq in .config. 
> Then run `dmesg -n 8' so all messages get printed by the kernel and
> then, in the middle of that 15-second delay, do
> 
>         echo d > /proc/sysrq-trigger
> 
> I'll confess that I've never used sysrq-d and am unsure what the output
> looks like.  Fingers crossed!

With a little luck, lockdep by itself might even be able to find an
inconsistency in the BTM use and warn right away about it. I found
a number of bugs in the TTY code just by running with lockdep in the
mutex version.

	Arnd