On Fri, 2005-02-04 at 11:03 +0100, Ingo Molnar wrote:
> http://redhat.com/~mingo/realtime-preempt/
>
Testing on an all SCSI 1.3Ghz Athlon XP system, I am seeing very long
latencies in the journalling code with 2.6.11-rc4-RT-V0.7.39-02.
preemption latency trace v1.1.4 on 2.6.11-rc4-RT-V0.7.39-02
--------------------------------------------------------------------
latency: 713 µs, #3455/3455, CPU#0 | (M:preempt VP:0, KP:1, SP:1 HP:1 #P:1)
-----------------
| task: ksoftirqd/0-2 (uid:0 nice:-10 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
kjournal-2478 0dn.4 0µs!: <756f6a6b> (<6c616e72>)
kjournal-2478 0dn.4 0µs : __trace_start_sched_wakeup (try_to_wake_up)
kjournal-2478 0dn.3 0µs : preempt_schedule (try_to_wake_up)
kjournal-2478 0dn.3 0µs : try_to_wake_up <<...>-2> (69 73):
kjournal-2478 0dn.2 0µs : preempt_schedule (try_to_wake_up)
kjournal-2478 0dn.2 0µs : wake_up_process (do_softirq)
kjournal-2478 0dn.1 1µs < (1)
The repeating pattern is 8 of these:
kjournal-2478 0.n.1 1µs : inverted_lock (journal_commit_transaction)
kjournal-2478 0.n.1 1µs : __journal_unfile_buffer
(journal_commit_transaction)
kjournal-2478 0.n.1 1µs : journal_remove_journal_head
(journal_commit_transaction)
kjournal-2478 0.n.1 1µs : __journal_remove_journal_head
(journal_remove_journal_head)
kjournal-2478 0.n.1 1µs : __brelse (__journal_remove_journal_head)
kjournal-2478 0.n.1 1µs : journal_free_journal_head
(journal_remove_journal_head)
kjournal-2478 0.n.1 2µs : kmem_cache_free (journal_free_journal_head)
and one of these:
kjournal-2478 0dn.1 9µs : cache_flusharray (kmem_cache_free)
kjournal-2478 0dn.2 9µs : free_block (cache_flusharray)
kjournal-2478 0dn.1 11µs : preempt_schedule (cache_flusharray)
kjournal-2478 0dn.1 11µs : memmove (cache_flusharray)
kjournal-2478 0dn.1 11µs : memcpy (memmove)
etc. Finally:
kjournal-2478 0dn.1 704µs : cache_flusharray (kmem_cache_free)
kjournal-2478 0dn.2 704µs+: free_block (cache_flusharray)
kjournal-2478 0dn.1 707µs : preempt_schedule (cache_flusharray)
kjournal-2478 0dn.1 707µs : memmove (cache_flusharray)
kjournal-2478 0dn.1 707µs : memcpy (memmove)
kjournal-2478 0.n.1 708µs : inverted_lock (journal_commit_transaction)
kjournal-2478 0.n.1 708µs : __journal_unfile_buffer
(journal_commit_transaction)
kjournal-2478 0.n.1 709µs : journal_remove_journal_head
(journal_commit_transaction)
kjournal-2478 0.n.1 709µs : __journal_remove_journal_head
(journal_remove_journal_head)
kjournal-2478 0.n.1 709µs : __brelse (__journal_remove_journal_head)
kjournal-2478 0.n.1 709µs : journal_free_journal_head
(journal_remove_journal_head)
kjournal-2478 0.n.1 709µs : kmem_cache_free (journal_free_journal_head)
kjournal-2478 0.n.. 710µs : preempt_schedule (journal_commit_transaction)
kjournal-2478 0dn.. 710µs : __schedule (preempt_schedule)
kjournal-2478 0dn.. 710µs : profile_hit (__schedule)
kjournal-2478 0dn.1 710µs : sched_clock (__schedule)
kjournal-2478 0dn.2 711µs : dequeue_task (__schedule)
kjournal-2478 0dn.2 711µs : recalc_task_prio (__schedule)
kjournal-2478 0dn.2 711µs : effective_prio (recalc_task_prio)
kjournal-2478 0dn.2 711µs : enqueue_task (__schedule)
<...>-2 0d..2 712µs : __switch_to (__schedule)
<...>-2 0d..2 712µs : __schedule <kjournal-2478> (73 69):
<...>-2 0d..2 712µs : finish_task_switch (__schedule)
<...>-2 0d..1 712µs : trace_stop_sched_switched (finish_task_switch)
<...>-2 0d..1 712µs : trace_stop_sched_switched <<...>-2> (69 0):
<...>-2 0d..1 713µs : trace_stop_sched_switched (finish_task_switch)
Lee
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [EMAIL PROTECTED]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
