Re: [patch] Real-Time Preemption, -RT-2.6.9-rc4-mm1-U6

[Florian Schmidt]

On Tue, 19 Oct 2004 18:56:46 +0200
Ingo Molnar <mingo@xxxxxxx> wrote:

> do you get the same pauses if you do 'dmesg -n 1'? Also, are you using
> preempt_thresh or the maximum-searching variant? preempt_thresh can
> generate _tons_ of messages with a low threshold, freezing the system in
> essence for long periods of time.

afaik i use the maximum search:

mango:~# cat /proc/sys/kernel/preempt_thresh 
0
mango:~# cat /proc/sys/kernel/preempt_max_latency 
1841

I'll compile a kernel w/o preempt-timing and tracing. But i will get to it
tomorrow the earliest.

> but this trace is weird:

 [snip]
 
> this doesnt seem like normal behavior. It seems two tasks are
> ping-pong-ing a semaphore but are unable to make any progress. The whole
> thing is non-preemptible because this semaphore was taken while in a 
> PREEMPT_ACTIVE section.
> 
> (i'd say this is the BKL semaphore - it is quite special in that
> regard.)

btw: afaics these long critical sections reports do not correlate to the
pauses X makes (not sure though). I have anther long one. This is from
syslog as i haven't had the tracing enabled at that time:

(IRQ 3/117/CPU#0): new 1385 us maximum-latency critical section.
 => started at timestamp 2293619762: <call_console_drivers+0x76/0x140>
 =>   ended at timestamp 2293621147: <finish_task_switch+0x43/0xb0>
 [<c012f630>] sub_preempt_count+0x60/0x90
 [<c012f31e>] check_preempt_timing+0x15e/0x270
 [<c0114ae3>] finish_task_switch+0x43/0xb0
 [<c012f630>] sub_preempt_count+0x60/0x90
 [<c0114ae3>] finish_task_switch+0x43/0xb0
 [<c0114ae3>] finish_task_switch+0x43/0xb0
 [<c02a7917>] __schedule+0x2d7/0x5d0
 [<c0136faa>] do_irqd+0x5a/0x80
 [<c0112440>] mcount+0x14/0x18
 [<c0136faa>] do_irqd+0x5a/0x80
 [<c012d82a>] kthread+0xaa/0xb0
 [<c0136f50>] do_irqd+0x0/0x80
 [<c012d780>] kthread+0x0/0xb0
 [<c0104099>] kernel_thread_helper+0x5/0xc
preempt count: 00000002
. 2-level deep critical section nesting:
.. entry 1: __schedule+0x3b/0x5d0 / (do_irqd+0x5a/0x80)
.. entry 2: print_traces+0x1d/0x80 / (dump_stack+0x23/0x30)

 =>   dump-end timestamp 2293621634



Here's a similar (to the one from my last mail) shorter one:

preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U6
-------------------------------------------------------
 latency: 471 us, entries: 2562 (2562)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: xterm/3155, uid:1000 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0x23/0x80 <c02a82b3>
 => ended at:   finish_task_switch+0x43/0xb0 <c0114ae3>
=======>
04000001 0.000ms (+0.000ms): __rwsem_deadlock (down_write)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)
04000001 0.000ms (+0.000ms): sched_clock (__schedule)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)
04000001 0.000ms (+0.000ms): sched_clock (__schedule)
04000000 0.001ms (+0.000ms): schedule (down_write)
04000000 0.001ms (+0.000ms): __schedule (down_write)
04000001 0.001ms (+0.000ms): sched_clock (__schedule)
04000000 0.001ms (+0.000ms): schedule (down_write)
04000000 0.001ms (+0.000ms): __schedule (down_write)
04000001 0.001ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.002ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.002ms (+0.000ms): sched_clock (__schedule)
04000000 0.002ms (+0.000ms): schedule (down_write)
04000000 0.002ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.003ms (+0.000ms): schedule (down_write)
04000000 0.003ms (+0.000ms): __schedule (down_write)
04000001 0.003ms (+0.000ms): sched_clock (__schedule)
04000000 0.003ms (+0.000ms): schedule (down_write)

[many many more]

04000000 0.445ms (+0.000ms): __schedule (down_write)
04000001 0.445ms (+0.000ms): sched_clock (__schedule)
04000000 0.446ms (+0.000ms): schedule (down_write)
04000000 0.446ms (+0.000ms): __schedule (down_write)
04000001 0.446ms (+0.000ms): sched_clock (__schedule)
04000000 0.446ms (+0.000ms): schedule (down_write)
04000000 0.446ms (+0.000ms): __schedule (down_write)
04000001 0.447ms (+0.000ms): sched_clock (__schedule)
04000000 0.447ms (+0.000ms): schedule (down_write)
04000000 0.447ms (+0.000ms): __schedule (down_write)
04000001 0.447ms (+0.000ms): sched_clock (__schedule)
04000000 0.447ms (+0.000ms): schedule (down_write)
04000000 0.447ms (+0.000ms): __schedule (down_write)
04000001 0.448ms (+0.000ms): sched_clock (__schedule)
04000000 0.448ms (+0.000ms): schedule (down_write)
04000000 0.448ms (+0.000ms): __schedule (down_write)
04000001 0.448ms (+0.000ms): sched_clock (__schedule)
04000000 0.448ms (+0.000ms): schedule (down_write)
04000000 0.449ms (+0.000ms): __schedule (down_write)
04000001 0.449ms (+0.000ms): sched_clock (__schedule)
04000000 0.449ms (+0.000ms): schedule (down_write)
04000000 0.449ms (+0.000ms): __schedule (down_write)
04000001 0.449ms (+0.000ms): sched_clock (__schedule)
04000000 0.449ms (+0.000ms): schedule (down_write)
04000000 0.450ms (+0.000ms): __schedule (down_write)
04000001 0.450ms (+0.000ms): sched_clock (__schedule)
04000000 0.450ms (+0.000ms): schedule (down_write)
04000000 0.450ms (+0.000ms): __schedule (down_write)
04000001 0.450ms (+0.000ms): sched_clock (__schedule)
04000000 0.450ms (+0.000ms): schedule (down_write)
04000000 0.451ms (+0.000ms): __schedule (down_write)
04000001 0.451ms (+0.000ms): sched_clock (__schedule)
04000000 0.451ms (+0.000ms): schedule (down_write)
04000000 0.451ms (+0.000ms): __schedule (down_write)
04000001 0.451ms (+0.000ms): sched_clock (__schedule)
04000000 0.452ms (+0.000ms): schedule (down_write)
04000000 0.452ms (+0.000ms): __schedule (down_write)
04000001 0.452ms (+0.000ms): sched_clock (__schedule)
04000000 0.452ms (+0.000ms): schedule (down_write)
04000000 0.452ms (+0.000ms): __schedule (down_write)
04000001 0.452ms (+0.000ms): sched_clock (__schedule)
04000000 0.453ms (+0.000ms): schedule (down_write)
04000000 0.453ms (+0.000ms): __schedule (down_write)
04000001 0.453ms (+0.000ms): sched_clock (__schedule)
04000000 0.453ms (+0.000ms): schedule (down_write)
04000000 0.453ms (+0.000ms): __schedule (down_write)
04000001 0.453ms (+0.000ms): sched_clock (__schedule)
04000000 0.454ms (+0.000ms): schedule (down_write)
04000000 0.454ms (+0.000ms): __schedule (down_write)
04000001 0.454ms (+0.000ms): sched_clock (__schedule)
04000000 0.454ms (+0.000ms): schedule (down_write)
04000000 0.454ms (+0.001ms): __schedule (down_write)
04010000 0.455ms (+0.000ms): do_IRQ (add_preempt_count)
04010000 0.455ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.456ms (+0.001ms): mask_and_ack_8259A (__do_IRQ)
00010001 0.458ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010000 0.458ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010000 0.458ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.458ms (+0.006ms): mark_offset_tsc (timer_interrupt)
00010001 0.464ms (+0.000ms): do_timer (timer_interrupt)
00010001 0.465ms (+0.000ms): update_wall_time (do_timer)
00010001 0.465ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010001 0.465ms (+0.000ms): update_process_times (timer_interrupt)
00010001 0.465ms (+0.000ms): update_one_process (update_process_times)
00010001 0.465ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.466ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.466ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.466ms (+0.000ms): sched_clock (scheduler_tick)
00010002 0.466ms (+0.000ms): task_timeslice (scheduler_tick)
00010002 0.467ms (+0.000ms): dequeue_task (scheduler_tick)
00010002 0.467ms (+0.000ms): effective_prio (scheduler_tick)
00010002 0.467ms (+0.000ms): enqueue_task (scheduler_tick)
00010001 0.468ms (+0.000ms): note_interrupt (__do_IRQ)
00010001 0.468ms (+0.000ms): end_8259A_irq (__do_IRQ)
00010001 0.468ms (+0.000ms): enable_8259A_irq (__do_IRQ)
04010000 0.469ms (+0.000ms): irq_exit (do_IRQ)
04000001 0.469ms (+0.000ms): sched_clock (__schedule)
00000002 0.470ms (+0.000ms): __switch_to (__schedule)
00000002 0.470ms (+0.000ms): finish_task_switch (__schedule)












one more:

preemption latency trace v1.0.7 on 2.6.9-rc4-mm1-RT-U6
-------------------------------------------------------
 latency: 2363 us, entries: 4000 (15429)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: xterm/3155, uid:1000 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0x23/0x80 <c02a82b3>
 => ended at:   finish_task_switch+0x43/0xb0 <c0114ae3>
=======>
04000001 0.000ms (+0.000ms): __rwsem_deadlock (down_write)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)
04000001 0.000ms (+0.000ms): sched_clock (__schedule)
04000000 0.000ms (+0.000ms): schedule (down_write)
04000000 0.000ms (+0.000ms): __schedule (down_write)

[more]

04000000 0.347ms (+0.000ms): schedule (down_write)
04000000 0.348ms (+0.000ms): __schedule (down_write)
04000001 0.348ms (+0.000ms): sched_clock (__schedule)
04000000 0.348ms (+0.000ms): schedule (down_write)
04000000 0.348ms (+0.000ms): __schedule (down_write)
04000001 0.348ms (+0.000ms): sched_clock (__schedule)
04000000 0.349ms (+0.000ms): schedule (down_write)
04000000 0.349ms (+0.000ms): __schedule (down_write)
04000001 0.349ms (+0.000ms): sched_clock (__schedule)
04000000 0.349ms (+0.000ms): schedule (down_write)
04000000 0.349ms (+0.000ms): __schedule (down_write)
04000001 0.349ms (+0.000ms): sched_clock (__schedule)
04000000 0.350ms (+0.000ms): schedule (down_write)
04000000 0.350ms (+0.000ms): __schedule (down_write)
04000001 0.350ms (+0.000ms): sched_clock (__schedule)
04000000 0.350ms (+0.000ms): schedule (down_write)
04000000 0.350ms (+0.000ms): __schedule (down_write)
04000001 0.351ms (+0.000ms): sched_clock (__schedule)
04000000 0.351ms (+0.000ms): schedule (down_write)
04000000 0.351ms (+0.000ms): __schedule (down_write)
04000001 0.351ms (+0.000ms): sched_clock (__schedule)
04000000 0.352ms (+0.000ms): schedule (down_write)
04000000 0.352ms (+0.000ms): __schedule (down_write)
04010001 0.352ms (+0.000ms): do_IRQ (add_preempt_count)
04010001 0.353ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.353ms (+0.001ms): mask_and_ack_8259A (__do_IRQ)
00010001 0.355ms (+0.000ms): redirect_hardirq (__do_IRQ)
00010000 0.355ms (+0.000ms): handle_IRQ_event (__do_IRQ)
00010000 0.355ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.356ms (+0.006ms): mark_offset_tsc (timer_interrupt)
00010001 0.362ms (+0.000ms): do_timer (timer_interrupt)
00010001 0.363ms (+0.000ms): update_wall_time (do_timer)
00010001 0.363ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010001 0.363ms (+0.000ms): update_process_times (timer_interrupt)
00010001 0.363ms (+0.000ms): update_one_process (update_process_times)
00010001 0.363ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.363ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.364ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.364ms (+0.000ms): sched_clock (scheduler_tick)
00010002 0.364ms (+0.000ms): task_timeslice (scheduler_tick)
00010001 0.365ms (+0.000ms): note_interrupt (__do_IRQ)
00010001 0.365ms (+0.000ms): end_8259A_irq (__do_IRQ)
00010001 0.365ms (+0.000ms): enable_8259A_irq (__do_IRQ)
04010001 0.366ms (+0.000ms): irq_exit (do_IRQ)
04000001 0.367ms (+0.000ms): sched_clock (__schedule)
04000000 0.367ms (+0.000ms): schedule (down_write)
04000000 0.367ms (+0.000ms): __schedule (down_write)
04000001 0.367ms (+0.000ms): sched_clock (__schedule)
04000000 0.368ms (+0.000ms): schedule (down_write)
04000000 0.368ms (+0.000ms): __schedule (down_write)
04000001 0.368ms (+0.000ms): sched_clock (__schedule)
04000000 0.368ms (+0.000ms): schedule (down_write)
04000000 0.368ms (+0.000ms): __schedule (down_write)
04000001 0.369ms (+0.000ms): sched_clock (__schedule)
04000000 0.369ms (+0.000ms): schedule (down_write)
04000000 0.369ms (+0.000ms): __schedule (down_write)
04000001 0.369ms (+0.000ms): sched_clock (__schedule)
04000000 0.370ms (+0.000ms): schedule (down_write)
04000000 0.370ms (+0.000ms): __schedule (down_write)
04000001 0.370ms (+0.000ms): sched_clock (__schedule)
04000000 0.370ms (+0.000ms): schedule (down_write)

[more]

04000000 0.797ms (+0.000ms): schedule (down_write)
04000000 0.797ms (+0.000ms): __schedule (down_write)
04000001 0.797ms (+0.000ms): sched_clock (__schedule)
04000000 0.797ms (+0.000ms): schedule (down_write)
04000000 0.798ms (+0.000ms): __schedule (down_write)
04000001 0.798ms (+0.000ms): sched_clock (__schedule)
04000000 0.798ms (+0.000ms): schedule (down_write)
04000000 0.798ms (+0.000ms): __schedule (down_write)
04000001 0.798ms (+0.000ms): sched_clock (__schedule)
04000000 0.799ms (+0.000ms): schedule (down_write)
04000000 0.799ms (+0.000ms): __schedule (down_write)
04000001 0.799ms (+0.000ms): sched_clock (__schedule)
04000000 0.799ms (+0.000ms): schedule (down_write)
04000000 0.799ms (+0.000ms): __schedule (down_write)
04000001 0.800ms (+0.000ms): sched_clock (__schedule)
04000000 0.800ms (+0.000ms): schedule (down_write)
04000000 0.800ms (+0.000ms): __schedule (down_write)
04000001 0.800ms (+877840.005ms): sched_clock (__schedule)



fio
-
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/