Re: [patch] Real-Time Preemption, -RT-2.6.10-rc2-mm2-V0.7.30-2

[Mark_H_Johnson]

>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@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/