preemption latency trace v1.0.7 on 2.6.9-rc1-bk12-VP-S0
-------------------------------------------------------
 latency: 242 us, entries: 81 (81)   |   [VP:1 KP:1 SP:1 HP:1 #CPUS:1]
    -----------------
    | task: holey/3298, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: kmap_atomic+0x23/0x88
 => ended at:   kunmap_atomic+0x17/0x31
=======>
00000001 0.000ms (+0.000ms): kmap_atomic (file_read_actor)
00000001 0.000ms (+0.000ms): page_address (file_read_actor)
00000001 0.000ms (+0.212ms): __copy_to_user_ll (file_read_actor)
00000001 0.212ms (+0.000ms): smp_apic_timer_interrupt (__copy_to_user_ll)
00010001 0.213ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 0.213ms (+0.000ms): profile_hook (profile_tick)
00010001 0.214ms (+0.000ms): read_lock (profile_hook)
00010002 0.214ms (+0.000ms): read_lock (<00000000>)
00010002 0.214ms (+0.000ms): notifier_call_chain (profile_hook)
00010002 0.214ms (+0.000ms): _read_unlock (profile_tick)
00010001 0.215ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 0.215ms (+0.000ms): update_process_times (smp_apic_timer_interrupt)
00010001 0.215ms (+0.000ms): update_one_process (update_process_times)
00010001 0.216ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.216ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.216ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.217ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.218ms (+0.000ms): spin_lock (scheduler_tick)
00010002 0.218ms (+0.000ms): spin_lock (<00000000>)
00010002 0.218ms (+0.000ms): _spin_unlock (scheduler_tick)
00010001 0.218ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 0.219ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 0.219ms (+0.000ms): __do_softirq (do_softirq)
00000002 0.220ms (+0.000ms): wake_up_process (do_softirq)
00000002 0.220ms (+0.000ms): try_to_wake_up (wake_up_process)
00000002 0.220ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000002 0.221ms (+0.000ms): spin_lock (task_rq_lock)
00000003 0.221ms (+0.000ms): spin_lock (<00000000>)
00000003 0.221ms (+0.000ms): wake_idle (try_to_wake_up)
00000003 0.222ms (+0.000ms): idle_cpu (wake_idle)
00000003 0.222ms (+0.000ms): idle_cpu (wake_idle)
00000003 0.222ms (+0.000ms): find_next_bit (wake_idle)
00000003 0.223ms (+0.000ms): activate_task (try_to_wake_up)
00000003 0.223ms (+0.000ms): sched_clock (activate_task)
00000003 0.223ms (+0.000ms): recalc_task_prio (activate_task)
00000003 0.224ms (+0.000ms): effective_prio (recalc_task_prio)
00000003 0.224ms (+0.000ms): enqueue_task (activate_task)
00000003 0.224ms (+0.000ms): resched_task (try_to_wake_up)
00000003 0.224ms (+0.000ms): _spin_unlock_irqrestore (try_to_wake_up)
00000002 0.225ms (+0.001ms): preempt_schedule (try_to_wake_up)
00010001 0.226ms (+0.000ms): do_IRQ (__copy_to_user_ll)
00010001 0.226ms (+0.000ms): do_IRQ (<00000000>)
00010001 0.226ms (+0.000ms): spin_lock (do_IRQ)
00010002 0.226ms (+0.000ms): spin_lock (<00000000>)
00010002 0.227ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ)
00010002 0.227ms (+0.000ms): redirect_hardirq (do_IRQ)
00010002 0.227ms (+0.000ms): _spin_unlock (do_IRQ)
00010001 0.228ms (+0.000ms): preempt_schedule (do_IRQ)
00010001 0.228ms (+0.000ms): handle_IRQ_event (do_IRQ)
00010001 0.228ms (+0.000ms): timer_interrupt (handle_IRQ_event)
00010001 0.228ms (+0.000ms): spin_lock (timer_interrupt)
00010002 0.229ms (+0.000ms): spin_lock (<00000000>)
00010002 0.229ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010002 0.229ms (+0.000ms): spin_lock (mark_offset_tsc)
00010003 0.229ms (+0.000ms): spin_lock (<00000000>)
00010003 0.229ms (+0.000ms): spin_lock (mark_offset_tsc)
00010004 0.229ms (+0.005ms): spin_lock (<00000000>)
00010004 0.235ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010003 0.235ms (+0.000ms): preempt_schedule (mark_offset_tsc)
00010003 0.236ms (+0.000ms): _spin_unlock (mark_offset_tsc)
00010002 0.236ms (+0.000ms): preempt_schedule (mark_offset_tsc)
00010002 0.236ms (+0.000ms): spin_lock (timer_interrupt)
00010003 0.236ms (+0.001ms): spin_lock (<00000000>)
00010003 0.238ms (+0.000ms): _spin_unlock (timer_interrupt)
00010002 0.238ms (+0.000ms): preempt_schedule (timer_interrupt)
00010002 0.238ms (+0.000ms): do_timer (timer_interrupt)
00010002 0.239ms (+0.000ms): update_wall_time (do_timer)
00010002 0.239ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010002 0.239ms (+0.000ms): _spin_unlock (timer_interrupt)
00010001 0.239ms (+0.000ms): preempt_schedule (timer_interrupt)
00010001 0.240ms (+0.000ms): spin_lock (do_IRQ)
00010002 0.240ms (+0.000ms): spin_lock (<00000000>)
00010002 0.240ms (+0.000ms): note_interrupt (do_IRQ)
00010002 0.240ms (+0.000ms): end_edge_ioapic_irq (do_IRQ)
00010002 0.240ms (+0.000ms): _spin_unlock (do_IRQ)
00010001 0.240ms (+0.000ms): preempt_schedule (do_IRQ)
00000002 0.241ms (+0.000ms): do_softirq (do_IRQ)
00000002 0.241ms (+0.001ms): __do_softirq (do_softirq)
00000001 0.242ms (+0.000ms): kunmap_atomic (file_read_actor)
00000001 0.242ms (+0.000ms): sub_preempt_count (kunmap_atomic)
00000001 0.243ms (+0.000ms): update_max_trace (check_preempt_timing)