Skip to contentSkip to conversation

known vboxgetty/isdn issue in 2.6.35.3?

DISCUSSION Udo van den Heuvel 4 participants 8 messages Sep 7, 2010 – Mar 18, 2011

lore
Share & tools
lore
#0 lore raw

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

#1 lore raw
Quoted 7 lines · 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.

Quoted 23 lines
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
Quoted 8 lines
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.

Quoted 1 line
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.

Quoted 2 lines

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.

Quoted 1 line

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

#2 lore raw
Quoted 66 lines · Arnd Bergmann
Quoted 7 lines · 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.

Quoted 23 lines
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
Quoted 8 lines
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.

Quoted 1 line
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.

Quoted 2 lines

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.

Quoted 1 line

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.

Quoted 7 lines

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

#3 lore raw
In reply to Arnd Bergmann
Quoted 2 lines · Arnd Bergmann

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

#4 lore raw
Quoted 18 lines · Udo van den Heuvel

==> /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
Quoted 1 line

[<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 <[email protected]>
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
---

Quoted 1 line

From bc10f96757bd6ab3721510df8defa8f21c32f974 Mon Sep 17 00:00:00 2001

From: Tilman Schmidt <[email protected]>
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.

drivers/isdn/i4l/isdn_tty.c +0 -6
index fc8454d..51dc60d 100644
@@ -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)))) {
#5 lore raw

Am Dienstag, den 09.11.2010, 11:15 +0100 schrieb Arnd Bergmann:

Quoted 24 lines · Udo van den Heuvel
Quoted 18 lines

==> /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
Quoted 1 line

[<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.

[...]

Quoted 2 lines

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

#6 lore raw
Quoted 6 lines · Michael Karcher

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.

Arnd

#7 lore raw

Am Freitag, den 18.03.2011, 15:24 +0100 schrieb Arnd Bergmann:

Quoted 11 lines · Michael Karcher
Quoted 6 lines

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