lkml.org 
[lkml]   [2010]   [Nov]   [1]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
SubjectRe: open() on /dev/tty takes 30 seconds on 2.6.36
Date
On Monday 01 November 2010, Eli Billauer wrote:
> Let me start with the headline: It's close() of a ttySx that takes 30
> seconds, during which the big TTY lock is held. Now to details.

Ok, good to hear you tracked it down this far!

> Arnd Bergmann wrote:
>
> > So modem-manager is the process you need to look at, as it holds the
> > BTM, probably for a long time. It should not do that. First you should
> > verify that when you don't have modem-manager running, the problem goes
> > away. This may indeed be related to the misdetection of a serial port.
> >
> That test is built-in: When modem-manager stops poking around,
> everything becomes fine again.

Ok.

> > The other thing to check is what modem-manager is actually doing. You can
> > find out by looking at /proc/<pid>/stack, where <pid> is the pid of the
> > modem-manager process, 1835 in your example.
> >
> OK, so this is what I did eventually: I ran strace on sshd and
> modem-manager, and I also added printk's to tell me when tty_lock() is
> invoked, when it actually got the lock, and when tty_unlock() is
> invoked. Pretty messy, and still.
>
> Let's start with sshd's strace. We have a
> 01:06:20.152787 open("/dev/tty", O_RDWR|O_NOCTTY) = -1 ENXIO (No such
> device or address) <30.008153>

That looks unrelated, as far as I can tell.

> And this is what we have in /var/log/messages:
>
> Nov 1 01:06:20 ocho modem-manager: (ttyS2) closing serial device...
> Nov 1 01:06:20 ocho kernel: tty_lock() called
> Nov 1 01:06:20 ocho kernel: tty_lock() got lock
> Nov 1 01:06:20 ocho kernel: tty_lock() called
> Nov 1 01:06:50 ocho kernel: tty_unlock() called
> Nov 1 01:06:50 ocho kernel: tty_lock() got lock
> Nov 1 01:06:50 ocho kernel: tty_unlock() called
> Nov 1 01:06:50 ocho kernel: tty_lock() called
>
> So we can see that someone got the lock, and then didn't release it for
> 30 seconds, and that someone else tried to get the lock and waited for
> it 30 seconds.

Ok, that's certainly modem-manager in the tty_release function, calling
uart_close, which has this code:

if (port->closing_wait != ASYNC_CLOSING_WAIT_NONE) {
/*
* hack: open-coded tty_wait_until_sent to avoid
* recursive tty_lock
*/
long timeout = msecs_to_jiffies(port->closing_wait);
if (wait_event_interruptible_timeout(tty->write_wait,
!tty_chars_in_buffer(tty), timeout) >= 0)
__uart_wait_until_sent(uport, timeout);
}

port->closing_wait gets initialized to 30 seconds, which fits your
symptom.

I'm not sure whether it blocks in wait_event or in __uart_wait_until_sent
though, both get the same timeout.

> An strace of modem-manager running under vanilla kernel 2.6.35-4 shows
> that close() takes 30 seconds there as well. It just so happens that it
> went unnoticed (maybe because of the changes in the locking schema?).

Exactly. The code used to hold the BKL, which gets implicitly released
during a sleeping operation like wait_event_interruptible_timeout or
__uart_wait_until_sent. With the change to a mutex, this does not
happen any more.

When I did the change, I did not anticipate the call actually timing
out the 30 seconds.

> I should only note that all TTY close() calls take 30 seconds, and that
> all ports get a ioctl() and extra close() after the file descriptor is
> closed, with an EBADF as response.

This must be an unrelated bug in modem-manager.

Can you confirm that this only happens on tty1 through tty4, but not on
tty0, which is your real uart?

I think we need to find out why it's hitting the timeout most of all,
and that means understanding what the hardware on your system is actually
doing or supposed to be doing. What does "lspci -vvx" show about the
port? Can you disable it in some way?

Arnd


\
 
 \ /
  Last update: 2010-11-01 20:41    [W:0.136 / U:0.592 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site