Re: Early hang with 2.6.21-rc4-rt1
From: Roland Dreier
Date: Tue Mar 27 2007 - 15:42:38 EST
Great, thanks ... I'm not sure which of the 2 patches fixed things,
but I now got the following trace. I've not really analyzed this, but
it definitely looks like tun_init() is doing something
fishy... ("149776 us maximum-latency"!!)
- R.
[ 272.392694] tun: Universal TUN/TAP device driver, 1.6
[ 272.397780] ( modprobe-1857 |#2): new 5088 us maximum-latency critical section.
[ 272.397782] => started at timestamp 176092523: <__spin_lock_irqsave+0x18/0x42>
[ 272.397790] => ended at timestamp 176097606: <release_console_sem+0x1ae/0x1fa>
[ 272.397795]
[ 272.397796] Call Trace:
[ 272.397801] [<ffffffff80255e74>] check_critical_timing+0x1e6/0x2f7
[ 272.397805] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.397810] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.397814] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.397819] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.397824] [<ffffffff8022c4e3>] vprintk+0x2a4/0x301
[ 272.397828] [<ffffffff80255f76>] check_critical_timing+0x2e8/0x2f7
[ 272.397833] [<ffffffff8022c5ac>] printk+0x6c/0x6e
[ 272.397837] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.397841] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.397846] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.397849] [<ffffffff8042785c>] wait_for_completion+0xbd/0xc6
[ 272.397854] [<ffffffff802262f9>] default_wake_function+0x0/0x19
[ 272.397859] [<ffffffff8042847a>] mutex_unlock+0x9/0x15
[ 272.397863] [<ffffffff80238dec>] blocking_notifier_call_chain+0x10/0x4e
[ 272.397868] [<ffffffff8800a02a>] :tun:tun_init+0x2a/0x6b
[ 272.397873] [<ffffffff8024d597>] sys_init_module+0x15d6/0x1731
[ 272.397879] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.397885] [<ffffffff803d2b89>] register_netdevice+0x0/0x31e
[ 272.397891] [<ffffffff80209e0f>] system_call+0xef/0x15c
[ 272.397896]
[ 272.397900] => dump-end timestamp 176097734
[ 272.397902]
[ 272.547556] ( modprobe-1857 |#2): new 149776 us maximum-latency critical section.
[ 272.547559] => started at timestamp 176097899: <__spin_lock_irqsave+0x18/0x42>
[ 272.547563] => ended at timestamp 176247674: <release_console_sem+0x1ae/0x1fa>
[ 272.547566]
[ 272.547567] Call Trace:
[ 272.547570] [<ffffffff80255e74>] check_critical_timing+0x1e6/0x2f7
[ 272.547575] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.547579] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.547583] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.547588] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.547593] [<ffffffff8022c4e3>] vprintk+0x2a4/0x301
[ 272.547597] [<ffffffff80255f76>] check_critical_timing+0x2e8/0x2f7
[ 272.547602] [<ffffffff8022c5ac>] printk+0x6c/0x6e
[ 272.547606] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.547610] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.547614] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.547618] [<ffffffff8042785c>] wait_for_completion+0xbd/0xc6
[ 272.547622] [<ffffffff802262f9>] default_wake_function+0x0/0x19
[ 272.547627] [<ffffffff8042847a>] mutex_unlock+0x9/0x15
[ 272.547630] [<ffffffff80238dec>] blocking_notifier_call_chain+0x10/0x4e
[ 272.547635] [<ffffffff8800a02a>] :tun:tun_init+0x2a/0x6b
[ 272.547639] [<ffffffff8024d597>] sys_init_module+0x15d6/0x1731
[ 272.547646] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.547650] [<ffffffff803d2b89>] register_netdevice+0x0/0x31e
[ 272.547656] [<ffffffff80209e0f>] system_call+0xef/0x15c
[ 272.547660]
[ 272.547663] => dump-end timestamp 176247784
[ 272.547664]
[ 272.697343] ( modprobe-1857 |#2): new 149919 us maximum-latency critical section.
[ 272.697345] => started at timestamp 176247830: <__spin_lock_irqsave+0x18/0x42>
[ 272.697349] => ended at timestamp 176397741: <release_console_sem+0x1ae/0x1fa>
[ 272.697353]
[ 272.697354] Call Trace:
[ 272.697357] [<ffffffff80255e74>] check_critical_timing+0x1e6/0x2f7
[ 272.697361] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.697366] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.697369] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.697374] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.697379] [<ffffffff8022c4e3>] vprintk+0x2a4/0x301
[ 272.697383] [<ffffffff80255f76>] check_critical_timing+0x2e8/0x2f7
[ 272.697388] [<ffffffff8022c5ac>] printk+0x6c/0x6e
[ 272.697392] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.697396] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.697401] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.697404] [<ffffffff8042785c>] wait_for_completion+0xbd/0xc6
[ 272.697409] [<ffffffff802262f9>] default_wake_function+0x0/0x19
[ 272.697413] [<ffffffff8042847a>] mutex_unlock+0x9/0x15
[ 272.697416] [<ffffffff80238dec>] blocking_notifier_call_chain+0x10/0x4e
[ 272.697421] [<ffffffff8800a02a>] :tun:tun_init+0x2a/0x6b
[ 272.697425] [<ffffffff8024d597>] sys_init_module+0x15d6/0x1731
[ 272.697432] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.697436] [<ffffffff803d2b89>] register_netdevice+0x0/0x31e
[ 272.697442] [<ffffffff80209e0f>] system_call+0xef/0x15c
[ 272.697446]
[ 272.697450] => dump-end timestamp 176397858
[ 272.697451]
[ 272.847183] ( modprobe-1857 |#2): new 149953 us maximum-latency critical section.
[ 272.847186] => started at timestamp 176397924: <__spin_lock_irqsave+0x18/0x42>
[ 272.847190] => ended at timestamp 176547875: <release_console_sem+0x1ae/0x1fa>
[ 272.847193]
[ 272.847194] Call Trace:
[ 272.847197] [<ffffffff80255e74>] check_critical_timing+0x1e6/0x2f7
[ 272.847201] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.847206] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.847210] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.847215] [<ffffffff8022be60>] release_console_sem+0x1ae/0x1fa
[ 272.847219] [<ffffffff8022c4e3>] vprintk+0x2a4/0x301
[ 272.847224] [<ffffffff80255f76>] check_critical_timing+0x2e8/0x2f7
[ 272.847229] [<ffffffff8022c5ac>] printk+0x6c/0x6e
[ 272.847232] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.847237] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.847241] [<ffffffff80429572>] __spin_unlock_irq+0x14/0x17
[ 272.847245] [<ffffffff8042785c>] wait_for_completion+0xbd/0xc6
[ 272.847249] [<ffffffff802262f9>] default_wake_function+0x0/0x19
[ 272.847253] [<ffffffff8042847a>] mutex_unlock+0x9/0x15
[ 272.847257] [<ffffffff80238dec>] blocking_notifier_call_chain+0x10/0x4e
[ 272.847262] [<ffffffff8800a02a>] :tun:tun_init+0x2a/0x6b
[ 272.847266] [<ffffffff8024d597>] sys_init_module+0x15d6/0x1731
[ 272.847272] [<ffffffff80256323>] trace_hardirqs_on+0x9a/0xb9
[ 272.847277] [<ffffffff803d2b89>] register_netdevice+0x0/0x31e
[ 272.847282] [<ffffffff80209e0f>] system_call+0xef/0x15c
[ 272.847287]
[ 272.847289] => dump-end timestamp 176547985
[ 272.847291]
[ 272.997056] tun: (C) 1999-2004 Max Krasnyansky <maxk@xxxxxxxxxxxx>
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/