* known vboxgetty/isdn issue in 2.6.35.3?
@ 2010-09-07 13:42 Udo van den Heuvel
2010-09-07 19:45 ` Arnd Bergmann
0 siblings, 1 reply; 8+ messages in thread
From: Udo van den Heuvel @ 2010-09-07 13:42 UTC (permalink / raw)
To: linux-kernel
Found this in messages:
Sep 2 15:00:22 epia klogd: INFO: task vboxgetty:25662 blocked for more
than 120 seconds.
Sep 2 15:00:22 epia klogd: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 2 15:00:22 epia klogd: vboxgetty D 00000000 0 25662 1
0x00000000
Sep 2 15:00:22 epia klogd: cba29c74 00000046 c1157e3a 00000000
f4c28000 f4c28000 cbb13c4c f4c28000
Sep 2 15:00:22 epia klogd: cbb13858 f4c28000 00000202 cba29ca4
c1294879 cbb13878 00000202 cbb13878
Sep 2 15:00:22 epia klogd: cbb13878 f4c28000 cba29c84 ffffffff
cbb13800 cbb13858 cbb13c4c cba29cb4
Sep 2 15:00:22 epia klogd: Call Trace:
Sep 2 15:00:22 epia klogd: [<c1157e3a>] ? tty_unthrottle+0x13/0x3a
Sep 2 15:00:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
Sep 2 15:00:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
Sep 2 15:00:22 epia klogd: [<c1156a6e>] reset_buffer_flags+0xd4/0xd9
Sep 2 15:00:22 epia klogd: [<c1156a80>] n_tty_flush_buffer+0xd/0x63
Sep 2 15:00:22 epia klogd: [<c11593c7>] tty_ldisc_flush+0x1f/0x34
Sep 2 15:00:22 epia klogd: [<c11d6e28>] isdn_tty_modem_result+0x342/0x37c
Sep 2 15:00:22 epia klogd: [<c1153ff3>] ? tty_wakeup+0x46/0x4e
Sep 2 15:00:22 epia klogd: [<c11d910a>] isdn_tty_modem_hup+0x76/0x176
Sep 2 15:00:22 epia klogd: [<c115824b>] ? set_termios+0x1a8/0x397
Sep 2 15:00:22 epia klogd: [<c129476a>] ? mutex_lock_nested+0x2f/0x23f
Sep 2 15:00:22 epia klogd: [<c11d9b17>] isdn_tty_change_speed+0xa2/0xd4
Sep 2 15:00:22 epia klogd: [<c11d9b86>] isdn_tty_set_termios+0x3d/0x5a
Sep 2 15:00:22 epia klogd: [<c11583bb>] set_termios+0x318/0x397
Sep 2 15:00:22 epia klogd: [<c1158661>] tty_mode_ioctl+0x178/0x2db
Sep 2 15:00:22 epia klogd: [<c1158a06>] ? tty_ldisc_try+0x11/0x38
Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:00:22 epia klogd: [<c1158908>] n_tty_ioctl_helper+0x144/0x154
Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:00:22 epia klogd: [<c1155ff9>] n_tty_ioctl+0x97/0xa0
Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:00:22 epia klogd: [<c11547ed>] tty_ioctl+0x699/0x6d3
Sep 2 15:00:22 epia klogd: [<c1083788>] vfs_ioctl+0x27/0x91
Sep 2 15:00:22 epia klogd: [<c1154154>] ? tty_ioctl+0x0/0x6d3
Sep 2 15:00:22 epia klogd: [<c1083d06>] do_vfs_ioctl+0x467/0x4a5
Sep 2 15:00:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
Sep 2 15:00:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
Sep 2 15:00:22 epia klogd: [<c1209c83>] ? net_tx_action+0x47/0xcc
Sep 2 15:00:22 epia klogd: [<c102262a>] ? __do_softirq+0xc3/0xd2
Sep 2 15:00:22 epia klogd: [<c1083d85>] sys_ioctl+0x41/0x61
Sep 2 15:00:22 epia klogd: [<c1003cb9>] ? do_IRQ+0x74/0x87
Sep 2 15:00:22 epia klogd: [<c1002813>] sysenter_do_call+0x12/0x2d
Sep 2 15:00:22 epia klogd: INFO: lockdep is turned off.
Sep 2 15:02:22 epia klogd: INFO: task vboxgetty:25662 blocked for more
than 120 seconds.
Sep 2 15:02:22 epia klogd: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 2 15:02:22 epia klogd: vboxgetty D 00000000 0 25662 1
0x00000000
Sep 2 15:02:22 epia klogd: cba29c74 00000046 c1157e3a 00000000
f4c28000 f4c28000 cbb13c4c f4c28000
Sep 2 15:02:22 epia klogd: cbb13858 f4c28000 00000202 cba29ca4
c1294879 cbb13878 00000202 cbb13878
Sep 2 15:02:22 epia klogd: cbb13878 f4c28000 cba29c84 ffffffff
cbb13800 cbb13858 cbb13c4c cba29cb4
Sep 2 15:02:22 epia klogd: Call Trace:
Sep 2 15:02:22 epia klogd: [<c1157e3a>] ? tty_unthrottle+0x13/0x3a
Sep 2 15:02:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
Sep 2 15:02:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
Sep 2 15:02:22 epia klogd: [<c1156a6e>] reset_buffer_flags+0xd4/0xd9
Sep 2 15:02:22 epia klogd: [<c1156a80>] n_tty_flush_buffer+0xd/0x63
Sep 2 15:02:22 epia klogd: [<c11593c7>] tty_ldisc_flush+0x1f/0x34
Sep 2 15:02:22 epia klogd: [<c11d6e28>] isdn_tty_modem_result+0x342/0x37c
Sep 2 15:02:22 epia klogd: [<c1153ff3>] ? tty_wakeup+0x46/0x4e
Sep 2 15:02:22 epia klogd: [<c11d910a>] isdn_tty_modem_hup+0x76/0x176
Sep 2 15:02:22 epia klogd: [<c115824b>] ? set_termios+0x1a8/0x397
Sep 2 15:02:22 epia klogd: [<c129476a>] ? mutex_lock_nested+0x2f/0x23f
Sep 2 15:02:22 epia klogd: [<c11d9b17>] isdn_tty_change_speed+0xa2/0xd4
Sep 2 15:02:22 epia klogd: [<c11d9b86>] isdn_tty_set_termios+0x3d/0x5a
Sep 2 15:02:22 epia klogd: [<c11583bb>] set_termios+0x318/0x397
Sep 2 15:02:22 epia klogd: [<c1158661>] tty_mode_ioctl+0x178/0x2db
Sep 2 15:02:22 epia klogd: [<c1158a06>] ? tty_ldisc_try+0x11/0x38
Sep 2 15:02:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:02:22 epia klogd: [<c1158908>] n_tty_ioctl_helper+0x144/0x154
Sep 2 15:02:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:02:22 epia klogd: [<c1155ff9>] n_tty_ioctl+0x97/0xa0
Sep 2 15:02:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:02:22 epia klogd: [<c11547ed>] tty_ioctl+0x699/0x6d3
Sep 2 15:02:22 epia klogd: [<c1083788>] vfs_ioctl+0x27/0x91
Sep 2 15:02:22 epia klogd: [<c1154154>] ? tty_ioctl+0x0/0x6d3
Sep 2 15:02:22 epia klogd: [<c1083d06>] do_vfs_ioctl+0x467/0x4a5
Sep 2 15:02:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
Sep 2 15:02:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
Sep 2 15:02:22 epia klogd: [<c1209c83>] ? net_tx_action+0x47/0xcc
Sep 2 15:02:22 epia klogd: [<c102262a>] ? __do_softirq+0xc3/0xd2
Sep 2 15:02:22 epia klogd: [<c1083d85>] sys_ioctl+0x41/0x61
Sep 2 15:02:22 epia klogd: [<c1003cb9>] ? do_IRQ+0x74/0x87
Sep 2 15:02:22 epia klogd: [<c1002813>] sysenter_do_call+0x12/0x2d
Sep 2 15:02:22 epia klogd: INFO: lockdep is turned off.
Sep 2 15:04:22 epia klogd: INFO: task vboxgetty:25662 blocked for more
than 120 seconds.
Sep 2 15:04:22 epia klogd: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 2 15:04:22 epia klogd: vboxgetty D 00000000 0 25662 1
0x00000000
Sep 2 15:04:22 epia klogd: cba29c74 00000046 c1157e3a 00000000
f4c28000 f4c28000 cbb13c4c f4c28000
Sep 2 15:04:22 epia klogd: cbb13858 f4c28000 00000202 cba29ca4
c1294879 cbb13878 00000202 cbb13878
Sep 2 15:04:22 epia klogd: cbb13878 f4c28000 cba29c84 ffffffff
cbb13800 cbb13858 cbb13c4c cba29cb4
Sep 2 15:04:22 epia klogd: Call Trace:
Sep 2 15:04:22 epia klogd: [<c1157e3a>] ? tty_unthrottle+0x13/0x3a
Sep 2 15:04:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
Sep 2 15:04:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
Sep 2 15:04:22 epia klogd: [<c1156a6e>] reset_buffer_flags+0xd4/0xd9
Sep 2 15:04:22 epia klogd: [<c1156a80>] n_tty_flush_buffer+0xd/0x63
Sep 2 15:04:22 epia klogd: [<c11593c7>] tty_ldisc_flush+0x1f/0x34
Sep 2 15:04:22 epia klogd: [<c11d6e28>] isdn_tty_modem_result+0x342/0x37c
Sep 2 15:04:22 epia klogd: [<c1153ff3>] ? tty_wakeup+0x46/0x4e
Sep 2 15:04:22 epia klogd: [<c11d910a>] isdn_tty_modem_hup+0x76/0x176
Sep 2 15:04:22 epia klogd: [<c115824b>] ? set_termios+0x1a8/0x397
Sep 2 15:04:22 epia klogd: [<c129476a>] ? mutex_lock_nested+0x2f/0x23f
Sep 2 15:04:22 epia klogd: [<c11d9b17>] isdn_tty_change_speed+0xa2/0xd4
Sep 2 15:04:22 epia klogd: [<c11d9b86>] isdn_tty_set_termios+0x3d/0x5a
Sep 2 15:04:22 epia klogd: [<c11583bb>] set_termios+0x318/0x397
Sep 2 15:04:22 epia klogd: [<c1158661>] tty_mode_ioctl+0x178/0x2db
Sep 2 15:04:22 epia klogd: [<c1158a06>] ? tty_ldisc_try+0x11/0x38
Sep 2 15:04:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:04:22 epia klogd: [<c1158908>] n_tty_ioctl_helper+0x144/0x154
Sep 2 15:04:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:04:22 epia klogd: [<c1155ff9>] n_tty_ioctl+0x97/0xa0
Sep 2 15:04:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
Sep 2 15:04:22 epia klogd: [<c11547ed>] tty_ioctl+0x699/0x6d3
Sep 2 15:04:22 epia klogd: [<c1083788>] vfs_ioctl+0x27/0x91
Sep 2 15:04:22 epia klogd: [<c1154154>] ? tty_ioctl+0x0/0x6d3
Sep 2 15:04:22 epia klogd: [<c1083d06>] do_vfs_ioctl+0x467/0x4a5
Sep 2 15:04:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
Sep 2 15:04:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
Sep 2 15:04:22 epia klogd: [<c1209c83>] ? net_tx_action+0x47/0xcc
Sep 2 15:04:22 epia klogd: [<c102262a>] ? __do_softirq+0xc3/0xd2
Sep 2 15:04:22 epia klogd: [<c1083d85>] sys_ioctl+0x41/0x61
Sep 2 15:04:22 epia klogd: [<c1003cb9>] ? do_IRQ+0x74/0x87
Sep 2 15:04:22 epia klogd: [<c1002813>] sysenter_do_call+0x12/0x2d
Sep 2 15:04:22 epia klogd: INFO: lockdep is turned off.
(etc)
Load went to 1.0 and up even while the box was 90%+ idle.
Why did this happen?
How to debug?
Kind regards,
Udo
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2010-09-07 13:42 known vboxgetty/isdn issue in 2.6.35.3? Udo van den Heuvel
@ 2010-09-07 19:45 ` Arnd Bergmann
2010-09-08 0:35 ` Greg KH
2010-11-06 14:04 ` Udo van den Heuvel
0 siblings, 2 replies; 8+ messages in thread
From: Arnd Bergmann @ 2010-09-07 19:45 UTC (permalink / raw)
To: Udo van den Heuvel, Karsten Keil, Greg KH; +Cc: linux-kernel
On Tuesday 07 September 2010 15:42:27 Udo van den Heuvel wrote:
> Sep 2 15:00:22 epia klogd: INFO: task vboxgetty:25662 blocked for more
> than 120 seconds.
>
> Sep 2 15:00:22 epia klogd: Call Trace:
> Sep 2 15:00:22 epia klogd: [<c1157e3a>] ? tty_unthrottle+0x13/0x3a
> Sep 2 15:00:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
> Sep 2 15:00:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
It appears that the process deadlocks on tty->termios_mutex.
> Sep 2 15:00:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
> Sep 2 15:00:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
> Sep 2 15:00:22 epia klogd: [<c1156a6e>] reset_buffer_flags+0xd4/0xd9
> Sep 2 15:00:22 epia klogd: [<c1156a80>] n_tty_flush_buffer+0xd/0x63
> Sep 2 15:00:22 epia klogd: [<c11593c7>] tty_ldisc_flush+0x1f/0x34
> Sep 2 15:00:22 epia klogd: [<c11d6e28>] isdn_tty_modem_result+0x342/0x37c
> Sep 2 15:00:22 epia klogd: [<c1153ff3>] ? tty_wakeup+0x46/0x4e
> Sep 2 15:00:22 epia klogd: [<c11d910a>] isdn_tty_modem_hup+0x76/0x176
> Sep 2 15:00:22 epia klogd: [<c115824b>] ? set_termios+0x1a8/0x397
> Sep 2 15:00:22 epia klogd: [<c129476a>] ? mutex_lock_nested+0x2f/0x23f
> Sep 2 15:00:22 epia klogd: [<c11d9b17>] isdn_tty_change_speed+0xa2/0xd4
> Sep 2 15:00:22 epia klogd: [<c11d9b86>] isdn_tty_set_termios+0x3d/0x5a
> Sep 2 15:00:22 epia klogd: [<c11583bb>] set_termios+0x318/0x397
> Sep 2 15:00:22 epia klogd: [<c1158661>] tty_mode_ioctl+0x178/0x2db
> Sep 2 15:00:22 epia klogd: [<c1158a06>] ? tty_ldisc_try+0x11/0x38
> Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
> Sep 2 15:00:22 epia klogd: [<c1158908>] n_tty_ioctl_helper+0x144/0x154
> Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
> Sep 2 15:00:22 epia klogd: [<c1155ff9>] n_tty_ioctl+0x97/0xa0
> Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
> Sep 2 15:00:22 epia klogd: [<c11547ed>] tty_ioctl+0x699/0x6d3
> Sep 2 15:00:22 epia klogd: [<c1083788>] vfs_ioctl+0x27/0x91
> Sep 2 15:00:22 epia klogd: [<c1154154>] ? tty_ioctl+0x0/0x6d3
> Sep 2 15:00:22 epia klogd: [<c1083d06>] do_vfs_ioctl+0x467/0x4a5
> Sep 2 15:00:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
> Sep 2 15:00:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
> Sep 2 15:00:22 epia klogd: [<c1209c83>] ? net_tx_action+0x47/0xcc
> Sep 2 15:00:22 epia klogd: [<c102262a>] ? __do_softirq+0xc3/0xd2
> Sep 2 15:00:22 epia klogd: [<c1083d85>] sys_ioctl+0x41/0x61
> Sep 2 15:00:22 epia klogd: [<c1003cb9>] ? do_IRQ+0x74/0x87
> Sep 2 15:00:22 epia klogd: [<c1002813>] sysenter_do_call+0x12/0x2d
This happened when vboxgetty was doing an ioctl on an ISDN tty, apparently
while the TTY was getting hung up.
> Sep 2 15:00:22 epia klogd: INFO: lockdep is turned off.
Enabling CONFIG_LOCKDEP in your .config should provide better
information if you can reproduce it.
> Load went to 1.0 and up even while the box was 90%+ idle.
> Why did this happen?
When waiting uninterruptible for a mutex, we treat the process as busy,
even though it is not doing anything. The question is why it is waiting
for a mutex that should never be held for an extended time.
> How to debug?
One thing to check is if there are other processes blocked as well
that may be holding the mutex.
Can you send the output of "head -n 20 /proc/*/stack"? If
CONFIG_LOCKDEP gives you more data, that would be even better.
Another thing to try is to run 2.6.36-rc3. We just did a major change
to the locking in the tty subsystem, so if the behavior is different
there, that may be an explanation.
I also took Greg and Karten on Cc, they maintain the TTY and ISDN code
that is involved in the code path in question. Maybe one of them already
knows the answer.
Arnd
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2010-09-07 19:45 ` Arnd Bergmann
@ 2010-09-08 0:35 ` Greg KH
2010-11-06 14:04 ` Udo van den Heuvel
1 sibling, 0 replies; 8+ messages in thread
From: Greg KH @ 2010-09-08 0:35 UTC (permalink / raw)
To: Arnd Bergmann; +Cc: Udo van den Heuvel, Karsten Keil, linux-kernel
On Tue, Sep 07, 2010 at 09:45:10PM +0200, Arnd Bergmann wrote:
> On Tuesday 07 September 2010 15:42:27 Udo van den Heuvel wrote:
> > Sep 2 15:00:22 epia klogd: INFO: task vboxgetty:25662 blocked for more
> > than 120 seconds.
> >
> > Sep 2 15:00:22 epia klogd: Call Trace:
> > Sep 2 15:00:22 epia klogd: [<c1157e3a>] ? tty_unthrottle+0x13/0x3a
> > Sep 2 15:00:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
> > Sep 2 15:00:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
>
> It appears that the process deadlocks on tty->termios_mutex.
>
> > Sep 2 15:00:22 epia klogd: [<c1294879>] mutex_lock_nested+0x13e/0x23f
> > Sep 2 15:00:22 epia klogd: [<c1157e3a>] tty_unthrottle+0x13/0x3a
> > Sep 2 15:00:22 epia klogd: [<c1156a6e>] reset_buffer_flags+0xd4/0xd9
> > Sep 2 15:00:22 epia klogd: [<c1156a80>] n_tty_flush_buffer+0xd/0x63
> > Sep 2 15:00:22 epia klogd: [<c11593c7>] tty_ldisc_flush+0x1f/0x34
> > Sep 2 15:00:22 epia klogd: [<c11d6e28>] isdn_tty_modem_result+0x342/0x37c
> > Sep 2 15:00:22 epia klogd: [<c1153ff3>] ? tty_wakeup+0x46/0x4e
> > Sep 2 15:00:22 epia klogd: [<c11d910a>] isdn_tty_modem_hup+0x76/0x176
> > Sep 2 15:00:22 epia klogd: [<c115824b>] ? set_termios+0x1a8/0x397
> > Sep 2 15:00:22 epia klogd: [<c129476a>] ? mutex_lock_nested+0x2f/0x23f
> > Sep 2 15:00:22 epia klogd: [<c11d9b17>] isdn_tty_change_speed+0xa2/0xd4
> > Sep 2 15:00:22 epia klogd: [<c11d9b86>] isdn_tty_set_termios+0x3d/0x5a
> > Sep 2 15:00:22 epia klogd: [<c11583bb>] set_termios+0x318/0x397
> > Sep 2 15:00:22 epia klogd: [<c1158661>] tty_mode_ioctl+0x178/0x2db
> > Sep 2 15:00:22 epia klogd: [<c1158a06>] ? tty_ldisc_try+0x11/0x38
> > Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
> > Sep 2 15:00:22 epia klogd: [<c1158908>] n_tty_ioctl_helper+0x144/0x154
> > Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
> > Sep 2 15:00:22 epia klogd: [<c1155ff9>] n_tty_ioctl+0x97/0xa0
> > Sep 2 15:00:22 epia klogd: [<c1155f62>] ? n_tty_ioctl+0x0/0xa0
> > Sep 2 15:00:22 epia klogd: [<c11547ed>] tty_ioctl+0x699/0x6d3
> > Sep 2 15:00:22 epia klogd: [<c1083788>] vfs_ioctl+0x27/0x91
> > Sep 2 15:00:22 epia klogd: [<c1154154>] ? tty_ioctl+0x0/0x6d3
> > Sep 2 15:00:22 epia klogd: [<c1083d06>] do_vfs_ioctl+0x467/0x4a5
> > Sep 2 15:00:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
> > Sep 2 15:00:22 epia klogd: [<c1205478>] ? __kfree_skb+0x68/0x6b
> > Sep 2 15:00:22 epia klogd: [<c1209c83>] ? net_tx_action+0x47/0xcc
> > Sep 2 15:00:22 epia klogd: [<c102262a>] ? __do_softirq+0xc3/0xd2
> > Sep 2 15:00:22 epia klogd: [<c1083d85>] sys_ioctl+0x41/0x61
> > Sep 2 15:00:22 epia klogd: [<c1003cb9>] ? do_IRQ+0x74/0x87
> > Sep 2 15:00:22 epia klogd: [<c1002813>] sysenter_do_call+0x12/0x2d
>
> This happened when vboxgetty was doing an ioctl on an ISDN tty, apparently
> while the TTY was getting hung up.
>
> > Sep 2 15:00:22 epia klogd: INFO: lockdep is turned off.
>
> Enabling CONFIG_LOCKDEP in your .config should provide better
> information if you can reproduce it.
>
> > Load went to 1.0 and up even while the box was 90%+ idle.
> > Why did this happen?
>
> When waiting uninterruptible for a mutex, we treat the process as busy,
> even though it is not doing anything. The question is why it is waiting
> for a mutex that should never be held for an extended time.
>
> > How to debug?
>
> One thing to check is if there are other processes blocked as well
> that may be holding the mutex.
>
> Can you send the output of "head -n 20 /proc/*/stack"? If
> CONFIG_LOCKDEP gives you more data, that would be even better.
>
> Another thing to try is to run 2.6.36-rc3. We just did a major change
> to the locking in the tty subsystem, so if the behavior is different
> there, that may be an explanation.
>
> I also took Greg and Karten on Cc, they maintain the TTY and ISDN code
> that is involved in the code path in question. Maybe one of them already
> knows the answer.
Hm, nope, I haven't heard of this one.
Can it be tracked down to the specific patch by running 'git bisect'?
thanks,
greg k-h
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2010-09-07 19:45 ` Arnd Bergmann
2010-09-08 0:35 ` Greg KH
@ 2010-11-06 14:04 ` Udo van den Heuvel
2010-11-09 10:15 ` Arnd Bergmann
1 sibling, 1 reply; 8+ messages in thread
From: Udo van den Heuvel @ 2010-11-06 14:04 UTC (permalink / raw)
To: Arnd Bergmann; +Cc: Karsten Keil, Greg KH, linux-kernel
On 2010-09-07 21:45, Arnd Bergmann wrote:
> Can you send the output of "head -n 20 /proc/*/stack"? If
> CONFIG_LOCKDEP gives you more data, that would be even better.
My most recent post about this issue, occurring on 2.6.35.7, had a
kernel with this:
# gzip -dc /proc/config.gz |grep LOCKDEP
CONFIG_LOCKDEP_SUPPORT=y
CONFIG_LOCKDEP=y
# CONFIG_DEBUG_LOCKDEP is not set
Stacks below, after occurring on 2.6.35.7:
# head -n 20 /proc/*/stack
==> /proc/1077/stack <==
[<c10fe6a5>] kjournald+0x171/0x1e2
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/113/stack <==
[<c1066639>] bdi_sync_supers+0x20/0x33
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/11418/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/115/stack <==
[<c1066ed6>] bdi_forker_task+0x155/0x25f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1179/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/117/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/118/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/119/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/11/stack <==
[<c1034242>] async_manager_thread+0x92/0xb2
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/120/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1386/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1451/stack <==
[<c109269a>] bdi_writeback_task+0x77/0xd9
[<c1067037>] bdi_start_fn+0x57/0xad
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1485/stack <==
[<c10fe6a5>] kjournald+0x171/0x1e2
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1486/stack <==
[<c10fe6a5>] kjournald+0x171/0x1e2
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1487/stack <==
[<c10fe6a5>] kjournald+0x171/0x1e2
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1488/stack <==
[<c10fe6a5>] kjournald+0x171/0x1e2
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1489/stack <==
[<c1104e1d>] kjournald2+0x15b/0x1cf
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1490/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1491/stack <==
[<c1104e1d>] kjournald2+0x15b/0x1cf
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1492/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1493/stack <==
[<c1104e1d>] kjournald2+0x15b/0x1cf
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1494/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1495/stack <==
[<c1104e1d>] kjournald2+0x15b/0x1cf
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1496/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1497/stack <==
[<c1104e1d>] kjournald2+0x15b/0x1cf
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1498/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1508/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086b55>] sys_ppoll+0x87/0xf6
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/1509/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086b55>] sys_ppoll+0x87/0xf6
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/1510/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1516/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/1517/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/16758/stack <==
[<c118731a>] tty_unthrottle+0x13/0x3a
[<c1185f4e>] reset_buffer_flags+0xd4/0xd9
[<c1185f60>] n_tty_flush_buffer+0xd/0x63
[<c11888a7>] tty_ldisc_flush+0x1f/0x34
[<c120797c>] isdn_tty_modem_result+0x342/0x37c
[<c1209c5e>] isdn_tty_modem_hup+0x76/0x176
[<c120a66b>] isdn_tty_change_speed+0xa2/0xd4
[<c120a6da>] isdn_tty_set_termios+0x3d/0x5a
[<c118789b>] set_termios+0x318/0x397
[<c1187b41>] tty_mode_ioctl+0x178/0x2db
[<c1187de8>] n_tty_ioctl_helper+0x144/0x154
[<c11854d9>] n_tty_ioctl+0x97/0xa0
[<c1183ccd>] tty_ioctl+0x699/0x6d3
[<c108557c>] vfs_ioctl+0x27/0x91
[<c1085ade>] do_vfs_ioctl+0x44b/0x47f
[<c1085b53>] sys_ioctl+0x41/0x61
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/1692/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/19110/stack <==
[<c11096d0>] sys_semtimedop+0x6ee/0x828
[<c110b6b9>] sys_ipc+0x49/0x130
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/19748/stack <==
[<c10a1516>] sys_epoll_wait+0x145/0x1e3
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/19773/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/1/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2002/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2005/stack <==
[<c101feb5>] do_syslog+0xd3/0x340
[<c10b7ed3>] kmsg_read+0x3b/0x44
[<c10b0ea1>] proc_reg_read+0x6a/0x84
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2047/stack <==
[<c1027e71>] sys_rt_sigsuspend+0x98/0xb1
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20615/stack <==
[<c1021703>] do_wait+0x14d/0x1aa
[<c10217e7>] sys_wait4+0x87/0xa0
[<c1021813>] sys_waitpid+0x13/0x15
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20617/stack <==
[<c10a1516>] sys_epoll_wait+0x145/0x1e3
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20619/stack <==
[<c1080856>] pipe_wait+0x4a/0x62
[<c1080f09>] pipe_read+0x279/0x2dc
[<c107a465>] do_sync_read+0x89/0xc4
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2061/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20792/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20794/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20802/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2082/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20902/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2090/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/20947/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/209/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/2103/stack <==
[<c10a1516>] sys_epoll_wait+0x145/0x1e3
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2106/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/210/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/2131/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/214/stack <==
[<c11df5b1>] hub_thread+0xb32/0xbb9
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/2161/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2164/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2167/stack <==
[<c1080856>] pipe_wait+0x4a/0x62
[<c1080f09>] pipe_read+0x279/0x2dc
[<c107a465>] do_sync_read+0x89/0xc4
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2170/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/217/stack <==
[<c11eb28a>] serio_thread+0x259/0x27f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/2198/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/219/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/2220/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2250/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2258/stack <==
[<c1027c85>] sys_pause+0x13/0x1a
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2270/stack <==
[<c1268454>] inet_csk_accept+0x9d/0x197
[<c1283bc9>] inet_accept+0x20/0x9b
[<c1231721>] sys_accept4+0xfb/0x1d2
[<c1231c83>] sys_socketcall+0x194/0x1a5
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2295/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2317/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2398/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2406/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2414/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2415/stack <==
[<c1298bab>] unix_stream_recvmsg+0x1f8/0x4bd
[<c122fe06>] sock_aio_read+0x10b/0x115
[<c107a465>] do_sync_read+0x89/0xc4
[<c107adb8>] vfs_read+0x98/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2423/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2431/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2432/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2477/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2497/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2510/stack <==
[<c1032a38>] hrtimer_nanosleep+0x82/0xda
[<c1032ad4>] sys_nanosleep+0x44/0x51
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2517/stack <==
[<c1185c1c>] n_tty_read+0x395/0x5f3
[<c118203f>] tty_read+0x67/0x9e
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2519/stack <==
[<c1185c1c>] n_tty_read+0x395/0x5f3
[<c118203f>] tty_read+0x67/0x9e
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2521/stack <==
[<c1185c1c>] n_tty_read+0x395/0x5f3
[<c118203f>] tty_read+0x67/0x9e
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2523/stack <==
[<c1185c1c>] n_tty_read+0x395/0x5f3
[<c118203f>] tty_read+0x67/0x9e
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2525/stack <==
[<c1185c1c>] n_tty_read+0x395/0x5f3
[<c118203f>] tty_read+0x67/0x9e
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2527/stack <==
[<c1185c1c>] n_tty_read+0x395/0x5f3
[<c118203f>] tty_read+0x67/0x9e
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2545/stack <==
[<c1027c85>] sys_pause+0x13/0x1a
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/26042/stack <==
[<c1298bab>] unix_stream_recvmsg+0x1f8/0x4bd
[<c122fe06>] sock_aio_read+0x10b/0x115
[<c107a465>] do_sync_read+0x89/0xc4
[<c107adb8>] vfs_read+0x98/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/26050/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/26055/stack <==
[<c1021703>] do_wait+0x14d/0x1aa
[<c10217e7>] sys_wait4+0x87/0xa0
[<c1021813>] sys_waitpid+0x13/0x15
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/29184/stack <==
[<c10a1516>] sys_epoll_wait+0x145/0x1e3
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/29193/stack <==
[<c11096d0>] sys_semtimedop+0x6ee/0x828
[<c110b6b9>] sys_ipc+0x49/0x130
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/29376/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1086a4f>] do_sys_poll+0x350/0x3cf
[<c1086c03>] sys_poll+0x3f/0x88
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/29574/stack <==
[<c11096d0>] sys_semtimedop+0x6ee/0x828
[<c110b6b9>] sys_ipc+0x49/0x130
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/29615/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/2/stack <==
[<c102f6f6>] kthreadd+0x4d/0xbd
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/30863/stack <==
[<c1021703>] do_wait+0x14d/0x1aa
[<c10217e7>] sys_wait4+0x87/0xa0
[<c1021813>] sys_waitpid+0x13/0x15
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/30872/stack <==
[<c1021703>] do_wait+0x14d/0x1aa
[<c10217e7>] sys_wait4+0x87/0xa0
[<c1021813>] sys_waitpid+0x13/0x15
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/336/stack <==
[<c104daf1>] watchdog+0x30/0x1fe
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/337/stack <==
[<c1062c25>] kswapd+0x604/0x614
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/3580/stack <==
[<c1080856>] pipe_wait+0x4a/0x62
[<c1080f09>] pipe_read+0x279/0x2dc
[<c107a465>] do_sync_read+0x89/0xc4
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/3581/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/388/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/3/stack <==
[<c10230ec>] run_ksoftirqd+0x3d/0xf4
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/402/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/4454/stack <==
[<c108667e>] poll_schedule_timeout+0x27/0x3e
[<c1087183>] do_select+0x4f8/0x533
[<c1087375>] core_sys_select+0x1b7/0x252
[<c10875b8>] sys_select+0x68/0x84
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
==> /proc/4/stack <==
[<c104d939>] watchdog+0x50/0x79
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/516/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/524/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/5/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/6/stack <==
[<c102cd03>] worker_thread+0x97/0x22f
[<c102f6a4>] kthread+0x69/0x6e
[<c1002d7e>] kernel_thread_helper+0x6/0x10
[<ffffffff>] 0xffffffff
==> /proc/self/stack <==
[<c1009ae6>] save_stack_trace_tsk+0x17/0x33
[<c10b1af4>] proc_pid_stack+0x4a/0x76
[<c10b2cc8>] proc_single_show+0x48/0x6c
[<c108f539>] seq_read+0x160/0x315
[<c107ada8>] vfs_read+0x88/0x110
[<c107aec7>] sys_read+0x3b/0x60
[<c10027d3>] sysenter_do_call+0x12/0x2d
[<ffffffff>] 0xffffffff
Udo
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2010-11-06 14:04 ` Udo van den Heuvel
@ 2010-11-09 10:15 ` Arnd Bergmann
2011-03-17 21:48 ` Michael Karcher
0 siblings, 1 reply; 8+ messages in thread
From: Arnd Bergmann @ 2010-11-09 10:15 UTC (permalink / raw)
To: Udo van den Heuvel
Cc: Karsten Keil, Greg KH, linux-kernel, Alan Cox, Tilman Schmidt
On Saturday 06 November 2010, Udo van den Heuvel wrote:
> ==> /proc/16758/stack <==
> [<c118731a>] tty_unthrottle+0x13/0x3a
> [<c1185f4e>] reset_buffer_flags+0xd4/0xd9
> [<c1185f60>] n_tty_flush_buffer+0xd/0x63
> [<c11888a7>] tty_ldisc_flush+0x1f/0x34
> [<c120797c>] isdn_tty_modem_result+0x342/0x37c
> [<c1209c5e>] isdn_tty_modem_hup+0x76/0x176
> [<c120a66b>] isdn_tty_change_speed+0xa2/0xd4
> [<c120a6da>] isdn_tty_set_termios+0x3d/0x5a
> [<c118789b>] set_termios+0x318/0x397
> [<c1187b41>] tty_mode_ioctl+0x178/0x2db
> [<c1187de8>] n_tty_ioctl_helper+0x144/0x154
> [<c11854d9>] n_tty_ioctl+0x97/0xa0
> [<c1183ccd>] tty_ioctl+0x699/0x6d3
> [<c108557c>] vfs_ioctl+0x27/0x91
> [<c1085ade>] do_vfs_ioctl+0x44b/0x47f
> [<c1085b53>] sys_ioctl+0x41/0x61
> [<c10027d3>] sysenter_do_call+0x12/0x2d
> [<ffffffff>] 0xffffffff
Ok, so it seems that set_termios calls change_termios, which holds the
termios_mutex while calling isdn_tty_set_termios. This ends up
calling tty_unthrottle, which tries to take the same mutex, and that fails.
As far as I can tell, the problem got introduced in this commit:
commit 38db89799bdf11625a831c5af33938dcb11908b6
Author: Alan Cox <alan@linux.intel.com>
Date: Thu Jun 11 12:44:17 2009 +0100
Subject: tty: throttling race fix
However, a fix has recently gone into the kernel that should fix it. As
far as I can tell, 2.6.36 and later should not call tty_ldisc_flush
from isdn_tty_modem_result any more, which avoids the original problem.
Please apply the patch below to see if it helps. We should probably
have it in 2.6.32-stable and 2.6.35-stable, if there is another one.
Arnd
---
>From bc10f96757bd6ab3721510df8defa8f21c32f974 Mon Sep 17 00:00:00 2001
From: Tilman Schmidt <tilman@imap.cc>
Date: Mon, 5 Jul 2010 14:18:27 +0000
Subject: [PATCH] isdn: avoid calling tty_ldisc_flush() in atomic context
Remove the call to tty_ldisc_flush() from the RESULT_NO_CARRIER
branch of isdn_tty_modem_result(), as already proposed in commit
00409bb045887ec5e7b9e351bc080c38ab6bfd33.
This avoids a "sleeping function called from invalid context" BUG
when the hardware driver calls the statcallb() callback with
command==ISDN_STAT_DHUP in atomic context, which in turn calls
isdn_tty_modem_result(RESULT_NO_CARRIER, ~), and from there,
tty_ldisc_flush() which may sleep.
Signed-off-by: Tilman Schmidt <tilman@imap.cc>
Signed-off-by: David S. Miller <davem@davemloft.net>
diff --git a/drivers/isdn/i4l/isdn_tty.c b/drivers/isdn/i4l/isdn_tty.c
index fc8454d..51dc60d 100644
--- a/drivers/isdn/i4l/isdn_tty.c
+++ b/drivers/isdn/i4l/isdn_tty.c
@@ -2636,12 +2636,6 @@ isdn_tty_modem_result(int code, modem_info * info)
if ((info->flags & ISDN_ASYNC_CLOSING) || (!info->tty)) {
return;
}
-#ifdef CONFIG_ISDN_AUDIO
- if ( !info->vonline )
- tty_ldisc_flush(info->tty);
-#else
- tty_ldisc_flush(info->tty);
-#endif
if ((info->flags & ISDN_ASYNC_CHECK_CD) &&
(!((info->flags & ISDN_ASYNC_CALLOUT_ACTIVE) &&
(info->flags & ISDN_ASYNC_CALLOUT_NOHUP)))) {
^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2010-11-09 10:15 ` Arnd Bergmann
@ 2011-03-17 21:48 ` Michael Karcher
2011-03-18 14:24 ` Arnd Bergmann
0 siblings, 1 reply; 8+ messages in thread
From: Michael Karcher @ 2011-03-17 21:48 UTC (permalink / raw)
To: Arnd Bergmann
Cc: Udo van den Heuvel, Karsten Keil, Greg KH, linux-kernel,
Alan Cox, Tilman Schmidt
Am Dienstag, den 09.11.2010, 11:15 +0100 schrieb Arnd Bergmann:
> On Saturday 06 November 2010, Udo van den Heuvel wrote:
> > ==> /proc/16758/stack <==
> > [<c118731a>] tty_unthrottle+0x13/0x3a
> > [<c1185f4e>] reset_buffer_flags+0xd4/0xd9
> > [<c1185f60>] n_tty_flush_buffer+0xd/0x63
> > [<c11888a7>] tty_ldisc_flush+0x1f/0x34
> > [<c120797c>] isdn_tty_modem_result+0x342/0x37c
> > [<c1209c5e>] isdn_tty_modem_hup+0x76/0x176
> > [<c120a66b>] isdn_tty_change_speed+0xa2/0xd4
> > [<c120a6da>] isdn_tty_set_termios+0x3d/0x5a
> > [<c118789b>] set_termios+0x318/0x397
> > [<c1187b41>] tty_mode_ioctl+0x178/0x2db
> > [<c1187de8>] n_tty_ioctl_helper+0x144/0x154
> > [<c11854d9>] n_tty_ioctl+0x97/0xa0
> > [<c1183ccd>] tty_ioctl+0x699/0x6d3
> > [<c108557c>] vfs_ioctl+0x27/0x91
> > [<c1085ade>] do_vfs_ioctl+0x44b/0x47f
> > [<c1085b53>] sys_ioctl+0x41/0x61
> > [<c10027d3>] sysenter_do_call+0x12/0x2d
> > [<ffffffff>] 0xffffffff
>
> Ok, so it seems that set_termios calls change_termios, which holds the
> termios_mutex while calling isdn_tty_set_termios. This ends up
> calling tty_unthrottle, which tries to take the same mutex, and that fails.
[...]
> Please apply the patch below to see if it helps. We should probably
> have it in 2.6.32-stable and 2.6.35-stable, if there is another one.
The same issue happened on our system. Sometimes vboxgetty gets stuck in
state D on a debian stable system (2.6.32). I just applied your patch to
that kernel and hope the problem went away. Please remind me to report
back in one to two weeks if I didn't already report whether the hangs
are fixed. Is something except for a test on a productive system missing
to get this fix into 32-stable?
Regards,
Michael Karcher
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2011-03-17 21:48 ` Michael Karcher
@ 2011-03-18 14:24 ` Arnd Bergmann
2011-03-18 14:29 ` Michael Karcher
0 siblings, 1 reply; 8+ messages in thread
From: Arnd Bergmann @ 2011-03-18 14:24 UTC (permalink / raw)
To: Michael Karcher
Cc: Udo van den Heuvel, Karsten Keil, Greg KH, linux-kernel,
Alan Cox, Tilman Schmidt, stable
On Thursday 17 March 2011, Michael Karcher wrote:
> The same issue happened on our system. Sometimes vboxgetty gets stuck in
> state D on a debian stable system (2.6.32). I just applied your patch to
> that kernel and hope the problem went away. Please remind me to report
> back in one to two weeks if I didn't already report whether the hangs
> are fixed. Is something except for a test on a productive system missing
> to get this fix into 32-stable?
Thanks for the report. You are talking about this patch, right?
bc10f96757 "isdn: avoid calling tty_ldisc_flush() in atomic context"
Remove the call to tty_ldisc_flush() from the RESULT_NO_CARRIER
branch of isdn_tty_modem_result(), as already proposed in commit
00409bb045887ec5e7b9e351bc080c38ab6bfd33.
This avoids a "sleeping function called from invalid context" BUG
when the hardware driver calls the statcallb() callback with
command==ISDN_STAT_DHUP in atomic context, which in turn calls
isdn_tty_modem_result(RESULT_NO_CARRIER, ~), and from there,
tty_ldisc_flush() which may sleep.
Signed-off-by: Tilman Schmidt <tilman@imap.cc>
Signed-off-by: David S. Miller <davem@davemloft.net>
Arnd
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: known vboxgetty/isdn issue in 2.6.35.3?
2011-03-18 14:24 ` Arnd Bergmann
@ 2011-03-18 14:29 ` Michael Karcher
0 siblings, 0 replies; 8+ messages in thread
From: Michael Karcher @ 2011-03-18 14:29 UTC (permalink / raw)
To: Arnd Bergmann
Cc: Udo van den Heuvel, Karsten Keil, Greg KH, linux-kernel,
Alan Cox, Tilman Schmidt, stable
Am Freitag, den 18.03.2011, 15:24 +0100 schrieb Arnd Bergmann:
> On Thursday 17 March 2011, Michael Karcher wrote:
> > The same issue happened on our system. Sometimes vboxgetty gets stuck in
> > state D on a debian stable system (2.6.32). I just applied your patch to
> > that kernel and hope the problem went away. Please remind me to report
> > back in one to two weeks if I didn't already report whether the hangs
> > are fixed. Is something except for a test on a productive system missing
> > to get this fix into 32-stable?
>
> Thanks for the report. You are talking about this patch, right?
>
> bc10f96757 "isdn: avoid calling tty_ldisc_flush() in atomic context"
Yes, exactly. Sorry for not mentioning it. I did not experience the BUG,
but the hung task, just as in the mail I replied to.
Regards,
Michael Karcher
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2011-03-18 14:29 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2010-09-07 13:42 known vboxgetty/isdn issue in 2.6.35.3? Udo van den Heuvel
2010-09-07 19:45 ` Arnd Bergmann
2010-09-08 0:35 ` Greg KH
2010-11-06 14:04 ` Udo van den Heuvel
2010-11-09 10:15 ` Arnd Bergmann
2011-03-17 21:48 ` Michael Karcher
2011-03-18 14:24 ` Arnd Bergmann
2011-03-18 14:29 ` Michael Karcher
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).