Re: 2.6.16.18 kernel freezes while pppd is exiting

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Chuck Ebbert]

In-Reply-To: <448893DD.7010207@microgate.com>

On Thu, 08 Jun 2006 16:17:17 -0500, Paul Fulghum wrote:

> > Very infrequently I get kernel freezes while pppd is exiting.
> > Today I finally got traces from the serial console.
> 
> Chuck:
> 
> What kind of device are you using with pppd?
> (so I can identify which driver is feeding
> the tty layer receive data)

Just a regular 16550A port at 57600 baud using the 8250 driver.

> Are you setting the low_latency flag on that device?
> (setserial)

Not that I know of.

-- 
Chuck

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

Chuck Ebbert wrote:
>>What kind of device are you using with pppd?
>>(so I can identify which driver is feeding
>>the tty layer receive data)
> 
> 
> Just a regular 16550A port at 57600 baud using the 8250 driver.
> 
> 
>>Are you setting the low_latency flag on that device?
>>(setserial)
> 
> 
> Not that I know of.

OK, thanks.

I'm 99.9% sure I've identified the problem correctly,
as it would effect the free list in precisely the
way necessary to cause an infinite loop when trying to
free the list.

My first suggested fix has problems, but there is
a straight forward solution I'll try to post
today (I've got a backlog of stuff to do here at
work before I can get to that.)

-- 
Paul Fulghum
Microgate Systems, Ltd.

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

Chuck:

Here is a patch to serialize flush_to_ldisc
with per device granularity. It should fix the
corruption of the free list that is the probably
cause of the freeze you are seeing. Test it to
see if there are any ill effects (it works fine here
on an AMD x2 SMP kernel). I realize that
the problem happens infrequently, so you won't
be able to tell quickly if it fixed the freeze.

This is a necessary change regardless, but I'm
confident it is the cause of your problem.

Just keep using it and keep me posted on the results.

Thanks,
Paul

--- a/include/linux/tty.h	2006-06-09 09:33:16.000000000 -0500
+++ b/include/linux/tty.h	2006-06-12 09:22:10.000000000 -0500
@@ -267,6 +267,7 @@ struct tty_struct {
 #define TTY_PTY_LOCK 		16	/* pty private */
 #define TTY_NO_WRITE_SPLIT 	17	/* Preserve write boundaries to driver */
 #define TTY_HUPPED 		18	/* Post driver->hangup() */
+#define TTY_FLUSHING 		19	/* Flushing tty buffers to line discipline */
 
 #define TTY_WRITE_FLUSH(tty) tty_write_flush((tty))
 
--- a/drivers/char/tty_io.c	2006-06-12 09:27:35.000000000 -0500
+++ b/drivers/char/tty_io.c	2006-06-12 09:31:41.000000000 -0500
@@ -2785,10 +2785,8 @@ static void flush_to_ldisc(void *private
 	if (disc == NULL)	/*  !TTY_LDISC */
 		return;
 
-	if (test_bit(TTY_DONT_FLIP, &tty->flags)) {
-		/*
-		 * Do it after the next timer tick:
-		 */
+	if (test_bit(TTY_DONT_FLIP, &tty->flags) ||
+	    test_and_set_bit(TTY_FLUSHING, &tty->flags)) {
 		schedule_delayed_work(&tty->buf.work, 1);
 		goto out;
 	}
@@ -2810,6 +2808,7 @@ static void flush_to_ldisc(void *private
 		tty_buffer_free(tty, tbuf);
 	}
 	spin_unlock_irqrestore(&tty->buf.lock, flags);
+	clear_bit(TTY_FLUSHING, &tty->flags);
 out:
 	tty_ldisc_deref(disc);
 }

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Alan Cox]

Ar Llu, 2006-06-12 am 10:07 -0500, ysgrifennodd Paul Fulghum:
> Chuck:
> 
> Here is a patch to serialize flush_to_ldisc
> with per device granularity. It should fix the
> corruption of the free list that is the probably

>  	spin_unlock_irqrestore(&tty->buf.lock, flags);
> +	clear_bit(TTY_FLUSHING, &tty->flags);

Shouldn't those two be reversed if you want to go with this path. How is
this occuring anyway the flush_to_ldisc path should never re-enter.

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

Alan Cox wrote:
>> 	spin_unlock_irqrestore(&tty->buf.lock, flags);
>>+	clear_bit(TTY_FLUSHING, &tty->flags);
> 
> 
> Shouldn't those two be reversed if you want to go with this path.

I don't see that is necessary.

 > How is this occuring anyway the flush_to_ldisc path should never re-enter.

If a driver has low_latency set, flush_to_ldisc
can be called from both scheduled work (due to
hitting TTY_DONT_FLIP) and directly from an ISR.
On an SMP system, they can run in parallel.

I don't know for sure that is the path being hit,
it could be some other odd combination.
But there is no inherent serialization
of flush_to_ldisc.

-- 
Paul Fulghum
Microgate Systems, Ltd.

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Alan Cox]

Ar Llu, 2006-06-12 am 11:11 -0500, ysgrifennodd Paul Fulghum:
> If a driver has low_latency set, flush_to_ldisc
> can be called from both scheduled work (due to
> hitting TTY_DONT_FLIP) and directly from an ISR.
> On an SMP system, they can run in parallel.

Ok, so yet another reason that the ugly TTY_DONT_FLIP hack should die
forever.

Alan

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

Alan Cox wrote:
> ... the ugly TTY_DONT_FLIP hack should die forever.

No tears here.

-- 
Paul Fulghum
Microgate Systems, Ltd.

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Chuck Ebbert]

In-Reply-To: <1150124830.3703.6.camel@amdx2.microgate.com>

On Mon, 12 Jun 2006 10:07:10 -0500, Paul Fulghum wrote:

> Here is a patch to serialize flush_to_ldisc
> with per device granularity. It should fix the
> corruption of the free list that is the probably
> cause of the freeze you are seeing. Test it to
> see if there are any ill effects (it works fine here
> on an AMD x2 SMP kernel). I realize that
> the problem happens infrequently, so you won't
> be able to tell quickly if it fixed the freeze.

I already applied this, which should keep it from freezing and
will print a warning, so I will apply your patch and then check
the log every time pppd exits.



Check for infinite loops in tty_buffer_free_all().  Hangs have only
been seen in the second loop, but check both anyway.

Signed-off-by: Chuck Ebbert <76306.1226@compuserve.com>

--- 2.6.16.20-d4.orig/drivers/char/tty_io.c
+++ 2.6.16.20-d4/drivers/char/tty_io.c
@@ -240,11 +240,23 @@ static int check_tty_count(struct tty_st
 static void tty_buffer_free_all(struct tty_struct *tty)
 {
 	struct tty_buffer *thead;
+	int free_loops;
+
+	free_loops = 0;
 	while((thead = tty->buf.head) != NULL) {
+		if (++free_loops > 9999) {
+			WARN_ON(1);
+			break;
+		}
 		tty->buf.head = thead->next;
 		kfree(thead);
 	}
+	free_loops = 0;
 	while((thead = tty->buf.free) != NULL) {
+		if (++free_loops > 9999) {
+			WARN_ON(1);
+			break;
+		}
 		tty->buf.free = thead->next;
 		kfree(thead);
 	}
-- 
Chuck

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

On Mon, 2006-06-12 at 12:36 -0400, Chuck Ebbert wrote:
> I already applied this, which should keep it from freezing and
> will print a warning, so I will apply your patch and then check
> the log every time pppd exits.

Your debug output seems like a good idea for catching
the mechanism of reentrance on flush_to_ldisc (if it
is happening at all).

My reading of the workqueue code is that the work
function can run in parallel on a multiple CPU
system. The default workqueue has multiple, per
CPU queues, and the pending bit for the
work item is cleared before execution. This would
allow the work item to be requeued for another CPU
while the function is executing.
(If I'm wrong, I would be happy to be told why)

Anyways, if I can impose on you to use this version
with debug output, it would help clarify this.

If the DONT_FLIP debug output happens too often and
fills you syslog, comment out that part.

--- a/include/linux/tty.h	2006-06-09 09:33:16.000000000 -0500
+++ b/include/linux/tty.h	2006-06-12 09:22:10.000000000 -0500
@@ -267,6 +267,7 @@ struct tty_struct {
 #define TTY_PTY_LOCK 		16	/* pty private */
 #define TTY_NO_WRITE_SPLIT 	17	/* Preserve write boundaries to driver */
 #define TTY_HUPPED 		18	/* Post driver->hangup() */
+#define TTY_FLUSHING 		19	/* Flushing tty buffers to line discipline */
 
 #define TTY_WRITE_FLUSH(tty) tty_write_flush((tty))
 
--- a/drivers/char/tty_io.c	2006-06-12 12:54:37.000000000 -0500
+++ b/drivers/char/tty_io.c	2006-06-12 12:54:54.000000000 -0500
@@ -2786,9 +2786,12 @@ static void flush_to_ldisc(void *private
 		return;
 
 	if (test_bit(TTY_DONT_FLIP, &tty->flags)) {
-		/*
-		 * Do it after the next timer tick:
-		 */
+		printk(KERN_ERR"flush_to_ldisc - TTY_DONT_FLIP set\n");
+		schedule_delayed_work(&tty->buf.work, 1);
+		goto out;
+	}
+	if (test_and_set_bit(TTY_FLUSHING, &tty->flags)) {
+		printk(KERN_ERR"flush_to_ldisc - TTY_FLUSHING set, low_latency=%d\n", tty->low_latency);
 		schedule_delayed_work(&tty->buf.work, 1);
 		goto out;
 	}
@@ -2810,6 +2813,7 @@ static void flush_to_ldisc(void *private
 		tty_buffer_free(tty, tbuf);
 	}
 	spin_unlock_irqrestore(&tty->buf.lock, flags);
+	clear_bit(TTY_FLUSHING, &tty->flags);
 out:
 	tty_ldisc_deref(disc);
 }

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

A little more clarification on the TTY_DONT_FLIP
debug output... I don't expect it to trigger at all
as the PPP line discipline does not use it (only n_tty).

The only chance it could trigger is after switching
back to n_tty on termination of the PPP link.

Thanks,
Paul

2.6.16.18 kernel freezes while pppd is exiting

[Chuck Ebbert]

Very infrequently I get kernel freezes while pppd is exiting.
Today I finally got traces from the serial console.

[1410445.728958] Pid: 887, comm:             sendmail
[1410445.743307] EIP: 0060:[<c03b29f8>] CPU: 1
[1410445.755837] EIP is at lock_kernel+0x18/0x30
[1410445.768882]  EFLAGS: 00000286    Not tainted  (2.6.16.18-d4 #6)
[1410445.787126] EAX: d791fa70 EBX: d78dbf2c ECX: 00000000 EDX: d78da000
[1410445.806408] ESI: fffffffe EDI: 00000000 EBP: c139bf14 DS: 007b ES: 007b
[1410445.826787] CR0: 8005003b CR2: 0064ef90 CR3: 174e5000 CR4: 000002d0
[1410445.846068]  [<c0192cfb>] proc_lookup+0x1b/0xd0
[1410445.860260]  [<c018fe7b>] proc_root_lookup+0x2b/0x70
[1410445.875748]  [<c016fbb5>] real_lookup+0xc5/0xf0
[1410445.889939]  [<c016feed>] do_lookup+0x9d/0xb0
[1410445.903607]  [<c01705bc>] __link_path_walk+0x6bc/0xc80
[1410445.919619]  [<c0170bc9>] link_path_walk+0x49/0xd0
[1410445.934588]  [<c03b101d>] schedule+0x38d/0x760
[1410445.948518]  [<c0170fa8>] do_path_lookup+0x138/0x2b0
[1410445.964007]  [<c01629ca>] get_empty_filp+0x6a/0xf0
[1410445.978978]  [<c017118a>] __path_lookup_intent_open+0x4a/0x90
[1410445.996805]  [<c0171205>] path_lookup_open+0x35/0x40
[1410446.012297]  [<c0171a67>] open_namei+0x87/0x680
[1410446.026486]  [<c0160d20>] do_filp_open+0x40/0x60
[1410446.040937]  [<c01610b1>] do_sys_open+0x51/0x90
[1410446.055125]  [<c0161117>] sys_open+0x27/0x30
[1410446.068536]  [<c0102f09>] syscall_call+0x7/0xb

[1410462.415500] Pid: 22020, comm:                 pppd
[1410462.430365] EIP: 0060:[<c015eaae>] CPU: 0
[1410462.442913] EIP is at kfree+0x4e/0x70
[1410462.454413]  EFLAGS: 00000286    Not tainted  (2.6.16.18-d4 #6)
[1410462.472652] EAX: 0000001d EBX: c137a160 ECX: 00000000 EDX: c137f600
[1410462.491936] ESI: c4823800 EDI: 00000286 EBP: 00000001 DS: 007b ES: 007b
[1410462.512314] CR0: 8005003b CR2: 0069f6a0 CR3: 032c5000 CR4: 000002d0
[1410462.531597]  [<c0244d90>] tty_buffer_free_all+0x60/0x80
[1410462.547890]  [<c0246e9d>] release_mem+0x18d/0x1a0
[1410462.562598]  [<c024b130>] n_tty_close+0x0/0x40
[1410462.576529]  [<c02474b1>] release_dev+0x601/0x760
[1410462.591238]  [<c01385f5>] enqueue_hrtimer+0x75/0xc0
[1410462.606469]  [<c013839b>] lock_hrtimer_base+0x2b/0x60
[1410462.622218]  [<c01387b2>] hrtimer_try_to_cancel+0x42/0x70
[1410462.639009]  [<c01387f8>] hrtimer_cancel+0x18/0x20
[1410462.653976]  [<c03b208a>] schedule_hrtimer+0x4a/0xa0
[1410462.669467]  [<c0138abf>] hrtimer_nanosleep+0x6f/0x130
[1410462.685477]  [<c022c032>] copy_to_user+0x42/0x60
[1410462.699926]  [<c0174797>] do_ioctl+0x77/0xa0
[1410462.713337]  [<c0247af4>] tty_release+0x14/0x20
[1410462.727525]  [<c0162b2d>] __fput+0xbd/0xd0
[1410462.740417]  [<c01611cd>] filp_close+0x4d/0x80
[1410462.754349]  [<c016126d>] sys_close+0x6d/0x90
[1410462.768018]  [<c0102f09>] syscall_call+0x7/0xb

pppd seems to be looping here while holding the BKL:

static void tty_buffer_free_all(struct tty_struct *tty)
{
        struct tty_buffer *thead;
        while((thead = tty->buf.head) != NULL) {
                tty->buf.head = thead->next;
                kfree(thead);
        }
        while((thead = tty->buf.free) != NULL) {
                tty->buf.free = thead->next;
====>           kfree(thead);
        }
        tty->buf.tail = NULL;
}

I did alt-sysrq-p over and over and all I got was basically these two
traces -- CPU 1 in lock_kernel() and CPU 0 in kfree().

-- 
Chuck

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

On Thu, 2006-06-08 at 14:09 -0400, Chuck Ebbert wrote:
> Very infrequently I get kernel freezes while pppd is exiting.

> [1410445.728958] Pid: 887, comm:             sendmail
> [1410445.743307] EIP: 0060:[<c03b29f8>] CPU: 1
> [1410445.755837] EIP is at lock_kernel+0x18/0x30
...
> [1410462.415500] Pid: 22020, comm:                 pppd
> [1410462.430365] EIP: 0060:[<c015eaae>] CPU: 0
> [1410462.442913] EIP is at kfree+0x4e/0x70
...
> pppd seems to be looping here while holding the BKL:
> 
> static void tty_buffer_free_all(struct tty_struct *tty)
> {
>         struct tty_buffer *thead;
>         while((thead = tty->buf.head) != NULL) {
>                 tty->buf.head = thead->next;
>                 kfree(thead);
>         }
>         while((thead = tty->buf.free) != NULL) {
>                 tty->buf.free = thead->next;
> ====>           kfree(thead);
>         }
>         tty->buf.tail = NULL;
> }
> 
> I did alt-sysrq-p over and over and all I got was basically these two
> traces -- CPU 1 in lock_kernel() and CPU 0 in kfree().

It looks like the free list is corrupt.

in drivers/char/tty_io.c, flush_to_ldisc processes
buffers and frees them:

static void flush_to_ldisc(void *private_)
{
...
	spin_lock_irqsave(&tty->buf.lock, flags);
	while((tbuf = tty->buf.head) != NULL) {
		while ((count = tbuf->commit - tbuf->read) != 0) {
			char_buf = tbuf->char_buf_ptr + tbuf->read;
			flag_buf = tbuf->flag_buf_ptr + tbuf->read;
			tbuf->read += count;
			spin_unlock_irqrestore(&tty->buf.lock, flags);
			disc->receive_buf(tty, char_buf, flag_buf, count);
			spin_lock_irqsave(&tty->buf.lock, flags);
		}
		if (tbuf->active)
			break;
		tty->buf.head = tbuf->next;
		if (tty->buf.head == NULL)
			tty->buf.tail = NULL;
		tty_buffer_free(tty, tbuf);
	}
	spin_unlock_irqrestore(&tty->buf.lock, flags);
...
}

If two copies of flush_to_ldisc run simultaneously on different
CPUs, the free list can be corrupted. tbuf is read from
the head, the list lock is dropped to pass tbuf to disc->receive_buf.
While in receive_buf, the other flush_to_ldisc can get a pointer
to the same buf. Both end up freeing the same buf, corrupting the list.

The following should correct that by forcing a re-read of the
list head after passing tbuf to receive_buf. I'm posting now for
quick feedback (hi Alan). I'm going to implement and test this before
posting a patch (possibly tomorrow).

	spin_lock_irqsave(&tty->buf.lock, flags);
	while((tbuf = tty->buf.head) != NULL) {
		if ((count = tbuf->commit - tbuf->read) == 0) {
			if (tbuf->active)
				break;
			tty->buf.head = tbuf->next;
			if (tty->buf.head == NULL)
				tty->buf.tail = NULL;
			tty_buffer_free(tty, tbuf);
			continue;
		}
		while ((count = tbuf->commit - tbuf->read) != 0) {
			char_buf = tbuf->char_buf_ptr + tbuf->read;
			flag_buf = tbuf->flag_buf_ptr + tbuf->read;
			tbuf->read += count;
			spin_unlock_irqrestore(&tty->buf.lock, flags);
			disc->receive_buf(tty, char_buf, flag_buf, count);
			spin_lock_irqsave(&tty->buf.lock, flags);
		}
	}
	spin_unlock_irqrestore(&tty->buf.lock, flags);

Re: 2.6.16.18 kernel freezes while pppd is exiting

[Paul Fulghum]

Chuck Ebbert wrote:
> Very infrequently I get kernel freezes while pppd is exiting.
> Today I finally got traces from the serial console.

Chuck:

What kind of device are you using with pppd?
(so I can identify which driver is feeding
the tty layer receive data)

Are you setting the low_latency flag on that device?
(setserial)

Thanks,
Paul