preemption latency trace v1.0.7 on 2.6.9-rc1-bk12-VP-S0
-------------------------------------------------------
 latency: 219 us, entries: 58 (58)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: ksoftirqd/0/3, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: preempt_schedule+0x3b/0x5f
 => ended at:   schedule+0x378/0xbaf
=======>
04000000 0.000ms (+0.000ms): preempt_schedule (need_resched)
04000000 0.000ms (+0.000ms): schedule (preempt_schedule)
04000001 0.000ms (+0.203ms): sched_clock (schedule)
04000001 0.203ms (+0.000ms): spin_lock_irq (schedule)
04010001 0.204ms (+0.000ms): do_IRQ (__mcount)
04010001 0.204ms (+0.000ms): do_IRQ (<00000000>)
04010001 0.204ms (+0.000ms): spin_lock (do_IRQ)
04010002 0.204ms (+0.000ms): spin_lock (<00000000>)
04010002 0.204ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ)
04010002 0.205ms (+0.000ms): redirect_hardirq (do_IRQ)
04010002 0.205ms (+0.000ms): _spin_unlock (do_IRQ)
04010001 0.205ms (+0.000ms): preempt_schedule (do_IRQ)
04010001 0.205ms (+0.000ms): handle_IRQ_event (do_IRQ)
04010001 0.205ms (+0.000ms): timer_interrupt (handle_IRQ_event)
04010001 0.205ms (+0.000ms): spin_lock (timer_interrupt)
04010002 0.205ms (+0.000ms): spin_lock (<00000000>)
04010002 0.206ms (+0.000ms): mark_offset_tsc (timer_interrupt)
04010002 0.206ms (+0.000ms): spin_lock (mark_offset_tsc)
04010003 0.206ms (+0.000ms): spin_lock (<00000000>)
04010003 0.206ms (+0.000ms): spin_lock (mark_offset_tsc)
04010004 0.206ms (+0.005ms): spin_lock (<00000000>)
04010004 0.212ms (+0.000ms): _spin_unlock (mark_offset_tsc)
04010003 0.212ms (+0.000ms): preempt_schedule (mark_offset_tsc)
04010003 0.212ms (+0.000ms): _spin_unlock (mark_offset_tsc)
04010002 0.212ms (+0.000ms): preempt_schedule (mark_offset_tsc)
04010002 0.212ms (+0.000ms): spin_lock (timer_interrupt)
04010003 0.212ms (+0.001ms): spin_lock (<00000000>)
04010003 0.214ms (+0.000ms): _spin_unlock (timer_interrupt)
04010002 0.214ms (+0.000ms): preempt_schedule (timer_interrupt)
04010002 0.214ms (+0.000ms): do_timer (timer_interrupt)
04010002 0.214ms (+0.000ms): update_wall_time (do_timer)
04010002 0.215ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
04010002 0.215ms (+0.000ms): _spin_unlock (timer_interrupt)
04010001 0.215ms (+0.000ms): preempt_schedule (timer_interrupt)
04010001 0.215ms (+0.000ms): spin_lock (do_IRQ)
04010002 0.215ms (+0.000ms): spin_lock (<00000000>)
04010002 0.215ms (+0.000ms): note_interrupt (do_IRQ)
04010002 0.215ms (+0.000ms): end_edge_ioapic_irq (do_IRQ)
04010002 0.215ms (+0.000ms): _spin_unlock (do_IRQ)
04010001 0.216ms (+0.000ms): preempt_schedule (do_IRQ)
04000002 0.216ms (+0.000ms): do_softirq (do_IRQ)
04000002 0.216ms (+0.000ms): __do_softirq (do_softirq)
04000001 0.216ms (+0.000ms): __spin_lock_irqsave (spin_lock_irq)
04000002 0.217ms (+0.000ms): __spin_lock_irqsave (<00000000>)
04000002 0.217ms (+0.000ms): _spin_unlock (schedule)
04000001 0.217ms (+0.000ms): preempt_schedule (schedule)
04000001 0.217ms (+0.000ms): spin_lock (schedule)
04000002 0.217ms (+0.000ms): spin_lock (<00000000>)
04000002 0.217ms (+0.000ms): find_next_bit (schedule)
04000002 0.218ms (+0.000ms): dequeue_task (schedule)
04000002 0.218ms (+0.000ms): recalc_task_prio (schedule)
04000002 0.218ms (+0.000ms): effective_prio (recalc_task_prio)
04000002 0.218ms (+0.000ms): enqueue_task (schedule)
00000002 0.218ms (+0.000ms): __switch_to (schedule)
00000002 0.219ms (+0.000ms): finish_task_switch (schedule)
00000002 0.219ms (+0.000ms): _spin_unlock_irq (finish_task_switch)
00000001 0.219ms (+0.000ms): sub_preempt_count (schedule)
00000001 0.219ms (+0.000ms): update_max_trace (check_preempt_timing)