* 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