Messages in this thread | | | From | Mark_H_Johnson@raytheon ... | Subject | Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.30-2 | Date | Mon, 22 Nov 2004 13:12:32 -0600 |
| |
>I have a few ideas to simplify the set up to see if I can get some >useful data out of the system.
It appears the lockup only occurs after I do echo 0 > /proc/sys/kernel/preempt_wakeup_latency
I did manage to get a few messages out of the system before the lockup this time and here is what was on the serial console.
[I didn't do "dmesg -n 1" like I usually do...]
--Mark --------
[starts with a couple of the wakeup latency messages, then the messages from changing the tracing type] (X/2869/CPU#1): new 76 us maximum-latency wakeup. (ksoftirqd/1/7/CPU#1): new 110 us maximum-latency wakeup. (X/2869/CPU#0): new 825 us maximum-latency critical section. => started at timestamp 4156290879: <try_to_wake_up+0x379/0x3e0> => ended at timestamp 4156291705: <__up_mutex+0x469/0x4d0> [<c0104e83>] dump_stack+0x23/0x30 (20) [<c013d107>] check_critical_timing+0x1d7/0x390 (88) [<c013d58d>] trace_irqs_on+0x7d/0x90 (24) [<c013ad19>] __up_mutex+0x469/0x4d0 (60) [<c013b4c6>] up_mutex+0xb6/0x110 (40) [<c016e234>] fget+0x54/0x70 (28) [<c0182c37>] do_select+0x207/0x2b0 (120) [<c0182fee>] sys_select+0x2be/0x580 (92) [<c0103f8d>] sysenter_past_esp+0x52/0x71 (-8124) --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [<c013e32d>] .... print_traces+0x1d/0x60 .....[<c0104e83>] .. ( <= dump_stack+0x23/0x30)
=> dump-end timestamp 4156528745
(IRQ 0/2/CPU#0): new 51 us maximum-latency critical section. => started at timestamp 4208681904: <__up_mutex+0x9c/0x4d0> => ended at timestamp 4208681955: <schedule+0x4c/0x140> [<c0104e83>] dump_stack+0x23/0x30 (20) [<c013d107>] check_critical_timing+0x1d7/0x390 (88) [<c013d58d>] trace_irqs_on+0x7d/0x90 (24) [<c032ad7c>] schedule+0x4c/0x140 (36) [<c032c386>] __down_mutex+0x2a6/0x310 (84) [<c013bccb>] __spin_lock+0x4b/0x60 (24) [<c013bcfd>] _spin_lock+0x1d/0x30 (16) [<c0109260>] timer_interrupt+0x20/0x110 (32) [<c0147b63>] handle_IRQ_event+0x53/0xa0 (40) [<c01483d5>] do_hardirq+0xa5/0x100 (40) [<c0148571>] do_irqd+0x141/0x210 (48) [<c0138b6b>] kthread+0xbb/0xc0 (48) [<c0102019>] kernel_thread_helper+0x5/0xc (536952852) --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [<c013e32d>] .... print_traces+0x1d/0x60 .....[<c0104e83>] .. ( <= dump_stack+0x23/0x30)
=> dump-end timestamp 4208969387
(get_ltrace.sh/6305/CPU#1): new 64 us maximum-latency critical section. => started at timestamp 4209005150: <do_exit+0x32c/0x5e0> => ended at timestamp 4209005214: <try_to_wake_up+0x23d/0x3e0> [<c0104e83>] dump_stack+0x23/0x30 (20) [<c013d107>] check_critical_timing+0x1d7/0x390 (88) [<c013d320>] touch_critical_timing+0x60/0x90 (24) [<c0118c5d>] try_to_wake_up+0x23d/0x3e0 (72) [<c0118e2b>] wake_up_process+0x2b/0x40 (28) [<c01201c7>] __mmdrop_delayed+0x67/0xa0 (20) [<c01192f7>] finish_task_switch+0x97/0xc0 (24) [<c032a857>] __sched_text_start+0x457/0x930 (112) [<c032ad70>] schedule+0x40/0x140 (36) [<c01257c6>] do_wait+0x1d6/0x540 (140) [<c0125c01>] sys_wait4+0x41/0x50 (28) [<c0125c3a>] sys_waitpid+0x2a/0x30 (24) [<c0103f8d>] sysenter_past_esp+0x52/0x71 (-8124) --------------------------- | preempt count: 00000004 ] | 4-level deep critical section nesting: ---------------------------------------- .. [<c032a44f>] .... __sched_text_start+0x4f/0x930 .....[<c032ad70>] .. ( <= schedule+0x40/0x140) .. [<c012017f>] .... __mmdrop_delayed+0x1f/0xa0 .....[<c01192f7>] .. ( <= finish_task_switch+0x97/0xc0) .. [<c032ca3f>] .... _raw_spin_lock+0x1f/0x70 .....[<c0117f62>] .. ( <= task_rq_lock+0x42/0x80) .. [<c013e32d>] .... print_traces+0x1d/0x60 .....[<c0104e83>] .. ( <= dump_stack+0x23/0x30)
=> dump-end timestamp 4209394021
(get_ltrace.sh/6305/CPU#1): new 77 us maximum-latency critical section. => started at timestamp 4209417650: <__sched_text_start+0x4f/0x930> => ended at timestamp 4209417728: <preempt_schedule+0x6e/0x80> [<c0104e83>] dump_stack+0x23/0x30 (20) [<c013d107>] check_critical_timing+0x1d7/0x390 (88) [<c013d58d>] trace_irqs_on+0x7d/0x90 (24) [<c032aede>] preempt_schedule+0x6e/0x80 (20) [<c01190fb>] wake_up_new_task+0x16b/0x240 (44) [<c011fce9>] do_fork+0x129/0x1d0 (132) [<c01029be>] sys_clone+0x3e/0x50 (32) [<c0103f8d>] sysenter_past_esp+0x52/0x71 (-8124) --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [<c013e32d>] .... print_traces+0x1d/0x60 .....[<c0104e83>] .. ( <= dump_stack+0x23/0x30)
=> dump-end timestamp 4209652960
- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
| |