tty vs workqueue oddities
Hi Alan !
Current upstream (but that's been around for at least 2 or 3 days) seems to have a strange behaviour on one of my powerbooks. Something like "dmesg" or "cat" of a large file in an X terminal "hangs" the machine litterally for minutes. It generally recovers, so not always.
Network is unresponsive as well.
My attempts at stopping it into xmon always landed in process_one_work() or flush_to_ldisc() from what I can tell, and a simple ftrace run shows something that looks like an -enormous- lot of:
kworker/0:1-258 [000] 412.105871: flush_to_ldisc <-process_one_work
kworker/0:1-258 [000] 412.105871: tty_ldisc_ref <-flush_to_ldisc
kworker/0:1-258 [000] 412.105872: n_tty_receive_buf <-flush_to_ldisc
kworker/0:1-258 [000] 412.105872: kill_fasync <-n_tty_receive_buf
kworker/0:1-258 [000] 412.105873: __wake_up <-n_tty_receive_buf
kworker/0:1-258 [000] 412.105873: __wake_up_common <-__wake_up
kworker/0:1-258 [000] 412.105874: default_wake_function <-__wake_up_common
kworker/0:1-258 [000] 412.105874: try_to_wake_up <-default_wake_function
kworker/0:1-258 [000] 412.105874: tty_throttle <-n_tty_receive_buf
kworker/0:1-258 [000] 412.105875: mutex_lock <-tty_throttle
kworker/0:1-258 [000] 412.105875: mutex_unlock <-tty_throttle
kworker/0:1-258 [000] 412.105876: schedule_work <-flush_to_ldisc
kworker/0:1-258 [000] 412.105876: queue_work <-schedule_work
kworker/0:1-258 [000] 412.105877: queue_work_on <-queue_work
kworker/0:1-258 [000] 412.105877: __queue_work <-queue_work_on
kworker/0:1-258 [000] 412.105878: insert_work <-__queue_work
kworker/0:1-258 [000] 412.105878: tty_ldisc_deref <-flush_to_ldisc
kworker/0:1-258 [000] 412.105879: put_ldisc <-tty_ldisc_deref
kworker/0:1-258 [000] 412.105879: __wake_up <-put_ldisc
kworker/0:1-258 [000] 412.105880: __wake_up_common <-__wake_up
kworker/0:1-258 [000] 412.105880: cwq_dec_nr_in_flight <-process_one_work
kworker/0:1-258 [000] 412.105880: process_one_work <-worker_threadand repeat that sequence more/less identical ad nauseum
Sometimes it breaks out and makes progress, usually after a few mn.
2.6.39 is fine. I'm going to attempt a bisection but it's a bit slow on those machines and I'm running out of time today, so I wanted to shoot that to you in case it rings a bell.
Cheers,
Ben.
tty breakage in X (Was: tty vs workqueue oddities)
Quoted 1 line · Benjamin Herrenschmidt
Hi Alan !
Hrm... looks like Alan is innocent ... interesting tho, the culprit patch looks like something he (or somebody known to understand the tty code :-) should have reviewed.
So I bisected the problem down to
Commit: b1c43f82c5aa265442f82dba31ce985ebb7aa71c
Author: Felipe Balbi <[email protected]> 2011-03-21 21:25:08
Committer: Greg Kroah-Hartman <[email protected]> 2011-04-23 10:31:53
tty: make receive_buf() return the amout of bytes received
it makes it simpler to keep track of the amount of bytes received and simplifies how flush_to_ldisc counts the remaining bytes. It also fixes a bug of lost bytes on n_tty when flushing too many bytes via the USB serial gadget driver.
It looks like the patch is causing some major malfunctions of the X server for me, possibly related to PTYs. For example, cat'ing a large file in a gnome terminal hangs the kernel for -minutes- in a loop of what looks like flush_to_ldisc/workqueue code, (some ftrace data in the quoted bits further down).
It's pretty gross and it doesn't look powerpc related in any ways (tho I haven't had a chance to test on an x86 box), on the other hand I'm surprised nobody else complained :-)
Should it just be reverted ? Is there a fix ?
Hand-reverting it on top of upstream (with some bluetooth manual fixups) fixes the problems for me, X is back to normal.
Cheers,
Ben.
Quoted 45 lines
Current upstream (but that's been around for at least 2 or 3 days) seems to have a strange behaviour on one of my powerbooks. Something like "dmesg" or "cat" of a large file in an X terminal "hangs" the machine litterally for minutes. It generally recovers, so not always.
Network is unresponsive as well.
My attempts at stopping it into xmon always landed in
process_one_work()orflush_to_ldisc()from what I can tell, and a simple ftrace run shows something that looks like an -enormous- lot of:kworker/0:1-258 [000] 412.105871: flush_to_ldisc <-process_one_work kworker/0:1-258 [000] 412.105871: tty_ldisc_ref <-flush_to_ldisc kworker/0:1-258 [000] 412.105872: n_tty_receive_buf <-flush_to_ldisc kworker/0:1-258 [000] 412.105872: kill_fasync <-n_tty_receive_buf kworker/0:1-258 [000] 412.105873: __wake_up <-n_tty_receive_buf kworker/0:1-258 [000] 412.105873: __wake_up_common <-__wake_up kworker/0:1-258 [000] 412.105874: default_wake_function <-__wake_up_common kworker/0:1-258 [000] 412.105874: try_to_wake_up <-default_wake_function kworker/0:1-258 [000] 412.105874: tty_throttle <-n_tty_receive_buf kworker/0:1-258 [000] 412.105875: mutex_lock <-tty_throttle kworker/0:1-258 [000] 412.105875: mutex_unlock <-tty_throttle kworker/0:1-258 [000] 412.105876: schedule_work <-flush_to_ldisc kworker/0:1-258 [000] 412.105876: queue_work <-schedule_work kworker/0:1-258 [000] 412.105877: queue_work_on <-queue_work kworker/0:1-258 [000] 412.105877: __queue_work <-queue_work_on kworker/0:1-258 [000] 412.105878: insert_work <-__queue_work kworker/0:1-258 [000] 412.105878: tty_ldisc_deref <-flush_to_ldisc kworker/0:1-258 [000] 412.105879: put_ldisc <-tty_ldisc_deref kworker/0:1-258 [000] 412.105879: __wake_up <-put_ldisc kworker/0:1-258 [000] 412.105880: __wake_up_common <-__wake_up kworker/0:1-258 [000] 412.105880: cwq_dec_nr_in_flight <-process_one_work kworker/0:1-258 [000] 412.105880: process_one_work <-worker_threadand repeat that sequence more/less identical ad nauseum
Sometimes it breaks out and makes progress, usually after a few mn.
2.6.39 is fine. I'm going to attempt a bisection but it's a bit slow on those machines and I'm running out of time today, so I wanted to shoot that to you in case it rings a bell.
Cheers,
Ben.
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 5 lines · Benjamin Herrenschmidt
It looks like the patch is causing some major malfunctions of the X server for me, possibly related to PTYs. For example, cat'ing a large file in a gnome terminal hangs the kernel for -minutes- in a loop of what looks like flush_to_ldisc/workqueue code, (some ftrace data in the quoted bits further down).
Btw., do you already have d72bce0 ("rcu: Cure load woes")? Although that is about an independent bug, it appears to amplify this issue a lot.
Andreas.
Signature · 3 lines
Andreas Schwab, [email protected] GPG Key fingerprint = 58CA 54C7 6D53 942B 1756 01D3 44D5 214B 8276 4ED5 "And now for something completely different."
Re: tty breakage in X (Was: tty vs workqueue oddities)
In reply to Benjamin HerrenschmidtQuoted 6 lines · On Thu, 02 Jun 2011 18:37:01 +1000 Benjamin Herrenschmidt…
Quoted 1 line · Benjamin Herrenschmidt
Hi Alan !
Hrm... looks like Alan is innocent ... interesting tho, the culprit patch looks like something he (or somebody known to understand the tty code :-) should have reviewed.
I did review it, and ran it and it worked beautifully on my system 8)
I do wonder if it has an interaction with Linus earlier changes to queue flushing as I've never tested both together.
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 6 lines · Alan Cox
Quoted 3 lines · On Thu, 02 Jun 2011 18:37:01 +1000 Benjamin Herrenschmidt…
Quoted 1 line · Benjamin Herrenschmidt
Hi Alan !
Quoted 8 lines
Quoted 3 lines
Hrm... looks like Alan is innocent ... interesting tho, the culprit patch looks like something he (or somebody known to understand the tty code :-) should have reviewed.
I did review it, and ran it and it worked beautifully on my system 8)
I do wonder if it has an interaction with Linus earlier changes to queue flushing as I've never tested both together.
I just noticed it doesn't happen (or if it does, it recovers fast enough to not be noticable) on an SMP machine (dual G5). However, if I boot the same machine with maxcpus=1, the problem is back. A simple "dmesg" in gnome terminal shows it.
However, on that much faster machine, it also recovers a lot faster. On the powerbook, it hangs a few minutes, on the G5 it hangs a few seconds.
I don't have the bandwidth to dive into the workqueue/tty before this week-end, I'll give it a shot next week if nobody beats me to it.
Cheers,
Ben.
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 10 lines · Benjamin Herrenschmidt
I just noticed it doesn't happen (or if it does, it recovers fast enough to not be noticable) on an SMP machine (dual G5). However, if I boot the same machine with maxcpus=1, the problem is back. A simple "dmesg" in gnome terminal shows it.
However, on that much faster machine, it also recovers a lot faster. On the powerbook, it hangs a few minutes, on the G5 it hangs a few seconds.
I don't have the bandwidth to dive into the workqueue/tty before this week-end, I'll give it a shot next week if nobody beats me to it.
Some more data: It -looks- like what happens is that the flush_to_ldisc work queue entry constantly re-queues itself (because the PTY is full ?) and the workqueue thread will basically loop forver calling it without ever scheduling, thus starving the consumer process that could have emptied the PTY.
At least that's a semi half-assed theory. If I add a schedule() to process_one_work() after dropping the lock, the problem disappears.
So there's a combination of things here that are quite interesting:
- A lot of work queued for the kworker will essentially go on without
scheduling for as long as it takes to empty all work items. That doesn't sound very nice latency-wise. At least on a non-PREEMPT kernel.
- flush_to_ldisc seems to be nasty and requeues itself over and over
again from what I can tell, when it can't push the data out, in this case, I suspect because the PTY is full but I don't know for sure yet.
Cheers,
Ben.
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 11 lines · Benjamin Herrenschmidt
Some more data: It -looks- like what happens is that the
flush_to_ldiscwork queue entry constantly re-queues itself (because the PTY is full ?) and the workqueue thread will basically loop forver calling it without ever scheduling, thus starving the consumer process that could have emptied the PTY.At least that's a semi half-assed theory. If I add a
schedule()toprocess_one_work()after dropping the lock, the problem disappears.So there's a combination of things here that are quite interesting:
Quoted 7 lines
- A lot of work queued for the kworker will essentially go on without
scheduling for as long as it takes to empty all work items. That doesn't sound very nice latency-wise. At least on a non-PREEMPT kernel.-
flush_to_ldiscseems to be nasty and requeues itself over and over
again from what I can tell, when it can't push the data out, in this case, I suspect because the PTY is full but I don't know for sure yet.
Interesting results from x86. I could not initially reproduce there at all on my little Atom board (the one from kernel summit last year).
Eventually I looked at the kernel config, switched off PREEMPT_VOLUNTARY and I can now reproduce on x86 too. Again, if you have both threads/core running, the problem isn't as visible (you do see "hickups" when cat'ing a large file, the atom is slow enough I suppose).
But offline a cpu (leave only one up) and cat a large file (dmesg is enough for me to trigger it) and you see the hangs.
So I think my theory stands that flush_to_ldisc constantly reschedule itself causing the worker thread to eat all CPU and starve the consumer of the PTY. I won't have time to dig much deeper today nor probably this week-end so I'm sending this email for others who want to look.
Cheers,
Ben.
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 5 lines · Benjamin Herrenschmidt
So I think my theory stands that
flush_to_ldiscconstantly reschedule itself causing the worker thread to eat all CPU and starve the consumer of the PTY. I won't have time to dig much deeper today nor probably this week-end so I'm sending this email for others who want to look.
Gaah - that commit is total and utter crap.
I *removed* the whole "reschedule the work queue again" crap. It was totally wrong. See commit a5660b41af6a.
But then commit b1c43f82c5aa added the crap right back in.
So does it all work if you just remove the broken schedule_work() line from flush_to_ldisc?
Otherwise we'll need to just revert it. The commit is clearly totally broken.
Linus
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 1 line · Linus Torvalds
Otherwise we'll need to just revert it. The commit is clearly totally broken.
Even after the revert in http://git.kernel.org/linus/55db4c6 I can reproduce some pty oddities using the test program in
http://lkml.org/lkml/2005/2/14/212.
Instead of having the output being different from the input, the child process hangs reading while the parent is done writing.
The hangs should be easily seen with:
$ while :; do date; yes | head -n 5000 | ./a.out > /dev/null; done
Signature · 1 line
Guillaume
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 1 line · Guillaume Chazarain
$ while :; do date; yes | head -n 5000 | ./a.out > /dev/null; done
After reverting http://git.kernel.org/linus/a5660b4 "tty: fix endless work loop when the buffer fills up" I cannot reproduce the hangs on SMP anymore but it brings back the busy loop on UP.
Signature · 1 line
Guillaume
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 4 lines · Guillaume Chazarain
After reverting http://git.kernel.org/linus/a5660b4 "tty: fix endless work loop when the buffer fills up" I cannot reproduce the hangs on SMP anymore but it brings back the busy loop on UP.
Hmm. The n_tty layer has some rather distressing locking, and doesn't lock "tty->receive_room" changes at all, for example (and uses multiple locks for some other things).
It may well be that there is some SMP race there. The n_tty line discipline has its own locking for its counts, and the tty buffer code has its own locking, and "receive_room" kind o fends up being in the middle between them.
The sad part is that the patch that made receive_buf() return the amout of bytes received was actually trying to do the right thing, it just did it entirely in the wrong way (re-introducing the crazy re-arming of the workqueue from within itself, and using all the wrong sign issues).
I'd love to get rid of receive_room entirely - and just letting the tty line discipline handler say how much it actually received. in other words, having receive_buf() just tell us how much it used, and not looking at receive_room in the caller is absolutely the right thing.
It just needs to be done properly.
Linus
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 6 lines · Linus Torvalds
Hmm. The
n_ttylayer has some rather distressing locking, and doesn't lock "tty->receive_room" changes at all, for example (and uses multiple locks for some other things).It may well be that there is some SMP race there.
Actually, I think it's simpler than that.
Does this patch fix things for you? It just removes the "stop if you've seen the tail, but somebody added a new buffer in the meantime" logic.
We might want to keep the "re-arm the work" for just that case, but let's see what happens if we just remove the logic entirely.
Linus
drivers/tty/tty_buffer.c | 14 ++------------ 1 files changed, 2 insertions(+), 12 deletions(-)
drivers/tty/tty_buffer.c +2 -12
@@ -413,8 +413,7 @@ static void flush_to_ldisc(struct work_struct *work)spin_lock_irqsave (&tty->buf.lock, flags);if (!test_and_set_bit (TTY_FLUSHING , &tty->flags)) { -struct tty_buffer *head, *tail = tty->buf.tail; -int seen_tail =0 ; +struct tty_buffer *head;while ((head = tty->buf.head) !=NULL ) {int count;char *char_buf;
@@ -424,15 +423,6 @@ static void flush_to_ldisc(struct work_struct *work)if (!count) {if (head->next ==NULL )break ; -/* -There's a possibility tty might get new buffer -added during the unlock window below. We could -end up spinning in here forever hogging the CPU -completely. To avoid this let's have a rest each -time we processed the tail buffer. -*/ -if (tail == head) - seen_tail =1 ; tty->buf.head = head->next;tty_buffer_free (tty, head);continue ;
@@ -442,7 +432,7 @@ static void flush_to_ldisc(struct work_struct *work)line discipline as we want to empty the queue */ if (test_bit (TTY_FLUSHPENDING , &tty->flags))break ; -if (!tty->receive_room || seen_tail) +if (!tty->receive_room)break ;if (count > tty->receive_room) count = tty->receive_room;
Re: tty breakage in X (Was: tty vs workqueue oddities)
Quoted 1 line · Linus Torvalds
Does this patch fix things for you?
Works perfectly on SMP and UP, thanks!
Signature · 1 line
Guillaume
Re: tty breakage in X (Was: tty vs workqueue oddities)
In reply to Linus TorvaldsHi,
Quoted 15 lines · Linus Torvalds
Quoted 4 lines · Guillaume Chazarain
After reverting http://git.kernel.org/linus/a5660b4 "tty: fix endless work loop when the buffer fills up" I cannot reproduce the hangs on SMP anymore but it brings back the busy loop on UP.
Hmm. The
n_ttylayer has some rather distressing locking, and doesn't lock "tty->receive_room" changes at all, for example (and uses multiple locks for some other things).It may well be that there is some SMP race there. The
n_ttyline discipline has its own locking for its counts, and the tty buffer code has its own locking, and "receive_room" kind o fends up being in the middle between them.
Quoted 5 lines
The sad part is that the patch that made
receive_buf()return the amout of bytes received was actually trying to do the right thing, it just did it entirely in the wrong way (re-introducing the crazy re-arming of the workqueue from within itself, and using all the wrong sign issues).
yeah sorry about that. I originally wrote that patch over one year ago and had to send it three times until it was finally noticed. Then I had to do a quick rebase and things went pretty bad.
Should've checked better and forget about loosing another merge window.
Quoted 5 lines
I'd love to get rid of
receive_roomentirely - and just letting the tty line discipline handler say how much it actually received. in other words, havingreceive_buf()just tell us how much it used, and not looking atreceive_roomin the caller is absolutely the right thing.
that was the idea, unfortunately I missed the last part. Sorry about that.
Signature · 1 line
balbi
Re: tty breakage in X (Was: tty vs workqueue oddities)
In reply to Linus TorvaldsQuoted 5 lines
I'd love to get rid of
receive_roomentirely - and just letting the tty line discipline handler say how much it actually received. in other words, havingreceive_buf()just tell us how much it used, and not looking atreceive_roomin the caller is absolutely the right thing.
Shouldn't be too hard - the only use of receive_room beyond setting it to 'fire at will' is n_tty.
Quoted 23 lines · On Thu, 02 Jun 2011 17:17:25 +1000 Benjamin Herrenschmidt…
Hi Alan !
Current upstream (but that's been around for at least 2 or 3 days) seems to have a strange behaviour on one of my powerbooks. Something like "dmesg" or "cat" of a large file in an X terminal "hangs" the machine litterally for minutes. It generally recovers, so not always.
Network is unresponsive as well.
My attempts at stopping it into xmon always landed in
process_one_work()orflush_to_ldisc()from what I can tell, and a simple ftrace run shows something that looks like an -enormous- lot of:kworker/0:1-258 [000] 412.105871: flush_to_ldisc <-process_one_work kworker/0:1-258 [000] 412.105871: tty_ldisc_ref <-flush_to_ldisc kworker/0:1-258 [000] 412.105872: n_tty_receive_buf <-flush_to_ldisc kworker/0:1-258 [000] 412.105872: kill_fasync <-n_tty_receive_buf kworker/0:1-258 [000] 412.105873: __wake_up <-n_tty_receive_buf kworker/0:1-258 [000] 412.105873: __wake_up_common <-__wake_up kworker/0:1-258 [000] 412.105874: default_wake_function <-__wake_up_common kworker/0:1-258 [000] 412.105874: try_to_wake_up <-default_wake_function kworker/0:1-258 [000] 412.105874: tty_throttle <-n_tty_receive_buf kworker/0:1-258 [000] 412.105875: mutex_lock <-tty_throttle
Quoted 8 lines
kworker/0:1-258 [000] 412.105875: mutex_unlock <-tty_throttle
kworker/0:1-258 [000] 412.105876: schedule_work <-flush_to_ldisc
kworker/0:1-258 [000] 412.105876: queue_work <-schedule_work
kworker/0:1-258 [000] 412.105877: queue_work_on <-queue_work
kworker/0:1-258 [000] 412.105877: __queue_work <-queue_work_on
kworker/0:1-258 [000] 412.105878: insert_work <-__queue_work
kworker/0:1-258 [000] 412.105878: tty_ldisc_deref <-flush_to_ldisc
kworker/0:1-258 [000] 412.105879: put_ldisc <-tty_ldisc_"Yedvab, Nadav" <[email protected]>deref
Quoted 5 lines
kworker/0:1-258 [000] 412.105879: __wake_up <-put_ldisc
kworker/0:1-258 [000] 412.105880: __wake_up_common <-__wake_up
kworker/0:1-258 [000] 412.105880: cwq_dec_nr_in_flight <-process_one_work
kworker/0:1-258 [000] 412.105880: process_one_work <-worker_threadQuoted 7 lines
and repeat that sequence more/less identical ad nauseum
Sometimes it breaks out and makes progress, usually after a few mn.
2.6.39 is fine. I'm going to attempt a bisection but it's a bit slow on those machines and I'm running out of time today, so I wanted to shoot that to you in case it rings a bell.
Possibly
b1c43f82c5aa265442f82dba31ce985ebb7aa71c
other suspect would be
a5660b41af6a28f8004e70eb261e1202ad55c5e3
but 2.6.39 working suggests its not